yahoo-eng-team team mailing list archive

[Matt Riedemann <mriedem.os@xxxxxxxxx>]

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