[libvirt-users] create vm timeout

Tuesday, 13 November 2018


Hi all:
I create VM on most hypervisors very quickly, about 2 seconds. But some hypervisors are
slow, taking more than 10 seconds. I started the debug log for libvirtd and found that
some threads had timed out. Thread 95205 has two 5-second timeouts, but I don't know
why?
Below some information about my hypervisor:
[root@node1 datapool]# virsh -v
3.4.0
[root@node1 datapool]# qemu-x86_64 --version
qemu-x86_64 version 2.9.0
Copyright (c) 2003-2017 Fabrice Bellard and the QEMU Project developers
[root@node1 datapool]# uname -a
Linux node1 3.10.0-693.el7.x86_64 #1 SMP Tue Aug 22 21:09:27 UTC 2017 x86_64 x86_64 x86_64
GNU/Linux
Here are some log fragments:
2018-11-13 14:21:39.942+0000: 95205: debug : virEventPollRunOnce:650 : Poll got 0
event(s)
2018-11-13 14:21:39.942+0000: 95205: debug : virEventPollDispatchTimeouts:432 : Dispatch
2
2018-11-13 14:21:39.942+0000: 95205: info : virEventPollDispatchTimeouts:455 :
EVENT_POLL_DISPATCH_TIMEOUT: timer=2
2018-11-13 14:21:39.942+0000: 95205: info : virObjectRef:296 : OBJECT_REF:
obj=0x561dca9e7b60
2018-11-13 14:21:39.942+0000: 95205: info : virKeepAliveTimerInternal:136 :
RPC_KEEPALIVE_TIMEOUT: ka=0x561dca9e7b60 client=0x561dca9e6e60 countToDeath=5 idle=5
2018-11-13 14:21:39.942+0000: 95205: debug : virNetMessageNew:46 : msg=0x561dca9e2880
tracked=0
2018-11-13 14:21:39.942+0000: 95205: debug : virNetMessageEncodePayloadEmpty:492 : Encode
length as 28
2018-11-13 14:21:39.942+0000: 95205: debug : virKeepAliveMessage:104 : Sending keepalive
request to client 0x561dca9e6e60
2018-11-13 14:21:39.942+0000: 95205: info : virKeepAliveMessage:107 : RPC_KEEPALIVE_SEND:
ka=0x561dca9e7b60 client=0x561dca9e6e60 prog=1801807216 vers=1 proc=1
2018-11-13 14:21:39.942+0000: 95205: info : virEventPollUpdateTimeout:265 :
EVENT_POLL_UPDATE_TIMEOUT: timer=2 frequency=5000
2018-11-13 14:21:39.942+0000: 95205: debug : virEventPollUpdateTimeout:282 : Set timer
freq=5000 expires=1542118904942
2018-11-13 14:21:39.942+0000: 95205: debug : virEventPollInterruptLocked:722 : Skip
interrupt, 1 140197681715264
2018-11-13 14:21:39.942+0000: 95205: debug : virNetServerClientSendMessageLocked:1480 :
msg=0x561dca9e2880 proc=1 len=28 offset=0
2018-11-13 14:21:39.942+0000: 95205: info : virNetServerClientSendMessageLocked:1488 :
RPC_SERVER_CLIENT_MSG_TX_QUEUE: client=0x561dca9e6e60 len=28 prog=1801807216 vers=1 proc=1
type=2 status=0 serial=0
2018-11-13 14:21:39.942+0000: 95205: debug : virNetServerClientCalculateHandleMode:166 :
tls=(nil) hs=-1, rx=0x561dca9e1050 tx=0x561dca9e2880
2018-11-13 14:21:39.942+0000: 95205: debug : virNetServerClientCalculateHandleMode:201 :
mode=3
2018-11-13 14:21:39.942+0000: 95205: info : virEventPollUpdateHandle:152 :
EVENT_POLL_UPDATE_HANDLE: watch=12 events=3
2018-11-13 14:21:39.942+0000: 95205: debug : virEventPollInterruptLocked:722 : Skip
interrupt, 1 140197681715264
2018-11-13 14:21:39.942+0000: 95205: info : virObjectUnref:259 : OBJECT_UNREF:
obj=0x561dca9e7b60
2018-11-13 14:21:39.942+0000: 95205: debug : virEventPollCleanupTimeouts:525 : Cleanup 2
2018-11-13 14:21:39.942+0000: 95205: debug : virEventPollCleanupHandles:574 : Cleanup 12
2018-11-13 14:21:39.942+0000: 95205: debug : virEventRunDefaultImpl:311 : running default
event implementation
2018-11-13 14:21:39.942+0000: 95205: debug : virEventPollCleanupTimeouts:525 : Cleanup 2
2018-11-13 14:21:39.942+0000: 95205: debug : virEventPollCleanupHandles:574 : Cleanup 12
2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=0
w=1, f=5 e=1 d=0
2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=1
w=2, f=7 e=1 d=0
2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=2
w=3, f=9 e=1 d=0
2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=3
w=4, f=10 e=1 d=0
2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=4
w=5, f=11 e=1 d=0
2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=5
w=6, f=12 e=1 d=0
2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=6
w=7, f=13 e=1 d=0
2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=7
w=8, f=14 e=1 d=0
2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=8
w=9, f=15 e=1 d=0
2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=9
w=10, f=17 e=1 d=0
2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=10
w=11, f=18 e=1 d=0
2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=11
w=12, f=19 e=5 d=0
2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollCalculateTimeout:338 : Calculate
expiry of 2 timers
2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollCalculateTimeout:346 : Got a
timeout scheduled for 1542118904942
2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollCalculateTimeout:359 : Schedule
timeout then=1542118904942 now=1542118899943
2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollCalculateTimeout:369 : Timeout at
1542118904942 due in 4999 ms
2018-11-13 14:21:39.943+0000: 95205: info : virEventPollRunOnce:640 : EVENT_POLL_RUN:
nhandles=12 timeout=4999
2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollRunOnce:650 : Poll got 1
event(s)
2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollDispatchTimeouts:432 : Dispatch
2
2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollDispatchHandles:478 : Dispatch
12
2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollDispatchHandles:492 : i=0 w=1
2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollDispatchHandles:492 : i=1 w=2
2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollDispatchHandles:492 : i=2 w=3
2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollDispatchHandles:492 : i=3 w=4
2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollDispatchHandles:492 : i=4 w=5
2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollDispatchHandles:492 : i=5 w=6
2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollDispatchHandles:492 : i=6 w=7
2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollDispatchHandles:492 : i=7 w=8
2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollDispatchHandles:492 : i=8 w=9
2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollDispatchHandles:492 : i=9 w=10
2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollDispatchHandles:492 : i=10 w=11
2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollDispatchHandles:492 : i=11 w=12
2018-11-13 14:21:39.943+0000: 95205: info : virEventPollDispatchHandles:506 :
EVENT_POLL_DISPATCH_HANDLE: watch=12 events=2
2018-11-13 14:21:39.943+0000: 95205: debug : virNetMessageFree:87 : msg=0x561dca9e2880
nfds=0 cb=(nil)
2018-11-13 14:21:39.943+0000: 95205: debug : virNetServerClientCalculateHandleMode:166 :
tls=(nil) hs=-1, rx=0x561dca9e1050 tx=(nil)
2018-11-13 14:21:39.943+0000: 95205: debug : virNetServerClientCalculateHandleMode:201 :
mode=1
2018-11-13 14:21:39.943+0000: 95205: info : virEventPollUpdateHandle:152 :
EVENT_POLL_UPDATE_HANDLE: watch=12 events=1
2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollInterruptLocked:722 : Skip
interrupt, 1 140197681715264
2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollCleanupTimeouts:525 : Cleanup 2
2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollCleanupHandles:574 : Cleanup 12
2018-11-13 14:21:39.943+0000: 95205: debug : virEventRunDefaultImpl:311 : running default
event implementation
2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollCleanupTimeouts:525 : Cleanup 2
2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollCleanupHandles:574 : Cleanup 12
2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=0
w=1, f=5 e=1 d=0
2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=1
w=2, f=7 e=1 d=0
2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=2
w=3, f=9 e=1 d=0
2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=3
w=4, f=10 e=1 d=0
2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=4
w=5, f=11 e=1 d=0
2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=5
w=6, f=12 e=1 d=0
2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=6
w=7, f=13 e=1 d=0
2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=7
w=8, f=14 e=1 d=0
2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=8
w=9, f=15 e=1 d=0
2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=9
w=10, f=17 e=1 d=0
2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=10
w=11, f=18 e=1 d=0
2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=11
w=12, f=19 e=1 d=0
2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollCalculateTimeout:338 : Calculate
expiry of 2 timers
2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollCalculateTimeout:346 : Got a
timeout scheduled for 1542118904942
2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollCalculateTimeout:359 : Schedule
timeout then=1542118904942 now=1542118899943
2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollCalculateTimeout:369 : Timeout at
1542118904942 due in 4999 ms
2018-11-13 14:21:39.943+0000: 95205: info : virEventPollRunOnce:640 : EVENT_POLL_RUN:
nhandles=12 timeout=4999
2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollRunOnce:650 : Poll got 1
event(s)
2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollDispatchTimeouts:432 : Dispatch
2
2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollDispatchHandles:478 : Dispatch
12
2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollDispatchHandles:492 : i=0 w=1
2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollDispatchHandles:492 : i=1 w=2
2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollDispatchHandles:492 : i=2 w=3
2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollDispatchHandles:492 : i=3 w=4
2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollDispatchHandles:492 : i=4 w=5
2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollDispatchHandles:492 : i=5 w=6
2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollDispatchHandles:492 : i=6 w=7
2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollDispatchHandles:492 : i=7 w=8
2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollDispatchHandles:492 : i=8 w=9
2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollDispatchHandles:492 : i=9 w=10
2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollDispatchHandles:492 : i=10 w=11
2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollDispatchHandles:492 : i=11 w=12
2018-11-13 14:21:39.943+0000: 95205: info : virEventPollDispatchHandles:506 :
EVENT_POLL_DISPATCH_HANDLE: watch=12 events=1
2018-11-13 14:21:39.943+0000: 95205: debug : virNetMessageDecodeLength:161 : Got length,
now need 28 total (24 more)
2018-11-13 14:21:39.943+0000: 95205: debug : virNetServerClientCalculateHandleMode:166 :
tls=(nil) hs=-1, rx=0x561dca9e1050 tx=(nil)
2018-11-13 14:21:39.943+0000: 95205: debug : virNetServerClientCalculateHandleMode:201 :
mode=1
2018-11-13 14:21:39.943+0000: 95205: info : virEventPollUpdateHandle:152 :
EVENT_POLL_UPDATE_HANDLE: watch=12 events=1
2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollInterruptLocked:722 : Skip
interrupt, 1 140197681715264
2018-11-13 14:21:39.943+0000: 95205: info : virNetServerClientDispatchRead:1231 :
RPC_SERVER_CLIENT_MSG_RX: client=0x561dca9e6e60 len=28 prog=1801807216 vers=1 proc=2
type=2 status=0 serial=0
2018-11-13 14:21:39.943+0000: 95205: debug : virKeepAliveCheckMessage:374 :
ka=0x561dca9e7b60, client=0x561dca9e6e60, msg=0x561dca9e1050
2018-11-13 14:21:39.943+0000: 95205: info : virKeepAliveCheckMessage:391 :
RPC_KEEPALIVE_RECEIVED: ka=0x561dca9e7b60 client=0x561dca9e6e60 prog=1801807216 vers=1
proc=2
2018-11-13 14:21:39.943+0000: 95205: debug : virKeepAliveCheckMessage:400 : Got keepalive
response from client 0x561dca9e6e60
2018-11-13 14:21:39.943+0000: 95205: info : virEventPollUpdateTimeout:265 :
EVENT_POLL_UPDATE_TIMEOUT: timer=2 frequency=5000
2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollUpdateTimeout:282 : Set timer
freq=5000 expires=1542118904943
2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollInterruptLocked:722 : Skip
interrupt, 1 140197681715264
2018-11-13 14:21:39.943+0000: 95205: debug : virNetMessageFree:87 : msg=0x561dca9e1050
nfds=0 cb=(nil)
2018-11-13 14:21:39.943+0000: 95205: debug : virNetMessageNew:46 : msg=0x561dca9e1050
tracked=1
2018-11-13 14:21:39.943+0000: 95205: debug : virNetServerClientCalculateHandleMode:166 :
tls=(nil) hs=-1, rx=0x561dca9e1050 tx=(nil)
2018-11-13 14:21:39.943+0000: 95205: debug : virNetServerClientCalculateHandleMode:201 :
mode=1
2018-11-13 14:21:39.943+0000: 95205: info : virEventPollUpdateHandle:152 :
EVENT_POLL_UPDATE_HANDLE: watch=12 events=1
2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollInterruptLocked:722 : Skip
interrupt, 1 140197681715264
2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollCleanupTimeouts:525 : Cleanup 2
2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollCleanupHandles:574 : Cleanup 12
2018-11-13 14:21:39.943+0000: 95205: debug : virEventRunDefaultImpl:311 : running default
event implementation
2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollCleanupTimeouts:525 : Cleanup 2
2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollCleanupHandles:574 : Cleanup 12
2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=0
w=1, f=5 e=1 d=0
2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=1
w=2, f=7 e=1 d=0
2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=2
w=3, f=9 e=1 d=0
2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=3
w=4, f=10 e=1 d=0
2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=4
w=5, f=11 e=1 d=0
2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=5
w=6, f=12 e=1 d=0
2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=6
w=7, f=13 e=1 d=0
2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=7
w=8, f=14 e=1 d=0
2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=8
w=9, f=15 e=1 d=0
2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=9
w=10, f=17 e=1 d=0
2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=10
w=11, f=18 e=1 d=0
2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=11
w=12, f=19 e=1 d=0
2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollCalculateTimeout:338 : Calculate
expiry of 2 timers
2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollCalculateTimeout:346 : Got a
timeout scheduled for 1542118904943
2018-11-13 14:21:39.944+0000: 95205: debug : virEventPollCalculateTimeout:359 : Schedule
timeout then=1542118904943 now=1542118899944
2018-11-13 14:21:39.944+0000: 95205: debug : virEventPollCalculateTimeout:369 : Timeout at
1542118904943 due in 4999 ms
2018-11-13 14:21:39.944+0000: 95205: info : virEventPollRunOnce:640 : EVENT_POLL_RUN:
nhandles=12 timeout=4999
2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollRunOnce:650 : Poll got 0
event(s)
2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollDispatchTimeouts:432 : Dispatch
2
2018-11-13 14:21:44.948+0000: 95205: info : virEventPollDispatchTimeouts:455 :
EVENT_POLL_DISPATCH_TIMEOUT: timer=2
2018-11-13 14:21:44.948+0000: 95205: info : virObjectRef:296 : OBJECT_REF:
obj=0x561dca9e7b60
2018-11-13 14:21:44.948+0000: 95205: info : virKeepAliveTimerInternal:136 :
RPC_KEEPALIVE_TIMEOUT: ka=0x561dca9e7b60 client=0x561dca9e6e60 countToDeath=5 idle=5
2018-11-13 14:21:44.948+0000: 95205: debug : virNetMessageNew:46 : msg=0x561dca9e06b0
tracked=0
2018-11-13 14:21:44.948+0000: 95205: debug : virNetMessageEncodePayloadEmpty:492 : Encode
length as 28
2018-11-13 14:21:44.948+0000: 95205: debug : virKeepAliveMessage:104 : Sending keepalive
request to client 0x561dca9e6e60
2018-11-13 14:21:44.948+0000: 95205: info : virKeepAliveMessage:107 : RPC_KEEPALIVE_SEND:
ka=0x561dca9e7b60 client=0x561dca9e6e60 prog=1801807216 vers=1 proc=1
2018-11-13 14:21:44.948+0000: 95205: info : virEventPollUpdateTimeout:265 :
EVENT_POLL_UPDATE_TIMEOUT: timer=2 frequency=5000
2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollUpdateTimeout:282 : Set timer
freq=5000 expires=1542118909948
2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollInterruptLocked:722 : Skip
interrupt, 1 140197681715264
2018-11-13 14:21:44.948+0000: 95205: debug : virNetServerClientSendMessageLocked:1480 :
msg=0x561dca9e06b0 proc=1 len=28 offset=0
2018-11-13 14:21:44.948+0000: 95205: info : virNetServerClientSendMessageLocked:1488 :
RPC_SERVER_CLIENT_MSG_TX_QUEUE: client=0x561dca9e6e60 len=28 prog=1801807216 vers=1 proc=1
type=2 status=0 serial=0
2018-11-13 14:21:44.948+0000: 95205: debug : virNetServerClientCalculateHandleMode:166 :
tls=(nil) hs=-1, rx=0x561dca9e1050 tx=0x561dca9e06b0
2018-11-13 14:21:44.948+0000: 95205: debug : virNetServerClientCalculateHandleMode:201 :
mode=3
2018-11-13 14:21:44.948+0000: 95205: info : virEventPollUpdateHandle:152 :
EVENT_POLL_UPDATE_HANDLE: watch=12 events=3
2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollInterruptLocked:722 : Skip
interrupt, 1 140197681715264
2018-11-13 14:21:44.948+0000: 95205: info : virObjectUnref:259 : OBJECT_UNREF:
obj=0x561dca9e7b60
2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollCleanupTimeouts:525 : Cleanup 2
2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollCleanupHandles:574 : Cleanup 12
2018-11-13 14:21:44.948+0000: 95205: debug : virEventRunDefaultImpl:311 : running default
event implementation
2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollCleanupTimeouts:525 : Cleanup 2
2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollCleanupHandles:574 : Cleanup 12
2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=0
w=1, f=5 e=1 d=0
2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=1
w=2, f=7 e=1 d=0
2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=2
w=3, f=9 e=1 d=0
2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=3
w=4, f=10 e=1 d=0
2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=4
w=5, f=11 e=1 d=0
2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=5
w=6, f=12 e=1 d=0
2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=6
w=7, f=13 e=1 d=0
2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=7
w=8, f=14 e=1 d=0
2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=8
w=9, f=15 e=1 d=0
2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=9
w=10, f=17 e=1 d=0
2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=10
w=11, f=18 e=1 d=0
2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=11
w=12, f=19 e=5 d=0
2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollCalculateTimeout:338 : Calculate
expiry of 2 timers
2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollCalculateTimeout:346 : Got a
timeout scheduled for 1542118909948
2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollCalculateTimeout:359 : Schedule
timeout then=1542118909948 now=1542118904948
2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollCalculateTimeout:369 : Timeout at
1542118909948 due in 5000 ms
2018-11-13 14:21:44.948+0000: 95205: info : virEventPollRunOnce:640 : EVENT_POLL_RUN:
nhandles=12 timeout=5000
2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollRunOnce:650 : Poll got 1
event(s)
2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollDispatchTimeouts:432 : Dispatch
2
2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollDispatchHandles:478 : Dispatch
12
2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollDispatchHandles:492 : i=0 w=1
2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollDispatchHandles:492 : i=1 w=2
2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollDispatchHandles:492 : i=2 w=3
2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollDispatchHandles:492 : i=3 w=4
2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollDispatchHandles:492 : i=4 w=5
2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollDispatchHandles:492 : i=5 w=6
2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollDispatchHandles:492 : i=6 w=7
2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollDispatchHandles:492 : i=7 w=8
2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollDispatchHandles:492 : i=8 w=9
2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollDispatchHandles:492 : i=9 w=10
2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollDispatchHandles:492 : i=10 w=11
2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollDispatchHandles:492 : i=11 w=12
2018-11-13 14:21:44.948+0000: 95205: info : virEventPollDispatchHandles:506 :
EVENT_POLL_DISPATCH_HANDLE: watch=12 events=2
2018-11-13 14:21:44.948+0000: 95205: debug : virNetMessageFree:87 : msg=0x561dca9e06b0
nfds=0 cb=(nil)
2018-11-13 14:21:44.948+0000: 95205: debug : virNetServerClientCalculateHandleMode:166 :
tls=(nil) hs=-1, rx=0x561dca9e1050 tx=(nil)
2018-11-13 14:21:44.948+0000: 95205: debug : virNetServerClientCalculateHandleMode:201 :
mode=1
2018-11-13 14:21:44.948+0000: 95205: info : virEventPollUpdateHandle:152 :
EVENT_POLL_UPDATE_HANDLE: watch=12 events=1
2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollInterruptLocked:722 : Skip
interrupt, 1 140197681715264
2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollCleanupTimeouts:525 : Cleanup 2
2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollCleanupHandles:574 : Cleanup 12
2018-11-13 14:21:44.948+0000: 95205: debug : virEventRunDefaultImpl:311 : running default
event implementation
2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollCleanupTimeouts:525 : Cleanup 2
2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollCleanupHandles:574 : Cleanup 12
2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=0
w=1, f=5 e=1 d=0
2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=1
w=2, f=7 e=1 d=0
2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=2
w=3, f=9 e=1 d=0
2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=3
w=4, f=10 e=1 d=0
2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=4
w=5, f=11 e=1 d=0
2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=5
w=6, f=12 e=1 d=0
2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=6
w=7, f=13 e=1 d=0
2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=7
w=8, f=14 e=1 d=0
2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=8
w=9, f=15 e=1 d=0
2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=9
w=10, f=17 e=1 d=0
2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=10
w=11, f=18 e=1 d=0
2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=11
w=12, f=19 e=1 d=0
2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollCalculateTimeout:338 : Calculate
expiry of 2 timers
2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollCalculateTimeout:346 : Got a
timeout scheduled for 1542118909948
2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollCalculateTimeout:359 : Schedule
timeout then=1542118909948 now=1542118904948
2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollCalculateTimeout:369 : Timeout at
1542118909948 due in 5000 ms
2018-11-13 14:21:44.948+0000: 95205: info : virEventPollRunOnce:640 : EVENT_POLL_RUN:
nhandles=12 timeout=5000
2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollRunOnce:650 : Poll got 1
event(s)
2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollDispatchTimeouts:432 : Dispatch
2
2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollDispatchHandles:478 : Dispatch
12
2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollDispatchHandles:492 : i=0 w=1
2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollDispatchHandles:492 : i=1 w=2
2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollDispatchHandles:492 : i=2 w=3
2018-11-13 14:21:44.949+0000: 95205: debug : virEventPollDispatchHandles:492 : i=3 w=4
2018-11-13 14:21:44.949+0000: 95205: debug : virEventPollDispatchHandles:492 : i=4 w=5
2018-11-13 14:21:44.949+0000: 95205: debug : virEventPollDispatchHandles:492 : i=5 w=6
2018-11-13 14:21:44.949+0000: 95205: debug : virEventPollDispatchHandles:492 : i=6 w=7
2018-11-13 14:21:44.949+0000: 95205: debug : virEventPollDispatchHandles:492 : i=7 w=8
2018-11-13 14:21:44.949+0000: 95205: debug : virEventPollDispatchHandles:492 : i=8 w=9
2018-11-13 14:21:44.949+0000: 95205: debug : virEventPollDispatchHandles:492 : i=9 w=10
2018-11-13 14:21:44.949+0000: 95205: debug : virEventPollDispatchHandles:492 : i=10 w=11
2018-11-13 14:21:44.949+0000: 95205: debug : virEventPollDispatchHandles:492 : i=11 w=12
2018-11-13 14:21:44.949+0000: 95205: info : virEventPollDispatchHandles:506 :
EVENT_POLL_DISPATCH_HANDLE: watch=12 events=1
2018-11-13 14:21:44.949+0000: 95205: debug : virNetMessageDecodeLength:161 : Got length,
now need 28 total (24 more)
2018-11-13 14:21:44.949+0000: 95205: debug : virNetServerClientCalculateHandleMode:166 :
tls=(nil) hs=-1, rx=0x561dca9e1050 tx=(nil)
2018-11-13 14:21:44.949+0000: 95205: debug : virNetServerClientCalculateHandleMode:201 :
mode=1
2018-11-13 14:21:44.949+0000: 95205: info : virEventPollUpdateHandle:152 :
EVENT_POLL_UPDATE_HANDLE: watch=12 events=1
2018-11-13 14:21:44.949+0000: 95205: debug : virEventPollInterruptLocked:722 : Skip
interrupt, 1 140197681715264
2018-11-13 14:21:44.949+0000: 95205: info : virNetServerClientDispatchRead:1231 :
RPC_SERVER_CLIENT_MSG_RX: client=0x561dca9e6e60 len=28 prog=1801807216 vers=1 proc=2
type=2 status=0 serial=0
2018-11-13 14:21:44.949+0000: 95205: debug : virKeepAliveCheckMessage:374 :
ka=0x561dca9e7b60, client=0x561dca9e6e60, msg=0x561dca9e1050
2018-11-13 14:21:44.949+0000: 95205: info : virKeepAliveCheckMessage:391 :
RPC_KEEPALIVE_RECEIVED: ka=0x561dca9e7b60 client=0x561dca9e6e60 prog=1801807216 vers=1
proc=2
2018-11-13 14:21:44.949+0000: 95205: debug : virKeepAliveCheckMessage:400 : Got keepalive
response from client 0x561dca9e6e60
2018-11-13 14:21:44.949+0000: 95205: info : virEventPollUpdateTimeout:265 :
EVENT_POLL_UPDATE_TIMEOUT: timer=2 frequency=5000
2018-11-13 14:21:44.949+0000: 95205: debug : virEventPollUpdateTimeout:282 : Set timer
freq=5000 expires=1542118909949
2018-11-13 14:21:44.949+0000: 95205: debug : virEventPollInterruptLocked:722 : Skip
interrupt, 1 140197681715264
2018-11-13 14:21:44.949+0000: 95205: debug : virNetMessageFree:87 : msg=0x561dca9e1050
nfds=0 cb=(nil)
2018-11-13 14:21:44.949+0000: 95205: debug : virNetMessageNew:46 : msg=0x561dca9e1050
tracked=1
2018-11-13 14:21:44.949+0000: 95205: debug : virNetServerClientCalculateHandleMode:166 :
tls=(nil) hs=-1, rx=0x561dca9e1050 tx=(nil)
2018-11-13 14:21:44.949+0000: 95205: debug : virNetServerClientCalculateHandleMode:201 :
mode=1
2018-11-13 14:21:44.949+0000: 95205: info : virEventPollUpdateHandle:152 :
EVENT_POLL_UPDATE_HANDLE: watch=12 events=1
2018-11-13 14:21:44.949+0000: 95205: debug : virEventPollInterruptLocked:722 : Skip
interrupt, 1 140197681715264
2018-11-13 14:21:44.949+0000: 95205: debug : virEventPollCleanupTimeouts:525 : Cleanup 2
2018-11-13 14:21:44.949+0000: 95205: debug : virEventPollCleanupHandles:574 : Cleanup 12
2018-11-13 14:21:44.949+0000: 95205: debug : virEventRunDefaultImpl:311 : running default
event implementation
2018-11-13 14:21:44.949+0000: 95205: debug : virEventPollCleanupTimeouts:525 : Cleanup 2
2018-11-13 14:21:44.949+0000: 95205: debug : virEventPollCleanupHandles:574 : Cleanup 12
2018-11-13 14:21:44.949+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=0
w=1, f=5 e=1 d=0
2018-11-13 14:21:44.949+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=1
w=2, f=7 e=1 d=0
2018-11-13 14:21:44.949+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=2
w=3, f=9 e=1 d=0
2018-11-13 14:21:44.949+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=3
w=4, f=10 e=1 d=0
2018-11-13 14:21:44.949+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=4
w=5, f=11 e=1 d=0
2018-11-13 14:21:44.949+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=5
w=6, f=12 e=1 d=0
2018-11-13 14:21:44.949+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=6
w=7, f=13 e=1 d=0
2018-11-13 14:21:44.949+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=7
w=8, f=14 e=1 d=0
2018-11-13 14:21:44.949+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=8
w=9, f=15 e=1 d=0
2018-11-13 14:21:44.949+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=9
w=10, f=17 e=1 d=0
2018-11-13 14:21:44.949+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=10
w=11, f=18 e=1 d=0
2018-11-13 14:21:44.949+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=11
w=12, f=19 e=1 d=0
2018-11-13 14:21:44.949+0000: 95205: debug : virEventPollCalculateTimeout:338 : Calculate
expiry of 2 timers
2018-11-13 14:21:44.949+0000: 95205: debug : virEventPollCalculateTimeout:346 : Got a
timeout scheduled for 1542118909949
2018-11-13 14:21:44.949+0000: 95205: debug : virEventPollCalculateTimeout:359 : Schedule
timeout then=1542118909949 now=1542118904949
2018-11-13 14:21:44.949+0000: 95205: debug : virEventPollCalculateTimeout:369 : Timeout at
1542118909949 due in 5000 ms
2018-11-13 14:21:44.949+0000: 95205: info : virEventPollRunOnce:640 : EVENT_POLL_RUN:
nhandles=12 timeout=5000
2018-11-13 14:21:49.954+0000: 95205: debug : virEventPollRunOnce:650 : Poll got 0
event(s)
2018-11-13 14:21:49.954+0000: 95205: debug : virEventPollDispatchTimeouts:432 : Dispatch
2
2018-11-13 14:21:49.954+0000: 95205: info : virEventPollDispatchTimeouts:455 :
EVENT_POLL_DISPATCH_TIMEOUT: timer=2
2018-11-13 14:21:49.954+0000: 95205: info : virObjectRef:296 : OBJECT_REF:
obj=0x561dca9e7b60
2018-11-13 14:21:49.954+0000: 95205: info : virKeepAliveTimerInternal:136 :
RPC_KEEPALIVE_TIMEOUT: ka=0x561dca9e7b60 client=0x561dca9e6e60 countToDeath=5 idle=5
2018-11-13 14:21:49.954+0000: 95205: debug : virNetMessageNew:46 : msg=0x561dca9d9d90
tracked=0
2018-11-13 14:21:49.954+0000: 95205: debug : virNetMessageEncodePayloadEmpty:492 : Encode
length as 28
2018-11-13 14:21:49.954+0000: 95205: debug : virKeepAliveMessage:104 : Sending keepalive
request to client 0x561dca9e6e60
2018-11-13 14:21:49.954+0000: 95205: info : virKeepAliveMessage:107 : RPC_KEEPALIVE_SEND:
ka=0x561dca9e7b60 client=0x561dca9e6e60 prog=1801807216 vers=1 proc=1
2018-11-13 14:21:49.954+0000: 95205: info : virEventPollUpdateTimeout:265 :
EVENT_POLL_UPDATE_TIMEOUT: timer=2 frequency=5000
2018-11-13 14:21:49.954+0000: 95205: debug : virEventPollUpdateTimeout:282 : Set timer
freq=5000 expires=1542118914954
2018-11-13 14:21:49.954+0000: 95205: debug : virEventPollInterruptLocked:722 : Skip
interrupt, 1 140197681715264
2018-11-13 14:21:49.954+0000: 95205: debug : virNetServerClientSendMessageLocked:1480 :
msg=0x561dca9d9d90 proc=1 len=28 offset=0
2018-11-13 14:21:49.954+0000: 95205: info : virNetServerClientSendMessageLocked:1488 :
RPC_SERVER_CLIENT_MSG_TX_QUEUE: client=0x561dca9e6e60 len=28 prog=1801807216 vers=1 proc=1
type=2 status=0 serial=0
2018-11-13 14:21:49.954+0000: 95205: debug : virNetServerClientCalculateHandleMode:166 :
tls=(nil) hs=-1, rx=0x561dca9e1050 tx=0x561dca9d9d90
2018-11-13 14:21:49.954+0000: 95205: debug : virNetServerClientCalculateHandleMode:201 :
mode=3
2018-11-13 14:21:49.954+0000: 95205: info : virEventPollUpdateHandle:152 :
EVENT_POLL_UPDATE_HANDLE: watch=12 events=3
2018-11-13 14:21:49.954+0000: 95205: debug : virEventPollInterruptLocked:722 : Skip
interrupt, 1 140197681715264
2018-11-13 14:21:49.954+0000: 95205: info : virObjectUnref:259 : OBJECT_UNREF:
obj=0x561dca9e7b60
2018-11-13 14:21:49.954+0000: 95205: debug : virEventPollCleanupTimeouts:525 : Cleanup 2
2018-11-13 14:21:49.954+0000: 95205: debug : virEventPollCleanupHandles:574 : Cleanup 12
2018-11-13 14:21:49.954+0000: 95205: debug : virEventRunDefaultImpl:311 : running default
event implementation
2018-11-13 14:21:49.954+0000: 95205: debug : virEventPollCleanupTimeouts:525 : Cleanup 2
2018-11-13 14:21:49.954+0000: 95205: debug : virEventPollCleanupHandles:574 : Cleanup 12
2018-11-13 14:21:49.954+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=0
w=1, f=5 e=1 d=0
2018-11-13 14:21:49.954+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=1
w=2, f=7 e=1 d=0
2018-11-13 14:21:49.954+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=2
w=3, f=9 e=1 d=0
2018-11-13 14:21:49.954+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=3
w=4, f=10 e=1 d=0
2018-11-13 14:21:49.954+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=4
w=5, f=11 e=1 d=0
2018-11-13 14:21:49.954+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=5
w=6, f=12 e=1 d=0
2018-11-13 14:21:49.954+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=6
w=7, f=13 e=1 d=0
2018-11-13 14:21:49.954+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=7
w=8, f=14 e=1 d=0
2018-11-13 14:21:49.954+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=8
w=9, f=15 e=1 d=0
2018-11-13 14:21:49.954+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=9
w=10, f=17 e=1 d=0
2018-11-13 14:21:49.954+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=10
w=11, f=18 e=1 d=0
2018-11-13 14:21:49.954+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=11
w=12, f=19 e=5 d=0
2018-11-13 14:21:49.954+0000: 95205: debug : virEventPollCalculateTimeout:338 : Calculate
expiry of 2 timers
2018-11-13 14:21:49.954+0000: 95205: debug : virEventPollCalculateTimeout:346 : Got a
timeout scheduled for 1542118914954
2018-11-13 14:21:49.954+0000: 95205: debug : virEventPollCalculateTimeout:359 : Schedule
timeout then=1542118914954 now=1542118909954
2018-11-13 14:21:49.954+0000: 95205: debug : virEventPollCalculateTimeout:369 : Timeout at
1542118914954 due in 5000 ms
2018-11-13 14:21:49.955+0000: 95205: info : virEventPollRunOnce:640 : EVENT_POLL_RUN:
nhandles=12 timeout=5000
2018-11-13 14:21:49.955+0000: 95205: debug : virEventPollRunOnce:650 : Poll got 1
event(s)
2018-11-13 14:21:49.955+0000: 95205: debug : virEventPollDispatchTimeouts:432 : Dispatch
2
2018-11-13 14:21:49.955+0000: 95205: debug : virEventPollDispatchHandles:478 : Dispatch
12
2018-11-13 14:21:49.955+0000: 95205: debug : virEventPollDispatchHandles:492 : i=0 w=1
2018-11-13 14:21:49.955+0000: 95205: debug : virEventPollDispatchHandles:492 : i=1 w=2
2018-11-13 14:21:49.955+0000: 95205: debug : virEventPollDispatchHandles:492 : i=2 w=3
2018-11-13 14:21:49.955+0000: 95205: debug : virEventPollDispatchHandles:492 : i=3 w=4
2018-11-13 14:21:49.955+0000: 95205: debug : virEventPollDispatchHandles:492 : i=4 w=5
2018-11-13 14:21:49.955+0000: 95205: debug : virEventPollDispatchHandles:492 : i=5 w=6
2018-11-13 14:21:49.955+0000: 95205: debug : virEventPollDispatchHandles:492 : i=6 w=7
2018-11-13 14:21:49.955+0000: 95205: debug : virEventPollDispatchHandles:492 : i=7 w=8
2018-11-13 14:21:49.955+0000: 95205: debug : virEventPollDispatchHandles:492 : i=8 w=9
2018-11-13 14:21:49.955+0000: 95205: debug : virEventPollDispatchHandles:492 : i=9 w=10
2018-11-13 14:21:49.955+0000: 95205: debug : virEventPollDispatchHandles:492 : i=10 w=11
2018-11-13 14:21:49.955+0000: 95205: debug : virEventPollDispatchHandles:492 : i=11 w=12
2018-11-13 14:21:49.955+0000: 95205: info : virEventPollDispatchHandles:506 :
EVENT_POLL_DISPATCH_HANDLE: watch=12 events=2
2018-11-13 14:21:49.955+0000: 95205: debug : virNetMessageFree:87 : msg=0x561dca9d9d90
nfds=0 cb=(nil)
2018-11-13 14:21:49.955+0000: 95205: debug : virNetServerClientCalculateHandleMode:166 :
tls=(nil) hs=-1, rx=0x561dca9e1050 tx=(nil)
2018-11-13 14:21:49.955+0000: 95205: debug : virNetServerClientCalculateHandleMode:201 :
mode=1
2018-11-13 14:21:49.955+0000: 95205: info : virEventPollUpdateHandle:152 :
EVENT_POLL_UPDATE_HANDLE: watch=12 events=1
2018-11-13 14:21:49.955+0000: 95205: debug : virEventPollInterruptLocked:722 : Skip
interrupt, 1 140197681715264
2018-11-13 14:21:49.955+0000: 95205: debug : virEventPollCleanupTimeouts:525 : Cleanup 2
2018-11-13 14:21:49.955+0000: 95205: debug : virEventPollCleanupHandles:574 : Cleanup 12
2018-11-13 14:21:49.955+0000: 95205: debug : virEventRunDefaultImpl:311 : running default
event implementation
2018-11-13 14:21:49.955+0000: 95205: debug : virEventPollCleanupTimeouts:525 : Cleanup 2
2018-11-13 14:21:49.955+0000: 95205: debug : virEventPollCleanupHandles:574 : Cleanup 12
2018-11-13 14:21:49.955+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=0
w=1, f=5 e=1 d=0
2018-11-13 14:21:49.955+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=1
w=2, f=7 e=1 d=0
2018-11-13 14:21:49.955+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=2
w=3, f=9 e=1 d=0
2018-11-13 14:21:49.955+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=3
w=4, f=10 e=1 d=0
2018-11-13 14:21:49.955+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=4
w=5, f=11 e=1 d=0
2018-11-13 14:21:49.955+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=5
w=6, f=12 e=1 d=0
2018-11-13 14:21:49.955+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=6
w=7, f=13 e=1 d=0
2018-11-13 14:21:49.955+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=7
w=8, f=14 e=1 d=0
2018-11-13 14:21:49.955+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=8
w=9, f=15 e=1 d=0
2018-11-13 14:21:49.955+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=9
w=10, f=17 e=1 d=0
2018-11-13 14:21:49.955+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=10
w=11, f=18 e=1 d=0
2018-11-13 14:21:49.955+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=11
w=12, f=19 e=1 d=0
2018-11-13 14:21:49.955+0000: 95205: debug : virEventPollCalculateTimeout:338 : Calculate
expiry of 2 timers
2018-11-13 14:21:49.955+0000: 95205: debug : virEventPollCalculateTimeout:346 : Got a
timeout scheduled for 1542118914954
2018-11-13 14:21:49.955+0000: 95205: debug : virEventPollCalculateTimeout:359 : Schedule
timeout then=1542118914954 now=1542118909955
2018-11-13 14:21:49.955+0000: 95205: debug : virEventPollCalculateTimeout:369 : Timeout at
1542118914954 due in 4999 ms
2018-11-13 14:21:49.955+0000: 95205: info : virEventPollRunOnce:640 : EVENT_POLL_RUN:
nhandles=12 timeout=4999

2024

2023

2022

2021

2020

2019

2018

2017

2016

2015

2014

2013

2012

2011

2010

[libvirt-users] create vm timeout