Earlier  
Later
New Search
Posted Nick Remark
#openstack-nova - 2018-02-02
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
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
18:28:37 sean-k-mooney melwitt: looking at http://logs.openstack.org/42/525842/11/check/neutron-tempest-linuxbridge/2502b64/logs/screen-n-cpu.txt.gz#_Jan_29_16_01_37_811903 we are configuring libvirt to add the interface to the bridge iteself. the linuxbridge os-vif plugin plug method seams to be doing a lot of work that is not strictly require for neutron and presuable is there for nova network
18:30:24 sean-k-mooney for example it also addes the vm port to the bridge if not already done so and also ensure the bridge existis and has an uplink port (phyical or vlan) added and brings up the bridge
18:31:25 sean-k-mooney the only thing its doing that is really required is setting the mtu and making sure ip adresses are not configured on the tap on the host.
18:32:05 sean-k-mooney i would guess we can make that driver alot smaller once nova-networks support can be dropped.
19:18:07 openstackgerrit Matt Riedemann proposed openstack/nova stable/pike: doc: Add user index page https://review.openstack.org/540494
19:18:08 openstackgerrit Matt Riedemann proposed openstack/nova stable/pike: Migrate "launch instance" user guide docs https://review.openstack.org/540495
20:01:14 openstackgerrit Matt Riedemann proposed openstack/nova master: libvirt: fix native luks encryption failure to find volume_id https://review.openstack.org/539739
20:18:24 openstackgerrit Brianna Poulos proposed openstack/nova master: docs: Add booting from an encrypted volume https://review.openstack.org/540506
20:30:52 openstackgerrit Matt Riedemann proposed openstack/nova master: Fix test_get_allocation_candidates tests https://review.openstack.org/540513

Earlier   Later