| Posted | Nick | Remark | |
|---|---|---|---|
| #openstack-nova - 2019-05-16 | |||
| 21:30:46 | sean-k-mooney | well in the scater gater case at least we are querying a bunch of gread threads to execute then waiting | |
| 21:30:59 | dansmith | the heartbeat gthread is always schedulable work on any io switch if we've not run it in t/2 or whatever it's period is | |
| 21:31:33 | dansmith | sean-k-mooney: right but on the first io that we do, to even start that, we'll run all the greenthreads pending, which is at least the heartbeat gthread, before we do much of anything else | |
| 21:31:38 | efried | cmart: that line or L3533 | |
| 21:32:01 | sean-k-mooney | ya we should | |
| 21:33:05 | cmart | efried thank you for the orientation | |
| 21:33:30 | efried | cmart: Good luck :) | |
| 21:38:36 | openstackgerrit | Merged openstack/nova master: Remove fake_libvirt_utils from connection tests. https://review.opendev.org/642557 | |
| 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 | dansmith | which means it's waiting for a reply | |
| 21:42:02 | melwitt | yeah | |
| 21:42:11 | imacdonn | 504 from timeout, yeah | |
| 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 | |