| Posted | Nick | Remark | |
|---|---|---|---|
| #openstack-nova - 2019-09-20 | |||
| 17:24:39 | mriedem | mnaser: that's really strange, there are only two places we bury in cell0, | |
| 17:24:42 | mriedem | 1. if scheduling fails https://github.com/openstack/nova/blob/stable/stein/nova/conductor/manager.py#L1359 | |
| 17:24:58 | mriedem | 2. or scheduling picks a host that doesn't have a mapping https://github.com/openstack/nova/blob/stable/stein/nova/conductor/manager.py#L1386 | |
| 17:25:17 | mriedem | i wonder if you had hosts incorrectly mapped to cell0? | |
| 17:25:21 | mriedem | https://github.com/openstack/nova/blob/stable/stein/nova/conductor/manager.py#L1397 | |
| 17:25:42 | mriedem | there shouldn't ever be host mappings pointing at cell0 but we don't explicitly fail if you try to do that | |
| 17:26:04 | mriedem | e.g. if you started a compute service pointing at the wrong cell database and it was registered in cell0 and then got mapped there in the host mapping | |
| 17:27:57 | mriedem | dansmith: do you think it'd be worthwhile to have a sanity check around https://github.com/openstack/nova/blob/stable/stein/nova/conductor/manager.py#L1421 such that if the cell is actually cell0 in that case we blow up with some kind of "idk what you're doing but this is definitely wrong" | |
| 17:30:50 | mriedem | that still wouldn't explain how the instance in mnaser's case went from cell0 to cell1, unless he has a busted heal script | |
| 17:32:34 | mriedem | maybe a host mapping pointing at cell0 isn't possible after all https://github.com/openstack/nova/blob/stable/stein/nova/objects/host_mapping.py#L253 | |
| 17:33:18 | mnaser | yeah so in this case, i have a db record for this instance both in cell0 and cell1 | |
| 17:33:25 | mnaser | and i dont think the config changed anytime recently.. | |
| 17:33:50 | mriedem | is the host value set for either instance record? | |
| 17:34:16 | mnaser | both null | |
| 17:34:27 | mnaser | but the cell0 one is deleted and cell1 is not (aka deleted=0) | |
| 17:34:38 | mriedem | which has the older created_at time? | |
| 17:34:47 | mnaser | oh good idea | |
| 17:35:11 | mnaser | the same exact time. | |
| 17:35:21 | mriedem | wtf | |
| 17:35:41 | mriedem | you don't have some janky homebrew scripts that try to heal and revive an instance in cell0 and put it into cell1? | |
| 17:36:22 | mnaser | not that i know of | |
| 17:36:25 | mnaser | and also in case im losing it | |
| 17:36:26 | mnaser | http://paste.openstack.org/show/778146/ | |
| 17:37:34 | mriedem | some sort of weird mariadb cluster issue or something? | |
| 17:37:48 | mriedem | you wouldn't be clustering those together though unless you really screwed up | |
| 17:38:01 | mnaser | its just plain old galera, and those are two different databases too.. | |
| 17:38:11 | mnaser | so i dont know how it would like "oh let me make a cell0 thing" | |
| 17:38:24 | mriedem | it's clearly a phantom, some kind of 9/11 phantom, and it showed up too early for halloween | |
| 17:38:44 | mriedem | no obvious weirdness for that instance uuid in the logs? | |
| 17:39:06 | mnaser | stuff are mostly rotated out but im looking at all the fields and see the diffs | |
| 17:39:42 | mnaser | oh hm | |
| 17:40:06 | mnaser | so different fields are | |
| 17:40:44 | openstackgerrit | Balazs Gibizer proposed openstack/nova master: Remove functional test specific nova code https://review.opendev.org/683609 | |
| 17:40:57 | mnaser | updated_at (obviously cause deleted was changed), deleted_at (for the one that deleted), id (different ids from cell0 and cell1), availablity zone and launched_on (it looks like it was scheduled?!) | |
| 17:41:07 | dansmith | mriedem: hmm, that's probably not a bad idea | |
| 17:41:08 | mnaser | let me check if there's anything intersting on the host it was provisioned on.. | |
| 17:41:52 | mriedem | it's very weird that launched_on would be set but host is not | |
| 17:42:03 | openstackgerrit | OpenStack Release Bot proposed openstack/python-novaclient stable/train: Update .gitreview for stable/train https://review.opendev.org/683625 | |
| 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? | |