| Posted | Nick | Remark | |
|---|---|---|---|
| #openstack-nova - 2017-05-04 | |||
| 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 | |
| 19:49:14 | sdague | I wonder if we can find out about that | |
| 19:49:25 | dansmith | oh interesting | |
| 19:49:32 | sdague | dansmith: you have the journals all down already? | |
| 19:49:40 | dansmith | sdague: just one journal, right? | |
| 19:49:41 | sdague | search for -k systemd | |
| 19:49:46 | dansmith | devstack.journal.gz? | |
| 19:50:02 | sdague | well, there are usual multiples of them because they roll over | |
| 19:50:17 | sdague | but, yeh, only looks like one in there | |
| 19:50:32 | dansmith | -k is dmesg, which you can't do on a file | |
| 19:50:45 | dansmith | unless you mean something else | |
| 19:50:46 | dansmith | -u? | |
| 19:51:23 | dansmith | journalctl | grep systemd yields not much of relevance | |
| 19:51:39 | sdague | -t | |
| 19:51:40 | sdague | sorry | |
| 19:51:53 | dansmith | same as the grep | |
| 19:52:05 | edleafe | bauzas: should be ready to upload soon. I've already created a unit test. | |