| Posted | Nick | Remark | |
|---|---|---|---|
| #openstack-nova - 2017-05-04 | |||
| 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. | |
| 19:52:11 | sdague | ok, so default seems to be 1000 messages per 30s | |
| 19:52:17 | sdague | I am sure we are exceeding that | |
| 19:52:23 | dansmith | surely at startup | |
| 19:54:05 | sdague | let me put in a fix for that | |
| 19:54:13 | dansmith | cool thanks | |
| 19:54:26 | dansmith | link me and I'll depend on it and recheck | |
| 19:56:18 | melwitt | dansmith: so the websocketproxy goes direct to the instance? it doesn't need to know the compute host MQ right | |
| 19:56:44 | dansmith | it goes direct to the host | |
| 19:56:59 | dansmith | consoleauth validate_token does talk to the compute mq, but it does the looku | |
| 19:57:17 | melwitt | okay. we'll just have to see the logs then, nothing is jumping out at me | |
| 19:57:20 | dansmith | I think the token in memcache must have the ip/port that the proxy needs to connect to | |
| 19:57:21 | dansmith | yeah | |
| 19:57:28 | dansmith | hopefully something dumb | |
| 19:57:32 | dansmith | simple and dumb | |
| 19:57:34 | dansmith | like me. | |
| 19:57:44 | sdague | dansmith: I think this is it - https://review.openstack.org/462725 | |
| 19:57:46 | melwitt | lol :P | |
| 19:58:42 | openstackgerrit | Dan Smith proposed openstack/nova master: DNM: Canary test against multi-cell devstack https://review.openstack.org/458537 | |
| 19:58:44 | dansmith | sdague: ack thanks | |