Volume failed to reach in-use status within the required time

[Attila Fazekas]

http://logs.openstack.org/59/99559/4/check/check-tempest-dsvm-postgres-full/be6a190/console.html.gz#_2014-06-13_21_20_11_328

The volume attache did not happen in normal time.
(The failed change is completely unrelated to this).

[Ray Chen (chenrano2002)]

in n-cpu.log, the instance '5a6fa678-23cf-4f17-bdb9-38d0219a6d21' is not live status, so fail to run virt_dom.attachDeviceFlags with libvirt.VIR_DOMAIN_AFFECT_LIVE

2014-06-13 20:56:26.904 ERROR nova.virt.block_device [req-0aa46d1c-5afe-47f2-95d9-c3ce940ed7cc DeleteServersTestJSON-1605815992 DeleteServersTestJSON-1498618205] [instance: 5a6fa678-23cf-4f17-bdb9-38d0219a6d21] Driver failed to attach volume 50d13d9e-4607-4703-9566-3be550a1614f at /dev/vdb
2014-06-13 20:56:26.904 31567 TRACE nova.virt.block_device [instance: 5a6fa678-23cf-4f17-bdb9-38d0219a6d21] Traceback (most recent call last):
2014-06-13 20:56:26.904 31567 TRACE nova.virt.block_device [instance: 5a6fa678-23cf-4f17-bdb9-38d0219a6d21] File "/opt/stack/new/nova/nova/virt/block_device.py", line 240, in attach
2014-06-13 20:56:26.904 31567 TRACE nova.virt.block_device [instance: 5a6fa678-23cf-4f17-bdb9-38d0219a6d21] device_type=self['device_type'], encryption=encryption)
2014-06-13 20:56:26.904 31567 TRACE nova.virt.block_device [instance: 5a6fa678-23cf-4f17-bdb9-38d0219a6d21] File "/opt/stack/new/nova/nova/virt/libvirt/driver.py", line 1256, in attach_volume
2014-06-13 20:56:26.904 31567 TRACE nova.virt.block_device [instance: 5a6fa678-23cf-4f17-bdb9-38d0219a6d21] disk_dev)
2014-06-13 20:56:26.904 31567 TRACE nova.virt.block_device [instance: 5a6fa678-23cf-4f17-bdb9-38d0219a6d21] File "/opt/stack/new/nova/nova/openstack/common/excutils.py", line 82, in __exit__
2014-06-13 20:56:26.904 31567 TRACE nova.virt.block_device [instance: 5a6fa678-23cf-4f17-bdb9-38d0219a6d21] six.reraise(self.type_, self.value, self.tb)
2014-06-13 20:56:26.904 31567 TRACE nova.virt.block_device [instance: 5a6fa678-23cf-4f17-bdb9-38d0219a6d21] File "/opt/stack/new/nova/nova/virt/libvirt/driver.py", line 1243, in attach_volume
2014-06-13 20:56:26.904 31567 TRACE nova.virt.block_device [instance: 5a6fa678-23cf-4f17-bdb9-38d0219a6d21] virt_dom.attachDeviceFlags(conf.to_xml(), flags)
2014-06-13 20:56:26.904 31567 TRACE nova.virt.block_device [instance: 5a6fa678-23cf-4f17-bdb9-38d0219a6d21] File "/usr/local/lib/python2.7/dist-packages/eventlet/tpool.py", line 179, in doit
2014-06-13 20:56:26.904 31567 TRACE nova.virt.block_device [instance: 5a6fa678-23cf-4f17-bdb9-38d0219a6d21] result = proxy_call(self._autowrap, f, *args, **kwargs)
2014-06-13 20:56:26.904 31567 TRACE nova.virt.block_device [instance: 5a6fa678-23cf-4f17-bdb9-38d0219a6d21] File "/usr/local/lib/python2.7/dist-packages/eventlet/tpool.py", line 139, in proxy_call
2014-06-13 20:56:26.904 31567 TRACE nova.virt.block_device [instance: 5a6fa678-23cf-4f17-bdb9-38d0219a6d21] rv = execute(f,*args,**kwargs)
2014-06-13 20:56:26.904 31567 TRACE nova.virt.block_device [instance: 5a6fa678-23cf-4f17-bdb9-38d0219a6d21] File "/usr/local/lib/python2.7/dist-packages/eventlet/tpool.py", line 77, in tworker
2014-06-13 20:56:26.904 31567 TRACE nova.virt.block_device [instance: 5a6fa678-23cf-4f17-bdb9-38d0219a6d21] rv = meth(*args,**kwargs)
2014-06-13 20:56:26.904 31567 TRACE nova.virt.block_device [instance: 5a6fa678-23cf-4f17-bdb9-38d0219a6d21] File "/usr/lib/python2.7/dist-packages/libvirt.py", line 420, in attachDeviceFla...

[Ray Chen (chenrano2002)]

temptest log show that the instance is going to attach volume at aroud 20:50.

2014-06-13 20:50:42,039 Request (DeleteServersTestJSON:test_delete_server_while_in_attached_volume): 200 POST http://127.0.0.1:8774/v2/941f2c9052fc496bb943b60c543ff33e/servers/5a6fa678-23cf-4f17-bdb9-38d0219a6d21/os-volume_attachments 0.430s

However, the volume status is always 'attaching', so temptest compain the timeout.

From nova log, the instance have been spawned and status is set to RUNNING. The API virt_dom.attachDeviceFlags should be work...

another hint from in libvirtd log:
2014-06-13 20:51:19.000+0000: 15921: error : qemuDomainObjBeginJobInternal:789 : Timed out during operation: cannot acquire state change lock

https://bugs.launchpad.net/nova/+bug/1254872

[Joe Gordon (jogo)]

Seeing a lot of hits for message:"cannot do live update a device on inactive domain" but most are for successful runs. So I don't think this stacktrace alone is enough

[Joe Gordon (jogo)]

marking bug as invalid because "Volume failed to reach in-use status within the required time" is too general