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 -- Mailing list: https://launchpad.net/~yahoo-eng-team Post to : [email protected] Unsubscribe : https://launchpad.net/~yahoo-eng-team More help : https://help.launchpad.net/ListHelp
