From: "Dr. David Alan Gilbert" <dgilbert@redhat.com>
To: Or Gerlitz <gerlitz.or@gmail.com>
Cc: Orit Wasserman <owasserm@redhat.com>,
Kamal Heib <kamalh@mellanox.com>,
"Michael S. Tsirkin" <mst@redhat.com>,
qemu-devel@nongnu.org, Saeed Mahameed <saeedm@mellanox.com>
Subject: Re: [Qemu-devel] KVM/Qemu migration under fast network stress
Date: Wed, 25 Nov 2015 10:10:58 +0000 [thread overview]
Message-ID: <20151125101057.GA2545@work-vm> (raw)
In-Reply-To: <CAJ3xEMg6MT=bdvA==m_8Qy8xy0ooHW02QV3tuJs0-DF_ssVs+w@mail.gmail.com>
* 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
prev parent reply other threads:[~2015-11-25 10:11 UTC|newest]
Thread overview: 3+ messages / expand[flat|nested] mbox.gz Atom feed top
2015-11-24 22:44 [Qemu-devel] KVM/Qemu migration under fast network stress Or Gerlitz
2015-11-24 23:32 ` Andrey Korolyov
2015-11-25 10:10 ` Dr. David Alan Gilbert [this message]
Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
Avoid top-posting and favor interleaved quoting:
https://en.wikipedia.org/wiki/Posting_style#Interleaved_style
* Reply using the --to, --cc, and --in-reply-to
switches of git-send-email(1):
git send-email \
--in-reply-to=20151125101057.GA2545@work-vm \
--to=dgilbert@redhat.com \
--cc=gerlitz.or@gmail.com \
--cc=kamalh@mellanox.com \
--cc=mst@redhat.com \
--cc=owasserm@redhat.com \
--cc=qemu-devel@nongnu.org \
--cc=saeedm@mellanox.com \
/path/to/YOUR_REPLY
https://kernel.org/pub/software/scm/git/docs/git-send-email.html
* If your mail client supports setting the In-Reply-To header
via mailto: links, try the mailto: link
Be sure your reply has a Subject: header at the top and a blank line
before the message body.
This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.