- Users - libvirt List Archives

[libvirt-users] Long time to restart guest
by Jesson 23 Nov '18

23 Nov '18

Hello, my guest is professional Windows, the version is 10. Standby (display lights up) After more than 2 days, if we restart on Windows (do not restart X with virsh), the reboot takes a long time, maybe about 7 minutes. But all kvm logs are normal, and the guest state is running, only the linux system log gives me some messages. My guests only started after resetting all the devices. So what should I do to get started quickly? there are my environment: Compiled against library: libvirt 4.4.0 Using library: libvirt 4.4.0 Using API: QEMU 4.4.0 Running hypervisor: QEMU 2.12.0 Linux: LFS 7.10 Kernel: 4.17.2

1 0

[libvirt-users] Remote and local connections at the same time (Centos 7)
by Anastasiya Ruzhanskaya 22 Nov '18

22 Nov '18

Hello! I was investigating libvirt a year ago regarding it's remote control. I figured out necessary settings for configuring remote control in ubuntu (setting flags in libvirt setting files). Now I have several questions: 1) Are these flags the same for Centos? They did not worked for me. My flags for ubuntu are (for tcp for example): /etc/libvirt/libvirtd.conf : listen_tls = 0, listen_tcp = 1, listen_addr = "0.0.0.0 " auth_- tcp = "none " /etc/init/libvirt-bin.conf: add -l (listen) : env libvirtd_opts = d -l" /etc/default/libvirt-bin add -l : libvirtd_opts = d -l" 2) Can the remote control be configured along with local on one machine? For example, in one configuration I want to run libvirt on this machine and accept incoming remote calls, and at the same time I want to be able to run virtual machines locally on the same machine. Are these two things somehow connected or I am free to set up both of them? As I see the flags touch not only libvirtd settings, but also libvirt settings.

2 2

[libvirt-users] Libvirt access control drivers
by Anastasiya Ruzhanskaya 21 Nov '18

21 Nov '18

Hello! According to the documentation access control drivers are not in really "good condition". There is a polkit, but it can distinguish users only according the pid. However, I have met some articles about more fine-grained control and about selinux drivers for libvirt? So, what is the status now? Should I implement something by myself if I want access based on login, are their instructions how to write these drivers or there is smth already?

3 18

[libvirt-users] Dual Stack setup problems
by Simon Michalke 21 Nov '18

21 Nov '18

Hi, my host hast 2 interface with 2 different ipv4 addresses: eno1 and eno1:1. eno1 also has an ipv6 subnet. Is there a way to have ipv4 redirect to eno1:1 and ipv6 redirect to eno1 with one network or do I have to setup a 2 virtual networks with 2 interfaces to get dual stack working properly? Regards, Simon

1 0

[libvirt-users] guest on host's shutdown/reboot (problem?) - centos 7.5
by lejeczek 19 Nov '18

19 Nov '18

hi guys I have just two guest after which libvirt looks and when I shutdown those guests: $ virsh shutdown $_dom that domain takes little time to power down, as expected one would say(~20sec) But! I reboot the hosts and I have in my: /etc/sysconfig/libvirt-guests : ON_SHUTDOWN=shutdown PARALLEL_SHUTDOWN=1 SHUTDOWN_TIMEOUT=300 I see libvirtd service shut down takes minutes, a few good minutes to deal with guests shutdown(I suppose?) How could I dig into it and troubleshoot? Would you have any idea as why libvirtd shutdown takes that long? many thank, L.

1 0

[libvirt-users] libvirt call qemu to create vm need more than 10 seconds
by netsurfed 16 Nov '18

16 Nov '18

Hi all: It takes more than 10 seconds to create a vm on a Dell R830 machine, but it takes less than 2 seconds on other machines. This is not normal, so I turned on the debug log for libvirtd. I analyzed the log and found that the time was spent on libvirtd calling qemu. Thread 95225 calls the qemuProcessLaunch interface at 14:22:30.129 and then builds the emulator command line, but the qemuDomainObjTaint method is called after 10 seconds. I tried to analyze the qemuProcessLaunch function to find the reason, but nothing was found. What is the cause? 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 There are too many debug logs. I paste the log of thread 99225 below: Line 58679: 2018-11-13 14:22:30.129+0000: 95225: debug : qemuProcessLaunch:5614 : vm=0x7f822c002fe0 name=6efd749c-3162-4ac4-90e6-b3fca6fde9bc id=1 asyncJob=6 incoming.launchURI=<null> incoming.deferredURI=<null> incoming.fd=-1 incoming.path=<null> snapshot=(nil) vmop=0 flags=0x11 Line 58680: 2018-11-13 14:22:30.129+0000: 95225: info : virObjectRef:296 : OBJECT_REF: obj=0x7f81f80166f0 Line 58681: 2018-11-13 14:22:30.129+0000: 95225: info : virObjectRef:296 : OBJECT_REF: obj=0x7f81f8257e60 Line 58682: 2018-11-13 14:22:30.129+0000: 95225: debug : qemuProcessLaunch:5634 : Creating domain log file Line 58683: 2018-11-13 14:22:30.129+0000: 95225: info : virObjectRef:296 : OBJECT_REF: obj=0x7f81f80166f0 Line 58684: 2018-11-13 14:22:30.129+0000: 95225: info : virObjectNew:202 : OBJECT_NEW: obj=0x7f822c006560 classname=qemuDomainLogContext Line 58685: 2018-11-13 14:22:30.129+0000: 95225: debug : qemuDomainLogContextNew:4563 : Context new 0x7f822c006560 stdioLogD=1 Line 58686: 2018-11-13 14:22:30.130+0000: 95225: debug : virNetSocketNewConnectUNIX:640 : path=/var/run/libvirt/virtlogd-sock spawnDaemon=0 binary=<null> Line 58687: 2018-11-13 14:22:30.130+0000: 95225: debug : virNetSocketNewConnectUNIX:704 : connect() succeeded Line 58688: 2018-11-13 14:22:30.130+0000: 95225: debug : virNetSocketNew:236 : localAddr=0x7f8244ca5530 remoteAddr=0x7f8244ca55c0 fd=20 errfd=-1 pid=0 Line 58689: 2018-11-13 14:22:30.130+0000: 95225: info : virObjectNew:202 : OBJECT_NEW: obj=0x7f822c00aab0 classname=virNetSocket Line 58690: 2018-11-13 14:22:30.130+0000: 95225: info : virNetSocketNew:292 : RPC_SOCKET_NEW: sock=0x7f822c00aab0 fd=20 errfd=-1 pid=0 localAddr=127.0.0.1;0, remoteAddr=127.0.0.1;0 Line 58691: 2018-11-13 14:22:30.130+0000: 95225: info : virObjectNew:202 : OBJECT_NEW: obj=0x7f822c00b1b0 classname=virNetClient Line 58692: 2018-11-13 14:22:30.130+0000: 95225: info : virNetClientNew:328 : RPC_CLIENT_NEW: client=0x7f822c00b1b0 sock=0x7f822c00aab0 Line 58693: 2018-11-13 14:22:30.130+0000: 95225: info : virObjectNew:202 : OBJECT_NEW: obj=0x7f822c00ac50 classname=virNetClientProgram Line 58694: 2018-11-13 14:22:30.130+0000: 95225: info : virObjectRef:296 : OBJECT_REF: obj=0x7f822c00ac50 Line 58695: 2018-11-13 14:22:30.130+0000: 95225: debug : virNetMessageNew:46 : msg=0x7f822c00a900 tracked=0 Line 58696: 2018-11-13 14:22:30.130+0000: 95225: debug : virNetMessageEncodePayload:387 : Encode length as 164 Line 58697: 2018-11-13 14:22:30.130+0000: 95225: info : virNetClientSendInternal:2120 : RPC_CLIENT_MSG_TX_QUEUE: client=0x7f822c00b1b0 len=164 prog=2270401305 vers=1 proc=1 type=0 status=0 serial=0 Line 58698: 2018-11-13 14:22:30.130+0000: 95225: debug : virNetClientCallNew:2073 : New call 0x7f822c00acc0: msg=0x7f822c00a900, expectReply=1, nonBlock=0 Line 58699: 2018-11-13 14:22:30.130+0000: 95225: debug : virNetClientIO:1879 : Outgoing message prog=2270401305 version=1 serial=0 proc=1 type=0 length=164 dispatch=(nil) Line 58700: 2018-11-13 14:22:30.130+0000: 95225: debug : virNetClientIO:1938 : We have the buck head=0x7f822c00acc0 call=0x7f822c00acc0 Line 58701: 2018-11-13 14:22:30.130+0000: 95225: debug : virNetSocketUpdateIOCallback:2198 : Watch not registered on socket 0x7f822c00aab0 Line 58702: 2018-11-13 14:22:30.130+0000: 95225: debug : virNetMessageDecodeLength:161 : Got length, now need 48 total (44 more) Line 58703: 2018-11-13 14:22:30.130+0000: 95225: debug : virNetMessageDecodeNumFDs:336 : Got 1 FDs from peer Line 58704: 2018-11-13 14:22:30.130+0000: 95225: info : virNetSocketRecvFD:2048 : RPC_SOCKET_RECV_FD: sock=0x7f822c00aab0 fd=23 Line 58705: 2018-11-13 14:22:30.130+0000: 95225: info : virNetClientCallDispatch:1267 : RPC_CLIENT_MSG_RX: client=0x7f822c00b1b0 len=48 prog=2270401305 vers=1 proc=1 type=5 status=0 serial=0 Line 58706: 2018-11-13 14:22:30.130+0000: 95225: debug : virKeepAliveCheckMessage:374 : ka=(nil), client=0x7f82505b0086, msg=0x7f822c00b210 Line 58707: 2018-11-13 14:22:30.130+0000: 95225: debug : virNetMessageClear:74 : msg=0x7f822c00b210 nfds=0 Line 58708: 2018-11-13 14:22:30.130+0000: 95225: debug : virNetClientIOEventLoopPassTheBuck:1562 : Giving up the buck 0x7f822c00acc0 Line 58709: 2018-11-13 14:22:30.130+0000: 95225: debug : virNetClientIOEventLoopPassTheBuck:1576 : No thread to pass the buck to Line 58710: 2018-11-13 14:22:30.130+0000: 95225: debug : virNetSocketUpdateIOCallback:2198 : Watch not registered on socket 0x7f822c00aab0 Line 58711: 2018-11-13 14:22:30.130+0000: 95225: debug : virNetClientIO:1968 : All done with our call head=(nil) call=0x7f822c00acc0 rv=0 Line 58712: 2018-11-13 14:22:30.130+0000: 95225: debug : virNetMessageFree:87 : msg=0x7f822c00a900 nfds=1 cb=(nil) Line 58713: 2018-11-13 14:22:30.130+0000: 95225: debug : virFileClose:110 : Closed fd 23 Line 58714: 2018-11-13 14:22:30.130+0000: 95225: info : virObjectUnref:259 : OBJECT_UNREF: obj=0x7f81f80166f0 Line 58715: 2018-11-13 14:22:30.130+0000: 95225: debug : qemuProcessLaunch:5640 : Building emulator command line Line 58716: 2018-11-13 14:22:30.130+0000: 95225: debug : virFileClose:110 : Closed fd 23 Line 58717: 2018-11-13 14:22:30.130+0000: 95225: info : virObjectRef:296 : OBJECT_REF: obj=0x7f81f80166f0 Line 58718: 2018-11-13 14:22:30.130+0000: 95225: debug : qemuBuildCommandLine:9894 : driver=0x7f81f8011790 def=0x7f822c00b7e0 mon=0x7f822c0062a0 json=1 qemuCaps=0x7f822c002e80 migrateURI=(null) snapshot=(nil) vmop=0 Line 58719: 2018-11-13 14:22:30.131+0000: 95225: debug : virArchFromHost:181 : Mapped x86_64 to 32 (x86_64) Line 58720: 2018-11-13 14:22:30.131+0000: 95225: info : virObjectRef:296 : OBJECT_REF: obj=0x7f81f8257e60 Line 58721: 2018-11-13 14:22:30.131+0000: 95225: info : virObjectUnref:259 : OBJECT_UNREF: obj=0x7f81f8257e60 Line 58722: 2018-11-13 14:22:30.131+0000: 95225: debug : virCPUCheckFeature:817 : arch=x86_64, cpu=0x7f822c00c090, feature=svm Line 58723: 2018-11-13 14:22:30.131+0000: 95225: info : virObjectRef:296 : OBJECT_REF: obj=0x7f81f80166f0 Line 58724: 2018-11-13 14:22:30.131+0000: 95225: info : virNetDevProbeVnetHdr:208 : Enabling IFF_VNET_HDR Line 58772: 2018-11-13 14:22:30.132+0000: 95225: debug : virNetDevSetMACInternal:277 : SIOCSIFHWADDR vnet0 MAC=fe:54:00:28:29:1d - Success Line 58773: 2018-11-13 14:22:30.132+0000: 95225: debug : virFileClose:110 : Closed fd 25 Line 58775: 2018-11-13 14:22:30.132+0000: 95225: debug : virFileClose:110 : Closed fd 25 Line 58777: 2018-11-13 14:22:30.132+0000: 95225: debug : virFileClose:110 : Closed fd 25 Line 58782: 2018-11-13 14:22:30.132+0000: 95225: debug : virCommandRunAsync:2448 : About to run ovs-vsctl --timeout=5 -- --if-exists del-port vnet0 -- add-port lcs_br_1 vnet0 -- set Interface vnet0 'external-ids:attached-mac="52:54:00:28:29:1d"' -- set Interface vnet0 'external-ids:iface-id="04af9169-2c72-45e9-845d-3d162268728b"' -- set Interface vnet0 'external-ids:vm-id="6efd749c-3162-4ac4-90e6-b3fca6fde9bc"' -- set Interface vnet0 external-ids:iface-status=active Line 58789: 2018-11-13 14:22:30.133+0000: 95225: debug : virFileClose:110 : Closed fd 25 Line 58791: 2018-11-13 14:22:30.133+0000: 95225: debug : virFileClose:110 : Closed fd 27 Line 58792: 2018-11-13 14:22:30.133+0000: 95225: debug : virFileClose:110 : Closed fd 29 Line 58793: 2018-11-13 14:22:30.133+0000: 95225: debug : virCommandRunAsync:2451 : Command result 0, with PID 95350 Line 58993: 2018-11-13 14:22:30.146+0000: 95225: debug : virCommandRun:2299 : Result status 0, stdout: '' stderr: '2018-11-13 14:22:30.136+0000: 95350: debug : virFileClose:110 : Closed fd 27 Line 58997: 2018-11-13 14:22:30.146+0000: 95225: debug : virFileClose:110 : Closed fd 26 Line 58998: 2018-11-13 14:22:30.146+0000: 95225: debug : virFileClose:110 : Closed fd 28 Line 58999: 2018-11-13 14:22:30.147+0000: 95225: debug : virFileClose:110 : Closed fd 25 Line 59000: 2018-11-13 14:22:30.147+0000: 95225: info : virObjectUnref:259 : OBJECT_UNREF: obj=0x7f81f80166f0 Line 59001: 2018-11-13 14:22:30.147+0000: 95225: debug : virFileClose:110 : Closed fd 25 Line 59002: 2018-11-13 14:22:30.147+0000: 95225: info : virObjectRef:296 : OBJECT_REF: obj=0x7f81f80166f0 Line 59003: 2018-11-13 14:22:30.147+0000: 95225: info : virObjectUnref:259 : OBJECT_UNREF: obj=0x7f81f80166f0 Line 59004: 2018-11-13 14:22:30.147+0000: 95225: info : virObjectUnref:259 : OBJECT_UNREF: obj=0x7f81f80166f0 Line 60062: 2018-11-13 14:22:40.161+0000: 95225: info : virObjectRef:296 : OBJECT_REF: obj=0x7f81f80166f0 Line 60063: 2018-11-13 14:22:40.161+0000: 95225: warning : qemuDomainObjTaint:4415 : Domain id=1 name='6efd749c-3162-4ac4-90e6-b3fca6fde9bc' uuid=6efd749c-3162-4ac4-90e6-b3fca6fde9bc is tainted: high-privileges

2 1

[libvirt-users] performance overhead with backing chains?
by Riccardo Ravaioli 15 Nov '18

15 Nov '18

Hi, I was wondering if there are any studies on the performance overhead of a QEMU/KVM virtual machine when the backing chain of its disk(s) is of size n, with n > 1. In particular, it would be useful to know until what size we can expect little or no impact on a Linux virtual machine, for instance. Thanks! Regards, Riccardo

1 0

[libvirt-users] create vm timeout
by netsurfed 14 Nov '18

14 Nov '18

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

1 1

[libvirt-users] virsh reboot "in shutdown" state?
by Michael Taboada 12 Nov '18

12 Nov '18

Hi all, I've got a weird issue, and I'm trying to confirm if it's a bug, and if so, if there is a workaround until it is fixed. The situation is this: If I virsh reboot <domain> --mode acpi, it will actually reboot the domain cleanly (watching from the console allows me to see the full shutdown messages, followed by a bootup). However, after this point, virsh domstate <domain> provides the state "in shutdown". From what I read, this is only supposed to persist for more than a tiny fraction of a second if there was a problem killing qemu or cleaning up its resources which, to my knowledge, should not apply here since there is no killing of qemu involved, just an acpi signal sent to the domain. Am I wrong? Either way, the only way to run any start/stop type commands with virsh after running the reboot command is to destroy the domain, obviously not very practical. I've attached console output from my tests, and the log of the same time period below. System info: libvirt 4.8.0-2, qemu 3.0.0-3, linux 4.18.6.arch1-1, running on arch linux. Thanks, -Michael. ############################# Log of virsh commands: ############################# [lilmike@iof838 ~]$ virsh start test Domain test started [lilmike@iof838 ~]$ virsh domstate test running [lilmike@iof838 ~]$ virsh shutdown test --mode acpi Domain test is being shutdown [lilmike@iof838 ~]$ virsh domstate test shut off [lilmike@iof838 ~]$ sudo pgrep qemu-system 815 857 [lilmike@iof838 ~]$ virsh start test Domain test started [lilmike@iof838 ~]$ virsh domstate test running [lilmike@iof838 ~]$ virsh reboot test --mode acpi Domain test is being rebooted [lilmike@iof838 ~]$ virsh domstate test in shutdown [lilmike@iof838 ~]$ ############################# libvirt log file of domain: ############################# 2018-11-12 13:36:44.042+0000: starting up libvirt version: 4.8.0, qemu version: 3.0.0, kernel: 4.18.16-arch1-1-ARCH, hostname: mthost.mwtd.net LC_ALL=C PATH=/usr/local/sbin:/usr/local/bin:/usr/bin QEMU_AUDIO_DRV=spice /usr/bin/qemu-system-x86_64 -name guest=test,debug-threads=on -S -object secret,id=masterKey0,format=raw,file=/var/lib/libvirt/qemu/domain-9-test/master-key.aes -machine pc-i440fx-3.0,accel=kvm,usb=off,vmport=off,dump-guest-core=off -cpu Westmere,vme=on,ss=on,pclmuldq=on,pcid=on,x2apic=on,tsc-deadline=on,hypervisor=on,arat=on,tsc_adjust=on,umip=on,pdpe1gb=on,rdtscp=on,topoext=on -m 1024 -realtime mlock=off -smp 1,sockets=1,cores=1,threads=1 -uuid 8060a1de-66e9-4300-8677-0fdb0f830379 -no-user-config -nodefaults -chardev socket,id=charmonitor,fd=52,server,nowait -mon chardev=charmonitor,id=monitor,mode=control -rtc base=utc,driftfix=slew -global kvm-pit.lost_tick_policy=delay -no-hpet -no-shutdown -global PIIX4_PM.disable_s3=1 -global PIIX4_PM.disable_s4=1 -boot menu=on,strict=on -device ich9-usb-ehci1,id=usb,bus=pci.0,addr=0x6.0x7 -device ich9-usb-uhci1,masterbus=usb.0,firstport=0,bus=pci.0,multifunction=on,addr=0x6 -device ich9-usb-uhci2,masterbus=usb.0,firstport=2,bus=pci.0,addr=0x6.0x1 -device ich9-usb-uhci3,masterbus=usb.0,firstport=4,bus=pci.0,addr=0x6.0x2 -device ahci,id=sata0,bus=pci.0,addr=0x7 -drive file=/var/lib/livecd/arch.iso,format=raw,if=none,id=drive-sata0-0-0,media=cdrom,readonly=on -device ide-cd,bus=sata0.0,drive=drive-sata0-0-0,id=sata0-0-0,bootindex=1 -netdev tap,fd=54,id=hostnet0 -device e1000,netdev=hostnet0,id=net0,mac=52:54:00:e1:28:d3,bus=pci.0,addr=0x3 -netdev tap,fd=55,id=hostnet1 -device e1000,netdev=hostnet1,id=net1,mac=52:54:00:74:d0:3f,bus=pci.0,addr=0x4 -chardev pty,id=charserial0 -device isa-serial,chardev=charserial0,id=serial0 -device usb-tablet,id=input0,bus=usb.0,port=1 -spice port=5902,addr=127.0.0.1,disable-ticketing,image-compression=off,seamless-migration=on -device qxl-vga,id=video0,ram_size=67108864,vram_size=67108864,vram64_size_mb=0,vgamem_mb=16,max_outputs=1,bus=pci.0,addr=0x2 -device intel-hda,id=sound0,bus=pci.0,addr=0x5 -device hda-duplex,id=sound0-codec0,bus=sound0.0,cad=0 -chardev spicevmc,id=charredir0,name=usbredir -device usb-redir,chardev=charredir0,id=redir0,bus=usb.0,port=2 -chardev spicevmc,id=charredir1,name=usbredir -device usb-redir,chardev=charredir1,id=redir1,bus=usb.0,port=3 -device virtio-balloon-pci,id=balloon0,bus=pci.0,addr=0x8 -sandbox on,obsolete=deny,elevateprivileges=deny,spawn=deny,resourcecontrol=deny -msg timestamp=on 2018-11-12T13:36:44.112904Z qemu-system-x86_64: -chardev pty,id=charserial0: char device redirected to /dev/pts/3 (label charserial0) 2018-11-12T13:37:35.867474Z qemu-system-x86_64: terminating on signal 15 from pid 597 (/usr/bin/libvirtd) 2018-11-12 13:37:36.192+0000: shutting down, reason=shutdown 2018-11-12 13:37:52.035+0000: starting up libvirt version: 4.8.0, qemu version: 3.0.0, kernel: 4.18.16-arch1-1-ARCH, hostname: mthost.mwtd.net LC_ALL=C PATH=/usr/local/sbin:/usr/local/bin:/usr/bin QEMU_AUDIO_DRV=spice /usr/bin/qemu-system-x86_64 -name guest=test,debug-threads=on -S -object secret,id=masterKey0,format=raw,file=/var/lib/libvirt/qemu/domain-10-test/master-key.aes -machine pc-i440fx-3.0,accel=kvm,usb=off,vmport=off,dump-guest-core=off -cpu Westmere,vme=on,ss=on,pclmuldq=on,pcid=on,x2apic=on,tsc-deadline=on,hypervisor=on,arat=on,tsc_adjust=on,umip=on,pdpe1gb=on,rdtscp=on,topoext=on -m 1024 -realtime mlock=off -smp 1,sockets=1,cores=1,threads=1 -uuid 8060a1de-66e9-4300-8677-0fdb0f830379 -no-user-config -nodefaults -chardev socket,id=charmonitor,fd=52,server,nowait -mon chardev=charmonitor,id=monitor,mode=control -rtc base=utc,driftfix=slew -global kvm-pit.lost_tick_policy=delay -no-hpet -no-shutdown -global PIIX4_PM.disable_s3=1 -global PIIX4_PM.disable_s4=1 -boot menu=on,strict=on -device ich9-usb-ehci1,id=usb,bus=pci.0,addr=0x6.0x7 -device ich9-usb-uhci1,masterbus=usb.0,firstport=0,bus=pci.0,multifunction=on,addr=0x6 -device ich9-usb-uhci2,masterbus=usb.0,firstport=2,bus=pci.0,addr=0x6.0x1 -device ich9-usb-uhci3,masterbus=usb.0,firstport=4,bus=pci.0,addr=0x6.0x2 -device ahci,id=sata0,bus=pci.0,addr=0x7 -drive file=/var/lib/livecd/arch.iso,format=raw,if=none,id=drive-sata0-0-0,media=cdrom,readonly=on -device ide-cd,bus=sata0.0,drive=drive-sata0-0-0,id=sata0-0-0,bootindex=1 -netdev tap,fd=54,id=hostnet0 -device e1000,netdev=hostnet0,id=net0,mac=52:54:00:e1:28:d3,bus=pci.0,addr=0x3 -netdev tap,fd=55,id=hostnet1 -device e1000,netdev=hostnet1,id=net1,mac=52:54:00:74:d0:3f,bus=pci.0,addr=0x4 -chardev pty,id=charserial0 -device isa-serial,chardev=charserial0,id=serial0 -device usb-tablet,id=input0,bus=usb.0,port=1 -spice port=5902,addr=127.0.0.1,disable-ticketing,image-compression=off,seamless-migration=on -device qxl-vga,id=video0,ram_size=67108864,vram_size=67108864,vram64_size_mb=0,vgamem_mb=16,max_outputs=1,bus=pci.0,addr=0x2 -device intel-hda,id=sound0,bus=pci.0,addr=0x5 -device hda-duplex,id=sound0-codec0,bus=sound0.0,cad=0 -chardev spicevmc,id=charredir0,name=usbredir -device usb-redir,chardev=charredir0,id=redir0,bus=usb.0,port=2 -chardev spicevmc,id=charredir1,name=usbredir -device usb-redir,chardev=charredir1,id=redir1,bus=usb.0,port=3 -device virtio-balloon-pci,id=balloon0,bus=pci.0,addr=0x8 -sandbox on,obsolete=deny,elevateprivileges=deny,spawn=deny,resourcecontrol=deny -msg timestamp=on 2018-11-12T13:37:52.106657Z qemu-system-x86_64: -chardev pty,id=charserial0: char device redirected to /dev/pts/3 (label charserial0)

2 1

[libvirt-users] usb post passthough stopped workng after kernel upgrade
by daggs 09 Nov '18

09 Nov '18

Greetings, I have a vm on debian 9.5 to which I pass an specific usb from the host. here is the relevant part in the vm's xml file: <hostdev mode='subsystem' type='usb' managed='yes'> <source> <vendor id='0x148f'/> <product id='0x5572'/> </source> <address type='usb' bus='0' port='1'/> </hostdev> the address line was added automatically by libvirt. everything was working well with kernel 4.15.11-1~bpo9+1 until I needed to upgrade the kernel to latest possible version due to usb issues I've upgraded to 4.18.6-1~bpo9+1. after the upgrade, my vm doesn't starts anymore, I see this msg: error: Failed to start domain router error: internal error: qemu unexpectedly closed the monitor: 2018-11-02T13:43:32.174730Z qemu-system-x86_64: -device usb-host,hostbus=1,hostaddr=4,id=hostdev4,bus=usb.0,port=1: failed to find host usb device 1:4 how can a kernel upgrade cause this? is there a fix for this issue? Thanks, Dagg.

1 2