yahoo-eng-team team mailing list archive

Thread
Date
[Bug 1489860] Re: libvirtError: Unable to write to monitor: Broken pipe during snapshotting

To: yahoo-eng-team@xxxxxxxxxxxxxxxxxxx
From: Silvan Kaiser <silvan@xxxxxxxxxxx>
Date: Mon, 31 Aug 2015 08:07:46 -0000
Reply-to: Bug 1489860 <1489860@xxxxxxxxxxxxxxxxxx>
Sender: bounces@xxxxxxxxxxxxx
*** This bug is a duplicate of bug 1489581 ***
    https://bugs.launchpad.net/bugs/1489581

I'll mark this as a duplicate of 1489581 that i linked to earlier, since
that bugs fix has merged all is well.

** This bug has been marked a duplicate of bug 1489581
   test_create_ebs_image_and_check_boot is race failing

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

Title:
   libvirtError: Unable to write to monitor: Broken pipe during
  snapshotting

Status in OpenStack Compute (nova):
  Incomplete

Bug description:
  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

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

[Bug 1489860] [NEW] libvirtError: Unable to write to monitor: Broken pipe during snapshotting
From: Silvan Kaiser, 2015-08-28