Earlier  
Later
New Search
Posted Nick Remark
#openstack-nova - 2018-02-02
16:35:32 giblet mriedem: responeded in https://review.openstack.org/#/c/532689
16:35:48 sean-k-mooney a hard reboot should entirely tear down the vm the same way virsh destroy would
16:35:56 melwitt if it does, then I'm surprised we haven't heard about people complaining
16:36:05 giblet mriedem: I'm OK to +W this and continue discussing the run.yaml issue separately as it seems the job works
16:36:32 giblet mriedem: and the rest of the nits can be handled in a follow up (like naming)
16:36:41 sean-k-mooney the soft reboot should jsut send an achi reboot command to the guest but not destry and recreate the entire vm
16:37:12 giblet figleaf: have you tried runnig PS4 in your env or just PS3?
16:37:28 mriedem giblet: works for me
16:37:28 melwitt mriedem: I'm trying to understand how we even get that "Unexpected attempt to pop events during shutdown" in that test run
16:37:50 mriedem melwitt: looking at the n-cpu log, it looks like because we get a network-changed event before that which we process and pop the event, but not sure
16:37:54 melwitt sean-k-mooney: yeah, it does. just trying to understand whether any of that blows away iptables rules
16:38:05 melwitt since that would be bad
16:38:48 sean-k-mooney melwitt: if qemu removes the tap. then any ip tables rules associated with the tap will be removed for the kernel when the tap is removed
16:38:57 mriedem but network-changed shouldn't mess with the _events stuff at all...
16:39:00 giblet mriedem: OK. I've +Wd it
16:39:15 mriedem melwitt: we're probably just getting a network-vif-plugged event that we weren't expecting, so there was nothing in _events
16:39:17 melwitt sean-k-mooney: okay. I don't know what makes qemu decide to remove a tap
16:39:30 mriedem giblet: thanks
16:39:58 ildikov mriedem: giblet: thanks
16:39:59 melwitt mriedem: we did get an unexpected one. we weirdly get network-change AND network-vif-plugged during the hard reboot while we are 'virsh destroy'ing and BEFORE we unplug anything. I don't understand it
16:40:12 mriedem melwitt: yeah was looking at that,
16:40:22 mriedem and after that, the nw info cache says the port is active=false
16:40:28 melwitt right
16:40:30 mriedem so that's why we wait for vif-plugged
16:40:34 mriedem but we aren't going to get that,
16:40:35 melwitt which is how we go into waiting mode
16:40:39 mriedem because we alreayd got a vif-plugged
16:40:46 mriedem yeah...
16:41:00 melwitt I don't get how we get a vif plugged from ... not plugging anything yet
16:41:30 melwitt because you can see the first vif-plugged from the instance boot, then after the reboot starts but before even the unplug, we get vif-plugged again
16:41:34 sean-k-mooney melwitt: well unplug for linux bridge in os-vif is a noop https://github.com/openstack/os-vif/blob/stable/queens/vif_plug_linux_bridge/linux_bridge.py#L114-L117 which is why i dont that that os-vif is the issue here.
16:42:13 melwitt hah, a no-op
16:42:44 mriedem so after the instance is created but before we reboot, we get network-changed here:
16:42:45 mriedem http://logs.openstack.org/42/525842/11/check/neutron-tempest-linuxbridge/2502b64/logs/screen-n-cpu.txt.gz#_Jan_29_16_01_35_168999
16:42:51 mriedem which forces us to refresh the nw info cache
16:43:10 melwitt ah, so that's where the active=True -> active=False change comes from
16:43:21 melwitt I was wondering how that happens
16:43:23 figleaf giblet: no, I was testing on PS3
16:43:30 mriedem then we start rebooting http://logs.openstack.org/42/525842/11/check/neutron-tempest-linuxbridge/2502b64/logs/screen-n-cpu.txt.gz#_Jan_29_16_01_35_600736
16:44:00 figleaf giblet: if you need to explicitly add that to every test class in order to catch invalid UUIDs, then I don't think that's very useful
16:44:07 mriedem "active": true
16:44:07 mriedem at that point, it says the vif is active
16:44:27 melwitt yes
16:44:37 mriedem then we get a vif-plugged event, from god knwos where http://logs.openstack.org/42/525842/11/check/neutron-tempest-linuxbridge/2502b64/logs/screen-n-cpu.txt.gz#_Jan_29_16_01_36_665892
16:44:48 melwitt yep
16:45:02 mriedem which we were'nt expecting and that's why we see "Unexpected attempt to pop events during shutdown"
16:45:08 melwitt right
16:45:13 giblet figleaf: nova tests are derived from nova.tests.TestCase and that automatically sets up the warning fixture. The test case you added does not derive from nova.tests.TestCase but derives from testools.TestCase
16:45:41 mriedem at that point the vif is not active
16:45:42 mriedem "active": false
16:45:46 mriedem and we've refreshed the nw info cache
16:46:11 mriedem i'm not sure what is event making us refresh the nw info cache there
16:46:19 giblet figleaf: we can try to make TestWarningsFixture derive from nova.tests.TestCase then we don't need the extra test setup test_invalid_uuid_errors
16:46:55 melwitt mriedem: do we do it for any event? maybe the vif plugged refreshed it?
16:47:06 mriedem no, _process_instance_event doesn't do that
16:47:24 melwitt and I see now the erroneous "pop event during shutdown", I agree it would log that any time we got an unexpected event
16:48:29 melwitt okay, so external_instance_event in compute is what decides whether to refresh the info_cache
16:48:40 melwitt I see it for network-changed only
16:50:29 melwitt but something did update the info_cache right after we got the random plug event
16:51:03 sean-k-mooney i wonder if its related to this change in neutron https://review.openstack.org/#/c/246898/22/neutron/plugins/ml2/rpc.py
16:52:20 mriedem this is where neutron sends that mystery vif-plugged event http://logs.openstack.org/42/525842/11/check/neutron-tempest-linuxbridge/2502b64/logs/screen-q-svc.txt.gz#_Jan_29_16_01_36_514905
16:52:43 sean-k-mooney that chagne was done for live migration but it emits that event every time a port state is modified
16:52:50 melwitt mriedem: yeah, saw that
16:53:07 mriedem sean-k-mooney: hmm, that's been around since newton
16:53:21 melwitt I wish I could tell what refreshed the info_cache in this mystery refresh. doesn't look like it was from a periodic heal else we'd see a log message about that
16:53:54 sean-k-mooney mriedem: yes though i dont think we use it in nova yet
16:54:19 sean-k-mooney melwitt: sahid has some patches related to it currently
16:54:49 mriedem hmm http://logs.openstack.org/42/525842/11/check/neutron-tempest-linuxbridge/2502b64/logs/screen-q-svc.txt.gz#_Jan_29_16_01_36_095844
16:54:58 mriedem Jan 29 16:01:36.095844 ubuntu-xenial-rax-ord-0002240582 neutron-server[21191]: DEBUG neutron.notifiers.nova [None req-1655d8dd-b810-4510-ba6a-fb2a5019a84a None None] Ignoring state change previous_port_status: ACTIVE current_port_status: BUILD port_id 8de74fd2-a3bc-4d41-9c11-c04f25b52b6d {{(pid=21288) record_port_status_changed /opt/stack/new/neutron/neutron/notifiers/nova.py:208}}
16:56:48 sean-k-mooney mriedem: ya that looks... interesting. perhaps neutron does not allow an active port to go back to build?
16:57:25 melwitt mriedem: the mystery refresh might be this? https://github.com/openstack/nova/blob/master/nova/compute/manager.py#L3152
16:58:49 openstackgerrit Balazs Gibizer proposed openstack/nova master: Escalate UUID validation warning to error in test https://review.openstack.org/540386
16:59:01 mriedem melwitt: for that call, it's this http://logs.openstack.org/42/525842/11/check/neutron-tempest-linuxbridge/2502b64/logs/screen-n-cpu.txt.gz#_Jan_29_16_01_36_172052
16:59:09 mriedem same request id as for the rebooting instance message
16:59:23 giblet figleaf: ^^ now the test derives from nova.test.TestCase and therefore I could remove the explicit fixture setup from this test as well
16:59:24 melwitt oh :\
16:59:44 mriedem melwitt: what i'm confused about is the mystery vif-plugged happens, and the request id being used is here http://logs.openstack.org/42/525842/11/check/neutron-tempest-linuxbridge/2502b64/logs/screen-n-cpu.txt.gz#_Jan_29_16_01_37_230004
16:59:52 mriedem Jan 29 16:01:36.673427 ubuntu-xenial-rax-ord-0002240582 nova-compute[29444]: WARNING nova.compute.manager [None req-1cb07971-b6f2-41f9-b34b-bc03b867abdb service nova] [instance: 3fa55d94-b1f4-42f4-8ba0-9ca46c71d7c0] Received unexpected event network-vif-plugged-8de74fd2-a3bc-4d41-9c11-c04f25b52b6d for instance with vm_state active and task_state rebooting_hard.
17:00:04 mriedem Jan 29 16:01:37.230004 ubuntu-xenial-rax-ord-0002240582 nova-compute[29444]: DEBUG nova.network.base_api [None req-1cb07971-b6f2-41f9-b34b-bc03b867abdb service nova] [instance: 3fa55d94-b1f4-42f4-8ba0-9ca46c71d7c0] Updating instance_info_cache with network_info:
17:00:08 mriedem those are the same request id
17:00:37 openstackgerrit Chris Dent proposed openstack/nova-specs master: Add generation support in aggregate association https://review.openstack.org/540447
17:01:38 mriedem in the neutron logs, that's this request http://logs.openstack.org/42/525842/11/check/neutron-tempest-linuxbridge/2502b64/logs/screen-q-svc.txt.gz#_Jan_29_16_01_37_142123
17:01:45 mriedem RESP BODY: {"events": [{"status": "completed", "tag": "8de74fd2-a3bc-4d41-9c11-c04f25b52b6d", "name": "network-vif-plugged", "server_uuid": "3fa55d94-b1f4-42f4-8ba0-9ca46c71d7c0", "code": 200}]}
17:02:20 mriedem maybe there is just a bug in logging with request ids getting mixed up, idk, but i feel like i've seen that before
17:02:27 melwitt mriedem: how do you know the first one is the call from the compute manager reboot method?
17:02:28 sean-k-mooney mriedem: https://github.com/openstack/neutron/blob/3f1a9846d23198f4a89f89bac73ba80ef201dea0/neutron/notifiers/nova.py#L178-L215 if we go directly from active to build the unpugged event will not be sent
17:02:43 mriedem melwitt: same request id
17:03:05 sean-k-mooney melwitt: that is why we are seeing the ignored event http://logs.openstack.org/42/525842/11/check/neutron-tempest-linuxbridge/2502b64/logs/screen-q-svc.txt.gz#_Jan_29_16_01_36_095844
17:03:08 melwitt oh derp, I see now
17:03:16 melwitt got it
17:03:44 mriedem i don't know why we'd go from active to build
17:03:57 melwitt well, the external instance events are REST API calls to nova from neutron so they'd have separate request ids, right?
17:04:07 mriedem they shoud
17:04:09 mriedem *should
17:04:59 melwitt but yeah why the vif plug event call and the refresh info cache call have the same id doesn't make sense if we don't refresh for a plug event
17:05:29 mriedem i don't really trust the request id logging lately
17:07:15 mriedem so, again, idk wtf is going on - and since we can't rely on this, it seems we just can't wait for vif plugged events during hard reboot and have to punt on that
17:07:45 mriedem definitely some weird timing issues
17:08:09 mriedem this is likely also something one might not see in the real world,
17:08:16 mriedem because tempest is creating an instance and then immediately hard rebooting it

Earlier   Later