Our CI hits the following issue in about 30% of it's runs, shown in the nova compute log:
2015-08-28 11:57:47.780 INFO nova.compute.manager [req-4eab5a49-fbee-4623-a14a-d1a4b52fb332 tempest-TestVolumeBootPattern-771277616 tempest-TestVolumeBootPattern-1634675604] [instance: 6436ffab-6706-484b-bb29-bafc9f1b6559] Terminating instance
2015-08-28 11:57:48.933 ERROR nova.virt.libvirt.driver [req-1fb42c20-c1d5-462b-a3a8-8c1ff0f028fc nova service] [instance: 6436ffab-6706-484b-bb29-bafc9f1b6559] Unable to create VM snapshot, failing volume_snapshot operation.
2015-08-28 11:57:48.933 13341 ERROR nova.virt.libvirt.driver [instance: 6436ffab-6706-484b-bb29-bafc9f1b6559] Traceback (most recent call last):
2015-08-28 11:57:48.933 13341 ERROR nova.virt.libvirt.driver [instance: 6436ffab-6706-484b-bb29-bafc9f1b6559] File "/opt/stack/nova/nova/virt/libvirt/driver.py", line 1753, in _volume_snapshot_create
2015-08-28 11:57:48.933 13341 ERROR nova.virt.libvirt.driver [instance: 6436ffab-6706-484b-bb29-bafc9f1b6559] domain.snapshotCreateXML(snapshot_xml, snap_flags)
2015-08-28 11:57:48.933 13341 ERROR nova.virt.libvirt.driver [instance: 6436ffab-6706-484b-bb29-bafc9f1b6559] File "/usr/local/lib/python2.7/dist-packages/eventlet/tpool.py", line 183, in doit
2015-08-28 11:57:48.933 13341 ERROR nova.virt.libvirt.driver [instance: 6436ffab-6706-484b-bb29-bafc9f1b6559] result = proxy_call(self._autowrap, f, *args, **kwargs)
2015-08-28 11:57:48.933 13341 ERROR nova.virt.libvirt.driver [instance: 6436ffab-6706-484b-bb29-bafc9f1b6559] File "/usr/local/lib/python2.7/dist-packages/eventlet/tpool.py", line 141, in proxy_call
2015-08-28 11:57:48.933 13341 ERROR nova.virt.libvirt.driver [instance: 6436ffab-6706-484b-bb29-bafc9f1b6559] rv = execute(f, *args, **kwargs)
2015-08-28 11:57:48.933 13341 ERROR nova.virt.libvirt.driver [instance: 6436ffab-6706-484b-bb29-bafc9f1b6559] File "/usr/local/lib/python2.7/dist-packages/eventlet/tpool.py", line 122, in execute
2015-08-28 11:57:48.933 13341 ERROR nova.virt.libvirt.driver [instance: 6436ffab-6706-484b-bb29-bafc9f1b6559] six.reraise(c, e, tb)
2015-08-28 11:57:48.933 13341 ERROR nova.virt.libvirt.driver [instance: 6436ffab-6706-484b-bb29-bafc9f1b6559] File "/usr/local/lib/python2.7/dist-packages/eventlet/tpool.py", line 80, in tworker
2015-08-28 11:57:48.933 13341 ERROR nova.virt.libvirt.driver [instance: 6436ffab-6706-484b-bb29-bafc9f1b6559] rv = meth(*args, **kwargs)
2015-08-28 11:57:48.933 13341 ERROR nova.virt.libvirt.driver [instance: 6436ffab-6706-484b-bb29-bafc9f1b6559] File "/usr/local/lib/python2.7/dist-packages/libvirt.py", line 2292, in snapshotCreateXML
2015-08-28 11:57:48.933 13341 ERROR nova.virt.libvirt.driver [instance: 6436ffab-6706-484b-bb29-bafc9f1b6559] if ret is None:raise libvirtError('virDomainSnapshotCreateXML() failed', dom=self)
2015-08-28 11:57:48.933 13341 ERROR nova.virt.libvirt.driver [instance: 6436ffab-6706-484b-bb29-bafc9f1b6559] libvirtError: Unable to write to monitor: Broken pipe
2015-08-28 11:57:48.933 13341 ERROR nova.virt.libvirt.driver [instance: 6436ffab-6706-484b-bb29-bafc9f1b6559]
2015-08-28 11:57:48.934 ERROR nova.virt.libvirt.driver [req-1fb42c20-c1d5-462b-a3a8-8c1ff0f028fc nova service] [instance: 6436ffab-6706-484b-bb29-bafc9f1b6559] Error occurred during volume_snapshot_create, sending error status to Cinder.
2015-08-28 11:57:48.934 13341 ERROR nova.virt.libvirt.driver [instance: 6436ffab-6706-484b-bb29-bafc9f1b6559] Traceback (most recent call last):
2015-08-28 11:57:48.934 13341 ERROR nova.virt.libvirt.driver [instance: 6436ffab-6706-484b-bb29-bafc9f1b6559] File "/opt/stack/nova/nova/virt/libvirt/driver.py", line 1808, in volume_snapshot_create
2015-08-28 11:57:48.934 13341 ERROR nova.virt.libvirt.driver [instance: 6436ffab-6706-484b-bb29-bafc9f1b6559] volume_id, create_info['new_file'])
2015-08-28 11:57:48.934 13341 ERROR nova.virt.libvirt.driver [instance: 6436ffab-6706-484b-bb29-bafc9f1b6559] File "/opt/stack/nova/nova/virt/libvirt/driver.py", line 1753, in _volume_snapshot_create
2015-08-28 11:57:48.934 13341 ERROR nova.virt.libvirt.driver [instance: 6436ffab-6706-484b-bb29-bafc9f1b6559] domain.snapshotCreateXML(snapshot_xml, snap_flags)
2015-08-28 11:57:48.934 13341 ERROR nova.virt.libvirt.driver [instance: 6436ffab-6706-484b-bb29-bafc9f1b6559] File "/usr/local/lib/python2.7/dist-packages/eventlet/tpool.py", line 183, in doit
2015-08-28 11:57:48.934 13341 ERROR nova.virt.libvirt.driver [instance: 6436ffab-6706-484b-bb29-bafc9f1b6559] result = proxy_call(self._autowrap, f, *args, **kwargs)
2015-08-28 11:57:48.934 13341 ERROR nova.virt.libvirt.driver [instance: 6436ffab-6706-484b-bb29-bafc9f1b6559] File "/usr/local/lib/python2.7/dist-packages/eventlet/tpool.py", line 141, in proxy_call
2015-08-28 11:57:48.934 13341 ERROR nova.virt.libvirt.driver [instance: 6436ffab-6706-484b-bb29-bafc9f1b6559] rv = execute(f, *args, **kwargs)
2015-08-28 11:57:48.934 13341 ERROR nova.virt.libvirt.driver [instance: 6436ffab-6706-484b-bb29-bafc9f1b6559] File "/usr/local/lib/python2.7/dist-packages/eventlet/tpool.py", line 122, in execute
2015-08-28 11:57:48.934 13341 ERROR nova.virt.libvirt.driver [instance: 6436ffab-6706-484b-bb29-bafc9f1b6559] six.reraise(c, e, tb)
2015-08-28 11:57:48.934 13341 ERROR nova.virt.libvirt.driver [instance: 6436ffab-6706-484b-bb29-bafc9f1b6559] File "/usr/local/lib/python2.7/dist-packages/eventlet/tpool.py", line 80, in tworker
2015-08-28 11:57:48.934 13341 ERROR nova.virt.libvirt.driver [instance: 6436ffab-6706-484b-bb29-bafc9f1b6559] rv = meth(*args, **kwargs)
2015-08-28 11:57:48.934 13341 ERROR nova.virt.libvirt.driver [instance: 6436ffab-6706-484b-bb29-bafc9f1b6559] File "/usr/local/lib/python2.7/dist-packages/libvirt.py", line 2292, in snapshotCreateXML
2015-08-28 11:57:48.934 13341 ERROR nova.virt.libvirt.driver [instance: 6436ffab-6706-484b-bb29-bafc9f1b6559] if ret is None:raise libvirtError('virDomainSnapshotCreateXML() failed', dom=self)
2015-08-28 11:57:48.934 13341 ERROR nova.virt.libvirt.driver [instance: 6436ffab-6706-484b-bb29-bafc9f1b6559] libvirtError: Unable to write to monitor: Broken pipe
2015-08-28 11:57:48.934 13341 ERROR nova.virt.libvirt.driver [instance: 6436ffab-6706-484b-bb29-bafc9f1b6559]
2015-08-28 11:57:48.936 DEBUG keystoneclient.session [req-1fb42c20-c1d5-462b-a3a8-8c1ff0f028fc nova service] REQ: curl -g -i -X POST http://127.0.0.1:8776/v2/a6c5e7426d6346b2a20d2ae23c6fd1ff/snapshots/ff510a70-0888-4f73-b3c8-7b87205a56b1/action -H "User-Agent: python-cinderclient" -H "Content-Type: application/json" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}769f73dbe11475837009bbe6d9407dd698de4b92" -d '{"os-update_snapshot_status": {"status": "error", "progress": "90%"}}' _http_log_request /usr/local/lib/python2.7/dist-packages/keystoneclient/session.py:195
2015-08-28 11:57:48.941 DEBUG nova.virt.driver [req-1b591b7d-a6de-4cb3-ab7f-2be5242aaf15 None None] Emitting event <LifecycleEvent: 1440763068.93, 6436ffab-6706-484b-bb29-bafc9f1b6559 => Paused> emit_event /opt/stack/nova/nova/virt/driver.py:1303
Other example trace:
2015-08-28 11:44:49.045 DEBUG nova.compute.manager [req-bde1d5a9-bc6b-43e1-8523-e6c206f398f6 None None] [instance: f0a9d036-5b01-4eab-b737-a0b6eecd68cc] Checking state _get_power_state /opt/stack/nova/nova/compute/manager.py:1300
2015-08-28 11:44:49.051 DEBUG nova.compute.manager [req-bde1d5a9-bc6b-43e1-8523-e6c206f398f6 None None] [instance: f0a9d036-5b01-4eab-b737-a0b6eecd68cc] Synchronizing instance power state after lifecycle event "Started"; current vm_state: building, current task_state: spawning, current DB power_state: 0, VM power_state: 1 handle_lifecycle_event /opt/stack/nova/nova/compute/manager.py:1229
2015-08-28 11:44:49.104 DEBUG keystoneclient.session [req-7761f514-eba1-4724-b27c-d659739a31b4 nova service] RESP: [202] date: Fri, 28 Aug 2015 11:44:49 GMT connection: keep-alive content-type: text/html; charset=UTF-8 content-length: 0 x-openstack-request-id: req-aa92c7cb-0708-407b-bd92-24d6140b407b _http_log_response /usr/local/lib/python2.7/dist-packages/keystoneclient/session.py:224
2015-08-28 11:44:49.106 ERROR oslo_messaging.rpc.dispatcher [req-7761f514-eba1-4724-b27c-d659739a31b4 nova service] Exception during message handling: Unable to write to monitor: Broken pipe
2015-08-28 11:44:49.106 13324 ERROR oslo_messaging.rpc.dispatcher Traceback (most recent call last):
2015-08-28 11:44:49.106 13324 ERROR oslo_messaging.rpc.dispatcher File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/rpc/dispatcher.py", line 142, in _dispatch_and_reply
2015-08-28 11:44:49.106 13324 ERROR oslo_messaging.rpc.dispatcher executor_callback))
2015-08-28 11:44:49.106 13324 ERROR oslo_messaging.rpc.dispatcher File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/rpc/dispatcher.py", line 186, in _dispatch
2015-08-28 11:44:49.106 13324 ERROR oslo_messaging.rpc.dispatcher executor_callback)
2015-08-28 11:44:49.106 13324 ERROR oslo_messaging.rpc.dispatcher File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/rpc/dispatcher.py", line 129, in _do_dispatch
2015-08-28 11:44:49.106 13324 ERROR oslo_messaging.rpc.dispatcher result = func(ctxt, **new_args)
2015-08-28 11:44:49.106 13324 ERROR oslo_messaging.rpc.dispatcher File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/rpc/server.py", line 142, in inner
2015-08-28 11:44:49.106 13324 ERROR oslo_messaging.rpc.dispatcher return func(*args, **kwargs)
2015-08-28 11:44:49.106 13324 ERROR oslo_messaging.rpc.dispatcher File "/opt/stack/nova/nova/exception.py", line 89, in wrapped
2015-08-28 11:44:49.106 13324 ERROR oslo_messaging.rpc.dispatcher payload)
2015-08-28 11:44:49.106 13324 ERROR oslo_messaging.rpc.dispatcher File "/usr/local/lib/python2.7/dist-packages/oslo_utils/excutils.py", line 195, in __exit__
2015-08-28 11:44:49.106 13324 ERROR oslo_messaging.rpc.dispatcher six.reraise(self.type_, self.value, self.tb)
2015-08-28 11:44:49.106 13324 ERROR oslo_messaging.rpc.dispatcher File "/opt/stack/nova/nova/exception.py", line 72, in wrapped
2015-08-28 11:44:49.106 13324 ERROR oslo_messaging.rpc.dispatcher return f(self, context, *args, **kw)
2015-08-28 11:44:49.106 13324 ERROR oslo_messaging.rpc.dispatcher File "/opt/stack/nova/nova/compute/manager.py", line 2978, in volume_snapshot_create
2015-08-28 11:44:49.106 13324 ERROR oslo_messaging.rpc.dispatcher create_info)
2015-08-28 11:44:49.106 13324 ERROR oslo_messaging.rpc.dispatcher File "/opt/stack/nova/nova/virt/libvirt/driver.py", line 1816, in volume_snapshot_create
2015-08-28 11:44:49.106 13324 ERROR oslo_messaging.rpc.dispatcher context, snapshot_id, 'error')
2015-08-28 11:44:49.106 13324 ERROR oslo_messaging.rpc.dispatcher File "/usr/local/lib/python2.7/dist-packages/oslo_utils/excutils.py", line 195, in __exit__
2015-08-28 11:44:49.106 13324 ERROR oslo_messaging.rpc.dispatcher six.reraise(self.type_, self.value, self.tb)
2015-08-28 11:44:49.106 13324 ERROR oslo_messaging.rpc.dispatcher File "/opt/stack/nova/nova/virt/libvirt/driver.py", line 1808, in volume_snapshot_create
2015-08-28 11:44:49.106 13324 ERROR oslo_messaging.rpc.dispatcher volume_id, create_info['new_file'])
2015-08-28 11:44:49.106 13324 ERROR oslo_messaging.rpc.dispatcher File "/opt/stack/nova/nova/virt/libvirt/driver.py", line 1753, in _volume_snapshot_create
2015-08-28 11:44:49.106 13324 ERROR oslo_messaging.rpc.dispatcher domain.snapshotCreateXML(snapshot_xml, snap_flags)
2015-08-28 11:44:49.106 13324 ERROR oslo_messaging.rpc.dispatcher File "/usr/local/lib/python2.7/dist-packages/eventlet/tpool.py", line 183, in doit
2015-08-28 11:44:49.106 13324 ERROR oslo_messaging.rpc.dispatcher result = proxy_call(self._autowrap, f, *args, **kwargs)
2015-08-28 11:44:49.106 13324 ERROR oslo_messaging.rpc.dispatcher File "/usr/local/lib/python2.7/dist-packages/eventlet/tpool.py", line 141, in proxy_call
2015-08-28 11:44:49.106 13324 ERROR oslo_messaging.rpc.dispatcher rv = execute(f, *args, **kwargs)
2015-08-28 11:44:49.106 13324 ERROR oslo_messaging.rpc.dispatcher File "/usr/local/lib/python2.7/dist-packages/eventlet/tpool.py", line 122, in execute
2015-08-28 11:44:49.106 13324 ERROR oslo_messaging.rpc.dispatcher six.reraise(c, e, tb)
2015-08-28 11:44:49.106 13324 ERROR oslo_messaging.rpc.dispatcher File "/usr/local/lib/python2.7/dist-packages/eventlet/tpool.py", line 80, in tworker
2015-08-28 11:44:49.106 13324 ERROR oslo_messaging.rpc.dispatcher rv = meth(*args, **kwargs)
2015-08-28 11:44:49.106 13324 ERROR oslo_messaging.rpc.dispatcher File "/usr/local/lib/python2.7/dist-packages/libvirt.py", line 2292, in snapshotCreateXML
2015-08-28 11:44:49.106 13324 ERROR oslo_messaging.rpc.dispatcher if ret is None:raise libvirtError('virDomainSnapshotCreateXML() failed', dom=self)
2015-08-28 11:44:49.106 13324 ERROR oslo_messaging.rpc.dispatcher libvirtError: Unable to write to monitor: Broken pipe
2015-08-28 11:44:49.106 13324 ERROR oslo_messaging.rpc.dispatcher
2015-08-28 11:44:49.217 INFO nova.compute.manager [req-bde1d5a9-bc6b-43e1-8523-e6c206f398f6 None None] [instance: f0a9d036-5b01-4eab-b737-a0b6eecd68cc] During sync_power_state the instance has a pending task (spawning). Skip.
2015-08-28 11:44:49.281 DEBUG nova.compute.manager [req-f19b8b3c-5ad1-4179-a250-9481aa789887 tempest-TestVolumeBootPattern-1480878034 tempest-TestVolumeBootPattern-1262635365] [instance: e3b48af1-067b-41d4-a5f8-3602a83db3cd] Deallocating network for instance _deallocate_network /opt/stack/nova/nova/compute/manager.py:1796
Complete logs for example test runs that hit this issue can be found here:
http://176.9.127.22:8081/refs-changes-86-214386-12/
http://176.9.127.22:8081/refs-changes-71-216771-2/
The testing setup is devstack trunk with an ubuntu trusty image in a VM, using a Quobyte backend for the Cinder volumes. These issues occur during the same tempest test:
tempest.scenario.test_volume_boot_pattern.TestVolumeBootPattern.test_create_ebs_image_and_check_boot
After some more digging, this is possibly related to bug #1489581 .