| Posted | Nick | Remark | |
|---|---|---|---|
| #openstack-nova - 2019-05-16 | |||
| 21:42:28 | imacdonn | look at http://paste.openstack.org/show/751486/ - the reset follows the publish failure, not a heartbeat failure | |
| 21:42:28 | dansmith | which can happen if we effectively connect to rabbit, subscribe to a reply queue, but never sent the thing and thus time out waiting for a reply to nothing | |
| 21:42:39 | imacdonn | the reconnect, I mean | |
| 21:43:00 | sean-k-mooney | this is ment to handel the resent i think https://github.com/openstack/oslo.messaging/blob/40c25c2bde6d2f5a756e7169060b7ce389caf174/oslo_messaging/_drivers/impl_rabbit.py#L1088-L1101 | |
| 21:43:59 | sean-k-mooney | for a direct send we do not pass retry | |
| 21:44:11 | imacdonn | I don't see any "Failed to publish message to topic" logged | |
| 21:44:20 | melwitt | yeah that's what confuses me, if publish does a reconnect, why are we left hanging for a timeout? unless we never send a thing like you both mentioned | |
| 21:44:28 | sean-k-mooney | https://github.com/openstack/oslo.messaging/blob/40c25c2bde6d2f5a756e7169060b7ce389caf174/oslo_messaging/_drivers/impl_rabbit.py#L1204-L1213 | |
| 21:45:03 | dansmith | melwitt: it would be if the act of sending triggered the "huh, this is dead, lemme reconnect" but was not followed by a "okay, now that I have reconnected, let me send that thing I had" | |
| 21:45:13 | melwitt | aye | |
| 21:45:20 | dansmith | because socket.write() is where you find out it's dead | |
| 21:45:30 | dansmith | which is how heartbeat is finding out | |
| 21:45:42 | dansmith | it gets scheduled, and does a "shit I'm late.. socket.write(heartbeat mofo!)" | |
| 21:46:17 | melwitt | right | |
| 21:51:17 | melwitt | sean-k-mooney: yeah, I don't know the difference between direct_send and topic_send. though topic_send sounds more like what's probably being used | |
| 21:52:25 | melwitt | (based on the fact that our message queues all have topics, I would think that means those are topic_send, but I don't actually know) | |
| 21:53:59 | sean-k-mooney | so we are invoking the get_vnc_console as a "call" | |
| 21:54:01 | sean-k-mooney | https://github.com/openstack/oslo.messaging/blob/40c25c2bde6d2f5a756e7169060b7ce389caf174/oslo_messaging/rpc/client.py#L157-L182 | |
| 21:54:34 | sean-k-mooney | which im still tracing to see if it sa topic send or a direct send | |
| 21:55:27 | sean-k-mooney | that is where we do the actul call in the nova side https://github.com/openstack/nova/blob/eae1f2257a9ee6e851182bf949568b1cfe2af763/nova/compute/rpcapi.py#L635-L640 | |
| 21:56:51 | sean-k-mooney | im getting flashbacks to the openstack bootstrap podcast looking at this code | |
| 22:01:14 | sean-k-mooney | ok instesting so | |
| 22:01:29 | sean-k-mooney | _send_reply uses a direct send | |
| 22:02:10 | sean-k-mooney | and that is used for this heartbeat https://github.com/openstack/oslo.messaging/blob/40c25c2bde6d2f5a756e7169060b7ce389caf174/oslo_messaging/_drivers/amqpdriver.py#L174 | |
| 22:03:07 | sean-k-mooney | but this is the send function that matters https://github.com/openstack/oslo.messaging/blob/40c25c2bde6d2f5a756e7169060b7ce389caf174/oslo_messaging/_drivers/amqpdriver.py#L581 | |
| 22:07:08 | sean-k-mooney | ok so ya its a topic_send https://github.com/openstack/oslo.messaging/blob/40c25c2bde6d2f5a756e7169060b7ce389caf174/oslo_messaging/_drivers/amqpdriver.py#L628 | |
| 22:08:18 | sean-k-mooney | which means the retry behavior is contoled by the context object | |
| 22:26:41 | openstackgerrit | Eric Fried proposed openstack/nova master: DNM: Revert "Use external placement in functional tests" https://review.opendev.org/659680 | |
| 22:29:46 | sean-k-mooney | ok dumb question but where does the context objec we use to sent the rpc call come form | |
| 22:31:18 | sean-k-mooney | context = req.environ['nova.context'] | |
| 22:31:38 | sean-k-mooney | so what sets that... | |
| 22:32:51 | sean-k-mooney | this https://github.com/openstack/nova/blob/c6218428e9b29a2c52808ec7d27b4b21aadc0299/nova/api/auth.py#L95-L105 ? | |
| 22:36:31 | sean-k-mooney | no that has to be the wrong context that the keystone atuth context | |
| 22:39:47 | sean-k-mooney | ok i give up i cant tell if we actully set retry to ture | |
| 22:40:08 | imacdonn | I suppose I could add debug logging to find out | |
| 22:40:13 | sean-k-mooney | what i can tell is we dont set it expreclity wehn we call prepare in which case retry is check in the context | |
| 22:41:30 | melwitt | I think the keystone middleware does that https://docs.openstack.org/keystonemiddleware/latest/middlewarearchitecture.html | |
| 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 | |