yahoo-eng-team team mailing list archive

Thread
Date
[Bug 1645464] Re: InstanceNotFound stacktrace in _process_instance_vif_deleted_event

To: yahoo-eng-team@xxxxxxxxxxxxxxxxxxx
From: OpenStack Infra <1645464@xxxxxxxxxxxxxxxxxx>
Date: Tue, 31 Jan 2017 20:42:22 -0000
Reply-to: Bug 1645464 <1645464@xxxxxxxxxxxxxxxxxx>
Sender: bounces@xxxxxxxxxxxxx
Reviewed:  https://review.openstack.org/403925
Committed: https://git.openstack.org/cgit/openstack/nova/commit/?id=4fce45f83bd510202fd1cbcdb7694361c41e9400
Submitter: Jenkins
Branch:    master

commit 4fce45f83bd510202fd1cbcdb7694361c41e9400
Author: Matt Riedemann <mriedem@xxxxxxxxxx>
Date:   Mon Nov 28 17:07:51 2016 -0500

    Pre-load info_cache when handling external events and handle NotFound
    
    Before change a5b920a197c70d2ae08a1e1335d979857f923b4f we'd join the
    info_cache column when getting the instance in the API. Without
    joining the info_cache column when getting the instance, that has
    to be lazy-loaded on the compute when processing an external
    neutron event, like network-vif-deleted. So this change pre-loads
    the info_cache in the API again as an optimization.
    
    There is also a race to contend with here when deleting an instance.
    Neutron can send the network-vif-deleted event after we've already
    marked the instance as deleted in the database, at which point
    lazy-loading info_cache (or updating InstanceInfoCache for that
    matter), can result in an Instance(InfoCache)NotFound error, so this
    change handles that also.
    
    Change-Id: Ia3b4288691b392d56324e9d13c92e8e0b0d81e76
    Closes-Bug: #1645464


** 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/1645464

Title:
  InstanceNotFound stacktrace in _process_instance_vif_deleted_event

Status in OpenStack Compute (nova):
  Fix Released
Status in OpenStack Compute (nova) newton series:
  Confirmed

Bug description:
  Seen in a CI run here:

  http://logs.openstack.org/16/393416/6/check/gate-tempest-dsvm-full-
  devstack-plugin-ceph-ubuntu-
  xenial/44f3329/logs/screen-n-cpu.txt.gz?level=TRACE#_2016-11-28_17_34_36_535

  2016-11-28 17:34:36.535 2361 ERROR oslo_messaging.rpc.server [req-8d784631-28c2-41b4-8175-7cfb59480838 nova service] Exception during message handling
  2016-11-28 17:34:36.535 2361 ERROR oslo_messaging.rpc.server Traceback (most recent call last):
  2016-11-28 17:34:36.535 2361 ERROR oslo_messaging.rpc.server   File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/rpc/server.py", line 155, in _process_incoming
  2016-11-28 17:34:36.535 2361 ERROR oslo_messaging.rpc.server     res = self.dispatcher.dispatch(message)
  2016-11-28 17:34:36.535 2361 ERROR oslo_messaging.rpc.server   File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/rpc/dispatcher.py", line 225, in dispatch
  2016-11-28 17:34:36.535 2361 ERROR oslo_messaging.rpc.server     return self._do_dispatch(endpoint, method, ctxt, args)
  2016-11-28 17:34:36.535 2361 ERROR oslo_messaging.rpc.server   File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/rpc/dispatcher.py", line 195, in _do_dispatch
  2016-11-28 17:34:36.535 2361 ERROR oslo_messaging.rpc.server     result = func(ctxt, **new_args)
  2016-11-28 17:34:36.535 2361 ERROR oslo_messaging.rpc.server   File "/opt/stack/new/nova/nova/exception_wrapper.py", line 75, in wrapped
  2016-11-28 17:34:36.535 2361 ERROR oslo_messaging.rpc.server     function_name, call_dict, binary)
  2016-11-28 17:34:36.535 2361 ERROR oslo_messaging.rpc.server   File "/usr/local/lib/python2.7/dist-packages/oslo_utils/excutils.py", line 220, in __exit__
  2016-11-28 17:34:36.535 2361 ERROR oslo_messaging.rpc.server     self.force_reraise()
  2016-11-28 17:34:36.535 2361 ERROR oslo_messaging.rpc.server   File "/usr/local/lib/python2.7/dist-packages/oslo_utils/excutils.py", line 196, in force_reraise
  2016-11-28 17:34:36.535 2361 ERROR oslo_messaging.rpc.server     six.reraise(self.type_, self.value, self.tb)
  2016-11-28 17:34:36.535 2361 ERROR oslo_messaging.rpc.server   File "/opt/stack/new/nova/nova/exception_wrapper.py", line 66, in wrapped
  2016-11-28 17:34:36.535 2361 ERROR oslo_messaging.rpc.server     return f(self, context, *args, **kw)
  2016-11-28 17:34:36.535 2361 ERROR oslo_messaging.rpc.server   File "/opt/stack/new/nova/nova/compute/manager.py", line 6800, in external_instance_event
  2016-11-28 17:34:36.535 2361 ERROR oslo_messaging.rpc.server     event.tag)
  2016-11-28 17:34:36.535 2361 ERROR oslo_messaging.rpc.server   File "/opt/stack/new/nova/nova/compute/manager.py", line 6755, in _process_instance_vif_deleted_event
  2016-11-28 17:34:36.535 2361 ERROR oslo_messaging.rpc.server     network_info = instance.info_cache.network_info
  2016-11-28 17:34:36.535 2361 ERROR oslo_messaging.rpc.server   File "/usr/local/lib/python2.7/dist-packages/oslo_versionedobjects/base.py", line 67, in getter
  2016-11-28 17:34:36.535 2361 ERROR oslo_messaging.rpc.server     self.obj_load_attr(name)
  2016-11-28 17:34:36.535 2361 ERROR oslo_messaging.rpc.server   File "/opt/stack/new/nova/nova/objects/instance.py", line 1063, in obj_load_attr
  2016-11-28 17:34:36.535 2361 ERROR oslo_messaging.rpc.server     self._load_generic(attrname)
  2016-11-28 17:34:36.535 2361 ERROR oslo_messaging.rpc.server   File "/opt/stack/new/nova/nova/objects/instance.py", line 819, in _load_generic
  2016-11-28 17:34:36.535 2361 ERROR oslo_messaging.rpc.server     expected_attrs=[attrname])
  2016-11-28 17:34:36.535 2361 ERROR oslo_messaging.rpc.server   File "/usr/local/lib/python2.7/dist-packages/oslo_versionedobjects/base.py", line 177, in wrapper
  2016-11-28 17:34:36.535 2361 ERROR oslo_messaging.rpc.server     args, kwargs)
  2016-11-28 17:34:36.535 2361 ERROR oslo_messaging.rpc.server   File "/opt/stack/new/nova/nova/conductor/rpcapi.py", line 236, in object_class_action_versions
  2016-11-28 17:34:36.535 2361 ERROR oslo_messaging.rpc.server     args=args, kwargs=kwargs)
  2016-11-28 17:34:36.535 2361 ERROR oslo_messaging.rpc.server   File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/rpc/client.py", line 169, in call
  2016-11-28 17:34:36.535 2361 ERROR oslo_messaging.rpc.server     retry=self.retry)
  2016-11-28 17:34:36.535 2361 ERROR oslo_messaging.rpc.server   File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/transport.py", line 97, in _send
  2016-11-28 17:34:36.535 2361 ERROR oslo_messaging.rpc.server     timeout=timeout, retry=retry)
  2016-11-28 17:34:36.535 2361 ERROR oslo_messaging.rpc.server   File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py", line 467, in send
  2016-11-28 17:34:36.535 2361 ERROR oslo_messaging.rpc.server     retry=retry)
  2016-11-28 17:34:36.535 2361 ERROR oslo_messaging.rpc.server   File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py", line 458, in _send
  2016-11-28 17:34:36.535 2361 ERROR oslo_messaging.rpc.server     raise result
  2016-11-28 17:34:36.535 2361 ERROR oslo_messaging.rpc.server InstanceNotFound_Remote: Instance f2cbed80-0516-4c2a-b575-24b9885ec189 could not be found.
  2016-11-28 17:34:36.535 2361 ERROR oslo_messaging.rpc.server Traceback (most recent call last):
  2016-11-28 17:34:36.535 2361 ERROR oslo_messaging.rpc.server 
  2016-11-28 17:34:36.535 2361 ERROR oslo_messaging.rpc.server   File "/opt/stack/new/nova/nova/conductor/manager.py", line 87, in _object_dispatch
  2016-11-28 17:34:36.535 2361 ERROR oslo_messaging.rpc.server     return getattr(target, method)(*args, **kwargs)
  2016-11-28 17:34:36.535 2361 ERROR oslo_messaging.rpc.server 
  2016-11-28 17:34:36.535 2361 ERROR oslo_messaging.rpc.server   File "/usr/local/lib/python2.7/dist-packages/oslo_versionedobjects/base.py", line 184, in wrapper
  2016-11-28 17:34:36.535 2361 ERROR oslo_messaging.rpc.server     result = fn(cls, context, *args, **kwargs)
  2016-11-28 17:34:36.535 2361 ERROR oslo_messaging.rpc.server 
  2016-11-28 17:34:36.535 2361 ERROR oslo_messaging.rpc.server   File "/opt/stack/new/nova/nova/objects/instance.py", line 463, in get_by_uuid
  2016-11-28 17:34:36.535 2361 ERROR oslo_messaging.rpc.server     use_slave=use_slave)
  2016-11-28 17:34:36.535 2361 ERROR oslo_messaging.rpc.server 
  2016-11-28 17:34:36.535 2361 ERROR oslo_messaging.rpc.server   File "/opt/stack/new/nova/nova/db/sqlalchemy/api.py", line 226, in wrapper
  2016-11-28 17:34:36.535 2361 ERROR oslo_messaging.rpc.server     return f(*args, **kwargs)
  2016-11-28 17:34:36.535 2361 ERROR oslo_messaging.rpc.server 
  2016-11-28 17:34:36.535 2361 ERROR oslo_messaging.rpc.server   File "/opt/stack/new/nova/nova/objects/instance.py", line 455, in _db_instance_get_by_uuid
  2016-11-28 17:34:36.535 2361 ERROR oslo_messaging.rpc.server     columns_to_join=columns_to_join)
  2016-11-28 17:34:36.535 2361 ERROR oslo_messaging.rpc.server 
  2016-11-28 17:34:36.535 2361 ERROR oslo_messaging.rpc.server   File "/opt/stack/new/nova/nova/db/api.py", line 725, in instance_get_by_uuid
  2016-11-28 17:34:36.535 2361 ERROR oslo_messaging.rpc.server     return IMPL.instance_get_by_uuid(context, uuid, columns_to_join)
  2016-11-28 17:34:36.535 2361 ERROR oslo_messaging.rpc.server 
  2016-11-28 17:34:36.535 2361 ERROR oslo_messaging.rpc.server   File "/opt/stack/new/nova/nova/db/sqlalchemy/api.py", line 170, in wrapper
  2016-11-28 17:34:36.535 2361 ERROR oslo_messaging.rpc.server     return f(*args, **kwargs)
  2016-11-28 17:34:36.535 2361 ERROR oslo_messaging.rpc.server 
  2016-11-28 17:34:36.535 2361 ERROR oslo_messaging.rpc.server   File "/opt/stack/new/nova/nova/db/sqlalchemy/api.py", line 271, in wrapped
  2016-11-28 17:34:36.535 2361 ERROR oslo_messaging.rpc.server     return f(context, *args, **kwargs)
  2016-11-28 17:34:36.535 2361 ERROR oslo_messaging.rpc.server 
  2016-11-28 17:34:36.535 2361 ERROR oslo_messaging.rpc.server   File "/opt/stack/new/nova/nova/db/sqlalchemy/api.py", line 1885, in instance_get_by_uuid
  2016-11-28 17:34:36.535 2361 ERROR oslo_messaging.rpc.server     columns_to_join=columns_to_join)
  2016-11-28 17:34:36.535 2361 ERROR oslo_messaging.rpc.server 
  2016-11-28 17:34:36.535 2361 ERROR oslo_messaging.rpc.server   File "/opt/stack/new/nova/nova/db/sqlalchemy/api.py", line 1894, in _instance_get_by_uuid
  2016-11-28 17:34:36.535 2361 ERROR oslo_messaging.rpc.server     raise exception.InstanceNotFound(instance_id=uuid)
  2016-11-28 17:34:36.535 2361 ERROR oslo_messaging.rpc.server 
  2016-11-28 17:34:36.535 2361 ERROR oslo_messaging.rpc.server InstanceNotFound: Instance f2cbed80-0516-4c2a-b575-24b9885ec189 could not be found.
  2016-11-28 17:34:36.535 2361 ERROR oslo_messaging.rpc.server 
  2016-11-28 17:34:36.535 2361 ERROR oslo_messaging.rpc.server 

  We have a race when deleting an instance and deleting the ports
  attached to that instance. Neutron sends the vif-deleted event to nova
  and nova tries to refresh the InstanceInfoCache.network_info field but
  the instance is already deleted so we fail and log a stacktrace. We
  should handle the InstanceNotFound so we don't stacktrace in the n-cpu
  logs.

To manage notifications about this bug go to:
https://bugs.launchpad.net/nova/+bug/1645464/+subscriptions
References

[Bug 1645464] [NEW] InstanceNotFound stacktrace in _process_instance_vif_deleted_event
From: Matt Riedemann, 2016-11-28