| 2015-09-14 21:49:16 |
Patrick East |
bug |
|
|
added bug |
| 2015-09-14 21:49:59 |
Patrick East |
bug task added |
|
cinder |
|
| 2015-09-15 00:55:49 |
Koji Iida |
bug |
|
|
added subscriber Koji Iida |
| 2015-09-17 15:13:38 |
Markus Zoeller (markus_z) |
tags |
|
fibre-channel libvirt multipath volumes |
|
| 2015-09-29 20:42:27 |
Patrick East |
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. |
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-193-96-24.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. |
|
| 2015-09-30 12:05:10 |
Pawel Koniszewski |
bug |
|
|
added subscriber Pawel Koniszewski |
| 2015-09-30 12:05:23 |
Pawel Koniszewski |
removed subscriber Pawel Koniszewski |
|
|
|
| 2015-09-30 20:10:57 |
Patrick East |
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-193-96-24.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. |
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-52-8-200-217.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. |
|
| 2015-10-15 17:43:45 |
Patrick East |
bug task added |
|
os-brick |
|
| 2015-10-15 18:36:41 |
Patrick East |
os-brick: assignee |
|
Patrick East (patrick-east) |
|
| 2015-10-18 00:21:39 |
OpenStack Infra |
os-brick: status |
New |
In Progress |
|
| 2015-10-30 05:42:45 |
OpenStack Infra |
tags |
fibre-channel libvirt multipath volumes |
fibre-channel in-stable-liberty libvirt multipath volumes |
|
| 2015-11-06 17:44:12 |
Scott DAngelo |
bug |
|
|
added subscriber Scott DAngelo |
| 2016-02-08 22:35:40 |
Augustina Ragwitz |
nova: status |
New |
Confirmed |
|
| 2016-07-14 09:57:52 |
John Garbutt |
nova: status |
Confirmed |
Incomplete |
|
| 2016-10-12 18:14:58 |
Sean McGinnis |
nova: status |
Incomplete |
Invalid |
|
| 2016-10-12 18:15:09 |
Sean McGinnis |
os-brick: status |
In Progress |
Fix Released |
|
| 2016-10-12 18:15:17 |
Sean McGinnis |
cinder: status |
New |
Invalid |
|
