| Posted | Nick | Remark | |
|---|---|---|---|
| #openstack-nova - 2019-05-16 | |||
| 21:39:09 | imacdonn | I wonder if part of the issue is that the AMQP message is not being resent in the case where the connection reset is detected during publish, vs. during heartbeat | |
| 21:40:20 | melwitt | I wonder that too | |
| 21:40:43 | dansmith | imacdonn: meaning if we hit it on publish, we reconnect, but didn't actually send, think we did, and wait for it until timeout? | |
| 21:40:50 | dansmith | if so that would be a giant o.msg bug | |
| 21:41:12 | imacdonn | yeah, smth like that | |
| 21:41:26 | melwitt | but I think we know it won't reconnect on publish right | |
| 21:41:45 | melwitt | otherwise the 500 wouldn't happen | |
| 21:41:49 | dansmith | no, | |
| 21:41:55 | dansmith | the 500 is from timeout right? | |
| 21:42:02 | melwitt | yeah | |
| 21:42:02 | dansmith | which means it's waiting for a reply | |
| 21:42:11 | imacdonn | 504 from timeout, yeah | |
| 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:28 | imacdonn | look at http://paste.openstack.org/show/751486/ - the reset follows the publish failure, not a heartbeat failure | |
| 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 | |