Public bug reported: This is happening on the latest master branch in CI systems. It happens very rarely in the gate:
http://logstash.openstack.org/#eyJzZWFyY2giOiJcImxpYnZpcnRFcnJvcjogb3BlcmF0aW9uIGZhaWxlZDogb3BlbiBkaXNrIGltYWdlIGZpbGUgZmFpbGVkXCIiLCJmaWVsZHMiOltdLCJvZmZzZXQiOjAsInRpbWVmcmFtZSI6IjYwNDgwMCIsImdyYXBobW9kZSI6ImNvdW50IiwidGltZSI6eyJ1c2VyX2ludGVydmFsIjowfSwic3RhbXAiOjE0NDIyNjY3MDU1NzZ9 And on some third party CI systems (not included in the logstash results): http://ec2-54-67-51-189.us- west-1.compute.amazonaws.com/28/216728/5/check/PureFCDriver-tempest- dsvm-volume- multipath/bd3618d/logs/libvirt/libvirtd.txt.gz#_2015-09-14_09_00_44_829 When the error occurs there is a stack trace in the n-cpu log like this: http://logs.openstack.org/22/222922/2/check/gate-tempest-dsvm-full- lio/550be5e/logs/screen-n-cpu.txt.gz?level=DEBUG#_2015-09-13_17_34_07_787 2015-09-13 17:34:07.787 ERROR nova.virt.libvirt.driver [req-4ac04f97-f468-466a-9fb2-02d1df3a5633 tempest-TestEncryptedCinderVolumes-1564844141 tempest-TestEncryptedCinderVolumes-804461249] [instance: 82f33247-d8be-49c7-9f89-f02602de5ef6] Failed to attach volume at mountpoint: /dev/vdb 2015-09-13 17:34:07.787 22300 ERROR nova.virt.libvirt.driver [instance: 82f33247-d8be-49c7-9f89-f02602de5ef6] Traceback (most recent call last): 2015-09-13 17:34:07.787 22300 ERROR nova.virt.libvirt.driver [instance: 82f33247-d8be-49c7-9f89-f02602de5ef6] File "/opt/stack/new/nova/nova/virt/libvirt/driver.py", line 1115, in attach_volume 2015-09-13 17:34:07.787 22300 ERROR nova.virt.libvirt.driver [instance: 82f33247-d8be-49c7-9f89-f02602de5ef6] guest.attach_device(conf, persistent=True, live=live) 2015-09-13 17:34:07.787 22300 ERROR nova.virt.libvirt.driver [instance: 82f33247-d8be-49c7-9f89-f02602de5ef6] File "/opt/stack/new/nova/nova/virt/libvirt/guest.py", line 233, in attach_device 2015-09-13 17:34:07.787 22300 ERROR nova.virt.libvirt.driver [instance: 82f33247-d8be-49c7-9f89-f02602de5ef6] self._domain.attachDeviceFlags(conf.to_xml(), flags=flags) 2015-09-13 17:34:07.787 22300 ERROR nova.virt.libvirt.driver [instance: 82f33247-d8be-49c7-9f89-f02602de5ef6] File "/usr/local/lib/python2.7/dist-packages/eventlet/tpool.py", line 183, in doit 2015-09-13 17:34:07.787 22300 ERROR nova.virt.libvirt.driver [instance: 82f33247-d8be-49c7-9f89-f02602de5ef6] result = proxy_call(self._autowrap, f, *args, **kwargs) 2015-09-13 17:34:07.787 22300 ERROR nova.virt.libvirt.driver [instance: 82f33247-d8be-49c7-9f89-f02602de5ef6] File "/usr/local/lib/python2.7/dist-packages/eventlet/tpool.py", line 141, in proxy_call 2015-09-13 17:34:07.787 22300 ERROR nova.virt.libvirt.driver [instance: 82f33247-d8be-49c7-9f89-f02602de5ef6] rv = execute(f, *args, **kwargs) 2015-09-13 17:34:07.787 22300 ERROR nova.virt.libvirt.driver [instance: 82f33247-d8be-49c7-9f89-f02602de5ef6] File "/usr/local/lib/python2.7/dist-packages/eventlet/tpool.py", line 122, in execute 2015-09-13 17:34:07.787 22300 ERROR nova.virt.libvirt.driver [instance: 82f33247-d8be-49c7-9f89-f02602de5ef6] six.reraise(c, e, tb) 2015-09-13 17:34:07.787 22300 ERROR nova.virt.libvirt.driver [instance: 82f33247-d8be-49c7-9f89-f02602de5ef6] File "/usr/local/lib/python2.7/dist-packages/eventlet/tpool.py", line 80, in tworker 2015-09-13 17:34:07.787 22300 ERROR nova.virt.libvirt.driver [instance: 82f33247-d8be-49c7-9f89-f02602de5ef6] rv = meth(*args, **kwargs) 2015-09-13 17:34:07.787 22300 ERROR nova.virt.libvirt.driver [instance: 82f33247-d8be-49c7-9f89-f02602de5ef6] File "/usr/local/lib/python2.7/dist-packages/libvirt.py", line 517, in attachDeviceFlags 2015-09-13 17:34:07.787 22300 ERROR nova.virt.libvirt.driver [instance: 82f33247-d8be-49c7-9f89-f02602de5ef6] if ret == -1: raise libvirtError ('virDomainAttachDeviceFlags() failed', dom=self) 2015-09-13 17:34:07.787 22300 ERROR nova.virt.libvirt.driver [instance: 82f33247-d8be-49c7-9f89-f02602de5ef6] libvirtError: operation failed: open disk image file failed 2015-09-13 17:34:07.787 22300 ERROR nova.virt.libvirt.driver [instance: 82f33247-d8be-49c7-9f89-f02602de5ef6] and a corresponding error in the libvirt log such as this: http://logs.openstack.org/22/222922/2/check/gate-tempest-dsvm-full- lio/550be5e/logs/libvirt/libvirtd.txt.gz#_2015-09-13_17_34_07_499 2015-09-13 17:34:07.496+0000: 16871: debug : qemuMonitorJSONCommandWithFd:264 : Send command '{"execute":"human-monitor-command","arguments":{"command-line":"drive_add dummy file=/dev/disk/by-path/ip-172.99.112.13:3260-iscsi-iqn.2010-10.org.openstack:volume-561640e9-081a-430b-a7f8-9cadd63d2d00-lun-0,if=none,id=drive-virtio-disk1,format=raw,serial=561640e9-081a-430b-a7f8-9cadd63d2d00,cache=none"},"id":"libvirt-16"}' for write with FD -1 2015-09-13 17:34:07.496+0000: 16871: debug : qemuMonitorSend:959 : QEMU_MONITOR_SEND_MSG: mon=0x7f50dc008db0 msg={"execute":"human-monitor-command","arguments":{"command-line":"drive_add dummy file=/dev/disk/by-path/ip-172.99.112.13:3260-iscsi-iqn.2010-10.org.openstack:volume-561640e9-081a-430b-a7f8-9cadd63d2d00-lun-0,if=none,id=drive-virtio-disk1,format=raw,serial=561640e9-081a-430b-a7f8-9cadd63d2d00,cache=none"},"id":"libvirt-16"} fd=-1 2015-09-13 17:34:07.496+0000: 16868: debug : qemuMonitorIOWrite:504 : QEMU_MONITOR_IO_WRITE: mon=0x7f50dc008db0 buf={"execute":"human-monitor-command","arguments":{"command-line":"drive_add dummy file=/dev/disk/by-path/ip-172.99.112.13:3260-iscsi-iqn.2010-10.org.openstack:volume-561640e9-081a-430b-a7f8-9cadd63d2d00-lun-0,if=none,id=drive-virtio-disk1,format=raw,serial=561640e9-081a-430b-a7f8-9cadd63d2d00,cache=none"},"id":"libvirt-16"} len=325 ret=325 errno=22 2015-09-13 17:34:07.499+0000: 16868: debug : qemuMonitorIOProcess:396 : QEMU_MONITOR_IO_PROCESS: mon=0x7f50dc008db0 buf={"return": "could not open disk image /dev/disk/by-path/ip-172.99.112.13:3260-iscsi-iqn.2010-10.org.openstack:volume-561640e9-081a-430b-a7f8-9cadd63d2d00-lun-0: Could not open '/dev/disk/by-path/ip-172.99.112.13:3260-iscsi-iqn.2010-10.org.openstack:volume-561640e9-081a-430b-a7f8-9cadd63d2d00-lun-0': Operation not permitted\r\n", "id": "libvirt-16"} len=352 2015-09-13 17:34:07.499+0000: 16868: debug : qemuMonitorJSONIOProcessLine:157 : Line [{"return": "could not open disk image /dev/disk/by-path/ip-172.99.112.13:3260-iscsi-iqn.2010-10.org.openstack:volume-561640e9-081a-430b-a7f8-9cadd63d2d00-lun-0: Could not open '/dev/disk/by-path/ip-172.99.112.13:3260-iscsi-iqn.2010-10.org.openstack:volume-561640e9-081a-430b-a7f8-9cadd63d2d00-lun-0': Operation not permitted\r\n", "id": "libvirt-16"}] 2015-09-13 17:34:07.499+0000: 16868: debug : qemuMonitorJSONIOProcessLine:177 : QEMU_MONITOR_RECV_REPLY: mon=0x7f50dc008db0 reply={"return": "could not open disk image /dev/disk/by-path/ip-172.99.112.13:3260-iscsi-iqn.2010-10.org.openstack:volume-561640e9-081a-430b-a7f8-9cadd63d2d00-lun-0: Could not open '/dev/disk/by-path/ip-172.99.112.13:3260-iscsi-iqn.2010-10.org.openstack:volume-561640e9-081a-430b-a7f8-9cadd63d2d00-lun-0': Operation not permitted\r\n", "id": "libvirt-16"} 2015-09-13 17:34:07.499+0000: 16868: debug : qemuMonitorJSONIOProcess:226 : Total used 352 bytes out of 352 available in buffer 2015-09-13 17:34:07.499+0000: 16871: debug : qemuMonitorJSONCommandWithFd:269 : Receive command reply ret=0 rxObject=0x7f511026bfc0 2015-09-13 17:34:07.499+0000: 16871: error : qemuMonitorTextAddDrive:2611 : operation failed: open disk image file failed 2015-09-13 17:34:07.499+0000: 16871: debug : qemuDomainObjExitMonitorInternal:1301 : Exited monitor (mon=0x7f50dc008db0 vm=0x7f50f81661f0 name=instance-00000057) It is unclear yet what causes this to occur. It has reproduced in several different tempest tests. ** Affects: cinder Importance: Undecided Status: New ** Affects: nova Importance: Undecided Status: New ** Also affects: cinder Importance: Undecided Status: New -- 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/1495701 Title: Sometimes Cinder volumes fail to attach with error "The device is not writable: Permission denied" Status in Cinder: New Status in OpenStack Compute (nova): New Bug description: This is happening on the latest master branch in CI systems. It happens very rarely in the gate: http://logstash.openstack.org/#eyJzZWFyY2giOiJcImxpYnZpcnRFcnJvcjogb3BlcmF0aW9uIGZhaWxlZDogb3BlbiBkaXNrIGltYWdlIGZpbGUgZmFpbGVkXCIiLCJmaWVsZHMiOltdLCJvZmZzZXQiOjAsInRpbWVmcmFtZSI6IjYwNDgwMCIsImdyYXBobW9kZSI6ImNvdW50IiwidGltZSI6eyJ1c2VyX2ludGVydmFsIjowfSwic3RhbXAiOjE0NDIyNjY3MDU1NzZ9 And on some third party CI systems (not included in the logstash results): http://ec2-54-67-51-189.us- west-1.compute.amazonaws.com/28/216728/5/check/PureFCDriver-tempest- dsvm-volume- multipath/bd3618d/logs/libvirt/libvirtd.txt.gz#_2015-09-14_09_00_44_829 When the error occurs there is a stack trace in the n-cpu log like this: http://logs.openstack.org/22/222922/2/check/gate-tempest-dsvm-full- lio/550be5e/logs/screen-n-cpu.txt.gz?level=DEBUG#_2015-09-13_17_34_07_787 2015-09-13 17:34:07.787 ERROR nova.virt.libvirt.driver [req-4ac04f97-f468-466a-9fb2-02d1df3a5633 tempest-TestEncryptedCinderVolumes-1564844141 tempest-TestEncryptedCinderVolumes-804461249] [instance: 82f33247-d8be-49c7-9f89-f02602de5ef6] Failed to attach volume at mountpoint: /dev/vdb 2015-09-13 17:34:07.787 22300 ERROR nova.virt.libvirt.driver [instance: 82f33247-d8be-49c7-9f89-f02602de5ef6] Traceback (most recent call last): 2015-09-13 17:34:07.787 22300 ERROR nova.virt.libvirt.driver [instance: 82f33247-d8be-49c7-9f89-f02602de5ef6] File "/opt/stack/new/nova/nova/virt/libvirt/driver.py", line 1115, in attach_volume 2015-09-13 17:34:07.787 22300 ERROR nova.virt.libvirt.driver [instance: 82f33247-d8be-49c7-9f89-f02602de5ef6] guest.attach_device(conf, persistent=True, live=live) 2015-09-13 17:34:07.787 22300 ERROR nova.virt.libvirt.driver [instance: 82f33247-d8be-49c7-9f89-f02602de5ef6] File "/opt/stack/new/nova/nova/virt/libvirt/guest.py", line 233, in attach_device 2015-09-13 17:34:07.787 22300 ERROR nova.virt.libvirt.driver [instance: 82f33247-d8be-49c7-9f89-f02602de5ef6] self._domain.attachDeviceFlags(conf.to_xml(), flags=flags) 2015-09-13 17:34:07.787 22300 ERROR nova.virt.libvirt.driver [instance: 82f33247-d8be-49c7-9f89-f02602de5ef6] File "/usr/local/lib/python2.7/dist-packages/eventlet/tpool.py", line 183, in doit 2015-09-13 17:34:07.787 22300 ERROR nova.virt.libvirt.driver [instance: 82f33247-d8be-49c7-9f89-f02602de5ef6] result = proxy_call(self._autowrap, f, *args, **kwargs) 2015-09-13 17:34:07.787 22300 ERROR nova.virt.libvirt.driver [instance: 82f33247-d8be-49c7-9f89-f02602de5ef6] File "/usr/local/lib/python2.7/dist-packages/eventlet/tpool.py", line 141, in proxy_call 2015-09-13 17:34:07.787 22300 ERROR nova.virt.libvirt.driver [instance: 82f33247-d8be-49c7-9f89-f02602de5ef6] rv = execute(f, *args, **kwargs) 2015-09-13 17:34:07.787 22300 ERROR nova.virt.libvirt.driver [instance: 82f33247-d8be-49c7-9f89-f02602de5ef6] File "/usr/local/lib/python2.7/dist-packages/eventlet/tpool.py", line 122, in execute 2015-09-13 17:34:07.787 22300 ERROR nova.virt.libvirt.driver [instance: 82f33247-d8be-49c7-9f89-f02602de5ef6] six.reraise(c, e, tb) 2015-09-13 17:34:07.787 22300 ERROR nova.virt.libvirt.driver [instance: 82f33247-d8be-49c7-9f89-f02602de5ef6] File "/usr/local/lib/python2.7/dist-packages/eventlet/tpool.py", line 80, in tworker 2015-09-13 17:34:07.787 22300 ERROR nova.virt.libvirt.driver [instance: 82f33247-d8be-49c7-9f89-f02602de5ef6] rv = meth(*args, **kwargs) 2015-09-13 17:34:07.787 22300 ERROR nova.virt.libvirt.driver [instance: 82f33247-d8be-49c7-9f89-f02602de5ef6] File "/usr/local/lib/python2.7/dist-packages/libvirt.py", line 517, in attachDeviceFlags 2015-09-13 17:34:07.787 22300 ERROR nova.virt.libvirt.driver [instance: 82f33247-d8be-49c7-9f89-f02602de5ef6] if ret == -1: raise libvirtError ('virDomainAttachDeviceFlags() failed', dom=self) 2015-09-13 17:34:07.787 22300 ERROR nova.virt.libvirt.driver [instance: 82f33247-d8be-49c7-9f89-f02602de5ef6] libvirtError: operation failed: open disk image file failed 2015-09-13 17:34:07.787 22300 ERROR nova.virt.libvirt.driver [instance: 82f33247-d8be-49c7-9f89-f02602de5ef6] and a corresponding error in the libvirt log such as this: http://logs.openstack.org/22/222922/2/check/gate-tempest-dsvm-full- lio/550be5e/logs/libvirt/libvirtd.txt.gz#_2015-09-13_17_34_07_499 2015-09-13 17:34:07.496+0000: 16871: debug : qemuMonitorJSONCommandWithFd:264 : Send command '{"execute":"human-monitor-command","arguments":{"command-line":"drive_add dummy file=/dev/disk/by-path/ip-172.99.112.13:3260-iscsi-iqn.2010-10.org.openstack:volume-561640e9-081a-430b-a7f8-9cadd63d2d00-lun-0,if=none,id=drive-virtio-disk1,format=raw,serial=561640e9-081a-430b-a7f8-9cadd63d2d00,cache=none"},"id":"libvirt-16"}' for write with FD -1 2015-09-13 17:34:07.496+0000: 16871: debug : qemuMonitorSend:959 : QEMU_MONITOR_SEND_MSG: mon=0x7f50dc008db0 msg={"execute":"human-monitor-command","arguments":{"command-line":"drive_add dummy file=/dev/disk/by-path/ip-172.99.112.13:3260-iscsi-iqn.2010-10.org.openstack:volume-561640e9-081a-430b-a7f8-9cadd63d2d00-lun-0,if=none,id=drive-virtio-disk1,format=raw,serial=561640e9-081a-430b-a7f8-9cadd63d2d00,cache=none"},"id":"libvirt-16"} fd=-1 2015-09-13 17:34:07.496+0000: 16868: debug : qemuMonitorIOWrite:504 : QEMU_MONITOR_IO_WRITE: mon=0x7f50dc008db0 buf={"execute":"human-monitor-command","arguments":{"command-line":"drive_add dummy file=/dev/disk/by-path/ip-172.99.112.13:3260-iscsi-iqn.2010-10.org.openstack:volume-561640e9-081a-430b-a7f8-9cadd63d2d00-lun-0,if=none,id=drive-virtio-disk1,format=raw,serial=561640e9-081a-430b-a7f8-9cadd63d2d00,cache=none"},"id":"libvirt-16"} len=325 ret=325 errno=22 2015-09-13 17:34:07.499+0000: 16868: debug : qemuMonitorIOProcess:396 : QEMU_MONITOR_IO_PROCESS: mon=0x7f50dc008db0 buf={"return": "could not open disk image /dev/disk/by-path/ip-172.99.112.13:3260-iscsi-iqn.2010-10.org.openstack:volume-561640e9-081a-430b-a7f8-9cadd63d2d00-lun-0: Could not open '/dev/disk/by-path/ip-172.99.112.13:3260-iscsi-iqn.2010-10.org.openstack:volume-561640e9-081a-430b-a7f8-9cadd63d2d00-lun-0': Operation not permitted\r\n", "id": "libvirt-16"} len=352 2015-09-13 17:34:07.499+0000: 16868: debug : qemuMonitorJSONIOProcessLine:157 : Line [{"return": "could not open disk image /dev/disk/by-path/ip-172.99.112.13:3260-iscsi-iqn.2010-10.org.openstack:volume-561640e9-081a-430b-a7f8-9cadd63d2d00-lun-0: Could not open '/dev/disk/by-path/ip-172.99.112.13:3260-iscsi-iqn.2010-10.org.openstack:volume-561640e9-081a-430b-a7f8-9cadd63d2d00-lun-0': Operation not permitted\r\n", "id": "libvirt-16"}] 2015-09-13 17:34:07.499+0000: 16868: debug : qemuMonitorJSONIOProcessLine:177 : QEMU_MONITOR_RECV_REPLY: mon=0x7f50dc008db0 reply={"return": "could not open disk image /dev/disk/by-path/ip-172.99.112.13:3260-iscsi-iqn.2010-10.org.openstack:volume-561640e9-081a-430b-a7f8-9cadd63d2d00-lun-0: Could not open '/dev/disk/by-path/ip-172.99.112.13:3260-iscsi-iqn.2010-10.org.openstack:volume-561640e9-081a-430b-a7f8-9cadd63d2d00-lun-0': Operation not permitted\r\n", "id": "libvirt-16"} 2015-09-13 17:34:07.499+0000: 16868: debug : qemuMonitorJSONIOProcess:226 : Total used 352 bytes out of 352 available in buffer 2015-09-13 17:34:07.499+0000: 16871: debug : qemuMonitorJSONCommandWithFd:269 : Receive command reply ret=0 rxObject=0x7f511026bfc0 2015-09-13 17:34:07.499+0000: 16871: error : qemuMonitorTextAddDrive:2611 : operation failed: open disk image file failed 2015-09-13 17:34:07.499+0000: 16871: debug : qemuDomainObjExitMonitorInternal:1301 : Exited monitor (mon=0x7f50dc008db0 vm=0x7f50f81661f0 name=instance-00000057) It is unclear yet what causes this to occur. It has reproduced in several different tempest tests. To manage notifications about this bug go to: https://bugs.launchpad.net/cinder/+bug/1495701/+subscriptions -- Mailing list: https://launchpad.net/~yahoo-eng-team Post to : yahoo-eng-team@lists.launchpad.net Unsubscribe : https://launchpad.net/~yahoo-eng-team More help : https://help.launchpad.net/ListHelp
