yahoo-eng-team team mailing list archive

Thread
Date
[Bug 1348661] Re: nova.tests.api.ec2.test_cloud.CloudTestCase.test_terminate_instances_two_instances race fails with UnexpectedDeletingTaskStateError

To: yahoo-eng-team@xxxxxxxxxxxxxxxxxxx
From: Thierry Carrez <thierry.carrez+lp@xxxxxxxxx>
Date: Fri, 05 Sep 2014 09:49:17 -0000
Reply-to: Bug 1348661 <1348661@xxxxxxxxxxxxxxxxxx>
Sender: bounces@xxxxxxxxxxxxx
** Changed in: nova
       Status: Fix Committed => Fix Released

** Changed in: nova
    Milestone: None => juno-3

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

Title:
  nova.tests.api.ec2.test_cloud.CloudTestCase.test_terminate_instances_two_instances
  race fails with UnexpectedDeletingTaskStateError

Status in OpenStack Compute (Nova):
  Fix Released

Bug description:
  This was being masked by bug 1311778 due to the MessagingTimeout
  failure, but there are more specific errors.

  http://logs.openstack.org/79/108879/1/gate/gate-nova-
  python26/283e967/console.html#_2014-07-24_08_14_12_631

  2014-07-24 08:14:12.631 | FAIL: nova.tests.api.ec2.test_cloud.CloudTestCase.test_terminate_instances_two_instances
  2014-07-24 08:14:12.631 | tags: worker-4
  2014-07-24 08:14:12.631 | ----------------------------------------------------------------------
  2014-07-24 08:14:12.631 | Empty attachments:
  2014-07-24 08:14:12.631 |   pythonlogging:'boto'
  2014-07-24 08:14:12.631 |   stderr
  2014-07-24 08:14:12.631 |   stdout
  2014-07-24 08:14:12.631 | 
  2014-07-24 08:14:12.631 | pythonlogging:'': {{{
  2014-07-24 08:14:12.631 | INFO [nova.network.driver] Loading network driver 'nova.network.linux_net'
  2014-07-24 08:14:12.632 | AUDIT [nova.service] Starting conductor node (version 2014.2)
  2014-07-24 08:14:12.632 | INFO [nova.virt.driver] Loading compute driver 'nova.virt.fake.FakeDriver'
  2014-07-24 08:14:12.632 | AUDIT [nova.service] Starting compute node (version 2014.2)
  2014-07-24 08:14:12.632 | AUDIT [nova.compute.resource_tracker] Auditing locally available compute resources
  2014-07-24 08:14:12.632 | AUDIT [nova.compute.resource_tracker] Free ram (MB): 7680
  2014-07-24 08:14:12.632 | AUDIT [nova.compute.resource_tracker] Free disk (GB): 1028
  2014-07-24 08:14:12.632 | AUDIT [nova.compute.resource_tracker] Free VCPUS: 1
  2014-07-24 08:14:12.632 | AUDIT [nova.compute.resource_tracker] PCI stats: []
  2014-07-24 08:14:12.632 | INFO [nova.compute.resource_tracker] Compute_service record created for 093d0c3802bf440db8f3f839963027c4:fake-mini
  2014-07-24 08:14:12.632 | AUDIT [nova.service] Starting scheduler node (version 2014.2)
  2014-07-24 08:14:12.632 | INFO [nova.network.driver] Loading network driver 'nova.network.linux_net'
  2014-07-24 08:14:12.633 | AUDIT [nova.service] Starting network node (version 2014.2)
  2014-07-24 08:14:12.633 | AUDIT [nova.service] Starting consoleauth node (version 2014.2)
  2014-07-24 08:14:12.633 | AUDIT [nova.compute.manager] Starting instance...
  2014-07-24 08:14:12.633 | AUDIT [nova.compute.claims] Attempting claim: memory 2048 MB, disk 20 GB
  2014-07-24 08:14:12.633 | AUDIT [nova.compute.claims] Total memory: 8192 MB, used: 512.00 MB
  2014-07-24 08:14:12.633 | AUDIT [nova.compute.claims] memory limit not specified, defaulting to unlimited
  2014-07-24 08:14:12.633 | AUDIT [nova.compute.claims] Total disk: 1028 GB, used: 0.00 GB
  2014-07-24 08:14:12.633 | AUDIT [nova.compute.claims] disk limit not specified, defaulting to unlimited
  2014-07-24 08:14:12.633 | AUDIT [nova.compute.claims] Claim successful
  2014-07-24 08:14:12.633 | AUDIT [nova.compute.manager] Starting instance...
  2014-07-24 08:14:12.633 | AUDIT [nova.compute.claims] Attempting claim: memory 2048 MB, disk 20 GB
  2014-07-24 08:14:12.633 | AUDIT [nova.compute.claims] Total memory: 8192 MB, used: 2560.00 MB
  2014-07-24 08:14:12.634 | AUDIT [nova.compute.claims] memory limit not specified, defaulting to unlimited
  2014-07-24 08:14:12.634 | AUDIT [nova.compute.claims] Total disk: 1028 GB, used: 20.00 GB
  2014-07-24 08:14:12.634 | AUDIT [nova.compute.claims] disk limit not specified, defaulting to unlimited
  2014-07-24 08:14:12.634 | AUDIT [nova.compute.claims] Claim successful
  2014-07-24 08:14:12.634 | WARNING [nova.compute.manager] Instance is not stopped. Calling the stop API.
  2014-07-24 08:14:12.634 | ERROR [nova.compute.manager] error during stop() in sync_power_state.
  2014-07-24 08:14:12.634 | Traceback (most recent call last):
  2014-07-24 08:14:12.634 |   File "nova/compute/manager.py", line 5551, in _sync_instance_power_state
  2014-07-24 08:14:12.634 |     self.compute_api.force_stop(context, db_instance)
  2014-07-24 08:14:12.634 |   File "nova/compute/api.py", line 1767, in force_stop
  2014-07-24 08:14:12.634 |     self.compute_rpcapi.stop_instance(context, instance, do_cast=do_cast)
  2014-07-24 08:14:12.635 |   File "nova/compute/rpcapi.py", line 908, in stop_instance
  2014-07-24 08:14:12.635 |     return rpc_method(ctxt, 'stop_instance', instance=instance)
  2014-07-24 08:14:12.635 |   File "/home/jenkins/workspace/gate-nova-python26/.tox/py26/lib/python2.6/site-packages/oslo/messaging/rpc/client.py", line 150, in call
  2014-07-24 08:14:12.635 |     wait_for_reply=True, timeout=timeout)
  2014-07-24 08:14:12.635 |   File "/home/jenkins/workspace/gate-nova-python26/.tox/py26/lib/python2.6/site-packages/oslo/messaging/transport.py", line 90, in _send
  2014-07-24 08:14:12.635 |     timeout=timeout)
  2014-07-24 08:14:12.635 |   File "/home/jenkins/workspace/gate-nova-python26/.tox/py26/lib/python2.6/site-packages/oslo/messaging/_drivers/impl_fake.py", line 166, in send
  2014-07-24 08:14:12.635 |     return self._send(target, ctxt, message, wait_for_reply, timeout)
  2014-07-24 08:14:12.635 |   File "/home/jenkins/workspace/gate-nova-python26/.tox/py26/lib/python2.6/site-packages/oslo/messaging/_drivers/impl_fake.py", line 161, in _send
  2014-07-24 08:14:12.635 |     'No reply on topic %s' % target.topic)
  2014-07-24 08:14:12.635 | MessagingTimeout: No reply on topic compute
  2014-07-24 08:14:12.635 | AUDIT [nova.compute.manager] Terminating instance
  2014-07-24 08:14:12.636 | INFO [nova.compute.manager] Task possibly preempted: Unexpected task state: expecting ('powering-off',) but the actual state is deleting
  2014-07-24 08:14:12.636 | ERROR [oslo.messaging.rpc.dispatcher] Exception during message handling: Unexpected task state: expecting ('powering-off',) but the actual state is deleting
  2014-07-24 08:14:12.636 | Traceback (most recent call last):
  2014-07-24 08:14:12.636 |   File "/home/jenkins/workspace/gate-nova-python26/.tox/py26/lib/python2.6/site-packages/oslo/messaging/rpc/dispatcher.py", line 133, in _dispatch_and_reply
  2014-07-24 08:14:12.636 |     incoming.message))
  2014-07-24 08:14:12.636 |   File "/home/jenkins/workspace/gate-nova-python26/.tox/py26/lib/python2.6/site-packages/oslo/messaging/rpc/dispatcher.py", line 176, in _dispatch
  2014-07-24 08:14:12.636 |     return self._do_dispatch(endpoint, method, ctxt, args)
  2014-07-24 08:14:12.636 |   File "/home/jenkins/workspace/gate-nova-python26/.tox/py26/lib/python2.6/site-packages/oslo/messaging/rpc/dispatcher.py", line 122, in _do_dispatch
  2014-07-24 08:14:12.636 |     result = getattr(endpoint, method)(ctxt, **new_args)
  2014-07-24 08:14:12.636 |   File "nova/exception.py", line 88, in wrapped
  2014-07-24 08:14:12.636 |     payload)
  2014-07-24 08:14:12.636 |   File "nova/openstack/common/excutils.py", line 82, in __exit__
  2014-07-24 08:14:12.637 |     six.reraise(self.type_, self.value, self.tb)
  2014-07-24 08:14:12.637 |   File "nova/exception.py", line 71, in wrapped
  2014-07-24 08:14:12.637 |     return f(self, context, *args, **kw)
  2014-07-24 08:14:12.637 |   File "nova/compute/manager.py", line 283, in decorated_function
  2014-07-24 08:14:12.637 |     LOG.info(_("Task possibly preempted: %s") % e.format_message())
  2014-07-24 08:14:12.637 |   File "nova/openstack/common/excutils.py", line 82, in __exit__
  2014-07-24 08:14:12.637 |     six.reraise(self.type_, self.value, self.tb)
  2014-07-24 08:14:12.637 |   File "nova/compute/manager.py", line 277, in decorated_function
  2014-07-24 08:14:12.637 |     return function(self, context, *args, **kwargs)
  2014-07-24 08:14:12.637 |   File "nova/compute/manager.py", line 341, in decorated_function
  2014-07-24 08:14:12.637 |     return function(self, context, *args, **kwargs)
  2014-07-24 08:14:12.637 |   File "nova/compute/manager.py", line 319, in decorated_function
  2014-07-24 08:14:12.638 |     kwargs['instance'], e, sys.exc_info())
  2014-07-24 08:14:12.638 |   File "nova/openstack/common/excutils.py", line 82, in __exit__
  2014-07-24 08:14:12.638 |     six.reraise(self.type_, self.value, self.tb)
  2014-07-24 08:14:12.638 |   File "nova/compute/manager.py", line 307, in decorated_function
  2014-07-24 08:14:12.638 |     return function(self, context, *args, **kwargs)
  2014-07-24 08:14:12.638 |   File "nova/compute/manager.py", line 2388, in stop_instance
  2014-07-24 08:14:12.638 |     do_stop_instance()
  2014-07-24 08:14:12.638 |   File "nova/openstack/common/lockutils.py", line 325, in inner
  2014-07-24 08:14:12.638 |     return f(*args, **kwargs)
  2014-07-24 08:14:12.638 |   File "nova/compute/manager.py", line 2384, in do_stop_instance
  2014-07-24 08:14:12.638 |     instance.save(expected_task_state=task_states.POWERING_OFF)
  2014-07-24 08:14:12.638 |   File "nova/objects/base.py", line 196, in wrapper
  2014-07-24 08:14:12.639 |     return fn(self, ctxt, *args, **kwargs)
  2014-07-24 08:14:12.639 |   File "nova/objects/instance.py", line 469, in save
  2014-07-24 08:14:12.639 |     columns_to_join=_expected_cols(expected_attrs))
  2014-07-24 08:14:12.639 |   File "nova/db/api.py", line 780, in instance_update_and_get_original
  2014-07-24 08:14:12.639 |     columns_to_join=columns_to_join)
  2014-07-24 08:14:12.639 |   File "nova/db/sqlalchemy/api.py", line 167, in wrapper
  2014-07-24 08:14:12.639 |     return f(*args, **kwargs)
  2014-07-24 08:14:12.639 |   File "nova/db/sqlalchemy/api.py", line 2238, in instance_update_and_get_original
  2014-07-24 08:14:12.640 |     columns_to_join=columns_to_join)
  2014-07-24 08:14:12.640 |   File "nova/db/sqlalchemy/api.py", line 2286, in _instance_update
  2014-07-24 08:14:12.640 |     actual=actual_state, expected=expected)
  2014-07-24 08:14:12.640 | UnexpectedDeletingTaskStateError: Unexpected task state: expecting ('powering-off',) but the actual state is deleting

  And this:

  2014-07-24 08:14:12.643 | ERROR [oslo.messaging.rpc.dispatcher] Exception during message handling: Object action obj_load_attr failed because: attribute id not lazy-loadable
  2014-07-24 08:14:12.643 | Traceback (most recent call last):
  2014-07-24 08:14:12.643 |   File "/home/jenkins/workspace/gate-nova-python26/.tox/py26/lib/python2.6/site-packages/oslo/messaging/rpc/dispatcher.py", line 133, in _dispatch_and_reply
  2014-07-24 08:14:12.643 |     incoming.message))
  2014-07-24 08:14:12.643 |   File "/home/jenkins/workspace/gate-nova-python26/.tox/py26/lib/python2.6/site-packages/oslo/messaging/rpc/dispatcher.py", line 176, in _dispatch
  2014-07-24 08:14:12.643 |     return self._do_dispatch(endpoint, method, ctxt, args)
  2014-07-24 08:14:12.643 |   File "/home/jenkins/workspace/gate-nova-python26/.tox/py26/lib/python2.6/site-packages/oslo/messaging/rpc/dispatcher.py", line 122, in _do_dispatch
  2014-07-24 08:14:12.643 |     result = getattr(endpoint, method)(ctxt, **new_args)
  2014-07-24 08:14:12.644 |   File "nova/exception.py", line 88, in wrapped
  2014-07-24 08:14:12.644 |     payload)
  2014-07-24 08:14:12.644 |   File "/home/jenkins/workspace/gate-nova-python26/.tox/py26/lib/python2.6/site-packages/oslo/messaging/notify/notifier.py", line 232, in error
  2014-07-24 08:14:12.644 |     self._notify(ctxt, event_type, payload, 'ERROR')
  2014-07-24 08:14:12.644 |   File "/home/jenkins/workspace/gate-nova-python26/.tox/py26/lib/python2.6/site-packages/oslo/messaging/notify/notifier.py", line 278, in _notify
  2014-07-24 08:14:12.644 |     super(_SubNotifier, self)._notify(ctxt, event_type, payload, priority)
  2014-07-24 08:14:12.644 |   File "/home/jenkins/workspace/gate-nova-python26/.tox/py26/lib/python2.6/site-packages/oslo/messaging/notify/notifier.py", line 151, in _notify
  2014-07-24 08:14:12.644 |     payload = self._serializer.serialize_entity(ctxt, payload)
  2014-07-24 08:14:12.644 |   File "nova/rpc.py", line 106, in serialize_entity
  2014-07-24 08:14:12.644 |     return self._base.serialize_entity(context, entity)
  2014-07-24 08:14:12.644 |   File "nova/rpc.py", line 95, in serialize_entity
  2014-07-24 08:14:12.645 |     return jsonutils.to_primitive(entity, convert_instances=True)
  2014-07-24 08:14:12.645 |   File "nova/openstack/common/jsonutils.py", line 133, in to_primitive
  2014-07-24 08:14:12.645 |     return dict((k, recursive(v)) for k, v in six.iteritems(value))
  2014-07-24 08:14:12.645 |   File "nova/openstack/common/jsonutils.py", line 133, in <genexpr>
  2014-07-24 08:14:12.645 |     return dict((k, recursive(v)) for k, v in six.iteritems(value))
  2014-07-24 08:14:12.645 |   File "nova/openstack/common/jsonutils.py", line 133, in to_primitive
  2014-07-24 08:14:12.645 |     return dict((k, recursive(v)) for k, v in six.iteritems(value))
  2014-07-24 08:14:12.645 |   File "nova/openstack/common/jsonutils.py", line 133, in <genexpr>
  2014-07-24 08:14:12.645 |     return dict((k, recursive(v)) for k, v in six.iteritems(value))
  2014-07-24 08:14:12.645 |   File "nova/openstack/common/jsonutils.py", line 148, in to_primitive
  2014-07-24 08:14:12.645 |     return recursive(dict(value.iteritems()), level=level + 1)
  2014-07-24 08:14:12.646 |   File "nova/objects/base.py", line 438, in iteritems
  2014-07-24 08:14:12.646 |     yield name, getattr(self, name)
  2014-07-24 08:14:12.646 |   File "nova/objects/instance.py", line 229, in name
  2014-07-24 08:14:12.646 |     base_name = CONF.instance_name_template % self.id
  2014-07-24 08:14:12.646 |   File "nova/objects/base.py", line 67, in getter
  2014-07-24 08:14:12.646 |     self.obj_load_attr(name)
  2014-07-24 08:14:12.646 |   File "nova/objects/instance.py", line 507, in obj_load_attr
  2014-07-24 08:14:12.646 |     reason='attribute %s not lazy-loadable' % attrname)
  2014-07-24 08:14:12.646 | ObjectActionError: Object action obj_load_attr failed because: attribute id not lazy-loadable
  2014-07-24 08:14:12.646 | }}}

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

[Bug 1348661] [NEW] nova.tests.api.ec2.test_cloud.CloudTestCase.test_terminate_instances_two_instances race fails with UnexpectedDeletingTaskStateError
From: Matt Riedemann, 2014-07-25