test_server_security_groups failed to reboot with "Domain not found: no domain with matching uuid" because of missing vif event from linuxbridge agent

I wonder if this is related to https://review.openstack.org/#/c/400384/.

nova-compute isn't ignoring the event due to the instance state, it's just logging the current state of the instance when it got the event.

Related fix proposed to branch: master
Review: https://review.openstack.org/538103

Unfortunately the log link from comment 0 is a "File Not Found" today because of zuul issues, but in examining the code I think what's happening is we're waiting for a plug event for a different vif['id'] than the one we're receiving from neutron.

The patch [1] Matt linked in comment 1 changed the behavior of hard reboot such that it will unplug vifs and then re-plug vifs when previously it did not do anything with the vifs.

So upon receiving a reboot request, we query network_info from neutron and pass it down to the driver reboot, the driver uses network_info to unplug vifs, then uses the same network_info to plug vifs again while re-creating the virt domain.

When we plug vifs, we only register to wait on events for vifs whose status is not 'active' in the network_info. And when we unplug vifs, we don't wait for any indication from neutron that the unplugging has been completed. So, I wonder if this is a race where we unplug vifs and then immediately try to plug them again before they have transitioned away from 'active'.

The thing that doesn't make sense is why we're waiting for a different vif_id to be plugged instead of not waiting for any events at all. I thought there would only be one vif_id and if it's not 'active', we would have an empty event list and therefore not wait for any events. Do vif_ids change if unplugged and plugged again?

I've added logging of the event_names to the "Timeout waiting ..." log message in a related patch to help with debugging when it happens again.

[1] https://review.openstack.org/#/c/400384/

Looking at a new set of logs for the same bug today, I found that the message in n-cpu [1]:

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.

is received after we have begun the hard reboot, while we are tearing down the virt domain for the instance, *before* we even attempt to unplug the vif and re-plug it. Could this be an erroneous re-sending of the original plug event that occurred during the initial instance creation?

This is the event for the initial instance boot, from q-svc:

Jan 29 16:01:31.012692 ubuntu-xenial-rax-ord-0002240582 neutron-server[21191]: DEBUG neutron.notifiers.nova [-] Sending events: [{'status': 'completed', 'tag': u'8de74fd2-a3bc-4d41-9c11-c04f25b52b6d', 'name': 'network-vif-plugged', 'server_uuid': u'3fa55d94-b1f4-42f4-8ba0-9ca46c71d7c0'}] {{(pid=21288) send_events /opt/stack/new/neutron/neutron/notifiers/nova.py:241}}

We later see a network-changed event just before the reboot in q-svc. Maybe this comes from the :

Jan 29 16:01:35.091047 ubuntu-xenial-rax-ord-0002240582 neutron-server[21191]: DEBUG neutron.notifiers.nova [-] Sending events: [{'tag': u'8de74fd2-a3bc-4d41-9c11-c04f25b52b6d', 'name': 'network-changed', 'server_uuid': u'3fa55d94-b1f4-42f4-8ba0-9ca46c71d7c0'}] {{(pid=21286) send_events /opt/stack/new/neutron/neutron/notifiers/nova.py:241}}

Reboot initiated in n-cpu:

Jan 29 16:01:35.600736 ubuntu-xenial-rax-ord-0002240582 nova-compute[29444]: INFO nova.compute.manager [None req-8935127a-f033-4675-92c5-b1720131f285 tempest-SecurityGroupsTestJSON-504835102 tempest-SecurityGroupsTestJSON-504835102] [instance: 3fa55d94-b1f4-42f4-8ba0-9ca46c71d7c0] Rebooting instance

Then we see neutron send an unexpected plug event, we haven't plugged the vif yet:

Jan 29 16:01:36.514905 ubuntu-xenial-rax-ord-0002240582 neutron-server[21191]: DEBUG neutron.notifiers.nova [-] Sending events: [{'status': 'completed', 'tag': u'8de74fd2-a3bc-4d41-9c11-c04f25b52b6d', 'name': 'network-vif-plugged', 'server_uuid': u'3fa55d94-b1f4-42f4-8ba0-9ca46c71d7c0'}] {{(pid=21288) send_events /opt/stack/new/neutron/neutron/notifiers/nova.py:241}}

And then n-cpu logs "Received unexpected event".

Then, n-cpu unplugs the vif,

Jan 29 16:01:37.704617 ubuntu-xenial-rax-ord-0002240582 nova-compute[29444]: INFO os_vif [None req-1cb07971-b6f2-41f9-b34b-bc03b867abdb service nova] Successfully unplugged vif VIFBridge(active=False,address=fa:16:3e:58:eb:2a,bridge_name='brq169b5db1-db',has_traffic_filtering=True,id=8de74fd2-a3bc-4d41-9c11-c04f25b52b6d,network=Network(169b5db1-db8e-4c45-b3ad-23e2aa4e1908),plugin='linux_bridge',port_profile=<?>,preserve_on_delete=False,vif_name='tap8de74fd2-a3')

prepares to wait for the plug event,

Jan 29 16:01:38.080682 ubuntu-xenial-rax-ord-0002240582 nova-compute[29444]: DEBUG nova.compute.manager [None req-125bc0b4-7bac-413f-9a8f-0f56750108bd service nova] [instance: 3fa55d94-b1f4-42f4-8ba0-9ca46c71d...

I think I found the answer. It looks like this was already documented in our code in a different place [1]:

        # NOTE(mriedem): vifs_already_plugged=True here, regardless of whether
        # or not we've migrated to another host, because we unplug VIFs locally
        # and the status change in the port might go undetected by the neutron
        # L2 agent (or neutron server) so neutron may not know that the VIF was
        # unplugged in the first place and never send an event.
        guest = self._create_domain_and_network(context, xml, instance,
                                        network_info,
                                        block_device_info=block_device_info,
                                        power_on=power_on,
                                        vifs_already_plugged=True,
                                        post_xml_callback=gen_confdrive)

So, we shouldn't be waiting for vif plug events if we've only locally unplugged vifs.

[1] https://github.com/openstack/nova/blob/d189e68/nova/virt/libvirt/driver.py#L8088-L8092

Fix proposed to branch: master
Review: https://review.openstack.org/540168

Reviewed: https://review.openstack.org/538103
Committed: https://git.openstack.org/cgit/openstack/nova/commit/?id=6ea939b792279595e37b80fff3d44c1e712d4fc7
Submitter: Zuul
Branch: master

commit 6ea939b792279595e37b80fff3d44c1e712d4fc7
Author: melanie witt <email address hidden>
Date: Fri Jan 26 01:30:51 2018 +0000

    Log the events we timed out waiting for while plugging vifs

    We currently log that we timed out waiting for vif plugging callbacks
    from neutron but we don't include detail about which vif_ids we were
    waiting for. This adds the event_names to the log message to aid
    in debugging.

    Related-Bug: #1744361

    Change-Id: I8b67f1049b6a968b1dd0d839a7f0b30aa1730eeb

We'll also have to backport the nova change to stable/pike since we merged this which caused the regression:

https://review.openstack.org/#/c/531407/

Reviewed: https://review.openstack.org/540168
Committed: https://git.openstack.org/cgit/openstack/nova/commit/?id=236bb54493385bcfe2034e8b0fd7a387fa66635a
Submitter: Zuul
Branch: master

commit 236bb54493385bcfe2034e8b0fd7a387fa66635a
Author: melanie witt <email address hidden>
Date: Thu Feb 1 22:27:57 2018 +0000

    Don't wait for vif plug events during _hard_reboot

    Originally, in change Id188d48609f3d22d14e16c7f6114291d547a8986 we
    added a re-initialization of volumes, encryptors, and vifs to hard
    reboot. When creating the libvirt domain and network, we were waiting
    for vif plug events from neutron when we replugged the vifs. Then, we
    started seeing timeouts in the linuxbridge gate job because compute
    was timing out waiting for plug events from neutron during a hard
    reboot.

    It turns out that the behavior of neutron plug events depends on what
    vif type we're using and we're also using a stale network info_cache
    throughout the hard reboot code path, so we can't be 100% sure we know
    which vifs to wait for plug events from anyway. We coincidentally get
    some info_cache refreshes from network-changed events from neutron,
    but we shouldn't rely on that.

    Ideally, we could do something like wait for an unplug event after we
    unplug the vif, then refresh the network_info cache, then wait for the
    plug event. BUT, in the case of the os-vif linuxbridge unplug method,
    it is a no-op, so I don't think we could expect to get an unplug
    event for it (and we don't see any network-vif-unplugged events sent
    in the q-svc log for the linuxbridge job during a hard reboot).

    Closes-Bug: #1744361

    Change-Id: Ib0cf5d55750f13d0499a570f14024dca551ed4d4

Fix proposed to branch: stable/pike
Review: https://review.openstack.org/540555

Reviewed: https://review.openstack.org/540555
Committed: https://git.openstack.org/cgit/openstack/nova/commit/?id=83ffc76edd360929925fc4bb66e5dcbf8254a30e
Submitter: Zuul
Branch: stable/pike

commit 83ffc76edd360929925fc4bb66e5dcbf8254a30e
Author: melanie witt <email address hidden>
Date: Thu Feb 1 22:27:57 2018 +0000

    Don't wait for vif plug events during _hard_reboot

    Originally, in change Id188d48609f3d22d14e16c7f6114291d547a8986 we
    added a re-initialization of volumes, encryptors, and vifs to hard
    reboot. When creating the libvirt domain and network, we were waiting
    for vif plug events from neutron when we replugged the vifs. Then, we
    started seeing timeouts in the linuxbridge gate job because compute
    was timing out waiting for plug events from neutron during a hard
    reboot.

    It turns out that the behavior of neutron plug events depends on what
    vif type we're using and we're also using a stale network info_cache
    throughout the hard reboot code path, so we can't be 100% sure we know
    which vifs to wait for plug events from anyway. We coincidentally get
    some info_cache refreshes from network-changed events from neutron,
    but we shouldn't rely on that.

    Ideally, we could do something like wait for an unplug event after we
    unplug the vif, then refresh the network_info cache, then wait for the
    plug event. BUT, in the case of the os-vif linuxbridge unplug method,
    it is a no-op, so I don't think we could expect to get an unplug
    event for it (and we don't see any network-vif-unplugged events sent
    in the q-svc log for the linuxbridge job during a hard reboot).

    Closes-Bug: #1744361

    Change-Id: Ib0cf5d55750f13d0499a570f14024dca551ed4d4
    (cherry picked from commit 236bb54493385bcfe2034e8b0fd7a387fa66635a)

Fix proposed to branch: stable/ocata
Review: https://review.openstack.org/540680

Reviewed: https://review.openstack.org/540680
Committed: https://git.openstack.org/cgit/openstack/nova/commit/?id=b9f9e0912101f28d4a3706b16f194b4f17ae60c2
Submitter: Zuul
Branch: stable/ocata

commit b9f9e0912101f28d4a3706b16f194b4f17ae60c2
Author: melanie witt <email address hidden>
Date: Thu Feb 1 22:27:57 2018 +0000

    Don't wait for vif plug events during _hard_reboot

    Originally, in change Id188d48609f3d22d14e16c7f6114291d547a8986 we
    added a re-initialization of volumes, encryptors, and vifs to hard
    reboot. When creating the libvirt domain and network, we were waiting
    for vif plug events from neutron when we replugged the vifs. Then, we
    started seeing timeouts in the linuxbridge gate job because compute
    was timing out waiting for plug events from neutron during a hard
    reboot.

    It turns out that the behavior of neutron plug events depends on what
    vif type we're using and we're also using a stale network info_cache
    throughout the hard reboot code path, so we can't be 100% sure we know
    which vifs to wait for plug events from anyway. We coincidentally get
    some info_cache refreshes from network-changed events from neutron,
    but we shouldn't rely on that.

    Ideally, we could do something like wait for an unplug event after we
    unplug the vif, then refresh the network_info cache, then wait for the
    plug event. BUT, in the case of the os-vif linuxbridge unplug method,
    it is a no-op, so I don't think we could expect to get an unplug
    event for it (and we don't see any network-vif-unplugged events sent
    in the q-svc log for the linuxbridge job during a hard reboot).

    Conflicts:
            nova/tests/unit/virt/libvirt/test_driver.py
            nova/virt/libvirt/driver.py

    NOTE(lyarwood): As with the stable/ocata version of
    Id188d48609f3d22d14e16c7f6114291d547a8986 these conflicts are caused by
    _create_domain_and_network using an additional disk_info argument in O.

    Closes-Bug: #1744361

    Change-Id: Ib0cf5d55750f13d0499a570f14024dca551ed4d4
    (cherry picked from commit 236bb54493385bcfe2034e8b0fd7a387fa66635a)
    (cherry picked from commit 83ffc76edd360929925fc4bb66e5dcbf8254a30e)

Related fix proposed to branch: master
Review: https://review.openstack.org/541442

Reviewed: https://review.openstack.org/541442
Committed: https://git.openstack.org/cgit/openstack/nova/commit/?id=aaf37a26d6caa124f0cc6c3fe21bfdf58ccb8517
Submitter: Zuul
Branch: master

commit aaf37a26d6caa124f0cc6c3fe21bfdf58ccb8517
Author: melanie witt <email address hidden>
Date: Tue Feb 6 20:32:33 2018 +0000

    Refine waiting for vif plug events during _hard_reboot

    In change Ib0cf5d55750f13d0499a570f14024dca551ed4d4, we stopped waiting
    for vif plug events during hard reboot and start, because the behavior
    of neutron plug events depended on the vif type and we couldn't rely on
    the stale network info cache.

    This refines the logic not to wait for vif plug events only for the
    bridge vif type, instead of for all types. We also add a flag to
    _create_domain_and_network to indicate that we're in the middle of a
    reboot and to expect to wait for plug events for all vif types except
    the bridge vif type, regardless of the vif's 'active' status.

    We only query network_info from neutron at the beginning of a reboot,
    before we've unplugged anything, so the majority of the time, the vifs
    will be active=True. The current logic in get_neutron_events will only
    expect events for vifs with 'active' status False. This adds a way to
    override that if we know we've already unplugged vifs as part of a
    reboot.

    Related-Bug: #1744361

    Change-Id: Ib08afad3822f2ca95cfeea18d7f4fc4cb407b4d6

This issue was fixed in the openstack/nova 17.0.0.0rc1 release candidate.

Related fix proposed to branch: stable/queens
Review: https://review.openstack.org/542738

Related fix proposed to branch: stable/pike
Review: https://review.openstack.org/542748

Related fix proposed to branch: stable/ocata
Review: https://review.openstack.org/542767

This issue was fixed in the openstack/nova 16.1.0 release.

Reviewed: https://review.openstack.org/542738
Committed: https://git.openstack.org/cgit/openstack/nova/commit/?id=5a10047f9dd4383f6ec9046d392f26c93f8420d4
Submitter: Zuul
Branch: stable/queens

commit 5a10047f9dd4383f6ec9046d392f26c93f8420d4
Author: melanie witt <email address hidden>
Date: Tue Feb 6 20:32:33 2018 +0000

    Refine waiting for vif plug events during _hard_reboot

    In change Ib0cf5d55750f13d0499a570f14024dca551ed4d4, we stopped waiting
    for vif plug events during hard reboot and start, because the behavior
    of neutron plug events depended on the vif type and we couldn't rely on
    the stale network info cache.

    This refines the logic not to wait for vif plug events only for the
    bridge vif type, instead of for all types. We also add a flag to
    _create_domain_and_network to indicate that we're in the middle of a
    reboot and to expect to wait for plug events for all vif types except
    the bridge vif type, regardless of the vif's 'active' status.

    We only query network_info from neutron at the beginning of a reboot,
    before we've unplugged anything, so the majority of the time, the vifs
    will be active=True. The current logic in get_neutron_events will only
    expect events for vifs with 'active' status False. This adds a way to
    override that if we know we've already unplugged vifs as part of a
    reboot.

    Related-Bug: #1744361

    Change-Id: Ib08afad3822f2ca95cfeea18d7f4fc4cb407b4d6
    (cherry picked from commit aaf37a26d6caa124f0cc6c3fe21bfdf58ccb8517)

Reviewed: https://review.openstack.org/542748
Committed: https://git.openstack.org/cgit/openstack/nova/commit/?id=e06ad602f3ef98c505e49078dd225dde2a79e2a1
Submitter: Zuul
Branch: stable/pike

commit e06ad602f3ef98c505e49078dd225dde2a79e2a1
Author: melanie witt <email address hidden>
Date: Tue Feb 6 20:32:33 2018 +0000

    Refine waiting for vif plug events during _hard_reboot

    In change Ib0cf5d55750f13d0499a570f14024dca551ed4d4, we stopped waiting
    for vif plug events during hard reboot and start, because the behavior
    of neutron plug events depended on the vif type and we couldn't rely on
    the stale network info cache.

    This refines the logic not to wait for vif plug events only for the
    bridge vif type, instead of for all types. We also add a flag to
    _create_domain_and_network to indicate that we're in the middle of a
    reboot and to expect to wait for plug events for all vif types except
    the bridge vif type, regardless of the vif's 'active' status.

    We only query network_info from neutron at the beginning of a reboot,
    before we've unplugged anything, so the majority of the time, the vifs
    will be active=True. The current logic in get_neutron_events will only
    expect events for vifs with 'active' status False. This adds a way to
    override that if we know we've already unplugged vifs as part of a
    reboot.

    Conflicts:
            nova/virt/libvirt/driver.py

    NOTE(lyarwood): Ica323b87fa85a454fca9d46ada3677f18fe50022 and
    I13de970c3beed29311d43991115a0c6d28ac14e0 are the source of the above
    conflicts in driver.py. The first removed encryptor attach logic from
    _create_domain_and_network in Queens while the second altered the
    signature of _create_domain_and_network in Queens, removing reboot that
    is then reintroduced with this change.

    Related-Bug: #1744361

    Change-Id: Ib08afad3822f2ca95cfeea18d7f4fc4cb407b4d6
    (cherry picked from commit aaf37a26d6caa124f0cc6c3fe21bfdf58ccb8517)
    (cherry picked from commit 5a10047f9dd4383f6ec9046d392f26c93f8420d4)

Change abandoned by Lee Yarwood (<email address hidden>) on branch: stable/ocata
Review: https://review.openstack.org/542767

This issue was fixed in the openstack/nova 15.1.1 release.