| Posted | Nick | Remark | |
|---|---|---|---|
| #openstack-nova - 2017-02-08 | |||
| 14:48:49 | johnthetubaguy | according to placement, its only ever been reached by the scheduler I guess | |
| 14:48:53 | EmilienM | FYI I'm using https://review.openstack.org/#/c/430571/ for testing | |
| 14:49:26 | cdent | johnthetubaguy: yes (I was looking at the main logs when I saw no activity above, not the subnode-2, but subnode-2 is just hearing from the scheduler) | |
| 14:49:41 | johnthetubaguy | I just wish we had more details on why compute isn't able to talk to placement in here: http://logs.openstack.org/71/430571/1/check/gate-tripleo-ci-centos-7-nonha-multinode/bae4746/logs/subnode-2/var/log/nova/nova-compute.txt.gz#_2017-02-08_06_43_28_610 | |
| 14:50:20 | cdent | johnthetubaguy: shortly before that; http://logs.openstack.org/71/430571/1/check/gate-tripleo-ci-centos-7-nonha-multinode/bae4746/logs/subnode-2/var/log/nova/nova-compute.txt.gz#_2017-02-08_06_40_24_634 | |
| 14:50:33 | dansmith | ot | |
| 14:50:42 | dansmith | it is clearly hitting placement because it's getting Unauthorized right? | |
| 14:51:02 | dansmith | which means that the service catalog is working, and that the credentials just aren't right I think | |
| 14:51:16 | dansmith | unless it's hitting placement for the undercloud somehow, but I doubt it | |
| 14:51:34 | cdent | dansmith: where is unauthorized happening? | |
| 14:51:41 | EmilienM | dansmith: our current CI jobs (pin to nova-ocata-3) use the same credentials, and it seems to work. I can give you a link so you can confirm | |
| 14:51:55 | dansmith | cdent: https://github.com/openstack/nova/blob/master/nova/scheduler/client/report.py#L70-L76 | |
| 14:52:02 | dansmith | cdent: that's the message in the logs, yes? | |
| 14:52:03 | johnthetubaguy | EmilienM: it is probably just silently failing | |
| 14:52:25 | johnthetubaguy | EmilienM: would wouldn't notice anything wrong if compute couldn't ever talk to placement until after ocata-3 | |
| 14:52:39 | EmilienM | ok now i'm checking our haproxy config, etc to make sure placement api is reachable | |
| 14:52:50 | dansmith | cdent: placement access log is completely empty on the undercloud? | |
| 14:53:01 | EmilienM | yeah | |
| 14:53:06 | EmilienM | please don't look undercloud for multinode jobs | |
| 14:53:11 | EmilienM | nova is not used to spawn the overcloud | |
| 14:53:14 | johnthetubaguy | dansmith: its odd we don't see 401 in the placement logs, or is that normal? | |
| 14:53:16 | EmilienM | we use nodepool to spawn the subnode2 | |
| 14:53:20 | dansmith | johnthetubaguy: I dunno | |
| 14:53:39 | cdent | ks_exc.Unauthorized means two things | |
| 14:53:43 | EmilienM | if you want to read logs from a real undercloud that spawns an undercloud, please look OVB jobs: https://review.openstack.org/#/c/430571/ | |
| 14:53:46 | mordred | cdent: of course it does | |
| 14:53:48 | johnthetubaguy | I wonder if its not actually got the correct url from the service catalog, or maybe it just can't talk to keystone to get it? | |
| 14:53:55 | dansmith | johnthetubaguy: placement access log on the undercloud is zero bytes, but we do have a few gets in the overcloud log | |
| 14:53:55 | cdent | one of them is entirely driven by code, not a response from anything | |
| 14:53:59 | cdent | mordred: ikr | |
| 14:54:17 | johnthetubaguy | dansmith: looks like they are the scheduler calls that work, yeah | |
| 14:54:31 | johnthetubaguy | dansmith: well the empty list would give us the no-valid host error I think | |
| 14:54:44 | EmilienM | I don't think it can comes from HAproxy because nova-placement-api log file exists, so API was reached | |
| 14:54:58 | EmilienM | it can be in credentials, I'm checking now. | |
| 14:55:10 | dansmith | actually, placement access is not zero bytes, it just looks empty | |
| 14:55:16 | EmilienM | johnthetubaguy: you said you checked in keystone logs, did you see something? | |
| 14:55:32 | johnthetubaguy | EmilienM: I haven't looked there, was looking at placement | |
| 14:55:52 | cdent | EmilienM: I'm pretty sure when apache starts it opens the log file, but only when the wsgi application is requested to, will it write and when it does the error log should get a bunch of oslo config noise | |
| 14:56:23 | EmilienM | cdent: right, and it's used, see http://logs.openstack.org/71/430571/1/check/gate-tripleo-ci-centos-7-nonha-multinode/bae4746/logs/subnode-2/var/log/nova/nova-placement-api.txt.gz#_2017-02-08_06_40_29_306 | |
| 14:56:58 | cdent | too many different log files! ;) | |
| 14:57:07 | mriedem | i second that | |
| 14:57:09 | dansmith | oh jeez | |
| 14:57:12 | dansmith | why are those there? | |
| 14:57:13 | mriedem | i get totally lost in the tripleo logs | |
| 14:57:27 | dansmith | mriedem: and no filtering :/ | |
| 14:57:36 | mriedem | yes no filtering is my other top complaint | |
| 14:57:59 | EmilienM | that's useful feedback, I'll take some actions | |
| 14:58:02 | dansmith | and it's nearly a full system dump, so lots of noise, and some of the files don't have a mimetype that lets them be displayed in a browser | |
| 14:58:06 | johnthetubaguy | dansmith: thats what I meant by it looks like the scheduler can fetch, even though compute can't :S | |
| 14:58:15 | cdent | so, that log starts at 06:40:28, but the nova-compute is delcaring the endpoing not found at 06:40:24 | |
| 14:58:28 | cdent | s/that log/the placement api log/ | |
| 14:58:45 | dansmith | johnthetubaguy: gotcha, so confusing | |
| 14:58:52 | EmilienM | let me check when endpoint is created | |
| 14:58:55 | johnthetubaguy | 2017-02-08 06:40:28.684 is when placement starts | |
| 14:58:56 | EmilienM | would it recheck later? | |
| 14:59:10 | mriedem | the compute will keep trying | |
| 14:59:18 | johnthetubaguy | 2017-02-08 06:40:29.306 is first request | |
| 14:59:38 | mriedem | the scheduler will keep trying to, but not per request | |
| 15:00:05 | EmilienM | endpoint is created at 06:38:25 | |
| 15:00:26 | EmilienM | oh wait no, it's for regionOne/nova::compute | |
| 15:00:27 | EmilienM | not placement | |
| 15:00:29 | dansmith | surely the credentials are created by that time right? | |
| 15:00:46 | dansmith | I figure they must be created before they're written to the configfile yes? | |
| 15:00:59 | EmilienM | 06:38:25 centos-7-2-node-osic-cloud1-s3500-7172104-416160 os-collect-config: #033[mNotice: /Stage[main]/Nova::Keystone::Auth_placement/Keystone::Resource::Service_identity[placement]/Keystone_endpoint[regionOne/placement::placement]/ensure: created | |
| 15:01:53 | EmilienM | and it's highly possible nova-compute starts afterward | |
| 15:02:35 | EmilienM | err, before I mean. I checked and nova-compute started at 06:32:06 | |
| 15:02:49 | EmilienM | 06:32:06 centos-7-2-node-osic-cloud1-s3500-7172104-416160 os-collect-config: #033[mNotice: /Stage[main]/Nova::Compute/Nova::Generic_service[compute]/Service[nova-compute]/ensure: ensure changed 'stopped' to 'running' | |
| 15:03:01 | cdent | EmilienM: right, which explains the change from endpoint not found to "Placement service credentials do not work." | |
| 15:03:20 | EmilienM | right, but IIUC it should retry | |
| 15:03:21 | cdent | in the nova-compute logs | |
| 15:03:25 | cdent | it does | |
| 15:03:31 | cdent | that's why we get the change | |
| 15:03:43 | cdent | can't find endpoint, wait, retry, found endpoint credentials don't work | |
| 15:03:46 | EmilienM | and if you look at logs, it retries only 2 times after the first fialure | |
| 15:04:03 | cdent | (or at least ks.Unauthorized, which means many things) | |
| 15:04:24 | dansmith | cdent: did you ever elaborate on what the multiple things are? | |
| 15:04:36 | dansmith | cdent: can't get a token and a real 403 I assume? | |
| 15:04:45 | EmilienM | what worries me is "Unable to refresh my resource provider record" | |
| 15:05:06 | dansmith | EmilienM: that's part of the same thing | |
| 15:05:08 | mriedem | EmilienM: "and if you look at logs, it retries only 2 times after the first fialure" - are you sure it didn't just stop giving errors after 2 retries because it started working? | |
| 15:05:12 | dansmith | EmilienM: can't GET it before it can't POST it | |
| 15:05:18 | cdent | dansmith: no, I'm trying to find it again, but from a few days ago it was something much weirder than that | |
| 15:05:23 | mriedem | stepping back, wasn't this working like a week ago? | |
| 15:05:27 | dansmith | cdent: okay, knowing might be relevant | |
| 15:05:29 | mriedem | if so, what changed on the tripleo side? | |
| 15:05:32 | cdent | dansmith: yes :) | |
| 15:05:54 | EmilienM | mriedem: it works fine today when I deploy OpenStack from trunk except nova which is pin to ocata-3 | |
| 15:05:56 | dansmith | cdent: just call me captain obvious | |
| 15:06:17 | EmilienM | mriedem: I'm having a CI test patch that deploy nova from trunk and it fails | |
| 15:06:30 | EmilienM | mriedem: but like johnthetubaguy and dansmith said, it was probably silently failing? | |
| 15:06:58 | EmilienM | mriedem: if you want I can show you how it works with ocata-3 and you can tell if nova placement/ novacompute are actually working together | |
| 15:06:59 | owalsh | EmilienM: don't we have POST requests in the ocata-3 placement-api log? | |
| 15:07:21 | EmilienM | owalsh: let me check a sec | |
| 15:07:28 | mriedem | EmilienM: so...last week tripleo ci was testing from nova trunk and things worked, but now it's nova ocata-3 (which is older than rc1) and things aren't working? | |
| 15:07:58 | owalsh | mriedem: ocata-3 works, trunk does not | |
| 15:08:19 | mriedem | owalsh: ok | |
| 15:08:22 | EmilienM | cdent, owalsh: that is an ocata-3 CI job: http://logs.openstack.org/50/330050/17/check/gate-tripleo-ci-centos-7-nonha-multinode/95f4ed9/logs/subnode-2/var/log/nova/nova-placement-api.txt.gz#_2017-02-08_13_22_00_143 | |
| 15:08:42 | EmilienM | mriedem: no, we don't test nova-trunk in tripleo, we manually pin to ocata-3 because trunk doesn't work for us | |
| 15:08:47 | EmilienM | mriedem: we do that since days | |
| 15:08:52 | EmilienM | since ocata-3 actually | |