November 2018 - Users - libvirt List Archives

[libvirt-users] [virtual interface] detach interface during boot succeed with no changes
by Yalan Zhang 08 Sep '22

08 Sep '22

Hi guys, when I detach an interface from vm during boot (vm boot not finished), it always fail. I'm not sure if there is an existing bug. I have confirmed with someone that for disk, there is similar behavior, if this is also acceptable? # virsh destroy rhel7.2; virsh start rhel7.2 ;sleep 2; virsh detach-interface rhel7.2 network 52:54:00:98:c4:a0; sleep 2; virsh dumpxml rhel7.2 |grep /interface -B9 Domain rhel7.2 destroyed Domain rhel7.2 started Interface detached successfully <address type='pci' domain='0x0000' bus='0x00' slot='0x06' function='0x0'/> </controller> <interface type='network'> <mac address='52:54:00:98:c4:a0'/> <source network='default' bridge='virbr0'/> <target dev='vnet0'/> <model type='rtl8139'/> <alias name='net0'/> <address type='pci' domain='0x0000' bus='0x00' slot='0x03' function='0x0'/> </interface> When I detach after the vm boot, expand the sleep time to 10, it will succeed. # virsh destroy rhel7.2; virsh start rhel7.2 ;sleep 10; virsh detach-interface rhel7.2 network 52:54:00:98:c4:a0; sleep 2; virsh dumpxml rhel7.2 |grep /interface -B9 Domain rhel7.2 destroyed Domain rhel7.2 started Interface detached successfully ------- Best Regards, Yalan Zhang IRC: yalzhang Internal phone: 8389413

3 4

[libvirt-users] Add Virtlyst to the list of libvirt users
by Daniel Nicoletti 23 Sep '20

23 Sep '20

Hi, I've just released v1.0.0 of Virtlyst[1] a web tool to manage VMs using Qt/C++/Cutelyst https://dantti.wordpress.com/2018/04/19/announcing-virtlyst-a-web-interface… Thanks. 1 - https://github.com/cutelyst/Virtlyst -- Daniel Nicoletti KDE Developer - http://dantti.wordpress.com

4 5

[libvirt-users] Question about disabling UFO on guest
by Bao Nguyen 05 Aug '20

05 Aug '20

Hello everyone, I would like to ask a question regarding to disable UFO of virtio vNIC in my guest. I have read the document at https://libvirt.org/formatdomain.html *host* The csum, gso, tso4, tso6, ecn and ufo attributes with possible values on and off can be used to turn off host offloading options. By default, the supported offloads are enabled by QEMU. *Since 1.2.9 (QEMU only)* The mrg_rxbuf attribute can be used to control mergeable rx buffers on the host side. Possible values are on (default) and off. *Since 1.2.13 (QEMU only)* *guest* The csum, tso4, tso6, ecn and ufo attributes with possible values on and off can be used to turn off guest offloading options. By default, the supported offloads are enabl ed by QEMU. *Since 1.2.9 (QEMU only)* Then I disabled UFO on my vNIC on guest as the following configuration <devices> <interface type='network'> <source network='default'/> <target dev='vnet1'/> <model type='virtio'/> <driver name='vhost' txmode='iothread' ioeventfd='on' event_idx='off' queues='5' rx_queue_size='256' tx_queue_size='256'> *<host gso='off' ufo='off' />* *<guest ufo='off'/>* </driver> </interface> </devices> Then I reboot my node to get the change effect and it works. However, can I disable the UFO without touching the host OS? or it always has to disable on both host and guest like that? Thanks, Brs, Natsu

2 1

[libvirt-users] Libvirt api for esx
by ROHIT SINGH 13 Dec '18

13 Dec '18

Hi, I am doing poc for using libvirt api for implementation of esx in python. I tried researching through module but did not find a way how it works for esx. Any help on how to proceed specifically for esx would be of great help. Please let me know as soon as possible, lagging on deliverables. Thanks for help!! Regards Rohit Singh

2 11

[libvirt-users] console type tcp with logging
by Vasiliy Tolstov 03 Dec '18

03 Dec '18

Hi! I want to have ability to connect to guest console via libvirt api (and expose this data to xtermjs via websocket) with getty tty. And also i want to have log of tty1 (do log grub, kernel booting and errors). What i need to do in libvirt xml for such case? -- Vasiliy Tolstov, e-mail: v.tolstov(a)selfip.ru

3 8

[libvirt-users] virsh console and other language keymaps
by Michael Taboada 29 Nov '18

29 Nov '18

Hi, I've got a small vm server running kvm + libvirt, and I made a simple shell script that allows users to ssh in and control their vms (power off, etc). However, one of my users uses the french canadian keyboard layout on her home computer, and upon being told "escape character is ^]" expected to need to press ctrl+right-alt_] (] being in the same location it is on a US keyboard). This is because on a french canadian layout, the right bracket key is in the same spot at on US layout, but needs to press right alt with it or it is the c-cedilla key. However, upon pressing ctrl+right-alt+c-cedilla, nothing happens (even this is ctrl+right bracket on a canadian keyboard). Instead, pressing ctrl+c-cedilla on her canadian french keyboard exits the console as if it were using a US layout. My question: how to make it so pressing ctrl+(canadian ]) works? Is this something that has to be done on the vm side, or on the host side, or maybe on the client ssh side? I'd prefer it be something thast can be different based on who is using the virsh console command since me, as the admin, may need to help with the console at some points, and my keyboard is US, so I have no c-cedilla or canadian right bracket key, but she does. Thanks, -Michael.

3 2

[libvirt-users] Unable to configure libxl's memory management parameters
by Mathieu Tarral 28 Nov '18

28 Nov '18

Hi ! I'm trying to get a working installation of Xen 4.11 from source, with Libvirt. I managed to compile, install and boot on Xen so far. But when I start the libvirt daemon, it fails with the following error: info : libvirt version: 4.1.0, package: 5.fc28 (Fedora Project, 2018-08-23-19:00:58, buildvm-19 error : libxlDriverConfigNew:1644 : Unable to configure libxl's memory management parameters error : virStateInitialize:775 : Initialization of LIBXL state driver failed: no error error : daemonRunStateInit:837 : Driver state initialization failed So there are 2 things here: - why libvirt is unable to configure Libxl ? where should i look for any clues ? - "Initialization of LIBXL state driver failed: no error" it looks like a bug in Libvirt, if it fails, an error message should be reported Thank you. -- Mathieu Tarral Sent with ProtonMail Secure Email.

2 1

[libvirt-users] Sasl+tls setup
by Anastasiya Ruzhanskaya 28 Nov '18

28 Nov '18

Hello everyone, I am trying to set up sasl authentication in virt-manager. I read in one existing bug, that it is better to use tls for encryption and sasl for authentication, but not use sasl for both. I configured tls, it was fine. Then I created a user "u" on server and modified libvirtd.conf. I set auth_tls = "sasl" there and mech_list: scram-sha-1 in sasl2 config for libvirt. The output of sasl: u@ubuntu2:~$ sudo sasldblistusers2 -f /etc/libvirt/passwd.db u@ubuntu: userPassword Then I connect to server using tls and entering as the user u. Then I have the following message: Unable to connect to libvirt qemu+tls://u@192.168.246.135/system. authentication failed: authentication failed What are the correct steps to set up everything right. I just followed this: set up tls, set up user, modify config file, relaunch and connect.

1 0

[libvirt-users] Sasl + tls setup
by Anastasiya Ruzhanskaya 28 Nov '18

28 Nov '18

Hello everyone, I am trying to set up sasl authentication in virt-manager. I read in one existing bug, that it is better to use tls for encryption and sasl for authentication, but not use sasl for both. I configured tls, it was fine. Then I created a user "u" on server and modified libvirtd.conf. I set auth_tls = "sasl" there and mech_list: scram-sha-1 in sasl2 config for libvirt. The output of sasl: u@ubuntu2:~$ sudo sasldblistusers2 -f /etc/libvirt/passwd.db u@ubuntu: userPassword Then I connect to server using tls and entering as the user u. Then I have the following message: Unable to connect to libvirt qemu+tls://u@192.168.246.135/system. authentication failed: authentication failed What are the correct steps to set up everything right. I just followed this: set up tls, set up user, modify config file, relaunch and connect.

1 0

[libvirt-users] External Snapshots vs Core Dump.
by Tanmoy Sinha 26 Nov '18

26 Nov '18

Hi, I would like to get a clear picture on external snapshots memory dump ( i.e. system-checkpoint) vs dumping the memory of the guest. I have created external snapshots which produces a disk file and a memory file. I am not able to use this memory file in any memory analysis tools, for instance volatility. However, the memory dump taken through "virsh dump" works just fine with such tools. What am I missing here? The memory dump generated through external snapshot seems to be compressed, compared to the one generated by virsh dump. Can I specify the memory dump format in the snapshot XML? Was reading through a couple of old threads in libvirt-users, haven't found anything conclusive. If this is a redundant query, guide me me to the thread. Thanks, Tanmoy

2 3

[libvirt-users] lvm vs qcow (on NVMe)
by lejeczek 26 Nov '18

26 Nov '18

hi guys, anybody observed, maybe has measured performance difference between the two with qemu quests(windows OS)? Any conclusions, recommendations? many thanks, L.

3 2

[libvirt-users] Sasl authentication
by Anastasiya Ruzhanskaya 26 Nov '18

26 Nov '18

Hello everyone, I am trying to set up sasl authentication in virt-manager. I read in one existing bug, that it is better to use tls for encryption and sasl for authentication, but not use sasl for both. I configured tls, it was fine. Then I created a user "u" on server and modified libvirtd.conf. I set auth_tls = "sasl" there and mech_list: scram-sha-1 in sasl2 config for libvirt. The output of sasl: u@ubuntu2:~$ sudo sasldblistusers2 -f /etc/libvirt/passwd.db u@ubuntu: userPassword Then I connect to server using tls and entering as the user u. Then I have the following message: Unable to connect to libvirt qemu+tls://u@192.168.246.135/system. authentication failed: authentication failed What are the correct steps to set up everything right. I just followed this: set up tls, set up user, modify config file, relaunch and connect.

1 0

[libvirt-users] user information sent when using sasl or tls
by Anastasiya Ruzhanskaya 26 Nov '18

26 Nov '18

Hello everyone! I am trying without any success to decipher traffic from client to server in virt-manager in wireshark, but I don't know the sessioon key there, so seems no chance to do this. This is why I want to ask, is any info related to the certificate sent through the connection? Or if I use kerberos protocol for authentication, will the user id be sent in every message from client to server? Or only during authentication?

1 0

[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

[libvirt-users] virsh dominfo not returning any stats
by Tony Lin 09 Nov '18

09 Nov '18

Hi there, We're running virsh on centos and hit a couple of issues. First instance is cpu.time not incrementing even with the VMs on the hypervisor running a stress tool. After running 'virsh domstats' sometimes it'll go into a state where no output is generated at all. Have anyone seen something like this? We're running a pretty recent build of libvirt. # virsh versionCompiled against library: libvirt 3.9.0Using library: libvirt 3.9.0Using API: QEMU 3.9.0RUNNING HYPERVISOR: QEMU 2.9.0 Through the two domstats we see that the cpu.time is not increasing, but vcpu.0.time is not. It's also not reporting a vcpu.0.wait on this centos hypervisor. # virsh domstats Domain: '3a1de3d0-9de3-4876-a51a-1337d2ad0b87' state.state=1 state.reason=5 cpu.time=18530581887 cpu.user=430000000 cpu.system=2910000000 balloon.current=786432 balloon.maximum=786432 vcpu.current=1 vcpu.maximum=1 vcpu.0.state=1 vcpu.0.time=1145240000000 # virsh domstats Domain: '3a1de3d0-9de3-4876-a51a-1337d2ad0b87' state.state=1 state.reason=5 cpu.time=18530581887 cpu.user=430000000 cpu.system=2910000000 balloon.current=786432 balloon.maximum=786432 vcpu.current=1 vcpu.maximum=1 vcpu.0.state=1 vcpu.0.time=1153920000000

1 0

[libvirt-users] Getting two different guest in the same network
by Tjaco 08 Nov '18

08 Nov '18

Dear list, Being a libvirt noob, I have some trouble understanding. It is about getting two different guest in the same network. *********** I've defined a network with libvirt. This is the source xml: <network> <name>private2</name> <uuid>9684f2c6-6fd0-491b-9cb5-80ee268b01ce</uuid> <bridge name='br2' stp='on' delay='0'/> <mac address='52:54:00:b0:0a:c5'/> <ip address='10.0.0.1' netmask='255.255.255.0'> <dhcp> <range start='10.0.0.20' end='10.0.0.254'/> </dhcp> </ip> <ip family='ipv6' address='2001:db8:ca2:3::1' prefix='64'> </ip> </network> There is no 'forward' identifier so this should define an isolated network. br2 Was not pre-defined, it appeard after defining this network with libvirt. *********** ps aux shows: /usr/sbin/dnsmasq --conf-file=/var/lib/libvirt/dnsmasq/private2.conf *********** ip a shows: 11: br2: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc noqueue state UP group default qlen 1000 link/ether 52:54:00:b0:0a:c5 brd ff:ff:ff:ff:ff:ff inet 10.0.0.1/24 brd 10.0.0.255 scope global br2 valid_lft forever preferred_lft forever inet6 2001:db8:ca2:3::1/64 scope global valid_lft forever preferred_lft forever inet6 fe80::5054:ff:feb0:ac5/64 scope link valid_lft forever preferred_lft forever 12: br2-nic: <BROADCAST,MULTICAST> mtu 1500 qdisc fq_codel master br2 state DOWN group default qlen 1000 link/ether 52:54:00:b0:0a:c5 brd ff:ff:ff:ff:ff:ff *********** virsh net-list --all shows: Name State Autostart Persistent ---------------------------------------------------------- private2 active yes yes *********** Then I start two guests with different MAC-addresses and differt UUID's Both guests are set on DHCP. They share the same network config: <interface type='network'> <mac address='52:54:00:xx:xx:xx'/> <source network='private2'/> <model type='virtio'/> <address type='pci' domain='0x0000' bus='0x00' slot='0x03' function='0x0'/> </interface> Both guests take a lot of time to boot, waiting for network configuration. Then they end up having the same IP address, not able to communicate with each other. What am I missing? Your advise is much appreciated.

1 0