| Posted | Nick | Remark | |
|---|---|---|---|
| #openstack-nova - 2019-05-16 | |||
| 18:46:23 | sean-k-mooney | and we strated to see these uwsgi errors | |
| 18:46:31 | sean-k-mooney | ya | |
| 18:48:01 | sean-k-mooney | so setting the env var would allow people to go back to the un monkeypatched versions under wsgi with no code change but its nolonger paralle | |
| 18:48:11 | dansmith | exactly | |
| 18:48:36 | sean-k-mooney | although in that case uwsgi/apache would still provde its own concurancy | |
| 18:49:06 | dansmith | sean-k-mooney: between requests, but not between cells | |
| 18:49:14 | dansmith | cells would still be sequential | |
| 18:49:19 | sean-k-mooney | yes | |
| 18:49:44 | sean-k-mooney | im just thinking about what people can do as a workaound in the short term | |
| 18:50:04 | sean-k-mooney | e.g. what can people do that hit this in production | |
| 18:50:06 | dansmith | people being the 1.9 people we know that are having this problem right? :) | |
| 18:51:13 | sean-k-mooney | well i think the only reason that we are not seeing this in osp is because hte kolla container use the console-script in the container instead of running under wsgi | |
| 18:51:28 | sean-k-mooney | so i think that is why we are not hitting it downstream | |
| 18:51:47 | sean-k-mooney | but i dont know what other deployment tools default too | |
| 18:52:04 | dansmith | well, we got the vexxhost data that they're reconnecting properly | |
| 18:52:18 | sean-k-mooney | in osa | |
| 18:52:23 | sean-k-mooney | *with | |
| 18:52:24 | dansmith | so they're clearly seeing the same threading behavior, but not suffering | |
| 18:52:25 | dansmith | i.e. they're getting the best of both worlds | |
| 18:59:23 | sean-k-mooney | perhaps its because they are installing the nova api under uwsgi and not mod_wsgi | |
| 18:59:52 | sean-k-mooney | imacdonn: what are you running the nova-api with? | |
| 19:00:45 | imacdonn | sean-k-mooney: uWSGI ... I've also reproduced the heartbeats not happening with mod_wsgi, but I can't say if I've seen the failure to "establish a new connection and move on" in that case | |
| 19:01:39 | sean-k-mooney | we know that uwsgi and mod_wsgi handel the lifetime of there python interperters diffrently so model level variable are reinitalised in uwsgi but are not in mod_wsgi becuase it reuses the interpreter when the app is reloaded an uwisg does not | |
| 19:01:54 | sean-k-mooney | *module level | |
| 19:02:45 | sean-k-mooney | imacdonn: if the wsgi app dies and is restarted by uwsgi it will return to a clean state | |
| 19:03:11 | sean-k-mooney | in the mod_wsgi case it will reuse the interperter and maybe that impact the reconnection | |
| 19:03:16 | sean-k-mooney | that is a strech however | |
| 19:03:48 | sean-k-mooney | we are seeing it not reconnect on mod_wsgi correct? | |
| 19:04:05 | imacdonn | I don't see any evidence of the app dying and being restarted | |
| 19:04:50 | melwitt | sean-k-mooney: we're not sure what the common denominator is for not reconnecting and 500ing, I think | |
| 19:05:18 | melwitt | I have a python2 devstack, going to check whether it reconnects | |
| 19:05:20 | sean-k-mooney | if it was you would see nova print it config again and all the other start up stuff so if you are not seeing that its proably not happening then | |
| 19:05:43 | sean-k-mooney | ok that is testing with uwsgi then | |
| 19:05:49 | imacdonn | yeah .. the 504 error seems to be caused by an RPC timeout following the reconnect ... don't yet know why I'm seeing that where others are not | |
| 19:06:31 | sean-k-mooney | do we have any periodic task that could be keeping it alive? | |
| 19:06:39 | imacdonn | I can't say I've reproduced the RPC timeout with mod_wsgi - was focused on the absence of heartbeats before | |
| 19:07:08 | dansmith | sean-k-mooney: if you read the backscroll, it has been reprod with both | |
| 19:07:30 | imacdonn | I'm not able to reproduce the RPC timeout with py2 devstack either | |
| 19:08:16 | melwitt | how do you get the connection reset by peer message to show up in nova-api log? just waiting doesn't seem to do it | |
| 19:08:39 | dansmith | request after a delay I think | |
| 19:08:54 | sean-k-mooney | i tought it was 2 different errors one on each but ok in that case ill stop looking to see what the differe is between how the both run | |
| 19:08:59 | imacdonn | I have an instance already running.. I make a call to get the VNC console URL, wait about 5 mins, then repeat the call to get the console URL | |
| 19:09:39 | sean-k-mooney | that shoudl not need to hit rabbit | |
| 19:09:53 | sean-k-mooney | that should just hit the db directly no? | |
| 19:09:54 | dansmith | sean-k-mooney: eh | |
| 19:10:02 | sean-k-mooney | to get the url | |
| 19:10:08 | dansmith | no, it calls to the driver | |
| 19:10:10 | sean-k-mooney | to get teh console it woudl have to do an rpc | |
| 19:10:49 | sean-k-mooney | oh ok i assuem we would have sored the console url in the db | |
| 19:13:29 | melwitt | it is stored there afterward (base url and token hash, etc) but the driver hands out the connection details initially | |
| 19:14:28 | melwitt | ok yeah I see now the "Unexpected error during heartbeart thread processing, retrying...: error: [Errno 104] Connection reset by peer" happens on the second request after waiting some minutes. but the request works fine | |
| 19:15:27 | melwitt | (with py2 and uwsgi) | |
| 19:15:38 | sean-k-mooney | ok but this is what get console is actully doing right https://github.com/openstack/nova/blob/master/nova/console/api.py#L27-L29 | |
| 19:17:01 | sean-k-mooney | or rather openstack console url show | |
| 19:17:06 | melwitt | I think that's probably the xen-specific service nova-console stephenfin is looking to deprecate | |
| 19:17:47 | melwitt | this is get_vnc_console https://github.com/openstack/nova/blob/master/nova/compute/api.py#L3876 | |
| 19:17:53 | sean-k-mooney | that is what called form here https://github.com/openstack/nova/blob/master/nova/api/openstack/compute/consoles.py#L48 | |
| 19:18:37 | sean-k-mooney | oh ok so that one does a downcall to the compute cool | |
| 19:18:41 | melwitt | I think that's the xen thing that no one except old rax cluster uses | |
| 19:19:05 | dansmith | this is one reason I suggested using a different call | |
| 19:19:14 | dansmith | because console has all manner of stuff wrapped up in it | |
| 19:19:25 | dansmith | I think pause/unpause is a call right? use that | |
| 19:19:33 | dansmith | or just boot/delete | |
| 19:19:43 | imacdonn | looking at my py2 devstack, it seems the connection reset is observed at a difference place | |
| 19:19:47 | sean-k-mooney | ya or the server diagnostics | |
| 19:19:50 | dansmith | well, boot isn't a call from the apiI guess, so pause | |
| 19:19:53 | dansmith | sean-k-mooney: or that | |
| 19:20:51 | sean-k-mooney | ... of cose they are only in the nova client... | |
| 19:20:53 | melwitt | imacdonn: in my py2 devstack, I see the connection reset in nova-api log (for get_vnc_console) | |
| 19:22:06 | sean-k-mooney | nova diagnostics <server> is definetly a down call to the compute but nova get-vnc-console should be too | |
| 19:43:05 | sean-k-mooney | efried: just finsihed reviewing https://review.opendev.org/#/q/topic:bug/1809095+(status:open+OR+status:merged) | |
| 19:43:41 | sean-k-mooney | efried: im provisionly +1 on both i have one question on the second patch but its and edgecase | |
| 19:55:16 | imacdonn_ | sean-k-mooney: vnc console does rpc .. you can see it in the trace at http://paste.openstack.org/show/751486/ | |
| 19:55:31 | imacdonn_ | (the trace for the RPC timeout) | |
| 19:56:10 | sean-k-mooney | those call to the compute node? ya | |
| 19:56:33 | imacdonn_ | yes | |
| 19:56:36 | sean-k-mooney | but it was not clear what api enpoint osc was calling for openstack console url show | |
| 19:57:10 | sean-k-mooney | if you are using the nova clintes get-vnc-console that was defietly downcalling | |
| 19:57:36 | sean-k-mooney | osc is doing some magic to figure out what console type the vm is uesing | |
| 19:57:49 | sean-k-mooney | as it has a singel command that works for all console types | |
| 19:58:49 | sean-k-mooney | so i was not sure if the osc command would actully hit the db or the compute node | |
| 19:59:26 | imacdonn_ | yeah, def does ... that stack trace resulted from 'openstack console url show ...' | |
| 20:00:43 | sean-k-mooney | its kind of strange | |
| 20:00:54 | sean-k-mooney | we can see the hearbeat_tick printed | |
| 20:01:05 | imacdonn_ | yeah, but only once | |
| 20:01:13 | imacdonn_ | it should be period from that point on | |
| 20:01:17 | imacdonn_ | periodic | |
| 20:01:25 | sean-k-mooney | no its there several times | |
| 20:01:37 | sean-k-mooney | look at line 140 to 153 | |
| 20:01:39 | imacdonn_ | for the same thread? | |
| 20:01:58 | imacdonn_ | in any case, in the non-patched case, it's continuous .. in the patched case, it goes quiet | |
| 20:03:14 | imacdonn_ | those are all within the same second | |
| 20:04:24 | imacdonn_ | I *may* have just found what's different about my env vs. others and devstack | |
| 20:07:58 | sean-k-mooney | have you adjusted any of the messaging timeouts? | |
| 20:09:19 | imacdonn | no, but in my uwsgi config, had "threads = 8" ... I've removed that now, and it seems that the reconnect is working | |
| 20:10:09 | sean-k-mooney | this is the osa one https://opendev.org/openstack/openstack-ansible-os_nova/src/branch/master/templates/nova-uwsgi.ini.j2 | |
| 20:10:34 | imacdonn | I'm thinking (loosely) that maybe in the threads=X case, the thread making the RPC call has fired before the thread handling heartbeats has noticed the connection failure and reestablished | |
| 20:10:48 | sean-k-mooney | which defaults to 1 | |
| 20:11:23 | imacdonn | yeah. devstack doesn't set it at all | |
| 20:11:33 | imacdonn | I was thinking to figure out what uwsgi does by default .. guessing 1 | |