OpenStack Compute (nova)

Unit tests fail with MessagingTimeout errors

Bug #1311778 reported by Mohammed Naser on 2014-04-23

This bug affects 5 people

Affects		Status	Importance	Assigned to	Milestone
	OpenStack Compute (nova)	Fix Released	Critical	Christopher Lefelhocz	OpenStack Compute (nova) 2014.2 "juno"
	Icehouse	Fix Released	Critical	Matt Riedemann	OpenStack Compute (nova) 2014.1.2

Bug Description

There is an issue that is causing unit tests to fail with the following error:

MessagingTimeout: No reply on topic conductor
MessagingTimeout: No reply on topic scheduler

2014-04-23 13:45:52.017 | Traceback (most recent call last):
2014-04-23 13:45:52.017 | 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-04-23 13:45:52.017 | incoming.message))
2014-04-23 13:45:52.017 | File "/home/jenkins/workspace/gate-nova-python26/.tox/py26/lib/python2.6/site-packages/oslo/messaging/rpc/dispatcher.py", line 176, in _dispatch
2014-04-23 13:45:52.017 | return self._do_dispatch(endpoint, method, ctxt, args)
2014-04-23 13:45:52.017 | 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-04-23 13:45:52.017 | result = getattr(endpoint, method)(ctxt, **new_args)
2014-04-23 13:45:52.018 | File "nova/conductor/manager.py", line 798, in build_instances
2014-04-23 13:45:52.018 | legacy_bdm_in_spec=legacy_bdm)
2014-04-23 13:51:50.628 | File "nlibvir: error : internal error could not initialize domain event timer
2014-04-23 13:54:57.953 | ova/scheduler/rpcapi.py", line 120, in run_instance
2014-04-23 13:54:57.953 | cctxt.cast(ctxt, 'run_instance', **msg_kwargs)
2014-04-23 13:54:57.953 | File "/home/jenkins/workspace/gate-nova-python26/.tox/py26/lib/python2.6/site-packages/oslo/messaging/rpc/client.py", line 150, in call
2014-04-23 13:54:57.953 | wait_for_reply=True, timeout=timeout)
2014-04-23 13:54:57.953 | File "/home/jenkins/workspace/gate-nova-python26/.tox/py26/lib/python2.6/site-packages/oslo/messaging/transport.py", line 90, in _send
2014-04-23 13:54:57.953 | timeout=timeout)
2014-04-23 13:54:57.954 | 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-04-23 13:54:57.954 | return self._send(target, ctxt, message, wait_for_reply, timeout)
2014-04-23 13:54:57.954 | 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-04-23 13:54:57.954 | 'No reply on topic %s' % target.topic)
2014-04-23 13:54:57.954 | MessagingTimeout: No reply on topic scheduler

============================

2014-04-23 13:45:52.008 | Traceback (most recent call last):
2014-04-23 13:45:52.008 | File "nova/api/openstack/__init__.py", line 125, in __call__
2014-04-23 13:45:52.008 | return req.get_response(self.application)
2014-04-23 13:45:52.009 | File "/home/jenkins/workspace/gate-nova-python26/.tox/py26/lib/python2.6/site-packages/webob/request.py", line 1320, in send
2014-04-23 13:45:52.009 | application, catch_exc_info=False)
2014-04-23 13:45:52.009 | File "/home/jenkins/workspace/gate-nova-python26/.tox/py26/lib/python2.6/site-packages/webob/request.py", line 1284, in call_application
2014-04-23 13:45:52.009 | app_iter = application(self.environ, start_response)
2014-04-23 13:45:52.009 | File "/home/jenkins/workspace/gate-nova-python26/.tox/py26/lib/python2.6/site-packages/webob/dec.py", line 144, in __call__
2014-04-23 13:45:52.009 | return resp(environ, start_response)
2014-04-23 13:45:52.009 | File "/home/jenkins/workspace/gate-nova-python26/.tox/py26/lib/python2.6/site-packages/webob/dec.py", line 144, in __call__
2014-04-23 13:45:52.010 | return resp(environ, start_response)
2014-04-23 13:45:52.010 | File "/home/jenkins/workspace/gate-nova-python26/.tox/py26/lib/python2.6/site-packages/webob/dec.py", line 144, in __call__
2014-04-23 13:45:52.010 | return resp(environ, start_response)
2014-04-23 13:45:52.010 | File "/home/jenkins/workspace/gate-nova-python26/.tox/py26/lib/python2.6/site-packages/webob/dec.py", line 144, in __call__
2014-04-23 13:45:52.010 | return resp(environ, start_response)
2014-04-23 13:45:52.010 | File "/home/jenkins/workspace/gate-nova-python26/.tox/py26/lib/python2.6/site-packages/routes/middleware.py", line 131, in __call__
2014-04-23 13:45:52.010 | response = self.app(environ, start_response)
2014-04-23 13:45:52.011 | File "/home/jenkins/workspace/gate-nova-python26/.tox/py26/lib/python2.6/site-packages/webob/dec.py", line 144, in __call__
2014-04-23 13:45:52.011 | return resp(environ, start_response)
2014-04-23 13:45:52.011 | File "/home/jenkins/workspace/gate-nova-python26/.tox/py26/lib/python2.6/site-packages/webob/dec.py", line 130, in __call__
2014-04-23 13:45:52.011 | resp = self.call_func(req, *args, **self.kwargs)
2014-04-23 13:45:52.011 | File "/home/jenkins/workspace/gate-nova-python26/.tox/py26/lib/python2.6/site-packages/webob/dec.py", line 195, in call_func
2014-04-23 13:45:52.011 | return self.func(req, *args, **kwargs)
2014-04-23 13:45:52.012 | File "nova/api/openstack/wsgi.py", line 917, in __call__
2014-04-23 13:45:52.012 | content_type, body, accept)
2014-04-23 13:45:52.012 | File "nova/api/openstack/wsgi.py", line 983, in _process_stack
2014-04-23 13:45:52.012 | action_result = self.dispatch(meth, request, action_args)
2014-04-23 13:45:52.012 | File "nova/api/openstack/wsgi.py", line 1070, in dispatch
2014-04-23 13:45:52.012 | return method(req=request, **action_args)
2014-04-23 13:45:52.012 | File "nova/api/openstack/compute/servers.py", line 956, in create
2014-04-23 13:45:52.012 | legacy_bdm=legacy_bdm)
2014-04-23 13:45:52.013 | File "nova/tests/fake_network.py", line 473, in fake_create
2014-04-23 13:45:52.013 | return _create_instances_with_cached_ips(orig_create, *args, **kwargs)
2014-04-23 13:45:52.013 | File "nova/tests/fake_network.py", line 543, in _create_instances_with_cached_ips
2014-04-23 13:45:52.013 | instances, reservation_id = orig_func(*args, **kwargs)
2014-04-23 13:45:52.013 | File "nova/hooks.py", line 103, in inner
2014-04-23 13:45:52.013 | rv = f(*args, **kwargs)
2014-04-23 13:45:52.013 | File "nova/compute/api.py", line 1341, in create
2014-04-23 13:45:52.014 | legacy_bdm=legacy_bdm)
2014-04-23 13:45:52.014 | File "nova/compute/api.py", line 1007, in _create_instance
2014-04-23 13:45:52.014 | legacy_bdm=False)
2014-04-23 13:45:52.014 | File "nova/conductor/api.py", line 371, in build_instances
2014-04-23 13:45:52.014 | legacy_bdm=legacy_bdm)
2014-04-23 13:45:52.014 | File "nova/conductor/rpcapi.py", line 455, in build_instances
2014-04-23 13:45:52.015 | legacy_bdm=legacy_bdm)
2014-04-23 13:45:52.015 | File "/home/jenkins/workspace/gate-nova-python26/.tox/py26/lib/python2.6/site-packages/oslo/messaging/rpc/client.py", line 150, in call
2014-04-23 13:45:52.015 | wait_for_reply=True, timeout=timeout)
2014-04-23 13:45:52.015 | File "/home/jenkins/workspace/gate-nova-python26/.tox/py26/lib/python2.6/site-packages/oslo/messaging/transport.py", line 90, in _send
2014-04-23 13:45:52.015 | timeout=timeout)
2014-04-23 13:45:52.015 | 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-04-23 13:45:52.015 | return self._send(target, ctxt, message, wait_for_reply, timeout)
2014-04-23 13:45:52.016 | 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-04-23 13:45:52.016 | 'No reply on topic %s' % target.topic)
2014-04-23 13:45:52.016 | MessagingTimeout: No reply on topic conductor

Tags:

Matt Riedemann (mriedem) on 2014-04-23

tags:

added: testing

Revision history for this message

Matt Riedemann (mriedem) wrote on 2014-04-23:

e-r query: https://review.openstack.org/#/c/89891/

Revision history for this message

Lance Bragstad (lbragstad) wrote on 2014-05-20:

Elastic recheck query:

http://logstash.openstack.org/#eyJzZWFyY2giOiJtZXNzYWdlOlwiTWVzc2FnaW5nVGltZW91dDogTm8gcmVwbHkgb24gdG9waWNcIiBBTkQgdGFnczpjb25zb2xlIEFORCAoYnVpbGRfbmFtZTpcImdhdGUtbm92YS1weXRob24yN1wiIE9SIGJ1aWxkX25hbWU6XCJnYXRlLW5vdmEtcHl0aG9uMjZcIikiLCJmaWVsZHMiOltdLCJvZmZzZXQiOjAsInRpbWVmcmFtZSI6IjYwNDgwMCIsImdyYXBobW9kZSI6ImNvdW50IiwidGltZSI6eyJ1c2VyX2ludGVydmFsIjowfSwic3RhbXAiOjEzOTgyNzEwMTI3MzZ9

Hit this on my local env

Revision history for this message

Matt Riedemann (mriedem) wrote on 2014-05-20:

I've hit this intermittently locally and I think it just comes down to how fast the system is that's running tox, I think the messaging timeout in the unit tests is 30 seconds, so on a slow VM we can hit this - sometimes I hit it and then run it later and it's fine.

Also need to make sure that *.pyc files are all deleted before running tox, which would be the case when Jenkins runs this, but need to remember to do that locally.

This can also be an indication of a real bug in the code/tests but it's masked by that big failure, so it's kind of hard to debug.

Sean Dague (sdague) on 2014-06-05

Changed in nova:
importance:	Undecided → Critical

Revision history for this message

Tracy Jones (tjones-i) wrote on 2014-06-18:

which exact tests are failing or is it just random intermittent bugs??

tags:

added: libvirt

Tracy Jones (tjones-i) on 2014-06-18

Changed in nova:
status:	New → Incomplete

Revision history for this message

Joe Gordon (jogo) wrote on 2014-06-24:

http://logs.openstack.org/05/95105/16/gate/gate-nova-python26/ef47993/console.html#_2014-06-24_12_50_13_228

nova.tests.compute.test_compute.ComputeTestCase.test_reboot_fail_running

http://logs.openstack.org/20/100120/4/gate/gate-nova-python27/4dbc13d/console.html

nova.tests.compute.test_compute.ComputeTestCase.test_reboot_fail_running

http://logs.openstack.org/55/93755/10/gate/gate-nova-python26/fa73be4/console.html.gz

nova.tests.compute.test_compute.ComputeTestCase.test_reboot_fail_running

So it looks like nova.tests.compute.test_compute.ComputeTestCase.test_reboot_fail_running is the test that is failing.

Changed in nova:
status:	Incomplete → Confirmed

Revision history for this message

Joe Gordon (jogo) wrote on 2014-06-24:

Looks like this issue has been around for some time now, but is very rare

Matt Riedemann (mriedem) on 2014-06-25

Changed in nova:
importance:	Critical → High

Revision history for this message

Matt Riedemann (mriedem) wrote on 2014-06-25:

test_reboot_fail_running failed here too:

http://logs.openstack.org/19/97619/6/check/gate-nova-python27/ae239e1/console.html

Going back 2 weeks in logstash, that test started failing more often around 6/17.

I looked at what merged around that time in the compute manager and there is nothing jumping out at me.

Revision history for this message

Matt Riedemann (mriedem) wrote on 2014-06-25:

https://review.openstack.org/#/c/102653/

Changed in nova:
status:	Confirmed → In Progress
assignee:	nobody → Christopher Lefelhocz (christopher-lefelhoc)

Matt Riedemann (mriedem) on 2014-06-26

tags:

added: icehouse-backport-potential

Revision history for this message

OpenStack Infra (hudson-openstack) wrote on 2014-06-26: Fix merged to nova (master)

Reviewed: https://review.openstack.org/102653
Committed: https://git.openstack.org/cgit/openstack/nova/commit/?id=dead965a4398d5093426cf21d2875b55a451e671
Submitter: Jenkins
Branch: master

commit dead965a4398d5093426cf21d2875b55a451e671
Author: Christopher Lefelhocz <email address hidden>
Date: Wed Jun 25 16:35:59 2014 -0500

Use default rpc_response_timeout in unit tests

    During running of tox the system can timeout on slower systems.
    We have seen this occur in our internal tests and have seen
    better results when we increased the api timeout from 15 to 60
    seconds. This can be used until faster hardware is availale
    or a better fix is proposed. Andrew Laski first proposed
    this fix.

Closes-Bug: 1311778

Change-Id: I33da328e7bea8fbdde3f01ee0147b4c5a3a278d2

Changed in nova:
status:	In Progress → Fix Committed

Revision history for this message

OpenStack Infra (hudson-openstack) wrote on 2014-06-26: Fix proposed to nova (stable/icehouse)

#10

Fix proposed to branch: stable/icehouse
Review: https://review.openstack.org/102865

Revision history for this message

OpenStack Infra (hudson-openstack) wrote on 2014-07-07: Fix merged to nova (stable/icehouse)

#11

Reviewed: https://review.openstack.org/102865
Committed: https://git.openstack.org/cgit/openstack/nova/commit/?id=f864329e342684efb28269ddbf98aa6bc179875e
Submitter: Jenkins
Branch: stable/icehouse

commit f864329e342684efb28269ddbf98aa6bc179875e
Author: Christopher Lefelhocz <email address hidden>
Date: Wed Jun 25 16:35:59 2014 -0500

Use default rpc_response_timeout in unit tests

Closes-Bug: 1311778

Change-Id: I33da328e7bea8fbdde3f01ee0147b4c5a3a278d2
(cherry picked from commit dead965a4398d5093426cf21d2875b55a451e671)

tags:

added: in-stable-icehouse

Revision history for this message

Joe Gordon (jogo) wrote on 2014-07-21:

#12

This bug is still happening, moving back to open

Changed in nova:
status:	Fix Committed → Confirmed
importance:	High → Critical
assignee:	Christopher Lefelhocz (christopher-lefelhoc) → nobody

Revision history for this message

Christopher Lefelhocz (christopher-lefelhoc) wrote on 2014-07-22:

#13

Download full text (35.6 KiB)

Most recent traceback is...

2014-07-21 16:17:52.528 | ${PYTHON:-python} -m subunit.run discover -t ./ ./nova/tests  --load-list /tmp/tmp.RvKIckAzcM/tmpPcO317
2014-07-21 16:17:52.529 | running=OS_STDOUT_CAPTURE=${OS_STDOUT_CAPTURE:-1} \
2014-07-21 16:17:52.529 | OS_STDERR_CAPTURE=${OS_STDERR_CAPTURE:-1} \
2014-07-21 16:17:52.529 | OS_TEST_TIMEOUT=${OS_TEST_TIMEOUT:-160} \
2014-07-21 16:17:52.529 | ${PYTHON:-python} -m subunit.run discover -t ./ ./nova/tests  --load-list /tmp/tmp.RvKIckAzcM/tmpUtxqlY
2014-07-21 16:17:52.529 | ======================================================================
2014-07-21 16:17:52.529 | FAIL: nova.tests.compute.test_shelve.ShelveComputeManagerTestCase.test_shelve_offload
2014-07-21 16:17:52.529 | tags: worker-1
2014-07-21 16:17:52.529 | ----------------------------------------------------------------------
2014-07-21 16:17:52.529 | Empty attachments:
2014-07-21 16:17:52.530 |   stdout
2014-07-21 16:17:52.530 | 
2014-07-21 16:17:52.530 | pythonlogging:'': {{{
2014-07-21 16:17:52.530 | INFO [nova.virt.driver] Loading compute driver 'nova.virt.fake.FakeDriver'
2014-07-21 16:17:52.530 | AUDIT [nova.compute.resource_tracker] Auditing locally available compute resources
2014-07-21 16:17:52.530 | AUDIT [nova.compute.resource_tracker] Free ram (MB): 7680
2014-07-21 16:17:52.530 | AUDIT [nova.compute.resource_tracker] Free disk (GB): 1028
2014-07-21 16:17:52.530 | AUDIT [nova.compute.resource_tracker] Free VCPUS: 1
2014-07-21 16:17:52.530 | AUDIT [nova.compute.resource_tracker] PCI stats: []
2014-07-21 16:17:52.531 | INFO [nova.compute.resource_tracker] Compute_service record created for fake-mini:fakenode1
2014-07-21 16:17:52.531 | AUDIT [nova.compute.manager] Deleting orphan compute node 2
2014-07-21 16:17:52.531 | AUDIT [nova.compute.manager] Starting instance...
2014-07-21 16:17:52.531 | WARNING [nova.compute.resource_tracker] Host field should not be set on the instance until resources have been claimed.
2014-07-21 16:17:52.531 | WARNING [nova.compute.resource_tracker] Node field should not be set on the instance until resources have been claimed.
2014-07-21 16:17:52.531 | AUDIT [nova.compute.claims] Attempting claim: memory 0 MB, disk 0 GB, VCPUs 0
2014-07-21 16:17:52.531 | AUDIT [nova.compute.claims] Total memory: 8192 MB, used: 512.00 MB
2014-07-21 16:17:52.531 | AUDIT [nova.compute.claims] memory limit not specified, defaulting to unlimited
2014-07-21 16:17:52.532 | AUDIT [nova.compute.claims] Total disk: 1028 GB, used: 0.00 GB
2014-07-21 16:17:52.532 | AUDIT [nova.compute.claims] disk limit not specified, defaulting to unlimited
2014-07-21 16:17:52.532 | AUDIT [nova.compute.claims] Total CPUs: 1 VCPUs, used: 0.00 VCPUs
2014-07-21 16:17:52.532 | AUDIT [nova.compute.claims] CPUs limit not specified, defaulting to unlimited
2014-07-21 16:17:52.532 | AUDIT [nova.compute.claims] Claim successful
2014-07-21 16:17:52.532 | ERROR [nova.scheduler.driver] Exception during scheduler.run_instance
2014-07-21 16:17:52.532 | Traceback (most recent call last):
2014-07-21 16:17:52.532 |   File "nova/conductor/manager.py", line 606, in build_instances
2014-07-21 16:17:52.532 |     request_spec, filter_properties)
2014-07-21 16:17:52.533 |   File "nova/scheduler/rpcapi.py", line 107, in select_destinations
2014-07-21 16:17:52.533 |     request_spec=request_spec, filter_properties=filter_properties)
2014-07-21 16:17:52.533 |   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-21 16:17:52.533 |     wait_for_reply=True, timeout=timeout)
2014-07-21 16:17:52.533 |   File "/home/jenkins/workspace/gate-nova-python26/.tox/py26/lib/python2.6/site-packages/oslo/messaging/transport.py", line 90, in _send
2014-07-21 16:17:52.533 |     timeout=timeout)
2014-07-21 16:17:52.533 |   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-21 16:17:52.533 |     return self._send(target, ctxt, message, wait_for_reply, timeout)
2014-07-21 16:17:52.533 |   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-21 16:17:52.534 |     'No reply on topic %s' % target.topic)
2014-07-21 16:17:52.534 | MessagingTimeout: No reply on topic scheduler
2014-07-21 16:17:52.534 | WARNING [nova.scheduler.driver] Setting instance to ERROR state.
2014-07-21 16:17:52.534 | INFO [nova.network.driver] Loading network driver 'nova.network.linux_net'
2014-07-21 16:17:52.534 | ERROR [nova.scheduler.driver] Exception during scheduler.run_instance
2014-07-21 16:17:52.534 | Traceback (most recent call last):
2014-07-21 16:17:52.534 |   File "nova/conductor/manager.py", line 606, in build_instances
2014-07-21 16:17:52.534 |     request_spec, filter_properties)
2014-07-21 16:17:52.534 |   File "nova/scheduler/rpcapi.py", line 107, in select_destinations
2014-07-21 16:17:52.535 |     request_spec=request_spec, filter_properties=filter_properties)
2014-07-21 16:17:52.535 |   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-21 16:17:52.535 |     wait_for_reply=True, timeout=timeout)
2014-07-21 16:17:52.535 |   File "/home/jenkins/workspace/gate-nova-python26/.tox/py26/lib/python2.6/site-packages/oslo/messaging/transport.py", line 90, in _send
2014-07-21 16:17:52.535 |     timeout=timeout)
2014-07-21 16:17:52.535 |   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-21 16:17:52.535 |     return self._send(target, ctxt, message, wait_for_reply, timeout)
2014-07-21 16:17:52.535 |   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-21 16:17:52.535 |     'No reply on topic %s' % target.topic)
2014-07-21 16:17:52.536 | MessagingTimeout: No reply on topic scheduler
2014-07-21 16:17:52.536 | WARNING [nova.scheduler.driver] Setting instance to ERROR state.
2014-07-21 16:17:52.536 | }}}
2014-07-21 16:17:52.536 | 
2014-07-21 16:17:52.536 | stderr: {{{
2014-07-21 16:17:52.536 | Traceback (most recent call last):
2014-07-21 16:17:52.536 |   File "/home/jenkins/workspace/gate-nova-python26/.tox/py26/lib/python2.6/site-packages/eventlet/hubs/hub.py", line 346, in fire_timers
2014-07-21 16:17:52.536 |     timer()
2014-07-21 16:17:52.536 |   File "/home/jenkins/workspace/gate-nova-python26/.tox/py26/lib/python2.6/site-packages/eventlet/hubs/timer.py", line 58, in __call__
2014-07-21 16:17:52.537 |     cb(*args, **kw)
2014-07-21 16:17:52.537 |   File "nova/utils.py", line 949, in wrapper
2014-07-21 16:17:52.537 |     return func(*args, **kwargs)
2014-07-21 16:17:52.537 |   File "nova/conductor/manager.py", line 610, in build_instances
2014-07-21 16:17:52.537 |     instance.uuid, request_spec)
2014-07-21 16:17:52.537 |   File "nova/scheduler/driver.py", line 63, in handle_schedule_error
2014-07-21 16:17:52.537 |     'task_state': None})
2014-07-21 16:17:52.537 |   File "nova/db/api.py", line 780, in instance_update_and_get_original
2014-07-21 16:17:52.537 |     columns_to_join=columns_to_join)
2014-07-21 16:17:52.538 |   File "nova/db/sqlalchemy/api.py", line 164, in wrapper
2014-07-21 16:17:52.538 |     return f(*args, **kwargs)
2014-07-21 16:17:52.538 |   File "nova/db/sqlalchemy/api.py", line 2235, in instance_update_and_get_original
2014-07-21 16:17:52.538 |     columns_to_join=columns_to_join)
2014-07-21 16:17:52.538 |   File "nova/db/sqlalchemy/api.py", line 2273, in _instance_update
2014-07-21 16:17:52.538 |     columns_to_join=columns_to_join)
2014-07-21 16:17:52.538 |   File "nova/db/sqlalchemy/api.py", line 1723, in _instance_get_by_uuid
2014-07-21 16:17:52.538 |     raise exception.InstanceNotFound(instance_id=uuid)
2014-07-21 16:17:52.538 | InstanceNotFound: Instance 75ec35ac-f21d-40a1-8fcd-bad659c595b7 could not be found.
2014-07-21 16:17:52.539 | Traceback (most recent call last):
2014-07-21 16:17:52.539 |   File "/home/jenkins/workspace/gate-nova-python26/.tox/py26/lib/python2.6/site-packages/eventlet/hubs/hub.py", line 346, in fire_timers
2014-07-21 16:17:52.539 |     timer()
2014-07-21 16:17:52.539 |   File "/home/jenkins/workspace/gate-nova-python26/.tox/py26/lib/python2.6/site-packages/eventlet/hubs/timer.py", line 58, in __call__
2014-07-21 16:17:52.539 |     cb(*args, **kw)
2014-07-21 16:17:52.539 |   File "nova/utils.py", line 949, in wrapper
2014-07-21 16:17:52.539 |     return func(*args, **kwargs)
2014-07-21 16:17:52.539 |   File "nova/conductor/manager.py", line 610, in build_instances
2014-07-21 16:17:52.539 |     instance.uuid, request_spec)
2014-07-21 16:17:52.540 |   File "nova/scheduler/driver.py", line 63, in handle_schedule_error
2014-07-21 16:17:52.540 |     'task_state': None})
2014-07-21 16:17:52.556 |   File "/home/jenkins/workspace/gate-nova-python26/.tox/py26/lib/python2.6/site-packages/mox.py", line 765, in __call__
2014-07-21 16:17:52.556 |     return mock_method(*params, **named_params)
2014-07-21 16:17:52.556 |   File "/home/jenkins/workspace/gate-nova-python26/.tox/py26/lib/python2.6/site-packages/mox.py", line 1002, in __call__
2014-07-21 16:17:52.556 |     expected_method = self._VerifyMethodCall()
2014-07-21 16:17:52.556 |   File "/home/jenkins/workspace/gate-nova-python26/.tox/py26/lib/python2.6/site-packages/mox.py", line 1060, in _VerifyMethodCall
2014-07-21 16:17:52.556 |     raise UnexpectedMethodCallError(self, expected)
2014-07-21 16:17:52.556 | UnexpectedMethodCallError: Unexpected method call.  unexpected:-  expected:+
2014-07-21 16:17:52.556 | - instance_update_and_get_original.__call__(<nova.context.RequestContext object at 0x8ffa810>, '2e3a18ac-8d55-4884-b84c-fdd2472c6b0d', {'vm_state': 'error', 'task_state': None}) -> None
2014-07-21 16:17:52.609 | + instance_update_and_get_original.__call__(<nova.context.RequestContext object at 0xbb79dd0>, '5b76c1af-2fa5-4707-9242-957c5e9ca029', {'vm_state': 'shelved', 'system_metadata': {u'instance_type_memory_mb': u'512', u'instance_type_swap': u'0', u'instance_type_vcpu_weight': None, u'instance_type_root_gb': u'1', u'instance_type_id': u'2', u'instance_type_name': u'm1.tiny', u'instance_type_ephemeral_gb': u'0', u'instance_type_rxtx_factor': u'1.0', 'shelved_at': '2014-07-21T16:17:49.765399', 'shelved_host': 'fake-mini', u'instance_type_flavorid': u'1', u'instance_type_vcpus': u'1', 'shelved_image_id': 'fake_image_id'}, 'task_state': 'shelving_offloading', 'expected_task_state': ['shelving', 'shelving_image_uploading'], 'power_state': 123}, columns_to_join=['metadata', 'system_metadata'], update_cells=False) -> ({'vm_state': 'active', 'internal_id': None, 'availability_zone': None, 'terminated_at': None, 'ephemeral_gb': 0, 'instance_type_id': 2, 'user_data': None, 'cleaned': 0, 'vm_mode': None, 'deleted_at': None, 'reservation_id': 'r-fakeres', 'id': 1, 'security_groups': [], 'disable_terminate': False, 'user_id': 'fake', 'uuid': '5b76c1af-2fa5-4707-9242-957c5e9ca029', 'default_swap_device': None, 'info_cache': {'instance_uuid': '5b76c1af-2fa5-4707-9242-957c5e9ca029', 'deleted': 0, 'created_at': '2014-07-21T16:17:49.034579', 'updated_at': None, 'instance': {'vm_state': 'active', 'internal_id': None, 'availability_zone': None, 'terminated_at': None, 'ephemeral_gb': 0, 'instance_type_id': 2, 'user_data': None, 'cleaned': 0, 'vm_mode': None, 'deleted_at': None, 'reservation_id': 'r-fakeres', 'id': 1, 'security_groups': [], 'disable_terminate': False, 'user_id': 'fake', 'uuid': '5b76c1af-2fa5-4707-9242-957c5e9ca029', 'default_swap_device': None, 'info_cache': '?', 'hostname': None, 'launched_on': None, 'display_description': None, 'key_data': None, 'kernel_id': None, 'power_state': None, 'default_ephemeral_device': None, 'progress': None, 'project_id': 'fake', 'launched_at': '2014-07-21T16:17:49.020912', 'config_drive': None, 'node': 'fakenode1', 'ramdisk_id': None, 'access_ip_v6': None, 'access_ip_v4': None, 'deleted': 0, 'key_name': None, 'updated_at': '2014-07-21T16:17:49.020911', 'host': 'fake_host', 'ephemeral_key_uuid': None, 'architecture': 'x86_64', 'display_name': None, 'system_metadata': ['?', '?', '?', '?', '?', '?', '?', '?', '?', '?'], 'task_state': None, 'shutdown_terminate': False, 'cell_name': None, 'root_gb': 0, 'locked': False, 'name': 'instance-00000001', 'ami_launch_index': 0, 'created_at': '2014-07-21T16:17:49.020902', 'locked_by': None, 'launch_index': None, 'metadata': [], 'memory_mb': 0, 'vcpus': 0, 'image_ref': 'fake-image-ref', 'root_device_name': None, 'auto_disk_config': None, 'os_type': 'Linux', 'scheduled_at': None}, 'network_info': None, 'deleted_at': None, 'id': 1}, 'hostname': None, 'launched_on': None, 'display_description': None, 'key_data': None, 'kernel_id': None, 'power_state': None, 'default_ephemeral_device': None, 'progress': None, 'project_id': 'fake', 'launched_at': '2014-07-21T16:17:49.020912', 'config_drive': None, 'node': 'fakenode1', 'ramdisk_id': None, 'access_ip_v6': None, 'access_ip_v4': None, 'deleted': 0, 'key_name': None, 'updated_at': '2014-07-21T16:17:49.020911', 'host': 'fake_host', 'ephemeral_key_uuid': None, 'architecture': 'x86_64', 'display_name': None, 'system_metadata': [{'value': u'512', 'key': u'instance_type_memory_mb'}, {'value': u'0', 'key': u'instance_type_swap'}, {'value': None, 'key': u'instance_type_vcpu_weight'}, {'value': u'1', 'key': u'instance_type_root_gb'}, {'value': u'2', 'key': u'instance_type_id'}, {'value': u'm1.tiny', 'key': u'instance_type_name'}, {'value': u'0', 'key': u'instance_type_ephemeral_gb'}, {'value': u'1.0', 'key': u'instance_type_rxtx_factor'}, {'value': '2014-07-21T16:17:49.765399', 'key': 'shelved_at'}, {'value': 'fake-mini', 'key': 'shelved_host'}, {'value': u'1', 'key': u'instance_type_flavorid'}, {'value': u'1', 'key': u'instance_type_vcpus'}, {'value': 'fake_image_id', 'key': 'shelved_image_id'}], 'task_state': None, 'shutdown_terminate': False, 'cell_name': None, 'root_gb': 0, 'locked': False, 'name': 'instance-00000001', 'ami_launch_index': 0, 'created_at': '2014-07-21T16:17:49.020902', 'locked_by': None, 'launch_index': None, 'metadata': [], 'memory_mb': 0, 'vcpus': 0, 'image_ref': 'fake-image-ref', 'root_device_name': None, 'auto_disk_config': None, 'os_type': 'Linux', 'scheduled_at': None}, {'vm_state': 'active', 'internal_id': None, 'availability_zone': None, 'terminated_at': None, 'ephemeral_gb': 0, 'instance_type_id': 2, 'user_data': None, 'cleaned': 0, 'vm_mode': None, 'deleted_at': None, 'reservation_id': 'r-fakeres', 'id': 1, 'security_groups': [], 'disable_terminate': False, 'user_id': 'fake', 'uuid': '5b76c1af-2fa5-4707-9242-957c5e9ca029', 'default_swap_device': None, 'info_cache': {'instance_uuid': '5b76c1af-2fa5-4707-9242-957c5e9ca029', 'deleted': 0, 'created_at': '2014-07-21T16:17:49.034579', 'updated_at': None, 'instance': {'vm_state': 'active', 'internal_id': None, 'availability_zone': None, 'terminated_at': None, 'ephemeral_gb': 0, 'instance_type_id': 2, 'user_data': None, 'cleaned': 0, 'vm_mode': None, 'deleted_at': None, 'reservation_id': 'r-fakeres', 'id': 1, 'security_groups': [], 'disable_terminate': False, 'user_id': 'fake', 'uuid': '5b76c1af-2fa5-4707-9242-957c5e9ca029', 'default_swap_device': None, 'info_cache': '?', 'hostname': None, 'launched_on': None, 'display_description': None, 'key_data': None, 'kernel_id': None, 'power_state': None, 'default_ephemeral_device': None, 'progress': None, 'project_id': 'fake', 'launched_at': '2014-07-21T16:17:49.020912', 'config_drive': None, 'node': 'fakenode1', 'ramdisk_id': None, 'access_ip_v6': None, 'access_ip_v4': None, 'deleted': 0, 'key_name': None, 'updated_at': '2014-07-21T16:17:49.020911', 'host': 'fake_host', 'ephemeral_key_uuid': None, 'architecture': 'x86_64', 'display_name': None, 'system_metadata': ['?', '?', '?', '?', '?', '?', '?', '?', '?', '?'], 'task_state': None, 'shutdown_terminate': False, 'cell_name': None, 'root_gb': 0, 'locked': False, 'name': 'instance-00000001', 'ami_launch_index': 0, 'created_at': '2014-07-21T16:17:49.020902', 'locked_by': None, 'launch_index': None, 'metadata': [], 'memory_mb': 0, 'vcpus': 0, 'image_ref': 'fake-image-ref', 'root_device_name': None, 'auto_disk_config': None, 'os_type': 'Linux', 'scheduled_at': None}, 'network_info': None, 'deleted_at': None, 'id': 1}, 'hostname': None, 'launched_on': None, 'display_description': None, 'key_data': None, 'kernel_id': None, 'power_state': None, 'default_ephemeral_device': None, 'progress': None, 'project_id': 'fake', 'launched_at': '2014-07-21T16:17:49.020912', 'config_drive': None, 'node': 'fakenode1', 'ramdisk_id': None, 'access_ip_v6': None, 'access_ip_v4': None, 'deleted': 0, 'key_name': None, 'updated_at': '2014-07-21T16:17:49.020911', 'host': 'fake_host', 'ephemeral_key_uuid': None, 'architecture': 'x86_64', 'display_name': None, 'system_metadata': [{'value': u'512', 'key': u'instance_type_memory_mb'}, {'value': u'0', 'key': u'instance_type_swap'}, {'value': None, 'key': u'instance_type_vcpu_weight'}, {'value': u'1', 'key': u'instance_type_root_gb'}, {'value': u'2', 'key': u'instance_type_id'}, {'value': u'm1.tiny', 'key': u'instance_type_name'}, {'value': u'0', 'key': u'instance_type_ephemeral_gb'}, {'value': u'1.0', 'key': u'instance_type_rxtx_factor'}, {'value': '2014-07-21T16:17:49.765399', 'key': 'shelved_at'}, {'value': 'fake-mini', 'key': 'shelved_host'}, {'value': u'1', 'key': u'instance_type_flavorid'}, {'value': u'1', 'key': u'instance_type_vcpus'}, {'value': 'fake_image_id', 'key': 'shelved_image_id'}], 'task_state': None, 'shutdown_terminate': False, 'cell_name': None, 'root_gb': 0, 'locked': False, 'name': 'instance-00000001', 'ami_launch_index': 0, 'created_at': '2014-07-21T16:17:49.020902', 'locked_by': None, 'launch_index': None, 'metadata': [], 'memory_mb': 0, 'vcpus': 0, 'image_ref': 'fake-image-ref', 'root_device_name': None, 'auto_disk_config': None, 'os_type': 'Linux', 'scheduled_at': None})
2014-07-21 16:17:52.609 | }}}
2014-07-21 16:17:52.609 | 
2014-07-21 16:17:52.609 | traceback-1: {{{
2014-07-21 16:17:52.609 | Traceback (most recent call last):
2014-07-21 16:17:52.609 |   File "/home/jenkins/workspace/gate-nova-python26/.tox/py26/lib/python2.6/site-packages/fixtures/fixture.py", line 112, in cleanUp
2014-07-21 16:17:52.610 |     return self._cleanups(raise_errors=raise_first)
2014-07-21 16:17:52.610 |   File "/home/jenkins/workspace/gate-nova-python26/.tox/py26/lib/python2.6/site-packages/fixtures/callmany.py", line 88, in __call__
2014-07-21 16:17:52.610 |     reraise(error[0], error[1], error[2])
2014-07-21 16:17:52.610 |   File "/home/jenkins/workspace/gate-nova-python26/.tox/py26/lib/python2.6/site-packages/fixtures/callmany.py", line 82, in __call__
2014-07-21 16:17:52.610 |     cleanup(*args, **kwargs)
2014-07-21 16:17:52.610 |   File "/home/jenkins/workspace/gate-nova-python26/.tox/py26/lib/python2.6/site-packages/mox.py", line 286, in VerifyAll
2014-07-21 16:17:52.610 |     mock_obj._Verify()
2014-07-21 16:17:52.610 |   File "/home/jenkins/workspace/gate-nova-python26/.tox/py26/lib/python2.6/site-packages/mox.py", line 506, in _Verify
2014-07-21 16:17:52.610 |     raise ExpectedMethodCallsError(self._expected_calls_queue)
2014-07-21 16:17:52.610 | ExpectedMethodCallsError: Verify: Expected methods never called:
2014-07-21 16:17:52.610 |   0.  _notify_about_instance_usage.__call__(<nova.context.RequestContext object at 0xbb79dd0>, Instance(access_ip_v4=None,access_ip_v6=None,architecture='x86_64',auto_disk_config=False,availability_zone=None,cell_name=None,cleaned=False,config_drive=None,created_at=2014-07-21T16:17:49Z,default_ephemeral_device=None,default_swap_device=None,deleted=False,deleted_at=None,disable_terminate=False,display_description=None,display_name=None,ephemeral_gb=0,ephemeral_key_uuid=None,fault=<?>,host='fake-mini',hostname=None,id=1,image_ref='fake-image-ref',info_cache=<?>,instance_type_id=2,kernel_id=None,key_data=None,key_name=None,launch_index=None,launched_at=2014-07-21T16:17:49Z,launched_on='fake-mini',locked=False,locked_by=None,memory_mb=0,metadata={},node='fakenode1',os_type='Linux',pci_devices=<?>,power_state=123,progress=None,project_id='fake',ramdisk_id=None,reservation_id='r-fakeres',root_device_name=None,root_gb=0,scheduled_at=None,security_groups=<?>,shutdown_terminate=False,system_metadata={instance_type_ephemeral_gb='0',instance_type_flavorid='1',instance_type_id='2',instance_type_memory_mb='512',instance_type_name='m1.tiny',instance_type_root_gb='1',instance_type_rxtx_factor='1.0',instance_type_swap='0',instance_type_vcpu_weight=None,instance_type_vcpus='1',shelved_at='2014-07-21T16:17:49.765399',shelved_host='fake-mini',shelved_image_id='fake_image_id'},task_state='shelving_offloading',terminated_at=None,updated_at=2014-07-21T16:17:49Z,user_data=None,user_id='fake',uuid=5b76c1af-2fa5-4707-9242-957c5e9ca029,vcpus=0,vm_mode=None,vm_state='shelved'), 'shelve.end') -> None
2014-07-21 16:17:52.611 |   1.  _notify_about_instance_usage.__call__(<nova.context.RequestContext object at 0xbb79dd0>, Instance(access_ip_v4=None,access_ip_v6=None,architecture='x86_64',auto_disk_config=False,availability_zone=None,cell_name=None,cleaned=False,config_drive=None,created_at=2014-07-21T16:17:49Z,default_ephemeral_device=None,default_swap_device=None,deleted=False,deleted_at=None,disable_terminate=False,display_description=None,display_name=None,ephemeral_gb=0,ephemeral_key_uuid=None,fault=<?>,host='fake-mini',hostname=None,id=1,image_ref='fake-image-ref',info_cache=<?>,instance_type_id=2,kernel_id=None,key_data=None,key_name=None,launch_index=None,launched_at=2014-07-21T16:17:49Z,launched_on='fake-mini',locked=False,locked_by=None,memory_mb=0,metadata={},node='fakenode1',os_type='Linux',pci_devices=<?>,power_state=123,progress=None,project_id='fake',ramdisk_id=None,reservation_id='r-fakeres',root_device_name=None,root_gb=0,scheduled_at=None,security_groups=<?>,shutdown_terminate=False,system_metadata={instance_type_ephemeral_gb='0',instance_type_flavorid='1',instance_type_id='2',instance_type_memory_mb='512',instance_type_name='m1.tiny',instance_type_root_gb='1',instance_type_rxtx_factor='1.0',instance_type_swap='0',instance_type_vcpu_weight=None,instance_type_vcpus='1',shelved_at='2014-07-21T16:17:49.765399',shelved_host='fake-mini',shelved_image_id='fake_image_id'},task_state='shelving_offloading',terminated_at=None,updated_at=2014-07-21T16:17:49Z,user_data=None,user_id='fake',uuid=5b76c1af-2fa5-4707-9242-957c5e9ca029,vcpus=0,vm_mode=None,vm_state='shelved'), 'shelve_offload.start') -> None
2014-07-21 16:17:52.611 |   2.  _notify_about_instance_usage.__call__(<nova.context.RequestContext object at 0xbb79dd0>, Instance(access_ip_v4=None,access_ip_v6=None,architecture='x86_64',auto_disk_config=False,availability_zone=None,cell_name=None,cleaned=False,config_drive=None,created_at=2014-07-21T16:17:49Z,default_ephemeral_device=None,default_swap_device=None,deleted=False,deleted_at=None,disable_terminate=False,display_description=None,display_name=None,ephemeral_gb=0,ephemeral_key_uuid=None,fault=<?>,host='fake-mini',hostname=None,id=1,image_ref='fake-image-ref',info_cache=<?>,instance_type_id=2,kernel_id=None,key_data=None,key_name=None,launch_index=None,launched_at=2014-07-21T16:17:49Z,launched_on='fake-mini',locked=False,locked_by=None,memory_mb=0,metadata={},node='fakenode1',os_type='Linux',pci_devices=<?>,power_state=123,progress=None,project_id='fake',ramdisk_id=None,reservation_id='r-fakeres',root_device_name=None,root_gb=0,scheduled_at=None,security_groups=<?>,shutdown_terminate=False,system_metadata={instance_type_ephemeral_gb='0',instance_type_flavorid='1',instance_type_id='2',instance_type_memory_mb='512',instance_type_name='m1.tiny',instance_type_root_gb='1',instance_type_rxtx_factor='1.0',instance_type_swap='0',instance_type_vcpu_weight=None,instance_type_vcpus='1',shelved_at='2014-07-21T16:17:49.765399',shelved_host='fake-mini',shelved_image_id='fake_image_id'},task_state='shelving_offloading',terminated_at=None,updated_at=2014-07-21T16:17:49Z,user_data=None,user_id='fake',uuid=5b76c1af-2fa5-4707-9242-957c5e9ca029,vcpus=0,vm_mode=None,vm_state='shelved'), 'shelve_offload.end') -> None
2014-07-21 16:17:52.611 | }}}
2014-07-21 16:17:52.611 | 
2014-07-21 16:17:52.611 | Traceback (most recent call last):
2014-07-21 16:17:52.611 |   File "nova/tests/compute/test_shelve.py", line 124, in test_shelve_offload
2014-07-21 16:17:52.611 |     self._shelve_instance(0)
2014-07-21 16:17:52.611 |   File "nova/tests/compute/test_shelve.py", line 118, in _shelve_instance
2014-07-21 16:17:52.611 |     image_id=image_id)
2014-07-21 16:17:52.611 |   File "nova/exception.py", line 88, in wrapped
2014-07-21 16:17:52.612 |     payload)
2014-07-21 16:17:52.612 |   File "nova/openstack/common/excutils.py", line 82, in __exit__
2014-07-21 16:17:52.612 |     six.reraise(self.type_, self.value, self.tb)
2014-07-21 16:17:52.612 |   File "nova/exception.py", line 71, in wrapped
2014-07-21 16:17:52.612 |     return f(self, context, *args, **kw)
2014-07-21 16:17:52.612 |   File "nova/compute/manager.py", line 291, in decorated_function
2014-07-21 16:17:52.612 |     pass
2014-07-21 16:17:52.612 |   File "nova/openstack/common/excutils.py", line 82, in __exit__
2014-07-21 16:17:52.612 |     six.reraise(self.type_, self.value, self.tb)
2014-07-21 16:17:52.612 |   File "nova/compute/manager.py", line 277, in decorated_function
2014-07-21 16:17:52.612 |     return function(self, context, *args, **kwargs)
2014-07-21 16:17:52.612 |   File "nova/compute/manager.py", line 341, in decorated_function
2014-07-21 16:17:52.613 |     return function(self, context, *args, **kwargs)
2014-07-21 16:17:52.613 |   File "nova/compute/manager.py", line 319, in decorated_function
2014-07-21 16:17:52.613 |     kwargs['instance'], e, sys.exc_info())
2014-07-21 16:17:52.613 |   File "nova/openstack/common/excutils.py", line 82, in __exit__
2014-07-21 16:17:52.613 |     six.reraise(self.type_, self.value, self.tb)
2014-07-21 16:17:52.613 |   File "nova/compute/manager.py", line 307, in decorated_function
2014-07-21 16:17:52.613 |     return function(self, context, *args, **kwargs)
2014-07-21 16:17:52.613 |   File "nova/compute/manager.py", line 3924, in shelve_instance
2014-07-21 16:17:52.613 |     task_states.SHELVING_IMAGE_UPLOADING])
2014-07-21 16:17:52.613 |   File "nova/objects/base.py", line 196, in wrapper
2014-07-21 16:17:52.613 |     return fn(self, ctxt, *args, **kwargs)
2014-07-21 16:17:52.614 |   File "nova/objects/instance.py", line 469, in save
2014-07-21 16:17:52.614 |     columns_to_join=_expected_cols(expected_attrs))
2014-07-21 16:17:52.614 |   File "/home/jenkins/workspace/gate-nova-python26/.tox/py26/lib/python2.6/site-packages/mox.py", line 765, in __call__
2014-07-21 16:17:52.614 |     return mock_method(*params, **named_params)
2014-07-21 16:17:52.614 |   File "/home/jenkins/workspace/gate-nova-python26/.tox/py26/lib/python2.6/site-packages/mox.py", line 1002, in __call__
2014-07-21 16:17:52.614 |     expected_method = self._VerifyMethodCall()
2014-07-21 16:17:52.614 |   File "/home/jenkins/workspace/gate-nova-python26/.tox/py26/lib/python2.6/site-packages/mox.py", line 1060, in _VerifyMethodCall
2014-07-21 16:17:52.614 |     raise UnexpectedMethodCallError(self, expected)
2014-07-21 16:17:52.614 | UnexpectedMethodCallError: Unexpected method call.  unexpected:-  expected:+
2014-07-21 16:17:52.615 | - instance_update_and_get_original.__call__(<nova.context.RequestContext object at 0xbb79dd0>, '5b76c1af-2fa5-4707-9242-957c5e9ca029', {'vm_state': u'shelved', 'system_metadata': {u'instance_type_memory_mb': u'512', u'instance_type_swap': u'0', u'instance_type_vcpu_weight': None, u'instance_type_root_gb': u'1', u'instance_type_name': u'm1.tiny', u'instance_type_id': u'2', u'instance_type_ephemeral_gb': u'0', u'instance_type_rxtx_factor': u'1.0', 'shelved_at': '2014-07-21T16:17:49.765399', 'shelved_host': 'fake-mini', u'instance_type_flavorid': u'1', u'instance_type_vcpus': u'1', 'shelved_image_id': 'fake_image_id'}, 'task_state': u'shelving_offloading', 'expected_task_state': ['shelving', 'shelving_image_uploading'], 'power_state': 123}, columns_to_join=['metadata', 'system_metadata'], update_cells=False) -> None
2014-07-21 16:26:39.029 | + instance_update_and_get_original.__call__(<nova.context.RequestContext object at 0xbb79dd0>, '5b76c1af-2fa5-4707-9242-957c5e9ca029', {'node': None, 'vm_state': 'shelved_offloaded', 'expected_task_state': ['shelving', 'shelving_offloading'], 'host': None, 'power_state': 123, 'task_state': None}, columns_to_join=['metadata', 'system_metadata'], update_cells=False) -> ({'vm_state': 'active', 'internal_id': None, 'availability_zone': None, 'terminated_at': None, 'ephemeral_gb': 0, 'instance_type_id': 2, 'user_data': None, 'cleaned': 0, 'vm_mode': None, 'deleted_at': None, 'reservation_id': 'r-fakeres', 'id': 1, 'security_groups': [], 'disable_terminate': False, 'user_id': 'fake', 'uuid': '5b76c1af-2fa5-4707-9242-957c5e9ca029', 'default_swap_device': None, 'info_cache': {'instance_uuid': '5b76c1af-2fa5-4707-9242-957c5e9ca029', 'deleted': 0, 'created_at': '2014-07-21T16:17:49.034579', 'updated_at': None, 'instance': {'vm_state': 'active', 'internal_id': None, 'availability_zone': None, 'terminated_at': None, 'ephemeral_gb': 0, 'instance_type_id': 2, 'user_data': None, 'cleaned': 0, 'vm_mode': None, 'deleted_at': None, 'reservation_id': 'r-fakeres', 'id': 1, 'security_groups': [], 'disable_terminate': False, 'user_id': 'fake', 'uuid': '5b76c1af-2fa5-4707-9242-957c5e9ca029', 'default_swap_device': None, 'info_cache': '?', 'hostname': None, 'launched_on': None, 'display_description': None, 'key_data': None, 'kernel_id': None, 'power_state': None, 'default_ephemeral_device': None, 'progress': None, 'project_id': 'fake', 'launched_at': '2014-07-21T16:17:49.020912', 'config_drive': None, 'node': 'fakenode1', 'ramdisk_id': None, 'access_ip_v6': None, 'access_ip_v4': None, 'deleted': 0, 'key_name': None, 'updated_at': '2014-07-21T16:17:49.020911', 'host': 'fake_host', 'ephemeral_key_uuid': None, 'architecture': 'x86_64', 'display_name': None, 'system_metadata': ['?', '?', '?', '?', '?', '?', '?', '?', '?', '?'], 'task_state': None, 'shutdown_terminate': False, 'cell_name': None, 'root_gb': 0, 'locked': False, 'name': 'instance-00000001', 'ami_launch_index': 0, 'created_at': '2014-07-21T16:17:49.020902', 'locked_by': None, 'launch_index': None, 'metadata': [], 'memory_mb': 0, 'vcpus': 0, 'image_ref': 'fake-image-ref', 'root_device_name': None, 'auto_disk_config': None, 'os_type': 'Linux', 'scheduled_at': None}, 'network_info': None, 'deleted_at': None, 'id': 1}, 'hostname': None, 'launched_on': None, 'display_description': None, 'key_data': None, 'kernel_id': None, 'power_state': None, 'default_ephemeral_device': None, 'progress': None, 'project_id': 'fake', 'launched_at': '2014-07-21T16:17:49.020912', 'config_drive': None, 'node': 'fakenode1', 'ramdisk_id': None, 'access_ip_v6': None, 'access_ip_v4': None, 'deleted': 0, 'key_name': None, 'updated_at': '2014-07-21T16:17:49.020911', 'host': 'fake_host', 'ephemeral_key_uuid': None, 'architecture': 'x86_64', 'display_name': None, 'system_metadata': [{'value': u'512', 'key': u'instance_type_memory_mb'}, {'value': u'0', 'key': u'instance_type_swap'}, {'value': None, 'key': u'instance_type_vcpu_weight'}, {'value': u'1', 'key': u'instance_type_root_gb'}, {'value': u'2', 'key': u'instance_type_id'}, {'value': u'm1.tiny', 'key': u'instance_type_name'}, {'value': u'0', 'key': u'instance_type_ephemeral_gb'}, {'value': u'1.0', 'key': u'instance_type_rxtx_factor'}, {'value': '2014-07-21T16:17:49.765399', 'key': 'shelved_at'}, {'value': 'fake-mini', 'key': 'shelved_host'}, {'value': u'1', 'key': u'instance_type_flavorid'}, {'value': u'1', 'key': u'instance_type_vcpus'}, {'value': 'fake_image_id', 'key': 'shelved_image_id'}], 'task_state': None, 'shutdown_terminate': False, 'cell_name': None, 'root_gb': 0, 'locked': False, 'name': 'instance-00000001', 'ami_launch_index': 0, 'created_at': '2014-07-21T16:17:49.020902', 'locked_by': None, 'launch_index': None, 'metadata': [], 'memory_mb': 0, 'vcpus': 0, 'image_ref': 'fake-image-ref', 'root_device_name': None, 'auto_disk_config': None, 'os_type': 'Linux', 'scheduled_at': None}, {'vm_state': 'active', 'internal_id': None, 'availability_zone': None, 'terminated_at': None, 'ephemeral_gb': 0, 'instance_type_id': 2, 'user_data': None, 'cleaned': 0, 'vm_mode': None, 'deleted_at': None, 'reservation_id': 'r-fakeres', 'id': 1, 'security_groups': [], 'disable_terminate': False, 'user_id': 'fake', 'uuid': '5b76c1af-2fa5-4707-9242-957c5e9ca029', 'default_swap_device': None, 'info_cache': {'instance_uuid': '5b76c1af-2fa5-4707-9242-957c5e9ca029', 'deleted': 0, 'created_at': '2014-07-21T16:17:49.034579', 'updated_at': None, 'instance': {'vm_state': 'active', 'internal_id': None, 'availability_zone': None, 'terminated_at': None, 'ephemeral_gb': 0, 'instance_type_id': 2, 'user_data': None, 'cleaned': 0, 'vm_mode': None, 'deleted_at': None, 'reservation_id': 'r-fakeres', 'id': 1, 'security_groups': [], 'disable_terminate': False, 'user_id': 'fake', 'uuid': '5b76c1af-2fa5-4707-9242-957c5e9ca029', 'default_swap_device': None, 'info_cache': '?', 'hostname': None, 'launched_on': None, 'display_description': None, 'key_data': None, 'kernel_id': None, 'power_state': None, 'default_ephemeral_device': None, 'progress': None, 'project_id': 'fake', 'launched_at': '2014-07-21T16:17:49.020912', 'config_drive': None, 'node': 'fakenode1', 'ramdisk_id': None, 'access_ip_v6': None, 'access_ip_v4': None, 'deleted': 0, 'key_name': None, 'updated_at': '2014-07-21T16:17:49.020911', 'host': 'fake_host', 'ephemeral_key_uuid': None, 'architecture': 'x86_64', 'display_name': None, 'system_metadata': ['?', '?', '?', '?', '?', '?', '?', '?', '?', '?'], 'task_state': None, 'shutdown_terminate': False, 'cell_name': None, 'root_gb': 0, 'locked': False, 'name': 'instance-00000001', 'ami_launch_index': 0, 'created_at': '2014-07-21T16:17:49.020902', 'locked_by': None, 'launch_index': None, 'metadata': [], 'memory_mb': 0, 'vcpus': 0, 'image_ref': 'fake-image-ref', 'root_device_name': None, 'auto_disk_config': None, 'os_type': 'Linux', 'scheduled_at': None}, 'network_info': None, 'deleted_at': None, 'id': 1}, 'hostname': None, 'launched_on': None, 'display_description': None, 'key_data': None, 'kernel_id': None, 'power_state': None, 'default_ephemeral_device': None, 'progress': None, 'project_id': 'fake', 'launched_at': '2014-07-21T16:17:49.020912', 'config_drive': None, 'node': 'fakenode1', 'ramdisk_id': None, 'access_ip_v6': None, 'access_ip_v4': None, 'deleted': 0, 'key_name': None, 'updated_at': '2014-07-21T16:17:49.020911', 'host': 'fake_host', 'ephemeral_key_uuid': None, 'architecture': 'x86_64', 'display_name': None, 'system_metadata': [{'value': u'512', 'key': u'instance_type_memory_mb'}, {'value': u'0', 'key': u'instance_type_swap'}, {'value': None, 'key': u'instance_type_vcpu_weight'}, {'value': u'1', 'key': u'instance_type_root_gb'}, {'value': u'2', 'key': u'instance_type_id'}, {'value': u'm1.tiny', 'key': u'instance_type_name'}, {'value': u'0', 'key': u'instance_type_ephemeral_gb'}, {'value': u'1.0', 'key': u'instance_type_rxtx_factor'}, {'value': '2014-07-21T16:17:49.765399', 'key': 'shelved_at'}, {'value': 'fake-mini', 'key': 'shelved_host'}, {'value': u'1', 'key': u'instance_type_flavorid'}, {'value': u'1', 'key': u'instance_type_vcpus'}, {'value': 'fake_image_id', 'key': 'shelved_image_id'}], 'task_state': None, 'shutdown_terminate': False, 'cell_name': None, 'root_gb': 0, 'locked': False, 'name': 'instance-00000001', 'ami_launch_index': 0, 'created_at': '2014-07-21T16:17:49.020902', 'locked_by': None, 'launch_index': None, 'metadata': [], 'memory_mb': 0, 'vcpus': 0, 'image_ref': 'fake-image-ref', 'root_device_name': None, 'auto_disk_config': None, 'os_type': 'Linux', 'scheduled_at': None})
2014-07-21 16:26:39.030 | ======================================================================
2014-07-21 16:26:39.030 | FAIL: process-returncode
2014-07-21 16:26:39.030 | tags: worker-1
2014-07-21 16:26:39.030 | ----------------------------------------------------------------------

Changed in nova:
assignee:	nobody → Christopher Lefelhocz (christopher-lefelhoc)

Revision history for this message

Christopher Lefelhocz (christopher-lefelhoc) wrote on 2014-07-22:

#14

This bug is going to be a bit like whack-a-mole. As we moved to conductor and separate process that we are simulating in unit tests, we'll see failures when the test apparatus slows down or hangs. In this particular case, we don't even need to run instance to simulate the shelving tests. We'll remove these calls since they don't affect the test cases.

Revision history for this message

OpenStack Infra (hudson-openstack) wrote on 2014-07-22: Fix proposed to nova (master)

#15

Fix proposed to branch: master
Review: https://review.openstack.org/108546

Changed in nova:
status:	Confirmed → In Progress

Revision history for this message

Joe Gordon (jogo) wrote on 2014-07-22:

#16

the exception is coming from oslo.messaging: http://git.openstack.org/cgit/openstack/oslo.messaging/tree/oslo/messaging/_drivers/impl_fake.py#n184

Revision history for this message

Joe Gordon (jogo) wrote on 2014-07-22:

#17

looks like this may be a few different bugs, and the MessagingTimeout is a bit of a red herring.

Revision history for this message

Joe Gordon (jogo) wrote on 2014-07-22:

#18

http://logs.openstack.org/65/59365/47/gate/gate-nova-python26/61651a5/console.html#_2014-07-22_07_25_40_979

http://logs.openstack.org/04/106704/2/gate/gate-nova-python26/7d61729/console.html#_2014-07-22_06_59_03_196

Revision history for this message

OpenStack Infra (hudson-openstack) wrote on 2014-07-22: Related fix proposed to nova (master)

#19

Related fix proposed to branch: master
Review: https://review.openstack.org/108833

Revision history for this message

OpenStack Infra (hudson-openstack) wrote on 2014-07-22: Fix merged to nova (master)

#20

Reviewed: https://review.openstack.org/108546
Committed: https://git.openstack.org/cgit/openstack/nova/commit/?id=1fb727876fff2f796de6442730527556c16a347e
Submitter: Jenkins
Branch: master

commit 1fb727876fff2f796de6442730527556c16a347e
Author: Christopher Lefelhocz <email address hidden>
Date: Mon Jul 21 20:06:39 2014 -0500

Remove unneeded calls in test_shelve to start instances

    During running of tox the system can timeout on slower systems. This
    is due to rpc calls to other threads failing in testing. This
    particular case involved shelving calls to start instances. However,
    when we started using objects, these calls became unnecessary for these
    unit tests. Thus we are removing the calls which should remove
    the traceback for slow systems.

Change-Id: I52f1e86815cc2cac8dc31865f00eef2d4ffeea59
Partial-Bug: 1311778

Revision history for this message

OpenStack Infra (hudson-openstack) wrote on 2014-07-22: Change abandoned on nova (master)

#21

Change abandoned by Joe Gordon (<email address hidden>) on branch: master
Review: https://review.openstack.org/108833
Reason: replaced by https://review.openstack.org/#/c/108837/

Revision history for this message

OpenStack Infra (hudson-openstack) wrote on 2014-07-24: Related fix merged to nova (master)

#22

Reviewed: https://review.openstack.org/108837
Committed: https://git.openstack.org/cgit/openstack/nova/commit/?id=f3f07f4401ff8be25598493c088e4e100b387fe4
Submitter: Jenkins
Branch: master

commit f3f07f4401ff8be25598493c088e4e100b387fe4
Author: Joe Gordon <email address hidden>
Date: Tue Jul 22 13:40:33 2014 -0700

Turn periodic tasks off in all unit tests

We shouldn't rely on periodic tasks to randomly run in unit tests,
instead if we need them to run we should explicitly call them out.

Change-Id: I35850c47288e50d3146771dc7a9a54d62e36c3cf
Related-Bug: 1311778

Revision history for this message

OpenStack Infra (hudson-openstack) wrote on 2014-07-24: Related fix proposed to nova (stable/icehouse)

#23

Related fix proposed to branch: stable/icehouse
Review: https://review.openstack.org/109411

Revision history for this message

Matt Riedemann (mriedem) wrote on 2014-07-25:

#24

Marking this as closed because the messaging timeout error is masking new, more specific, unit test failures, e.g.:

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

I've already put in a few fixes for the messaging timeout issue, so let's close this bug and open new ones for specific test failures.

Changed in nova:
status:	In Progress → Fix Committed
no longer affects:	oslo.messaging

Revision history for this message

Matt Riedemann (mriedem) wrote on 2014-07-25:

#25

I've opened a new bug for some new issues seen in unit test runs, bug 1348661.

Revision history for this message

Vish Ishaya (vishvananda) wrote on 2014-07-25:

#26

saw another run of the scheduler.run_instance. I believe it is a concurrent test run bug, where there is some test that is stubbing out scheduler_rpcapi in a way that is breaking the stubs set in the base compute test:

242 self.stubs.Set(self.compute, 'scheduler_rpcapi', fake_rpcapi)

Revision history for this message

OpenStack Infra (hudson-openstack) wrote on 2014-08-01: Related fix merged to nova (stable/icehouse)

#27

Reviewed: https://review.openstack.org/109411
Committed: https://git.openstack.org/cgit/openstack/nova/commit/?id=397de7bb7c45cf1367fccaf0847f3cee0f5f8660
Submitter: Jenkins
Branch: stable/icehouse

commit 397de7bb7c45cf1367fccaf0847f3cee0f5f8660
Author: Joe Gordon <email address hidden>
Date: Tue Jul 22 13:40:33 2014 -0700

Turn periodic tasks off in all unit tests

We shouldn't rely on periodic tasks to randomly run in unit tests,
instead if we need them to run we should explicitly call them out.

    Change-Id: I35850c47288e50d3146771dc7a9a54d62e36c3cf
    Related-Bug: 1311778
    (cherry picked from commit f3f07f4401ff8be25598493c088e4e100b387fe4)

Revision history for this message

Matt Riedemann (mriedem) wrote on 2014-08-06:

#28

Seeing more races in test_shelve here:

http://logs.openstack.org/77/77477/10/check/gate-nova-python26/67243b8/console.html#_2014-08-06_12_31_54_640

Revision history for this message

Christopher Lefelhocz (christopher-lefelhoc) wrote on 2014-08-07: Re: [Bug 1311778] Re: Unit tests fail with MessagingTimeout errors

#29

Download full text (8.4 KiB)

Thanks Matt, I'm on vacation off and on for the next two weeks. I'll try to take a look at some point when I'm free.

Christopher

Sent from my iPhone

> On Aug 6, 2014, at 12:36 PM, "Matt Riedemann" <email address hidden> wrote:
>
> Seeing more races in test_shelve here:
>
> http://logs.openstack.org/77/77477/10/check/gate-nova-
> python26/67243b8/console.html#_2014-08-06_12_31_54_640
>
> --
> You received this bug notification because you are a bug assignee.
> https://bugs.launchpad.net/bugs/1311778
>
> Title:
> Unit tests fail with MessagingTimeout errors
>
> Status in OpenStack Compute (Nova):
> Fix Committed
>
> Bug description:
> There is an issue that is causing unit tests to fail with the
> following error:
>
> MessagingTimeout: No reply on topic conductor
> MessagingTimeout: No reply on topic scheduler
>
> 2014-04-23 13:45:52.017 | Traceback (most recent call last):
> 2014-04-23 13:45:52.017 | 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-04-23 13:45:52.017 | incoming.message))
> 2014-04-23 13:45:52.017 | File "/home/jenkins/workspace/gate-nova-python26/.tox/py26/lib/python2.6/site-packages/oslo/messaging/rpc/dispatcher.py", line 176, in _dispatch
> 2014-04-23 13:45:52.017 | return self._do_dispatch(endpoint, method, ctxt, args)
> 2014-04-23 13:45:52.017 | 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-04-23 13:45:52.017 | result = getattr(endpoint, method)(ctxt, **new_args)
> 2014-04-23 13:45:52.018 | File "nova/conductor/manager.py", line 798, in build_instances
> 2014-04-23 13:45:52.018 | legacy_bdm_in_spec=legacy_bdm)
> 2014-04-23 13:51:50.628 | File "nlibvir: error : internal error could not initialize domain event timer
> 2014-04-23 13:54:57.953 | ova/scheduler/rpcapi.py", line 120, in run_instance
> 2014-04-23 13:54:57.953 | cctxt.cast(ctxt, 'run_instance', **msg_kwargs)
> 2014-04-23 13:54:57.953 | File "/home/jenkins/workspace/gate-nova-python26/.tox/py26/lib/python2.6/site-packages/oslo/messaging/rpc/client.py", line 150, in call
> 2014-04-23 13:54:57.953 | wait_for_reply=True, timeout=timeout)
> 2014-04-23 13:54:57.953 | File "/home/jenkins/workspace/gate-nova-python26/.tox/py26/lib/python2.6/site-packages/oslo/messaging/transport.py", line 90, in _send
> 2014-04-23 13:54:57.953 | timeout=timeout)
> 2014-04-23 13:54:57.954 | 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-04-23 13:54:57.954 | return self._send(target, ctxt, message, wait_for_reply, timeout)
> 2014-04-23 13:54:57.954 | 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-04-23 13:54:57.954 | 'No reply on topic %s' % target.topic)
> 2014-04-23 13:54:57.954 | MessagingTimeout: No reply on topic scheduler
>
> ============================
>
> 2014-04-2...

Duplicates of this bug

You are

Subscribing...

Edit bug mail

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.

Changed in nova:
milestone:	none → juno-3
status:	Fix Committed → Fix Released