Earlier  
Later
New Search
Posted Nick Remark
#openstack-nova - 2018-08-30
20:08:42 mriedem tzumainn: you might want to report a nova bug regardless so we don't lose track of what you hit
20:08:52 mriedem i'm not sure *how* you're hitting it, but that seems to be the theme this week with all bugs
20:09:00 mriedem "how in the hell is this even possible?"
20:09:12 tzumainn mriedem, hahaha - okay, I'll do that, thanks!
20:09:58 openstackgerrit Merged openstack/nova master: Report client: _reshape helper, placement min bump https://review.openstack.org/585034
20:10:00 mriedem dansmith: is it weird that ComputeNode.save() doesn't check to see if 'id' is changed?
20:10:01 mriedem or not set?
20:10:31 dansmith create or save?
20:10:32 mriedem i guess if it weren't set we'd blow up
20:10:33 mriedem save
20:10:36 melwitt I was thinking save() would just fail if there's no id, because then how could it find the thing to update
20:10:46 dansmith not sure we usually check that it's set on save, but we could
20:11:01 dansmith on create we usually check to avoid re-create
20:11:03 mriedem melwitt: right we'd blow up if id wasn't set on save
20:11:07 melwitt yeah
20:11:08 mriedem yeah we check on create
20:11:18 mriedem i was wondering if id changed though and we saved
20:11:51 mriedem i guess we don't really check for that anywhere
20:11:54 dansmith we pop id out of the changes,
20:12:03 melwitt even if we did, that doesn't explain the complete lack of an 'id' on a ComputeNode object in self.compute_nodes
20:12:04 dansmith but I guess we try to save anyway even if that was the only thing
20:12:50 melwitt I still don't see how we could lose that, even with the self.old_resources compare
20:13:23 dansmith if id is actually not set then it's either an object created with no id (not from the db) or someone del'd it off an objet
20:13:24 mriedem i don't either, i was wondering if we were getting a blank ComputeNode from old_resources which uses defaultdict and somehow shoved that blank one into self.compute_nodes
20:13:25 mriedem but we don't
20:13:51 melwitt yeah
20:16:17 mriedem there is a very small window where self.compute_nodes could have a ComputeNode in it without an id
20:16:20 mriedem in _init_compute_node
20:16:21 mriedem self.compute_nodes[nodename] = cn
20:16:21 mriedem cn.create()
20:16:25 mriedem b/c cn.create() is what sets the id
20:16:46 mriedem but, that code is all in a lock on the same host when we call update_available_resource
20:16:52 mriedem so not sure how anything could race and hit that
20:16:54 melwitt yeah, I wondered about that
20:17:46 mriedem tzumainn: did you by chance have multiple nova-compute services running on the same host?
20:17:59 mriedem no that still wouldn't do this
20:18:05 mriedem b/c the compute nodes map is in memory
20:18:19 mriedem i give up
20:18:20 tzumainn mriedem, I only have one, in any case
20:18:27 tzumainn mriedem, no worries, thanks for taking a look : )
20:20:16 mriedem so uh, the xen ci passed this time with the debug patch https://review.openstack.org/#/c/597613/
20:20:21 mriedem that's nice and consistent
20:23:46 melwitt great
20:26:28 melwitt keeping in the theme of Impossible Bug Week
20:26:29 Sundar melwitt: I am proposing a session for Cyborg/Nova to sort out os-acc. The main session could be in Cyborg time (Mon/Tue) and hopefully placement folks would attend. It may be helpful to get some time on Nova schedule as well to get everybody on board. What do you think?
20:26:52 cdent sorry mriedem, I'm sort of afk: if it was was that patch from back in queens, then the twisted narrow passageways are way twisted and have a lot of explaining to do to say why it's only showing up now
20:29:54 melwitt Sundar: do you think we need two sessions? we could just join the monday or tuesday session since nova doesn't start until wednesday
20:29:55 cdent mriedem: can you think of a way we could model the issue in a functional test? the feedback latency is hurting my head
20:30:50 mriedem cdent: given the xen ci is now passing, i don't really know
20:31:03 mriedem and why this isn't failing with the libvirt driver in master CI, again don't know
20:31:10 cdent fun fun
20:31:12 mriedem efried: we now have a new ERROR in the n-cpu logs on startup http://logs.openstack.org/98/584598/21/check/tempest-full/85acbda/controller/logs/screen-n-cpu.txt.gz?level=TRACE#_Aug_29_21_43_10_675029
20:31:22 mriedem efried: b/c we hit ^ before the resource provider is created
20:31:50 mriedem new from https://review.openstack.org/#/c/584598/
20:32:17 dansmith hmm, I got that disk not found one the other day locally
20:32:26 dansmith I thought it was residue from my old machine
20:33:04 dansmith is that because we're re-raising too?
20:34:18 mriedem https://bugs.launchpad.net/nova/+bug/1789998
20:34:18 openstack Launchpad bug 1789998 in OpenStack Compute (nova) "ResourceProviderAllocationRetrievalFailed ERROR log message on fresh n-cpu startup" [Low,Triaged]
20:34:50 mriedem the DiskNotFound during periodic is usually b/c we're deleting an instance on that host at the same time
20:35:11 mriedem http://logs.openstack.org/98/584598/21/check/tempest-full/85acbda/controller/logs/screen-n-cpu.txt.gz#_Aug_29_21_51_13_055225
20:35:14 dansmith okay this was on startup for me, which prevented it from every reporting initial inventory to placement
20:35:16 mriedem right before the DiskNotFound
20:35:25 mriedem Aug 29 21:51:13.055225 ubuntu-xenial-rax-iad-0001643010 nova-compute[16853]: INFO nova.virt.libvirt.driver [None req-af17b138-d942-4bbf-bf67-4d03b492ed3c tempest-ImagesTestJSON-1980657675 tempest-ImagesTestJSON-1980657675] [instance: 21227895-e216-463f-8e76-998fe637bab2] Deletion of /opt/stack/data/nova/instances/21227895-e216-463f-8e76-998fe637bab2_del complete
20:35:28 dansmith but I had what I think was a stale disk image in my instances directory
20:35:34 mriedem Aug 29 21:51:13.167422 ubuntu-xenial-rax-iad-0001643010 nova-compute[16853]: ERROR nova.compute.manager [None req-6f4285cc-ce12-4c29-b879-99fdaaae59be None None] Error updating resources for node ubuntu-xenial-rax-iad-0001643010.: DiskNotFound: No disk at /opt/stack/data/nova/instances/21227895-e216-463f-8e76-998fe637bab2/disk
20:35:42 dansmith nuking that fixed it, but I just had to do one more thing and then killed it all
20:35:46 mriedem yeah on startup would be a different weirdness
20:37:39 Sundar melwitt: If we can settle everything in one session, that would be great. Given the quantum of reviews, we want to make sure that there is enough convergence to close the spec https://review.openstack.org/#/c/577438 after the PTG.
20:38:02 Sundar Could we keep a 30-minute placeholder?
20:40:31 mriedem so on the 2nd go around in the RT.update_available_resource in this xen CI run, we see the RT say the tracked compute node has changed:
20:40:33 mriedem http://paste.openstack.org/show/729180/
20:40:44 mriedem b/c of _copy_resources updating the *_allocation_ratio values to 0.0
20:42:13 mriedem Aug 30 08:03:09.458344 dsvm-devstack-citrix-lon-nodepool-1379396 nova-compute[24292]: INFO nova.compute.resource_tracker [None req-9b1b9924-b89e-4a03-9a69-c9fff17594e3 None None] ComputeNode.cpu_allocation_ratio changed from 16.0 to 0.0 in _copy_resources.
20:44:50 melwitt Sundar: 30-minute placeholder for monday or tuesday?
20:46:05 melwitt Sundar: also, I think we should have the nova bits of the interaction proposed to nova-specs for review, that way we can more easily organize our review on that part
20:46:48 Sundar 30 min in Nova's schedule, anytime you want. Cyborg should allocate at least 1 hour on mon/tue.
20:47:27 Sundar The os-acc spec as a whole is Nova/Cyborg, so do we want another spec?
20:48:19 melwitt Sundar: okay, so you're saying you think we need two sessions. I can try to find a 30-minute slot on our schedule
20:48:51 melwitt Sundar: we need a nova spec for the proposed changes to the nova code, so the nova team can review those proposed changes
20:50:04 Sundar melwitt: Thanks a lot. OK, will propose a Nova spec too. BTW, I have been interacting a lot with efried and any Nova developer who gives feedback on os-acc spec.
20:50:08 melwitt nova meeting in 10 minutes
20:50:47 melwitt Sundar: thanks
20:52:57 mriedem cdent: just so you can rest easy tonight, i think we can safely confirm that we have some sort of weird multi-thread race with shared ProviderTree cache
20:52:59 mriedem https://bugs.launchpad.net/nova/+bug/1789654/comments/9
20:52:59 openstack Launchpad bug 1789654 in OpenStack Compute (nova) "placement allocation_ratio initialized with 0.0" [High,In progress] - Assigned to Matt Riedemann (mriedem)
20:52:59 melwitt mriedem: so _copy_resources is bypassing the compute node normalization routine?
20:53:00 mriedem efried: ^
20:53:32 mriedem melwitt: yes, and from my log digging in that comment it shows that if we hit this in the right order, we call ComputeNode.save() which will change the CN.cpu_allocation_ratio from 0.0 (from _copy_resources) back to 16.0
20:53:43 cdent oh great, I love weird multi-thread races, especially when caches are involved
20:53:49 mriedem which goes to the RT._normalize_inventory_from_cn_obj method which puts 16.0 back into the inventory dict
20:54:02 melwitt mriedem: ah, ok. nice sleuthing
20:54:13 mriedem but there is clearly something else hitting ProviderTree.update_inventory at the same time that RT.update_available_resource is running
20:54:42 mriedem and i don't think it's coming from the RT
20:54:59 mriedem the only place in RT that we call ProviderTree.update_inventory is after driver.update_provider_tree, which isn't implemented for xen
20:55:09 mriedem so i think it's the SchedulerReportClient's provider tree cache
20:57:37 cdent I suspect (or at least hope) that efried will have some insight on the meanderings of the cache
20:58:06 efried I may, once I'm not trying to do several things at once.
20:59:00 cdent efried: this seems to be an unfortunately common problem
20:59:15 cdent let's all quit

Earlier   Later