← Back to team overview

yahoo-eng-team team mailing list archive

  1. yahoo-eng-team team
  2. Mailing list archive
  3. Message #38478

[Bug 1495701] [NEW] Sometimes Cinder volumes fail to attach with error "The device is not writable: Permission denied"

  Thread Previous • Date Previous • • Thread Next 
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

Follow ups

  Thread Previous • Date Previous • • Thread Next