| Posted | Nick | Remark | |
|---|---|---|---|
| #openstack-nova - 2019-05-16 | |||
| 16:41:43 | mriedem | i did before -1ing it | |
| 16:44:03 | mriedem | but now i am :) | |
| 16:51:07 | imacdonn | dansmith: I've reproduced the lack of heartbeats on devstack (and confirmed that the heartbeats happen if monkey patching is removed) ... but somehow (so-far) devstack is able to recover from the unexpected loss of amqp connection, where my RDO environment is (sometimes) not | |
| 16:51:56 | dansmith | okay so devstack is behaving like we would expect, assuming the pause-the-interpreter wsgi behavior you describe | |
| 16:52:21 | imacdonn | so-far, I suppose so | |
| 16:52:40 | imacdonn | if the pause is considered "expected" | |
| 16:56:48 | dansmith | if the pause isn't, then the problem is in the configuration of the wsgi container or something else | |
| 16:57:29 | imacdonn | but it only happens when python has been monkeyed-with | |
| 16:58:06 | dansmith | mm, I think you're misunderstanding | |
| 16:58:13 | dansmith | I think that wsgi is pausing regardless, | |
| 16:58:22 | dansmith | and in the eventlet case, there is only one thing to pause, so it pauses | |
| 16:58:38 | dansmith | and without eventlet, we spawn a real thread that the wsgi container does not pause (only the main thread) | |
| 16:59:07 | dansmith | which is why I say that if the design of the wsgi container is to pause the whole thing between requests, then us subverting that with a real thread seems wrong | |
| 16:59:17 | imacdonn | I definitely don't understand the mechanisms well enough ... so my observation is fairly high-level ... in one case, the heartbeats happen, so it seems awake .. in the other case, it goes completely quiet | |
| 17:00:10 | imacdonn | so if it's wrong, the whole oslo_messaging model seems inappropriate ..... ??? | |
| 17:00:28 | imacdonn | cos it does heartbeats quite intentionally, AFAIK ... | |
| 17:00:49 | dansmith | well, o.msg _was_ developed with eventlet servers in mind | |
| 17:06:11 | dansmith | so here's a random person asking a similar question: https://github.com/benoitc/gunicorn/issues/1924 | |
| 17:06:29 | dansmith | not much response there, except that it basically says "don't spawn worker threads from your wsgi app" | |
| 17:08:50 | dansmith | check this out: https://docs.newrelic.com/docs/agents/python-agent/web-frameworks-servers/python-agent-uwsgi-web-server | |
| 17:09:05 | dansmith | "By default uWSGI does not enable threading support within the Python interpreter core. This means it is not possible to create background threads from Python code. " | |
| 17:09:35 | dansmith | ...which might mean that disabling eventlet and letting threading be unpatched just gets you synchronous behavior | |
| 17:11:04 | dansmith | I wonder if using --enable-threads but leaving the monkeypatching in place would allow the eventlet background threads to run? | |
| 17:12:02 | imacdonn | "By default the Python plugin does not initialize the GIL. This means your app-generated threads will not run. If you need threads, remember to enable them with enable-threads. Running uWSGI in multithreading mode (with the threads options) will automatically enable threading support. This “strange” default behaviour is for performance reasons, no shame in that." | |
| 17:12:17 | imacdonn | ^ from https://uwsgi-docs.readthedocs.io/en/latest/ThingsToKnow.html | |
| 17:12:39 | dansmith | yeah, just saw that.. so... do you have threads enabled? | |
| 17:12:59 | imacdonn | checking ... probably not | |
| 17:14:02 | dansmith | if I were you, I'd really want to find out why devstack recovers properly and yours does not though | |
| 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 | |