test_list_image_filters.py setUpClass created image never becomes active

[Matthew Treinish]

When running in parallel occassionally the tests in test_list_image_filters fail while waiting for one of the created images to become active. See the logs here:

http://logs.openstack.org/42/40342/2/gate/gate-tempest-devstack-vm-testr-full/dad876b/

From the tempest log:

2013-08-16 05:51:36.930 368 ERROR tempest.api.compute.images.test_list_image_filters [-] Request timed out
2013-08-16 05:51:36.930 368 TRACE tempest.api.compute.images.test_list_image_filters Traceback (most recent call last):
2013-08-16 05:51:36.930 368 TRACE tempest.api.compute.images.test_list_image_filters File "tempest/api/compute/images/test_list_image_filters.py", line 67, in setUpClass
2013-08-16 05:51:36.930 368 TRACE tempest.api.compute.images.test_list_image_filters cls.client.wait_for_image_status(cls.image2_id, 'ACTIVE')
2013-08-16 05:51:36.930 368 TRACE tempest.api.compute.images.test_list_image_filters File "tempest/services/compute/json/images_client.py", line 110, in wait_for_image_status
2013-08-16 05:51:36.930 368 TRACE tempest.api.compute.images.test_list_image_filters raise exceptions.TimeoutException
2013-08-16 05:51:36.930 368 TRACE tempest.api.compute.images.test_list_image_filters TimeoutException: Request timed out
2013-08-16 05:51:36.930 368 TRACE tempest.api.compute.images.test_list_image_filters

[Josh Durgin (jdurgin)]

A similar error occurred in this http://logs.openstack.org/79/46879/1/check/gate-tempest-devstack-vm-postgres-full/da6e518/console.html for tempest.api.compute.images.test_images_oneserver.ImagesOneServerTestJSON.test_create_second_image_when_first_image_is_being_saved[gate,negative]

[Ken'ichi Ohmichi (oomichi)]

"libvirtError: Timed out during operation: cannot acquire state change lock" happens when getting the second snapshot against the same server.

2013-08-16 05:45:28.738 21074 TRACE nova.openstack.common.rpc.amqp Traceback (most recent call last):
2013-08-16 05:45:28.738 21074 TRACE nova.openstack.common.rpc.amqp File "/opt/stack/new/nova/nova/openstack/common/rpc/amqp.py", line 421, in _process_data
2013-08-16 05:45:28.738 21074 TRACE nova.openstack.common.rpc.amqp **args)
2013-08-16 05:45:28.738 21074 TRACE nova.openstack.common.rpc.amqp File "/opt/stack/new/nova/nova/openstack/common/rpc/dispatcher.py", line 172, in dispatch
2013-08-16 05:45:28.738 21074 TRACE nova.openstack.common.rpc.amqp result = getattr(proxyobj, method)(ctxt, **kwargs)
2013-08-16 05:45:28.738 21074 TRACE nova.openstack.common.rpc.amqp File "/opt/stack/new/nova/nova/exception.py", line 100, in wrapped
2013-08-16 05:45:28.738 21074 TRACE nova.openstack.common.rpc.amqp temp_level, payload)
2013-08-16 05:45:28.738 21074 TRACE nova.openstack.common.rpc.amqp File "/opt/stack/new/nova/nova/exception.py", line 77, in wrapped
2013-08-16 05:45:28.738 21074 TRACE nova.openstack.common.rpc.amqp return f(self, context, *args, **kw)
2013-08-16 05:45:28.738 21074 TRACE nova.openstack.common.rpc.amqp File "/opt/stack/new/nova/nova/compute/manager.py", line 241, in decorated_function
2013-08-16 05:45:28.738 21074 TRACE nova.openstack.common.rpc.amqp pass
2013-08-16 05:45:28.738 21074 TRACE nova.openstack.common.rpc.amqp File "/opt/stack/new/nova/nova/compute/manager.py", line 227, in decorated_function
2013-08-16 05:45:28.738 21074 TRACE nova.openstack.common.rpc.amqp return function(self, context, *args, **kwargs)
2013-08-16 05:45:28.738 21074 TRACE nova.openstack.common.rpc.amqp File "/opt/stack/new/nova/nova/compute/manager.py", line 269, in decorated_function
2013-08-16 05:45:28.738 21074 TRACE nova.openstack.common.rpc.amqp e, sys.exc_info())
2013-08-16 05:45:28.738 21074 TRACE nova.openstack.common.rpc.amqp File "/opt/stack/new/nova/nova/compute/manager.py", line 256, in decorated_function
2013-08-16 05:45:28.738 21074 TRACE nova.openstack.common.rpc.amqp return function(self, context, *args, **kwargs)
2013-08-16 05:45:28.738 21074 TRACE nova.openstack.common.rpc.amqp File "/opt/stack/new/nova/nova/compute/manager.py", line 2157, in snapshot_instance
2013-08-16 05:45:28.738 21074 TRACE nova.openstack.common.rpc.amqp update_task_state)
2013-08-16 05:45:28.738 21074 TRACE nova.openstack.common.rpc.amqp File "/opt/stack/new/nova/nova/virt/libvirt/driver.py", line 1300, in snapshot
2013-08-16 05:45:28.738 21074 TRACE nova.openstack.common.rpc.amqp virt_dom.managedSave(0)
2013-08-16 05:45:28.738 21074 TRACE nova.openstack.common.rpc.amqp File "/usr/local/lib/python2.7/dist-packages/eventlet/tpool.py", line 179, in doit
2013-08-16 05:45:28.738 21074 TRACE nova.openstack.common.rpc.amqp result = proxy_call(self._autowrap, f, *args, **kwargs)
2013-08-16 05:45:28.738 21074 TRACE nova.openstack.common.rpc.amqp File "/usr/local/lib/python2.7/dist-packages/eventlet/tpool.py", line 139, in proxy_call
2013-08-16 05:45:28.738 21...

[Zhikun Liu (zhikunliu)]

this problem probably relate to https://bugs.launchpad.net/nova/+bug/1258635.
https://review.openstack.org/#/c/60604/ fixes bug 1258635.