| Posted | Nick | Remark | |
|---|---|---|---|
| #openstack-nova - 2019-05-16 | |||
| 21:18:19 | sean-k-mooney | and we did not reconnect before teh timeout expired | |
| 21:18:27 | sean-k-mooney | so the set succfully | |
| 21:18:40 | sean-k-mooney | then it closed and they never go tthe resopnece | |
| 21:18:52 | melwitt | ok | |
| 21:19:13 | sean-k-mooney | which likely means when we recoonet it will be sitting on the queue | |
| 21:21:13 | sean-k-mooney | things like the inststance list would likely be fine in that case | |
| 21:21:31 | sean-k-mooney | since the api is hitting all the cell dbs but not doing an rpc right | |
| 21:21:43 | sean-k-mooney | but things like get_vnc_console woudl fail | |
| 21:21:50 | efried | cmart: what does your [DEFAULT]virt_mkfs option look like? | |
| 21:23:05 | sean-k-mooney | thing like boot would likely be fine too since thats fire and forget | |
| 21:23:28 | imacdonn | so now I'm wondering if the connection reestablishment is working "by accident" with threads=1, or if I can depend on it........ | |
| 21:23:44 | cmart | efried I haven't defined it (on Queens, Ubuntu 16.04) so probably the default | |
| 21:24:07 | sean-k-mooney | well with threads=1 thre is a 50% change the connetion tread will run | |
| 21:24:20 | sean-k-mooney | sicne there is the main thread + the heatbeat thread | |
| 21:26:38 | melwitt | :\ | |
| 21:27:16 | sean-k-mooney | i did not say it woudl definetly work :P | |
| 21:27:23 | dansmith | sean-k-mooney: there's only one thread, | |
| 21:27:25 | sean-k-mooney | but its better then 1 in 9 | |
| 21:27:45 | imacdonn | so if I set threads=0, will it be 100% ? :) | |
| 21:27:50 | melwitt | lol | |
| 21:28:02 | sean-k-mooney | dansmith: the rabbitmq direver spawn a thread to run the heatbeat check | |
| 21:28:14 | dansmith | and I think that if we're monkeypatched, any io we do will always guarantee that we run the waiting greenthreads, so we'd consume the dead connection with the heartbeat right? | |
| 21:28:14 | sean-k-mooney | https://github.com/openstack/oslo.messaging/blob/9.5.0/oslo_messaging/_drivers/impl_rabbit.py#L884 | |
| 21:28:22 | dansmith | sean-k-mooney: green thread | |
| 21:28:50 | sean-k-mooney | ah your right if its monkey patched then its a greenthread | |
| 21:29:17 | dansmith | right, | |
| 21:29:22 | dansmith | so we'll always run that stuff on first io | |
| 21:29:43 | sean-k-mooney | i guess it depends on how many io operation were pending or had yeilded | |
| 21:29:46 | dansmith | I think if it was 50% we'd have heard about it | |
| 21:29:57 | dansmith | howso? | |
| 21:30:43 | efried | cmart: It looks like that name is being assigned in this neighborhood: https://opendev.org/openstack/nova/src/branch/stable/queens/nova/virt/libvirt/driver.py#L3510 | |
| 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 | |