| Posted | Nick | Remark | |
|---|---|---|---|
| #openstack-nova - 2019-05-16 | |||
| 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 | |
| 20:11:41 | imacdonn | I was *trying.... | |
| 20:11:52 | sean-k-mooney | im lookig fot atht too now :) | |
| 20:20:04 | efried | sean-k-mooney: thanks for reviewing. | |
| 20:21:49 | sean-k-mooney | imacdonn: finally https://github.com/unbit/uwsgi/blob/3149df02ed443131c54ea6afb29fcbb0ed4d1139/core/init.c#L96 it default to 1 | |
| 20:22:13 | sean-k-mooney | imacdonn: the default is not in the docs | |
| 20:23:12 | imacdonn | hah, thanks | |
| 20:23:27 | sean-k-mooney | for c code uwsgi is actully not to hard to read but finding stuff is a pain | |
| 20:24:30 | sean-k-mooney | imacdonn: so i think we know why vexhost are fine | |
| 20:24:47 | sean-k-mooney | osa expecitly sets it to 1 | |
| 20:25:11 | imacdonn | yeah, I think so ... the reconnect seems to be consistently working since I've changed that | |
| 20:26:14 | imacdonn | so now I wonder if I'm giving anything up by doing that, in terms of performance .... haven't really found any good guidance on processes/threads sizing for these things | |
| 20:26:49 | sean-k-mooney | well osa is running with 64 processes and 1 thread per process i think | |
| 20:27:03 | sean-k-mooney | sorry a max of 16 processes | |
| 20:27:12 | sean-k-mooney | each with 1 thread | |
| 20:29:09 | dansmith | is this threads per worker process? | |
| 20:29:36 | dansmith | if so, it could be that multiple threads per worker try to share a single connection pool, | |
| 20:29:37 | sean-k-mooney | yes i belive so | |
| 20:29:48 | dansmith | but maybe one of them gets responsibility for the eventlet heartbeat thread,m | |
| 20:30:07 | dansmith | so if that thread isn't the first scheduled after a period of inactivity, then heartbeat isn't run, we try to use the connection and are stuck? | |
| 20:30:11 | dansmith | something like that? | |
| 20:30:27 | imacdonn | yes, "something like that" is what it feels like | |
| 20:30:46 | sean-k-mooney | well im not sure if we have process=2 thread=2 if that wil result in 2 or 4 python interperters | |
| 20:31:05 | sean-k-mooney | e.g. are teh treads os threads or python threads | |
| 20:31:07 | melwitt | so heartbeat threads is the one that reconnects things if detected to not be open | |
| 20:31:08 | dansmith | I think that would mean two interpreters, two threads each | |
| 20:31:13 | melwitt | *thread | |
| 20:31:37 | dansmith | melwitt: no, | |
| 20:31:38 | sean-k-mooney | right so the gil would mean that only one of the two thread woudl actully be running in each python interperter | |
| 20:32:01 | dansmith | I think any of them would do it, but running or not running the heartbeat but definitely running the other threads is where I can see it getting wonky | |
| 20:32:14 | sean-k-mooney | so maybe it is staving the heart beat thread as you suggest | |
| 20:34:50 | melwitt | I guess I'm confused. so far, I thought the heart beat thread doesn't affect anything other than to log a message saying "connection reset" if it's been idle > 60s. how does its starvation prevent reconnection? | |
| 20:36:37 | dansmith | no, I think the heartbeat thread is just the first thin scheduled after a period of inactivity, so it's the first thing that hits the dead connection | |
| 20:36:41 | imacdonn | I don't think reconnection is being prevented .. you can see it happen in the log at http://paste.openstack.org/show/751486/ ... but I tihnk it might matter *when* it happens | |
| 20:37:35 | imacdonn | (line 227 in the log shows reconnected) | |