Earlier  
Later
New Search
Posted Nick Remark
#openstack-nova - 2018-02-02
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 at that point, it says the vif is active
16:44:07 mriedem "active": true
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
17:08:34 mriedem which is probably not helping the timing issue with the various events and such
17:09:13 mriedem which we could then argue, our code *should* wait for a vif plugged event during hard reboot...but it fails in the gate
17:09:30 melwitt yeah, agree
17:09:58 melwitt I'm working on the comment update, just was also examining logs and discussing about it in the middle of it
17:10:04 mriedem we could make vif plugging timeout be non-fatal in the LB job, but that's also a hack, and likely the test would timeout by then anyway b/c we're waiting 5 minutes for something to happen
17:11:17 melwitt yeah
17:14:33 figleaf giblet: just pulled down PS5, and it still fails locally for me. I don't know what could be the difference.
17:14:46 mriedem totally unrelated, but noticed https://review.openstack.org/#/c/274869/ - in what case does _heal_instance_info_cache() care about the instance.flavor?
17:15:57 melwitt does it send any notifications? that's the only thing that comes to mind
17:15:59 mriedem there must be a notification getting sent when the instance is updated as a result of updating the nw info cache i guess
17:20:15 openstackgerrit melanie witt proposed openstack/nova master: Don't wait for vif plug events during _hard_reboot https://review.openstack.org/540168
17:20:51 melwitt mriedem bauwser ^
17:24:06 mriedem heading to lunch, will take a look when i'm back
17:24:17 melwitt cool, thanks
17:24:18 mriedem btw, do we get a network-changed event at least from neutron during reboot after we unplug the vifs?
17:24:24 mriedem i didn't look for that yet in the logs
17:25:20 melwitt we don't. as sean-k-mooney mentioned, the os-vif unplug method for linuxbridge is a no-op, it just does a pass, so that seems consistent with the lack of any event about it
17:27:28 melwitt here's the unplug http://logs.openstack.org/42/525842/11/check/neutron-tempest-linuxbridge/2502b64/logs/screen-n-cpu.txt.gz#_Jan_29_16_01_37_704617
17:56:25 figleaf giblet: looks like zuul's environment matches mine: http://logs.openstack.org/86/540386/5/check/openstack-tox-py27/2b58498/job-output.txt.gz#_2018-02-02_17_26_13_388933

Earlier   Later