I don't think this is really a nova issue, apparmor config is beyond the
project scope.
** Changed in: nova
Status: New => Won't Fix
--
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:
Apparmor causes: libvirtError: operation failed: open disk image file
failed during online snapshots via Nova API
Status in OpenStack Compute (nova):
Won't Fix
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
