| Posted | Nick | Remark | |
|---|---|---|---|
| #openstack-nova - 2019-05-16 | |||
| 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 | mnaser | Let me grep some logs | |
| 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: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 | =ERROR REPORT==== 16-May-2019::16:45:39 === | |
| 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 | missed heartbeats from client, timeout: 60s | |
| 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 | |
| 17:54:02 | imacdonn | the "other person" is here: https://bugs.launchpad.net/nova/+bug/1825584/comments/7 | |
| 17:54:02 | openstack | Launchpad bug 1825584 in OpenStack Compute (nova) "eventlet monkey-patching breaks AMQP heartbeat on uWSGI" [Undecided,New] | |
| 17:54:07 | dansmith | imacdonn: can you also try disabling rabbit heartbeats on a wsgi api node? just to see if that eliminates the log noise | |
| 17:54:11 | dansmith | imacdonn: even if on the devstack | |
| 17:54:40 | melwitt | imacdonn: that's the bug I linked, I think, and the proposed patch is the stop monkey patching nova-api | |
| 17:54:55 | imacdonn | what do you mean by "log noise"? or are you just asking me to test if it's possible to disable heartbeats at all ? | |
| 17:55:09 | melwitt | but in that bug report, he says that rabbit reconnects | |
| 17:55:25 | imacdonn | that's my bug report, but he commented on it | |
| 17:55:42 | melwitt | no, the bug I linked you | |
| 17:55:45 | dansmith | imacdonn: I mean the log noise where nova-api complains that the connection was reset before reconnecting (in mnaser's case) | |
| 17:55:52 | melwitt | imacdonn: https://bugs.launchpad.net/tripleo/+bug/1827744 | |
| 17:55:54 | 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:55:54 | dansmith | i.e. this: [10:46:02] <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:56:35 | sean-k-mooney | actully in the api we dont really care about hearbeat to rabbitmq right | |
| 17:57:08 | dansmith | sean-k-mooney: I've been shouting that for hours, yes:) | |
| 17:57:22 | dansmith | there's really no reason to maintain a persistent connection to rabbit from an idle api worker | |
| 17:57:27 | sean-k-mooney | actullly i was going to say we never actully listen for anyting from the api but i guess we do if we make a blocking call | |
| 17:57:31 | imacdonn | melwitt: ah, I see .. OK ... yeah, maybe it was non-fatal in his case | |
| 17:57:37 | mnaser | I think the connection reset by peer is the real issue, I think the warning is log noise | |
| 17:57:41 | dansmith | sean-k-mooney: only in the reply case, which isn't a problem here | |
| 17:57:47 | sean-k-mooney | ya | |
| 17:58:01 | dansmith | mnaser: the connection reset by peer is because we're not running the heartbeat thread, and thus is expected | |
| 17:58:16 | sean-k-mooney | so even if the connect drops due to in activity in the normal case we just fire and forget | |
| 17:58:19 | dansmith | mnaser: it's the "this is dead let me reconnect immediately" signal, which seems to be working fine for you | |
| 17:58:28 | dansmith | sean-k-mooney: right | |
| 17:58:50 | mnaser | I'm in china and its 2am but for thee last time I'll say it | |
| 17:59:03 | mnaser | if you're getting 500s, it probably threw a traceback, and that'll probably contain something useful | |