[Qemu-devel] KVM/Qemu migration under fast network stress

[Qemu-devel] KVM/Qemu migration under fast network stress

[Or Gerlitz]

[-- Attachment #1: Type: text/plain, Size: 8183 bytes --]

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

[-- Attachment #2: migrate_a_b_fail.txt --]
[-- Type: text/plain, Size: 55316 bytes --]

\rMigration: [ 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)
\rMigration: [ 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

Re: [Qemu-devel] KVM/Qemu migration under fast network stress

[Andrey Korolyov]

On Wed, Nov 25, 2015 at 1:44 AM, Or Gerlitz <gerlitz.or@gmail.com> wrote:
> 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

Have you tried to use convergence mechanism which is presented in
contemporary libvirt as well? The problem you are describing was quite
common and general solution is to throttle VM down via cgroups (oldest
one) or via emulator` own vCPU throttling mechanism to allow migration
to be successfully completed. Libvirt can also fall back to migration
of the paused VM which could be assumed as a "last resort" within
migration flow procedures.

Re: [Qemu-devel] KVM/Qemu migration under fast network stress

[Dr. David Alan Gilbert]

* Or Gerlitz (gerlitz.or@gmail.com) wrote:
> 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?

Not if the problem is running out of bandwidth; if you don't have enough bandwidth
to carry the dirty pages then it just keeps going.

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

There are a few options:
   a) 'auto converge' - that slows the CPU down during migrate until it's
      dirtying less pages; QEMU has an implementation but it doesn't try
      and slow it down much until 2.5, which has an improved auto-converge.
      Some of the higher leve tools also do similar tricks with cgroups
      to slow it down.
   b) There are various compression schemes (xbzrle, multithreaded compression)
      but they all use a lot of CPU - onl useful if you have very low
      migration network (e.g. 1Gbps)
   c) There is 'postcopy' that I added in 2.5 - that starts the guest on
      the destination before we've finished copying all the memory, and then
      'pulls' the remaining pages across - that will cope even with a
      heavily loaded guest; see http://qemu-project.org/Features/PostCopyLiveMigration

Dave

> 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

--
Dr. David Alan Gilbert / dgilbert@redhat.com / Manchester, UK