Libvirt error when trying to mount ISCSI volumes

[rfz]

Binary package hint: libvirt-bin
1. Release:
DISTRIB_ID=Ubuntu
DISTRIB_RELEASE=12.04
DISTRIB_CODENAME=precise
DISTRIB_DESCRIPTION="Ubuntu 12.04 LTS"

2. Policies:

libvirt-bin:
  Installed: 0.9.8-2ubuntu17
  Candidate: 0.9.8-2ubuntu17
  Version table:
 *** 0.9.8-2ubuntu17 0
        500 http://br.archive.ubuntu.com/ubuntu/ precise/main amd64 Packages
        100 /var/lib/dpkg/status

nova-volume:
  Installed: 2012.1-0ubuntu2.1
  Candidate: 2012.1-0ubuntu2.1
  Version table:
 *** 2012.1-0ubuntu2.1 0
        500 http://br.archive.ubuntu.com/ubuntu/ precise-updates/main amd64 Packages
        500 http://security.ubuntu.com/ubuntu/ precise-security/main amd64 Packages
        100 /var/lib/dpkg/status
     2012.1-0ubuntu2 0
        500 http://br.archive.ubuntu.com/ubuntu/ precise/main amd64 Packages

tgt:
  Installed: 1:1.0.17-1ubuntu2
  Candidate: 1:1.0.17-1ubuntu2
  Version table:
 *** 1:1.0.17-1ubuntu2 0
        500 http://br.archive.ubuntu.com/ubuntu/ precise/main amd64 Packages
        100 /var/lib/dpkg/status

3. Problem: Using both iscsiadm CLI and Openstack’s nova-volume, mounting ISCSI volumes fail with error: qemuMonitorIOProcess:356 : QEMU_MONITOR_IO_PROCESS: mon=0x7f242c000a80 buf={"id": "libvirt-7", "error": {"class": "CommandNotFound", "desc": "The command drive_add has not been found", "data": {"name": "drive_add"}}}

libvirtd_trace_log:

2012-05-08 22:36:22.342+0000: 10381: debug : virNetMessageEncodePayload:351 : Encode length as 3952
2012-05-08 22:36:22.342+0000: 10381: debug : virNetServerClientSendMessage:1106 : msg=0xb5d930 proc=7 len=3952 offset=0
2012-05-08 22:36:22.342+0000: 10381: debug : virNetServerClientSendMessage:1116 : RPC_SERVER_CLIENT_MSG_TX_QUEUE: client=0xb1d7e0 len=3952 prog=536903814 vers=1 proc=7 type=1 status=0 serial=53
2012-05-08 22:36:22.342+0000: 10381: debug : virNetServerClientCalculateHandleMode:137 : tls=(nil) hs=-1, rx=0xb1d8c0 tx=0xb5d930
2012-05-08 22:36:22.342+0000: 10381: debug : virNetServerClientCalculateHandleMode:167 : mode=3
2012-05-08 22:36:22.342+0000: 10381: debug : virEventPollUpdateHandle:151 : EVENT_POLL_UPDATE_HANDLE: watch=10 events=3
2012-05-08 22:36:22.342+0000: 10381: debug : virEventPollInterruptLocked:706 : Interrupting
2012-05-08 22:36:22.342+0000: 10381: debug : virNetServerProgramFree:527 : prog=0xb173c0 refs=3
2012-05-08 22:36:22.342+0000: 10381: debug : virNetServerClientFree:591 : RPC_SERVER_CLIENT_FREE: client=0xb1d7e0 refs=4
2012-05-08 22:36:22.342+0000: 10380: debug : virEventPollRunOnce:630 : Poll got 1 event(s)
2012-05-08 22:36:22.342+0000: 10380: debug : virEventPollDispatchTimeouts:415 : Dispatch 6
2012-05-08 22:36:22.343+0000: 10380: debug : virEventPollDispatchHandles:460 : Dispatch 10
2012-05-08 22:36:22.343+0000: 10380: debug : virEventPollDispatchHandles:474 : i=0 w=1
2012-05-08 22:36:22.343+0000: 10380: debug : virEventPollDispatchHandles:488 : EVENT_POLL_DISPATCH_HANDLE: watch=1 events=1
2012-05-08 22:36:22.343+0000: 10380: debug : virEventPollDispatchHandles:474 : i=1 w=2
2012-05-08 22:36:22.343+0000: 10380: debug : virEventPollDispatchHandles:474 : i=2 w=3
2012-05-08 22:36:22.343+0000: 10380: debug : virEventPollDispatchHandles:474 : i=3 w=4
2012-05-08 22:36:22.343+0000: 10380: debug : virEventPollDispatchHandles:474 : i=4 w=5
2012-05-08 22:36:22.343+0000: 10380: debug : virEventPollDispatchHandles:474 : i=5 w=6
2012-05-08 22:36:22.343+0000: 10380: debug : virEventPollDispatchHandles:474 : i=6 w=7
2012-05-08 22:36:22.343+0000: 10380: debug : virEventPollDispatchHandles:474 : i=7 w=8
2012-05-08 22:36:22.343+0000: 10380: debug : virEventPollDispatchHandles:474 : i=8 w=9
2012-05-08 22:36:22.343+0000: 10380: debug : virEventPollDispatchHandles:474 : i=9 w=10
2012-05-08 22:36:22.343+0000: 10380: debug : virEventPollCleanupTimeouts:506 : Cleanup 6
2012-05-08 22:36:22.343+0000: 10380: debug : virEventPollCleanupHandles:554 : Cleanup 10
2012-05-08 22:36:22.343+0000: 10380: debug : virEventRunDefaultImpl:244 : running default event implementation
2012-05-08 22:36:22.343+0000: 10380: debug : virEventPollCleanupTimeouts:506 : Cleanup 6
2012-05-08 22:36:22.343+0000: 10380: debug : virEventPollCleanupHandles:554 : Cleanup 10
2012-05-08 22:36:22.343+0000: 10380: debug : virEventPollMakePollFDs:383 : Prepare n=0 w=1, f=7 e=1 d=0
2012-05-08 22:36:22.343+0000: 10380: debug : virEventPollMakePollFDs:383 : Prepare n=1 w=2, f=9 e=1 d=0
2012-05-08 22:36:22.343+0000: 10380: debug : virEventPollMakePollFDs:383 : Prepare n=2 w=3, f=11 e=1 d=0
2012-05-08 22:36:22.343+0000: 10380: debug : virEventPollMakePollFDs:383 : Prepare n=3 w=4, f=12 e=1 d=0
2012-05-08 22:36:22.343+0000: 10380: debug : virEventPollMakePollFDs:383 : Prepare n=4 w=5, f=6 e=1 d=0
2012-05-08 22:36:22.343+0000: 10380: debug : virEventPollMakePollFDs:383 : Prepare n=5 w=6, f=14 e=1 d=0
2012-05-08 22:36:22.343+0000: 10380: debug : virEventPollMakePollFDs:383 : Prepare n=6 w=7, f=15 e=25 d=0
2012-05-08 22:36:22.343+0000: 10380: debug : virEventPollMakePollFDs:383 : Prepare n=7 w=8, f=16 e=25 d=0
2012-05-08 22:36:22.343+0000: 10380: debug : virEventPollMakePollFDs:383 : Prepare n=8 w=9, f=17 e=1 d=0
2012-05-08 22:36:22.343+0000: 10380: debug : virEventPollMakePollFDs:383 : Prepare n=9 w=10, f=18 e=5 d=0
2012-05-08 22:36:22.343+0000: 10380: debug : virEventPollCalculateTimeout:325 : Calculate expiry of 6 timers
2012-05-08 22:36:22.343+0000: 10380: debug : virEventPollCalculateTimeout:351 : Timeout at 0 due in -1 ms
2012-05-08 22:36:22.343+0000: 10380: debug : virEventPollRunOnce:619 : EVENT_POLL_RUN: nhandles=10 imeout=-1
2012-05-08 22:36:22.343+0000: 10380: debug : virEventPollRunOnce:630 : Poll got 1 event(s)
2012-05-08 22:36:22.343+0000: 10380: debug : virEventPollDispatchTimeouts:415 : Dispatch 6
2012-05-08 22:36:22.343+0000: 10380: debug : virEventPollDispatchHandles:460 : Dispatch 10
2012-05-08 22:36:22.343+0000: 10380: debug : virEventPollDispatchHandles:474 : i=0 w=1
2012-05-08 22:36:22.343+0000: 10380: debug : virEventPollDispatchHandles:474 : i=1 w=2
2012-05-08 22:36:22.343+0000: 10380: debug : virEventPollDispatchHandles:474 : i=2 w=3
2012-05-08 22:36:22.343+0000: 10380: debug : virEventPollDispatchHandles:474 : i=3 w=4
2012-05-08 22:36:22.343+0000: 10380: debug : virEventPollDispatchHandles:474 : i=4 w=5
2012-05-08 22:36:22.343+0000: 10380: debug : virEventPollDispatchHandles:474 : i=5 w=6
2012-05-08 22:36:22.343+0000: 10380: debug : virEventPollDispatchHandles:474 : i=6 w=7
2012-05-08 22:36:22.343+0000: 10380: debug : virEventPollDispatchHandles:474 : i=7 w=8
2012-05-08 22:36:22.343+0000: 10380: debug : virEventPollDispatchHandles:474 : i=8 w=9
2012-05-08 22:36:22.343+0000: 10380: debug : virEventPollDispatchHandles:474 : i=9 w=10
2012-05-08 22:36:22.343+0000: 10380: debug : virEventPollDispatchHandles:488 : EVENT_POLL_DISPATCH_HANDLE: watch=10 events=2
2012-05-08 22:36:22.343+0000: 10380: debug : virNetMessageFree:75 : msg=0xb5d930 nfds=0 cb=(nil)
2012-05-08 22:36:22.343+0000: 10380: debug : virNetServerClientCalculateHandleMode:137 : tls=(nil) hs=-1, rx=0xb1d8c0 tx=(nil)
2012-05-08 22:36:22.343+0000: 10380: debug : virNetServerClientCalculateHandleMode:167 : mode=1
2012-05-08 22:36:22.343+0000: 10380: debug : virEventPollUpdateHandle:151 : EVENT_POLL_UPDATE_HANDLE: watch=10 events=1
2012-05-08 22:36:22.343+0000: 10380: debug : virEventPollInterruptLocked:702 : Skip interrupt, 1 1116432448
2012-05-08 22:36:22.343+0000: 10380: debug : virEventPollCleanupTimeouts:506 : Cleanup 6
2012-05-08 22:36:22.343+0000: 10380: debug : virEventPollCleanupHandles:554 : Cleanup 10
2012-05-08 22:36:22.343+0000: 10380: debug : virEventRunDefaultImpl:244 : running default event implementation
2012-05-08 22:36:22.343+0000: 10380: debug : virEventPollCleanupTimeouts:506 : Cleanup 6
2012-05-08 22:36:22.343+0000: 10380: debug : virEventPollCleanupHandles:554 : Cleanup 10
2012-05-08 22:36:22.343+0000: 10380: debug : virEventPollMakePollFDs:383 : Prepare n=0 w=1, f=7 e=1 d=0
2012-05-08 22:36:22.343+0000: 10380: debug : virEventPollMakePollFDs:383 : Prepare n=1 w=2, f=9 e=1 d=0
2012-05-08 22:36:22.343+0000: 10380: debug : virEventPollMakePollFDs:383 : Prepare n=2 w=3, f=11 e=1 d=0
2012-05-08 22:36:22.343+0000: 10380: debug : virEventPollMakePollFDs:383 : Prepare n=3 w=4, f=12 e=1 d=0
2012-05-08 22:36:22.343+0000: 10380: debug : virEventPollMakePollFDs:383 : Prepare n=4 w=5, f=6 e=1 d=0
2012-05-08 22:36:22.343+0000: 10380: debug : virEventPollMakePollFDs:383 : Prepare n=5 w=6, f=14 e=1 d=0
2012-05-08 22:36:22.343+0000: 10380: debug : virEventPollMakePollFDs:383 : Prepare n=6 w=7, f=15 e=25 d=0
2012-05-08 22:36:22.343+0000: 10380: debug : virEventPollMakePollFDs:383 : Prepare n=7 w=8, f=16 e=25 d=0
2012-05-08 22:36:22.343+0000: 10380: debug : virEventPollMakePollFDs:383 : Prepare n=8 w=9, f=17 e=1 d=0
2012-05-08 22:36:22.343+0000: 10380: debug : virEventPollMakePollFDs:383 : Prepare n=9 w=10, f=18 e=1 d=0
2012-05-08 22:36:22.343+0000: 10380: debug : virEventPollCalculateTimeout:325 : Calculate expiry of 6 timers
2012-05-08 22:36:22.343+0000: 10380: debug : virEventPollCalculateTimeout:351 : Timeout at 0 due in -1 ms
2012-05-08 22:36:22.343+0000: 10380: debug : virEventPollRunOnce:619 : EVENT_POLL_RUN: nhandles=10 imeout=-1
2012-05-08 22:36:22.344+0000: 10380: debug : virEventPollRunOnce:630 : Poll got 1 event(s)
2012-05-08 22:36:22.344+0000: 10380: debug : virEventPollDispatchTimeouts:415 : Dispatch 6
2012-05-08 22:36:22.344+0000: 10380: debug : virEventPollDispatchHandles:460 : Dispatch 10
2012-05-08 22:36:22.344+0000: 10380: debug : virEventPollDispatchHandles:474 : i=0 w=1
2012-05-08 22:36:22.344+0000: 10380: debug : virEventPollDispatchHandles:474 : i=1 w=2
2012-05-08 22:36:22.344+0000: 10380: debug : virEventPollDispatchHandles:474 : i=2 w=3
2012-05-08 22:36:22.344+0000: 10380: debug : virEventPollDispatchHandles:474 : i=3 w=4
2012-05-08 22:36:22.344+0000: 10380: debug : virEventPollDispatchHandles:474 : i=4 w=5
2012-05-08 22:36:22.344+0000: 10380: debug : virEventPollDispatchHandles:474 : i=5 w=6
2012-05-08 22:36:22.344+0000: 10380: debug : virEventPollDispatchHandles:474 : i=6 w=7
2012-05-08 22:36:22.344+0000: 10380: debug : virEventPollDispatchHandles:474 : i=7 w=8
2012-05-08 22:36:22.344+0000: 10380: debug : virEventPollDispatchHandles:474 : i=8 w=9
2012-05-08 22:36:22.344+0000: 10380: debug : virEventPollDispatchHandles:474 : i=9 w=10
2012-05-08 22:36:22.344+0000: 10380: debug : virEventPollDispatchHandles:488 : EVENT_POLL_DISPATCH_HANDLE: watch=10 events=1
2012-05-08 22:36:22.344+0000: 10380: debug : virNetMessageDecodeLength:149 : Got length, now need 376 total (372 more)
2012-05-08 22:36:22.344+0000: 10380: debug : virNetServerClientCalculateHandleMode:137 : tls=(nil) hs=-1, rx=0xb1d8c0 tx=(nil)
2012-05-08 22:36:22.344+0000: 10380: debug : virNetServerClientCalculateHandleMode:167 : mode=1
2012-05-08 22:36:22.344+0000: 10380: debug : virEventPollUpdateHandle:151 : EVENT_POLL_UPDATE_HANDLE: watch=10 events=1
2012-05-08 22:36:22.344+0000: 10380: debug : virEventPollInterruptLocked:702 : Skip interrupt, 1 1116432448
2012-05-08 22:36:22.344+0000: 10380: debug : virNetServerClientDispatchRead:886 : RPC_SERVER_CLIENT_MSG_RX: client=0xb1d7e0 len=376 prog=536903814 vers=1 proc=8 type=0 status=0 serial=54
2012-05-08 22:36:22.344+0000: 10380: debug : virKeepAliveCheckMessage:408 : ka=0xb180c0, client=0xb1d7e0, msg=0xb1d8c0
2012-05-08 22:36:22.344+0000: 10380: debug : virNetServerDispatchNewMessage:199 : server=0xb0c940 client=0xb1d7e0 message=0xb1d8c0
2012-05-08 22:36:22.344+0000: 10380: debug : virNetServerProgramRef:87 : prog=0xb173c0 refs=3
2012-05-08 22:36:22.344+0000: 10385: debug : virNetServerHandleJob:138 : server=0xb0c940 client=0xb1d7e0 message=0xb1d8c0 prog=0xb173c0
2012-05-08 22:36:22.344+0000: 10385: debug : virNetServerProgramDispatch:269 : prog=536903814 ver=1 type=0 status=0 serial=54 proc=8
2012-05-08 22:36:22.344+0000: 10380: debug : virNetMessageNew:48 : msg=0xb5d930 tracked=1
2012-05-08 22:36:22.344+0000: 10380: debug : virNetServerClientCalculateHandleMode:137 : tls=(nil) hs=-1, rx=0xb5d930 tx=(nil)
2012-05-08 22:36:22.344+0000: 10380: debug : virNetServerClientCalculateHandleMode:167 : mode=1
2012-05-08 22:36:22.344+0000: 10380: debug : virEventPollUpdateHandle:151 : EVENT_POLL_UPDATE_HANDLE: watch=10 events=1
2012-05-08 22:36:22.344+0000: 10380: debug : virEventPollInterruptLocked:702 : Skip interrupt, 1 1116432448
2012-05-08 22:36:22.344+0000: 10380: debug : virEventPollCleanupTimeouts:506 : Cleanup 6
2012-05-08 22:36:22.345+0000: 10380: debug : virEventPollCleanupHandles:554 : Cleanup 10
2012-05-08 22:36:22.345+0000: 10380: debug : virEventRunDefaultImpl:244 : running default event implementation
2012-05-08 22:36:22.345+0000: 10380: debug : virEventPollCleanupTimeouts:506 : Cleanup 6
2012-05-08 22:36:22.345+0000: 10380: debug : virEventPollCleanupHandles:554 : Cleanup 10
2012-05-08 22:36:22.345+0000: 10380: debug : virEventPollMakePollFDs:383 : Prepare n=0 w=1, f=7 e=1 d=0
2012-05-08 22:36:22.345+0000: 10380: debug : virEventPollMakePollFDs:383 : Prepare n=1 w=2, f=9 e=1 d=0
2012-05-08 22:36:22.345+0000: 10380: debug : virEventPollMakePollFDs:383 : Prepare n=2 w=3, f=11 e=1 d=0
2012-05-08 22:36:22.345+0000: 10385: debug : remoteDispatchDomainAttachDeviceHelper:297 : server=0xb0c940 client=0xb1d7e0 msg=0xb1d8c0 rerr=0x7f243bbaac70 args=0x7f2428008b20 ret=0x7f24280089f0
2012-05-08 22:36:22.345+0000: 10380: debug : virEventPollMakePollFDs:383 : Prepare n=3 w=4, f=12 e=1 d=0
2012-05-08 22:36:22.345+0000: 10380: debug : virEventPollMakePollFDs:383 : Prepare n=4 w=5, f=6 e=1 d=0
2012-05-08 22:36:22.345+0000: 10385: debug : virDomainAttachDevice:8542 : dom=0x7f2428008ae0, (VM: name=instance-00000011, uuid=5d91ed13-f88f-4ff0-aca4-f1cd3910256f), xml=<disk type='block'>
                     <driver name='qemu' type='raw' cache='none'/>
                     <source dev='/dev/disk/by-path/ip-XXX.XXX.XXX.3260-iscsi-iqn.2010-10.org.openstack:volume-0000002b-lun-1'/>
                     <target dev='vdf' bus='virtio'/>
                 </disk>
2012-05-08 22:36:22.345+0000: 10380: debug : virEventPollMakePollFDs:383 : Prepare n=5 w=6, f=14 e=1 d=0
2012-05-08 22:36:22.345+0000: 10380: debug : virEventPollMakePollFDs:383 : Prepare n=6 w=7, f=15 e=25 d=0
2012-05-08 22:36:22.345+0000: 10380: debug : virEventPollMakePollFDs:383 : Prepare n=7 w=8, f=16 e=25 d=0
2012-05-08 22:36:22.345+0000: 10380: debug : virEventPollMakePollFDs:383 : Prepare n=8 w=9, f=17 e=1 d=0
2012-05-08 22:36:22.345+0000: 10380: debug : virEventPollMakePollFDs:383 : Prepare n=9 w=10, f=18 e=1 d=0
2012-05-08 22:36:22.345+0000: 10380: debug : virEventPollCalculateTimeout:325 : Calculate expiry of 6 timers
2012-05-08 22:36:22.345+0000: 10380: debug : virEventPollCalculateTimeout:351 : Timeout at 0 due in -1 ms
2012-05-08 22:36:22.345+0000: 10380: debug : virEventPollRunOnce:619 : EVENT_POLL_RUN: nhandles=10 imeout=-1
2012-05-08 22:36:22.345+0000: 10385: debug : virDomainObjRef:1508 : obj=0x7f24300b8b70 refs=3
2012-05-08 22:36:22.345+0000: 10385: debug : qemuDomainObjBeginJobInternal:766 : Starting job: modify (async=none)
2012-05-08 22:36:22.345+0000: 10385: debug : virCgroupNew:602 : New group /libvirt/qemu/instance-00000011
2012-05-08 22:36:22.346+0000: 10385: debug : virCgroupDetect:261 : Detected mount/mapping 0:cpu at /sys/fs/cgroup/cpu in
2012-05-08 22:36:22.346+0000: 10385: debug : virCgroupDetect:261 : Detected mount/mapping 1:cpuacct at /sys/fs/cgroup/cpuacct in
2012-05-08 22:36:22.346+0000: 10385: debug : virCgroupDetect:261 : Detected mount/mapping 2:cpuset at /sys/fs/cgroup/cpuset in
2012-05-08 22:36:22.346+0000: 10385: debug : virCgroupDetect:261 : Detected mount/mapping 3:memory at /sys/fs/cgroup/memory in
2012-05-08 22:36:22.346+0000: 10385: debug : virCgroupDetect:261 : Detected mount/mapping 4:devices at /sys/fs/cgroup/devices in
2012-05-08 22:36:22.346+0000: 10385: debug : virCgroupDetect:261 : Detected mount/mapping 5:freezer at /sys/fs/cgroup/freezer in
2012-05-08 22:36:22.346+0000: 10385: debug : virCgroupDetect:261 : Detected mount/mapping 6:blkio at /sys/fs/cgroup/blkio in
2012-05-08 22:36:22.346+0000: 10385: debug : virCgroupMakeGroup:523 : Make group /libvirt/qemu/instance-00000011
2012-05-08 22:36:22.346+0000: 10385: debug : virCgroupMakeGroup:545 : Make controller /sys/fs/cgroup/cpu/libvirt/qemu/instance-00000011/
2012-05-08 22:36:22.346+0000: 10385: debug : virCgroupMakeGroup:545 : Make controller /sys/fs/cgroup/cpuacct/libvirt/qemu/instance-00000011/
2012-05-08 22:36:22.346+0000: 10385: debug : virCgroupMakeGroup:545 : Make controller /sys/fs/cgroup/cpuset/libvirt/qemu/instance-00000011/
2012-05-08 22:36:22.346+0000: 10385: debug : virCgroupMakeGroup:545 : Make controller /sys/fs/cgroup/memory/libvirt/qemu/instance-00000011/
2012-05-08 22:36:22.346+0000: 10385: debug : virCgroupMakeGroup:545 : Make controller /sys/fs/cgroup/devices/libvirt/qemu/instance-00000011/
2012-05-08 22:36:22.346+0000: 10385: debug : virCgroupMakeGroup:545 : Make controller /sys/fs/cgroup/freezer/libvirt/qemu/instance-00000011/
2012-05-08 22:36:22.346+0000: 10385: debug : virCgroupMakeGroup:545 : Make controller /sys/fs/cgroup/blkio/libvirt/qemu/instance-00000011/
2012-05-08 22:36:22.346+0000: 10385: debug : qemuSetupDiskPathAllow:70 : Process path /dev/disk/by-path/ip-XXX.XXX.XXX.XXX.189.10:3260-iscsi-iqn.2010-10.org.openstack:volume-0000002b-lun-1 for disk
2012-05-08 22:36:22.346+0000: 10385: debug : virCgroupSetValueStr:319 : Set value '/sys/fs/cgroup/devices/libvirt/qemu/instance-00000011/devices.allow' to 'b 8:48 rw'
2012-05-08 22:36:22.348+0000: 10385: debug : virDomainLockManagerNew:123 : plugin=0x7f2430025400 dom=0x7f24300b8b70 withResources=0
2012-05-08 22:36:22.348+0000: 10385: debug : virLockManagerNew:291 : plugin=0x7f2430025400 type=0 nparams=4 params=0x7f243bbaa8c0 flags=0
2012-05-08 22:36:22.348+0000: 10385: debug : virLockManagerLogParams:98 : key=uuid type=uuid value=5d91ed13-f88f-4ff0-aca4-f1cd3910256f
2012-05-08 22:36:22.348+0000: 10385: debug : virLockManagerLogParams:94 : key=name type=string value=instance-00000011
2012-05-08 22:36:22.348+0000: 10385: debug : virLockManagerLogParams:82 : key=id type=uint value=1
2012-05-08 22:36:22.348+0000: 10385: debug : virLockManagerLogParams:82 : key=pid type=uint value=2595
2012-05-08 22:36:22.348+0000: 10385: debug : virDomainLockManagerAddDisk:86 : Add disk /dev/disk/by-path/ip-XXX.XXX.XXX.XXX:3260-iscsi-iqn.2010-10.org.openstack:volume-0000002b-lun-1
2012-05-08 22:36:22.348+0000: 10385: debug : virLockManagerAddResource:320 : lock=0x7f2428002490 type=0 name=/dev/disk/by-path/ip-XXX.XXX.XXX.XXX:3260-iscsi-iqn.2010-10.org.openstack:volume-0000002b-lun-1 nparams=0 params=(nil) flags=0
2012-05-08 22:36:22.348+0000: 10385: debug : virLockManagerAcquire:337 : lock=0x7f2428002490 state='(null)' flags=0 fd=(nil)
2012-05-08 22:36:22.348+0000: 10385: debug : virLockManagerFree:374 : lock=0x7f2428002490
2012-05-08 22:36:22.349+0000: 10385: info : virSecurityDACSetOwnership:99 : Setting DAC user and group on '/dev/disk/by-path/ip-XXX.XXX.XXX.XXX:3260-iscsi-iqn.2010-10.org.openstack:volume-0000002b-lun-1' to '107:114'
2012-05-08 22:36:22.351+0000: 10385: debug : virCommandRunAsync:2062 : About to run /usr/lib/libvirt/virt-aa-helper -p 0 -r -u libvirt-5d91ed13-f88f-4ff0-aca4-f1cd3910256f -f /dev/disk/by-path/ip-XXX.XXX.XXX.XXX:3260-iscsi-iqn.2010-10.org.openstack:volume-0000002b-lun-1
2012-05-08 22:36:22.351+0000: 10385: debug : virCommandRunAsync:2078 : Command result 0, with PID 11956
2012-05-08 22:36:22.797+0000: 10385: debug : virCommandRun:1882 : Result status 0, stdout: '' stderr: '2012-05-08 22:36:22.352+0000: 11956: info : libvirt version: 0.9.8
2012-05-08 22:36:22.352+0000: 11956: debug : virCommandHook:1981 : Hook is done 0
'
2012-05-08 22:36:22.797+0000: 10385: debug : virCommandRun:1894 : ignoring failed close on fd 20
2012-05-08 22:36:22.797+0000: 10385: debug : qemuDomainPCIAddressSetNextAddr:1053 : PCI addr 0:0:2.0 already in use
2012-05-08 22:36:22.797+0000: 10385: debug : qemuDomainPCIAddressSetNextAddr:1053 : PCI addr 0:0:3.0 already in use
2012-05-08 22:36:22.797+0000: 10385: debug : qemuDomainPCIAddressSetNextAddr:1053 : PCI addr 0:0:4.0 already in use
2012-05-08 22:36:22.797+0000: 10385: debug : qemuDomainPCIAddressSetNextAddr:1053 : PCI addr 0:0:5.0 already in use
2012-05-08 22:36:22.797+0000: 10385: debug : qemuDomainPCIAddressSetNextAddr:1053 : PCI addr 0:0:6.0 already in use
2012-05-08 22:36:22.797+0000: 10385: debug : qemuDomainPCIAddressSetNextAddr:1058 : Allocating PCI addr 0:0:7.0
2012-05-08 22:36:22.797+0000: 10385: debug : qemuDomainPCIAddressReserveAddr:882 : Reserving PCI addr 0:0:7.0
2012-05-08 22:36:22.797+0000: 10385: debug : qemuDomainPCIAddressReserveAddr:882 : Reserving PCI addr 0:0:7.1
2012-05-08 22:36:22.797+0000: 10385: debug : qemuDomainPCIAddressReserveAddr:882 : Reserving PCI addr 0:0:7.2
2012-05-08 22:36:22.797+0000: 10385: debug : qemuDomainPCIAddressReserveAddr:882 : Reserving PCI addr 0:0:7.3
2012-05-08 22:36:22.797+0000: 10385: debug : qemuDomainPCIAddressReserveAddr:882 : Reserving PCI addr 0:0:7.4
2012-05-08 22:36:22.797+0000: 10385: debug : qemuDomainPCIAddressReserveAddr:882 : Reserving PCI addr 0:0:7.5
2012-05-08 22:36:22.797+0000: 10385: debug : qemuDomainPCIAddressReserveAddr:882 : Reserving PCI addr 0:0:7.6
2012-05-08 22:36:22.797+0000: 10385: debug : qemuDomainPCIAddressReserveAddr:882 : Reserving PCI addr 0:0:7.7
2012-05-08 22:36:22.797+0000: 10385: debug : qemuMonitorRef:230 : QEMU_MONITOR_REF: mon=0x7f242c000a80 refs=3
2012-05-08 22:36:22.797+0000: 10385: debug : qemuMonitorAddDrive:2441 : mon=0x7f242c000a80 drive=file=/dev/disk/by-path/ip-XXX.XXX.XXX.XXX:3260-iscsi-iqn.2010-10.org.openstack:volume-0000002b-lun-1,if=none,id=drive-virtio-disk5,format=raw,cache=none
2012-05-08 22:36:22.798+0000: 10385: debug : virJSONValueToString:1037 : object=0x7f2428008a10
2012-05-08 22:36:22.798+0000: 10385: debug : virJSONValueToStringOne:969 : object=0x7f2428008a10 type=0 gen=0x7f24280035c0
2012-05-08 22:36:22.798+0000: 10385: debug : virJSONValueToStringOne:969 : object=0x7f2428008650 type=2 gen=0x7f24280035c0
2012-05-08 22:36:22.798+0000: 10385: debug : virJSONValueToStringOne:969 : object=0x7f2428008470 type=0 gen=0x7f24280035c0
2012-05-08 22:36:22.798+0000: 10385: debug : virJSONValueToStringOne:969 : object=0x7f2428008490 type=2 gen=0x7f24280035c0
2012-05-08 22:36:22.798+0000: 10385: debug : virJSONValueToStringOne:969 : object=0x7f2428002460 type=2 gen=0x7f24280035c0
2012-05-08 22:36:22.798+0000: 10385: debug : virJSONValueToStringOne:969 : object=0x7f2428002480 type=2 gen=0x7f24280035c0
2012-05-08 22:36:22.798+0000: 10385: debug : virJSONValueToString:1071 : result={"execute":"drive_add","arguments":{"pci_addr":"dummy","opts":"file=/dev/disk/by-path/ip-XXX.XXX.XXX.XXX:3260-iscsi-iqn.2010-10.org.openstack:volume-0000002b-lun-1,if=none,id=drive-virtio-disk5,format=raw,cache=none"},"id":"libvirt-7"}
2012-05-08 22:36:22.798+0000: 10385: debug : qemuMonitorJSONCommandWithFd:228 : Send command '{"execute":"drive_add","arguments":{"pci_addr":"dummy","opts":"file=/dev/disk/by-path/ip-XXX.XXX.XXX.XXX:3260-iscsi-iqn.2010-10.org.openstack:volume-0000002b-lun-1,if=none,id=drive-virtio-disk5,format=raw,cache=none"},"id":"libvirt-7"}' for write with FD -1
2012-05-08 22:36:22.798+0000: 10385: debug : virEventPollUpdateHandle:151 : EVENT_POLL_UPDATE_HANDLE: watch=8 events=15
2012-05-08 22:36:22.798+0000: 10385: debug : virEventPollInterruptLocked:706 : Interrupting
2012-05-08 22:36:22.798+0000: 10385: debug : qemuMonitorSend:831 : QEMU_MONITOR_SEND_MSG: mon=0x7f242c000a80 msg={"execute":"drive_add","arguments":{"pci_addr":"dummy","opts":"file=/dev/disk/by-path/ip-XXX.XXX.XXX.XXX:3260-iscsi-iqn.2010-10.org.openstack:volume-0000002b-lun-1,if=none,id=drive-virtio-disk5,format=raw,cache=none"},"id":"libvirt-7"}

 fd=-1
2012-05-08 22:36:22.798+0000: 10380: debug : virEventPollRunOnce:630 : Poll got 1 event(s)
2012-05-08 22:36:22.798+0000: 10380: debug : virEventPollDispatchTimeouts:415 : Dispatch 6
2012-05-08 22:36:22.798+0000: 10380: debug : virEventPollDispatchHandles:460 : Dispatch 10
2012-05-08 22:36:22.798+0000: 10380: debug : virEventPollDispatchHandles:474 : i=0 w=1
2012-05-08 22:36:22.798+0000: 10380: debug : virEventPollDispatchHandles:488 : EVENT_POLL_DISPATCH_HANDLE: watch=1 events=1
2012-05-08 22:36:22.798+0000: 10380: debug : virEventPollDispatchHandles:474 : i=1 w=2
2012-05-08 22:36:22.798+0000: 10380: debug : virEventPollDispatchHandles:474 : i=2 w=3
2012-05-08 22:36:22.798+0000: 10380: debug : virEventPollDispatchHandles:474 : i=3 w=4
2012-05-08 22:36:22.798+0000: 10380: debug : virEventPollDispatchHandles:474 : i=4 w=5
2012-05-08 22:36:22.798+0000: 10380: debug : virEventPollDispatchHandles:474 : i=5 w=6
2012-05-08 22:36:22.798+0000: 10380: debug : virEventPollDispatchHandles:474 : i=6 w=7
2012-05-08 22:36:22.798+0000: 10380: debug : virEventPollDispatchHandles:474 : i=7 w=8
2012-05-08 22:36:22.798+0000: 10380: debug : virEventPollDispatchHandles:474 : i=8 w=9
2012-05-08 22:36:22.798+0000: 10380: debug : virEventPollDispatchHandles:474 : i=9 w=10
2012-05-08 22:36:22.798+0000: 10380: debug : virEventPollCleanupTimeouts:506 : Cleanup 6
2012-05-08 22:36:22.798+0000: 10380: debug : virEventPollCleanupHandles:554 : Cleanup 10
2012-05-08 22:36:22.798+0000: 10380: debug : virEventRunDefaultImpl:244 : running default event implementation
2012-05-08 22:36:22.798+0000: 10380: debug : virEventPollCleanupTimeouts:506 : Cleanup 6
2012-05-08 22:36:22.798+0000: 10380: debug : virEventPollCleanupHandles:554 : Cleanup 10
2012-05-08 22:36:22.798+0000: 10380: debug : virEventPollMakePollFDs:383 : Prepare n=0 w=1, f=7 e=1 d=0
2012-05-08 22:36:22.798+0000: 10380: debug : virEventPollMakePollFDs:383 : Prepare n=1 w=2, f=9 e=1 d=0
2012-05-08 22:36:22.798+0000: 10380: debug : virEventPollMakePollFDs:383 : Prepare n=2 w=3, f=11 e=1 d=0
2012-05-08 22:36:22.798+0000: 10380: debug : virEventPollMakePollFDs:383 : Prepare n=3 w=4, f=12 e=1 d=0
2012-05-08 22:36:22.798+0000: 10380: debug : virEventPollMakePollFDs:383 : Prepare n=4 w=5, f=6 e=1 d=0
2012-05-08 22:36:22.798+0000: 10380: debug : virEventPollMakePollFDs:383 : Prepare n=5 w=6, f=14 e=1 d=0
2012-05-08 22:36:22.798+0000: 10380: debug : virEventPollMakePollFDs:383 : Prepare n=6 w=7, f=15 e=25 d=0
2012-05-08 22:36:22.798+0000: 10380: debug : virEventPollMakePollFDs:383 : Prepare n=7 w=8, f=16 e=29 d=0
2012-05-08 22:36:22.798+0000: 10380: debug : virEventPollMakePollFDs:383 : Prepare n=8 w=9, f=17 e=1 d=0
2012-05-08 22:36:22.798+0000: 10380: debug : virEventPollMakePollFDs:383 : Prepare n=9 w=10, f=18 e=1 d=0
2012-05-08 22:36:22.798+0000: 10380: debug : virEventPollCalculateTimeout:325 : Calculate expiry of 6 timers
2012-05-08 22:36:22.798+0000: 10380: debug : virEventPollCalculateTimeout:351 : Timeout at 0 due in -1 ms
2012-05-08 22:36:22.798+0000: 10380: debug : virEventPollRunOnce:619 : EVENT_POLL_RUN: nhandles=10 imeout=-1
2012-05-08 22:36:22.798+0000: 10380: debug : virEventPollRunOnce:630 : Poll got 1 event(s)
2012-05-08 22:36:22.798+0000: 10380: debug : virEventPollDispatchTimeouts:415 : Dispatch 6
2012-05-08 22:36:22.798+0000: 10380: debug : virEventPollDispatchHandles:460 : Dispatch 10
2012-05-08 22:36:22.798+0000: 10380: debug : virEventPollDispatchHandles:474 : i=0 w=1
2012-05-08 22:36:22.798+0000: 10380: debug : virEventPollDispatchHandles:474 : i=1 w=2
2012-05-08 22:36:22.798+0000: 10380: debug : virEventPollDispatchHandles:474 : i=2 w=3
2012-05-08 22:36:22.798+0000: 10380: debug : virEventPollDispatchHandles:474 : i=3 w=4
2012-05-08 22:36:22.798+0000: 10380: debug : virEventPollDispatchHandles:474 : i=4 w=5
2012-05-08 22:36:22.798+0000: 10380: debug : virEventPollDispatchHandles:474 : i=5 w=6
2012-05-08 22:36:22.798+0000: 10380: debug : virEventPollDispatchHandles:474 : i=6 w=7
2012-05-08 22:36:22.798+0000: 10380: debug : virEventPollDispatchHandles:474 : i=7 w=8
2012-05-08 22:36:22.798+0000: 10380: debug : virEventPollDispatchHandles:488 : EVENT_POLL_DISPATCH_HANDLE: watch=8 events=2
2012-05-08 22:36:22.798+0000: 10380: debug : qemuMonitorRef:230 : QEMU_MONITOR_REF: mon=0x7f242c000a80 refs=4
2012-05-08 22:36:22.798+0000: 10380: debug : qemuMonitorIOWrite:461 : QEMU_MONITOR_IO_WRITE: mon=0x7f242c000a80 buf={"execute":"drive_add","arguments":{"pci_addr":"dummy","opts":"file=/dev/disk/by-path/ip-XXX.XXX.XXX.XXX:3260-iscsi-iqn.2010-10.org.openstack:volume-0000002b-lun-1,if=none,id=drive-virtio-disk5,format=raw,cache=none"},"id":"libvirt-7"}

 len=236 ret=236 errno=22
2012-05-08 22:36:22.798+0000: 10380: debug : virEventPollUpdateHandle:151 : EVENT_POLL_UPDATE_HANDLE: watch=8 events=13
2012-05-08 22:36:22.798+0000: 10380: debug : virEventPollInterruptLocked:702 : Skip interrupt, 1 1116432448
2012-05-08 22:36:22.798+0000: 10380: debug : qemuMonitorUnref:239 : QEMU_MONITOR_UNREF: mon=0x7f242c000a80 refs=3
2012-05-08 22:36:22.798+0000: 10380: debug : virEventPollDispatchHandles:474 : i=8 w=9
2012-05-08 22:36:22.798+0000: 10380: debug : virEventPollDispatchHandles:474 : i=9 w=10
2012-05-08 22:36:22.798+0000: 10380: debug : virEventPollCleanupTimeouts:506 : Cleanup 6
2012-05-08 22:36:22.798+0000: 10380: debug : virEventPollCleanupHandles:554 : Cleanup 10
2012-05-08 22:36:22.798+0000: 10380: debug : virEventRunDefaultImpl:244 : running default event implementation
2012-05-08 22:36:22.799+0000: 10380: debug : virEventPollCleanupTimeouts:506 : Cleanup 6
2012-05-08 22:36:22.799+0000: 10380: debug : virEventPollCleanupHandles:554 : Cleanup 10
2012-05-08 22:36:22.799+0000: 10380: debug : virEventPollMakePollFDs:383 : Prepare n=0 w=1, f=7 e=1 d=0
2012-05-08 22:36:22.799+0000: 10380: debug : virEventPollMakePollFDs:383 : Prepare n=1 w=2, f=9 e=1 d=0
2012-05-08 22:36:22.799+0000: 10380: debug : virEventPollMakePollFDs:383 : Prepare n=2 w=3, f=11 e=1 d=0
2012-05-08 22:36:22.799+0000: 10380: debug : virEventPollMakePollFDs:383 : Prepare n=3 w=4, f=12 e=1 d=0
2012-05-08 22:36:22.799+0000: 10380: debug : virEventPollMakePollFDs:383 : Prepare n=4 w=5, f=6 e=1 d=0
2012-05-08 22:36:22.799+0000: 10380: debug : virEventPollMakePollFDs:383 : Prepare n=5 w=6, f=14 e=1 d=0
2012-05-08 22:36:22.799+0000: 10380: debug : virEventPollMakePollFDs:383 : Prepare n=6 w=7, f=15 e=25 d=0
2012-05-08 22:36:22.799+0000: 10380: debug : virEventPollMakePollFDs:383 : Prepare n=7 w=8, f=16 e=25 d=0
2012-05-08 22:36:22.799+0000: 10380: debug : virEventPollMakePollFDs:383 : Prepare n=8 w=9, f=17 e=1 d=0
2012-05-08 22:36:22.799+0000: 10380: debug : virEventPollMakePollFDs:383 : Prepare n=9 w=10, f=18 e=1 d=0
2012-05-08 22:36:22.799+0000: 10380: debug : virEventPollCalculateTimeout:325 : Calculate expiry of 6 timers
2012-05-08 22:36:22.799+0000: 10380: debug : virEventPollCalculateTimeout:351 : Timeout at 0 due in -1 ms
2012-05-08 22:36:22.799+0000: 10380: debug : virEventPollRunOnce:619 : EVENT_POLL_RUN: nhandles=10 imeout=-1
2012-05-08 22:36:22.800+0000: 10380: debug : virEventPollRunOnce:630 : Poll got 1 event(s)
2012-05-08 22:36:22.800+0000: 10380: debug : virEventPollDispatchTimeouts:415 : Dispatch 6
2012-05-08 22:36:22.800+0000: 10380: debug : virEventPollDispatchHandles:460 : Dispatch 10
2012-05-08 22:36:22.800+0000: 10380: debug : virEventPollDispatchHandles:474 : i=0 w=1
2012-05-08 22:36:22.800+0000: 10380: debug : virEventPollDispatchHandles:474 : i=1 w=2
2012-05-08 22:36:22.800+0000: 10380: debug : virEventPollDispatchHandles:474 : i=2 w=3
2012-05-08 22:36:22.800+0000: 10380: debug : virEventPollDispatchHandles:474 : i=3 w=4
2012-05-08 22:36:22.800+0000: 10380: debug : virEventPollDispatchHandles:474 : i=4 w=5
2012-05-08 22:36:22.800+0000: 10380: debug : virEventPollDispatchHandles:474 : i=5 w=6
2012-05-08 22:36:22.800+0000: 10380: debug : virEventPollDispatchHandles:474 : i=6 w=7
2012-05-08 22:36:22.800+0000: 10380: debug : virEventPollDispatchHandles:474 : i=7 w=8
2012-05-08 22:36:22.800+0000: 10380: debug : virEventPollDispatchHandles:488 : EVENT_POLL_DISPATCH_HANDLE: watch=8 events=1
2012-05-08 22:36:22.800+0000: 10380: debug : qemuMonitorRef:230 : QEMU_MONITOR_REF: mon=0x7f242c000a80 refs=4
2012-05-08 22:36:22.800+0000: 10380: debug : qemuMonitorIOProcess:356 : QEMU_MONITOR_IO_PROCESS: mon=0x7f242c000a80 buf={"id": "libvirt-7", "error": {"class": "CommandNotFound", "desc": "The command drive_add has not been found", "data": {"name": "drive_add"}}}

 len=143
2012-05-08 22:36:22.800+0000: 10380: debug : qemuMonitorJSONIOProcessLine:115 : Line [{"id": "libvirt-7", "error": {"class": "CommandNotFound", "desc": "The command drive_add has not been found", "data": {"name": "drive_add"}}}]
2012-05-08 22:36:22.800+0000: 10380: debug : virJSONValueFromString:914 : string={"id": "libvirt-7", "error": {"class": "CommandNotFound", "desc": "The command drive_add has not been found", "data": {"name": "drive_add"}}}
2012-05-08 22:36:22.800+0000: 10380: debug : virJSONParserHandleStartMap:791 : parser=0x7fffdbcd3940
2012-05-08 22:36:22.801+0000: 10380: debug : virJSONParserHandleMapKey:772 : parser=0x7fffdbcd3940 key=0xb18542
2012-05-08 22:36:22.801+0000: 10380: debug : virJSONParserHandleString:752 : parser=0x7fffdbcd3940 str=0xb18548
2012-05-08 22:36:22.801+0000: 10380: debug : virJSONParserHandleMapKey:772 : parser=0x7fffdbcd3940 key=0xb18555
2012-05-08 22:36:22.801+0000: 10380: debug : virJSONParserHandleStartMap:791 : parser=0x7fffdbcd3940
2012-05-08 22:36:22.801+0000: 10380: debug : virJSONParserHandleMapKey:772 : parser=0x7fffdbcd3940 key=0xb1855f
2012-05-08 22:36:22.801+0000: 10380: debug : virJSONParserHandleString:752 : parser=0x7fffdbcd3940 str=0xb18568
2012-05-08 22:36:22.801+0000: 10380: debug : virJSONParserHandleMapKey:772 : parser=0x7fffdbcd3940 key=0xb1857b
2012-05-08 22:36:22.801+0000: 10380: debug : virJSONParserHandleString:752 : parser=0x7fffdbcd3940 str=0xb18583
2012-05-08 22:36:22.801+0000: 10380: debug : virJSONParserHandleMapKey:772 : parser=0x7fffdbcd3940 key=0xb185af
2012-05-08 22:36:22.801+0000: 10380: debug : virJSONParserHandleStartMap:791 : parser=0x7fffdbcd3940
2012-05-08 22:36:22.801+0000: 10380: debug : virJSONParserHandleMapKey:772 : parser=0x7fffdbcd3940 key=0xb185b8
2012-05-08 22:36:22.801+0000: 10380: debug : virJSONParserHandleString:752 : parser=0x7fffdbcd3940 str=0xb185c0
2012-05-08 22:36:22.801+0000: 10380: debug : virJSONParserHandleEndMap:820 : parser=0x7fffdbcd3940
2012-05-08 22:36:22.801+0000: 10380: debug : virJSONParserHandleEndMap:820 : parser=0x7fffdbcd3940
2012-05-08 22:36:22.801+0000: 10380: debug : virJSONParserHandleEndMap:820 : parser=0x7fffdbcd3940
2012-05-08 22:36:22.801+0000: 10380: debug : virJSONValueFromString:958 : result=0xaf2b00
2012-05-08 22:36:22.801+0000: 10380: debug : qemuMonitorJSONIOProcessLine:135 : QEMU_MONITOR_RECV_REPLY: mon=0x7f242c000a80 reply={"id": "libvirt-7", "error": {"class": "CommandNotFound", "desc": "The command drive_add has not been found", "data": {"name": "drive_add"}}}
2012-05-08 22:36:22.801+0000: 10380: debug : qemuMonitorJSONIOProcess:186 : Total used 143 bytes out of 143 available in buffer
2012-05-08 22:36:22.801+0000: 10380: debug : virEventPollUpdateHandle:151 : EVENT_POLL_UPDATE_HANDLE: watch=8 events=13
2012-05-08 22:36:22.801+0000: 10380: debug : virEventPollInterruptLocked:702 : Skip interrupt, 1 1116432448
2012-05-08 22:36:22.801+0000: 10380: debug : qemuMonitorUnref:239 : QEMU_MONITOR_UNREF: mon=0x7f242c000a80 refs=3
2012-05-08 22:36:22.801+0000: 10380: debug : virEventPollDispatchHandles:474 : i=8 w=9
2012-05-08 22:36:22.801+0000: 10380: debug : virEventPollDispatchHandles:474 : i=9 w=10
2012-05-08 22:36:22.801+0000: 10380: debug : virEventPollCleanupTimeouts:506 : Cleanup 6
2012-05-08 22:36:22.801+0000: 10380: debug : virEventPollCleanupHandles:554 : Cleanup 10
2012-05-08 22:36:22.801+0000: 10380: debug : virEventRunDefaultImpl:244 : running default event implementation
2012-05-08 22:36:22.801+0000: 10380: debug : virEventPollCleanupTimeouts:506 : Cleanup 6
2012-05-08 22:36:22.801+0000: 10380: debug : virEventPollCleanupHandles:554 : Cleanup 10
2012-05-08 22:36:22.801+0000: 10385: debug : virEventPollUpdateHandle:151 : EVENT_POLL_UPDATE_HANDLE: watch=8 events=13
2012-05-08 22:36:22.801+0000: 10380: debug : virEventPollMakePollFDs:383 : Prepare n=0 w=1, f=7 e=1 d=0
2012-05-08 22:36:22.801+0000: 10380: debug : virEventPollMakePollFDs:383 : Prepare n=1 w=2, f=9 e=1 d=0
2012-05-08 22:36:22.801+0000: 10380: debug : virEventPollMakePollFDs:383 : Prepare n=2 w=3, f=11 e=1 d=0
2012-05-08 22:36:22.801+0000: 10380: debug : virEventPollMakePollFDs:383 : Prepare n=3 w=4, f=12 e=1 d=0
2012-05-08 22:36:22.801+0000: 10380: debug : virEventPollMakePollFDs:383 : Prepare n=4 w=5, f=6 e=1 d=0
2012-05-08 22:36:22.801+0000: 10380: debug : virEventPollMakePollFDs:383 : Prepare n=5 w=6, f=14 e=1 d=0
2012-05-08 22:36:22.801+0000: 10380: debug : virEventPollMakePollFDs:383 : Prepare n=6 w=7, f=15 e=25 d=0
2012-05-08 22:36:22.801+0000: 10380: debug : virEventPollMakePollFDs:383 : Prepare n=7 w=8, f=16 e=25 d=0
2012-05-08 22:36:22.801+0000: 10380: debug : virEventPollMakePollFDs:383 : Prepare n=8 w=9, f=17 e=1 d=0
2012-05-08 22:36:22.801+0000: 10380: debug : virEventPollMakePollFDs:383 : Prepare n=9 w=10, f=18 e=1 d=0
2012-05-08 22:36:22.801+0000: 10380: debug : virEventPollCalculateTimeout:325 : Calculate expiry of 6 timers
2012-05-08 22:36:22.801+0000: 10380: debug : virEventPollCalculateTimeout:351 : Timeout at 0 due in -1 ms
2012-05-08 22:36:22.801+0000: 10380: debug : virEventPollRunOnce:619 : EVENT_POLL_RUN: nhandles=10 imeout=-1
2012-05-08 22:36:22.801+0000: 10385: debug : virEventPollInterruptLocked:706 : Interrupting
2012-05-08 22:36:22.801+0000: 10385: debug : qemuMonitorJSONCommandWithFd:233 : Receive command reply ret=0 rxObject=0xaf2b00
2012-05-08 22:36:22.801+0000: 10385: debug : qemuMonitorJSONAddDrive:2818 : drive_add command not found, trying HMP
2012-05-08 22:36:22.801+0000: 10380: debug : virEventPollRunOnce:630 : Poll got 1 event(s)
2012-05-08 22:36:22.801+0000: 10380: debug : virEventPollDispatchTimeouts:415 : Dispatch 6
2012-05-08 22:36:22.801+0000: 10380: debug : virEventPollDispatchHandles:460 : Dispatch 10
2012-05-08 22:36:22.801+0000: 10380: debug : virEventPollDispatchHandles:474 : i=0 w=1
2012-05-08 22:36:22.801+0000: 10380: debug : virEventPollDispatchHandles:488 : EVENT_POLL_DISPATCH_HANDLE: watch=1 events=1
2012-05-08 22:36:22.802+0000: 10380: debug : virEventPollDispatchHandles:474 : i=1 w=2
2012-05-08 22:36:22.802+0000: 10380: debug : virEventPollDispatchHandles:474 : i=2 w=3
2012-05-08 22:36:22.802+0000: 10380: debug : virEventPollDispatchHandles:474 : i=3 w=4
2012-05-08 22:36:22.802+0000: 10380: debug : virEventPollDispatchHandles:474 : i=4 w=5
2012-05-08 22:36:22.802+0000: 10380: debug : virEventPollDispatchHandles:474 : i=5 w=6
2012-05-08 22:36:22.802+0000: 10380: debug : virEventPollDispatchHandles:474 : i=6 w=7
2012-05-08 22:36:22.802+0000: 10380: debug : virEventPollDispatchHandles:474 : i=7 w=8
2012-05-08 22:36:22.802+0000: 10380: debug : virEventPollDispatchHandles:474 : i=8 w=9
2012-05-08 22:36:22.802+0000: 10380: debug : virEventPollDispatchHandles:474 : i=9 w=10
2012-05-08 22:36:22.802+0000: 10380: debug : virEventPollCleanupTimeouts:506 : Cleanup 6
2012-05-08 22:36:22.802+0000: 10380: debug : virEventPollCleanupHandles:554 : Cleanup 10
2012-05-08 22:36:22.802+0000: 10380: debug : virEventRunDefaultImpl:244 : running default event implementation
2012-05-08 22:36:22.802+0000: 10380: debug : virEventPollCleanupTimeouts:506 : Cleanup 6
2012-05-08 22:36:22.802+0000: 10380: debug : virEventPollCleanupHandles:554 : Cleanup 10
2012-05-08 22:36:22.802+0000: 10380: debug : virEventPollMakePollFDs:383 : Prepare n=0 w=1, f=7 e=1 d=0
2012-05-08 22:36:22.802+0000: 10380: debug : virEventPollMakePollFDs:383 : Prepare n=1 w=2, f=9 e=1 d=0
2012-05-08 22:36:22.802+0000: 10380: debug : virEventPollMakePollFDs:383 : Prepare n=2 w=3, f=11 e=1 d=0
2012-05-08 22:36:22.802+0000: 10380: debug : virEventPollMakePollFDs:383 : Prepare n=3 w=4, f=12 e=1 d=0
2012-05-08 22:36:22.802+0000: 10380: debug : virEventPollMakePollFDs:383 : Prepare n=4 w=5, f=6 e=1 d=0
2012-05-08 22:36:22.802+0000: 10380: debug : virEventPollMakePollFDs:383 : Prepare n=5 w=6, f=14 e=1 d=0
2012-05-08 22:36:22.802+0000: 10380: debug : virEventPollMakePollFDs:383 : Prepare n=6 w=7, f=15 e=25 d=0
2012-05-08 22:36:22.802+0000: 10380: debug : virEventPollMakePollFDs:383 : Prepare n=7 w=8, f=16 e=25 d=0
2012-05-08 22:36:22.802+0000: 10380: debug : virEventPollMakePollFDs:383 : Prepare n=8 w=9, f=17 e=1 d=0
2012-05-08 22:36:22.802+0000: 10380: debug : virEventPollMakePollFDs:383 : Prepare n=9 w=10, f=18 e=1 d=0
2012-05-08 22:36:22.802+0000: 10380: debug : virEventPollCalculateTimeout:325 : Calculate expiry of 6 timers
2012-05-08 22:36:22.802+0000: 10380: debug : virEventPollCalculateTimeout:351 : Timeout at 0 due in -1 ms
2012-05-08 22:36:22.802+0000: 10380: debug : virEventPollRunOnce:619 : EVENT_POLL_RUN: nhandles=10 imeout=-1

[Serge Hallyn (serge-hallyn)]

Thanks for reporting this bug.

qemu seems to support drive_add (as tested with typing 'drive_add' in 'kvm -monitor stdio -vnc :1'), although it's possible this is a problem with the json monitor.

To help me reproduce can you tell me exactly, step by step, how you are adding the drive?

It's possible this is related to https://bugzilla.redhat.com/show_bug.cgi?id=696884

[rfz (rfz)]

HI Serge,

virsh attach-disk instance-00000011 /dev/disk/by-path/ip-XXX.XXX.XXX.XXX\:3260-iscsi-iqn.2010-10.org.openstack\:volume-0000002b-lun-1 vdf
setlocale: No such file or directory
Disk attached successfully

Output:

-05-09 15:38:14.311+0000: 22564: debug : virJSONValueToString:1071 : result={"execute":"human-monitor-command","arguments":{"command-line":"drive_add dummy file=/dev/disk/by-path/ip-XXX.XXX.XXX.XXX:3260-iscsi-iqn.2010-10.org.openstack:volume-0000002b-lun-1,if=none,id=drive-virtio-disk5,format=raw"},"id":"libvirt-22"}
2012-05-09 15:38:14.311+0000: 22562: debug : virEventPollDispatchHandles:474 : i=8 w=9
2012-05-09 15:38:14.311+0000: 22564: debug : qemuMonitorJSONCommandWithFd:228 : Send command '{"execute":"human-monitor-command","arguments":{"command-line":"drive_add dummy file=/dev/disk/by-path/ip-XXX.XXX.XXX.XXX:3260-iscsi-iqn.2010-10.org.openstack:volume-0000002b-lun-1,if=none,id=drive-virtio-disk5,format=raw"},"id":"libvirt-22"}' for write with FD -1
2012-05-09 15:38:14.311+0000: 22564: debug : virEventPollUpdateHandle:151 : EVENT_POLL_UPDATE_HANDLE: watch=8 events=15
2012-05-09 15:38:14.311+0000: 22562: debug : virEventPollDispatchHandles:474 : i=9 w=17
2012-05-09 15:38:14.311+0000: 22562: debug : virEventPollCleanupTimeouts:506 : Cleanup 7
2012-05-09 15:38:14.311+0000: 22562: debug : virEventPollCleanupHandles:554 : Cleanup 10
2012-05-09 15:38:14.312+0000: 22562: debug : virEventRunDefaultImpl:244 : running default event implementation
2012-05-09 15:38:14.312+0000: 22564: debug : virEventPollInterruptLocked:702 : Skip interrupt, 0 1987651648
2012-05-09 15:38:14.312+0000: 22564: debug : qemuMonitorSend:831 : QEMU_MONITOR_SEND_MSG: mon=0x7ff660000a80 msg={"execute":"human-monitor-command","arguments":{"command-line":"drive_add dummy file=/dev/disk/by-path/ip-XXX.XXX.XXX.XXX:3260-iscsi-iqn.2010-10.org.openstack:volume-0000002b-lun-1,if=none,id=drive-virtio-disk5,format=raw"},"id":"libvirt-22"}^M
 fd=-1
2012-05-09 15:38:14.312+0000: 22562: d

Using nova volume-attach (nova volume-attach 5d91ed13-f88f-4ff0-aca4-f1cd3910256f 43 /dev/vdf) on the same ISCS LUN (Or new ones) produces this error and kills libvirtd:

2012-05-09 15:38:14.308+0000: 22564: debug : virJSONValueToString:1071 : result={"execute":"drive_add","arguments":{"pci_addr":"dummy","opts":"file=/dev/disk/by-path/ip-XXX.XXX.XXX.XXX:3260-iscsi-iqn.2010-10.org.openstack:volume-0000002b-lun-1,if=none,id=drive-virtio-disk5,format=raw"},"id":"libvirt-21"}
2012-05-09 15:38:14.308+0000: 22564: debug : qemuMonitorJSONCommandWithFd:228 : Send command '{"execute":"drive_add","arguments":{"pci_addr":"dummy","opts":"file=/dev/disk/by-path/ip-XXX.XXX.XXX.XXX:3260-iscsi-iqn.2010-10.org.openstack:volume-0000002b-lun-1,if=none,id=drive-virtio-disk5,format=raw"},"id":"libvirt-21"}' for write with FD -1
2012-05-09 15:38:14.308+0000: 22564: debug : virEventPollUpdateHandle:151 : EVENT_POLL_UPDATE_HANDLE: watch=8 events=15
2012-05-09 15:38:14.308+0000: 22564: debug : virEventPollInterruptLocked:706 : Interrupting
2012-05-09 15:38:14.308+0000: 22564: debug : qemuMonitorSend:831 : QEMU_MONITOR_SEND_MSG: mon=0x7ff660000a80 msg={"execute":"drive_add","arguments":{"pci_addr":"du...

[Launchpad Janitor (janitor)]

Status changed to 'Confirmed' because the bug affects multiple users.

[Hendrik Volkmer (hvolkmer)]

I can reproduce this using Ubuntu LTS 12.04 and 0.9.8-2ubuntu17 as mentioned. I use OpenStack nova (2012.1-0ubuntu2) and (openstack-dashboard 2012.1-0ubuntu8). However the same problem occurs when the nova command line client is used.

The nova.conf part relevant for nova-volume looks like this:

volume_group=nova-volumes
volume_name_template=volume-%08x
iscsi_helper=tgtadm

The iSCSI device on the nova-volume side is created successfully and is usable from the physical host. I can attach and use the device using "virsh" but now using OpenStack.

Replacing the line

virt_dom.attachDevice(xml)

in /usr/share/pyshared/nova/virt/libvirt/connection.py with

                LOG.info("Attaching device with virsh because attachDevice does not work")
                device_path = connection_info['data']['device_path']
                utils.execute('virsh', "attach-disk", instance_name, device_path, mount_device, run_as_root=True)

and adding

                filters.CommandFilter("/usr/bin/virsh", "root"),

to /usr/share/pyshared/nova/rootwrap/compute.py

works.

This behaviour is rather strange as I am sure it worked before.

This I tried:
 - restarting all nova services (on compute host and controller which is also the nova volume host)
 - restarting libvirt-bin
 - restarting tgtd on nova-volume host

I also tried to manually attach the volume using the libvirt-python bindings like this:

conn=libvirt.open("qemu:///system")
dom = conn.lookupByName("instance-00000047")

xml="""<disk type='block'>
                     <driver name='qemu' type='raw' cache='none'/>
                     <source dev='/dev/disk/by-path/ip-192.168.124.81:3260-iscsi-iqn.2010-10.org.openstack:volume-00000009-lun-1'/>
                     <target dev='vdc' bus='virtio'/>
                 </disk>"""

dom.attachDevice(xml)

The result was the same as with OpenStack: The API call hangs and the libvirt log does not show any other info as already posted above.

Attaching the volume via CLI using "virsh" does work.

Detaching the volume also works with Python using dom.detachDevice(xml).

[Chuck Short (zulcss)]

Can you attach your /var/log/nova/nova-compute.log when this happens as well?

Thanks
chuck

[Lorin Hochstein (lorinh)]

Added OpenStack Compute (nova) as an affected project, since I hit this as an OpenStack user and had a hard time finding this bug report.

[Dan Bode (bodepd)]

I also ran into this issue and have verified that the recommended patch resolves the issue for Ubuntu Precise.

[Hendrik Volkmer (hvolkmer)]

Dan, when you say "recommended patch" do you mean my hackish way of using virsh instead of the libvirt API? Or is there a real fix for the bug in libvirt?

[Dan Bode (bodepd)]

referring to your hackish patch. I could absolutely not figure out what the issue is with libvirt. I was going to refactor your patch to use the python bindings.

In the shorterm, I am going to use Puppet to patch nova-volumes

(https://github.com/bodepd/puppetlabs-nova/commit/3b6e838191a619d33c9fc036b9f5fbfca0435dc7)

. In the longer term, I am working with some other folks to figure out the real fix.

By the way, what hardware is everyone seeing this on?

[Dan Bode (bodepd)]

one note here:

There are actually no python bindings for attachDisk.

[Soren Hansen (soren)]

Right, attach-disk is a virshism. It's not in the C api either.

[Thierry Carrez (ttx)]

Is this a libvirt issue, or should it be workarounded in Nova ?

[Daniel Berrange (berrange)]

You can see here that libvirt is attempting to run the 'drive_add' command, using QMP (JSON) monitor:

QEMU_MONITOR_IO_WRITE: mon=0x7f242c000a80 buf={"execute":"drive_add","arguments":{"pci_addr":"dummy","opts":"file=/dev/disk/by-path/ip-XXX.XXX.XXX.XXX:3260-iscsi-iqn.2010-10.org.openstack:volume-0000002b-lun-1,if=none,id=drive-virtio-disk5,format=raw,cache=none"},"id":"libvirt-7"}

The problem is that although it existed in the HMP monitor, the QEMU developers decided *not* to make drive_add available in QMP monitor.

They did however add a 'hmp_passthrough' command to let you invoke HMP commands via QMP. Assuming you have a new enough QEMU and new enough libvirt, libvirt will not use hmp_passthrough to invoke 'drive_add'.

Since this is not happening for the bug reporter, either their QEMU or libvirt (or both) packages must be too old.

[Soren Hansen (soren)]

virsh has no back doors into libvirt. It consumes the C API directly, so if we mimic what virsh does (with the Python API, though), we should be golden. In fact, I'm fairly sure that's how the current code was written (i.e. by looking at what virsh did), but clearly something got messed up somewhere.

Shelling out to virsh makes me cry.

[Soren Hansen (soren)]

tl;dr: Don't please don't close this bug right now. There's still work to do.

13:52 < ttx> soren: could you comment on the right way to fix https://bugs.launchpad.net/nova/+bug/996840 ?
13:52 < uvirtbot`> Launchpad bug 996840 in libvirt "Libvirt error when trying to mount ISCSI volumes" [Medium,Confirmed]
14:01 < danpb> ttx: it is a combination of a QEMU and libvirt issue
14:01 < ttx> danpb: right.. nothing to fix in Nova there, right ?
14:02 <+soren> ttx: Will do.
14:02 < ttx> soren: if it's a combination of a QEMU and libvirt issue, just redirect the bug to the corresponding packages and invalidate the nova task
14:04 <+soren> danpb: Well, it works when usingn attach-disk in virsh.
14:05 <+soren> danpb: So clearly there's a way to make it work with the same versions of libvirt and qemu.
14:06 <+soren> ttx: Don't close the nova bug. There's still work to do here. At the very least, we should rip out the virsh call as soon as we can. This bug would help us track that.
14:06 < ttx> ok, just add a comment so that nobody closes it. It's bugsquashing day so the temptation is high
14:06 < ttx> soren: ^
14:07 * soren adds another comment.

[Daniel Berrange (berrange)]

Hmm this log from comment #2

-05-09 15:38:14.311+0000: 22564: debug : virJSONValueToString:1071 : result={"execute":"human-monitor-command","arguments":{"command-line":"drive_add dummy file=/dev/disk/by-path/ip-XXX.XXX.XXX.XXX:3260-iscsi-iqn.2010-10.org.openstack:volume-0000002b-lun-1,if=none,id=drive-virtio-disk5,format=raw"},"id":"libvirt-22"}

shows that the reporters' libvirt +QEMU are capable of doing the right thing and using human-monitor-command. So assuming this virsh demo was done against the same libvirtd instance, I think the most likely explanation is that Nova and virsh are somehow generating different XML, which causes different libvirt behaviour. We need to find out what XML virsh attach-interface creates.

[Soren Hansen (soren)]

danpb, did you ever have a chance to look into this?

[Soren Hansen (soren)]

Actually, I just instrumented both nova and virsh to dump the respective XML they build. These are the results:

Nova:
<disk type='block'>
  <driver name='qemu' type='raw' cache='none'/>
  <source dev='/dev/disk/by-path/ip-172.29.74.59:3260-iscsi-iqn.2010-10.org.openstack:volume-00000006-lun-1'/>
  <target dev='vdc' bus='virtio'/>
</disk>

Virsh:
<disk type='block'>
  <source dev='/dev/disk/by-path/ip-172.29.74.59:3260-iscsi-iqn.2010-10.org.openstack:volume-00000006-lun-1'/>
  <target dev='vdd'/>
</disk>

[Soren Hansen (soren)]

In my reading of libvirt:

   bus='virtio' is implied due to the device name beginning with "vd". So these are equal and unlikely to be the culprit.
   driver name="qemu" is the default for the qemu driver. Also equal, unlikely to be the culprit.
   driver type="raw" is the default for the qemu driver. Also equal, so unlikely to be the culprit.

The only thing left is the caching strategy. Virsh doesn't set one at all, so (AFAICT) no "cache=XXX" is passed to QEmu. When cache='none' is passed in the XML, def->cachemode gets set to VIR_DOMAIN_DISK_CACHE_DISABLE. For QEMU_CAPS_DRIVE_CACHE_V2 translates into ",cache=none". This seems like the only difference.

Just removing the <driver> tag should do the trick, really. The XML would end up being functionally identical to virsh's.

[Soren Hansen (soren)]

Obviously, this is also just a workaround (there's no reason passing cache="none" should cause libvirt or qemu or whatever to get stuck), but a rather more elegant one than shelling out to virsh.

[Edmund Haselwanter (ehaselwanter)]

so what is the current state, or way to go for nova-volume in essex?

- use the virsh fix?
- the updated xml (if so, is there a patch for this?)

either way if its not somehow merged it will never appear in os packages and we have to patch a package install for nova volume to work

[Daniel Berrange (berrange)]

@soren I built a copy of libvirt 0.9.8 and tried those two XML examples you show in comment #18. In both cases hotplug succeeds without error. Can you actually reproduce the bug using either of those two XML snippets in combination with 'virsh attach-device' ?

[Jerry Smith (jsmithabq)]

I hesitate to ask, because I know everyone is busy working on something...

But, here goes: does anyone have any updates to current status for this bug? I'm using mostly Ubuntu cloud platforms, but will add a significant number of RHEL compute nodes in the near future? Everything is behind a firewall with no Internet access, so I typically import (entire) mirror repositories, etc. I have several security-related agreements across enterprises that I like to adhere to with limited exceptions, e.g., preference for LTS releases, reluctance to use backports, etc.

I have multiple Essex private clouds up and running, lots of instances per cloud, etc., so I have to decide between pushing (across all platforms) a source-code workaround versus using a backports or cloud-archive solution. I haven't (yet) done off-site testing to verify whether or not the backports or the cloud archive address this bug because I have been watching this space. I'm wondering what other folks are doing on Essex platforms? A wholesale OpenStack upgrade will be a massive number of person-hours of work...

Thanks.

[Justin Shepherd (jshepher)]

Marking this issue as won't fix, as the bug is in reference to Essex and has not been updated in a year and a half.

[Justin Shepherd (jshepher)]

err.. i mean invalid