[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]
Re: [Qemu-devel] KVM/Qemu migration under fast network stress
|
From: |
Dr. David Alan Gilbert |
|
Subject: |
Re: [Qemu-devel] KVM/Qemu migration under fast network stress |
|
Date: |
Wed, 25 Nov 2015 10:10:58 +0000 |
|
User-agent: |
Mutt/1.5.24 (2015-08-30) |
* Or Gerlitz (address@hidden) 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 / address@hidden / Manchester, UK