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-9ca46c71d7c0] Preparing to wait for external event network-vif-plugged-8de74fd2-a3bc-4d41-9c11-c04f25b52b6d {{(pid=29444) prepare_for_instance_event /opt/stack/new/nova/nova/compute/manager.py:325}}

plugs the vif,

Jan 29 16:01:38.118916 ubuntu-xenial-rax-ord-0002240582 nova-compute[29444]: INFO os_vif [None req-125bc0b4-7bac-413f-9a8f-0f56750108bd service nova] Successfully plugged 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')

and doesn't receive another plug event from neutron, and times out waiting.

[1] http://logs.openstack.org/42/525842/11/check/neutron-tempest-linuxbridge/2502b64/logs/screen-n-cpu.txt.gz#_Jan_29_16_01_36_673427