yahoo-eng-team team mailing list archive

Thread
Date
[Bug 1645464] [NEW] InstanceNotFound stacktrace in _process_instance_vif_deleted_event

To: yahoo-eng-team@xxxxxxxxxxxxxxxxxxx
From: Matt Riedemann <mriedem@xxxxxxxxxx>
Date: Mon, 28 Nov 2016 20:28:04 -0000
Reply-to: Bug 1645464 <1645464@xxxxxxxxxxxxxxxxxx>
Sender: bounces@xxxxxxxxxxxxx
Public bug reported:

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.

** Affects: nova
     Importance: Medium
         Status: Triaged


** Tags: compute

-- 
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):
  Triaged

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

[Bug 1645464] Re: InstanceNotFound stacktrace in _process_instance_vif_deleted_event
From: OpenStack Infra, 2017-01-31
[Bug 1645464] Re: InstanceNotFound stacktrace in _process_instance_vif_deleted_event
From: Matt Riedemann, 2016-11-28