| Posted | Nick | Remark | |
|---|---|---|---|
| #openstack-nova - 2019-05-16 | |||
| 17:14:28 | imacdonn | or... | |
| 17:14:29 | imacdonn | # | |
| 17:14:29 | imacdonn | enable-threads = true | |
| 17:14:29 | imacdonn | # grep threads /etc/nova/nova-api-uwsgi.ini | |
| 17:14:34 | imacdonn | (this is on devstack) | |
| 17:15:41 | imacdonn | thinking about that some more ... I think if enable-threads was not on, the heartbeat thread would not work in the non-patched case (?) | |
| 17:15:47 | imacdonn | guess I could attempt to test that | |
| 17:16:59 | imacdonn | confirmed that I do have enable-threads in my "real" (non-devstack) config too | |
| 17:18:22 | openstackgerrit | Stephen Finucane proposed openstack/nova master: Fix some issues with the newton release notes https://review.opendev.org/659623 | |
| 17:18:56 | dansmith | so, | |
| 17:19:00 | dansmith | thinking about this some more | |
| 17:19:16 | openstackgerrit | Stephen Finucane proposed openstack/nova master: Use new hotness for upper-constraints https://review.opendev.org/659624 | |
| 17:19:26 | dansmith | I'm not sure how eventlet could really ever work in the wsgi mode, because background tasks really require the main thread to block on the event loop | |
| 17:19:46 | dansmith | I'm struggling to find where the entry point is for nova-api in wsgi mode... | |
| 17:21:10 | imacdonn | that seems to be the consensus ... eventlet and wsgi containers seem fundamentally incompatible | |
| 17:21:23 | dansmith | well, | |
| 17:21:25 | dansmith | not really, | |
| 17:21:32 | dansmith | just wsgi+eventlet with a background thread | |
| 17:21:59 | imacdonn | ok | |
| 17:23:38 | imacdonn | FWIW, with enable-threads turned off, and monkey patching still removed, it looks the same - no heartbeats after the API request that opens an RPC connection | |
| 17:23:59 | dansmith | yeah, not running the event loop means we'll just never do that thing | |
| 17:25:17 | dansmith | tbh, it kinda seems like what we should be doing is splitting nova-api into two pieces in a wsgi world | |
| 17:25:23 | dansmith | which is, of course, not how it was designed | |
| 17:25:32 | imacdonn | someone else suggested that | |
| 17:27:33 | dansmith | mnaser: you around? | |
| 17:28:05 | dansmith | imacdonn: how instantaneous is the reconnect to rabbit on devstack? | |
| 17:28:48 | imacdonn | no perceptible delay | |
| 17:29:08 | mnaser | dansmith: hiya | |
| 17:29:30 | dansmith | mnaser: you are on stein and running nova-api in wsgi something right? | |
| 17:29:47 | mnaser | Correct. Uwsgi | |
| 17:30:01 | dansmith | mnaser: and you don't see this rabbit heartbeat timeout freezeup thing correct? | |
| 17:30:33 | mnaser | I have not. I thought the ML post thread concluded it was mod_wsgi related ? | |
| 17:30:42 | dansmith | mnaser: nope, both apparently | |
| 17:31:18 | dansmith | mnaser: imacdonn says it's reproducible in devstack too, but it just reconnects instantaneously and thus isn't a problem (which is what ideal behavior should be) | |
| 17:31:21 | mnaser | Hmm, I mean, maybe it could be? I’ve not seen any issues but maybe our APIs get hit often enough? | |
| 17:31:29 | dansmith | i.e. not requiring the wsgi app to run a daemon thread to maintain a connection | |
| 17:32:08 | dansmith | mnaser: possible I guess. is there any way you could take one worker out of LB rotation and see if it hangs up after a couple minutes if you hit it directly? | |
| 17:32:08 | mnaser | Let me grep some logs | |
| 17:32:14 | mnaser | What string should I look for? | |
| 17:32:20 | dansmith | imacdonn: ^ | |
| 17:32:31 | imacdonn | QRX ... reproducing again | |
| 17:32:36 | imacdonn | erm, I mean .. standby :) | |
| 17:32:46 | dansmith | imacdonn: ah, so you are the ham I keep finding in my googling :D | |
| 17:33:02 | imacdonn | even an occasional chirp user ;) | |
| 17:33:16 | dansmith | hah nice | |
| 17:34:15 | mnaser | gosh the latency is awful from here | |
| 17:34:26 | mnaser | oh actually | |
| 17:34:31 | mnaser | I have a quiet stein cloud here | |
| 17:35:05 | dansmith | imacdonn: is it possible that mod_wsgi is the reason you don't get a reconnect and that uwsgi, despite pausing, makes that just work? | |
| 17:35:22 | imacdonn | mnaser: one think you could look for is, in your rabbitmq server log: | |
| 17:35:23 | imacdonn | missed heartbeats from client, timeout: 60s | |
| 17:35:23 | imacdonn | closing AMQP connection <0.4566.0> (x.x.x.x:34178 -> x.x.x.x:5672 - uwsgi:47892:8bc2c402-d1d4-4762-9b83-29a7b7f419fd): | |
| 17:35:23 | imacdonn | =ERROR REPORT==== 16-May-2019::16:45:39 === | |
| 17:35:50 | imacdonn | dansmith: no, because I'm using uWSGI "for real" too | |
| 17:35:57 | dansmith | okay | |
| 17:37:43 | mnaser | so is it only something logged inside RabbitMQ? | |
| 17:39:58 | imacdonn | trying to get the nova-api side logs .. I'll have to clean and pastebin them | |
| 17:42:43 | mnaser | im seeing this on a lightly loaded stein cluster 'missed heartbeats from client, timeout: 60s' | |
| 17:42:53 | mnaser | gonna see what nova logs say | |
| 17:43:54 | imacdonn | is there a handy place I can upload 10k lines of log to ? | |
| 17:44:45 | mnaser | 2019-05-16 17:38:53.643 3897 WARNING oslo.messaging._drivers.impl_rabbit [-] Unexpected error during heartbeart thread processing, retrying...: error: [Errno 104] Connection reset by peer | |
| 17:45:10 | dansmith | mnaser: but sounds like it's recovering when a new call comes in such that it's not noticeable? | |
| 17:45:31 | imacdonn | mnaser: yes! that's one of symptoms | |
| 17:45:33 | dansmith | bnemec: do you know if there's a way to turn off the heartbeat thread for rabbit? | |
| 17:45:40 | mnaser | but is there a problem however? | |
| 17:45:50 | dansmith | bnemec: for o.msg's rabbit driver I mean | |
| 17:45:59 | mnaser | like n-api seems to continue to respond fine afterwards | |
| 17:46:05 | mnaser | 2019-05-16 17:38:53.644 3897 WARNING oslo.messaging._drivers.impl_rabbit [-] Unexpected error during heartbeart thread processing, retrying...: error: [Errno 104] Connection reset by peer | |
| 17:46:18 | bnemec | There used to be. It was considered experimental for a couple of cycles. Let me look. | |
| 17:46:19 | dansmith | mnaser: yeah, so that's the behavior we would expect | |
| 17:46:26 | mnaser | but at a 17:38:54 a GET /v2.1/servers/uuid worked fine | |
| 17:46:39 | dansmith | dunno why imacdonn isn't getting that proper reconnect behavior | |
| 17:46:53 | dansmith | turning off the heartbeat thread for the wsgi workers would eliminate the log noise I think | |
| 17:47:24 | mnaser | rabbitmq heartbeats are super unreliable in my experience | |
| 17:47:26 | bnemec | dansmith: https://github.com/openstack/oslo.messaging/blob/master/oslo_messaging/_drivers/impl_rabbit.py#L145 | |
| 17:47:30 | mnaser | there used to be a nice article about configuring timeouts | |
| 17:47:48 | efried | aspiers: not sure I ever looked at that. | |
| 17:47:49 | imacdonn | yeah, perhaps I need to look closer at that ... but still, I think that heartbeats are there for a reason, and letting connections rot and "fail by design" is kinda icky | |
| 17:47:54 | mnaser | https://medium.com/@george.shuklin/rabbit-heartbeat-timeouts-in-openstack-fa5875e0309a | |
| 17:48:04 | mnaser | dunno how relevant it is but | |
| 17:48:06 | mnaser | a good read none the less | |
| 17:48:50 | dansmith | imacdonn: yeah, I just don't think I agree :) | |
| 17:48:58 | imacdonn | if nova-api isn't going to use persistent AMQP connections, it should gracefully close the connection before it goes to sleep, IMO | |
| 17:49:23 | mnaser | my question is: is there a problem? are your requests forever 500-ing after? | |
| 17:49:24 | dansmith | nova-api doesn't go to sleep | |
| 17:49:26 | melwitt | what's the behavior when it doesn't properly reconnect? nova-api responds with a failure? | |
| 17:49:32 | mnaser | ^^ | |
| 17:49:51 | imacdonn | yeah, I get some sort of 50x error | |
| 17:50:26 | dansmith | presumably because something is getting stuck and not letting the connections close off, which is why I want to know why imacdonn is different from the rest of the world | |
| 17:50:28 | mnaser | if you get a 50x that means you have aa traceback, right? | |
| 17:51:02 | imacdonn | dansmith: hey now .. there was at least one other person experiencing the failures | |
| 17:51:29 | mnaser | should you have a traceback if you're getting a 500? | |
| 17:51:33 | dansmith | imacdonn: I meant your deployment, not you as a person :) | |
| 17:51:59 | imacdonn | well, yeah, but the other person was using a different deployment, and mod_wsgi | |
| 17:52:16 | dansmith | imacdonn: ^ | |
| 17:53:14 | efried | mriedem: Were you going to put up a null nova change depending on https://review.opendev.org/659611 to make sure the ironic-tempest-ipa-wholedisk-bios-agent_ipmitool-tinyipa job passes? | |
| 17:53:19 | melwitt | I had thought someone else faced this behavior too, but looking at the bug report, they say it reconnects https://bugs.launchpad.net/tripleo/+bug/1827744 | |
| 17:53:20 | openstack | Launchpad bug 1827744 in tripleo "Running eventlet.monkey_patch in nova_api breaks the AMQP heartbeat thread" [High,In progress] - Assigned to Damien Ciabrini (dciabrin) | |
| 17:53:23 | efried | or does ironic run that job too? | |
| 17:53:26 | imacdonn | I'll have to rebuild my "real" environment with uWSGI and reproduce again, if we need more context around the failure to reconnect ... I'd already started down the path of reverting to running nova-api standalone, since there didn't seem to be a path forward | |