| Posted | Nick | Remark | |
|---|---|---|---|
| #openstack-nova - 2019-05-16 | |||
| 18:27:26 | sean-k-mooney | >>> gt = eventlet.greenthread.spawn(func) | |
| 18:27:28 | sean-k-mooney | >>> gt.wait() | |
| 18:27:30 | sean-k-mooney | it does not take 40 secods to print | |
| 18:27:50 | dansmith | sean-k-mooney: because you're using eventlet's sleep right? | |
| 18:27:58 | sean-k-mooney | yes | |
| 18:28:12 | imacdonn | mnaser (if still awake?), dansmith, sean-k-mooney: log from the failure-to-reconnect case: http://paste.openstack.org/show/751486/ | |
| 18:28:24 | dansmith | that does't mean it's concurrent, that means it's warping time for you :) | |
| 18:31:59 | mnaser | Looks like conductor yoking our | |
| 18:32:05 | mnaser | Timing out | |
| 18:32:31 | mnaser | I’ve seen really weird behaviour thy usually gets resolved by deleting every single queue in the vhost | |
| 18:33:34 | sean-k-mooney | dansmith: well in anycase i think we now now why its working if you dont monkeypatch | |
| 18:33:53 | dansmith | yup, as expected | |
| 18:33:54 | sean-k-mooney | there it concurant of fully synconous i dont know | |
| 18:35:51 | dansmith | sean-k-mooney: run this and tell me what you think :) https://pastebin.com/XHV9t9cM | |
| 18:36:01 | imacdonn | mnaser: this happens when the monkey patching is used in combination with a wsgi container ... and doesn't happen otherwise | |
| 18:36:32 | dansmith | sean-k-mooney: one single wait, but it clearly runs them in order, and blocking calls block everything | |
| 18:36:43 | melwitt | imacdonn: not sure what else to try other than a python2 devstack test maybe, to try and pinpoint what is the difference in your env vs the others. mnaser, are you running stein under py3 or py2? | |
| 18:37:28 | imacdonn | melwitt: yeah, thought about py2 devstack too | |
| 18:40:59 | sean-k-mooney | yes it took 53 seconds | |
| 18:41:04 | sean-k-mooney | but https://pastebin.com/QN5L7yDY took 5 | |
| 18:41:20 | sean-k-mooney | time.sleep will suppend the thread | |
| 18:41:44 | sean-k-mooney | eventlet.greenthread.sleep shoudl yeild to the next coroutine | |
| 18:41:52 | dansmith | sean-k-mooney: ah I see what you mean.. we will still get *interleaving* but not actual concurrency | |
| 18:42:15 | dansmith | sean-k-mooney: meaning we're not running multiple concurrent threads, but we will interleave their execution when they do stuff that calls into eventlet | |
| 18:42:20 | sean-k-mooney | we will get concurrency but not parrallisium | |
| 18:42:36 | sean-k-mooney | yes | |
| 18:42:42 | dansmith | sean-k-mooney: the thing I think you're missing is that if we haven't monkeypatched, then all our IO is blocking and so the first thing will be like time.sleep() andnot like eventlet.sleep() | |
| 18:43:20 | dansmith | first thing meaning first bit of IO | |
| 18:44:14 | sean-k-mooney | ya i was onding if we could import eventlet.green or somting | |
| 18:44:16 | sean-k-mooney | https://eventlet.net/doc/patching.html#import-green | |
| 18:44:38 | sean-k-mooney | our use a contex manger to patch or jsut the socket lib | |
| 18:45:12 | dansmith | I think that gets us further into the mixing paradigms state and confusion abounds, IMHO | |
| 18:45:25 | sean-k-mooney | ya perhaps | |
| 18:45:51 | sean-k-mooney | so we orginally merged the new scater gather stuff that used eventlests without monkey patching | |
| 18:46:09 | sean-k-mooney | then we noticed we were not monkeypatch and mdbooth fixed that | |
| 18:46:22 | dansmith | *for api running under wsgi | |
| 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 | |