Public bug reported: As seen here:
http://logs.openstack.org/71/551371/6/check/legacy-tempest-dsvm- multinode-live- migration/4d466b2/logs/subnode-2/screen-n-cpu.txt.gz#_Mar_19_14_25_07_798071 Mar 19 14:25:07.797329 ubuntu-xenial-rax-dfw-0003055554 nova-compute[29059]: DEBUG nova.compute.manager [None req-24e1d4e3-6f9c-4438-8059-5f7cf69566f0 service nova] [instance: 6347c3ea-894c-4cc8-a3b4-ea9bfe49033e] Received event network-vif-plugged-cd0afcf3-c654-488e-b578-6d3c45f3a5a5 {{(pid=29059) external_instance_event /opt/stack/new/nova/nova/compute/manager.py:7702}} Mar 19 14:25:07.797762 ubuntu-xenial-rax-dfw-0003055554 nova-compute[29059]: DEBUG oslo_concurrency.lockutils [None req-24e1d4e3-6f9c-4438-8059-5f7cf69566f0 service nova] Lock "6347c3ea-894c-4cc8-a3b4-ea9bfe49033e-events" acquired by "nova.compute.manager._pop_event" :: waited 0.000s {{(pid=29059) inner /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:273}} Mar 19 14:25:07.798071 ubuntu-xenial-rax-dfw-0003055554 nova-compute[29059]: DEBUG nova.compute.manager [None req-24e1d4e3-6f9c-4438-8059-5f7cf69566f0 service nova] [instance: 6347c3ea-894c-4cc8-a3b4-ea9bfe49033e] Unexpected attempt to pop events during shutdown {{(pid=29059) _pop_event /opt/stack/new/nova/nova/compute/manager.py:347}} Mar 19 14:25:07.798448 ubuntu-xenial-rax-dfw-0003055554 nova-compute[29059]: DEBUG oslo_concurrency.lockutils [None req-24e1d4e3-6f9c-4438-8059-5f7cf69566f0 service nova] Lock "6347c3ea-894c-4cc8-a3b4-ea9bfe49033e-events" released by "nova.compute.manager._pop_event" :: held 0.001s {{(pid=29059) inner /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:285}} Mar 19 14:25:07.798780 ubuntu-xenial-rax-dfw-0003055554 nova-compute[29059]: DEBUG nova.compute.manager [None req-24e1d4e3-6f9c-4438-8059-5f7cf69566f0 service nova] [instance: 6347c3ea-894c-4cc8-a3b4-ea9bfe49033e] No waiting events found dispatching network-vif-plugged-cd0afcf3-c654-488e-b578-6d3c45f3a5a5 {{(pid=29059) pop_instance_event /opt/stack/new/nova/nova/compute/manager.py:363}} Mar 19 14:25:07.799222 ubuntu-xenial-rax-dfw-0003055554 nova-compute[29059]: WARNING nova.compute.manager [None req-24e1d4e3-6f9c-4438-8059-5f7cf69566f0 service nova] [instance: 6347c3ea-894c-4cc8-a3b4-ea9bfe49033e] Received unexpected event network-vif-plugged-cd0afcf3-c654-488e-b578-6d3c45f3a5a5 for instance with vm_state active and task_state migrating. This is when the destination host has plugged VIFs during pre_live_migration, and then because the external server events are routed to the host that the instance is currently on (source host during live migration), the events are routed there and nothing is waiting on them. The message is misleading since the compute service isn't shutting down, it's just that nothing is waiting on the event, which is OK. That comes from this code: https://github.com/openstack/nova/blob/43c72f02f277d6f1083e5e9a4009d3d03d965368/nova/compute/manager.py#L346 That should be comparing self._events to None which indicates shutdown: https://github.com/openstack/nova/blob/43c72f02f277d6f1083e5e9a4009d3d03d965368/nova/compute/manager.py#L398 https://github.com/openstack/nova/blob/43c72f02f277d6f1083e5e9a4009d3d03d965368/nova/compute/manager.py#L1166 ** Affects: nova Importance: Low Assignee: Matt Riedemann (mriedem) Status: Triaged ** Tags: compute serviceability -- You received this bug notification because you are a member of Yahoo! Engineering Team, which is subscribed to OpenStack Compute (nova). https://bugs.launchpad.net/bugs/1756994 Title: Misleading log messages "Unexpected attempt to pop events during shutdown" on source host during live migration Status in OpenStack Compute (nova): Triaged Bug description: As seen here: http://logs.openstack.org/71/551371/6/check/legacy-tempest-dsvm- multinode-live- migration/4d466b2/logs/subnode-2/screen-n-cpu.txt.gz#_Mar_19_14_25_07_798071 Mar 19 14:25:07.797329 ubuntu-xenial-rax-dfw-0003055554 nova-compute[29059]: DEBUG nova.compute.manager [None req-24e1d4e3-6f9c-4438-8059-5f7cf69566f0 service nova] [instance: 6347c3ea-894c-4cc8-a3b4-ea9bfe49033e] Received event network-vif-plugged-cd0afcf3-c654-488e-b578-6d3c45f3a5a5 {{(pid=29059) external_instance_event /opt/stack/new/nova/nova/compute/manager.py:7702}} Mar 19 14:25:07.797762 ubuntu-xenial-rax-dfw-0003055554 nova-compute[29059]: DEBUG oslo_concurrency.lockutils [None req-24e1d4e3-6f9c-4438-8059-5f7cf69566f0 service nova] Lock "6347c3ea-894c-4cc8-a3b4-ea9bfe49033e-events" acquired by "nova.compute.manager._pop_event" :: waited 0.000s {{(pid=29059) inner /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:273}} Mar 19 14:25:07.798071 ubuntu-xenial-rax-dfw-0003055554 nova-compute[29059]: DEBUG nova.compute.manager [None req-24e1d4e3-6f9c-4438-8059-5f7cf69566f0 service nova] [instance: 6347c3ea-894c-4cc8-a3b4-ea9bfe49033e] Unexpected attempt to pop events during shutdown {{(pid=29059) _pop_event /opt/stack/new/nova/nova/compute/manager.py:347}} Mar 19 14:25:07.798448 ubuntu-xenial-rax-dfw-0003055554 nova-compute[29059]: DEBUG oslo_concurrency.lockutils [None req-24e1d4e3-6f9c-4438-8059-5f7cf69566f0 service nova] Lock "6347c3ea-894c-4cc8-a3b4-ea9bfe49033e-events" released by "nova.compute.manager._pop_event" :: held 0.001s {{(pid=29059) inner /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:285}} Mar 19 14:25:07.798780 ubuntu-xenial-rax-dfw-0003055554 nova-compute[29059]: DEBUG nova.compute.manager [None req-24e1d4e3-6f9c-4438-8059-5f7cf69566f0 service nova] [instance: 6347c3ea-894c-4cc8-a3b4-ea9bfe49033e] No waiting events found dispatching network-vif-plugged-cd0afcf3-c654-488e-b578-6d3c45f3a5a5 {{(pid=29059) pop_instance_event /opt/stack/new/nova/nova/compute/manager.py:363}} Mar 19 14:25:07.799222 ubuntu-xenial-rax-dfw-0003055554 nova-compute[29059]: WARNING nova.compute.manager [None req-24e1d4e3-6f9c-4438-8059-5f7cf69566f0 service nova] [instance: 6347c3ea-894c-4cc8-a3b4-ea9bfe49033e] Received unexpected event network-vif-plugged-cd0afcf3-c654-488e-b578-6d3c45f3a5a5 for instance with vm_state active and task_state migrating. This is when the destination host has plugged VIFs during pre_live_migration, and then because the external server events are routed to the host that the instance is currently on (source host during live migration), the events are routed there and nothing is waiting on them. The message is misleading since the compute service isn't shutting down, it's just that nothing is waiting on the event, which is OK. That comes from this code: https://github.com/openstack/nova/blob/43c72f02f277d6f1083e5e9a4009d3d03d965368/nova/compute/manager.py#L346 That should be comparing self._events to None which indicates shutdown: https://github.com/openstack/nova/blob/43c72f02f277d6f1083e5e9a4009d3d03d965368/nova/compute/manager.py#L398 https://github.com/openstack/nova/blob/43c72f02f277d6f1083e5e9a4009d3d03d965368/nova/compute/manager.py#L1166 To manage notifications about this bug go to: https://bugs.launchpad.net/nova/+bug/1756994/+subscriptions -- Mailing list: https://launchpad.net/~yahoo-eng-team Post to : [email protected] Unsubscribe : https://launchpad.net/~yahoo-eng-team More help : https://help.launchpad.net/ListHelp
