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= 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