yahoo-eng-team team mailing list archive

Thread
Date
[Bug 996840] Re: Libvirt error when trying to mount ISCSI volumes

To: yahoo-eng-team@xxxxxxxxxxxxxxxxxxx
From: Justin Shepherd <jshepher@xxxxxxxxxxxxx>
Date: Thu, 05 Jun 2014 01:33:58 -0000
Reply-to: Bug 996840 <996840@xxxxxxxxxxxxxxxxxx>
Sender: bounces@xxxxxxxxxxxxx
err.. i mean invalid

** Changed in: nova
       Status: Confirmed => Invalid

** Changed in: libvirt (Ubuntu)
       Status: Confirmed => Invalid

-- 
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/996840

Title:
  Libvirt error when trying to mount ISCSI volumes

Status in OpenStack Compute (Nova):
  Invalid
Status in “libvirt” package in Ubuntu:
  Invalid

Bug description:
  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

To manage notifications about this bug go to:
https://bugs.launchpad.net/nova/+bug/996840/+subscriptions