Earlier  
Later
New Search
Posted Nick Remark
#openstack-nova - 2017-12-20
16:19:34 mnaser ok reading scrollback
16:19:43 mriedem ah v
16:19:44 mriedem http://intermediatepythonista.com/python-generators#generator-expressions_1
16:19:50 mriedem ok i'm sorely lacking in this area then
16:20:20 mnaser ok but forgive me if i'm being unclear but i think the problem is a lot simpler than that
16:20:35 mnaser seen_nodes contains a tuple list of (host, node) of all hosts in the system
16:20:47 mnaser dead_notes contains a tuple list of (host, node) of all dead hosts in the system
16:21:11 mnaser as part of the for loop right before the generator, all dead_nodes are removed from self.host_state_map
16:21:32 mnaser which leaves self.host_state_map with keys of the alive hosts *only*
16:21:52 mnaser the generator loops over all of self.host_state_map but uses seen_nodes as the key (which is all hosts)
16:22:03 mnaser which includes dead nodes, that were removed, in the loop just prior
16:22:09 mriedem mnaser: dead_nodes is the set of entries in host_state_map that aren't also in seen_nodes
16:22:21 mriedem so it's removing existing dead entries from host_state_map
16:22:23 mriedem that's what the set is for
16:22:36 mnaser OH
16:22:39 mnaser i see what you mean
16:22:56 mriedem so i think mdbooth's analysis in the commit message here is correct https://review.openstack.org/#/c/529352/
16:23:11 mriedem because since we're using a generator (which i didn't realize),
16:23:28 mriedem the host_state_map results could change while processing a request,
16:23:39 mriedem if a compute node is deleted in between, in a busy cloud, such as someone's public cloud
16:24:01 mnaser ok but im pretty sure this compute node wasnt deleted, it still exists but it is dead
16:24:06 mnaser let me please double check
16:24:10 mriedem mdbooth: rathre than change it from returning a generator to a list, why not just check if the key is still in the host_state_map before returning the next item?
16:25:10 mriedem mnaser: maybe the service was deleted?
16:25:19 mriedem you can't delete a compute node through the REST API, but you can delete a service
16:25:32 mriedem https://review.openstack.org/#/c/529352/1/nova/scheduler/host_manager.py@686
16:26:19 mnaser on one conductor i see 40 instances of this with the most recent happening on the 20th
16:26:29 mriedem so i think a simple test could be you run _get_host_states once with 2 computes and 2 services, then delete one of the services and run _get_host_states again, and iterate the results and it should blow up
16:27:15 mnaser # grep KeyError /var/log/nova/nova-scheduler.log | grep req | wc -l => 20
16:27:20 mnaser one one of the schedulers
16:29:03 mnaser happened with 9 different compute nodes in the KeyError
16:29:29 mnaser and i know for a fact some of thoser havent been deleted, especially those a few days ago too
16:29:31 mriedem do those computes have corresponding services table entries?
16:29:52 mnaser mriedem: i mean i see them in 'nova service-list'
16:29:58 mnaser and their updated_at is recent so they're reporting in
16:30:13 mnaser afaik the only way for that service record to go away is... if someone deleted it?
16:30:38 mriedem correct
16:31:10 mriedem we do start auto-disabling computes that fail to build 10 times in a row
16:31:20 mriedem but in the scheduler code here, we include disabled services
16:31:54 mnaser mriedem: i think we disabled that because scheduling bugs would shut down our entire cloud lol
16:32:12 mnaser ex: failing to place numa on server will result in a build fail count being increased
16:38:57 mriedem mdbooth: ok i think we can still use part of your test and maintain the generator
16:39:02 mriedem i'm going to update your patch quick
16:39:18 mdbooth mriedem: on a call, but that's cool
16:42:46 cdent jaypipes, mriedem: if you're both still around, this is a good and relatively straightforward win for placement behaving in a version discovery world: https://review.openstack.org/#/c/522002/
16:43:21 mdbooth mriedem: Did you see my unit test, btw?
16:43:38 mnaser mriedem: im not sure if this is relevant or not but do you think the fact we run 3x nova-schedulers could play a role in this .. somehow
16:44:10 mriedem mdbooth: yes i pulled part of the test and applied it to an existing test to recreate the bug
16:44:21 mriedem mnaser: separate processes?
16:44:30 mnaser yes, on seperate machines too
16:44:34 mriedem mnaser: should be ok if it's separate processes because the host_state_map is global to the single process
16:44:40 mnaser (i dont think it would but i figure i would mention it0
16:44:50 mnaser oh you know what
16:44:58 mnaser let me see if i can grep the logs for "Removing dead compute node"
16:45:15 mnaser if that helps at all..
16:46:21 openstackgerrit Matt Riedemann proposed openstack/nova master: Fix an error in _get_host_states when deleting a compute node https://review.openstack.org/529352
16:46:43 mriedem mnaser: btw with placement making claims via the filter scheduler in pike, we actually expect you to be able to run multile scheduler processes safely
16:46:56 mriedem i have a todo to update one of our CI jobs to do that (run with 2 schedulers)
16:47:03 mriedem mdbooth: jaypipes: ^ updated
16:47:07 mnaser mriedem: yeah before we have a little hacky trick of letting things reschedule more often
16:47:17 mnaser because in large volume schedulers all take the same decisions (before at least)
16:47:37 mriedem mnaser: yup, exactly why we're doing claims in the scheduler rather than rely on the compute to fail and reschedule
16:47:57 mriedem mnaser: so in pike, you should be good to remove the core/ram/disk filters, but you'll still need to rely on numa claims in the compute
16:48:52 openstackgerrit Ilya Shakhat proposed openstack/nova master: Initialize osprofiler in uWSGI application https://review.openstack.org/519664
16:49:45 mnaser mriedem: ok i just found a really weird amount of compute nodes being marked as dead in logs
16:50:10 mnaser and i guess they're flapping for some reason and the state of self.host_state_map is always changing with the generator
16:50:26 mriedem mnaser: my guess would be the auto-disable thing if you don't have that disabled globally?
16:50:30 mriedem it's a per-compute config
16:50:32 mnaser or ntp
16:50:41 gibi_away I'm starting my vacation now. I will be back officially on 8th of Jan
16:50:43 mriedem yeah i guess service timeouts
16:50:48 mriedem gibi_away: NOOOO
16:51:02 mnaser gibi_away: have fun :-)
16:51:07 mriedem gibi_away: enjoy, see you in a few weeks
16:51:07 gibi_away mriedem: I'm trying to look at gerrit time to time but no promises
16:51:12 mriedem don't
16:51:18 mnaser mriedem: so logs from august till now in scheduler ... grep 'Removing dead compute node' /var/log/nova/nova-scheduler.log | wc -l => 102490.
16:51:23 mnaser so um
16:51:27 gibi_away mriedem: see you
16:51:43 mnaser something is wrong there, i guess with all those services going dead, it was creating the race condition
16:51:47 mnaser now why they are dead thats an exercise for me
16:52:16 openstackgerrit rahul bardia proposed openstack/python-novaclient master: nova limits ERROR (Exception): Field names must be unique https://review.openstack.org/527922
16:52:21 mnaser some being removed 4 minutes ago.. i think this is ntp related
16:52:52 mnaser the conductor is the one that updates the service record.. or is it the compute directly?
16:53:04 mnaser (as in, who decides what time goes in updated_at)
16:54:37 mriedem that's the servicegroup api i think
16:55:05 mriedem https://github.com/openstack/nova/blob/3ebc358002d3f62a9ff0a3b0f50fea4f2a5c2c91/nova/servicegroup/drivers/db.py#L56
16:55:39 mnaser so one of the compute nodes that went down 4 minutes ago is 4 seconds ahead
16:55:57 mriedem are you seeing any of the logging messages in here? https://github.com/openstack/nova/blob/3ebc358002d3f62a9ff0a3b0f50fea4f2a5c2c91/nova/servicegroup/drivers/db.py#L86
16:57:26 mnaser mriedem: no
16:57:39 melwitt mnaser: I agree that it sounds ntp related if you're seeing some computes ahead in time of others
16:58:09 mnaser melwitt: this one that went 'down' was actually 4 seconds ahead though so if anything it would have updated with a time that is more ahead
16:58:21 mriedem oopsy doodle http://logs.openstack.org/84/529184/2/check/legacy-tempest-dsvm-py35/888d647/logs/screen-n-super-cond.txt.gz#_Dec_20_15_15_20_744636
16:58:27 mriedem cdent: ^
17:00:40 mriedem http://logs.openstack.org/84/529184/2/check/legacy-tempest-dsvm-py35/888d647/logs/screen-placement-api.txt.gz#_Dec_20_15_15_20_666337
17:01:17 mriedem File "/opt/stack/new/nova/nova/objects/resource_provider.py", line 2029, in _set_allocations
17:01:22 mriedem nova.exception.ObjectActionError: Object action create failed because: already created
17:03:26 mriedem https://bugs.launchpad.net/nova/+bug/1739453
17:03:27 openstack Launchpad bug 1739453 in OpenStack Compute (nova) "MigrationsAdminTest fails with NoValidHost because resource claim swap in placement fails with 500" [High,Confirmed]
17:06:14 mriedem not sure if using POST /allocations would fix this or not

Earlier   Later