| Posted | Nick | Remark | |
|---|---|---|---|
| #openstack-nova - 2017-05-04 | |||
| 18:47:28 | melwitt | mriedem: sigh ... I miss that config option that used to make format errors fatal for tests | |
| 18:47:42 | mriedem | i don't know why that was removed | |
| 18:47:50 | mriedem | maybe it was too useful | |
| 18:48:38 | melwitt | yeah, really. it was removed as part of the centralize-config-options work, and I tried to recreate the behavior with wonky monkey patching and wasn't successful https://review.openstack.org/#/c/411615 | |
| 18:52:44 | dansmith | 184489 | |
| 18:52:50 | dansmith | heh sorry | |
| 18:53:10 | melwitt | there's been something in the unit tests spewing garbled text into the output for months now, I assume that's another KeyError some place in a test exception | |
| 18:56:37 | openstackgerrit | Eric Fried proposed openstack/nova-specs master: Updates for [glance]api_servers and ksa https://review.openstack.org/461481 | |
| 18:56:47 | efried | mriedem ^^ | |
| 19:05:29 | openstackgerrit | Steve Noyes proposed openstack/nova master: Add Cinder v3 detach to shutdown_instance https://review.openstack.org/456877 | |
| 19:08:20 | dansmith | melwitt: I wonder if I'm failing this test because of legit lack of cells support in consoleauth? http://logs.openstack.org/37/458537/9/check/gate-tempest-dsvm-neutron-full-ubuntu-xenial/fe108a8/logs/testr_results.html.gz | |
| 19:12:45 | melwitt | dansmith: I would guess so. looking to see if we do a target cell for getting the vnc console | |
| 19:13:19 | melwitt | I can't remember what the state of the compute rpcapi mq switching is | |
| 19:13:44 | dansmith | yeah, I think it might actually be in the proxy thing | |
| 19:16:40 | melwitt | in nova/api/openstack/compute/remote_consoles.py it gets an instance and passes it down to get_vnc_console, so if the context has already been targeted by the get_instance, it should work | |
| 19:17:52 | dansmith | melwitt: right, but that's to get the url, right? then we actually connect through the novncproxy to get to the rfb data, | |
| 19:18:01 | dansmith | and it has to know where to proxy to, which is what is failing I think | |
| 19:18:20 | dansmith | it makes a consoleauth rpc call, which may be going to the wrong place, I'm guessing | |
| 19:18:21 | melwitt | oh, yeah. must be | |
| 19:18:44 | dansmith | although I don't see anything barfing about an rpc timeout or anything | |
| 19:19:29 | melwitt | yeah, dtp's change made the consoleauth calls stay at the API and that call shouldn't try to mq switch | |
| 19:20:58 | melwitt | I can never remember how the consoles work. get the url first, now looking for where it does the consoleauth part | |
| 19:21:08 | dansmith | yeah I have to re-learn each time | |
| 19:22:18 | melwitt | okay, the consoleauth is in compute/api, in get_vnc_console, so that should be fine I think | |
| 19:23:04 | dansmith | that's the thing that authorizes, not what checks right? | |
| 19:23:22 | dansmith | yeah | |
| 19:23:31 | dansmith | so we go there, create a token, return a url | |
| 19:23:42 | dansmith | then we connect to the proxy, do a websocket and expect rfb data | |
| 19:23:54 | dansmith | but we have to check the token in there again, and we do a rpc call to do it | |
| 19:24:12 | dansmith | https://github.com/openstack/nova/blob/master/nova/console/websocketproxy.py#L105-L106 | |
| 19:25:00 | melwitt | okay, proxy is running at the API, so is consoleauth, seems like it should be okay | |
| 19:25:20 | dansmith | but the tokens are in the cell db, no? | |
| 19:25:57 | melwitt | tokens are in memcached | |
| 19:26:49 | melwitt | why are there no errors in the logs anywhere :| | |
| 19:27:01 | dansmith | oh, heh, and so the consoleauth service is just there to ask memcache for us for checking tokens? | |
| 19:27:04 | dansmith | yeah, that's the weird thing | |
| 19:27:49 | melwitt | that's my understanding, yeah | |
| 19:28:19 | dansmith | wtf | |
| 19:28:19 | dansmith | yeah, looks like it | |
| 19:28:25 | dansmith | oh no, | |
| 19:28:28 | dansmith | it also calls to compute | |
| 19:28:55 | dansmith | to validate a port | |
| 19:29:06 | dansmith | but it does the mapping lookup and the target | |
| 19:29:16 | dansmith | so yeah seems like maybe no logs because it's mostly working | |
| 19:29:47 | melwitt | I dunno if this is relevant but I don't see a log in consoleauth for the test you're failing http://logs.openstack.org/37/458537/9/check/gate-tempest-dsvm-neutron-full-ubuntu-xenial/fe108a8/logs/screen-n-cauth.txt.gz?#_May_04_18_01_45_091782 | |
| 19:30:44 | dansmith | I do see an authorize console report though | |
| 19:31:06 | dansmith | not for that test though yeah | |
| 19:31:25 | melwitt | yeah, based on the project/user names from the context | |
| 19:33:04 | dansmith | so, I see the corresponding things in n-api.log for that server actions test, | |
| 19:33:09 | dansmith | but nothing for the vnc test | |
| 19:33:15 | dansmith | dub tee eff | |
| 19:34:03 | melwitt | I can't even find that server uuid in n-api log | |
| 19:34:09 | dansmith | Body: {"console": {"url": "http://198.72.124.114:6080/vnc_auto.html?token=8bfe6807-a8be-44de-bca7-d9087fb2da4a", "type": "novnc"}} | |
| 19:34:15 | dansmith | sure looks like it was called by tempest though | |
| 19:34:51 | dansmith | hmm, yeah that's super bizarre | |
| 19:34:57 | melwitt | yeah, like, wtf | |
| 19:34:59 | dansmith | that server uuid is nowhere in the logs | |
| 19:35:31 | dansmith | this finished at noon, so it has to be without the journal usage | |
| 19:35:41 | melwitt | I found it a few times in n-cpu, but nothing about it spawning | |
| 19:36:16 | melwitt | just accounting stuff | |
| 19:36:44 | dansmith | o.O | |
| 19:36:54 | dansmith | I also noticed what looked like a few restarts of the api service at the top of the log | |
| 19:37:08 | dansmith | like in the tripleo logs, but that's because of puppet I think | |
| 19:37:19 | dansmith | so I wonder if we have an api worker that isn't actually logging | |
| 19:37:42 | bauzas | dansmith: edleafe: jaypipes: FWIW, I was writing some UTs for the scheduler-claims | |
| 19:38:11 | dansmith | mriedem: maybe those are the two api worker threads starting actually | |
| 19:38:27 | jaypipes | bauzas: cool. will review promptly when you push. | |
| 19:38:30 | bauzas | edleafe: could you pease upload your last point for https://review.openstack.org/#/c/460177/ for leaving me providing UTs ? | |
| 19:39:11 | dansmith | sdague: can you think of any reason why we might be missing logs from one of the api workers or something like that? | |
| 19:39:21 | melwitt | dansmith: I dunno, on the surface it looks like we have to be missing some logs | |
| 19:39:39 | dansmith | melwitt: yeah, seems like impossible that we're not missing logs | |
| 19:40:11 | mriedem | dansmith: haven't been following - did you pull the journal down and check there? | |
| 19:40:22 | dansmith | mriedem: was just about to | |
| 19:41:58 | openstackgerrit | Matt Riedemann proposed openstack/nova master: Add BDM to InstancePayload https://review.openstack.org/448779 | |
| 19:41:59 | openstackgerrit | Matt Riedemann proposed openstack/nova master: Add keypairs field to InstancePayload https://review.openstack.org/419730 | |
| 19:42:08 | dansmith | I only see it in nova-compute logs | |
| 19:43:11 | dansmith | in the journal I mean | |
| 19:44:44 | dansmith | I see it in scheduler too | |
| 19:44:52 | dansmith | but no api or anywhere else | |
| 19:44:56 | melwitt | dansmith: since you're depending on devstack change, did you rebase that to get the use_journal change. it looks like you did already | |
| 19:45:04 | dansmith | and I see it in neutron-server | |
| 19:45:10 | dansmith | melwitt: yep | |
| 19:45:26 | sdague | dansmith: what's going on? | |
| 19:45:36 | dansmith | sdague: we think we're missing nova-api logs | |
| 19:45:48 | dansmith | well, and nova-compute logs actually | |
| 19:45:55 | dansmith | we see instances that were booted and used by tempest, | |
| 19:46:08 | dansmith | but zero evidence of that uuid in nova api logs, very little in compute (not even the boot part) | |
| 19:46:12 | dansmith | in scheduler, and neutron | |
| 19:46:15 | dansmith | so it clearly exists | |
| 19:46:25 | dansmith | but it's like shockingly absent from the other services | |
| 19:47:09 | dansmith | sdague: that's the case in the text logs and in the raw journal I pulled down | |
| 19:47:17 | dansmith | (unified journal ftmfw by the way) | |
| 19:47:22 | sdague | right, they'll be the same | |
| 19:47:31 | sdague | ok, give me the example in question | |
| 19:47:34 | dansmith | well, I know they should be, but.. checking :) | |
| 19:47:42 | dansmith | http://logs.openstack.org/37/458537/9/check/gate-tempest-dsvm-neutron-full-ubuntu-xenial/fe108a8/logs/ | |
| 19:47:50 | dansmith | instance db767e42-2dbe-48d7-868d-b766d9879eb6 | |
| 19:48:44 | dansmith | and if you look for the NoVNCConsoleTestJSON tenant/user, | |
| 19:48:45 | dansmith | you get one hit in scheduler and nothing else | |
| 19:49:08 | sdague | so, it is entirely possible that the default rate limitters for journald are getting tripped | |