| Posted | Nick | Remark | |
|---|---|---|---|
| #openstack-nova - 2019-09-20 | |||
| 17:42:06 | dansmith | mriedem: I agree that this sounds highly fishy | |
| 17:42:06 | openstackgerrit | OpenStack Release Bot proposed openstack/python-novaclient stable/train: Update TOX/UPPER_CONSTRAINTS_FILE for stable/train https://review.opendev.org/683626 | |
| 17:42:08 | openstackgerrit | OpenStack Release Bot proposed openstack/python-novaclient master: Update master for stable/train https://review.opendev.org/683627 | |
| 17:42:14 | mriedem | dansmith: not even sounds, smells! | |
| 17:42:35 | mnaser | ok, timed out waiting for network-vif-plugged | |
| 17:42:39 | dansmith | mriedem: reeks of fishy sounds | |
| 17:42:50 | mriedem | mnaser: this is what sets launched_on https://github.com/openstack/nova/blob/f4aaa9e229c98a97af085f31e43509189e2e4585/nova/compute/resource_tracker.py#L544 | |
| 17:42:53 | mriedem | oh i bet i know why, | |
| 17:42:58 | mnaser | BuildAbortException: Build of instance 10d8a93a-bb6b-44ef-83f1-be6b21336651 aborted: Failed to allocate the network(s), not rescheduling. | |
| 17:43:05 | mriedem | we fail the build, set host/node to None but not launched_on or az | |
| 17:43:45 | mriedem | https://github.com/openstack/nova/blob/f4aaa9e229c98a97af085f31e43509189e2e4585/nova/compute/manager.py#L2069 | |
| 17:44:02 | mriedem | yeah _nil_out_instance_obj_host_and_node should also null out launched_on | |
| 17:44:35 | mriedem | anyway, that doesn't explain why the instance is also in cell0 | |
| 17:44:40 | mnaser | yeah that explains half the story i guess | |
| 17:44:45 | mriedem | mnaser: which copy of the instance has launched_on set? | |
| 17:44:46 | mriedem | cell1? | |
| 17:44:51 | mnaser | yeah | |
| 17:45:07 | mriedem | and that compute host that launched_on is set to, the host_mapping in the api db is pointing at cell1? | |
| 17:45:27 | mnaser | yeah the one is cell1 is correct | |
| 17:46:04 | mnaser | good question about host_mapping | |
| 17:46:11 | mriedem | does the name of the instance have an index-like suffix on it, i.e. was it part of a multi-create request? | |
| 17:46:27 | mriedem | e.g. my-vm-1, my-vm-2 etc | |
| 17:46:42 | mnaser | its not a multicreate request (afaik) but the title looks like it is | |
| 17:47:02 | mnaser | centos-7-large-tf-ci-0000006321 | |
| 17:47:04 | mnaser | a zuul instance though | |
| 17:47:19 | mriedem | oh that's not the kind of index i'd be looking for | |
| 17:47:21 | mriedem | simple integers | |
| 17:47:31 | mnaser | yeah | |
| 17:47:41 | mnaser | i was just wondering in case nova had some logic to match <name>-<number> | |
| 17:47:45 | mnaser | but i didn't think we'd be that wild :) | |
| 17:48:32 | mriedem | i don't know how this could happen, unless some kind of weird rabbit thing where like we actually got 2 copies of the same build request message to conductor, one went to cell1 and one failed scheduling and went to cell0 or something | |
| 17:48:34 | mnaser | yeah host_mappings is the right one | |
| 17:49:07 | mnaser | yeah im pretty confused.. | |
| 17:49:20 | dansmith | that sounds pretty fantastical | |
| 17:49:34 | dansmith | especially without other MAJOR problems showing up all over the place | |
| 17:49:43 | mriedem | btw the request_specs.num_instances field for the instance would tell you if it was a multi-create request | |
| 17:50:33 | mriedem | each instance in a multi-create request gets a unique id but i've seen some weird things with multi-create requests that blow up the scheduler and trigger automatic retries to the scheduler | |
| 17:50:37 | mriedem | we removed that in stein though i think | |
| 17:51:26 | mriedem | this thing https://github.com/openstack/nova/blob/stable/queens/nova/scheduler/utils.py#L807 | |
| 17:51:54 | mnaser | i mean, given the instance failed to deploy because of a timeout | |
| 17:52:08 | mnaser | there may be other weird things happening | |
| 17:52:13 | mriedem | well the timeout was likely a failure on the ovs agent | |
| 17:52:21 | mnaser | i .. don't know how it can result in something like scheduling it twice though | |
| 17:52:21 | mriedem | causing vif plugging to fail | |
| 17:53:27 | dansmith | if the failure was vif plugging, we should be well-settled on the destination host and in the right cell | |
| 17:53:36 | dansmith | way way way away from anything that would re-create it in cell0 | |
| 17:54:34 | mnaser | yeah thats why i think the only place it could have happened is scheduled twice | |
| 17:59:02 | mriedem | mnaser: do you see instance actions for that instance in both dbs? | |
| 17:59:09 | mnaser | oh good idea | |
| 17:59:12 | mriedem | and if so, are there any differences in the events? | |
| 17:59:18 | mriedem | the instance_action_events tables i mean | |
| 17:59:21 | mriedem | *table | |
| 18:00:04 | mriedem | i'm not sure we actually have instance action events until we have picked a cell though | |
| 18:00:29 | mnaser | theres no column for instance in instance_actions_events or am i losing it? | |
| 18:00:31 | mriedem | yeah we create the action once we've picked a cell https://github.com/openstack/nova/blob/stable/stein/nova/conductor/manager.py#L1483 | |
| 18:00:42 | mriedem | mnaser: instance -> instance_actions -> instance_action_events | |
| 18:00:48 | mnaser | ohhhh okay | |
| 18:01:03 | mriedem | *instance_actions_events | |
| 18:01:35 | mnaser | create in cell1, nothing in cell0 | |
| 18:01:58 | mnaser | compute__do_build_and_run_instance in actions | |
| 18:01:59 | mriedem | yeah i guess that's what i'd expect since bury in cell0 before creating the "create" action | |
| 18:02:26 | mnaser | so the only thing is somehow it got scheduled .. twice? | |
| 18:02:37 | mnaser | one said "nope" and the other said "yep" | |
| 18:02:46 | mriedem | idk how that could happen | |
| 18:02:49 | mnaser | probably because a db exception error for some constraint | |
| 18:02:54 | mnaser | i mean at this point i'm convinced it might be an infra thing | |
| 18:03:11 | mnaser | again the VM failed to provision because port plugging timed out so that does hint at things likely being weird | |
| 18:03:14 | mriedem | well that's why i brought up rabbit | |
| 18:03:45 | mnaser | and not an issue in galera, yeah, it would be rabbit issue surely | |
| 18:03:47 | mriedem | e.g. is it possible that rabbit thought the message to conductor (or scheduler) wasn't received and resent it? | |
| 18:04:08 | mnaser | i guess that is the most likely theory | |
| 18:04:14 | dansmith | I don't think so | |
| 18:04:17 | mriedem | pre-cells v2 we wouldn't have a problem b/c instances.uuid is unique per cell db | |
| 18:04:32 | mnaser | unless rabbit thought the cluster was split or something | |
| 18:04:50 | dansmith | I think that when you enqueue a message, it goes into a queue for a given receiver, if there is one waiting | |
| 18:04:55 | mriedem | do you have rabbit logs going back to when that instance was created? | |
| 18:04:56 | dansmith | but yeah, rabbit split brain could have done something I guess | |
| 18:05:27 | dansmith | mriedem: what if, in bury_in_cell0, we check last minute to see if there's already a host mapping and if so, we log and abort? | |
| 18:05:37 | dansmith | I mean, I would think that's where we fail in that routine anyway, | |
| 18:05:50 | dansmith | so there should be some log fallout from us failing to create the cell0 mapping anyway right? | |
| 18:06:03 | mriedem | is this one of the many reasons people say to not cluster rabbit? | |
| 18:06:07 | mriedem | beyond performance? | |
| 18:06:27 | mnaser | rabbitmq is the worlds biggest pita :( | |
| 18:07:55 | mnaser | ok so at least to clean things up i will update the instance_mappings to point that the right cell | |
| 18:08:01 | mnaser | and then at least the instance will be delete-able | |
| 18:08:12 | mnaser | and then the cell0 will just get archived and disappear | |
| 18:08:52 | mriedem | dansmith: i'm not sure what you mean by "already a host mapping" in bury_in_cell0 | |
| 18:09:09 | dansmith | mriedem: when we bury in cell0, we also have to create a mapping for it to be there | |
| 18:09:22 | dansmith | mriedem: we should fail to do that if we're late to the party because we're a failed reschedule right? | |
| 18:09:37 | mnaser | hmm yeah, that's true, i guess the bury doesn't check if there's an existing one there | |
| 18:09:43 | mriedem | dansmith: so here https://github.com/openstack/nova/blob/stable/stein/nova/conductor/manager.py#L1282 ? | |
| 18:09:52 | mriedem | before doing that, double check that instance_mapping.cell_mapping is None, right? | |
| 18:11:03 | mriedem | i mean we'd want to check way before that though, before this https://github.com/openstack/nova/blob/stable/stein/nova/conductor/manager.py#L1260 | |
| 18:11:41 | mriedem | i'm not opposed to adding a sanity check | |
| 18:11:48 | mriedem | worst case is it doesn't hurt anything, | |
| 18:11:58 | mriedem | best case is it avoids crazy rabbit clustering split brain weirdness | |
| 18:12:10 | dansmith | mriedem: well, I'm thinking more like direct hit the database to make sure | |
| 18:12:21 | dansmith | mriedem: but again, we should fail to create a duplicate mapping there | |
| 18:13:10 | mnaser | is this just a matter of `if inst_mapping.cell_mapping is not None:` before updating it? | |
| 18:14:22 | dansmith | no | |