Hi, When doing live migration with iperf running on the migrated VM over PV/virtio interface -- it doesn't end when the number of threads > 1 :( nor when we run an IO (fio) benchmark which gets high-throughput. None of these tests run over the network the migration is carried out.
We get this "error: operation failed: migration job: unexpectedly failed" The networking/IO benchmarks which executes at the time of migration runs over PV/virtio-->vhost-->Mellanox fast Eth NIC. In our env, with two threads the BW is ~20Gbs and with one thread ~10Gbs, IO BW can be around 600MB/s. Using the verbose option of virsh we see the migration status goes up to 99% and stays there for couple of seconds and then migration fails. If we used the --unsafe option it does end and goes from 99% to 100% at some point. I wonder if there is something we do wrong or can optimize... we're using upstream kernel 4.3 on both hosts and guest, the host OS is RHEL 7.0 based e.g with qemu qemu-kvm-1.5.3-60.el7.x86_64 - rings some bell? would it help to upgrade qemu? Is there an option to get the live migration process to give up on looping over dirty pages and stop the v-cpu on the migrate-out host so this migration actually ends? We're attaching debug messages from virsh for the time of migration, you can see there it's on 99% for couple of seconds and then gives up. Or. 2015-11-24 14:13:47.190+0000: 34957: debug : virKeepAliveCheckMessage:374 : ka=0x55d161e4e230, client=0x55d161e4df40, msg=0x55d161e4dfa8 2015-11-24 14:13:47.190+0000: 34957: debug : virNetMessageClear:55 : msg=0x55d161e4dfa8 nfds=0 2015-11-24 14:13:47.190+0000: 34957: debug : virNetClientIOEventLoopRemoveDone:1376 : Waking up sleep 0x55d161e4e520 2015-11-24 14:13:47.190+0000: 34955: debug : virNetClientIO:1750 : Woken up from sleep head=0x7f3644001d40 call=0x55d161e4e520 2015-11-24 14:13:47.190+0000: 34955: debug : virNetClientIO:1803 : All done with our call head=0x7f3644001d40 call=0x55d161e4e520 rv=0 2015-11-24 14:13:47.190+0000: 34955: debug : virNetMessageFree:72 : msg=0x55d161e4e7d0 nfds=0 cb=(nil) Migration: [ 99 %]2015-11-24 14:13:47.574+0000: 34956: debug : virEventPollRunOnce:638 : Poll got 1 event(s) The above is the last time we see the "Migration: [ 99 %]" running progress bar 2015-11-24 14:13:47.574+0000: 34956: debug : virEventPollDispatchTimeouts:423 : Dispatch 0 2015-11-24 14:13:47.574+0000: 34956: debug : virEventPollDispatchHandles:468 : Dispatch 2 2015-11-24 14:13:47.574+0000: 34956: debug : virEventPollDispatchHandles:482 : i=0 w=1 2015-11-24 14:13:47.574+0000: 34956: debug : virEventPollDispatchHandles:482 : i=2 w=3 2015-11-24 14:13:47.574+0000: 34956: debug : virEventPollDispatchHandles:496 : EVENT_POLL_DISPATCH_HANDLE: watch=3 events=1 2015-11-24 14:13:47.574+0000: 34956: debug : virNetClientIncomingEvent:1816 : client=0x7f36440019a0 wantclose=0 2015-11-24 14:13:47.574+0000: 34956: debug : virNetClientIncomingEvent:1824 : Event fired 0x7f3644001760 1 2015-11-24 14:13:47.574+0000: 34956: debug : virNetMessageDecodeLength:149 : Got length, now need 28 total (24 more) 2015-11-24 14:13:47.574+0000: 34956: debug : virNetClientCallDispatch:1123 : RPC_CLIENT_MSG_RX: client=0x7f36440019a0 len=28 prog=1801807216 vers=1 proc=1 type=2 status=0 serial=0 2015-11-24 14:13:47.574+0000: 34956: debug : virKeepAliveCheckMessage:374 : ka=0x7f36440015f0, client=0x7f36440019a0, msg=0x7f3644001a08 2015-11-24 14:13:47.574+0000: 34956: debug : virKeepAliveCheckMessage:391 : RPC_KEEPALIVE_RECEIVED: ka=0x7f36440015f0 client=0x7f36440019a0 prog=1801807216 vers=1 proc=1 and later we see "error: operation failed: migration job: unexpectedly failed" 015-11-24 14:13:47.766+0000: 34957: debug : virNetClientCloseInternal:687 : client=0x7f36440019a0 wantclose=0 2015-11-24 14:13:47.766+0000: 34956: debug : virFileClose:90 : Closed fd 16 2015-11-24 14:13:47.767+0000: 34957: debug : virObjectUnref:256 : OBJECT_UNREF: obj=0x7f36440019a0 2015-11-24 14:13:47.767+0000: 34956: debug : virProcessAbort:104 : aborting child process 34958 2015-11-24 14:13:47.767+0000: 34956: debug : virProcessAbort:109 : process has ended: exit status 1 2015-11-24 14:13:47.767+0000: 34956: debug : virEventRunDefaultImpl:270 : running default event implementation 2015-11-24 14:13:47.767+0000: 34956: debug : virEventPollCleanupTimeouts:514 : Cleanup 0 2015-11-24 14:13:47.767+0000: 34956: debug : virEventPollCleanupTimeouts:550 : Found 0 out of 0 timeout slots used, releasing 0 2015-11-24 14:13:47.767+0000: 34956: debug : virEventPollCleanupHandles:562 : Cleanup 2 2015-11-24 14:13:47.767+0000: 34956: debug : virEventPollMakePollFDs:391 : Prepare n=0 w=1, f=7 e=1 d=0 2015-11-24 14:13:47.767+0000: 34956: debug : virEventPollMakePollFDs:391 : Prepare n=1 w=2, f=9 e=1 d=0 2015-11-24 14:13:47.767+0000: 34956: debug : virEventPollCalculateTimeout:332 : Calculate expiry of 0 timers 2015-11-24 14:13:47.767+0000: 34956: debug : virEventPollCalculateTimeout:361 : Timeout at 0 due in -1 ms 2015-11-24 14:13:47.767+0000: 34956: debug : virEventPollRunOnce:627 : EVENT_POLL_RUN: nhandles=2 timeout=-1 2015-11-24 14:13:47.767+0000: 34957: debug : virObjectUnref:258 : OBJECT_DISPOSE: obj=0x7f36440019a0 2015-11-24 14:13:47.767+0000: 34957: debug : virNetClientDispose:599 : RPC_CLIENT_DISPOSE: client=0x7f36440019a0 2015-11-24 14:13:47.767+0000: 34957: debug : virObjectUnref:256 : OBJECT_UNREF: obj=0x7f3644010c80 2015-11-24 14:13:47.767+0000: 34957: debug : virObjectUnref:256 : OBJECT_UNREF: obj=0x7f3644001da0 2015-11-24 14:13:47.767+0000: 34957: debug : virObjectUnref:256 : OBJECT_UNREF: obj=0x7f3644001510 2015-11-24 14:13:47.767+0000: 34957: debug : virObjectUnref:256 : OBJECT_UNREF: obj=0x7f3644001bc0 2015-11-24 14:13:47.767+0000: 34957: debug : virFileClose:90 : Closed fd 17 2015-11-24 14:13:47.767+0000: 34957: debug : virFileClose:90 : Closed fd 15 2015-11-24 14:13:47.767+0000: 34957: debug : virNetMessageClear:55 : msg=0x7f3644001a08 nfds=0 2015-11-24 14:13:47.767+0000: 34957: debug : virObjectUnref:256 : OBJECT_UNREF: obj=0x7f3644001da0 2015-11-24 14:13:47.767+0000: 34957: debug : virObjectUnref:258 : OBJECT_DISPOSE: obj=0x7f3644001da0 2015-11-24 14:13:47.767+0000: 34957: debug : virObjectUnref:256 : OBJECT_UNREF: obj=0x7f3644001510 2015-11-24 14:13:47.767+0000: 34957: debug : virObjectUnref:258 : OBJECT_DISPOSE: obj=0x7f3644001510 2015-11-24 14:13:47.767+0000: 34957: debug : virObjectUnref:256 : OBJECT_UNREF: obj=0x7f3644001bc0 2015-11-24 14:13:47.767+0000: 34957: debug : virObjectUnref:258 : OBJECT_DISPOSE: obj=0x7f3644001bc0 2015-11-24 14:13:47.767+0000: 34957: debug : virObjectUnref:256 : OBJECT_UNREF: obj=0x7f3644010c80 2015-11-24 14:13:47.767+0000: 34957: debug : virObjectUnref:258 : OBJECT_DISPOSE: obj=0x7f3644010c80 2015-11-24 14:13:47.767+0000: 34957: debug : virDomainFree:2428 : dom=0x7f3644000c30, (VM: name=dev-h-vrt-008-006, uuid=04e20bfc-89e6-4098-bace-6a78c3e50919) 2015-11-24 14:13:47.767+0000: 34957: debug : virObjectUnref:256 : OBJECT_UNREF: obj=0x7f3644000c30 2015-11-24 14:13:47.767+0000: 34957: debug : virObjectUnref:258 : OBJECT_DISPOSE: obj=0x7f3644000c30 2015-11-24 14:13:47.767+0000: 34957: debug : virDomainDispose:262 : release domain 0x7f3644000c30 dev-h-vrt-008-006 04e20bfc-89e6-4098-bace-6a78c3e50919 2015-11-24 14:13:47.767+0000: 34957: debug : virObjectUnref:256 : OBJECT_UNREF: obj=0x55d161e4d340 2015-11-24 14:13:47.767+0000: 34955: debug : virDomainFree:2428 : dom=0x55d161e4d2d0, (VM: name=dev-h-vrt-008-006, uuid=04e20bfc-89e6-4098-bace-6a78c3e50919) 2015-11-24 14:13:47.767+0000: 34955: debug : virObjectUnref:256 : OBJECT_UNREF: obj=0x55d161e4d2d0 2015-11-24 14:13:47.767+0000: 34955: debug : virObjectUnref:258 : OBJECT_DISPOSE: obj=0x55d161e4d2d0 2015-11-24 14:13:47.767+0000: 34955: debug : virDomainDispose:262 : release domain 0x55d161e4d2d0 dev-h-vrt-008-006 04e20bfc-89e6-4098-bace-6a78c3e50919 2015-11-24 14:13:47.767+0000: 34955: debug : virObjectUnref:256 : OBJECT_UNREF: obj=0x55d161e4d340 2015-11-24 14:13:47.767+0000: 34955: debug : virFileClose:90 : Closed fd 12 2015-11-24 14:13:47.767+0000: 34955: debug : virFileClose:90 : Closed fd 13 error: operation failed: migration job: unexpectedly failed
Migration: [ 99 %]2015-11-24 14:13:47.189+0000: 34955: debug : virDomainGetJobInfo:18667 : dom=0x55d161e4d2d0, (VM: name=dev-h-vrt-008-006, uuid=04e20bfc-89e6-4098-bace-6a78c3e50919), info=0x7fff8bcfe800 2015-11-24 14:13:47.189+0000: 34955: debug : virNetMessageNew:44 : msg=0x55d161e4e7d0 tracked=0 2015-11-24 14:13:47.189+0000: 34955: debug : virNetMessageEncodePayload:374 : Encode length as 72 2015-11-24 14:13:47.189+0000: 34955: debug : virNetClientSendInternal:1952 : RPC_CLIENT_MSG_TX_QUEUE: client=0x55d161e4df40 len=72 prog=536903814 vers=1 proc=163 type=0 status=0 serial=94 2015-11-24 14:13:47.189+0000: 34955: debug : virNetClientCallNew:1905 : New call 0x55d161e4e520: msg=0x55d161e4e7d0, expectReply=1, nonBlock=0 2015-11-24 14:13:47.189+0000: 34955: debug : virNetClientIO:1714 : Outgoing message prog=536903814 version=1 serial=94 proc=163 type=0 length=72 dispatch=0x7f3644001d40 2015-11-24 14:13:47.189+0000: 34955: debug : virNetClientIO:1740 : Going to sleep head=0x7f3644001d40 call=0x55d161e4e520 2015-11-24 14:13:47.190+0000: 34957: debug : virNetClientIOEventLoop:1554 : Woken up from poll by other thread 2015-11-24 14:13:47.190+0000: 34957: debug : virNetMessageDecodeLength:149 : Got length, now need 120 total (116 more) 2015-11-24 14:13:47.190+0000: 34957: debug : virNetClientCallDispatch:1123 : RPC_CLIENT_MSG_RX: client=0x55d161e4df40 len=120 prog=536903814 vers=1 proc=163 type=1 status=0 serial=94 2015-11-24 14:13:47.190+0000: 34957: debug : virKeepAliveCheckMessage:374 : ka=0x55d161e4e230, client=0x55d161e4df40, msg=0x55d161e4dfa8 2015-11-24 14:13:47.190+0000: 34957: debug : virNetMessageClear:55 : msg=0x55d161e4dfa8 nfds=0 2015-11-24 14:13:47.190+0000: 34957: debug : virNetClientIOEventLoopRemoveDone:1376 : Waking up sleep 0x55d161e4e520 2015-11-24 14:13:47.190+0000: 34955: debug : virNetClientIO:1750 : Woken up from sleep head=0x7f3644001d40 call=0x55d161e4e520 2015-11-24 14:13:47.190+0000: 34955: debug : virNetClientIO:1803 : All done with our call head=0x7f3644001d40 call=0x55d161e4e520 rv=0 2015-11-24 14:13:47.190+0000: 34955: debug : virNetMessageFree:72 : msg=0x55d161e4e7d0 nfds=0 cb=(nil) Migration: [ 99 %]2015-11-24 14:13:47.574+0000: 34956: debug : virEventPollRunOnce:638 : Poll got 1 event(s) 2015-11-24 14:13:47.574+0000: 34956: debug : virEventPollDispatchTimeouts:423 : Dispatch 0 2015-11-24 14:13:47.574+0000: 34956: debug : virEventPollDispatchHandles:468 : Dispatch 2 2015-11-24 14:13:47.574+0000: 34956: debug : virEventPollDispatchHandles:482 : i=0 w=1 2015-11-24 14:13:47.574+0000: 34956: debug : virEventPollDispatchHandles:482 : i=2 w=3 2015-11-24 14:13:47.574+0000: 34956: debug : virEventPollDispatchHandles:496 : EVENT_POLL_DISPATCH_HANDLE: watch=3 events=1 2015-11-24 14:13:47.574+0000: 34956: debug : virNetClientIncomingEvent:1816 : client=0x7f36440019a0 wantclose=0 2015-11-24 14:13:47.574+0000: 34956: debug : virNetClientIncomingEvent:1824 : Event fired 0x7f3644001760 1 2015-11-24 14:13:47.574+0000: 34956: debug : virNetMessageDecodeLength:149 : Got length, now need 28 total (24 more) 2015-11-24 14:13:47.574+0000: 34956: debug : virNetClientCallDispatch:1123 : RPC_CLIENT_MSG_RX: client=0x7f36440019a0 len=28 prog=1801807216 vers=1 proc=1 type=2 status=0 serial=0 2015-11-24 14:13:47.574+0000: 34956: debug : virKeepAliveCheckMessage:374 : ka=0x7f36440015f0, client=0x7f36440019a0, msg=0x7f3644001a08 2015-11-24 14:13:47.574+0000: 34956: debug : virKeepAliveCheckMessage:391 : RPC_KEEPALIVE_RECEIVED: ka=0x7f36440015f0 client=0x7f36440019a0 prog=1801807216 vers=1 proc=1 2015-11-24 14:13:47.574+0000: 34956: debug : virKeepAliveCheckMessage:395 : Got keepalive request from client 0x7f36440019a0 2015-11-24 14:13:47.574+0000: 34956: debug : virNetMessageNew:44 : msg=0x7f364c000fe0 tracked=0 2015-11-24 14:13:47.574+0000: 34956: debug : virNetMessageEncodePayloadEmpty:479 : Encode length as 28 2015-11-24 14:13:47.574+0000: 34956: debug : virKeepAliveMessage:101 : Sending keepalive response to client 0x7f36440019a0 2015-11-24 14:13:47.574+0000: 34956: debug : virKeepAliveMessage:104 : RPC_KEEPALIVE_SEND: ka=0x7f36440015f0 client=0x7f36440019a0 prog=1801807216 vers=1 proc=2 2015-11-24 14:13:47.574+0000: 34956: debug : virNetClientQueueNonBlocking:1926 : RPC_CLIENT_MSG_TX_QUEUE: client=0x7f36440019a0 len=28 prog=1801807216 vers=1 proc=2 type=2 status=0 serial=0 2015-11-24 14:13:47.574+0000: 34956: debug : virNetClientCallNew:1905 : New call 0x7f364c000cd0: msg=0x7f364c000fe0, expectReply=0, nonBlock=1 2015-11-24 14:13:47.574+0000: 34956: debug : virNetMessageClear:55 : msg=0x7f3644001a08 nfds=0 2015-11-24 14:13:47.574+0000: 34956: debug : virEventPollUpdateHandle:147 : EVENT_POLL_UPDATE_HANDLE: watch=3 events=3 2015-11-24 14:13:47.574+0000: 34956: debug : virEventPollInterruptLocked:710 : Skip interrupt, 1 139871269107456 2015-11-24 14:13:47.574+0000: 34956: debug : virEventPollCleanupTimeouts:514 : Cleanup 0 2015-11-24 14:13:47.574+0000: 34956: debug : virEventPollCleanupTimeouts:550 : Found 0 out of 0 timeout slots used, releasing 0 2015-11-24 14:13:47.574+0000: 34956: debug : virEventPollCleanupHandles:562 : Cleanup 3 2015-11-24 14:13:47.574+0000: 34956: debug : virEventRunDefaultImpl:270 : running default event implementation 2015-11-24 14:13:47.574+0000: 34956: debug : virEventPollCleanupTimeouts:514 : Cleanup 0 2015-11-24 14:13:47.574+0000: 34956: debug : virEventPollCleanupTimeouts:550 : Found 0 out of 0 timeout slots used, releasing 0 2015-11-24 14:13:47.574+0000: 34956: debug : virEventPollCleanupHandles:562 : Cleanup 3 2015-11-24 14:13:47.574+0000: 34956: debug : virEventPollMakePollFDs:391 : Prepare n=0 w=1, f=7 e=1 d=0 2015-11-24 14:13:47.574+0000: 34956: debug : virEventPollMakePollFDs:391 : Prepare n=1 w=2, f=9 e=0 d=0 2015-11-24 14:13:47.574+0000: 34956: debug : virEventPollMakePollFDs:391 : Prepare n=2 w=3, f=14 e=5 d=0 2015-11-24 14:13:47.574+0000: 34956: debug : virEventPollCalculateTimeout:332 : Calculate expiry of 0 timers 2015-11-24 14:13:47.574+0000: 34956: debug : virEventPollCalculateTimeout:361 : Timeout at 0 due in -1 ms 2015-11-24 14:13:47.574+0000: 34956: debug : virEventPollRunOnce:627 : EVENT_POLL_RUN: nhandles=2 timeout=-1 2015-11-24 14:13:47.574+0000: 34956: debug : virEventPollRunOnce:638 : Poll got 1 event(s) 2015-11-24 14:13:47.574+0000: 34956: debug : virEventPollDispatchTimeouts:423 : Dispatch 0 2015-11-24 14:13:47.574+0000: 34956: debug : virEventPollDispatchHandles:468 : Dispatch 2 2015-11-24 14:13:47.574+0000: 34956: debug : virEventPollDispatchHandles:482 : i=0 w=1 2015-11-24 14:13:47.574+0000: 34956: debug : virEventPollDispatchHandles:482 : i=2 w=3 2015-11-24 14:13:47.574+0000: 34956: debug : virEventPollDispatchHandles:496 : EVENT_POLL_DISPATCH_HANDLE: watch=3 events=3 2015-11-24 14:13:47.574+0000: 34956: debug : virNetClientIncomingEvent:1816 : client=0x7f36440019a0 wantclose=0 2015-11-24 14:13:47.574+0000: 34956: debug : virNetClientIncomingEvent:1824 : Event fired 0x7f3644001760 3 2015-11-24 14:13:47.574+0000: 34956: debug : virNetMessageDecodeLength:149 : Got length, now need 28 total (24 more) 2015-11-24 14:13:47.574+0000: 34956: debug : virNetClientCallDispatch:1123 : RPC_CLIENT_MSG_RX: client=0x7f36440019a0 len=28 prog=1801807216 vers=1 proc=1 type=2 status=0 serial=0 2015-11-24 14:13:47.574+0000: 34956: debug : virKeepAliveCheckMessage:374 : ka=0x7f36440015f0, client=0x7f36440019a0, msg=0x7f3644001a08 2015-11-24 14:13:47.574+0000: 34956: debug : virKeepAliveCheckMessage:391 : RPC_KEEPALIVE_RECEIVED: ka=0x7f36440015f0 client=0x7f36440019a0 prog=1801807216 vers=1 proc=1 2015-11-24 14:13:47.574+0000: 34956: debug : virKeepAliveCheckMessage:395 : Got keepalive request from client 0x7f36440019a0 2015-11-24 14:13:47.574+0000: 34956: debug : virNetMessageNew:44 : msg=0x7f364c000a30 tracked=0 2015-11-24 14:13:47.574+0000: 34956: debug : virNetMessageEncodePayloadEmpty:479 : Encode length as 28 2015-11-24 14:13:47.574+0000: 34956: debug : virKeepAliveMessage:101 : Sending keepalive response to client 0x7f36440019a0 2015-11-24 14:13:47.574+0000: 34956: debug : virKeepAliveMessage:104 : RPC_KEEPALIVE_SEND: ka=0x7f36440015f0 client=0x7f36440019a0 prog=1801807216 vers=1 proc=2 2015-11-24 14:13:47.574+0000: 34956: debug : virNetClientQueueNonBlocking:1926 : RPC_CLIENT_MSG_TX_QUEUE: client=0x7f36440019a0 len=28 prog=1801807216 vers=1 proc=2 type=2 status=0 serial=0 2015-11-24 14:13:47.574+0000: 34956: debug : virNetClientCallNew:1905 : New call 0x7f364c000db0: msg=0x7f364c000a30, expectReply=0, nonBlock=1 2015-11-24 14:13:47.574+0000: 34956: debug : virNetMessageClear:55 : msg=0x7f3644001a08 nfds=0 2015-11-24 14:13:47.574+0000: 34956: debug : virNetClientIOEventLoopRemoveDone:1379 : Removing completed call 0x7f364c000cd0 2015-11-24 14:13:47.574+0000: 34956: debug : virEventPollUpdateHandle:147 : EVENT_POLL_UPDATE_HANDLE: watch=3 events=3 2015-11-24 14:13:47.574+0000: 34956: debug : virEventPollInterruptLocked:710 : Skip interrupt, 1 139871269107456 2015-11-24 14:13:47.574+0000: 34956: debug : virEventPollCleanupTimeouts:514 : Cleanup 0 2015-11-24 14:13:47.574+0000: 34956: debug : virEventPollCleanupTimeouts:550 : Found 0 out of 0 timeout slots used, releasing 0 2015-11-24 14:13:47.574+0000: 34956: debug : virEventPollCleanupHandles:562 : Cleanup 3 2015-11-24 14:13:47.574+0000: 34956: debug : virEventRunDefaultImpl:270 : running default event implementation 2015-11-24 14:13:47.574+0000: 34956: debug : virEventPollCleanupTimeouts:514 : Cleanup 0 2015-11-24 14:13:47.574+0000: 34956: debug : virEventPollCleanupTimeouts:550 : Found 0 out of 0 timeout slots used, releasing 0 2015-11-24 14:13:47.574+0000: 34956: debug : virEventPollCleanupHandles:562 : Cleanup 3 2015-11-24 14:13:47.574+0000: 34956: debug : virEventPollMakePollFDs:391 : Prepare n=0 w=1, f=7 e=1 d=0 2015-11-24 14:13:47.574+0000: 34956: debug : virEventPollMakePollFDs:391 : Prepare n=1 w=2, f=9 e=0 d=0 2015-11-24 14:13:47.574+0000: 34956: debug : virEventPollMakePollFDs:391 : Prepare n=2 w=3, f=14 e=5 d=0 2015-11-24 14:13:47.574+0000: 34956: debug : virEventPollCalculateTimeout:332 : Calculate expiry of 0 timers 2015-11-24 14:13:47.574+0000: 34956: debug : virEventPollCalculateTimeout:361 : Timeout at 0 due in -1 ms 2015-11-24 14:13:47.574+0000: 34956: debug : virEventPollRunOnce:627 : EVENT_POLL_RUN: nhandles=2 timeout=-1 2015-11-24 14:13:47.574+0000: 34956: debug : virEventPollRunOnce:638 : Poll got 1 event(s) 2015-11-24 14:13:47.574+0000: 34956: debug : virEventPollDispatchTimeouts:423 : Dispatch 0 2015-11-24 14:13:47.574+0000: 34956: debug : virEventPollDispatchHandles:468 : Dispatch 2 2015-11-24 14:13:47.574+0000: 34956: debug : virEventPollDispatchHandles:482 : i=0 w=1 2015-11-24 14:13:47.574+0000: 34956: debug : virEventPollDispatchHandles:482 : i=2 w=3 2015-11-24 14:13:47.574+0000: 34956: debug : virEventPollDispatchHandles:496 : EVENT_POLL_DISPATCH_HANDLE: watch=3 events=3 2015-11-24 14:13:47.574+0000: 34956: debug : virNetClientIncomingEvent:1816 : client=0x7f36440019a0 wantclose=0 2015-11-24 14:13:47.574+0000: 34956: debug : virNetClientIncomingEvent:1824 : Event fired 0x7f3644001760 3 2015-11-24 14:13:47.574+0000: 34956: debug : virNetMessageDecodeLength:149 : Got length, now need 28 total (24 more) 2015-11-24 14:13:47.574+0000: 34956: debug : virNetClientCallDispatch:1123 : RPC_CLIENT_MSG_RX: client=0x7f36440019a0 len=28 prog=1801807216 vers=1 proc=1 type=2 status=0 serial=0 2015-11-24 14:13:47.574+0000: 34956: debug : virKeepAliveCheckMessage:374 : ka=0x7f36440015f0, client=0x7f36440019a0, msg=0x7f3644001a08 2015-11-24 14:13:47.574+0000: 34956: debug : virKeepAliveCheckMessage:391 : RPC_KEEPALIVE_RECEIVED: ka=0x7f36440015f0 client=0x7f36440019a0 prog=1801807216 vers=1 proc=1 2015-11-24 14:13:47.575+0000: 34956: debug : virKeepAliveCheckMessage:395 : Got keepalive request from client 0x7f36440019a0 2015-11-24 14:13:47.575+0000: 34956: debug : virNetMessageNew:44 : msg=0x7f364c000aa0 tracked=0 2015-11-24 14:13:47.575+0000: 34956: debug : virNetMessageEncodePayloadEmpty:479 : Encode length as 28 2015-11-24 14:13:47.575+0000: 34956: debug : virKeepAliveMessage:101 : Sending keepalive response to client 0x7f36440019a0 2015-11-24 14:13:47.575+0000: 34956: debug : virKeepAliveMessage:104 : RPC_KEEPALIVE_SEND: ka=0x7f36440015f0 client=0x7f36440019a0 prog=1801807216 vers=1 proc=2 2015-11-24 14:13:47.575+0000: 34956: debug : virNetClientQueueNonBlocking:1926 : RPC_CLIENT_MSG_TX_QUEUE: client=0x7f36440019a0 len=28 prog=1801807216 vers=1 proc=2 type=2 status=0 serial=0 2015-11-24 14:13:47.575+0000: 34956: debug : virNetClientCallNew:1905 : New call 0x7f364c000e10: msg=0x7f364c000aa0, expectReply=0, nonBlock=1 2015-11-24 14:13:47.575+0000: 34956: debug : virNetMessageClear:55 : msg=0x7f3644001a08 nfds=0 2015-11-24 14:13:47.575+0000: 34956: debug : virNetClientIOEventLoopRemoveDone:1379 : Removing completed call 0x7f364c000db0 2015-11-24 14:13:47.575+0000: 34956: debug : virEventPollUpdateHandle:147 : EVENT_POLL_UPDATE_HANDLE: watch=3 events=3 2015-11-24 14:13:47.575+0000: 34956: debug : virEventPollInterruptLocked:710 : Skip interrupt, 1 139871269107456 2015-11-24 14:13:47.575+0000: 34956: debug : virEventPollCleanupTimeouts:514 : Cleanup 0 2015-11-24 14:13:47.575+0000: 34956: debug : virEventPollCleanupTimeouts:550 : Found 0 out of 0 timeout slots used, releasing 0 2015-11-24 14:13:47.575+0000: 34956: debug : virEventPollCleanupHandles:562 : Cleanup 3 2015-11-24 14:13:47.575+0000: 34956: debug : virEventRunDefaultImpl:270 : running default event implementation 2015-11-24 14:13:47.575+0000: 34956: debug : virEventPollCleanupTimeouts:514 : Cleanup 0 2015-11-24 14:13:47.575+0000: 34956: debug : virEventPollCleanupTimeouts:550 : Found 0 out of 0 timeout slots used, releasing 0 2015-11-24 14:13:47.575+0000: 34956: debug : virEventPollCleanupHandles:562 : Cleanup 3 2015-11-24 14:13:47.575+0000: 34956: debug : virEventPollMakePollFDs:391 : Prepare n=0 w=1, f=7 e=1 d=0 2015-11-24 14:13:47.575+0000: 34956: debug : virEventPollMakePollFDs:391 : Prepare n=1 w=2, f=9 e=0 d=0 2015-11-24 14:13:47.575+0000: 34956: debug : virEventPollMakePollFDs:391 : Prepare n=2 w=3, f=14 e=5 d=0 2015-11-24 14:13:47.575+0000: 34956: debug : virEventPollCalculateTimeout:332 : Calculate expiry of 0 timers 2015-11-24 14:13:47.575+0000: 34956: debug : virEventPollCalculateTimeout:361 : Timeout at 0 due in -1 ms 2015-11-24 14:13:47.575+0000: 34956: debug : virEventPollRunOnce:627 : EVENT_POLL_RUN: nhandles=2 timeout=-1 2015-11-24 14:13:47.575+0000: 34956: debug : virEventPollRunOnce:638 : Poll got 1 event(s) 2015-11-24 14:13:47.575+0000: 34956: debug : virEventPollDispatchTimeouts:423 : Dispatch 0 2015-11-24 14:13:47.575+0000: 34956: debug : virEventPollDispatchHandles:468 : Dispatch 2 2015-11-24 14:13:47.575+0000: 34956: debug : virEventPollDispatchHandles:482 : i=0 w=1 2015-11-24 14:13:47.575+0000: 34956: debug : virEventPollDispatchHandles:482 : i=2 w=3 2015-11-24 14:13:47.575+0000: 34956: debug : virEventPollDispatchHandles:496 : EVENT_POLL_DISPATCH_HANDLE: watch=3 events=3 2015-11-24 14:13:47.575+0000: 34956: debug : virNetClientIncomingEvent:1816 : client=0x7f36440019a0 wantclose=0 2015-11-24 14:13:47.575+0000: 34956: debug : virNetClientIncomingEvent:1824 : Event fired 0x7f3644001760 3 2015-11-24 14:13:47.575+0000: 34956: debug : virNetMessageDecodeLength:149 : Got length, now need 28 total (24 more) 2015-11-24 14:13:47.575+0000: 34956: debug : virNetClientCallDispatch:1123 : RPC_CLIENT_MSG_RX: client=0x7f36440019a0 len=28 prog=1801807216 vers=1 proc=1 type=2 status=0 serial=0 2015-11-24 14:13:47.575+0000: 34956: debug : virKeepAliveCheckMessage:374 : ka=0x7f36440015f0, client=0x7f36440019a0, msg=0x7f3644001a08 2015-11-24 14:13:47.575+0000: 34956: debug : virKeepAliveCheckMessage:391 : RPC_KEEPALIVE_RECEIVED: ka=0x7f36440015f0 client=0x7f36440019a0 prog=1801807216 vers=1 proc=1 2015-11-24 14:13:47.575+0000: 34956: debug : virKeepAliveCheckMessage:395 : Got keepalive request from client 0x7f36440019a0 2015-11-24 14:13:47.575+0000: 34956: debug : virNetMessageNew:44 : msg=0x7f364c000960 tracked=0 2015-11-24 14:13:47.575+0000: 34956: debug : virNetMessageEncodePayloadEmpty:479 : Encode length as 28 2015-11-24 14:13:47.575+0000: 34956: debug : virKeepAliveMessage:101 : Sending keepalive response to client 0x7f36440019a0 2015-11-24 14:13:47.575+0000: 34956: debug : virKeepAliveMessage:104 : RPC_KEEPALIVE_SEND: ka=0x7f36440015f0 client=0x7f36440019a0 prog=1801807216 vers=1 proc=2 2015-11-24 14:13:47.575+0000: 34956: debug : virNetClientQueueNonBlocking:1926 : RPC_CLIENT_MSG_TX_QUEUE: client=0x7f36440019a0 len=28 prog=1801807216 vers=1 proc=2 type=2 status=0 serial=0 2015-11-24 14:13:47.575+0000: 34956: debug : virNetClientCallNew:1905 : New call 0x7f364c000db0: msg=0x7f364c000960, expectReply=0, nonBlock=1 2015-11-24 14:13:47.575+0000: 34956: debug : virNetMessageClear:55 : msg=0x7f3644001a08 nfds=0 2015-11-24 14:13:47.575+0000: 34956: debug : virNetClientIOEventLoopRemoveDone:1379 : Removing completed call 0x7f364c000e10 2015-11-24 14:13:47.575+0000: 34956: debug : virEventPollUpdateHandle:147 : EVENT_POLL_UPDATE_HANDLE: watch=3 events=3 2015-11-24 14:13:47.575+0000: 34956: debug : virEventPollInterruptLocked:710 : Skip interrupt, 1 139871269107456 2015-11-24 14:13:47.575+0000: 34956: debug : virEventPollCleanupTimeouts:514 : Cleanup 0 2015-11-24 14:13:47.575+0000: 34956: debug : virEventPollCleanupTimeouts:550 : Found 0 out of 0 timeout slots used, releasing 0 2015-11-24 14:13:47.575+0000: 34956: debug : virEventPollCleanupHandles:562 : Cleanup 3 2015-11-24 14:13:47.575+0000: 34956: debug : virEventRunDefaultImpl:270 : running default event implementation 2015-11-24 14:13:47.575+0000: 34956: debug : virEventPollCleanupTimeouts:514 : Cleanup 0 2015-11-24 14:13:47.575+0000: 34956: debug : virEventPollCleanupTimeouts:550 : Found 0 out of 0 timeout slots used, releasing 0 2015-11-24 14:13:47.575+0000: 34956: debug : virEventPollCleanupHandles:562 : Cleanup 3 2015-11-24 14:13:47.575+0000: 34956: debug : virEventPollMakePollFDs:391 : Prepare n=0 w=1, f=7 e=1 d=0 2015-11-24 14:13:47.575+0000: 34956: debug : virEventPollMakePollFDs:391 : Prepare n=1 w=2, f=9 e=0 d=0 2015-11-24 14:13:47.575+0000: 34956: debug : virEventPollMakePollFDs:391 : Prepare n=2 w=3, f=14 e=5 d=0 2015-11-24 14:13:47.575+0000: 34956: debug : virEventPollCalculateTimeout:332 : Calculate expiry of 0 timers 2015-11-24 14:13:47.575+0000: 34956: debug : virEventPollCalculateTimeout:361 : Timeout at 0 due in -1 ms 2015-11-24 14:13:47.575+0000: 34956: debug : virEventPollRunOnce:627 : EVENT_POLL_RUN: nhandles=2 timeout=-1 2015-11-24 14:13:47.575+0000: 34956: debug : virEventPollRunOnce:638 : Poll got 1 event(s) 2015-11-24 14:13:47.575+0000: 34956: debug : virEventPollDispatchTimeouts:423 : Dispatch 0 2015-11-24 14:13:47.575+0000: 34956: debug : virEventPollDispatchHandles:468 : Dispatch 2 2015-11-24 14:13:47.575+0000: 34956: debug : virEventPollDispatchHandles:482 : i=0 w=1 2015-11-24 14:13:47.575+0000: 34956: debug : virEventPollDispatchHandles:482 : i=2 w=3 2015-11-24 14:13:47.575+0000: 34956: debug : virEventPollDispatchHandles:496 : EVENT_POLL_DISPATCH_HANDLE: watch=3 events=2 2015-11-24 14:13:47.575+0000: 34956: debug : virNetClientIncomingEvent:1816 : client=0x7f36440019a0 wantclose=0 2015-11-24 14:13:47.575+0000: 34956: debug : virNetClientIncomingEvent:1824 : Event fired 0x7f3644001760 2 2015-11-24 14:13:47.575+0000: 34956: debug : virNetClientIOEventLoopRemoveDone:1379 : Removing completed call 0x7f364c000db0 2015-11-24 14:13:47.575+0000: 34956: debug : virEventPollUpdateHandle:147 : EVENT_POLL_UPDATE_HANDLE: watch=3 events=1 2015-11-24 14:13:47.575+0000: 34956: debug : virEventPollInterruptLocked:710 : Skip interrupt, 1 139871269107456 2015-11-24 14:13:47.575+0000: 34956: debug : virEventPollCleanupTimeouts:514 : Cleanup 0 2015-11-24 14:13:47.575+0000: 34956: debug : virEventPollCleanupTimeouts:550 : Found 0 out of 0 timeout slots used, releasing 0 2015-11-24 14:13:47.575+0000: 34956: debug : virEventPollCleanupHandles:562 : Cleanup 3 2015-11-24 14:13:47.575+0000: 34956: debug : virEventRunDefaultImpl:270 : running default event implementation 2015-11-24 14:13:47.575+0000: 34956: debug : virEventPollCleanupTimeouts:514 : Cleanup 0 2015-11-24 14:13:47.575+0000: 34956: debug : virEventPollCleanupTimeouts:550 : Found 0 out of 0 timeout slots used, releasing 0 2015-11-24 14:13:47.575+0000: 34956: debug : virEventPollCleanupHandles:562 : Cleanup 3 2015-11-24 14:13:47.575+0000: 34956: debug : virEventPollMakePollFDs:391 : Prepare n=0 w=1, f=7 e=1 d=0 2015-11-24 14:13:47.575+0000: 34956: debug : virEventPollMakePollFDs:391 : Prepare n=1 w=2, f=9 e=0 d=0 2015-11-24 14:13:47.575+0000: 34956: debug : virEventPollMakePollFDs:391 : Prepare n=2 w=3, f=14 e=1 d=0 2015-11-24 14:13:47.575+0000: 34956: debug : virEventPollCalculateTimeout:332 : Calculate expiry of 0 timers 2015-11-24 14:13:47.575+0000: 34956: debug : virEventPollCalculateTimeout:361 : Timeout at 0 due in -1 ms 2015-11-24 14:13:47.575+0000: 34956: debug : virEventPollRunOnce:627 : EVENT_POLL_RUN: nhandles=2 timeout=-1 2015-11-24 14:13:47.660+0000: 34957: debug : virNetMessageDecodeLength:149 : Got length, now need 192 total (188 more) 2015-11-24 14:13:47.660+0000: 34957: debug : virNetClientCallDispatch:1123 : RPC_CLIENT_MSG_RX: client=0x55d161e4df40 len=192 prog=536903814 vers=1 proc=305 type=1 status=1 serial=11 2015-11-24 14:13:47.660+0000: 34957: debug : virKeepAliveCheckMessage:374 : ka=0x55d161e4e230, client=0x55d161e4df40, msg=0x55d161e4dfa8 2015-11-24 14:13:47.660+0000: 34957: debug : virNetMessageClear:55 : msg=0x55d161e4dfa8 nfds=0 2015-11-24 14:13:47.660+0000: 34957: debug : virNetClientIOEventLoopPassTheBuck:1420 : Giving up the buck 0x7f3644001d40 2015-11-24 14:13:47.660+0000: 34957: debug : virNetClientIOEventLoopPassTheBuck:1434 : No thread to pass the buck to 2015-11-24 14:13:47.660+0000: 34957: debug : virEventPollUpdateHandle:147 : EVENT_POLL_UPDATE_HANDLE: watch=2 events=1 2015-11-24 14:13:47.660+0000: 34957: debug : virEventPollInterruptLocked:714 : Interrupting 2015-11-24 14:13:47.660+0000: 34957: debug : virNetClientIO:1803 : All done with our call head=(nil) call=0x7f3644001d40 rv=0 2015-11-24 14:13:47.660+0000: 34957: debug : virNetMessageFree:72 : msg=0x7f3644001550 nfds=0 cb=(nil) 2015-11-24 14:13:47.660+0000: 34956: debug : virEventPollRunOnce:638 : Poll got 1 event(s) 2015-11-24 14:13:47.660+0000: 34956: debug : virEventPollDispatchTimeouts:423 : Dispatch 0 2015-11-24 14:13:47.660+0000: 34956: debug : virEventPollDispatchHandles:468 : Dispatch 2 2015-11-24 14:13:47.660+0000: 34956: debug : virEventPollDispatchHandles:482 : i=0 w=1 2015-11-24 14:13:47.660+0000: 34956: debug : virEventPollDispatchHandles:496 : EVENT_POLL_DISPATCH_HANDLE: watch=1 events=1 2015-11-24 14:13:47.660+0000: 34956: debug : virEventPollDispatchHandles:482 : i=2 w=3 2015-11-24 14:13:47.660+0000: 34956: debug : virEventPollCleanupTimeouts:514 : Cleanup 0 2015-11-24 14:13:47.660+0000: 34956: debug : virEventPollCleanupTimeouts:550 : Found 0 out of 0 timeout slots used, releasing 0 2015-11-24 14:13:47.660+0000: 34956: debug : virEventPollCleanupHandles:562 : Cleanup 3 2015-11-24 14:13:47.660+0000: 34956: debug : virEventRunDefaultImpl:270 : running default event implementation 2015-11-24 14:13:47.660+0000: 34956: debug : virEventPollCleanupTimeouts:514 : Cleanup 0 2015-11-24 14:13:47.660+0000: 34956: debug : virEventPollCleanupTimeouts:550 : Found 0 out of 0 timeout slots used, releasing 0 2015-11-24 14:13:47.660+0000: 34957: debug : virDomainMigrateVersion3Full:5148 : Finish3 0x7f3644000f30 ret=-1 2015-11-24 14:13:47.660+0000: 34956: debug : virEventPollCleanupHandles:562 : Cleanup 3 2015-11-24 14:13:47.660+0000: 34956: debug : virEventPollMakePollFDs:391 : Prepare n=0 w=1, f=7 e=1 d=0 2015-11-24 14:13:47.660+0000: 34956: debug : virEventPollMakePollFDs:391 : Prepare n=1 w=2, f=9 e=1 d=0 2015-11-24 14:13:47.660+0000: 34956: debug : virEventPollMakePollFDs:391 : Prepare n=2 w=3, f=14 e=1 d=0 2015-11-24 14:13:47.660+0000: 34956: debug : virEventPollCalculateTimeout:332 : Calculate expiry of 0 timers 2015-11-24 14:13:47.660+0000: 34956: debug : virEventPollCalculateTimeout:361 : Timeout at 0 due in -1 ms 2015-11-24 14:13:47.660+0000: 34956: debug : virEventPollRunOnce:627 : EVENT_POLL_RUN: nhandles=3 timeout=-1 2015-11-24 14:13:47.660+0000: 34957: debug : virNetMessageNew:44 : msg=0x7f3644000bc0 tracked=0 2015-11-24 14:13:47.660+0000: 34957: debug : virNetMessageEncodePayload:374 : Encode length as 3124 2015-11-24 14:13:47.660+0000: 34957: debug : virNetClientSendInternal:1952 : RPC_CLIENT_MSG_TX_QUEUE: client=0x7f36440019a0 len=3124 prog=536903814 vers=1 proc=306 type=0 status=0 serial=5 2015-11-24 14:13:47.660+0000: 34957: debug : virNetClientCallNew:1905 : New call 0x7f3644001690: msg=0x7f3644000bc0, expectReply=1, nonBlock=0 2015-11-24 14:13:47.661+0000: 34957: debug : virNetClientIO:1714 : Outgoing message prog=536903814 version=1 serial=5 proc=306 type=0 length=3124 dispatch=(nil) 2015-11-24 14:13:47.661+0000: 34957: debug : virNetClientIO:1773 : We have the buck head=0x7f3644001690 call=0x7f3644001690 2015-11-24 14:13:47.661+0000: 34957: debug : virEventPollUpdateHandle:147 : EVENT_POLL_UPDATE_HANDLE: watch=3 events=0 2015-11-24 14:13:47.661+0000: 34957: debug : virEventPollInterruptLocked:714 : Interrupting 2015-11-24 14:13:47.661+0000: 34956: debug : virEventPollRunOnce:638 : Poll got 1 event(s) 2015-11-24 14:13:47.661+0000: 34956: debug : virEventPollDispatchTimeouts:423 : Dispatch 0 2015-11-24 14:13:47.661+0000: 34956: debug : virEventPollDispatchHandles:468 : Dispatch 3 2015-11-24 14:13:47.661+0000: 34956: debug : virEventPollDispatchHandles:482 : i=0 w=1 2015-11-24 14:13:47.661+0000: 34956: debug : virEventPollDispatchHandles:496 : EVENT_POLL_DISPATCH_HANDLE: watch=1 events=1 2015-11-24 14:13:47.661+0000: 34956: debug : virEventPollDispatchHandles:482 : i=1 w=2 2015-11-24 14:13:47.661+0000: 34956: debug : virEventPollCleanupTimeouts:514 : Cleanup 0 2015-11-24 14:13:47.661+0000: 34956: debug : virEventPollCleanupTimeouts:550 : Found 0 out of 0 timeout slots used, releasing 0 2015-11-24 14:13:47.661+0000: 34956: debug : virEventPollCleanupHandles:562 : Cleanup 3 2015-11-24 14:13:47.661+0000: 34956: debug : virEventRunDefaultImpl:270 : running default event implementation 2015-11-24 14:13:47.661+0000: 34956: debug : virEventPollCleanupTimeouts:514 : Cleanup 0 2015-11-24 14:13:47.661+0000: 34956: debug : virEventPollCleanupTimeouts:550 : Found 0 out of 0 timeout slots used, releasing 0 2015-11-24 14:13:47.661+0000: 34956: debug : virEventPollCleanupHandles:562 : Cleanup 3 2015-11-24 14:13:47.661+0000: 34956: debug : virEventPollMakePollFDs:391 : Prepare n=0 w=1, f=7 e=1 d=0 2015-11-24 14:13:47.661+0000: 34956: debug : virEventPollMakePollFDs:391 : Prepare n=1 w=2, f=9 e=1 d=0 2015-11-24 14:13:47.661+0000: 34956: debug : virEventPollMakePollFDs:391 : Prepare n=2 w=3, f=14 e=0 d=0 2015-11-24 14:13:47.661+0000: 34956: debug : virEventPollCalculateTimeout:332 : Calculate expiry of 0 timers 2015-11-24 14:13:47.661+0000: 34956: debug : virEventPollCalculateTimeout:361 : Timeout at 0 due in -1 ms 2015-11-24 14:13:47.661+0000: 34956: debug : virEventPollRunOnce:627 : EVENT_POLL_RUN: nhandles=2 timeout=-1 2015-11-24 14:13:47.691+0000: 34955: debug : virDomainGetJobInfo:18667 : dom=0x55d161e4d2d0, (VM: name=dev-h-vrt-008-006, uuid=04e20bfc-89e6-4098-bace-6a78c3e50919), info=0x7fff8bcfe800 2015-11-24 14:13:47.691+0000: 34955: debug : virNetMessageNew:44 : msg=0x55d161e4d610 tracked=0 2015-11-24 14:13:47.691+0000: 34955: debug : virNetMessageEncodePayload:374 : Encode length as 72 2015-11-24 14:13:47.691+0000: 34955: debug : virNetClientSendInternal:1952 : RPC_CLIENT_MSG_TX_QUEUE: client=0x55d161e4df40 len=72 prog=536903814 vers=1 proc=163 type=0 status=0 serial=95 2015-11-24 14:13:47.691+0000: 34955: debug : virNetClientCallNew:1905 : New call 0x55d161e4e520: msg=0x55d161e4d610, expectReply=1, nonBlock=0 2015-11-24 14:13:47.691+0000: 34955: debug : virNetClientIO:1714 : Outgoing message prog=536903814 version=1 serial=95 proc=163 type=0 length=72 dispatch=(nil) 2015-11-24 14:13:47.691+0000: 34955: debug : virNetClientIO:1773 : We have the buck head=0x55d161e4e520 call=0x55d161e4e520 2015-11-24 14:13:47.691+0000: 34955: debug : virEventPollUpdateHandle:147 : EVENT_POLL_UPDATE_HANDLE: watch=2 events=0 2015-11-24 14:13:47.691+0000: 34955: debug : virEventPollInterruptLocked:714 : Interrupting 2015-11-24 14:13:47.691+0000: 34956: debug : virEventPollRunOnce:638 : Poll got 1 event(s) 2015-11-24 14:13:47.691+0000: 34956: debug : virEventPollDispatchTimeouts:423 : Dispatch 0 2015-11-24 14:13:47.691+0000: 34956: debug : virEventPollDispatchHandles:468 : Dispatch 2 2015-11-24 14:13:47.691+0000: 34956: debug : virEventPollDispatchHandles:482 : i=0 w=1 2015-11-24 14:13:47.691+0000: 34956: debug : virEventPollDispatchHandles:496 : EVENT_POLL_DISPATCH_HANDLE: watch=1 events=1 2015-11-24 14:13:47.691+0000: 34956: debug : virEventPollCleanupTimeouts:514 : Cleanup 0 2015-11-24 14:13:47.691+0000: 34956: debug : virEventPollCleanupTimeouts:550 : Found 0 out of 0 timeout slots used, releasing 0 2015-11-24 14:13:47.691+0000: 34956: debug : virEventPollCleanupHandles:562 : Cleanup 3 2015-11-24 14:13:47.691+0000: 34956: debug : virEventRunDefaultImpl:270 : running default event implementation 2015-11-24 14:13:47.691+0000: 34956: debug : virEventPollCleanupTimeouts:514 : Cleanup 0 2015-11-24 14:13:47.691+0000: 34956: debug : virEventPollCleanupTimeouts:550 : Found 0 out of 0 timeout slots used, releasing 0 2015-11-24 14:13:47.691+0000: 34956: debug : virEventPollCleanupHandles:562 : Cleanup 3 2015-11-24 14:13:47.691+0000: 34956: debug : virEventPollMakePollFDs:391 : Prepare n=0 w=1, f=7 e=1 d=0 2015-11-24 14:13:47.691+0000: 34956: debug : virEventPollMakePollFDs:391 : Prepare n=1 w=2, f=9 e=0 d=0 2015-11-24 14:13:47.691+0000: 34956: debug : virEventPollMakePollFDs:391 : Prepare n=2 w=3, f=14 e=0 d=0 2015-11-24 14:13:47.691+0000: 34956: debug : virEventPollCalculateTimeout:332 : Calculate expiry of 0 timers 2015-11-24 14:13:47.691+0000: 34956: debug : virEventPollCalculateTimeout:361 : Timeout at 0 due in -1 ms 2015-11-24 14:13:47.691+0000: 34956: debug : virEventPollRunOnce:627 : EVENT_POLL_RUN: nhandles=1 timeout=-1 2015-11-24 14:13:47.692+0000: 34955: debug : virNetMessageDecodeLength:149 : Got length, now need 120 total (116 more) 2015-11-24 14:13:47.692+0000: 34955: debug : virNetClientCallDispatch:1123 : RPC_CLIENT_MSG_RX: client=0x55d161e4df40 len=120 prog=536903814 vers=1 proc=163 type=1 status=0 serial=95 2015-11-24 14:13:47.692+0000: 34955: debug : virKeepAliveCheckMessage:374 : ka=0x55d161e4e230, client=0x55d161e4df40, msg=0x55d161e4dfa8 2015-11-24 14:13:47.692+0000: 34955: debug : virNetMessageClear:55 : msg=0x55d161e4dfa8 nfds=0 2015-11-24 14:13:47.692+0000: 34955: debug : virNetClientIOEventLoopPassTheBuck:1420 : Giving up the buck 0x55d161e4e520 2015-11-24 14:13:47.692+0000: 34955: debug : virNetClientIOEventLoopPassTheBuck:1434 : No thread to pass the buck to 2015-11-24 14:13:47.692+0000: 34955: debug : virEventPollUpdateHandle:147 : EVENT_POLL_UPDATE_HANDLE: watch=2 events=1 2015-11-24 14:13:47.692+0000: 34955: debug : virEventPollInterruptLocked:714 : Interrupting 2015-11-24 14:13:47.692+0000: 34955: debug : virNetClientIO:1803 : All done with our call head=(nil) call=0x55d161e4e520 rv=0 2015-11-24 14:13:47.692+0000: 34955: debug : virNetMessageFree:72 : msg=0x55d161e4d610 nfds=0 cb=(nil) 2015-11-24 14:13:47.692+0000: 34956: debug : virEventPollRunOnce:638 : Poll got 1 event(s) 2015-11-24 14:13:47.692+0000: 34956: debug : virEventPollDispatchTimeouts:423 : Dispatch 0 2015-11-24 14:13:47.692+0000: 34956: debug : virEventPollDispatchHandles:468 : Dispatch 1 2015-11-24 14:13:47.692+0000: 34956: debug : virEventPollDispatchHandles:482 : i=0 w=1 2015-11-24 14:13:47.692+0000: 34956: debug : virEventPollDispatchHandles:496 : EVENT_POLL_DISPATCH_HANDLE: watch=1 events=1 2015-11-24 14:13:47.692+0000: 34956: debug : virEventPollCleanupTimeouts:514 : Cleanup 0 2015-11-24 14:13:47.692+0000: 34956: debug : virEventPollCleanupTimeouts:550 : Found 0 out of 0 timeout slots used, releasing 0 2015-11-24 14:13:47.692+0000: 34956: debug : virEventPollCleanupHandles:562 : Cleanup 3 2015-11-24 14:13:47.692+0000: 34956: debug : virEventRunDefaultImpl:270 : running default event implementation 2015-11-24 14:13:47.692+0000: 34956: debug : virEventPollCleanupTimeouts:514 : Cleanup 0 2015-11-24 14:13:47.692+0000: 34956: debug : virEventPollCleanupTimeouts:550 : Found 0 out of 0 timeout slots used, releasing 0 2015-11-24 14:13:47.692+0000: 34956: debug : virEventPollCleanupHandles:562 : Cleanup 3 2015-11-24 14:13:47.692+0000: 34956: debug : virEventPollMakePollFDs:391 : Prepare n=0 w=1, f=7 e=1 d=0 2015-11-24 14:13:47.692+0000: 34956: debug : virEventPollMakePollFDs:391 : Prepare n=1 w=2, f=9 e=1 d=0 2015-11-24 14:13:47.692+0000: 34956: debug : virEventPollMakePollFDs:391 : Prepare n=2 w=3, f=14 e=0 d=0 2015-11-24 14:13:47.692+0000: 34956: debug : virEventPollCalculateTimeout:332 : Calculate expiry of 0 timers 2015-11-24 14:13:47.692+0000: 34956: debug : virEventPollCalculateTimeout:361 : Timeout at 0 due in -1 ms 2015-11-24 14:13:47.692+0000: 34956: debug : virEventPollRunOnce:627 : EVENT_POLL_RUN: nhandles=2 timeout=-1 2015-11-24 14:13:47.766+0000: 34957: debug : virNetClientMarkClose:633 : client=0x7f36440019a0, reason=0 2015-11-24 14:13:47.766+0000: 34957: debug : virEventPollRemoveHandle:180 : EVENT_POLL_REMOVE_HANDLE: watch=3 2015-11-24 14:13:47.766+0000: 34957: debug : virEventPollRemoveHandle:193 : mark delete 2 14 2015-11-24 14:13:47.766+0000: 34957: debug : virEventPollInterruptLocked:714 : Interrupting 2015-11-24 14:13:47.766+0000: 34957: debug : virNetClientIOEventLoopPassTheBuck:1420 : Giving up the buck 0x7f3644001690 2015-11-24 14:13:47.766+0000: 34957: debug : virNetClientIOEventLoopPassTheBuck:1434 : No thread to pass the buck to 2015-11-24 14:13:47.766+0000: 34957: debug : virNetClientCloseLocked:646 : client=0x7f36440019a0, sock=0x7f3644001760, reason=0 2015-11-24 14:13:47.766+0000: 34957: debug : virObjectUnref:256 : OBJECT_UNREF: obj=0x7f3644001760 2015-11-24 14:13:47.766+0000: 34957: debug : virObjectRef:293 : OBJECT_REF: obj=0x7f36440019a0 2015-11-24 14:13:47.766+0000: 34957: debug : virKeepAliveStop:307 : RPC_KEEPALIVE_STOP: ka=0x7f36440015f0 client=0x7f36440019a0 2015-11-24 14:13:47.766+0000: 34957: debug : virObjectUnref:256 : OBJECT_UNREF: obj=0x7f36440015f0 2015-11-24 14:13:47.766+0000: 34956: debug : virEventPollRunOnce:638 : Poll got 1 event(s) 2015-11-24 14:13:47.766+0000: 34956: debug : virEventPollDispatchTimeouts:423 : Dispatch 0 2015-11-24 14:13:47.766+0000: 34956: debug : virEventPollDispatchHandles:468 : Dispatch 2 2015-11-24 14:13:47.766+0000: 34956: debug : virEventPollDispatchHandles:482 : i=0 w=1 2015-11-24 14:13:47.766+0000: 34956: debug : virEventPollDispatchHandles:496 : EVENT_POLL_DISPATCH_HANDLE: watch=1 events=1 2015-11-24 14:13:47.766+0000: 34957: debug : virObjectUnref:258 : OBJECT_DISPOSE: obj=0x7f36440015f0 2015-11-24 14:13:47.766+0000: 34956: debug : virEventPollDispatchHandles:482 : i=1 w=2 2015-11-24 14:13:47.766+0000: 34957: debug : virKeepAliveDispose:227 : RPC_KEEPALIVE_DISPOSE: ka=0x7f36440015f0 2015-11-24 14:13:47.766+0000: 34956: debug : virEventPollCleanupTimeouts:514 : Cleanup 0 2015-11-24 14:13:47.766+0000: 34957: debug : virObjectUnref:256 : OBJECT_UNREF: obj=0x7f36440019a0 2015-11-24 14:13:47.766+0000: 34957: debug : virObjectUnref:256 : OBJECT_UNREF: obj=0x7f36440019a0 2015-11-24 14:13:47.766+0000: 34956: debug : virEventPollCleanupTimeouts:550 : Found 0 out of 0 timeout slots used, releasing 0 2015-11-24 14:13:47.766+0000: 34957: debug : virNetClientIO:1803 : All done with our call head=(nil) call=0x7f3644001690 rv=-1 2015-11-24 14:13:47.766+0000: 34956: debug : virEventPollCleanupHandles:562 : Cleanup 3 2015-11-24 14:13:47.766+0000: 34957: debug : virNetMessageFree:72 : msg=0x7f3644000bc0 nfds=0 cb=(nil) 2015-11-24 14:13:47.766+0000: 34957: debug : virConnectClose:1523 : conn=0x7f3644000f30 2015-11-24 14:13:47.766+0000: 34957: debug : virObjectUnref:256 : OBJECT_UNREF: obj=0x7f3644000f30 2015-11-24 14:13:47.766+0000: 34957: debug : virObjectUnref:258 : OBJECT_DISPOSE: obj=0x7f3644000f30 2015-11-24 14:13:47.766+0000: 34956: debug : virEventPollCleanupHandles:575 : EVENT_POLL_PURGE_HANDLE: watch=3 2015-11-24 14:13:47.766+0000: 34957: debug : virNetMessageNew:44 : msg=0x7f364400bec0 tracked=0 2015-11-24 14:13:47.766+0000: 34957: debug : virNetMessageEncodePayload:374 : Encode length as 28 2015-11-24 14:13:47.766+0000: 34956: debug : virObjectUnref:256 : OBJECT_UNREF: obj=0x7f36440019a0 2015-11-24 14:13:47.766+0000: 34956: debug : virObjectUnref:256 : OBJECT_UNREF: obj=0x7f3644001760 2015-11-24 14:13:47.766+0000: 34956: debug : virObjectUnref:258 : OBJECT_DISPOSE: obj=0x7f3644001760 2015-11-24 14:13:47.766+0000: 34957: debug : virNetClientSendInternal:1952 : RPC_CLIENT_MSG_TX_QUEUE: client=0x7f36440019a0 len=28 prog=536903814 vers=1 proc=2 type=0 status=0 serial=6 2015-11-24 14:13:47.766+0000: 34956: debug : virNetSocketDispose:1002 : RPC_SOCKET_DISPOSE: sock=0x7f3644001760 2015-11-24 14:13:47.766+0000: 34956: debug : virEventPollRemoveHandle:180 : EVENT_POLL_REMOVE_HANDLE: watch=3 2015-11-24 14:13:47.766+0000: 34956: debug : virFileClose:90 : Closed fd 14 2015-11-24 14:13:47.766+0000: 34957: debug : virNetMessageFree:72 : msg=0x7f364400bec0 nfds=0 cb=(nil) 2015-11-24 14:13:47.766+0000: 34957: debug : virNetClientCloseInternal:687 : client=0x7f36440019a0 wantclose=0 2015-11-24 14:13:47.766+0000: 34956: debug : virFileClose:90 : Closed fd 16 2015-11-24 14:13:47.767+0000: 34957: debug : virObjectUnref:256 : OBJECT_UNREF: obj=0x7f36440019a0 2015-11-24 14:13:47.767+0000: 34956: debug : virProcessAbort:104 : aborting child process 34958 2015-11-24 14:13:47.767+0000: 34956: debug : virProcessAbort:109 : process has ended: exit status 1 2015-11-24 14:13:47.767+0000: 34956: debug : virEventRunDefaultImpl:270 : running default event implementation 2015-11-24 14:13:47.767+0000: 34956: debug : virEventPollCleanupTimeouts:514 : Cleanup 0 2015-11-24 14:13:47.767+0000: 34956: debug : virEventPollCleanupTimeouts:550 : Found 0 out of 0 timeout slots used, releasing 0 2015-11-24 14:13:47.767+0000: 34956: debug : virEventPollCleanupHandles:562 : Cleanup 2 2015-11-24 14:13:47.767+0000: 34956: debug : virEventPollMakePollFDs:391 : Prepare n=0 w=1, f=7 e=1 d=0 2015-11-24 14:13:47.767+0000: 34956: debug : virEventPollMakePollFDs:391 : Prepare n=1 w=2, f=9 e=1 d=0 2015-11-24 14:13:47.767+0000: 34956: debug : virEventPollCalculateTimeout:332 : Calculate expiry of 0 timers 2015-11-24 14:13:47.767+0000: 34956: debug : virEventPollCalculateTimeout:361 : Timeout at 0 due in -1 ms 2015-11-24 14:13:47.767+0000: 34956: debug : virEventPollRunOnce:627 : EVENT_POLL_RUN: nhandles=2 timeout=-1 2015-11-24 14:13:47.767+0000: 34957: debug : virObjectUnref:258 : OBJECT_DISPOSE: obj=0x7f36440019a0 2015-11-24 14:13:47.767+0000: 34957: debug : virNetClientDispose:599 : RPC_CLIENT_DISPOSE: client=0x7f36440019a0 2015-11-24 14:13:47.767+0000: 34957: debug : virObjectUnref:256 : OBJECT_UNREF: obj=0x7f3644010c80 2015-11-24 14:13:47.767+0000: 34957: debug : virObjectUnref:256 : OBJECT_UNREF: obj=0x7f3644001da0 2015-11-24 14:13:47.767+0000: 34957: debug : virObjectUnref:256 : OBJECT_UNREF: obj=0x7f3644001510 2015-11-24 14:13:47.767+0000: 34957: debug : virObjectUnref:256 : OBJECT_UNREF: obj=0x7f3644001bc0 2015-11-24 14:13:47.767+0000: 34957: debug : virFileClose:90 : Closed fd 17 2015-11-24 14:13:47.767+0000: 34957: debug : virFileClose:90 : Closed fd 15 2015-11-24 14:13:47.767+0000: 34957: debug : virNetMessageClear:55 : msg=0x7f3644001a08 nfds=0 2015-11-24 14:13:47.767+0000: 34957: debug : virObjectUnref:256 : OBJECT_UNREF: obj=0x7f3644001da0 2015-11-24 14:13:47.767+0000: 34957: debug : virObjectUnref:258 : OBJECT_DISPOSE: obj=0x7f3644001da0 2015-11-24 14:13:47.767+0000: 34957: debug : virObjectUnref:256 : OBJECT_UNREF: obj=0x7f3644001510 2015-11-24 14:13:47.767+0000: 34957: debug : virObjectUnref:258 : OBJECT_DISPOSE: obj=0x7f3644001510 2015-11-24 14:13:47.767+0000: 34957: debug : virObjectUnref:256 : OBJECT_UNREF: obj=0x7f3644001bc0 2015-11-24 14:13:47.767+0000: 34957: debug : virObjectUnref:258 : OBJECT_DISPOSE: obj=0x7f3644001bc0 2015-11-24 14:13:47.767+0000: 34957: debug : virObjectUnref:256 : OBJECT_UNREF: obj=0x7f3644010c80 2015-11-24 14:13:47.767+0000: 34957: debug : virObjectUnref:258 : OBJECT_DISPOSE: obj=0x7f3644010c80 2015-11-24 14:13:47.767+0000: 34957: debug : virDomainFree:2428 : dom=0x7f3644000c30, (VM: name=dev-h-vrt-008-006, uuid=04e20bfc-89e6-4098-bace-6a78c3e50919) 2015-11-24 14:13:47.767+0000: 34957: debug : virObjectUnref:256 : OBJECT_UNREF: obj=0x7f3644000c30 2015-11-24 14:13:47.767+0000: 34957: debug : virObjectUnref:258 : OBJECT_DISPOSE: obj=0x7f3644000c30 2015-11-24 14:13:47.767+0000: 34957: debug : virDomainDispose:262 : release domain 0x7f3644000c30 dev-h-vrt-008-006 04e20bfc-89e6-4098-bace-6a78c3e50919 2015-11-24 14:13:47.767+0000: 34957: debug : virObjectUnref:256 : OBJECT_UNREF: obj=0x55d161e4d340 2015-11-24 14:13:47.767+0000: 34955: debug : virDomainFree:2428 : dom=0x55d161e4d2d0, (VM: name=dev-h-vrt-008-006, uuid=04e20bfc-89e6-4098-bace-6a78c3e50919) 2015-11-24 14:13:47.767+0000: 34955: debug : virObjectUnref:256 : OBJECT_UNREF: obj=0x55d161e4d2d0 2015-11-24 14:13:47.767+0000: 34955: debug : virObjectUnref:258 : OBJECT_DISPOSE: obj=0x55d161e4d2d0 2015-11-24 14:13:47.767+0000: 34955: debug : virDomainDispose:262 : release domain 0x55d161e4d2d0 dev-h-vrt-008-006 04e20bfc-89e6-4098-bace-6a78c3e50919 2015-11-24 14:13:47.767+0000: 34955: debug : virObjectUnref:256 : OBJECT_UNREF: obj=0x55d161e4d340 2015-11-24 14:13:47.767+0000: 34955: debug : virFileClose:90 : Closed fd 12 2015-11-24 14:13:47.767+0000: 34955: debug : virFileClose:90 : Closed fd 13 2015-11-24 14:13:47.767+0000: 34955: debug : virConnectUnregisterCloseCallback:21481 : conn=0x55d161e4d340 2015-11-24 14:13:47.767+0000: 34955: debug : virObjectUnref:256 : OBJECT_UNREF: obj=0x55d161e4d340 2015-11-24 14:13:47.767+0000: 34955: debug : virConnectClose:1523 : conn=0x55d161e4d340 2015-11-24 14:13:47.767+0000: 34955: debug : virObjectUnref:256 : OBJECT_UNREF: obj=0x55d161e4d340 2015-11-24 14:13:47.767+0000: 34955: debug : virObjectUnref:258 : OBJECT_DISPOSE: obj=0x55d161e4d340 2015-11-24 14:13:47.767+0000: 34955: debug : virNetMessageNew:44 : msg=0x55d161e4dc20 tracked=0 2015-11-24 14:13:47.767+0000: 34955: debug : virNetMessageEncodePayload:374 : Encode length as 28 2015-11-24 14:13:47.767+0000: 34955: debug : virNetClientSendInternal:1952 : RPC_CLIENT_MSG_TX_QUEUE: client=0x55d161e4df40 len=28 prog=536903814 vers=1 proc=2 type=0 status=0 serial=96 2015-11-24 14:13:47.767+0000: 34955: debug : virNetClientCallNew:1905 : New call 0x55d161e4e520: msg=0x55d161e4dc20, expectReply=1, nonBlock=0 2015-11-24 14:13:47.767+0000: 34955: debug : virNetClientIO:1714 : Outgoing message prog=536903814 version=1 serial=96 proc=2 type=0 length=28 dispatch=(nil) 2015-11-24 14:13:47.767+0000: 34955: debug : virNetClientIO:1773 : We have the buck head=0x55d161e4e520 call=0x55d161e4e520 2015-11-24 14:13:47.767+0000: 34955: debug : virEventPollUpdateHandle:147 : EVENT_POLL_UPDATE_HANDLE: watch=2 events=0 2015-11-24 14:13:47.767+0000: 34955: debug : virEventPollInterruptLocked:714 : Interrupting 2015-11-24 14:13:47.767+0000: 34956: debug : virEventPollRunOnce:638 : Poll got 1 event(s) 2015-11-24 14:13:47.767+0000: 34956: debug : virEventPollDispatchTimeouts:423 : Dispatch 0 2015-11-24 14:13:47.767+0000: 34956: debug : virEventPollDispatchHandles:468 : Dispatch 2 2015-11-24 14:13:47.767+0000: 34956: debug : virEventPollDispatchHandles:482 : i=0 w=1 2015-11-24 14:13:47.767+0000: 34956: debug : virEventPollDispatchHandles:496 : EVENT_POLL_DISPATCH_HANDLE: watch=1 events=1 2015-11-24 14:13:47.767+0000: 34956: debug : virEventPollCleanupTimeouts:514 : Cleanup 0 2015-11-24 14:13:47.767+0000: 34956: debug : virEventPollCleanupTimeouts:550 : Found 0 out of 0 timeout slots used, releasing 0 2015-11-24 14:13:47.767+0000: 34956: debug : virEventPollCleanupHandles:562 : Cleanup 2 2015-11-24 14:13:47.767+0000: 34956: debug : virEventRunDefaultImpl:270 : running default event implementation 2015-11-24 14:13:47.767+0000: 34956: debug : virEventPollCleanupTimeouts:514 : Cleanup 0 2015-11-24 14:13:47.767+0000: 34956: debug : virEventPollCleanupTimeouts:550 : Found 0 out of 0 timeout slots used, releasing 0 2015-11-24 14:13:47.767+0000: 34956: debug : virEventPollCleanupHandles:562 : Cleanup 2 2015-11-24 14:13:47.767+0000: 34956: debug : virEventPollMakePollFDs:391 : Prepare n=0 w=1, f=7 e=1 d=0 2015-11-24 14:13:47.767+0000: 34956: debug : virEventPollMakePollFDs:391 : Prepare n=1 w=2, f=9 e=0 d=0 2015-11-24 14:13:47.767+0000: 34956: debug : virEventPollCalculateTimeout:332 : Calculate expiry of 0 timers 2015-11-24 14:13:47.767+0000: 34956: debug : virEventPollCalculateTimeout:361 : Timeout at 0 due in -1 ms 2015-11-24 14:13:47.767+0000: 34956: debug : virEventPollRunOnce:627 : EVENT_POLL_RUN: nhandles=1 timeout=-1 2015-11-24 14:13:47.767+0000: 34955: debug : virNetMessageDecodeLength:149 : Got length, now need 28 total (24 more) 2015-11-24 14:13:47.767+0000: 34955: debug : virNetClientCallDispatch:1123 : RPC_CLIENT_MSG_RX: client=0x55d161e4df40 len=28 prog=536903814 vers=1 proc=2 type=1 status=0 serial=96 2015-11-24 14:13:47.767+0000: 34955: debug : virKeepAliveCheckMessage:374 : ka=0x55d161e4e230, client=0x55d161e4df40, msg=0x55d161e4dfa8 2015-11-24 14:13:47.767+0000: 34955: debug : virNetMessageClear:55 : msg=0x55d161e4dfa8 nfds=0 2015-11-24 14:13:47.767+0000: 34955: debug : virNetClientIOEventLoopPassTheBuck:1420 : Giving up the buck 0x55d161e4e520 2015-11-24 14:13:47.767+0000: 34955: debug : virNetClientIOEventLoopPassTheBuck:1434 : No thread to pass the buck to 2015-11-24 14:13:47.767+0000: 34955: debug : virEventPollUpdateHandle:147 : EVENT_POLL_UPDATE_HANDLE: watch=2 events=1 2015-11-24 14:13:47.767+0000: 34955: debug : virEventPollInterruptLocked:714 : Interrupting 2015-11-24 14:13:47.767+0000: 34955: debug : virNetClientIO:1803 : All done with our call head=(nil) call=0x55d161e4e520 rv=0 2015-11-24 14:13:47.767+0000: 34955: debug : virNetMessageFree:72 : msg=0x55d161e4dc20 nfds=0 cb=(nil) 2015-11-24 14:13:47.767+0000: 34955: debug : virNetClientCloseInternal:687 : client=0x55d161e4df40 wantclose=0 2015-11-24 14:13:47.768+0000: 34955: debug : virNetClientMarkClose:633 : client=0x55d161e4df40, reason=3 2015-11-24 14:13:47.768+0000: 34955: debug : virEventPollRemoveHandle:180 : EVENT_POLL_REMOVE_HANDLE: watch=2 2015-11-24 14:13:47.768+0000: 34955: debug : virEventPollRemoveHandle:193 : mark delete 1 9 2015-11-24 14:13:47.768+0000: 34955: debug : virEventPollInterruptLocked:714 : Interrupting 2015-11-24 14:13:47.768+0000: 34956: debug : virEventPollRunOnce:638 : Poll got 1 event(s) 2015-11-24 14:13:47.768+0000: 34956: debug : virEventPollDispatchTimeouts:423 : Dispatch 0 2015-11-24 14:13:47.768+0000: 34956: debug : virEventPollDispatchHandles:468 : Dispatch 1 2015-11-24 14:13:47.768+0000: 34956: debug : virEventPollDispatchHandles:482 : i=0 w=1 2015-11-24 14:13:47.768+0000: 34956: debug : virEventPollDispatchHandles:496 : EVENT_POLL_DISPATCH_HANDLE: watch=1 events=1 2015-11-24 14:13:47.768+0000: 34956: debug : virEventPollCleanupTimeouts:514 : Cleanup 0 2015-11-24 14:13:47.768+0000: 34956: debug : virEventPollCleanupTimeouts:550 : Found 0 out of 0 timeout slots used, releasing 0 2015-11-24 14:13:47.768+0000: 34956: debug : virEventPollCleanupHandles:562 : Cleanup 2 2015-11-24 14:13:47.768+0000: 34956: debug : virEventPollCleanupHandles:575 : EVENT_POLL_PURGE_HANDLE: watch=2 2015-11-24 14:13:47.768+0000: 34956: debug : virObjectUnref:256 : OBJECT_UNREF: obj=0x55d161e4df40 2015-11-24 14:13:47.768+0000: 34956: debug : virObjectUnref:256 : OBJECT_UNREF: obj=0x55d161e4dc90 2015-11-24 14:13:47.768+0000: 34956: debug : virEventRunDefaultImpl:270 : running default event implementation 2015-11-24 14:13:47.768+0000: 34956: debug : virEventPollCleanupTimeouts:514 : Cleanup 0 2015-11-24 14:13:47.768+0000: 34956: debug : virEventPollCleanupTimeouts:550 : Found 0 out of 0 timeout slots used, releasing 0 2015-11-24 14:13:47.768+0000: 34956: debug : virEventPollCleanupHandles:562 : Cleanup 1 2015-11-24 14:13:47.768+0000: 34956: debug : virEventPollMakePollFDs:391 : Prepare n=0 w=1, f=7 e=1 d=0 2015-11-24 14:13:47.768+0000: 34956: debug : virEventPollCalculateTimeout:332 : Calculate expiry of 0 timers 2015-11-24 14:13:47.768+0000: 34956: debug : virEventPollCalculateTimeout:361 : Timeout at 0 due in -1 ms 2015-11-24 14:13:47.768+0000: 34956: debug : virEventPollRunOnce:627 : EVENT_POLL_RUN: nhandles=1 timeout=-1 2015-11-24 14:13:47.768+0000: 34956: debug : virEventPollRunOnce:638 : Poll got 1 event(s) 2015-11-24 14:13:47.768+0000: 34956: debug : virEventPollDispatchTimeouts:423 : Dispatch 0 2015-11-24 14:13:47.768+0000: 34956: debug : virEventPollDispatchHandles:468 : Dispatch 1 2015-11-24 14:13:47.768+0000: 34956: debug : virEventPollDispatchHandles:482 : i=0 w=1 2015-11-24 14:13:47.768+0000: 34956: debug : virEventPollDispatchHandles:496 : EVENT_POLL_DISPATCH_HANDLE: watch=1 events=1 2015-11-24 14:13:47.768+0000: 34956: debug : virEventPollCleanupTimeouts:514 : Cleanup 0 2015-11-24 14:13:47.768+0000: 34956: debug : virEventPollCleanupTimeouts:550 : Found 0 out of 0 timeout slots used, releasing 0 2015-11-24 14:13:47.768+0000: 34956: debug : virEventPollCleanupHandles:562 : Cleanup 1 2015-11-24 14:13:47.768+0000: 34956: debug : virEventRunDefaultImpl:270 : running default event implementation 2015-11-24 14:13:47.768+0000: 34956: debug : virEventPollCleanupTimeouts:514 : Cleanup 0 2015-11-24 14:13:47.768+0000: 34956: debug : virEventPollCleanupTimeouts:550 : Found 0 out of 0 timeout slots used, releasing 0 2015-11-24 14:13:47.768+0000: 34956: debug : virEventPollCleanupHandles:562 : Cleanup 1 2015-11-24 14:13:47.768+0000: 34956: debug : virEventPollMakePollFDs:391 : Prepare n=0 w=1, f=7 e=1 d=0 2015-11-24 14:13:47.768+0000: 34956: debug : virEventPollCalculateTimeout:332 : Calculate expiry of 0 timers 2015-11-24 14:13:47.768+0000: 34956: debug : virEventPollCalculateTimeout:361 : Timeout at 0 due in -1 ms 2015-11-24 14:13:47.768+0000: 34956: debug : virEventPollRunOnce:627 : EVENT_POLL_RUN: nhandles=1 timeout=-1 2015-11-24 14:13:47.768+0000: 34955: debug : virNetClientIOEventLoopPassTheBuck:1420 : Giving up the buck (nil) 2015-11-24 14:13:47.768+0000: 34955: debug : virNetClientIOEventLoopPassTheBuck:1434 : No thread to pass the buck to 2015-11-24 14:13:47.768+0000: 34955: debug : virNetClientCloseLocked:646 : client=0x55d161e4df40, sock=0x55d161e4dc90, reason=3 2015-11-24 14:13:47.768+0000: 34955: debug : virObjectUnref:256 : OBJECT_UNREF: obj=0x55d161e4dc90 2015-11-24 14:13:47.768+0000: 34955: debug : virObjectUnref:258 : OBJECT_DISPOSE: obj=0x55d161e4dc90 2015-11-24 14:13:47.768+0000: 34955: debug : virNetSocketDispose:1002 : RPC_SOCKET_DISPOSE: sock=0x55d161e4dc90 2015-11-24 14:13:47.768+0000: 34955: debug : virEventPollRemoveHandle:180 : EVENT_POLL_REMOVE_HANDLE: watch=2 2015-11-24 14:13:47.768+0000: 34955: debug : virFileClose:90 : Closed fd 9 2015-11-24 14:13:47.768+0000: 34955: debug : virObjectRef:293 : OBJECT_REF: obj=0x55d161e4df40 2015-11-24 14:13:47.768+0000: 34955: debug : virKeepAliveStop:307 : RPC_KEEPALIVE_STOP: ka=0x55d161e4e230 client=0x55d161e4df40 2015-11-24 14:13:47.768+0000: 34955: debug : virObjectUnref:256 : OBJECT_UNREF: obj=0x55d161e4e230 2015-11-24 14:13:47.768+0000: 34955: debug : virObjectUnref:258 : OBJECT_DISPOSE: obj=0x55d161e4e230 2015-11-24 14:13:47.768+0000: 34955: debug : virKeepAliveDispose:227 : RPC_KEEPALIVE_DISPOSE: ka=0x55d161e4e230 2015-11-24 14:13:47.768+0000: 34955: debug : virObjectUnref:256 : OBJECT_UNREF: obj=0x55d161e4df40 2015-11-24 14:13:47.768+0000: 34955: debug : virObjectUnref:256 : OBJECT_UNREF: obj=0x55d161e4df40 2015-11-24 14:13:47.768+0000: 34955: debug : virObjectUnref:256 : OBJECT_UNREF: obj=0x55d161e4df40 2015-11-24 14:13:47.768+0000: 34955: debug : virObjectUnref:258 : OBJECT_DISPOSE: obj=0x55d161e4df40 2015-11-24 14:13:47.768+0000: 34955: debug : virNetClientDispose:599 : RPC_CLIENT_DISPOSE: client=0x55d161e4df40 2015-11-24 14:13:47.768+0000: 34955: debug : virObjectUnref:256 : OBJECT_UNREF: obj=0x55d161e4d4e0 2015-11-24 14:13:47.768+0000: 34955: debug : virObjectUnref:256 : OBJECT_UNREF: obj=0x55d161e4e150 2015-11-24 14:13:47.768+0000: 34955: debug : virObjectUnref:256 : OBJECT_UNREF: obj=0x55d161e4de60 2015-11-24 14:13:47.768+0000: 34955: debug : virObjectUnref:256 : OBJECT_UNREF: obj=0x55d161e4da60 2015-11-24 14:13:47.768+0000: 34955: debug : virFileClose:90 : Closed fd 11 2015-11-24 14:13:47.768+0000: 34955: debug : virFileClose:90 : Closed fd 10 2015-11-24 14:13:47.768+0000: 34955: debug : virNetMessageClear:55 : msg=0x55d161e4dfa8 nfds=0 2015-11-24 14:13:47.768+0000: 34955: debug : virObjectUnref:256 : OBJECT_UNREF: obj=0x55d161e4e150 2015-11-24 14:13:47.768+0000: 34955: debug : virObjectUnref:258 : OBJECT_DISPOSE: obj=0x55d161e4e150 2015-11-24 14:13:47.768+0000: 34955: debug : virObjectUnref:256 : OBJECT_UNREF: obj=0x55d161e4de60 2015-11-24 14:13:47.768+0000: 34955: debug : virObjectUnref:258 : OBJECT_DISPOSE: obj=0x55d161e4de60 2015-11-24 14:13:47.768+0000: 34955: debug : virObjectUnref:256 : OBJECT_UNREF: obj=0x55d161e4da60 2015-11-24 14:13:47.768+0000: 34955: debug : virObjectUnref:258 : OBJECT_DISPOSE: obj=0x55d161e4da60 2015-11-24 14:13:47.768+0000: 34955: debug : virObjectUnref:256 : OBJECT_UNREF: obj=0x55d161e4d4e0 2015-11-24 14:13:47.768+0000: 34955: debug : virObjectUnref:258 : OBJECT_DISPOSE: obj=0x55d161e4d4e0 2015-11-24 14:13:47.768+0000: 34955: debug : virEventPollAddTimeout:225 : Used 0 timeout slots, adding at least 10 more 2015-11-24 14:13:47.768+0000: 34955: debug : virEventPollInterruptLocked:714 : Interrupting 2015-11-24 14:13:47.768+0000: 34955: debug : virEventPollAddTimeout:248 : EVENT_POLL_ADD_TIMEOUT: timer=1 frequency=0 cb=0x55d160b5dbe0 opaque=(nil) ff=(nil) 2015-11-24 14:13:47.768+0000: 34956: debug : virEventPollRunOnce:638 : Poll got 1 event(s) 2015-11-24 14:13:47.768+0000: 34956: debug : virEventPollDispatchTimeouts:423 : Dispatch 1 2015-11-24 14:13:47.768+0000: 34956: debug : virEventPollDispatchTimeouts:446 : EVENT_POLL_DISPATCH_TIMEOUT: timer=1 2015-11-24 14:13:47.768+0000: 34956: debug : virEventPollDispatchHandles:468 : Dispatch 1 2015-11-24 14:13:47.768+0000: 34956: debug : virEventPollDispatchHandles:482 : i=0 w=1 2015-11-24 14:13:47.768+0000: 34956: debug : virEventPollDispatchHandles:496 : EVENT_POLL_DISPATCH_HANDLE: watch=1 events=1 2015-11-24 14:13:47.768+0000: 34956: debug : virEventPollCleanupTimeouts:514 : Cleanup 1 2015-11-24 14:13:47.768+0000: 34956: debug : virEventPollCleanupHandles:562 : Cleanup 1 2015-11-24 14:13:47.768+0000: 34955: debug : virEventPollRemoveTimeout:300 : EVENT_POLL_REMOVE_TIMEOUT: timer=1 2015-11-24 14:13:47.768+0000: 34955: debug : virEventPollInterruptLocked:710 : Skip interrupt, 0 139871269107456
