yahoo-eng-team team mailing list archive

[OpenStack Infra <1756994@xxxxxxxxxxxxxxxxxx>]

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

commit bbb668bbec2e2fa6b7f64b9af9504b973016058c
Author: Matt Riedemann <mriedem.os@xxxxxxxxx>
Date:   Mon Mar 19 19:24:32 2018 -0400

    Fix message for unexpected external event
    
    During live migration, we get vif plugged events
    that we're not waiting for, and if InstanceEvents._events
    is empty, pop_instance_event() will log a message about
    shutting down, but the compute service isn't actually
    shutting down. When it is, ComputeManager.cleanup_host()
    calls cancel_all_events() which sets _events to None, so
    we should only mention shutting down when _events is None.
    
    Change-Id: Ie868273c4b9629f9b35645df5785304ebba5d64c
    Closes-Bug: #1756994


** Changed in: nova
       Status: In Progress => Fix Released

-- 
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

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