yahoo-eng-team team mailing list archive

Thread
Date
[Bug 1598833] [NEW] libvirtError: operation failed: open disk image file failed during online snapshots via Nova API

To: yahoo-eng-team@xxxxxxxxxxxxxxxxxxx
From: Silvan Kaiser <silvan@xxxxxxxxxxx>
Date: Mon, 04 Jul 2016 12:53:29 -0000
Reply-to: Bug 1598833 <1598833@xxxxxxxxxxxxxxxxxx>
Sender: bounces@xxxxxxxxxxxxx
Public bug reported:

Quobyte CI fails test_snapshot_create_with_volume_in_use (v1 and v2)
tests with "libvirtError: operation failed: open disk image file failed"
. Nova compute log shows:

2016-07-04 09:06:35.649 7297 DEBUG oslo_concurrency.processutils [req-84dbb010-c105-4b5b-8d1d-41028c114307 tempest-VolumesV2SnapshotTestJSON-1508672341 tempest-VolumesV2SnapshotTestJSON-1508672341] u'findmnt --t
arget /mnt/quobyte-volume/abfa1002557ab2b21ec218a86487dd92 --source quobyte@78.46.57.153:7861/quobyteci_test_volume' failed. Not Retrying. execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processu
tils.py:422
2016-07-04 09:06:35.649 7297 DEBUG nova.virt.libvirt.volume.quobyte [req-84dbb010-c105-4b5b-8d1d-41028c114307 tempest-VolumesV2SnapshotTestJSON-1508672341 tempest-VolumesV2SnapshotTestJSON-1508672341] Mounting v
olume 78.46.57.153:7861/quobyteci_test_volume at mount point /mnt/quobyte-volume/abfa1002557ab2b21ec218a86487dd92 ... mount_volume /opt/stack/nova/nova/virt/libvirt/volume/quobyte.py:53
2016-07-04 09:06:35.649 7297 DEBUG oslo_concurrency.processutils [req-84dbb010-c105-4b5b-8d1d-41028c114307 tempest-VolumesV2SnapshotTestJSON-1508672341 tempest-VolumesV2SnapshotTestJSON-1508672341] Running cmd (
subprocess): mount.quobyte 78.46.57.153:7861/quobyteci_test_volume /mnt/quobyte-volume/abfa1002557ab2b21ec218a86487dd92 execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:344
2016-07-04 09:06:36.830 7297 DEBUG oslo_concurrency.processutils [req-84dbb010-c105-4b5b-8d1d-41028c114307 tempest-VolumesV2SnapshotTestJSON-1508672341 tempest-VolumesV2SnapshotTestJSON-1508672341] CMD "mount.qu
obyte 78.46.57.153:7861/quobyteci_test_volume /mnt/quobyte-volume/abfa1002557ab2b21ec218a86487dd92" returned: 0 in 1.181s execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:374
2016-07-04 09:06:36.832 7297 INFO nova.virt.libvirt.volume.quobyte [req-84dbb010-c105-4b5b-8d1d-41028c114307 tempest-VolumesV2SnapshotTestJSON-1508672341 tempest-VolumesV2SnapshotTestJSON-1508672341] Mounted vol
ume: 78.46.57.153:7861/quobyteci_test_volume
2016-07-04 09:06:36.832 7297 DEBUG oslo_concurrency.processutils [req-84dbb010-c105-4b5b-8d1d-41028c114307 tempest-VolumesV2SnapshotTestJSON-1508672341 tempest-VolumesV2SnapshotTestJSON-1508672341] Running cmd (
subprocess): getfattr -n quobyte.info /mnt/quobyte-volume/abfa1002557ab2b21ec218a86487dd92 execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:344
2016-07-04 09:06:36.853 7297 DEBUG oslo_concurrency.processutils [req-84dbb010-c105-4b5b-8d1d-41028c114307 tempest-VolumesV2SnapshotTestJSON-1508672341 tempest-VolumesV2SnapshotTestJSON-1508672341] CMD "getfattr
 -n quobyte.info /mnt/quobyte-volume/abfa1002557ab2b21ec218a86487dd92" returned: 0 in 0.021s execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:374
2016-07-04 09:06:36.854 7297 DEBUG oslo_concurrency.lockutils [req-84dbb010-c105-4b5b-8d1d-41028c114307 tempest-VolumesV2SnapshotTestJSON-1508672341 tempest-VolumesV2SnapshotTestJSON-1508672341] Lock "connect_vo
lume" released by "nova.virt.libvirt.volume.quobyte.connect_volume" :: held 1.232s inner /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:282
2016-07-04 09:06:36.857 7297 DEBUG nova.virt.libvirt.guest [req-84dbb010-c105-4b5b-8d1d-41028c114307 tempest-VolumesV2SnapshotTestJSON-1508672341 tempest-VolumesV2SnapshotTestJSON-1508672341] attach device xml: 
<disk type="file" device="disk">
  <driver name="qemu" type="qcow2" cache="none" io="native"/>
  <source file="/mnt/quobyte-volume/abfa1002557ab2b21ec218a86487dd92/volume-4604d6b5-cf47-4494-8833-15029e30a77e.f21ecc73-29a7-44c8-8f09-831e701569d2"/>
  <target bus="virtio" dev="vdb"/>
  <serial>4604d6b5-cf47-4494-8833-15029e30a77e</serial>
</disk>
 attach_device /opt/stack/nova/nova/virt/libvirt/guest.py:251  
2016-07-04 09:06:38.512 7297 ERROR nova.virt.libvirt.driver [req-84dbb010-c105-4b5b-8d1d-41028c114307 tempest-VolumesV2SnapshotTestJSON-1508672341 tempest-VolumesV2SnapshotTestJSON-1508672341] [instance: 0713aaa8-f630-4c7f-b541-616ce6541615] Failed to attach volume at mountpoint: /dev/vdb
2016-07-04 09:06:38.512 7297 ERROR nova.virt.libvirt.driver [instance: 0713aaa8-f630-4c7f-b541-616ce6541615] Traceback (most recent call last):
2016-07-04 09:06:38.512 7297 ERROR nova.virt.libvirt.driver [instance: 0713aaa8-f630-4c7f-b541-616ce6541615]   File "/opt/stack/nova/nova/virt/libvirt/driver.py", line 1232, in attach_volume
2016-07-04 09:06:38.512 7297 ERROR nova.virt.libvirt.driver [instance: 0713aaa8-f630-4c7f-b541-616ce6541615]     guest.attach_device(conf, persistent=True, live=live)
2016-07-04 09:06:38.512 7297 ERROR nova.virt.libvirt.driver [instance: 0713aaa8-f630-4c7f-b541-616ce6541615]   File "/opt/stack/nova/nova/virt/libvirt/guest.py", line 252, in attach_device
2016-07-04 09:06:38.512 7297 ERROR nova.virt.libvirt.driver [instance: 0713aaa8-f630-4c7f-b541-616ce6541615]     self._domain.attachDeviceFlags(device_xml, flags=flags)
2016-07-04 09:06:38.512 7297 ERROR nova.virt.libvirt.driver [instance: 0713aaa8-f630-4c7f-b541-616ce6541615]   File "/usr/local/lib/python2.7/dist-packages/eventlet/tpool.py", line 186, in doit
2016-07-04 09:06:38.512 7297 ERROR nova.virt.libvirt.driver [instance: 0713aaa8-f630-4c7f-b541-616ce6541615]     result = proxy_call(self._autowrap, f, *args, **kwargs)
2016-07-04 09:06:38.512 7297 ERROR nova.virt.libvirt.driver [instance: 0713aaa8-f630-4c7f-b541-616ce6541615]   File "/usr/local/lib/python2.7/dist-packages/eventlet/tpool.py", line 144, in proxy_call
2016-07-04 09:06:38.512 7297 ERROR nova.virt.libvirt.driver [instance: 0713aaa8-f630-4c7f-b541-616ce6541615]     rv = execute(f, *args, **kwargs)
2016-07-04 09:06:38.512 7297 ERROR nova.virt.libvirt.driver [instance: 0713aaa8-f630-4c7f-b541-616ce6541615]   File "/usr/local/lib/python2.7/dist-packages/eventlet/tpool.py", line 125, in execute
2016-07-04 09:06:38.512 7297 ERROR nova.virt.libvirt.driver [instance: 0713aaa8-f630-4c7f-b541-616ce6541615]     six.reraise(c, e, tb)
2016-07-04 09:06:38.512 7297 ERROR nova.virt.libvirt.driver [instance: 0713aaa8-f630-4c7f-b541-616ce6541615]   File "/usr/local/lib/python2.7/dist-packages/eventlet/tpool.py", line 83, in tworker
2016-07-04 09:06:38.512 7297 ERROR nova.virt.libvirt.driver [instance: 0713aaa8-f630-4c7f-b541-616ce6541615]     rv = meth(*args, **kwargs)
2016-07-04 09:06:38.512 7297 ERROR nova.virt.libvirt.driver [instance: 0713aaa8-f630-4c7f-b541-616ce6541615]   File "/usr/local/lib/python2.7/dist-packages/libvirt.py", line 517, in attachDeviceFlags
2016-07-04 09:06:38.512 7297 ERROR nova.virt.libvirt.driver [instance: 0713aaa8-f630-4c7f-b541-616ce6541615]     if ret == -1: raise libvirtError ('virDomainAttachDeviceFlags() failed', dom=self)
2016-07-04 09:06:38.512 7297 ERROR nova.virt.libvirt.driver [instance: 0713aaa8-f630-4c7f-b541-616ce6541615] libvirtError: operation failed: open disk image file failed
2016-07-04 09:06:38.512 7297 ERROR nova.virt.libvirt.driver [instance: 0713aaa8-f630-4c7f-b541-616ce6541615] 
2016-07-04 09:06:38.513 7297 DEBUG oslo_concurrency.lockutils [req-84dbb010-c105-4b5b-8d1d-41028c114307 tempest-VolumesV2SnapshotTestJSON-1508672341 tempest-VolumesV2SnapshotTestJSON-1508672341] Lock "connect_volume" acquired by "nova.virt.libvirt.volume.quobyte.disconnect_volume" :: waited 0.000s inner /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:270
2016-07-04 09:06:38.514 7297 DEBUG oslo_concurrency.processutils [req-84dbb010-c105-4b5b-8d1d-41028c114307 tempest-VolumesV2SnapshotTestJSON-1508672341 tempest-VolumesV2SnapshotTestJSON-1508672341] Running cmd (subprocess): findmnt --target /mnt/quobyte-volume/abfa1002557ab2b21ec218a86487dd92 --source quobyte@78.46.57.153:7861/quobyteci_test_volume execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:344
2016-07-04 09:06:38.520 7297 DEBUG oslo_concurrency.processutils [req-84dbb010-c105-4b5b-8d1d-41028c114307 tempest-VolumesV2SnapshotTestJSON-1508672341 tempest-VolumesV2SnapshotTestJSON-1508672341] CMD "findmnt --target /mnt/quobyte-volume/abfa1002557ab2b21ec218a86487dd92 --source quobyte@78.46.57.153:7861/quobyteci_test_volume" returned: 0 in 0.006s execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:374
2016-07-04 09:06:38.521 7297 DEBUG oslo_concurrency.processutils [req-84dbb010-c105-4b5b-8d1d-41028c114307 tempest-VolumesV2SnapshotTestJSON-1508672341 tempest-VolumesV2SnapshotTestJSON-1508672341] Running cmd (subprocess): umount.quobyte /mnt/quobyte-volume/abfa1002557ab2b21ec218a86487dd92 execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:344


libvirt daemon logs shows a permission denied error:
2016-07-04 09:06:37.885+0000: 24010: debug : qemuSetupDiskPathAllow:60 : Process path /mnt/quobyte-volume/abfa1002557ab2b21ec218a86487dd92/volume-4604d6b5-cf47-4494-8833-15029e30a77e.2c3539c0-c6ed-4c72-8e65-6afd
dda344df for disk
2016-07-04 09:06:37.885+0000: 24010: debug : qemuSetupDiskPathAllow:60 : Process path /mnt/quobyte-volume/abfa1002557ab2b21ec218a86487dd92/volume-4604d6b5-cf47-4494-8833-15029e30a77e for disk
2016-07-04 09:06:37.886+0000: 24010: debug : virCommandRunAsync:2282 : About to run /usr/lib/libvirt/virt-aa-helper -p 0 -r -u libvirt-0713aaa8-f630-4c7f-b541-616ce6541615 -f /mnt/quobyte-volume/abfa1002557ab2b2
1ec218a86487dd92/volume-4604d6b5-cf47-4494-8833-15029e30a77e.f21ecc73-29a7-44c8-8f09-831e701569d2
2016-07-04 09:06:37.886+0000: 24010: debug : virCommandRunAsync:2285 : Command result 0, with PID 15693
2016-07-04 09:06:38.174+0000: 24010: debug : virCommandRun:2142 : Result status 0, stdout: '' stderr: ''
2016-07-04 09:06:38.174+0000: 24010: debug : qemuDomainPCIAddressGetNextSlot:2270 : PCI slot 0000:00:01 already in use
2016-07-04 09:06:38.174+0000: 24010: debug : qemuDomainPCIAddressGetNextSlot:2270 : PCI slot 0000:00:02 already in use
2016-07-04 09:06:38.174+0000: 24010: debug : qemuDomainPCIAddressGetNextSlot:2270 : PCI slot 0000:00:03 already in use
2016-07-04 09:06:38.174+0000: 24010: debug : qemuDomainPCIAddressGetNextSlot:2270 : PCI slot 0000:00:04 already in use
2016-07-04 09:06:38.174+0000: 24010: debug : qemuDomainPCIAddressGetNextSlot:2313 : Found free PCI slot 0000:00:05
2016-07-04 09:06:38.174+0000: 24010: debug : qemuDomainPCIAddressReserveAddr:2114 : Reserving PCI slot 0000:00:05.0 (multifunction='off')
2016-07-04 09:06:38.174+0000: 24010: debug : qemuDomainObjEnterMonitorInternal:1278 : Entering monitor (mon=0x7f516c002820 vm=0x7f515c003540 name=instance-0000000f)
2016-07-04 09:06:38.174+0000: 24010: debug : qemuMonitorAddDrive:3011 : mon=0x7f516c002820 drive=file=/mnt/quobyte-volume/abfa1002557ab2b21ec218a86487dd92/volume-4604d6b5-cf47-4494-8833-15029e30a77e.f21ecc73-29a
7-44c8-8f09-831e701569d2,if=none,id=drive-virtio-disk1,format=qcow2,serial=4604d6b5-cf47-4494-8833-15029e30a77e,cache=none,aio=native
2016-07-04 09:06:38.174+0000: 24010: debug : qemuMonitorJSONAddDrive:3126 : drive_add command not found, trying HMP
2016-07-04 09:06:38.174+0000: 24010: debug : qemuMonitorJSONCommandWithFd:264 : Send command '{"execute":"human-monitor-command","arguments":{"command-line":"drive_add dummy file=/mnt/quobyte-volume/abfa1002557a
b2b21ec218a86487dd92/volume-4604d6b5-cf47-4494-8833-15029e30a77e.f21ecc73-29a7-44c8-8f09-831e701569d2,if=none,id=drive-virtio-disk1,format=qcow2,serial=4604d6b5-cf47-4494-8833-15029e30a77e,cache=none,aio=native"
},"id":"libvirt-16"}' for write with FD -1
2016-07-04 09:06:38.174+0000: 24010: debug : qemuMonitorSend:959 : QEMU_MONITOR_SEND_MSG: mon=0x7f516c002820 msg={"execute":"human-monitor-command","arguments":{"command-line":"drive_add dummy file=/mnt/quobyte-
volume/abfa1002557ab2b21ec218a86487dd92/volume-4604d6b5-cf47-4494-8833-15029e30a77e.f21ecc73-29a7-44c8-8f09-831e701569d2,if=none,id=drive-virtio-disk1,format=qcow2,serial=4604d6b5-cf47-4494-8833-15029e30a77e,cac
he=none,aio=native"},"id":"libvirt-16"}
 fd=-1
2016-07-04 09:06:38.176+0000: 24004: debug : qemuMonitorIOWrite:504 : QEMU_MONITOR_IO_WRITE: mon=0x7f516c002820 buf={"execute":"human-monitor-command","arguments":{"command-line":"drive_add dummy file=/mnt/quoby
te-volume/abfa1002557ab2b21ec218a86487dd92/volume-4604d6b5-cf47-4494-8833-15029e30a77e.f21ecc73-29a7-44c8-8f09-831e701569d2,if=none,id=drive-virtio-disk1,format=qcow2,serial=4604d6b5-cf47-4494-8833-15029e30a77e,
cache=none,aio=native"},"id":"libvirt-16"}
 len=350 ret=350 errno=11
2016-07-04 09:06:38.244+0000: 24004: debug : qemuMonitorIOProcess:396 : QEMU_MONITOR_IO_PROCESS: mon=0x7f516c002820 buf={"return": "could not open disk image /mnt/quobyte-volume/abfa1002557ab2b21ec218a86487dd92/
volume-4604d6b5-cf47-4494-8833-15029e30a77e.f21ecc73-29a7-44c8-8f09-831e701569d2: Could not open backing file: Could not open '/mnt/quobyte-volume/abfa1002557ab2b21ec218a86487dd92/volume-4604d6b5-cf47-4494-8833-
15029e30a77e.2c3539c0-c6ed-4c72-8e65-6afddda344df': Permission denied\r\n", "id": "libvirt-16"}
 len=399
2016-07-04 09:06:38.244+0000: 24004: debug : qemuMonitorJSONIOProcessLine:157 : Line [{"return": "could not open disk image /mnt/quobyte-volume/abfa1002557ab2b21ec218a86487dd92/volume-4604d6b5-cf47-4494-8833-150
29e30a77e.f21ecc73-29a7-44c8-8f09-831e701569d2: Could not open backing file: Could not open '/mnt/quobyte-volume/abfa1002557ab2b21ec218a86487dd92/volume-4604d6b5-cf47-4494-8833-15029e30a77e.2c3539c0-c6ed-4c72-8e
65-6afddda344df': Permission denied\r\n", "id": "libvirt-16"}]
2016-07-04 09:06:38.244+0000: 24004: debug : qemuMonitorJSONIOProcessLine:177 : QEMU_MONITOR_RECV_REPLY: mon=0x7f516c002820 reply={"return": "could not open disk image /mnt/quobyte-volume/abfa1002557ab2b21ec218a
86487dd92/volume-4604d6b5-cf47-4494-8833-15029e30a77e.f21ecc73-29a7-44c8-8f09-831e701569d2: Could not open backing file: Could not open '/mnt/quobyte-volume/abfa1002557ab2b21ec218a86487dd92/volume-4604d6b5-cf47-
4494-8833-15029e30a77e.2c3539c0-c6ed-4c72-8e65-6afddda344df': Permission denied\r\n", "id": "libvirt-16"}
2016-07-04 09:06:38.244+0000: 24004: debug : qemuMonitorJSONIOProcess:226 : Total used 399 bytes out of 399 available in buffer
2016-07-04 09:06:38.244+0000: 24010: debug : qemuMonitorJSONCommandWithFd:269 : Receive command reply ret=0 rxObject=0x7f518cff16e0
2016-07-04 09:06:38.244+0000: 24010: error : qemuMonitorTextAddDrive:2611 : operation failed: open disk image file failed
2016-07-04 09:06:38.244+0000: 24010: debug : qemuDomainObjExitMonitorInternal:1301 : Exited monitor (mon=0x7f516c002820 vm=0x7f515c003540 name=instance-0000000f)
2016-07-04 09:06:38.244+0000: 24010: debug : virCommandRunAsync:2282 : About to run /usr/lib/libvirt/virt-aa-helper -p 0 -r -u libvirt-0713aaa8-f630-4c7f-b541-616ce6541615
2016-07-04 09:06:38.245+0000: 24010: debug : virCommandRunAsync:2285 : Command result 0, with PID 15695
2016-07-04 09:06:38.511+0000: 24010: debug : virCommandRun:2142 : Result status 0, stdout: '' stderr: ''
2016-07-04 09:06:38.512+0000: 24010: debug : qemuTeardownDiskPathDeny:102 : Process path /mnt/quobyte-volume/abfa1002557ab2b21ec218a86487dd92/volume-4604d6b5-cf47-4494-8833-15029e30a77e.f21ecc73-29a7-44c8-8f09-8
31e701569d2 for disk
2016-07-04 09:06:38.512+0000: 24010: debug : qemuTeardownDiskPathDeny:102 : Process path /mnt/quobyte-volume/abfa1002557ab2b21ec218a86487dd92/volume-4604d6b5-cf47-4494-8833-15029e30a77e.2c3539c0-c6ed-4c72-8e65-6
afddda344df for disk
2016-07-04 09:06:38.512+0000: 24010: debug : qemuTeardownDiskPathDeny:102 : Process path /mnt/quobyte-volume/abfa1002557ab2b21ec218a86487dd92/volume-4604d6b5-cf47-4494-8833-15029e30a77e for disk
2016-07-04 09:06:38.512+0000: 24010: debug : qemuDomainObjEndJob:1206 : Stopping job: modify (async=none vm=0x7f515c003540 name=instance-0000000f)
2016-07-04 09:06:38.512+0000: 24010: debug : virDomainFree:2270 : dom=0x7f517417e660, (VM: name=instance-0000000f, uuid=0713aaa8-f630-4c7f-b541-616ce6541615)
2016-07-04 09:06:38.565+0000: 24004: debug : virNetlinkEventCallback:347 : dispatching to max 0 clients, called from event watch 6
2016-07-04 09:06:38.565+0000: 24004: debug : virNetlinkEventCallback:360 : event not handled.
2016-07-04 09:06:41.789+0000: 24004: debug : qemuMonitorIOProcess:396 : QEMU_MONITOR_IO_PROCESS: mon=0x7f516c002820 buf={"timestamp": {"seconds": 1467623201, "microseconds": 789082}, "event": "NIC_RX_FILTER_CHANGED", "data": {"name": "net0", "path": "/machine/peripheral/net0/virtio-backend"}}
 len=175

** Affects: nova
     Importance: Undecided
     Assignee: Silvan Kaiser (2-silvan)
         Status: New


** Tags: libvirt permissions quobyte

** Changed in: nova
     Assignee: (unassigned) => Silvan Kaiser (2-silvan)

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

Title:
  libvirtError: operation failed: open disk image file failed during
  online snapshots via Nova API

Status in OpenStack Compute (nova):
  New

Bug description:
  Quobyte CI fails test_snapshot_create_with_volume_in_use (v1 and v2)
  tests with "libvirtError: operation failed: open disk image file
  failed" . Nova compute log shows:

  2016-07-04 09:06:35.649 7297 DEBUG oslo_concurrency.processutils [req-84dbb010-c105-4b5b-8d1d-41028c114307 tempest-VolumesV2SnapshotTestJSON-1508672341 tempest-VolumesV2SnapshotTestJSON-1508672341] u'findmnt --t
  arget /mnt/quobyte-volume/abfa1002557ab2b21ec218a86487dd92 --source quobyte@78.46.57.153:7861/quobyteci_test_volume' failed. Not Retrying. execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processu
  tils.py:422
  2016-07-04 09:06:35.649 7297 DEBUG nova.virt.libvirt.volume.quobyte [req-84dbb010-c105-4b5b-8d1d-41028c114307 tempest-VolumesV2SnapshotTestJSON-1508672341 tempest-VolumesV2SnapshotTestJSON-1508672341] Mounting v
  olume 78.46.57.153:7861/quobyteci_test_volume at mount point /mnt/quobyte-volume/abfa1002557ab2b21ec218a86487dd92 ... mount_volume /opt/stack/nova/nova/virt/libvirt/volume/quobyte.py:53
  2016-07-04 09:06:35.649 7297 DEBUG oslo_concurrency.processutils [req-84dbb010-c105-4b5b-8d1d-41028c114307 tempest-VolumesV2SnapshotTestJSON-1508672341 tempest-VolumesV2SnapshotTestJSON-1508672341] Running cmd (
  subprocess): mount.quobyte 78.46.57.153:7861/quobyteci_test_volume /mnt/quobyte-volume/abfa1002557ab2b21ec218a86487dd92 execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:344
  2016-07-04 09:06:36.830 7297 DEBUG oslo_concurrency.processutils [req-84dbb010-c105-4b5b-8d1d-41028c114307 tempest-VolumesV2SnapshotTestJSON-1508672341 tempest-VolumesV2SnapshotTestJSON-1508672341] CMD "mount.qu
  obyte 78.46.57.153:7861/quobyteci_test_volume /mnt/quobyte-volume/abfa1002557ab2b21ec218a86487dd92" returned: 0 in 1.181s execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:374
  2016-07-04 09:06:36.832 7297 INFO nova.virt.libvirt.volume.quobyte [req-84dbb010-c105-4b5b-8d1d-41028c114307 tempest-VolumesV2SnapshotTestJSON-1508672341 tempest-VolumesV2SnapshotTestJSON-1508672341] Mounted vol
  ume: 78.46.57.153:7861/quobyteci_test_volume
  2016-07-04 09:06:36.832 7297 DEBUG oslo_concurrency.processutils [req-84dbb010-c105-4b5b-8d1d-41028c114307 tempest-VolumesV2SnapshotTestJSON-1508672341 tempest-VolumesV2SnapshotTestJSON-1508672341] Running cmd (
  subprocess): getfattr -n quobyte.info /mnt/quobyte-volume/abfa1002557ab2b21ec218a86487dd92 execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:344
  2016-07-04 09:06:36.853 7297 DEBUG oslo_concurrency.processutils [req-84dbb010-c105-4b5b-8d1d-41028c114307 tempest-VolumesV2SnapshotTestJSON-1508672341 tempest-VolumesV2SnapshotTestJSON-1508672341] CMD "getfattr
   -n quobyte.info /mnt/quobyte-volume/abfa1002557ab2b21ec218a86487dd92" returned: 0 in 0.021s execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:374
  2016-07-04 09:06:36.854 7297 DEBUG oslo_concurrency.lockutils [req-84dbb010-c105-4b5b-8d1d-41028c114307 tempest-VolumesV2SnapshotTestJSON-1508672341 tempest-VolumesV2SnapshotTestJSON-1508672341] Lock "connect_vo
  lume" released by "nova.virt.libvirt.volume.quobyte.connect_volume" :: held 1.232s inner /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:282
  2016-07-04 09:06:36.857 7297 DEBUG nova.virt.libvirt.guest [req-84dbb010-c105-4b5b-8d1d-41028c114307 tempest-VolumesV2SnapshotTestJSON-1508672341 tempest-VolumesV2SnapshotTestJSON-1508672341] attach device xml: 
  <disk type="file" device="disk">
    <driver name="qemu" type="qcow2" cache="none" io="native"/>
    <source file="/mnt/quobyte-volume/abfa1002557ab2b21ec218a86487dd92/volume-4604d6b5-cf47-4494-8833-15029e30a77e.f21ecc73-29a7-44c8-8f09-831e701569d2"/>
    <target bus="virtio" dev="vdb"/>
    <serial>4604d6b5-cf47-4494-8833-15029e30a77e</serial>
  </disk>
   attach_device /opt/stack/nova/nova/virt/libvirt/guest.py:251  
  2016-07-04 09:06:38.512 7297 ERROR nova.virt.libvirt.driver [req-84dbb010-c105-4b5b-8d1d-41028c114307 tempest-VolumesV2SnapshotTestJSON-1508672341 tempest-VolumesV2SnapshotTestJSON-1508672341] [instance: 0713aaa8-f630-4c7f-b541-616ce6541615] Failed to attach volume at mountpoint: /dev/vdb
  2016-07-04 09:06:38.512 7297 ERROR nova.virt.libvirt.driver [instance: 0713aaa8-f630-4c7f-b541-616ce6541615] Traceback (most recent call last):
  2016-07-04 09:06:38.512 7297 ERROR nova.virt.libvirt.driver [instance: 0713aaa8-f630-4c7f-b541-616ce6541615]   File "/opt/stack/nova/nova/virt/libvirt/driver.py", line 1232, in attach_volume
  2016-07-04 09:06:38.512 7297 ERROR nova.virt.libvirt.driver [instance: 0713aaa8-f630-4c7f-b541-616ce6541615]     guest.attach_device(conf, persistent=True, live=live)
  2016-07-04 09:06:38.512 7297 ERROR nova.virt.libvirt.driver [instance: 0713aaa8-f630-4c7f-b541-616ce6541615]   File "/opt/stack/nova/nova/virt/libvirt/guest.py", line 252, in attach_device
  2016-07-04 09:06:38.512 7297 ERROR nova.virt.libvirt.driver [instance: 0713aaa8-f630-4c7f-b541-616ce6541615]     self._domain.attachDeviceFlags(device_xml, flags=flags)
  2016-07-04 09:06:38.512 7297 ERROR nova.virt.libvirt.driver [instance: 0713aaa8-f630-4c7f-b541-616ce6541615]   File "/usr/local/lib/python2.7/dist-packages/eventlet/tpool.py", line 186, in doit
  2016-07-04 09:06:38.512 7297 ERROR nova.virt.libvirt.driver [instance: 0713aaa8-f630-4c7f-b541-616ce6541615]     result = proxy_call(self._autowrap, f, *args, **kwargs)
  2016-07-04 09:06:38.512 7297 ERROR nova.virt.libvirt.driver [instance: 0713aaa8-f630-4c7f-b541-616ce6541615]   File "/usr/local/lib/python2.7/dist-packages/eventlet/tpool.py", line 144, in proxy_call
  2016-07-04 09:06:38.512 7297 ERROR nova.virt.libvirt.driver [instance: 0713aaa8-f630-4c7f-b541-616ce6541615]     rv = execute(f, *args, **kwargs)
  2016-07-04 09:06:38.512 7297 ERROR nova.virt.libvirt.driver [instance: 0713aaa8-f630-4c7f-b541-616ce6541615]   File "/usr/local/lib/python2.7/dist-packages/eventlet/tpool.py", line 125, in execute
  2016-07-04 09:06:38.512 7297 ERROR nova.virt.libvirt.driver [instance: 0713aaa8-f630-4c7f-b541-616ce6541615]     six.reraise(c, e, tb)
  2016-07-04 09:06:38.512 7297 ERROR nova.virt.libvirt.driver [instance: 0713aaa8-f630-4c7f-b541-616ce6541615]   File "/usr/local/lib/python2.7/dist-packages/eventlet/tpool.py", line 83, in tworker
  2016-07-04 09:06:38.512 7297 ERROR nova.virt.libvirt.driver [instance: 0713aaa8-f630-4c7f-b541-616ce6541615]     rv = meth(*args, **kwargs)
  2016-07-04 09:06:38.512 7297 ERROR nova.virt.libvirt.driver [instance: 0713aaa8-f630-4c7f-b541-616ce6541615]   File "/usr/local/lib/python2.7/dist-packages/libvirt.py", line 517, in attachDeviceFlags
  2016-07-04 09:06:38.512 7297 ERROR nova.virt.libvirt.driver [instance: 0713aaa8-f630-4c7f-b541-616ce6541615]     if ret == -1: raise libvirtError ('virDomainAttachDeviceFlags() failed', dom=self)
  2016-07-04 09:06:38.512 7297 ERROR nova.virt.libvirt.driver [instance: 0713aaa8-f630-4c7f-b541-616ce6541615] libvirtError: operation failed: open disk image file failed
  2016-07-04 09:06:38.512 7297 ERROR nova.virt.libvirt.driver [instance: 0713aaa8-f630-4c7f-b541-616ce6541615] 
  2016-07-04 09:06:38.513 7297 DEBUG oslo_concurrency.lockutils [req-84dbb010-c105-4b5b-8d1d-41028c114307 tempest-VolumesV2SnapshotTestJSON-1508672341 tempest-VolumesV2SnapshotTestJSON-1508672341] Lock "connect_volume" acquired by "nova.virt.libvirt.volume.quobyte.disconnect_volume" :: waited 0.000s inner /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:270
  2016-07-04 09:06:38.514 7297 DEBUG oslo_concurrency.processutils [req-84dbb010-c105-4b5b-8d1d-41028c114307 tempest-VolumesV2SnapshotTestJSON-1508672341 tempest-VolumesV2SnapshotTestJSON-1508672341] Running cmd (subprocess): findmnt --target /mnt/quobyte-volume/abfa1002557ab2b21ec218a86487dd92 --source quobyte@78.46.57.153:7861/quobyteci_test_volume execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:344
  2016-07-04 09:06:38.520 7297 DEBUG oslo_concurrency.processutils [req-84dbb010-c105-4b5b-8d1d-41028c114307 tempest-VolumesV2SnapshotTestJSON-1508672341 tempest-VolumesV2SnapshotTestJSON-1508672341] CMD "findmnt --target /mnt/quobyte-volume/abfa1002557ab2b21ec218a86487dd92 --source quobyte@78.46.57.153:7861/quobyteci_test_volume" returned: 0 in 0.006s execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:374
  2016-07-04 09:06:38.521 7297 DEBUG oslo_concurrency.processutils [req-84dbb010-c105-4b5b-8d1d-41028c114307 tempest-VolumesV2SnapshotTestJSON-1508672341 tempest-VolumesV2SnapshotTestJSON-1508672341] Running cmd (subprocess): umount.quobyte /mnt/quobyte-volume/abfa1002557ab2b21ec218a86487dd92 execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:344


  libvirt daemon logs shows a permission denied error:
  2016-07-04 09:06:37.885+0000: 24010: debug : qemuSetupDiskPathAllow:60 : Process path /mnt/quobyte-volume/abfa1002557ab2b21ec218a86487dd92/volume-4604d6b5-cf47-4494-8833-15029e30a77e.2c3539c0-c6ed-4c72-8e65-6afd
  dda344df for disk
  2016-07-04 09:06:37.885+0000: 24010: debug : qemuSetupDiskPathAllow:60 : Process path /mnt/quobyte-volume/abfa1002557ab2b21ec218a86487dd92/volume-4604d6b5-cf47-4494-8833-15029e30a77e for disk
  2016-07-04 09:06:37.886+0000: 24010: debug : virCommandRunAsync:2282 : About to run /usr/lib/libvirt/virt-aa-helper -p 0 -r -u libvirt-0713aaa8-f630-4c7f-b541-616ce6541615 -f /mnt/quobyte-volume/abfa1002557ab2b2
  1ec218a86487dd92/volume-4604d6b5-cf47-4494-8833-15029e30a77e.f21ecc73-29a7-44c8-8f09-831e701569d2
  2016-07-04 09:06:37.886+0000: 24010: debug : virCommandRunAsync:2285 : Command result 0, with PID 15693
  2016-07-04 09:06:38.174+0000: 24010: debug : virCommandRun:2142 : Result status 0, stdout: '' stderr: ''
  2016-07-04 09:06:38.174+0000: 24010: debug : qemuDomainPCIAddressGetNextSlot:2270 : PCI slot 0000:00:01 already in use
  2016-07-04 09:06:38.174+0000: 24010: debug : qemuDomainPCIAddressGetNextSlot:2270 : PCI slot 0000:00:02 already in use
  2016-07-04 09:06:38.174+0000: 24010: debug : qemuDomainPCIAddressGetNextSlot:2270 : PCI slot 0000:00:03 already in use
  2016-07-04 09:06:38.174+0000: 24010: debug : qemuDomainPCIAddressGetNextSlot:2270 : PCI slot 0000:00:04 already in use
  2016-07-04 09:06:38.174+0000: 24010: debug : qemuDomainPCIAddressGetNextSlot:2313 : Found free PCI slot 0000:00:05
  2016-07-04 09:06:38.174+0000: 24010: debug : qemuDomainPCIAddressReserveAddr:2114 : Reserving PCI slot 0000:00:05.0 (multifunction='off')
  2016-07-04 09:06:38.174+0000: 24010: debug : qemuDomainObjEnterMonitorInternal:1278 : Entering monitor (mon=0x7f516c002820 vm=0x7f515c003540 name=instance-0000000f)
  2016-07-04 09:06:38.174+0000: 24010: debug : qemuMonitorAddDrive:3011 : mon=0x7f516c002820 drive=file=/mnt/quobyte-volume/abfa1002557ab2b21ec218a86487dd92/volume-4604d6b5-cf47-4494-8833-15029e30a77e.f21ecc73-29a
  7-44c8-8f09-831e701569d2,if=none,id=drive-virtio-disk1,format=qcow2,serial=4604d6b5-cf47-4494-8833-15029e30a77e,cache=none,aio=native
  2016-07-04 09:06:38.174+0000: 24010: debug : qemuMonitorJSONAddDrive:3126 : drive_add command not found, trying HMP
  2016-07-04 09:06:38.174+0000: 24010: debug : qemuMonitorJSONCommandWithFd:264 : Send command '{"execute":"human-monitor-command","arguments":{"command-line":"drive_add dummy file=/mnt/quobyte-volume/abfa1002557a
  b2b21ec218a86487dd92/volume-4604d6b5-cf47-4494-8833-15029e30a77e.f21ecc73-29a7-44c8-8f09-831e701569d2,if=none,id=drive-virtio-disk1,format=qcow2,serial=4604d6b5-cf47-4494-8833-15029e30a77e,cache=none,aio=native"
  },"id":"libvirt-16"}' for write with FD -1
  2016-07-04 09:06:38.174+0000: 24010: debug : qemuMonitorSend:959 : QEMU_MONITOR_SEND_MSG: mon=0x7f516c002820 msg={"execute":"human-monitor-command","arguments":{"command-line":"drive_add dummy file=/mnt/quobyte-
  volume/abfa1002557ab2b21ec218a86487dd92/volume-4604d6b5-cf47-4494-8833-15029e30a77e.f21ecc73-29a7-44c8-8f09-831e701569d2,if=none,id=drive-virtio-disk1,format=qcow2,serial=4604d6b5-cf47-4494-8833-15029e30a77e,cac
  he=none,aio=native"},"id":"libvirt-16"}
   fd=-1
  2016-07-04 09:06:38.176+0000: 24004: debug : qemuMonitorIOWrite:504 : QEMU_MONITOR_IO_WRITE: mon=0x7f516c002820 buf={"execute":"human-monitor-command","arguments":{"command-line":"drive_add dummy file=/mnt/quoby
  te-volume/abfa1002557ab2b21ec218a86487dd92/volume-4604d6b5-cf47-4494-8833-15029e30a77e.f21ecc73-29a7-44c8-8f09-831e701569d2,if=none,id=drive-virtio-disk1,format=qcow2,serial=4604d6b5-cf47-4494-8833-15029e30a77e,
  cache=none,aio=native"},"id":"libvirt-16"}
   len=350 ret=350 errno=11
  2016-07-04 09:06:38.244+0000: 24004: debug : qemuMonitorIOProcess:396 : QEMU_MONITOR_IO_PROCESS: mon=0x7f516c002820 buf={"return": "could not open disk image /mnt/quobyte-volume/abfa1002557ab2b21ec218a86487dd92/
  volume-4604d6b5-cf47-4494-8833-15029e30a77e.f21ecc73-29a7-44c8-8f09-831e701569d2: Could not open backing file: Could not open '/mnt/quobyte-volume/abfa1002557ab2b21ec218a86487dd92/volume-4604d6b5-cf47-4494-8833-
  15029e30a77e.2c3539c0-c6ed-4c72-8e65-6afddda344df': Permission denied\r\n", "id": "libvirt-16"}
   len=399
  2016-07-04 09:06:38.244+0000: 24004: debug : qemuMonitorJSONIOProcessLine:157 : Line [{"return": "could not open disk image /mnt/quobyte-volume/abfa1002557ab2b21ec218a86487dd92/volume-4604d6b5-cf47-4494-8833-150
  29e30a77e.f21ecc73-29a7-44c8-8f09-831e701569d2: Could not open backing file: Could not open '/mnt/quobyte-volume/abfa1002557ab2b21ec218a86487dd92/volume-4604d6b5-cf47-4494-8833-15029e30a77e.2c3539c0-c6ed-4c72-8e
  65-6afddda344df': Permission denied\r\n", "id": "libvirt-16"}]
  2016-07-04 09:06:38.244+0000: 24004: debug : qemuMonitorJSONIOProcessLine:177 : QEMU_MONITOR_RECV_REPLY: mon=0x7f516c002820 reply={"return": "could not open disk image /mnt/quobyte-volume/abfa1002557ab2b21ec218a
  86487dd92/volume-4604d6b5-cf47-4494-8833-15029e30a77e.f21ecc73-29a7-44c8-8f09-831e701569d2: Could not open backing file: Could not open '/mnt/quobyte-volume/abfa1002557ab2b21ec218a86487dd92/volume-4604d6b5-cf47-
  4494-8833-15029e30a77e.2c3539c0-c6ed-4c72-8e65-6afddda344df': Permission denied\r\n", "id": "libvirt-16"}
  2016-07-04 09:06:38.244+0000: 24004: debug : qemuMonitorJSONIOProcess:226 : Total used 399 bytes out of 399 available in buffer
  2016-07-04 09:06:38.244+0000: 24010: debug : qemuMonitorJSONCommandWithFd:269 : Receive command reply ret=0 rxObject=0x7f518cff16e0
  2016-07-04 09:06:38.244+0000: 24010: error : qemuMonitorTextAddDrive:2611 : operation failed: open disk image file failed
  2016-07-04 09:06:38.244+0000: 24010: debug : qemuDomainObjExitMonitorInternal:1301 : Exited monitor (mon=0x7f516c002820 vm=0x7f515c003540 name=instance-0000000f)
  2016-07-04 09:06:38.244+0000: 24010: debug : virCommandRunAsync:2282 : About to run /usr/lib/libvirt/virt-aa-helper -p 0 -r -u libvirt-0713aaa8-f630-4c7f-b541-616ce6541615
  2016-07-04 09:06:38.245+0000: 24010: debug : virCommandRunAsync:2285 : Command result 0, with PID 15695
  2016-07-04 09:06:38.511+0000: 24010: debug : virCommandRun:2142 : Result status 0, stdout: '' stderr: ''
  2016-07-04 09:06:38.512+0000: 24010: debug : qemuTeardownDiskPathDeny:102 : Process path /mnt/quobyte-volume/abfa1002557ab2b21ec218a86487dd92/volume-4604d6b5-cf47-4494-8833-15029e30a77e.f21ecc73-29a7-44c8-8f09-8
  31e701569d2 for disk
  2016-07-04 09:06:38.512+0000: 24010: debug : qemuTeardownDiskPathDeny:102 : Process path /mnt/quobyte-volume/abfa1002557ab2b21ec218a86487dd92/volume-4604d6b5-cf47-4494-8833-15029e30a77e.2c3539c0-c6ed-4c72-8e65-6
  afddda344df for disk
  2016-07-04 09:06:38.512+0000: 24010: debug : qemuTeardownDiskPathDeny:102 : Process path /mnt/quobyte-volume/abfa1002557ab2b21ec218a86487dd92/volume-4604d6b5-cf47-4494-8833-15029e30a77e for disk
  2016-07-04 09:06:38.512+0000: 24010: debug : qemuDomainObjEndJob:1206 : Stopping job: modify (async=none vm=0x7f515c003540 name=instance-0000000f)
  2016-07-04 09:06:38.512+0000: 24010: debug : virDomainFree:2270 : dom=0x7f517417e660, (VM: name=instance-0000000f, uuid=0713aaa8-f630-4c7f-b541-616ce6541615)
  2016-07-04 09:06:38.565+0000: 24004: debug : virNetlinkEventCallback:347 : dispatching to max 0 clients, called from event watch 6
  2016-07-04 09:06:38.565+0000: 24004: debug : virNetlinkEventCallback:360 : event not handled.
  2016-07-04 09:06:41.789+0000: 24004: debug : qemuMonitorIOProcess:396 : QEMU_MONITOR_IO_PROCESS: mon=0x7f516c002820 buf={"timestamp": {"seconds": 1467623201, "microseconds": 789082}, "event": "NIC_RX_FILTER_CHANGED", "data": {"name": "net0", "path": "/machine/peripheral/net0/virtio-backend"}}
   len=175

To manage notifications about this bug go to:
https://bugs.launchpad.net/nova/+bug/1598833/+subscriptions
Follow ups

[Bug 1598833] Re: Apparmor causes: libvirtError: operation failed: open disk image file failed during online snapshots via Nova API
From: Sean Dague, 2016-08-01