Earlier  
Later
New Search
Posted Nick Remark
#openstack-nova - 2017-06-05
15:33:50 mordred mriedem: I'd be happy to try to write something up - but if it's a bad or unworkable area there's no need to bother of course
15:34:50 mriedem mordred: it's been tried before, usually ends up being a problem because of leaking internal details about the cloud so could be used for attacks
15:35:12 mriedem cfriesen_ had a spec and some code for improving the filtering in the scheduler logs to help operators, but that doesn't help the end user
15:35:24 mriedem except get their ticket resolved faster maybe
15:35:59 mordred mriedem: yah - that's what I'd be worried about from a "this spec cant' happen' pov
15:37:56 mriedem mordred: so looking at your issue,
15:38:02 mriedem nova-compute is failing to talk to placement http://logs.openstack.org/95/468095/2/gate/gate-shade-functional/3f5d8dc/logs/screen-n-cpu.txt.gz#_Jun_02_12_46_14_477554
15:38:06 mriedem getting 503 back
15:38:26 mriedem which means as far as placement and the scheduler are concerned, there are no compute nodes available
15:39:15 mriedem mordred: the compute node finally gets registered here: http://logs.openstack.org/95/468095/2/gate/gate-shade-functional/3f5d8dc/logs/screen-n-cpu.txt.gz#_Jun_02_12_47_14_576829
15:39:34 mriedem which is 15 seconds after your test failed
15:42:15 mordred mriedem: ah - so there was an early issue, but it eventually heals
15:43:00 mordred mriedem: so in terms of the hacky thing I had for the tests, I could actually check for "Created resource provider record via placement API...$(hostname)" in the n-cpu logs
15:43:12 mordred as a check for "is the cloud up and ready for action" before starting the tests
15:44:04 mriedem well,
15:44:19 mriedem the better less hacky thing would be to GET /resource_providers against the placement endpoint
15:44:36 mriedem until you get something back that's not an empty body
15:44:47 mordred mriedem: ah - yah. could do that for sure
15:44:53 mriedem note that placement is admin-only by default
15:45:18 mordred mriedem: that's ok - we've got admin accounts in the functional tets
15:45:20 mordred tests
15:45:22 mriedem i'm also curious why placement is failing in the first place
15:45:28 mhenkel_ mriedem: when you find some time, would you mind to take a look into https://review.openstack.org/#/c/441183/ ?
15:45:34 mriedem that should be started well before n-cpu and n-sch
15:45:57 mhenkel_ it passed ci and I addressed all the open points
15:46:03 mordred I don't think this is actually a thing where shade sohuld be checking for the error in normal usage -it seems like a pretty specific first-install devstack race from an api consumer perspective
15:46:17 mriedem mordred: also, i'm not sure why this would have regressed in the last few days, i don't see anything related to changing the startup order in devstack
15:46:39 mordred mriedem: it might just have always been a race and something else caused something else to be slow so it just started showing up
15:47:09 cfriesen_ mriedem: mordred: in our environment the users are generally very tightly couple to the admins, so we expose all the sched failure logs directly to the user
15:47:13 mordred mriedem: or, actually,it could have always been here, but now something is improved so we get all the way to tests before the self-healing
15:47:32 mordred cfriesen_: yah - I have admin on almost none of my clouds :)
15:47:50 mordred so I'm usually the annoying voice of "how do I learn this as a non-admin"
15:48:57 mriedem looking at the placement logs it takes quite a while for it to be ready it looks like
15:49:01 mriedem http://logs.openstack.org/95/468095/2/gate/gate-shade-functional/3f5d8dc/logs/screen-placement-api.txt.gz
15:50:06 mriedem the first request i see it process is this:
15:50:07 mriedem Jun 02 12:46:58.883989 ubuntu-xenial-osic-cloud1-s3500-9104911 devstack@placement-api.service[22675]: DEBUG nova.api.openstack.placement.requestlog [None req-6e9651be-51e5-40e6-a887-bd72120060a0 service placement] Starting request: 10.39.244.211 "GET /placement/resource_providers?resources=MEMORY_MB%3A256%2CVCPU%3A1" {{(pid=22678) __call__ /opt/stack/new/nova/nova/api/openstack/placement/requestlog.py:38}}
15:50:31 mriedem which is the one during scheduling
15:50:38 mriedem so....placement isn't up when the compute service is trying to check in
15:50:41 mriedem wtf
15:51:00 mriedem takes >1 minute to startup placement-api
15:51:17 mriedem i don't know if that's systemd / uwsgi shenanigans or what
15:51:24 mriedem cdent: ^ any ideas?
15:51:36 cdent mriedem: sorry on intense hangout
15:51:44 cdent will catch up soonish
15:52:58 mriedem cdent: just tell them we're going to start doing noop claims everywhere
15:52:59 mriedem problem solved
15:54:41 mriedem sdague: maybe your spidey sense can detect something ^?
15:55:39 mriedem looks like we start placement here http://logs.openstack.org/95/468095/2/gate/gate-shade-functional/3f5d8dc/logs/devstacklog.txt.gz#_2017-06-02_12_45_42_061
15:55:47 mriedem 2017-06-02 12:45:42.061 | Waiting for placement-api to start...
15:56:41 mriedem which is *after* we started n-cpu
15:56:45 mriedem derp
15:56:56 jaypipes alex_xu: https://review.openstack.org/#/c/469578
15:57:15 sdague mriedem: it's only 4 seconds for start
15:57:30 mriedem http://logs.openstack.org/95/468095/2/gate/gate-shade-functional/3f5d8dc/logs/devstacklog.txt.gz#_2017-06-02_12_45_10_006
15:58:08 mriedem so we start placement-api 32 seconds after we start nova-compute,
15:58:22 mriedem nova-compute starts up and tries to register the compute node with placement but gets a 503 b/c placement isn't up yet,
15:58:33 mriedem meanwhile, the compute host is mapped to the cell and tests start,
15:59:00 mriedem test tries to create a server, scheduler asks placement for a resource provider (compute node) for the server, there are 0 because none are registered, and the server create fails,
15:59:18 mriedem 15 seconds later, n-cpu registers the compute node with placement during it's periodic task to update avialable resources (1 minute cron)
15:59:21 openstackgerrit Jay Pipes proposed openstack/nova master: placement project_id, user_id in PUT /allocations https://review.openstack.org/469634
15:59:21 openstackgerrit Jay Pipes proposed openstack/nova master: placement: Add GET /usages to placement API https://review.openstack.org/469635
15:59:22 openstackgerrit Jay Pipes proposed openstack/nova master: placement: use separate tables for projects/users https://review.openstack.org/470645
15:59:22 mriedem mordred: ^
16:01:02 mriedem cdent: edleafe: jaypipes: dansmith: can someone summarize whatever changes are coming out of the hangout you just had in the dev ML please?
16:01:10 dansmith mriedem: jay is on it
16:01:15 jaypipes mriedem: yes.
16:01:21 jaypipes mriedem: I will. etherpad being worked.
16:01:26 mriedem ok thanks
16:01:47 sdague mriedem: yeh, our order is super bonkers
16:01:49 sdague we should fix that
16:01:56 cdent mriedem: the devstack problem, appears to be that fundamentally placement starts after nova in stack.sh
16:02:06 mriedem cdent: yeah
16:02:07 sdague I actually have no idea why placement comes after nova, that's just silly
16:02:21 sdague someone propose the ordering patch, and I'll fast approve
16:02:27 mriedem i think it's because nova.sh sets up the config or something?
16:02:36 mriedem might be circular dep
16:02:39 cdent we can start later though
16:02:45 sdague mriedem: the config stage is a lot earlier
16:02:47 cdent we can config after but start before
16:02:49 sdague and should be done
16:02:50 cdent I'll push somehting
16:02:55 cdent one sec
16:02:57 sdague yeh
16:03:21 cdent is there a bug to related to in the commit?
16:03:34 mriedem cdent: https://bugs.launchpad.net/devstack/+bug/1695634
16:03:34 openstack Launchpad bug 1695634 in devstack "Something weird just broke in creating servers" [Undecided,New]
16:07:10 cdent sdague, mriedem : https://review.openstack.org/471042
16:07:16 cdent i started before neutron and cinder too
16:10:40 mriedem cdent: question inline
16:12:58 cdent mriedem: answer inline
16:18:22 mriedem ok i'd just remove the comment
16:18:24 mriedem the note i mean
16:18:27 mriedem the comment is fine, the note is confusing
16:18:32 cdent k
16:19:03 cdent done
16:19:20 mriedem thanks
16:28:21 mordred cdent, mriedem: woot! thank you!
16:29:13 mordred I'm glad this turned out to be potentially an actual issue and not just a random testing weird
16:29:21 cdent was a good spot
16:29:41 cdent that the problem hasn't come up sooner is odd

Earlier   Later