| Posted | Nick | Remark | |
|---|---|---|---|
| #openstack-nova - 2019-09-20 | |||
| 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? | |
| 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? | |