Earlier  
Later
New Search
Posted Nick Remark
#openstack-nova - 2017-02-08
14:47:23 dansmith oh, I'm not looking at subnode1
14:47:28 dansmith I'm looking at -2
14:47:33 EmilienM ok good
14:47:43 dansmith or are you calling the primary node "subnode1" ?
14:48:21 EmilienM so: http://logs.openstack.org/71/430571/1/check/gate-tripleo-ci-centos-7-nonha-multinode/bae4746/logs/var/log/nova/ is the undercloud and please don't look at it we don't care now
14:48:36 EmilienM http://logs.openstack.org/71/430571/1/check/gate-tripleo-ci-centos-7-nonha-multinode/bae4746/logs/subnode-2/var/log/nova/ is overcloud, and we currently can't spawn a VM on it
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?

Earlier   Later