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 [email protected]: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 [email protected]: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 [email protected]: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 [email protected]: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 [email protected]: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 [email protected]: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 -- Mailing list: https://launchpad.net/~yahoo-eng-team Post to : [email protected] Unsubscribe : https://launchpad.net/~yahoo-eng-team More help : https://help.launchpad.net/ListHelp
