Earlier  
Later
New Search
Posted Nick Remark
#openstack-nova - 2019-05-16
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
08:01:18 kashyap aspiers: From your comment:
08:01:19 kashyap "I don't quite understand how the fix in https://www.redhat.com/archives/libvir-list/2019-April/msg01418.html would make the Python arguments optional however, since they're still missing defaults."

Earlier   Later