| Posted | Nick | Remark | |
|---|---|---|---|
| #openstack-nova - 2019-05-16 | |||
| 22:42:18 | sean-k-mooney | i can see the keysone context being construted here | |
| 22:42:20 | sean-k-mooney | https://github.com/openstack/nova/blob/c6218428e9b29a2c52808ec7d27b4b21aadc0299/nova/api/auth.py#L95-L106 | |
| 22:42:45 | sean-k-mooney | and i think that is the context that is passed here as ctxt https://github.com/openstack/nova/blob/c6218428e9b29a2c52808ec7d27b4b21aadc0299/nova/compute/rpcapi.py#L593-L598 | |
| 22:42:46 | openstackgerrit | Eric Fried proposed openstack/nova stable/stein: DNM: Revert "Use external placement in functional tests" https://review.opendev.org/659682 | |
| 22:43:27 | melwitt | yeah, and it's the keystone middleware that sets the headers that are used to construct the context you show | |
| 22:44:08 | sean-k-mooney | but when we constuct the rpc client we dont set retry too true as far as i can tell | |
| 22:45:11 | openstackgerrit | Eric Fried proposed openstack/nova stable/stein: Skip _exclude_nested_providers() if not nested https://review.opendev.org/659206 | |
| 22:49:03 | melwitt | sean-k-mooney: looks like it comes from here https://github.com/openstack/oslo.messaging/blob/master/oslo_messaging/rpc/client.py#L342-L343 | |
| 22:49:22 | melwitt | (maybe, I didn't trace it) | |
| 22:50:43 | sean-k-mooney | ok i found that like 30 mins ago but i mis interpreted the default of None as dont retry | |
| 22:50:46 | melwitt | so transport._send() will be done with forever retry | |
| 22:50:50 | sean-k-mooney | ok so it shoudl retry for ever | |
| 22:50:57 | sean-k-mooney | ya | |
| 22:51:02 | sean-k-mooney | i shoudl have read the commet | |
| 22:53:39 | sean-k-mooney | ok so this https://github.com/openstack/oslo.messaging/blob/master/oslo_messaging/_drivers/impl_rabbit.py#L666 is where the retry is implemented | |
| 23:00:22 | sean-k-mooney | ok do i have traced that fully through nova into oslo.messaging and unless there is a bug in the auto retry suppupot in the kombu lib which i doubt the issue is not tha twe think we sent the message on publish | |
| 23:00:33 | imacdonn | seems that that retries ensuring that a connection exists, but doesn't retry sending a message ? | |
| 23:00:51 | sean-k-mooney | it does it delegate it to kombu | |
| 23:01:15 | melwitt | yeah, I saw that too, just passes everything (including the message) to kombu's autoretry method | |
| 23:01:24 | sean-k-mooney | https://github.com/openstack/oslo.messaging/blob/master/oslo_messaging/_drivers/impl_rabbit.py#L745-L752 | |
| 23:01:32 | melwitt | so you would think after reconnecting, it would send the message | |
| 23:03:27 | melwitt | I guess I'm wondering now if what's in these callbacks are what controls how it behaves, whether it would send the message after reconnecting? | |
| 23:04:08 | sean-k-mooney | i assume that is what on_revive=on_reconnection is doing? | |
| 23:04:30 | imacdonn | I'm missing something .. where is the message passed to the autoretry method ? | |
| 23:05:06 | sean-k-mooney | exec methond is a functoll.partial thing | |
| 23:05:30 | melwitt | imacdonn: here https://github.com/openstack/oslo.messaging/blob/master/oslo_messaging/_drivers/impl_rabbit.py#L1098-L1101 | |
| 23:05:50 | sean-k-mooney | https://github.com/openstack/oslo.messaging/blob/master/oslo_messaging/_drivers/impl_rabbit.py#L1098 | |
| 23:06:47 | sean-k-mooney | so the execute_method has the mesg and all the args curried in the partial callable | |
| 23:07:29 | melwitt | yeah, so the on_reconnection method just reconfigures some things | |
| 23:07:58 | sean-k-mooney | yes but that is called when the conenct is revived but the auto retry i think would retry? | |
| 23:07:59 | melwitt | unfortunately it looks like we're going to have to look at what autoretry source does | |
| 23:08:15 | openstackgerrit | Merged openstack/nova master: Test macvtap port with resource request https://review.opendev.org/641309 | |
| 23:08:26 | sean-k-mooney | unless you think we are ending up here https://github.com/openstack/oslo.messaging/blob/master/oslo_messaging/_drivers/impl_rabbit.py#L760-L771 | |
| 23:08:30 | melwitt | you would think so but symptom suggests it's not | |
| 23:08:59 | sean-k-mooney | well we set the retry limit to float("inf") | |
| 23:09:11 | sean-k-mooney | so it could take a while to hit that :) | |
| 23:09:12 | melwitt | no, I don't think we're ending up there (we haven't seen that log) | |
| 23:10:33 | melwitt | we see a reconnect message, and then we see a timeout fire some milliseconds later http://paste.openstack.org/show/751486/ | |
| 23:11:07 | imacdonn | the timeout is one minute later | |
| 23:11:27 | melwitt | oh guh, sorry | |
| 23:11:32 | imacdonn | ;) | |
| 23:11:33 | melwitt | I see now | |
| 23:17:00 | sean-k-mooney | thats being raised form https://github.com/openstack/oslo.messaging/blob/master/oslo_messaging/_drivers/impl_rabbit.py#L1125 form inside the partial functionin the auto retry thing | |
| 23:18:26 | sean-k-mooney | actully its from the publish line but im looking at master on github | |
| 23:19:36 | sean-k-mooney | so ya after the first trace which is the publish failing we see the reconnect | |
| 23:20:24 | sean-k-mooney | and then i think the timeout for sending that message has expired after we reconnect | |
| 23:20:51 | sean-k-mooney | we started to send it at 2019-05-16 18:24:09.089 | |
| 23:22:04 | sean-k-mooney | but that doesnt make sense | |
| 23:22:27 | sean-k-mooney | the conenct is reestablished at 2019-05-16 18:24:10.109 | |
| 23:22:43 | sean-k-mooney | and then there are no log messages untill the time out 1 minut later | |
| 23:22:58 | melwitt | right | |
| 23:23:06 | sean-k-mooney | but the rpc timeout should be longer then 60 seconds right? | |
| 23:23:28 | melwitt | I think it probably defaults to 60s | |
| 23:23:40 | melwitt | I can't remember where it is, lemme see | |
| 23:23:55 | imacdonn | 2019-05-16 18:16:05.973 23144 DEBUG nova.api.openstack.wsgi_app [-] long_rpc_timeout = 1800 log_opt_values /usr/lib/python2.7/site-packages/oslo_config/cfg.py:2571 | |
| 23:24:11 | imacdonn | wait that's not it | |
| 23:24:16 | melwitt | default to 60 https://github.com/openstack/oslo.messaging/blob/7102eddb1fd799d949ff5dca8aa2637794bb8a43/oslo_messaging/rpc/client.py#L41 | |
| 23:24:21 | sean-k-mooney | the long_rpc_timeout is not used for every rpc | |
| 23:24:44 | melwitt | rpc_response_timeout is the one | |
| 23:26:25 | sean-k-mooney | so this is what kombu is doing https://github.com/celery/kombu/blob/master/kombu/connection.py#L500-L547 | |
| 23:33:56 | openstackgerrit | Merged openstack/nova master: Fix some issues with the newton release notes https://review.opendev.org/659623 | |
| 23:34:08 | imacdonn | attempting repro with kombu debug logging | |
| 23:38:45 | melwitt | good call, because looking at the code it looks like it should be doing the right thing. no clue what's happening | |
| 23:42:21 | imacdonn | weird .. not getting the connection resets now | |
| 23:42:41 | sean-k-mooney | does it not take time for it to happen | |
| 23:42:45 | sean-k-mooney | e.g a few minutes | |
| 23:42:54 | melwitt | did you remember to set threads=8? | |
| 23:43:05 | imacdonn | yeah, I waited 5 mins the first try, then a little over 3 mins second try | |
| 23:43:19 | imacdonn | yes, threads=8, but I should see the connection reset either way | |
| 23:43:40 | melwitt | true | |
| 23:45:02 | sean-k-mooney | ok its technically friday here so im going to have pizza and then sleep. if ye find anything let me know but for no i guess we shoudl update the bug and tell people to run with thread=1 | |
| 23:45:15 | sean-k-mooney | our maybe with debug loging... | |
| 23:45:31 | melwitt | pizza, sounds like a solid plan | |
| 23:46:24 | imacdonn | Thanks, sean-k-mooney - pizza/sleep well! | |
| 23:46:29 | sean-k-mooney | i actully had a c++ bug where debug builds did not have the bug because it was an unitialised variable and in debug mode the compiler was "kind" enouch to initalise it to 0 | |
| 23:48:47 | imacdonn | ahh, got the reset now ... paste in a few mins | |
| 23:51:16 | imacdonn | http://paste.openstack.org/show/AZQET5IOgntK785RHtxh/ | |
| 23:57:51 | melwitt | weird, it says basic_publish_confirm but then one minute later timeout happens | |
| 23:58:24 | melwitt | so confused. | |
| #openstack-nova - 2019-05-17 | |||
| 00:02:03 | imacdonn | not sure what what basic_publish_confirm message really means | |
| 00:02:40 | melwitt | I don't either but just the indication that it made an attempt to send the message | |
| 00:03:00 | melwitt | I guess that implies it for some reason couldn't get through and results in the timeout? | |
| 00:05:33 | imacdonn | basic_publish_confirm is the method (that's supposed to get autoretry'ed), I guess | |
| 00:06:14 | imacdonn | I think it comes from python-amqp (?) | |
| 00:07:31 | imacdonn | File "/usr/lib/python2.7/site-packages/amqp/channel.py", line 1787, in basic_publish_confirm | |
| 00:10:59 | imacdonn | it does seem like it calls it the second time (at 23:48:19.113), but apparently still doesn't get an answer | |
| 00:12:07 | melwitt | yeah, that's the one I was looking at, the second that times out even after re-establishing the connection | |
| 00:13:23 | openstackgerrit | Dustin Cowles proposed openstack/nova master: Use SDK instead of ironicclient for setting instance id https://review.opendev.org/659690 | |
| 00:15:04 | openstackgerrit | Dustin Cowles proposed openstack/nova master: WIP: Use SDK instead of ironicclient for add/remove instance info from node https://review.opendev.org/659691 | |
| 00:34:56 | openstackgerrit | Merged openstack/nova master: Stop logging traceback when skipping quiesce https://review.opendev.org/659374 | |
| 01:08:39 | imacdonn | another data-point: the retried request DOES actually get sent, because I see the compute node act upon it ... I guess somehow the client (nova-api) has some issue with the response | |
| 03:02:16 | openstackgerrit | chenker proposed openstack/python-novaclient master: Optimize limit option docs string description for novaclient https://review.opendev.org/643035 | |
| 03:03:42 | openstackgerrit | Guo Jingyu proposed openstack/nova master: Skip existing VMs when hosts apply forceconfig_drive https://review.opendev.org/659703 | |
| 03:17:07 | openstackgerrit | Guo Jingyu proposed openstack/nova master: Skip existing VMs when hosts apply force_config_drive https://review.opendev.org/659703 | |
| 04:46:38 | ykarel | TheJulia, dtantsur|afk can you check comment in https://review.opendev.org/#/c/653279/1 | |
| 04:48:21 | ykarel | hmm looks like some issue is already there, as i can see https://review.opendev.org/#/c/659612/1, can you check if this ^^ is same issue or something else | |
| 05:25:41 | openstackgerrit | Guo Jingyu proposed openstack/nova master: Add rfb.VNC support for novncproxy https://review.opendev.org/622336 | |
| 05:26:26 | openstackgerrit | Guo Jingyu proposed openstack/nova-specs master: Proposal for a safer noVNC console with password authentication https://review.opendev.org/623120 | |
| 06:21:19 | openstackgerrit | Guo Jingyu proposed openstack/nova master: Skip existing VMs when hosts apply force_config_drive https://review.opendev.org/659703 | |
| 08:01:14 | kashyap | aspiers: That's in queue, I'm still backlogged :-( I know it is ready to merge. If I look at, I would like to spend a 2-hour block on it. So trying to find that :P | |