Attachment 868890 Details for Bug 1071181 – libvirtd_debug.log

libvirtd_debug.log

libvirtd_debug_clipped.log (text/plain), 64.45 KB, created by Hu Jianwei on 2014-02-28 08:32:49 UTC

(hide)

Description:

Filename:

MIME Type:

Creator: Hu Jianwei

Created: 2014-02-28 08:32:49 UTC

Size: 64.45 KB

patch

obsolete

>
>2014-02-28 05:56:45.999+0000: 478: debug : virFileClose:90 : Closed fd 25
>2014-02-28 05:56:45.999+0000: 478: debug : virFileClose:90 : Closed fd 27
>2014-02-28 05:56:46.023+0000: 2398: error : virNWFilterSnoopDHCPOpen:1116 : internal error: setup of pcap handle failed
>2014-02-28 05:56:46.029+0000: 2398: debug : virFileClose:90 : Closed fd 24
>Caught abort signal dumping internal log buffer:
>
>
>    ====== start of log =====
>
>\00 Dispatch 2
>2014-02-28 05:56:45.847+0000: 476: debug : virEventPollDispatchHandles:468 : Dispatch 9
>2014-02-28 05:56:45.847+0000: 476: debug : virEventPollDispatchHandles:482 : i=0 w=1
>2014-02-28 05:56:45.847+0000: 476: debug : virEventPollDispatchHandles:482 : i=1 w=2
>2014-02-28 05:56:45.847+0000: 476: debug : virEventPollDispatchHandles:482 : i=2 w=3
>2014-02-28 05:56:45.847+0000: 476: debug : virEventPollDispatchHandles:482 : i=3 w=4
>2014-02-28 05:56:45.847+0000: 476: debug : virEventPollDispatchHandles:482 : i=4 w=5
>2014-02-28 05:56:45.847+0000: 476: debug : virEventPollDispatchHandles:482 : i=5 w=6
>2014-02-28 05:56:45.847+0000: 476: debug : virEventPollDispatchHandles:482 : i=7 w=8
>2014-02-28 05:56:45.847+0000: 476: debug : virEventPollDispatchHandles:482 : i=8 w=9
>2014-02-28 05:56:45.847+0000: 476: debug : virEventPollDispatchHandles:482 : i=9 w=39
>2014-02-28 05:56:45.847+0000: 476: debug : virEventPollDispatchHandles:496 : EVENT_POLL_DISPATCH_HANDLE: watch=39 events=1
>2014-02-28 05:56:45.847+0000: 476: debug : virNetMessageDecodeLength:149 : Got length, now need 36 total (32 more)
>2014-02-28 05:56:45.847+0000: 476: debug : virNetServerClientCalculateHandleMode:153 : tls=(nil) hs=-1, rx=0x7fcda71b7900 tx=(nil)
>2014-02-28 05:56:45.847+0000: 476: debug : virNetServerClientCalculateHandleMode:188 : mode=1
>2014-02-28 05:56:45.847+0000: 476: debug : virEventPollUpdateHandle:147 : EVENT_POLL_UPDATE_HANDLE: watch=39 events=1
>2014-02-28 05:56:45.847+0000: 476: debug : virEventPollInterruptLocked:710 : Skip interrupt, 1 140521230579840
>2014-02-28 05:56:45.847+0000: 476: debug : virNetServerClientDispatchRead:1202 : RPC_SERVER_CLIENT_MSG_RX: client=0x7fcda71b88d0 len=36 prog=536903814 vers=1 proc=23 type=0 status=0 serial=4
>2014-02-28 05:56:45.847+0000: 476: debug : virKeepAliveCheckMessage:374 : ka=0x7fcda71b9390, client=0x7fcda71b88d0, msg=0x7fcda71b7900
>2014-02-28 05:56:45.847+0000: 476: debug : virEventPollUpdateTimeout:260 : EVENT_POLL_UPDATE_TIMEOUT: timer=58 frequency=5000
>2014-02-28 05:56:45.847+0000: 476: debug : virEventPollUpdateTimeout:278 : Set timer freq=5000 expires=1393567010847
>2014-02-28 05:56:45.847+0000: 476: debug : virEventPollInterruptLocked:710 : Skip interrupt, 1 140521230579840
>2014-02-28 05:56:45.847+0000: 476: debug : virObjectRef:293 : OBJECT_REF: obj=0x7fcda71b88d0
>2014-02-28 05:56:45.847+0000: 476: debug : virNetServerDispatchNewMessage:214 : server=0x7fcda71a8d70 client=0x7fcda71b88d0 message=0x7fcda71b7900
>2014-02-28 05:56:45.847+0000: 476: debug : virObjectRef:293 : OBJECT_REF: obj=0x7fcda71b4b30
>2014-02-28 05:56:45.847+0000: 476: debug : virNetMessageNew:44 : msg=0x7fcda71b9280 tracked=1
>2014-02-28 05:56:45.847+0000: 476: debug : virNetServerClientCalculateHandleMode:153 : tls=(nil) hs=-1, rx=0x7fcda71b9280 tx=(nil)
>2014-02-28 05:56:45.847+0000: 476: debug : virNetServerClientCalculateHandleMode:188 : mode=1
>2014-02-28 05:56:45.847+0000: 476: debug : virEventPollUpdateHandle:147 : EVENT_POLL_UPDATE_HANDLE: watch=39 events=1
>2014-02-28 05:56:45.847+0000: 476: debug : virEventPollInterruptLocked:710 : Skip interrupt, 1 140521230579840
>2014-02-28 05:56:45.847+0000: 476: debug : virEventPollCleanupTimeouts:514 : Cleanup 2
>2014-02-28 05:56:45.847+0000: 476: debug : virEventPollCleanupHandles:562 : Cleanup 10
>2014-02-28 05:56:45.847+0000: 476: debug : virEventRunDefaultImpl:270 : running default event implementation
>2014-02-28 05:56:45.847+0000: 476: debug : virEventPollCleanupTimeouts:514 : Cleanup 2
>2014-02-28 05:56:45.847+0000: 476: debug : virEventPollCleanupHandles:562 : Cleanup 10
>2014-02-28 05:56:45.847+0000: 476: debug : virEventPollMakePollFDs:391 : Prepare n=0 w=1, f=6 e=1 d=0
>2014-02-28 05:56:45.847+0000: 476: debug : virEventPollMakePollFDs:391 : Prepare n=1 w=2, f=8 e=1 d=0
>2014-02-28 05:56:45.847+0000: 476: debug : virEventPollMakePollFDs:391 : Prepare n=2 w=3, f=11 e=1 d=0
>2014-02-28 05:56:45.847+0000: 486: debug : virNetServerHandleJob:185 : server=0x7fcda71a8d70 client=0x7fcda71b88d0 message=0x7fcda71b7900 prog=0x7fcda71b4b30
>2014-02-28 05:56:45.847+0000: 476: debug : virEventPollMakePollFDs:391 : Prepare n=3 w=4, f=12 e=1 d=0
>2014-02-28 05:56:45.847+0000: 486: debug : virNetServerProgramDispatch:285 : prog=536903814 ver=1 type=0 status=0 serial=4 proc=23
>2014-02-28 05:56:45.847+0000: 476: debug : virEventPollMakePollFDs:391 : Prepare n=4 w=5, f=14 e=1 d=0
>2014-02-28 05:56:45.847+0000: 476: debug : virEventPollMakePollFDs:391 : Prepare n=5 w=6, f=19 e=1 d=0
>2014-02-28 05:56:45.847+0000: 486: debug : virObjectRef:293 : OBJECT_REF: obj=0x7fcd70000a40
>2014-02-28 05:56:45.847+0000: 476: debug : virEventPollMakePollFDs:391 : Prepare n=6 w=7, f=13 e=0 d=0
>2014-02-28 05:56:45.847+0000: 486: debug : virObjectRef:293 : OBJECT_REF: obj=0x7fcd70000a40
>2014-02-28 05:56:45.847+0000: 476: debug : virEventPollMakePollFDs:391 : Prepare n=7 w=8, f=13 e=1 d=0
>2014-02-28 05:56:45.847+0000: 486: debug : remoteDispatchDomainLookupByNameHelper:4943 : server=0x7fcda71a8d70 client=0x7fcda71b88d0 msg=0x7fcda71b7900 rerr=0x7fcd92567c80 args=0x7fcd60000980 ret=0x7fcd600009e0
>2014-02-28 05:56:45.847+0000: 476: debug : virEventPollMakePollFDs:391 : Prepare n=8 w=9, f=16 e=1 d=0
>2014-02-28 05:56:45.847+0000: 486: debug : virDomainLookupByName:2264 : conn=0x7fcd68000de0, name=r7
>2014-02-28 05:56:45.847+0000: 476: debug : virEventPollMakePollFDs:391 : Prepare n=9 w=39, f=21 e=1 d=0
>2014-02-28 05:56:45.847+0000: 476: debug : virEventPollCalculateTimeout:332 : Calculate expiry of 2 timers
>2014-02-28 05:56:45.847+0000: 486: debug : virObjectRef:293 : OBJECT_REF: obj=0x7fcda71b4210
>2014-02-28 05:56:45.847+0000: 476: debug : virEventPollCalculateTimeout:340 : Got a timeout scheduled for 1393567010847
>2014-02-28 05:56:45.847+0000: 486: debug : virAccessManagerCheckDomain:231 : manager=0x7fcda71b4210(name=stack) driver=QEMU domain=0x7fcd8827e3b0 perm=0
>2014-02-28 05:56:45.847+0000: 476: debug : virEventPollCalculateTimeout:353 : Schedule timeout then=1393567010847 now=1393567005847
>2014-02-28 05:56:45.847+0000: 486: debug : virAccessManagerCheckDomain:231 : manager=0x7fcda71a89e0(name=none) driver=QEMU domain=0x7fcd8827e3b0 perm=0
>2014-02-28 05:56:45.847+0000: 476: debug : virEventPollCalculateTimeout:361 : Timeout at 1393567010847 due in 5000 ms
>2014-02-28 05:56:45.847+0000: 486: debug : virObjectUnref:256 : OBJECT_UNREF: obj=0x7fcda71b4210
>2014-02-28 05:56:45.847+0000: 476: debug : virEventPollRunOnce:627 : EVENT_POLL_RUN: nhandles=9 timeout=5000
>2014-02-28 05:56:45.847+0000: 486: debug : virObjectNew:199 : OBJECT_NEW: obj=0x7fcd600009a0 classname=virDomain
>2014-02-28 05:56:45.847+0000: 486: debug : virObjectRef:293 : OBJECT_REF: obj=0x7fcd68000de0
>2014-02-28 05:56:45.847+0000: 486: debug : virDomainFree:2428 : dom=0x7fcd600009a0, (VM: name=r7, uuid=219e27b1-f639-4cbf-80a1-9ed45b3657f2)
>2014-02-28 05:56:45.847+0000: 486: debug : virObjectUnref:256 : OBJECT_UNREF: obj=0x7fcd600009a0
>2014-02-28 05:56:45.847+0000: 486: debug : virObjectUnref:258 : OBJECT_DISPOSE: obj=0x7fcd600009a0
>2014-02-28 05:56:45.847+0000: 486: debug : virDomainDispose:262 : release domain 0x7fcd600009a0 r7 219e27b1-f639-4cbf-80a1-9ed45b3657f2
>2014-02-28 05:56:45.847+0000: 486: debug : virObjectUnref:256 : OBJECT_UNREF: obj=0x7fcd68000de0
>2014-02-28 05:56:45.847+0000: 486: debug : virObjectUnref:256 : OBJECT_UNREF: obj=0x7fcd70000a40
>2014-02-28 05:56:45.847+0000: 486: debug : virNetMessageEncodePayload:374 : Encode length as 56
>2014-02-28 05:56:45.847+0000: 486: debug : virObjectUnref:256 : OBJECT_UNREF: obj=0x7fcd70000a40
>2014-02-28 05:56:45.847+0000: 486: debug : virNetServerClientSendMessageLocked:1451 : msg=0x7fcda71b7900 proc=23 len=56 offset=0
>2014-02-28 05:56:45.847+0000: 486: debug : virNetServerClientSendMessageLocked:1459 : RPC_SERVER_CLIENT_MSG_TX_QUEUE: client=0x7fcda71b88d0 len=56 prog=536903814 vers=1 proc=23 type=1 status=0 serial=4
>2014-02-28 05:56:45.847+0000: 486: debug : virNetServerClientCalculateHandleMode:153 : tls=(nil) hs=-1, rx=0x7fcda71b9280 tx=0x7fcda71b7900
>2014-02-28 05:56:45.847+0000: 486: debug : virNetServerClientCalculateHandleMode:188 : mode=3
>2014-02-28 05:56:45.847+0000: 486: debug : virEventPollUpdateHandle:147 : EVENT_POLL_UPDATE_HANDLE: watch=39 events=3
>2014-02-28 05:56:45.847+0000: 486: debug : virEventPollInterruptLocked:714 : Interrupting
>2014-02-28 05:56:45.847+0000: 486: debug : virObjectUnref:256 : OBJECT_UNREF: obj=0x7fcda71b4b30
>2014-02-28 05:56:45.847+0000: 476: debug : virEventPollRunOnce:638 : Poll got 1 event(s)
>2014-02-28 05:56:45.847+0000: 486: debug : virObjectUnref:256 : OBJECT_UNREF: obj=0x7fcda71b88d0
>2014-02-28 05:56:45.847+0000: 476: debug : virEventPollDispatchTimeouts:423 : Dispatch 2
>2014-02-28 05:56:45.847+0000: 476: debug : virEventPollDispatchHandles:468 : Dispatch 9
>2014-02-28 05:56:45.847+0000: 476: debug : virEventPollDispatchHandles:482 : i=0 w=1
>2014-02-28 05:56:45.847+0000: 476: debug : virEventPollDispatchHandles:496 : EVENT_POLL_DISPATCH_HANDLE: watch=1 events=1
>2014-02-28 05:56:45.847+0000: 476: debug : virEventPollDispatchHandles:482 : i=1 w=2
>2014-02-28 05:56:45.847+0000: 476: debug : virEventPollDispatchHandles:482 : i=2 w=3
>2014-02-28 05:56:45.847+0000: 476: debug : virEventPollDispatchHandles:482 : i=3 w=4
>2014-02-28 05:56:45.847+0000: 476: debug : virEventPollDispatchHandles:482 : i=4 w=5
>2014-02-28 05:56:45.847+0000: 476: debug : virEventPollDispatchHandles:482 : i=5 w=6
>2014-02-28 05:56:45.847+0000: 476: debug : virEventPollDispatchHandles:482 : i=7 w=8
>2014-02-28 05:56:45.847+0000: 476: debug : virEventPollDispatchHandles:482 : i=8 w=9
>2014-02-28 05:56:45.847+0000: 476: debug : virEventPollDispatchHandles:482 : i=9 w=39
>2014-02-28 05:56:45.847+0000: 476: debug : virEventPollCleanupTimeouts:514 : Cleanup 2
>2014-02-28 05:56:45.847+0000: 476: debug : virEventPollCleanupHandles:562 : Cleanup 10
>2014-02-28 05:56:45.847+0000: 476: debug : virEventRunDefaultImpl:270 : running default event implementation
>2014-02-28 05:56:45.847+0000: 476: debug : virEventPollCleanupTimeouts:514 : Cleanup 2
>2014-02-28 05:56:45.847+0000: 476: debug : virEventPollCleanupHandles:562 : Cleanup 10
>2014-02-28 05:56:45.847+0000: 476: debug : virEventPollMakePollFDs:391 : Prepare n=0 w=1, f=6 e=1 d=0
>2014-02-28 05:56:45.847+0000: 476: debug : virEventPollMakePollFDs:391 : Prepare n=1 w=2, f=8 e=1 d=0
>2014-02-28 05:56:45.847+0000: 476: debug : virEventPollMakePollFDs:391 : Prepare n=2 w=3, f=11 e=1 d=0
>2014-02-28 05:56:45.847+0000: 476: debug : virEventPollMakePollFDs:391 : Prepare n=3 w=4, f=12 e=1 d=0
>2014-02-28 05:56:45.847+0000: 476: debug : virEventPollMakePollFDs:391 : Prepare n=4 w=5, f=14 e=1 d=0
>2014-02-28 05:56:45.847+0000: 476: debug : virEventPollMakePollFDs:391 : Prepare n=5 w=6, f=19 e=1 d=0
>2014-02-28 05:56:45.847+0000: 476: debug : virEventPollMakePollFDs:391 : Prepare n=6 w=7, f=13 e=0 d=0
>2014-02-28 05:56:45.847+0000: 476: debug : virEventPollMakePollFDs:391 : Prepare n=7 w=8, f=13 e=1 d=0
>2014-02-28 05:56:45.847+0000: 476: debug : virEventPollMakePollFDs:391 : Prepare n=8 w=9, f=16 e=1 d=0
>2014-02-28 05:56:45.847+0000: 476: debug : virEventPollMakePollFDs:391 : Prepare n=9 w=39, f=21 e=5 d=0
>2014-02-28 05:56:45.847+0000: 476: debug : virEventPollCalculateTimeout:332 : Calculate expiry of 2 timers
>2014-02-28 05:56:45.847+0000: 476: debug : virEventPollCalculateTimeout:340 : Got a timeout scheduled for 1393567010847
>2014-02-28 05:56:45.847+0000: 476: debug : virEventPollCalculateTimeout:353 : Schedule timeout then=1393567010847 now=1393567005847
>2014-02-28 05:56:45.847+0000: 476: debug : virEventPollCalculateTimeout:361 : Timeout at 1393567010847 due in 5000 ms
>2014-02-28 05:56:45.847+0000: 476: debug : virEventPollRunOnce:627 : EVENT_POLL_RUN: nhandles=9 timeout=5000
>2014-02-28 05:56:45.847+0000: 476: debug : virEventPollRunOnce:638 : Poll got 1 event(s)
>2014-02-28 05:56:45.847+0000: 476: debug : virEventPollDispatchTimeouts:423 : Dispatch 2
>2014-02-28 05:56:45.847+0000: 476: debug : virEventPollDispatchHandles:468 : Dispatch 9
>2014-02-28 05:56:45.847+0000: 476: debug : virEventPollDispatchHandles:482 : i=0 w=1
>2014-02-28 05:56:45.847+0000: 476: debug : virEventPollDispatchHandles:482 : i=1 w=2
>2014-02-28 05:56:45.847+0000: 476: debug : virEventPollDispatchHandles:482 : i=2 w=3
>2014-02-28 05:56:45.847+0000: 476: debug : virEventPollDispatchHandles:482 : i=3 w=4
>2014-02-28 05:56:45.847+0000: 476: debug : virEventPollDispatchHandles:482 : i=4 w=5
>2014-02-28 05:56:45.847+0000: 476: debug : virEventPollDispatchHandles:482 : i=5 w=6
>2014-02-28 05:56:45.847+0000: 476: debug : virEventPollDispatchHandles:482 : i=7 w=8
>2014-02-28 05:56:45.847+0000: 476: debug : virEventPollDispatchHandles:482 : i=8 w=9
>2014-02-28 05:56:45.847+0000: 476: debug : virEventPollDispatchHandles:482 : i=9 w=39
>2014-02-28 05:56:45.847+0000: 476: debug : virEventPollDispatchHandles:496 : EVENT_POLL_DISPATCH_HANDLE: watch=39 events=2
>2014-02-28 05:56:45.847+0000: 476: debug : virNetMessageFree:72 : msg=0x7fcda71b7900 nfds=0 cb=(nil)
>2014-02-28 05:56:45.847+0000: 476: debug : virNetServerClientCalculateHandleMode:153 : tls=(nil) hs=-1, rx=0x7fcda71b9280 tx=(nil)
>2014-02-28 05:56:45.847+0000: 476: debug : virNetServerClientCalculateHandleMode:188 : mode=1
>2014-02-28 05:56:45.847+0000: 476: debug : virEventPollUpdateHandle:147 : EVENT_POLL_UPDATE_HANDLE: watch=39 events=1
>2014-02-28 05:56:45.847+0000: 476: debug : virEventPollInterruptLocked:710 : Skip interrupt, 1 140521230579840
>2014-02-28 05:56:45.847+0000: 476: debug : virEventPollCleanupTimeouts:514 : Cleanup 2
>2014-02-28 05:56:45.847+0000: 476: debug : virEventPollCleanupHandles:562 : Cleanup 10
>2014-02-28 05:56:45.847+0000: 476: debug : virEventRunDefaultImpl:270 : running default event implementation
>2014-02-28 05:56:45.847+0000: 476: debug : virEventPollCleanupTimeouts:514 : Cleanup 2
>2014-02-28 05:56:45.847+0000: 476: debug : virEventPollCleanupHandles:562 : Cleanup 10
>2014-02-28 05:56:45.847+0000: 476: debug : virEventPollMakePollFDs:391 : Prepare n=0 w=1, f=6 e=1 d=0
>2014-02-28 05:56:45.847+0000: 476: debug : virEventPollMakePollFDs:391 : Prepare n=1 w=2, f=8 e=1 d=0
>2014-02-28 05:56:45.847+0000: 476: debug : virEventPollMakePollFDs:391 : Prepare n=2 w=3, f=11 e=1 d=0
>2014-02-28 05:56:45.847+0000: 476: debug : virEventPollMakePollFDs:391 : Prepare n=3 w=4, f=12 e=1 d=0
>2014-02-28 05:56:45.847+0000: 476: debug : virEventPollMakePollFDs:391 : Prepare n=4 w=5, f=14 e=1 d=0
>2014-02-28 05:56:45.847+0000: 476: debug : virEventPollMakePollFDs:391 : Prepare n=5 w=6, f=19 e=1 d=0
>2014-02-28 05:56:45.847+0000: 476: debug : virEventPollMakePollFDs:391 : Prepare n=6 w=7, f=13 e=0 d=0
>2014-02-28 05:56:45.847+0000: 476: debug : virEventPollMakePollFDs:391 : Prepare n=7 w=8, f=13 e=1 d=0
>2014-02-28 05:56:45.847+0000: 476: debug : virEventPollMakePollFDs:391 : Prepare n=8 w=9, f=16 e=1 d=0
>2014-02-28 05:56:45.847+0000: 476: debug : virEventPollMakePollFDs:391 : Prepare n=9 w=39, f=21 e=1 d=0
>2014-02-28 05:56:45.847+0000: 476: debug : virEventPollCalculateTimeout:332 : Calculate expiry of 2 timers
>2014-02-28 05:56:45.847+0000: 476: debug : virEventPollCalculateTimeout:340 : Got a timeout scheduled for 1393567010847
>2014-02-28 05:56:45.847+0000: 476: debug : virEventPollCalculateTimeout:353 : Schedule timeout then=1393567010847 now=1393567005847
>2014-02-28 05:56:45.847+0000: 476: debug : virEventPollCalculateTimeout:361 : Timeout at 1393567010847 due in 5000 ms
>2014-02-28 05:56:45.847+0000: 476: debug : virEventPollRunOnce:627 : EVENT_POLL_RUN: nhandles=9 timeout=5000
>2014-02-28 05:56:45.847+0000: 476: debug : virEventPollRunOnce:638 : Poll got 1 event(s)
>2014-02-28 05:56:45.848+0000: 476: debug : virEventPollDispatchTimeouts:423 : Dispatch 2
>2014-02-28 05:56:45.848+0000: 476: debug : virEventPollDispatchHandles:468 : Dispatch 9
>2014-02-28 05:56:45.848+0000: 476: debug : virEventPollDispatchHandles:482 : i=0 w=1
>2014-02-28 05:56:45.848+0000: 476: debug : virEventPollDispatchHandles:482 : i=1 w=2
>2014-02-28 05:56:45.848+0000: 476: debug : virEventPollDispatchHandles:482 : i=2 w=3
>2014-02-28 05:56:45.848+0000: 476: debug : virEventPollDispatchHandles:482 : i=3 w=4
>2014-02-28 05:56:45.848+0000: 476: debug : virEventPollDispatchHandles:482 : i=4 w=5
>2014-02-28 05:56:45.848+0000: 476: debug : virEventPollDispatchHandles:482 : i=5 w=6
>2014-02-28 05:56:45.848+0000: 476: debug : virEventPollDispatchHandles:482 : i=7 w=8
>2014-02-28 05:56:45.848+0000: 476: debug : virEventPollDispatchHandles:482 : i=8 w=9
>2014-02-28 05:56:45.848+0000: 476: debug : virEventPollDispatchHandles:482 : i=9 w=39
>2014-02-28 05:56:45.848+0000: 476: debug : virEventPollDispatchHandles:496 : EVENT_POLL_DISPATCH_HANDLE: watch=39 events=1
>2014-02-28 05:56:45.848+0000: 476: debug : virNetMessageDecodeLength:149 : Got length, now need 56 total (52 more)
>2014-02-28 05:56:45.848+0000: 476: debug : virNetServerClientCalculateHandleMode:153 : tls=(nil) hs=-1, rx=0x7fcda71b9280 tx=(nil)
>2014-02-28 05:56:45.848+0000: 476: debug : virNetServerClientCalculateHandleMode:188 : mode=1
>2014-02-28 05:56:45.848+0000: 476: debug : virEventPollUpdateHandle:147 : EVENT_POLL_UPDATE_HANDLE: watch=39 events=1
>2014-02-28 05:56:45.848+0000: 476: debug : virEventPollInterruptLocked:710 : Skip interrupt, 1 140521230579840
>2014-02-28 05:56:45.848+0000: 476: debug : virNetServerClientDispatchRead:1202 : RPC_SERVER_CLIENT_MSG_RX: client=0x7fcda71b88d0 len=56 prog=536903814 vers=1 proc=9 type=0 status=0 serial=5
>2014-02-28 05:56:45.848+0000: 476: debug : virKeepAliveCheckMessage:374 : ka=0x7fcda71b9390, client=0x7fcda71b88d0, msg=0x7fcda71b9280
>2014-02-28 05:56:45.848+0000: 476: debug : virEventPollUpdateTimeout:260 : EVENT_POLL_UPDATE_TIMEOUT: timer=58 frequency=5000
>2014-02-28 05:56:45.848+0000: 476: debug : virEventPollUpdateTimeout:278 : Set timer freq=5000 expires=1393567010848
>2014-02-28 05:56:45.848+0000: 476: debug : virEventPollInterruptLocked:710 : Skip interrupt, 1 140521230579840
>2014-02-28 05:56:45.848+0000: 476: debug : virObjectRef:293 : OBJECT_REF: obj=0x7fcda71b88d0
>2014-02-28 05:56:45.848+0000: 476: debug : virNetServerDispatchNewMessage:214 : server=0x7fcda71a8d70 client=0x7fcda71b88d0 message=0x7fcda71b9280
>2014-02-28 05:56:45.848+0000: 476: debug : virObjectRef:293 : OBJECT_REF: obj=0x7fcda71b4b30
>2014-02-28 05:56:45.848+0000: 476: debug : virNetMessageNew:44 : msg=0x7fcda71b8860 tracked=1
>2014-02-28 05:56:45.848+0000: 476: debug : virNetServerClientCalculateHandleMode:153 : tls=(nil) hs=-1, rx=0x7fcda71b8860 tx=(nil)
>2014-02-28 05:56:45.848+0000: 476: debug : virNetServerClientCalculateHandleMode:188 : mode=1
>2014-02-28 05:56:45.848+0000: 476: debug : virEventPollUpdateHandle:147 : EVENT_POLL_UPDATE_HANDLE: watch=39 events=1
>2014-02-28 05:56:45.848+0000: 476: debug : virEventPollInterruptLocked:710 : Skip interrupt, 1 140521230579840
>2014-02-28 05:56:45.848+0000: 476: debug : virEventPollCleanupTimeouts:514 : Cleanup 2
>2014-02-28 05:56:45.848+0000: 476: debug : virEventPollCleanupHandles:562 : Cleanup 10
>2014-02-28 05:56:45.848+0000: 476: debug : virEventRunDefaultImpl:270 : running default event implementation
>2014-02-28 05:56:45.848+0000: 476: debug : virEventPollCleanupTimeouts:514 : Cleanup 2
>2014-02-28 05:56:45.848+0000: 476: debug : virEventPollCleanupHandles:562 : Cleanup 10
>2014-02-28 05:56:45.848+0000: 476: debug : virEventPollMakePollFDs:391 : Prepare n=0 w=1, f=6 e=1 d=0
>2014-02-28 05:56:45.848+0000: 476: debug : virEventPollMakePollFDs:391 : Prepare n=1 w=2, f=8 e=1 d=0
>2014-02-28 05:56:45.848+0000: 476: debug : virEventPollMakePollFDs:391 : Prepare n=2 w=3, f=11 e=1 d=0
>2014-02-28 05:56:45.848+0000: 476: debug : virEventPollMakePollFDs:391 : Prepare n=3 w=4, f=12 e=1 d=0
>2014-02-28 05:56:45.848+0000: 476: debug : virEventPollMakePollFDs:391 : Prepare n=4 w=5, f=14 e=1 d=0
>2014-02-28 05:56:45.848+0000: 476: debug : virEventPollMakePollFDs:391 : Prepare n=5 w=6, f=19 e=1 d=0
>2014-02-28 05:56:45.848+0000: 476: debug : virEventPollMakePollFDs:391 : Prepare n=6 w=7, f=13 e=0 d=0
>2014-02-28 05:56:45.848+0000: 476: debug : virEventPollMakePollFDs:391 : Prepare n=7 w=8, f=13 e=1 d=0
>2014-02-28 05:56:45.848+0000: 478: debug : virNetServerHandleJob:185 : server=0x7fcda71a8d70 client=0x7fcda71b88d0 message=0x7fcda71b9280 prog=0x7fcda71b4b30
>2014-02-28 05:56:45.848+0000: 476: debug : virEventPollMakePollFDs:391 : Prepare n=8 w=9, f=16 e=1 d=0
>2014-02-28 05:56:45.848+0000: 478: debug : virNetServerProgramDispatch:285 : prog=536903814 ver=1 type=0 status=0 serial=5 proc=9
>2014-02-28 05:56:45.848+0000: 476: debug : virEventPollMakePollFDs:391 : Prepare n=9 w=39, f=21 e=1 d=0
>2014-02-28 05:56:45.848+0000: 476: debug : virEventPollCalculateTimeout:332 : Calculate expiry of 2 timers
>2014-02-28 05:56:45.848+0000: 478: debug : virObjectRef:293 : OBJECT_REF: obj=0x7fcd70000a40
>2014-02-28 05:56:45.848+0000: 476: debug : virEventPollCalculateTimeout:340 : Got a timeout scheduled for 1393567010848
>2014-02-28 05:56:45.848+0000: 476: debug : virEventPollCalculateTimeout:353 : Schedule timeout then=1393567010848 now=1393567005848
>2014-02-28 05:56:45.848+0000: 478: debug : virObjectRef:293 : OBJECT_REF: obj=0x7fcd70000a40
>2014-02-28 05:56:45.848+0000: 476: debug : virEventPollCalculateTimeout:361 : Timeout at 1393567010848 due in 5000 ms
>2014-02-28 05:56:45.848+0000: 476: debug : virEventPollRunOnce:627 : EVENT_POLL_RUN: nhandles=9 timeout=5000
>2014-02-28 05:56:45.848+0000: 478: debug : remoteDispatchDomainCreateHelper:2865 : server=0x7fcda71a8d70 client=0x7fcda71b88d0 msg=0x7fcda71b9280 rerr=0x7fcd9656fc80 args=0x7fcd84002040 ret=0x7fcd84000bf0
>2014-02-28 05:56:45.848+0000: 478: debug : virObjectNew:199 : OBJECT_NEW: obj=0x7fcd84002000 classname=virDomain
>2014-02-28 05:56:45.848+0000: 478: debug : virObjectRef:293 : OBJECT_REF: obj=0x7fcd68000de0
>2014-02-28 05:56:45.848+0000: 478: debug : virDomainCreate:9494 : dom=0x7fcd84002000, (VM: name=r7, uuid=219e27b1-f639-4cbf-80a1-9ed45b3657f2)
>2014-02-28 05:56:45.848+0000: 478: debug : virObjectRef:293 : OBJECT_REF: obj=0x7fcda71b4210
>2014-02-28 05:56:45.848+0000: 478: debug : virAccessManagerCheckDomain:231 : manager=0x7fcda71b4210(name=stack) driver=QEMU domain=0x7fcd8827e3b0 perm=4
>2014-02-28 05:56:45.848+0000: 478: debug : virAccessManagerCheckDomain:231 : manager=0x7fcda71a89e0(name=none) driver=QEMU domain=0x7fcd8827e3b0 perm=4
>2014-02-28 05:56:45.848+0000: 478: debug : virObjectUnref:256 : OBJECT_UNREF: obj=0x7fcda71b4210
>2014-02-28 05:56:45.848+0000: 478: debug : virObjectRef:293 : OBJECT_REF: obj=0x7fcd881b5a20
>2014-02-28 05:56:45.848+0000: 478: debug : virObjectRef:293 : OBJECT_REF: obj=0x7fcd88216080
>2014-02-28 05:56:45.848+0000: 478: debug : qemuDomainObjBeginJobInternal:1038 : Starting job: modify (async=none)
>2014-02-28 05:56:45.848+0000: 478: debug : virObjectUnref:256 : OBJECT_UNREF: obj=0x7fcd881b5a20
>2014-02-28 05:56:45.848+0000: 478: debug : virObjectRef:293 : OBJECT_REF: obj=0x7fcd881b5a20
>2014-02-28 05:56:45.848+0000: 478: debug : virObjectUnref:256 : OBJECT_UNREF: obj=0x7fcd881b5a20
>2014-02-28 05:56:45.848+0000: 478: debug : virObjectRef:293 : OBJECT_REF: obj=0x7fcd881b5a20
>2014-02-28 05:56:45.848+0000: 478: debug : qemuProcessStart:3605 : Beginning VM startup process
>2014-02-28 05:56:45.848+0000: 478: debug : virObjectRef:293 : OBJECT_REF: obj=0x7fcd88215d10
>2014-02-28 05:56:45.848+0000: 478: debug : qemuProcessStart:3621 : Setting current domain def as transient
>2014-02-28 05:56:45.848+0000: 478: debug : virObjectRef:293 : OBJECT_REF: obj=0x7fcd881b5a20
>2014-02-28 05:56:45.848+0000: 478: debug : virObjectUnref:256 : OBJECT_UNREF: obj=0x7fcd881b5a20
>2014-02-28 05:56:45.849+0000: 478: debug : virObjectRef:293 : OBJECT_REF: obj=0x7fcd881b5a20
>2014-02-28 05:56:45.849+0000: 478: debug : virObjectUnref:256 : OBJECT_UNREF: obj=0x7fcd881b5a20
>2014-02-28 05:56:45.849+0000: 478: debug : virNetServerAddShutdownInhibition:798 : srv=0x7fcda71a8d70 inhibitions=1
>2014-02-28 05:56:45.849+0000: 478: debug : qemuProcessStart:3649 : Determining emulator version
>2014-02-28 05:56:45.849+0000: 478: debug : virQEMUCapsCacheLookup:2816 : Returning caps 0x7fcd882769d0 for /usr/libexec/qemu-kvm
>2014-02-28 05:56:45.849+0000: 478: debug : virObjectRef:293 : OBJECT_REF: obj=0x7fcd882769d0
>2014-02-28 05:56:45.849+0000: 478: debug : virObjectNew:199 : OBJECT_NEW: obj=0x7fcd8400af70 classname=virQEMUCaps
>2014-02-28 05:56:45.849+0000: 478: debug : virObjectUnref:256 : OBJECT_UNREF: obj=0x7fcd882769d0
>2014-02-28 05:56:45.849+0000: 478: debug : qemuProcessStart:3659 : Preparing network devices
>2014-02-28 05:56:45.849+0000: 478: debug : networkAllocateActualDevice:4188 : Using network default, 1 connections
>2014-02-28 05:56:45.849+0000: 478: debug : qemuProcessStart:3664 : Preparing host devices
>2014-02-28 05:56:45.849+0000: 478: debug : qemuProcessStart:3669 : Preparing chr devices
>2014-02-28 05:56:45.849+0000: 478: debug : qemuProcessStart:3678 : Generating domain security label (if required)
>2014-02-28 05:56:45.849+0000: 478: debug : virSecuritySELinuxGenSecurityLabel:593 : label=QEMU
>2014-02-28 05:56:45.849+0000: 478: debug : virSecuritySELinuxGenSecurityLabel:615 : type=2
>2014-02-28 05:56:45.849+0000: 478: debug : virSecuritySELinuxMCSFind:135 : Using sensitivity level 's0' cat min 0 max 1023 range 1024
>2014-02-28 05:56:45.849+0000: 478: debug : virSecuritySELinuxMCSFind:141 : Try cat s0:c817,c309
>2014-02-28 05:56:45.849+0000: 478: debug : virSecuritySELinuxGenNewContext:335 : basecontext=system_u:system_r:svirt_t:s0 mcs=s0:c309,c817 isObjectContext=0
>2014-02-28 05:56:45.849+0000: 478: debug : virSecuritySELinuxGenNewContext:348 : process=system_u:system_r:virtd_t:s0-s0:c0.c1023
>2014-02-28 05:56:45.849+0000: 478: debug : virSecuritySELinuxGenNewContext:387 : Generated context 'system_u:system_r:svirt_t:s0:c309,c817'
>2014-02-28 05:56:45.849+0000: 478: debug : virSecuritySELinuxGenNewContext:335 : basecontext=system_u:object_r:svirt_image_t:s0 mcs=s0:c309,c817 isObjectContext=1
>2014-02-28 05:56:45.849+0000: 478: debug : virSecuritySELinuxGenNewContext:348 : process=system_u:system_r:virtd_t:s0-s0:c0.c1023
>2014-02-28 05:56:45.849+0000: 478: debug : virSecuritySELinuxGenNewContext:387 : Generated context 'system_u:object_r:svirt_image_t:s0:c309,c817'
>2014-02-28 05:56:45.849+0000: 478: debug : virSecuritySELinuxGenSecurityLabel:726 : model=selinux label=system_u:system_r:svirt_t:s0:c309,c817 imagelabel=system_u:object_r:svirt_image_t:s0:c309,c817 baselabel=(null)
>2014-02-28 05:56:45.849+0000: 478: debug : qemuProcessStart:3696 : Ensuring no historical cgroup is lying around
>2014-02-28 05:56:45.849+0000: 478: debug : virFileClose:90 : Closed fd 22
>2014-02-28 05:56:45.849+0000: 478: debug : virFileMakePathHelper:2201 : path=/var/log/libvirt/qemu mode=0777
>2014-02-28 05:56:45.849+0000: 478: debug : qemuProcessStart:3733 : Creating domain log file
>2014-02-28 05:56:45.849+0000: 478: debug : virObjectRef:293 : OBJECT_REF: obj=0x7fcd881b5a20
>2014-02-28 05:56:45.849+0000: 478: debug : virObjectUnref:256 : OBJECT_UNREF: obj=0x7fcd881b5a20
>2014-02-28 05:56:45.849+0000: 478: debug : qemuProcessStart:3738 : Checking for KVM availability
>2014-02-28 05:56:45.849+0000: 478: debug : qemuDomainCheckDiskPresence:2158 : Checking for disk presence
>2014-02-28 05:56:45.849+0000: 478: debug : virObjectRef:293 : OBJECT_REF: obj=0x7fcd881b5a20
>2014-02-28 05:56:45.849+0000: 478: debug : virStorageFileGetMetadata:1109 : path=/var/lib/libvirt/images/r7.img format=1 uid=107 gid=107 probe=0
>2014-02-28 05:56:45.849+0000: 478: debug : virStorageFileGetMetadataRecurse:1041 : path=/var/lib/libvirt/images/r7.img format=1 uid=107 gid=107 probe=0
>2014-02-28 05:56:45.849+0000: 478: debug : virStorageFileGetMetadataInternal:765 : path=/var/lib/libvirt/images/r7.img, buf=0x7fcd8400dd00, len=33280, directory=(null), format=1
>2014-02-28 05:56:45.849+0000: 478: debug : virFileClose:90 : Closed fd 23
>2014-02-28 05:56:45.849+0000: 478: debug : virObjectUnref:256 : OBJECT_UNREF: obj=0x7fcd881b5a20
>2014-02-28 05:56:45.849+0000: 478: debug : qemuProcessStart:3790 : Preparing monitor state
>2014-02-28 05:56:45.849+0000: 478: debug : qemuProcessStart:3822 : Assigning domain PCI addresses
>2014-02-28 05:56:45.849+0000: 478: debug : qemuDomainPCIAddressReserveAddr:2052 : Reserving PCI slot 0000:00:03.0 (multifunction='off')
>2014-02-28 05:56:45.849+0000: 478: debug : qemuDomainPCIAddressReserveAddr:2052 : Reserving PCI slot 0000:00:04.0 (multifunction='off')
>2014-02-28 05:56:45.849+0000: 478: debug : qemuDomainPCIAddressReserveAddr:2052 : Reserving PCI slot 0000:00:02.0 (multifunction='off')
>2014-02-28 05:56:45.849+0000: 478: debug : qemuDomainPCIAddressReserveAddr:2052 : Reserving PCI slot 0000:00:05.0 (multifunction='off')
>2014-02-28 05:56:45.849+0000: 478: debug : qemuDomainPCIAddressReserveAddr:2052 : Reserving PCI slot 0000:00:06.0 (multifunction='off')
>2014-02-28 05:56:45.849+0000: 478: debug : qemuDomainPCIAddressReserveAddr:2052 : Reserving PCI slot 0000:00:01.0 (multifunction='off')
>2014-02-28 05:56:45.849+0000: 478: debug : qemuDomainPCIAddressGetNextSlot:2208 : PCI slot 0000:00:01 already in use
>2014-02-28 05:56:45.849+0000: 478: debug : qemuDomainPCIAddressGetNextSlot:2208 : PCI slot 0000:00:02 already in use
>2014-02-28 05:56:45.849+0000: 478: debug : qemuDomainPCIAddressGetNextSlot:2208 : PCI slot 0000:00:03 already in use
>2014-02-28 05:56:45.849+0000: 478: debug : qemuDomainPCIAddressGetNextSlot:2208 : PCI slot 0000:00:04 already in use
>2014-02-28 05:56:45.849+0000: 478: debug : qemuDomainPCIAddressGetNextSlot:2208 : PCI slot 0000:00:05 already in use
>2014-02-28 05:56:45.849+0000: 478: debug : qemuDomainPCIAddressGetNextSlot:2208 : PCI slot 0000:00:06 already in use
>2014-02-28 05:56:45.849+0000: 478: debug : qemuDomainPCIAddressGetNextSlot:2250 : Found free PCI slot 0000:00:07
>2014-02-28 05:56:45.849+0000: 478: debug : qemuDomainPCIAddressReserveAddr:2052 : Reserving PCI slot 0000:00:07.0 (multifunction='off')
>2014-02-28 05:56:45.849+0000: 478: debug : qemuDomainPCIAddressReserveAddr:2052 : Reserving PCI slot 0000:00:03.0 (multifunction='off')
>2014-02-28 05:56:45.849+0000: 478: debug : qemuDomainPCIAddressReserveAddr:2052 : Reserving PCI slot 0000:00:04.0 (multifunction='off')
>2014-02-28 05:56:45.849+0000: 478: debug : qemuDomainPCIAddressReserveAddr:2052 : Reserving PCI slot 0000:00:02.0 (multifunction='off')
>2014-02-28 05:56:45.849+0000: 478: debug : qemuDomainPCIAddressReserveAddr:2052 : Reserving PCI slot 0000:00:05.0 (multifunction='off')
>2014-02-28 05:56:45.849+0000: 478: debug : qemuDomainPCIAddressReserveAddr:2052 : Reserving PCI slot 0000:00:06.0 (multifunction='off')
>2014-02-28 05:56:45.849+0000: 478: debug : qemuDomainPCIAddressReserveAddr:2052 : Reserving PCI slot 0000:00:01.0 (multifunction='off')
>2014-02-28 05:56:45.849+0000: 478: debug : qemuProcessStart:3827 : Building emulator command line
>2014-02-28 05:56:45.849+0000: 478: debug : virArchFromHost:174 : Mapped x86_64 to 28 (x86_64)
>2014-02-28 05:56:45.849+0000: 478: debug : virObjectRef:293 : OBJECT_REF: obj=0x7fcd881b5a20
>2014-02-28 05:56:45.849+0000: 478: debug : qemuBuildCommandLine:7573 : conn=0x7fcd68000de0 driver=0x7fcd881b2350 def=0x7fcd8827e3b0 mon=0x7fcd8400a7c0 json=1 qemuCaps=0x7fcd8400af70 migrateFrom=(null) migrateFD=-1 snapshot=(nil) vmop=0
>2014-02-28 05:56:45.849+0000: 478: debug : virObjectRef:293 : OBJECT_REF: obj=0x7fcd88215d10
>2014-02-28 05:56:45.849+0000: 478: debug : cpuDataFree:211 : data=(nil)
>2014-02-28 05:56:45.849+0000: 478: debug : virObjectUnref:256 : OBJECT_UNREF: obj=0x7fcd88215d10
>2014-02-28 05:56:45.849+0000: 478: debug : virObjectRef:293 : OBJECT_REF: obj=0x7fcd881b5a20
>2014-02-28 05:56:45.849+0000: 478: debug : virNetworkLookupByName:11588 : conn=0x7fcd68000de0, name=default
>2014-02-28 05:56:45.849+0000: 478: debug : virObjectRef:293 : OBJECT_REF: obj=0x7fcda71b4210
>2014-02-28 05:56:45.849+0000: 478: debug : virAccessManagerCheckNetwork:261 : manager=0x7fcda71b4210(name=stack) driver=QEMU network=0x7fcd88013c10 perm=0
>2014-02-28 05:56:45.849+0000: 478: debug : virAccessManagerCheckNetwork:261 : manager=0x7fcda71a89e0(name=none) driver=QEMU network=0x7fcd88013c10 perm=0
>2014-02-28 05:56:45.849+0000: 478: debug : virObjectUnref:256 : OBJECT_UNREF: obj=0x7fcda71b4210
>2014-02-28 05:56:45.849+0000: 478: debug : virObjectNew:199 : OBJECT_NEW: obj=0x7fcd84006280 classname=virNetwork
>2014-02-28 05:56:45.849+0000: 478: debug : virObjectRef:293 : OBJECT_REF: obj=0x7fcd68000de0
>2014-02-28 05:56:45.849+0000: 478: debug : virNetworkIsActive:17791 : net=0x7fcd84006280
>2014-02-28 05:56:45.849+0000: 478: debug : virObjectRef:293 : OBJECT_REF: obj=0x7fcda71b4210
>2014-02-28 05:56:45.849+0000: 478: debug : virAccessManagerCheckNetwork:261 : manager=0x7fcda71b4210(name=stack) driver=QEMU network=0x7fcd88013c10 perm=1
>2014-02-28 05:56:45.849+0000: 478: debug : virAccessManagerCheckNetwork:261 : manager=0x7fcda71a89e0(name=none) driver=QEMU network=0x7fcd88013c10 perm=1
>2014-02-28 05:56:45.849+0000: 478: debug : virObjectUnref:256 : OBJECT_UNREF: obj=0x7fcda71b4210
>2014-02-28 05:56:45.849+0000: 478: debug : virNetworkGetBridgeName:12180 : network=0x7fcd84006280
>2014-02-28 05:56:45.849+0000: 478: debug : virObjectRef:293 : OBJECT_REF: obj=0x7fcda71b4210
>2014-02-28 05:56:45.849+0000: 478: debug : virAccessManagerCheckNetwork:261 : manager=0x7fcda71b4210(name=stack) driver=QEMU network=0x7fcd88013c10 perm=1
>2014-02-28 05:56:45.849+0000: 478: debug : virAccessManagerCheckNetwork:261 : manager=0x7fcda71a89e0(name=none) driver=QEMU network=0x7fcd88013c10 perm=1
>2014-02-28 05:56:45.849+0000: 478: debug : virObjectUnref:256 : OBJECT_UNREF: obj=0x7fcda71b4210
>2014-02-28 05:56:45.849+0000: 478: debug : virNetworkFree:11984 : network=0x7fcd84006280
>2014-02-28 05:56:45.849+0000: 478: debug : virObjectUnref:256 : OBJECT_UNREF: obj=0x7fcd84006280
>2014-02-28 05:56:45.849+0000: 478: debug : virObjectUnref:258 : OBJECT_DISPOSE: obj=0x7fcd84006280
>2014-02-28 05:56:45.849+0000: 478: debug : virNetworkDispose:332 : release network 0x7fcd84006280 default 3de9ed45-bedd-4af8-a746-4b7c233907d9
>2014-02-28 05:56:45.849+0000: 478: debug : virObjectUnref:256 : OBJECT_UNREF: obj=0x7fcd68000de0
>2014-02-28 05:56:45.850+0000: 476: debug : virEventPollRunOnce:638 : Poll got 1 event(s)
>2014-02-28 05:56:45.850+0000: 476: debug : virEventPollDispatchTimeouts:423 : Dispatch 2
>2014-02-28 05:56:45.850+0000: 476: debug : virEventPollDispatchHandles:468 : Dispatch 9
>2014-02-28 05:56:45.850+0000: 476: debug : virEventPollDispatchHandles:482 : i=0 w=1
>2014-02-28 05:56:45.850+0000: 476: debug : virEventPollDispatchHandles:482 : i=1 w=2
>2014-02-28 05:56:45.850+0000: 476: debug : virEventPollDispatchHandles:482 : i=2 w=3
>2014-02-28 05:56:45.850+0000: 476: debug : virEventPollDispatchHandles:482 : i=3 w=4
>2014-02-28 05:56:45.850+0000: 476: debug : virEventPollDispatchHandles:482 : i=4 w=5
>2014-02-28 05:56:45.850+0000: 476: debug : virEventPollDispatchHandles:482 : i=5 w=6
>2014-02-28 05:56:45.850+0000: 476: debug : virEventPollDispatchHandles:496 : EVENT_POLL_DISPATCH_HANDLE: watch=6 events=1
>2014-02-28 05:56:45.850+0000: 476: debug : virNetlinkEventCallback:347 : dispatching to max 0 clients, called from event watch 6
>2014-02-28 05:56:45.850+0000: 476: debug : virNetlinkEventCallback:360 : event not handled.
>2014-02-28 05:56:45.850+0000: 476: debug : virEventPollDispatchHandles:482 : i=7 w=8
>2014-02-28 05:56:45.850+0000: 476: debug : virEventPollDispatchHandles:482 : i=8 w=9
>2014-02-28 05:56:45.850+0000: 476: debug : virEventPollDispatchHandles:482 : i=9 w=39
>2014-02-28 05:56:45.850+0000: 476: debug : virEventPollCleanupTimeouts:514 : Cleanup 2
>2014-02-28 05:56:45.850+0000: 476: debug : virEventPollCleanupHandles:562 : Cleanup 10
>2014-02-28 05:56:45.850+0000: 476: debug : virEventRunDefaultImpl:270 : running default event implementation
>2014-02-28 05:56:45.850+0000: 476: debug : virEventPollCleanupTimeouts:514 : Cleanup 2
>2014-02-28 05:56:45.850+0000: 476: debug : virEventPollCleanupHandles:562 : Cleanup 10
>2014-02-28 05:56:45.850+0000: 476: debug : virEventPollMakePollFDs:391 : Prepare n=0 w=1, f=6 e=1 d=0
>2014-02-28 05:56:45.850+0000: 476: debug : virEventPollMakePollFDs:391 : Prepare n=1 w=2, f=8 e=1 d=0
>2014-02-28 05:56:45.850+0000: 476: debug : virEventPollMakePollFDs:391 : Prepare n=2 w=3, f=11 e=1 d=0
>2014-02-28 05:56:45.850+0000: 476: debug : virEventPollMakePollFDs:391 : Prepare n=3 w=4, f=12 e=1 d=0
>2014-02-28 05:56:45.850+0000: 476: debug : virEventPollMakePollFDs:391 : Prepare n=4 w=5, f=14 e=1 d=0
>2014-02-28 05:56:45.850+0000: 476: debug : virEventPollMakePollFDs:391 : Prepare n=5 w=6, f=19 e=1 d=0
>2014-02-28 05:56:45.850+0000: 476: debug : virEventPollMakePollFDs:391 : Prepare n=6 w=7, f=13 e=0 d=0
>2014-02-28 05:56:45.850+0000: 476: debug : virEventPollMakePollFDs:391 : Prepare n=7 w=8, f=13 e=1 d=0
>2014-02-28 05:56:45.850+0000: 476: debug : virEventPollMakePollFDs:391 : Prepare n=8 w=9, f=16 e=1 d=0
>2014-02-28 05:56:45.850+0000: 476: debug : virEventPollMakePollFDs:391 : Prepare n=9 w=39, f=21 e=1 d=0
>2014-02-28 05:56:45.850+0000: 476: debug : virEventPollCalculateTimeout:332 : Calculate expiry of 2 timers
>2014-02-28 05:56:45.850+0000: 476: debug : virEventPollCalculateTimeout:340 : Got a timeout scheduled for 1393567010848
>2014-02-28 05:56:45.850+0000: 476: debug : virEventPollCalculateTimeout:353 : Schedule timeout then=1393567010848 now=1393567005850
>2014-02-28 05:56:45.850+0000: 476: debug : virEventPollCalculateTimeout:361 : Timeout at 1393567010848 due in 4998 ms
>2014-02-28 05:56:45.850+0000: 476: debug : virEventPollRunOnce:627 : EVENT_POLL_RUN: nhandles=9 timeout=4998
>2014-02-28 05:56:45.850+0000: 476: debug : virEventPollRunOnce:638 : Poll got 1 event(s)
>2014-02-28 05:56:45.850+0000: 476: debug : virEventPollDispatchTimeouts:423 : Dispatch 2
>2014-02-28 05:56:45.850+0000: 476: debug : virEventPollDispatchHandles:468 : Dispatch 9
>2014-02-28 05:56:45.850+0000: 476: debug : virEventPollDispatchHandles:482 : i=0 w=1
>2014-02-28 05:56:45.850+0000: 476: debug : virEventPollDispatchHandles:482 : i=1 w=2
>2014-02-28 05:56:45.850+0000: 476: debug : virEventPollDispatchHandles:482 : i=2 w=3
>2014-02-28 05:56:45.850+0000: 476: debug : virEventPollDispatchHandles:482 : i=3 w=4
>2014-02-28 05:56:45.850+0000: 476: debug : virEventPollDispatchHandles:482 : i=4 w=5
>2014-02-28 05:56:45.850+0000: 476: debug : virEventPollDispatchHandles:482 : i=5 w=6
>2014-02-28 05:56:45.850+0000: 476: debug : virEventPollDispatchHandles:496 : EVENT_POLL_DISPATCH_HANDLE: watch=6 events=1
>2014-02-28 05:56:45.850+0000: 476: debug : virNetlinkEventCallback:347 : dispatching to max 0 clients, called from event watch 6
>2014-02-28 05:56:45.850+0000: 476: debug : virNetlinkEventCallback:360 : event not handled.
>2014-02-28 05:56:45.850+0000: 476: debug : virEventPollDispatchHandles:482 : i=7 w=8
>2014-02-28 05:56:45.850+0000: 476: debug : virEventPollDispatchHandles:482 : i=8 w=9
>2014-02-28 05:56:45.850+0000: 476: debug : virEventPollDispatchHandles:482 : i=9 w=39
>2014-02-28 05:56:45.850+0000: 476: debug : virEventPollCleanupTimeouts:514 : Cleanup 2
>2014-02-28 05:56:45.850+0000: 476: debug : virEventPollCleanupHandles:562 : Cleanup 10
>2014-02-28 05:56:45.850+0000: 476: debug : virEventRunDefaultImpl:270 : running default event implementation
>2014-02-28 05:56:45.850+0000: 476: debug : virEventPollCleanupTimeouts:514 : Cleanup 2
>2014-02-28 05:56:45.850+0000: 476: debug : virEventPollCleanupHandles:562 : Cleanup 10
>2014-02-28 05:56:45.850+0000: 476: debug : virEventPollMakePollFDs:391 : Prepare n=0 w=1, f=6 e=1 d=0
>2014-02-28 05:56:45.850+0000: 476: debug : virEventPollMakePollFDs:391 : Prepare n=1 w=2, f=8 e=1 d=0
>2014-02-28 05:56:45.850+0000: 476: debug : virEventPollMakePollFDs:391 : Prepare n=2 w=3, f=11 e=1 d=0
>2014-02-28 05:56:45.850+0000: 476: debug : virEventPollMakePollFDs:391 : Prepare n=3 w=4, f=12 e=1 d=0
>2014-02-28 05:56:45.850+0000: 476: debug : virEventPollMakePollFDs:391 : Prepare n=4 w=5, f=14 e=1 d=0
>2014-02-28 05:56:45.850+0000: 476: debug : virEventPollMakePollFDs:391 : Prepare n=5 w=6, f=19 e=1 d=0
>2014-02-28 05:56:45.850+0000: 476: debug : virEventPollMakePollFDs:391 : Prepare n=6 w=7, f=13 e=0 d=0
>2014-02-28 05:56:45.850+0000: 476: debug : virEventPollMakePollFDs:391 : Prepare n=7 w=8, f=13 e=1 d=0
>2014-02-28 05:56:45.850+0000: 476: debug : virEventPollMakePollFDs:391 : Prepare n=8 w=9, f=16 e=1 d=0
>2014-02-28 05:56:45.850+0000: 476: debug : virEventPollMakePollFDs:391 : Prepare n=9 w=39, f=21 e=1 d=0
>2014-02-28 05:56:45.850+0000: 476: debug : virEventPollCalculateTimeout:332 : Calculate expiry of 2 timers
>2014-02-28 05:56:45.850+0000: 476: debug : virEventPollCalculateTimeout:340 : Got a timeout scheduled for 1393567010848
>2014-02-28 05:56:45.850+0000: 476: debug : virEventPollCalculateTimeout:353 : Schedule timeout then=1393567010848 now=1393567005850
>2014-02-28 05:56:45.850+0000: 476: debug : virEventPollCalculateTimeout:361 : Timeout at 1393567010848 due in 4998 ms
>2014-02-28 05:56:45.850+0000: 476: debug : virEventPollRunOnce:627 : EVENT_POLL_RUN: nhandles=9 timeout=4998
>2014-02-28 05:56:45.850+0000: 476: debug : virEventPollRunOnce:638 : Poll got 1 event(s)
>2014-02-28 05:56:45.850+0000: 476: debug : virEventPollDispatchTimeouts:423 : Dispatch 2
>2014-02-28 05:56:45.850+0000: 476: debug : virEventPollDispatchHandles:468 : Dispatch 9
>2014-02-28 05:56:45.850+0000: 476: debug : virEventPollDispatchHandles:482 : i=0 w=1
>2014-02-28 05:56:45.850+0000: 476: debug : virEventPollDispatchHandles:482 : i=1 w=2
>2014-02-28 05:56:45.850+0000: 476: debug : virEventPollDispatchHandles:482 : i=2 w=3
>2014-02-28 05:56:45.850+0000: 476: debug : virEventPollDispatchHandles:482 : i=3 w=4
>2014-02-28 05:56:45.850+0000: 476: debug : virEventPollDispatchHandles:482 : i=4 w=5
>2014-02-28 05:56:45.850+0000: 476: debug : virEventPollDispatchHandles:482 : i=5 w=6
>2014-02-28 05:56:45.850+0000: 476: debug : virEventPollDispatchHandles:496 : EVENT_POLL_DISPATCH_HANDLE: watch=6 events=1
>2014-02-28 05:56:45.850+0000: 476: debug : virNetlinkEventCallback:347 : dispatching to max 0 clients, called from event watch 6
>2014-02-28 05:56:45.850+0000: 476: debug : virNetlinkEventCallback:360 : event not handled.
>2014-02-28 05:56:45.850+0000: 476: debug : virEventPollDispatchHandles:482 : i=7 w=8
>2014-02-28 05:56:45.850+0000: 476: debug : virEventPollDispatchHandles:482 : i=8 w=9
>2014-02-28 05:56:45.850+0000: 476: debug : virEventPollDispatchHandles:482 : i=9 w=39
>2014-02-28 05:56:45.850+0000: 476: debug : virEventPollCleanupTimeouts:514 : Cleanup 2
>2014-02-28 05:56:45.850+0000: 476: debug : virEventPollCleanupHandles:562 : Cleanup 10
>2014-02-28 05:56:45.850+0000: 476: debug : virEventRunDefaultImpl:270 : running default event implementation
>2014-02-28 05:56:45.850+0000: 476: debug : virEventPollCleanupTimeouts:514 : Cleanup 2
>2014-02-28 05:56:45.850+0000: 476: debug : virEventPollCleanupHandles:562 : Cleanup 10
>2014-02-28 05:56:45.850+0000: 476: debug : virEventPollMakePollFDs:391 : Prepare n=0 w=1, f=6 e=1 d=0
>2014-02-28 05:56:45.850+0000: 476: debug : virEventPollMakePollFDs:391 : Prepare n=1 w=2, f=8 e=1 d=0
>2014-02-28 05:56:45.850+0000: 476: debug : virEventPollMakePollFDs:391 : Prepare n=2 w=3, f=11 e=1 d=0
>2014-02-28 05:56:45.850+0000: 476: debug : virEventPollMakePollFDs:391 : Prepare n=3 w=4, f=12 e=1 d=0
>2014-02-28 05:56:45.850+0000: 476: debug : virEventPollMakePollFDs:391 : Prepare n=4 w=5, f=14 e=1 d=0
>2014-02-28 05:56:45.850+0000: 476: debug : virEventPollMakePollFDs:391 : Prepare n=5 w=6, f=19 e=1 d=0
>2014-02-28 05:56:45.850+0000: 476: debug : virEventPollMakePollFDs:391 : Prepare n=6 w=7, f=13 e=0 d=0
>2014-02-28 05:56:45.850+0000: 476: debug : virEventPollMakePollFDs:391 : Prepare n=7 w=8, f=13 e=1 d=0
>2014-02-28 05:56:45.850+0000: 476: debug : virEventPollMakePollFDs:391 : Prepare n=8 w=9, f=16 e=1 d=0
>2014-02-28 05:56:45.850+0000: 476: debug : virEventPollMakePollFDs:391 : Prepare n=9 w=39, f=21 e=1 d=0
>2014-02-28 05:56:45.850+0000: 476: debug : virEventPollCalculateTimeout:332 : Calculate expiry of 2 timers
>2014-02-28 05:56:45.850+0000: 476: debug : virEventPollCalculateTimeout:340 : Got a timeout scheduled for 1393567010848
>2014-02-28 05:56:45.850+0000: 476: debug : virEventPollCalculateTimeout:353 : Schedule timeout then=1393567010848 now=1393567005850
>2014-02-28 05:56:45.850+0000: 476: debug : virEventPollCalculateTimeout:361 : Timeout at 1393567010848 due in 4998 ms
>2014-02-28 05:56:45.850+0000: 476: debug : virEventPollRunOnce:627 : EVENT_POLL_RUN: nhandles=9 timeout=4998
>2014-02-28 05:56:45.852+0000: 476: debug : virEventPollRunOnce:638 : Poll got 1 event(s)
>2014-02-28 05:56:45.852+0000: 476: debug : virEventPollDispatchTimeouts:423 : Dispatch 2
>2014-02-28 05:56:45.852+0000: 476: debug : virEventPollDispatchHandles:468 : Dispatch 9
>2014-02-28 05:56:45.852+0000: 476: debug : virEventPollDispatchHandles:482 : i=0 w=1
>2014-02-28 05:56:45.852+0000: 476: debug : virEventPollDispatchHandles:482 : i=1 w=2
>2014-02-28 05:56:45.852+0000: 476: debug : virEventPollDispatchHandles:482 : i=2 w=3
>2014-02-28 05:56:45.852+0000: 476: debug : virEventPollDispatchHandles:482 : i=3 w=4
>2014-02-28 05:56:45.852+0000: 476: debug : virEventPollDispatchHandles:482 : i=4 w=5
>2014-02-28 05:56:45.852+0000: 476: debug : virEventPollDispatchHandles:482 : i=5 w=6
>2014-02-28 05:56:45.852+0000: 476: debug : virEventPollDispatchHandles:482 : i=7 w=8
>2014-02-28 05:56:45.852+0000: 476: debug : virEventPollDispatchHandles:482 : i=8 w=9
>2014-02-28 05:56:45.852+0000: 476: debug : virEventPollDispatchHandles:496 : EVENT_POLL_DISPATCH_HANDLE: watch=9 events=1
>2014-02-28 05:56:45.852+0000: 476: debug : udevEventHandleCallback:1523 : udev action: 'add'
>2014-02-28 05:56:45.852+0000: 476: debug : udevGetDeviceProperty:121 : udev reports device 'vnet0' does not have property 'DRIVER'
>2014-02-28 05:56:45.852+0000: 476: debug : udevGetDeviceProperty:139 : Found property key 'SUBSYSTEM' value 'net' for device with sysname 'vnet0'
>2014-02-28 05:56:45.852+0000: 476: debug : udevGetDeviceProperty:139 : Found property key 'INTERFACE' value 'vnet0' for device with sysname 'vnet0'
>2014-02-28 05:56:45.852+0000: 476: debug : udevGetDeviceSysfsAttr:226 : Found sysfs attribute 'address' value 'fe:54:00:7f:44:cb' for device with sysname 'vnet0'
>2014-02-28 05:56:45.852+0000: 476: debug : udevGetDeviceSysfsAttr:226 : Found sysfs attribute 'addr_len' value '6' for device with sysname 'vnet0'
>2014-02-28 05:56:45.852+0000: 476: debug : udevStrToLong_ui:86 : Converted '6' to unsigned int 6
>2014-02-28 05:56:45.852+0000: 476: debug : virEventPollDispatchHandles:482 : i=9 w=39
>2014-02-28 05:56:45.852+0000: 476: debug : virEventPollCleanupTimeouts:514 : Cleanup 2
>2014-02-28 05:56:45.852+0000: 476: debug : virEventPollCleanupHandles:562 : Cleanup 10
>2014-02-28 05:56:45.852+0000: 476: debug : virEventRunDefaultImpl:270 : running default event implementation
>2014-02-28 05:56:45.852+0000: 476: debug : virEventPollCleanupTimeouts:514 : Cleanup 2
>2014-02-28 05:56:45.852+0000: 476: debug : virEventPollCleanupHandles:562 : Cleanup 10
>2014-02-28 05:56:45.852+0000: 476: debug : virEventPollMakePollFDs:391 : Prepare n=0 w=1, f=6 e=1 d=0
>2014-02-28 05:56:45.852+0000: 476: debug : virEventPollMakePollFDs:391 : Prepare n=1 w=2, f=8 e=1 d=0
>2014-02-28 05:56:45.852+0000: 476: debug : virEventPollMakePollFDs:391 : Prepare n=2 w=3, f=11 e=1 d=0
>2014-02-28 05:56:45.852+0000: 476: debug : virEventPollMakePollFDs:391 : Prepare n=3 w=4, f=12 e=1 d=0
>2014-02-28 05:56:45.852+0000: 476: debug : virEventPollMakePollFDs:391 : Prepare n=4 w=5, f=14 e=1 d=0
>2014-02-28 05:56:45.852+0000: 476: debug : virEventPollMakePollFDs:391 : Prepare n=5 w=6, f=19 e=1 d=0
>2014-02-28 05:56:45.852+0000: 476: debug : virEventPollMakePollFDs:391 : Prepare n=6 w=7, f=13 e=0 d=0
>2014-02-28 05:56:45.852+0000: 476: debug : virEventPollMakePollFDs:391 : Prepare n=7 w=8, f=13 e=1 d=0
>2014-02-28 05:56:45.852+0000: 476: debug : virEventPollMakePollFDs:391 : Prepare n=8 w=9, f=16 e=1 d=0
>2014-02-28 05:56:45.852+0000: 476: debug : virEventPollMakePollFDs:391 : Prepare n=9 w=39, f=21 e=1 d=0
>2014-02-28 05:56:45.852+0000: 476: debug : virEventPollCalculateTimeout:332 : Calculate expiry of 2 timers
>2014-02-28 05:56:45.852+0000: 476: debug : virEventPollCalculateTimeout:340 : Got a timeout scheduled for 1393567010848
>2014-02-28 05:56:45.852+0000: 476: debug : virEventPollCalculateTimeout:353 : Schedule timeout then=1393567010848 now=1393567005852
>2014-02-28 05:56:45.852+0000: 476: debug : virEventPollCalculateTimeout:361 : Timeout at 1393567010848 due in 4996 ms
>2014-02-28 05:56:45.852+0000: 476: debug : virEventPollRunOnce:627 : EVENT_POLL_RUN: nhandles=9 timeout=4996
>2014-02-28 05:56:45.852+0000: 476: debug : virEventPollRunOnce:638 : Poll got 1 event(s)
>2014-02-28 05:56:45.852+0000: 476: debug : virEventPollDispatchTimeouts:423 : Dispatch 2
>2014-02-28 05:56:45.852+0000: 476: debug : virEventPollDispatchHandles:468 : Dispatch 9
>2014-02-28 05:56:45.852+0000: 476: debug : virEventPollDispatchHandles:482 : i=0 w=1
>2014-02-28 05:56:45.852+0000: 476: debug : virEventPollDispatchHandles:482 : i=1 w=2
>2014-02-28 05:56:45.852+0000: 476: debug : virEventPollDispatchHandles:482 : i=2 w=3
>2014-02-28 05:56:45.852+0000: 476: debug : virEventPollDispatchHandles:482 : i=3 w=4
>2014-02-28 05:56:45.852+0000: 476: debug : virEventPollDispatchHandles:482 : i=4 w=5
>2014-02-28 05:56:45.852+0000: 476: debug : virEventPollDispatchHandles:482 : i=5 w=6
>2014-02-28 05:56:45.852+0000: 476: debug : virEventPollDispatchHandles:482 : i=7 w=8
>2014-02-28 05:56:45.852+0000: 476: debug : virEventPollDispatchHandles:482 : i=8 w=9
>2014-02-28 05:56:45.852+0000: 476: debug : virEventPollDispatchHandles:496 : EVENT_POLL_DISPATCH_HANDLE: watch=9 events=1
>2014-02-28 05:56:45.852+0000: 476: debug : udevEventHandleCallback:1523 : udev action: 'add'
>2014-02-28 05:56:45.852+0000: 476: debug : udevGetDeviceProperty:121 : udev reports device 'rx-0' does not have property 'DRIVER'
>2014-02-28 05:56:45.852+0000: 476: debug : udevGetDeviceProperty:139 : Found property key 'SUBSYSTEM' value 'queues' for device with sysname 'rx-0'
>2014-02-28 05:56:45.852+0000: 476: debug : udevGetDeviceType:1217 : Could not determine device type for device with sysfs name 'rx-0'
>2014-02-28 05:56:45.852+0000: 476: debug : udevAddOneDevice:1392 : Discarding device -1 0x7fcda71b9420 /sys/devices/virtual/net/vnet0/queues/rx-0
>2014-02-28 05:56:45.852+0000: 476: debug : virEventPollDispatchHandles:482 : i=9 w=39
>2014-02-28 05:56:45.852+0000: 476: debug : virEventPollCleanupTimeouts:514 : Cleanup 2
>2014-02-28 05:56:45.852+0000: 476: debug : virEventPollCleanupHandles:562 : Cleanup 10
>2014-02-28 05:56:45.852+0000: 476: debug : virEventRunDefaultImpl:270 : running default event implementation
>2014-02-28 05:56:45.852+0000: 476: debug : virEventPollCleanupTimeouts:514 : Cleanup 2
>2014-02-28 05:56:45.852+0000: 476: debug : virEventPollCleanupHandles:562 : Cleanup 10
>2014-02-28 05:56:45.852+0000: 476: debug : virEventPollMakePollFDs:391 : Prepare n=0 w=1, f=6 e=1 d=0
>2014-02-28 05:56:45.852+0000: 476: debug : virEventPollMakePollFDs:391 : Prepare n=1 w=2, f=8 e=1 d=0
>2014-02-28 05:56:45.852+0000: 476: debug : virEventPollMakePollFDs:391 : Prepare n=2 w=3, f=11 e=1 d=0
>2014-02-28 05:56:45.852+0000: 476: debug : virEventPollMakePollFDs:391 : Prepare n=3 w=4, f=12 e=1 d=0
>2014-02-28 05:56:45.852+0000: 476: debug : virEventPollMakePollFDs:391 : Prepare n=4 w=5, f=14 e=1 d=0
>2014-02-28 05:56:45.852+0000: 476: debug : virEventPollMakePollFDs:391 : Prepare n=5 w=6, f=19 e=1 d=0
>2014-02-28 05:56:45.852+0000: 476: debug : virEventPollMakePollFDs:391 : Prepare n=6 w=7, f=13 e=0 d=0
>2014-02-28 05:56:45.852+0000: 476: debug : virEventPollMakePollFDs:391 : Prepare n=7 w=8, f=13 e=1 d=0
>2014-02-28 05:56:45.852+0000: 476: debug : virEventPollMakePollFDs:391 : Prepare n=8 w=9, f=16 e=1 d=0
>2014-02-28 05:56:45.852+0000: 476: debug : virEventPollMakePollFDs:391 : Prepare n=9 w=39, f=21 e=1 d=0
>2014-02-28 05:56:45.852+0000: 476: debug : virEventPollCalculateTimeout:332 : Calculate expiry of 2 timers
>2014-02-28 05:56:45.852+0000: 476: debug : virEventPollCalculateTimeout:340 : Got a timeout scheduled for 1393567010848
>2014-02-28 05:56:45.852+0000: 476: debug : virEventPollCalculateTimeout:353 : Schedule timeout then=1393567010848 now=1393567005852
>2014-02-28 05:56:45.852+0000: 476: debug : virEventPollCalculateTimeout:361 : Timeout at 1393567010848 due in 4996 ms
>2014-02-28 05:56:45.852+0000: 476: debug : virEventPollRunOnce:627 : EVENT_POLL_RUN: nhandles=9 timeout=4996
>2014-02-28 05:56:45.852+0000: 476: debug : virEventPollRunOnce:638 : Poll got 1 event(s)
>2014-02-28 05:56:45.852+0000: 476: debug : virEventPollDispatchTimeouts:423 : Dispatch 2
>2014-02-28 05:56:45.852+0000: 476: debug : virEventPollDispatchHandles:468 : Dispatch 9
>2014-02-28 05:56:45.852+0000: 476: debug : virEventPollDispatchHandles:482 : i=0 w=1
>2014-02-28 05:56:45.853+0000: 476: debug : virEventPollDispatchHandles:482 : i=1 w=2
>2014-02-28 05:56:45.853+0000: 476: debug : virEventPollDispatchHandles:482 : i=2 w=3
>2014-02-28 05:56:45.853+0000: 476: debug : virEventPollDispatchHandles:482 : i=3 w=4
>2014-02-28 05:56:45.853+0000: 476: debug : virEventPollDispatchHandles:482 : i=4 w=5
>2014-02-28 05:56:45.853+0000: 476: debug : virEventPollDispatchHandles:482 : i=5 w=6
>2014-02-28 05:56:45.853+0000: 476: debug : virEventPollDispatchHandles:482 : i=7 w=8
>2014-02-28 05:56:45.853+0000: 476: debug : virEventPollDispatchHandles:482 : i=8 w=9
>2014-02-28 05:56:45.853+0000: 476: debug : virEventPollDispatchHandles:496 : EVENT_POLL_DISPATCH_HANDLE: watch=9 events=1
>2014-02-28 05:56:45.853+0000: 476: debug : udevEventHandleCallback:1523 : udev action: 'add'
>2014-02-28 05:56:45.853+0000: 476: debug : udevGetDeviceProperty:121 : udev reports device 'tx-0' does not have property 'DRIVER'
>2014-02-28 05:56:45.853+0000: 476: debug : udevGetDeviceProperty:139 : Found property key 'SUBSYSTEM' value 'queues' for device with sysname 'tx-0'
>2014-02-28 05:56:45.853+0000: 476: debug : udevGetDeviceType:1217 : Could not determine device type for device with sysfs name 'tx-0'
>2014-02-28 05:56:45.853+0000: 476: debug : udevAddOneDevice:1392 : Discarding device -1 0x7fcda71ba020 /sys/devices/virtual/net/vnet0/queues/tx-0
>2014-02-28 05:56:45.853+0000: 476: debug : virEventPollDispatchHandles:482 : i=9 w=39
>2014-02-28 05:56:45.853+0000: 476: debug : virEventPollCleanupTimeouts:514 : Cleanup 2
>2014-02-28 05:56:45.853+0000: 476: debug : virEventPollCleanupHandles:562 : Cleanup 10
>2014-02-28 05:56:45.853+0000: 476: debug : virEventRunDefaultImpl:270 : running default event implementation
>2014-02-28 05:56:45.853+0000: 476: debug : virEventPollCleanupTimeouts:514 : Cleanup 2
>2014-02-28 05:56:45.853+0000: 476: debug : virEventPollCleanupHandles:562 : Cleanup 10
>2014-02-28 05:56:45.853+0000: 476: debug : virEventPollMakePollFDs:391 : Prepare n=0 w=1, f=6 e=1 d=0
>2014-02-28 05:56:45.853+0000: 476: debug : virEventPollMakePollFDs:391 : Prepare n=1 w=2, f=8 e=1 d=0
>2014-02-28 05:56:45.853+0000: 476: debug : virEventPollMakePollFDs:391 : Prepare n=2 w=3, f=11 e=1 d=0
>2014-02-28 05:56:45.853+0000: 476: debug : virEventPollMakePollFDs:391 : Prepare n=3 w=4, f=12 e=1 d=0
>2014-02-28 05:56:45.853+0000: 476: debug : virEventPollMakePollFDs:391 : Prepare n=4 w=5, f=14 e=1 d=0
>2014-02-28 05:56:45.853+0000: 476: debug : virEventPollMakePollFDs:391 : Prepare n=5 w=6, f=19 e=1 d=0
>2014-02-28 05:56:45.853+0000: 476: debug : virEventPollMakePollFDs:391 : Prepare n=6 w=7, f=13 e=0 d=0
>2014-02-28 05:56:45.853+0000: 476: debug : virEventPollMakePollFDs:391 : Prepare n=7 w=8, f=13 e=1 d=0
>2014-02-28 05:56:45.853+0000: 476: debug : virEventPollMakePollFDs:391 : Prepare n=8 w=9, f=16 e=1 d=0
>2014-02-28 05:56:45.853+0000: 476: debug : virEventPollMakePollFDs:391 : Prepare n=9 w=39, f=21 e=1 d=0
>2014-02-28 05:56:45.853+0000: 476: debug : virEventPollCalculateTimeout:332 : Calculate expiry of 2 timers
>2014-02-28 05:56:45.853+0000: 476: debug : virEventPollCalculateTimeout:340 : Got a timeout scheduled for 1393567010848
>2014-02-28 05:56:45.853+0000: 476: debug : virEventPollCalculateTimeout:353 : Schedule timeout then=1393567010848 now=1393567005853
>2014-02-28 05:56:45.853+0000: 476: debug : virEventPollCalculateTimeout:361 : Timeout at 1393567010848 due in 4995 ms
>2014-02-28 05:56:45.853+0000: 476: debug : virEventPollRunOnce:627 : EVENT_POLL_RUN: nhandles=9 timeout=4995
>2014-02-28 05:56:45.864+0000: 478: debug : virFileClose:90 : Closed fd 24
>2014-02-28 05:56:45.870+0000: 478: debug : virFileClose:90 : Closed fd 24
>2014-02-28 05:56:45.876+0000: 478: debug : virFileClose:90 : Closed fd 24
>2014-02-28 05:56:45.884+0000: 478: debug : virFileClose:90 : Closed fd 24
>2014-02-28 05:56:45.897+0000: 478: debug : virFileClose:90 : Closed fd 24
>2014-02-28 05:56:45.906+0000: 478: debug : virFileClose:90 : Closed fd 24
>2014-02-28 05:56:45.912+0000: 478: debug : virFileClose:90 : Closed fd 24
>2014-02-28 05:56:45.912+0000: 478: debug : __virNWFilterInstantiateFilter:838 : filter name: clean-traffic
>2014-02-28 05:56:45.912+0000: 478: debug : virNWFilterDetermineMissingVarsRec:528 : Following filter no-mac-spoofing
>
>2014-02-28 05:56:45.912+0000: 478: debug : virNWFilterDetermineMissingVarsRec:528 : Following filter no-ip-spoofing
>
>2014-02-28 05:56:45.912+0000: 478: debug : virNWFilterDetermineMissingVarsRec:528 : Following filter allow-incoming-ipv4
>
>2014-02-28 05:56:45.912+0000: 478: debug : virNWFilterDetermineMissingVarsRec:528 : Following filter no-arp-spoofing
>
>2014-02-28 05:56:45.912+0000: 478: debug : virNWFilterDetermineMissingVarsRec:528 : Following filter no-arp-mac-spoofing
>
>2014-02-28 05:56:45.912+0000: 478: debug : virNWFilterDetermineMissingVarsRec:528 : Following filter no-arp-ip-spoofing
>
>2014-02-28 05:56:45.912+0000: 478: debug : virNWFilterDetermineMissingVarsRec:528 : Following filter no-other-l2-traffic
>
>2014-02-28 05:56:45.912+0000: 478: debug : virNWFilterDetermineMissingVarsRec:528 : Following filter qemu-announce-self
>
>2014-02-28 05:56:45.912+0000: 478: debug : virNWFilterDetermineMissingVarsRec:528 : Following filter qemu-announce-self-rarp
>
>2014-02-28 05:56:45.912+0000: 478: debug : virNWFilterDetermineMissingVarsRec:528 : Following filter no-other-rarp-traffic
>
>2014-02-28 05:56:45.918+0000: 478: debug : virFileClose:90 : Closed fd 24
>2014-02-28 05:56:45.918+0000: 478: debug : virCommandRunAsync:2282 : About to run /bin/sh -c 'IPT="/usr/sbin/iptables"
>$IPT -D libvirt-out -m physdev --physdev-is-bridged --physdev-out vnet0 -g FO-vnet0
>$IPT -D libvirt-out -m physdev --physdev-out vnet0 -g FO-vnet0
>$IPT -D libvirt-in -m physdev --physdev-in vnet0 -g FI-vnet0
>$IPT -D libvirt-host-in -m physdev --physdev-in vnet0 -g HI-vnet0
>$IPT -D libvirt-in-post -m physdev --physdev-in vnet0 -j ACCEPT
>$IPT -F FO-vnet0
>$IPT -X FO-vnet0
>$IPT -F FI-vnet0
>$IPT -X FI-vnet0
>$IPT -F HI-vnet0
>$IPT -X HI-vnet0
>IPT="/usr/sbin/ip6tables"
>$IPT -D libvirt-out -m physdev --physdev-is-bridged --physdev-out vnet0 -g FO-vnet0
>$IPT -D libvirt-out -m physdev --physdev-out vnet0 -g FO-vnet0
>$IPT -D libvirt-in -m physdev --physdev-in vnet0 -g FI-vnet0
>$IPT -D libvirt-host-in -m physdev --physdev-in vnet0 -g HI-vnet0
>$IPT -D libvirt-in-post -m physdev --physdev-in vnet0 -j ACCEPT
>$IPT -F FO-vnet0
>$IPT -X FO-vnet0
>$IPT -F FI-vnet0
>$IPT -X FI-vnet0
>$IPT -F HI-vnet0
>$IPT -X HI-vnet0
>EBT="/usr/sbin/ebtables"
>$EBT -t nat -D PREROUTING -i vnet0 -j libvirt-I-vnet0
>$EBT -t nat -D POSTROUTING -o vnet0 -j libvirt-O-vnet0
>EBT="/usr/sbin/ebtables"
>collect_chains()
>{
>  for tmp2 in $*; do
>    for tmp in $($EBT -t nat -L $tmp2 | \
>      sed -n "/Bridge chain/,\$ s/.*-j \$[IO]-.*\$/\\1/p");
>    do
>      echo $tmp
>      collect_chains $tmp
>    done
>  done
>}
>rm_chains()
>{
>  for tmp in $*; do $EBT -t nat -F $tmp; done
>  for tmp in $*; do $EBT -t nat -X $tmp; done
>}
>tmp='\''
>'\''
>IFS='\'' '\'''\''	'\''$tmp
>chains="$(collect_chains libvirt-I-vnet0 libvirt-O-vnet0)"
>$EBT -t nat -F libvirt-I-vnet0
>$EBT -t nat -F libvirt-O-vnet0
>rm_chains $chains
>$EBT -t nat -F libvirt-I-vnet0
>$EBT -t nat -X libvirt-I-vnet0
>$EBT -t nat -F libvirt-O-vnet0
>$EBT -t nat -X libvirt-O-vnet0
>'
>2014-02-28 05:56:45.918+0000: 478: debug : virFileClose:90 : Closed fd 24
>2014-02-28 05:56:45.918+0000: 478: debug : virFileClose:90 : Closed fd 26
>2014-02-28 05:56:45.919+0000: 478: debug : virFileClose:90 : Closed fd 28
>2014-02-28 05:56:45.919+0000: 478: debug : virCommandRunAsync:2285 : Command result 0, with PID 2341
>2014-02-28 05:56:45.969+0000: 478: debug : virCommandRun:2142 : Result exit status 0, stdout: '' stderr: '2014-02-28 05:56:45.919+0000: 2341: debug : virFileClose:90 : Closed fd 26
>2014-02-28 05:56:45.919+0000: 2341: debug : virFileClose:90 : Closed fd 28
>2014-02-28 05:56:45.919+0000: 2341: debug : virFileClose:90 : Closed fd 24
>iptables v1.4.21: goto 'FO-vnet0' is not a chain
>
>Try `iptables -h' or 'iptables --help' for more information.
>iptables v1.4.21: goto 'FO-vnet0' is not a chain
>
>Try `iptables -h' or 'iptables --help' for more information.
>iptables v1.4.21: goto 'FI-vnet0' is not a chain
>
>Try `iptables -h' or 'iptables --help' for more information.
>iptables v1.4.21: goto 'HI-vnet0' is not a chain
>
>Try `iptables -h' or 'iptables --help' for more information.
>iptables: Bad rule (does a matching rule exist in that chain?).
>iptables: No chain/target/match by that name.
>iptables: No chain/target/match by that name.
>iptables: No chain/target/match by that name.
>iptables: No chain/target/match by that name.
>iptables: No chain/target/match by that name.
>iptables: No chain/target/match by that name.
>ip6tables v1.4.21: goto 'FO-vnet0' is not a chain
>
>Try `ip6tables -h' or 'ip6tables --help' for more information.
>ip6tables v1.4.21: goto 'FO-vnet0' is not a chain
>
>Try `ip6tables -h' or 'ip6tables --help' for more information.
>ip6tables v1.4.21: goto 'FI-vnet0' is not a chain
>
>Try `ip6tables -h' or 'ip6tables --help' for more information.
>ip6tables v1.4.21: goto 'HI-vnet0' is not a chain
>
>Try `ip6tables -h' or 'ip6tables --help' for more information.
>ip6tables: Bad rule (does a matching rule exist in that chain?).
>ip6tables: No chain/target/match by that name.
>ip6tables: No chain/target/match by that name.
>ip6tables: No chain/target/match by that name.
>ip6tables: No chain/target/match by that name.
>ip6tables: No chain/target/match by that name.
>ip6tables: No chain/target/match by that name.
>'
>2014-02-28 05:56:45.969+0000: 478: debug : virFileClose:90 : Closed fd 25
>2014-02-28 05:56:45.969+0000: 478: debug : virFileClose:90 : Closed fd 27
>2014-02-28 05:56:45.969+0000: 478: debug : virCommandRunAsync:2282 : About to run /bin/sh -c 'EBT="/usr/sbin/ebtables"
>cmd='\''$EBT -t nat -N libvirt-J-vnet0'\''
>eval res=\$$"${cmd} 2>&1"$
>if [ $? -ne 0 ]; then  echo "Failure to execute command '\''${cmd}'\'' : '\''${res}'\''.";  exit 1;fi
>cmd='\''$EBT -t nat -N libvirt-P-vnet0'\''
>eval res=\$$"${cmd} 2>&1"$
>if [ $? -ne 0 ]; then  echo "Failure to execute command '\''${cmd}'\'' : '\''${res}'\''.";  exit 1;fi
>cmd='\''$EBT -t nat -A libvirt-J-vnet0 -s 52:54:00:7f:44:cb -p ipv4 --ip-protocol udp --ip-sport 68 --ip-dport 67 -j ACCEPT'\''
>eval res=\$$"${cmd} 2>&1"$
>if [ $? -ne 0 ]; then  echo "Failure to execute command '\''${cmd}'\'' : '\''${res}'\''.";  exit 1;fi
>cmd='\''$EBT -t nat -A libvirt-J-vnet0 -j DROP'\''
>eval res=\$$"${cmd} 2>&1"$
>if [ $? -ne 0 ]; then  echo "Failure to execute command '\''${cmd}'\'' : '\''${res}'\''.";  exit 1;fi
>cmd='\''$EBT -t nat -A libvirt-P-vnet0 -d 52:54:00:7f:44:cb -p ipv4 --ip-protocol udp  --ip-sport 67 --ip-dport 68 -j ACCEPT'\''
>eval res=\$$"${cmd} 2>&1"$
>if [ $? -ne 0 ]; then  echo "Failure to execute command '\''${cmd}'\'' : '\''${res}'\''.";  exit 1;fi
>cmd='\''$EBT -t nat -A libvirt-P-vnet0 -d ff:ff:ff:ff:ff:ff -p ipv4 --ip-protocol udp  --ip-sport 67 --ip-dport 68 -j ACCEPT'\''
>eval res=\$$"${cmd} 2>&1"$
>if [ $? -ne 0 ]; then  echo "Failure to execute command '\''${cmd}'\'' : '\''${res}'\''.";  exit 1;fi
>cmd='\''$EBT -t nat -A libvirt-P-vnet0 -j DROP'\''
>eval res=\$$"${cmd} 2>&1"$
>if [ $? -ne 0 ]; then  echo "Failure to execute command '\''${cmd}'\'' : '\''${res}'\''.";  exit 1;fi
>cmd='\''$EBT -t nat -A PREROUTING -i vnet0 -j libvirt-J-vnet0'\''
>eval res=\$$"${cmd} 2>&1"$
>if [ $? -ne 0 ]; then  echo "Failure to execute command '\''${cmd}'\'' : '\''${res}'\''.";  exit 1;fi
>cmd='\''$EBT -t nat -A POSTROUTING -o vnet0 -j libvirt-P-vnet0'\''
>eval res=\$$"${cmd} 2>&1"$
>if [ $? -ne 0 ]; then  echo "Failure to execute command '\''${cmd}'\'' : '\''${res}'\''.";  exit 1;fi
>$EBT -t nat -E libvirt-J-vnet0 libvirt-I-vnet0
>$EBT -t nat -E libvirt-P-vnet0 libvirt-O-vnet0
>'
>2014-02-28 05:56:45.970+0000: 478: debug : virFileClose:90 : Closed fd 24
>2014-02-28 05:56:45.970+0000: 478: debug : virFileClose:90 : Closed fd 26
>2014-02-28 05:56:45.970+0000: 478: debug : virFileClose:90 : Closed fd 28
>2014-02-28 05:56:45.970+0000: 478: debug : virCommandRunAsync:2285 : Command result 0, with PID 2378
>2014-02-28 05:56:45.999+0000: 478: debug : virCommandRun:2142 : Result status 0, stdout: '' stderr: '2014-02-28 05:56:45.970+0000: 2378: debug : virFileClose:90 : Closed fd 26
>2014-02-28 05:56:45.970+0000: 2378: debug : virFileClose:90 : Closed fd 28
>2014-02-28 05:56:45.970+0000: 2378: debug : virFileClose:90 : Closed fd 24
>'
>2014-02-28 05:56:45.999+0000: 478: debug : virFileClose:90 : Closed fd 25
>2014-02-28 05:56:45.999+0000: 478: debug : virFileClose:90 : Closed fd 27
>2014-02-28 05:56:46.023+0000: 2398: error : virNWFilterSnoopDHCPOpen:1116 : internal error: setup of pcap handle failed
>2014-02-28 05:56:46.029+0000: 2398: debug : virFileClose:90 : Closed fd 24
>
>
>     ====== end of log =====
>
>

Actions: View

Attachments on bug 1071181: 868890