yahoo-eng-team team mailing list archive

[Matt Riedemann <mriedem.os@xxxxxxxxx>]

** Also affects: nova/pike
   Importance: Undecided
       Status: New

** Also affects: nova/queens
   Importance: Undecided
       Status: New

** Changed in: nova/pike
     Assignee: (unassigned) => s10 (vlad-esten)

** Changed in: nova/queens
     Assignee: (unassigned) => s10 (vlad-esten)

** Changed in: nova/pike
       Status: New => In Progress

** Changed in: nova/pike
   Importance: Undecided => Low

** Changed in: nova/queens
       Status: New => In Progress

** Changed in: nova/queens
   Importance: Undecided => Low

-- 
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):
  Fix Released
Status in OpenStack Compute (nova) pike series:
  In Progress
Status in OpenStack Compute (nova) queens series:
  In Progress

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