| Posted | Nick | Remark | |
|---|---|---|---|
| #openstack-nova - 2018-08-30 | |||
| 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 | |
| 20:59:22 | cdent | (that'll show em) | |
| 20:59:32 | mriedem | meeting in 1 min? | |
| 20:59:48 | melwitt | yes, I gave a 10 minute warning 9 minutes ago | |
| 21:05:13 | mriedem | far as i can tell the report client gets inventory like 500 times a second | |
| 21:05:25 | mriedem | it calls _refresh_and_get_inventory *a lot* | |
| 21:05:37 | mriedem | for every _ensure_resource_provider | |