[libvirt-users] can't find how to solve "QEMU guest agent is not connected"

Tue Apr 17 10:54:14 UTC 2018

I am trying to make Qemu agent work with libvirt thanks to
https://github.com/NixOS/nixops/pull/922 with libvirt 4.1.0. I've been
trying to make it work for quite some time but I still haven't the
slightest idea of what is wrong, I keep seeing "Guest agent is not
responding: QEMU guest agent is not connected" as the program I use
(nixops) calls the libvirt python API.

I apologize in advance for dropping so many details but in case
someone is interested in answering this post, I thought I would
provide details upfront.

The failure surprises me as typically a socket is created when I start
the VM with a priori the correct rights myuser:libvirtd (libvirtd is
the default libvirt group on nixos, different from upstream IIRC):
/var/lib/libvirt/qemu/channel/target/domain-10-nixops-3cb2c9c2-41ea/org.qemu.guest_agent.0

My domain contains
```
    <channel type='unix'>
      <target type='virtio' name='org.qemu.guest_agent.0'/>
      <address type='virtio-serial' controller='0' bus='0' port='1'/>
    </channel>
```
as requested per the doc (I tried with source=bind to no avail, btw
the doc for `source` is not that great)

my libvirtd.conf has the following setting

```
      log_level = 1
      # no filter for now
      log_filters="1:qemu.qemu_agent 1:qemu.qemu_monitor"
      # log_filters="3:remote 4:event 3:json 3:rpc"
      log_outputs="1:file:/var/log/libvirt/libvirtd.log"
```

`journalctl -b -u libvirtd.service` returns

```
avril 17 12:31:05 jedha libvirtd[22804]: 2018-04-17 03:31:05.482+0000:
22806: error : qemuDomainAgentAvailable:7755 : Guest agent is not
responding: QEMU guest agent is not connected
avril 17 12:31:06 jedha libvirtd[22804]: 2018-04-17 03:31:06.487+0000:
22807: error : qemuDomainAgentAvailable:7755 : Guest agent is not
responding: QEMU guest agent is not connected
avril 17 12:31:07 jedha libvirtd[22804]: 2018-04-17 03:31:07.493+0000:
22805: error : qemuDomainAgentAvailable:7755 : Guest agent is not
responding: QEMU guest agent is not connected
avril 17 12:31:08 jedha libvirtd[22804]: 2018-04-17 03:31:08.499+0000:
22809: error : qemuDomainAgentAvailable:7755 : Guest agent is not
responding: QEMU guest agent is not connected
avril 17 12:31:09 jedha libvirtd[22804]: 2018-04-17 03:31:09.506+0000:
22808: error : qemuDomainAgentAvailable:7755 : Guest agent is not
responding: QEMU guest agent is not connected
avril 17 12:31:10 jedha libvirtd[22804]: 2018-04-17 03:31:10.513+0000:
22806: error : qemuDomainAgentAvailable:7755 : Guest agent is not
responding: QEMU guest agent is not connected
avril 17 12:31:11 jedha libvirtd[22804]: 2018-04-17 03:31:11.512+0000:
22804: error : virNetSocketReadWire:1809 : End of file while reading
data: Input/output error
```

Here is an excerpt just before the error "GUest agent is not
connected" (full log of 82MB available at
https://drive.google.com/file/d/1sYpyJ2WQMlyFqNKkPkvSAJ13Tm2JjpVk/view?usp=sharing)
```
2018-04-17 03:56:41.982+0000: 806: debug : virEventPollMakePollFDs:401
: Prepare n=5 w=6, f=12 e=1 d=0
2018-04-17 03:56:41.983+0000: 806: debug : virEventPollMakePollFDs:401
: Prepare n=6 w=7, f=13 e=1 d=0
2018-04-17 03:56:41.983+0000: 806: debug : virEventPollMakePollFDs:401
: Prepare n=7 w=8, f=15 e=1 d=0
2018-04-17 03:56:41.983+0000: 807: debug :
virAccessManagerCheckDomain:234 : manager=0x55fa67d0d450(name=stack)
driver=QEMU domain=0x7f2c5800c040 perm=1
2018-04-17 03:56:41.983+0000: 806: debug : virEventPollMakePollFDs:401
: Prepare n=8 w=9, f=17 e=25 d=0
2018-04-17 03:56:41.983+0000: 807: debug :
virAccessManagerCheckDomain:234 : manager=0x55fa67d0d6f0(name=none)
driver=QEMU domain=0x7f2c5800c040 perm=1
2018-04-17 03:56:41.983+0000: 806: debug : virEventPollMakePollFDs:401
: Prepare n=9 w=10, f=18 e=1 d=0
2018-04-17 03:56:41.983+0000: 807: info : virObjectUnref:350 :
OBJECT_UNREF: obj=0x55fa67d0d450
2018-04-17 03:56:41.983+0000: 806: debug : virEventPollMakePollFDs:401
: Prepare n=10 w=11, f=19 e=1 d=0
2018-04-17 03:56:41.983+0000: 807: info : virObjectRef:388 :
OBJECT_REF: obj=0x7f2c14026460
2018-04-17 03:56:41.983+0000: 806: debug : virEventPollMakePollFDs:401
: Prepare n=11 w=13, f=23 e=25 d=0
2018-04-17 03:56:41.983+0000: 807: debug :
qemuDomainObjBeginJobInternal:5393 : Starting job: query
(vm=0x7f2c58004770
name=nixops-4f58a5c0-41f3-11e8-9858-309c233b770e-server, current
job=none async=none)
2018-04-17 03:56:41.983+0000: 806: debug :
virEventPollCalculateTimeout:338 : Calculate expiry of 1 timers
2018-04-17 03:56:41.983+0000: 807: debug :
qemuDomainObjBeginJobInternal:5434 : Started job: query (async=none
vm=0x7f2c58004770
name=nixops-4f58a5c0-41f3-11e8-9858-309c233b770e-server)
2018-04-17 03:56:41.983+0000: 806: debug :
virEventPollCalculateTimeout:371 : No timeout is pending
2018-04-17 03:56:41.983+0000: 807: info : virObjectUnref:350 :
OBJECT_UNREF: obj=0x7f2c14026460
2018-04-17 03:56:41.983+0000: 806: info : virEventPollRunOnce:640 :
EVENT_POLL_RUN: nhandles=12 timeout=-1
2018-04-17 03:56:41.983+0000: 807: error :
qemuDomainAgentAvailable:7755 : Guest agent is not responding: QEMU
guest agent is not connected
```

This is the VM log from a machine similar to the one in the previous
messages (same config)
```
2018-04-16 08:28:47.875+0000: starting up libvirt version: 4.1.0, qemu
version: 2.11.1, hostname: jedha
LC_ALL=C PATH=/run/libvirt/nix-emulators:/nix/store/f8hxcp939qwpiwzm6999gljdkd2kzg6v-iptables-1.6.2/bin:/nix/store/fs4p0aw14snppfcjrzmiic52sjc3z627-iproute2-4.15.0/bin:/nix/store/bbrlfy430b48fywf7rgk4x1qxrpm695j-pm-utils-1.4.1/bin:/nix/store/waj4yidjf59mknpkcd99pdp0wf1x5gs7-numad-0.5/bin:/nix/store/hz5x8d3nlqvkv63mkxajblp9pkawlwvq-numactl-2.0.11/bin:/nix/store/pj5iq5sdhc3f8v6ysyxssm039jrkxmcl-bridge-utils-1.5/bin:/nix/store/bkrl7mxmzn0whm1n29dhyhdhlgkv0m8c-dmidecode-3.1/bin:/nix/store/h6x6i584ihp1qvk19vvyk5gqjznxk6bp-dnsmasq-2.78/bin:/nix/store/xvnsxcsq2ca3cs7z4952jdjid48ql32c-ebtables-2.0.10-4/bin:/nix/store/j7x4cjlfrdhagmciqk5zc58g1icg91rb-qemu-2.11.1/bin:/nix/store/qrxs7sabhqcr3j9ai0j0cp58zfnny0jz-coreutils-8.29/bin:/nix/store/3ixa5cn578zz4pr81a0rdkbi4dal748a-findutils-4.6.0/bin:/nix/store/xd4m1v7q7kn902p8hvnfn79c2wjijlif-gnugrep-3.1/bin:/nix/store/r0wkp0vkw6wjfl0skmdpykabgj1bkyn2-gnused-4.4/bin:/nix/store/aw6jabbci1k81j6hvyskkhb3va45wws2-systemd-237/bin:/nix/store/j7x4cjlfrdhagmciqk5zc58g1icg91rb-qemu-2.11.1/sbin:/nix/store/qrxs7sabhqcr3j9ai0j0cp58zfnny0jz-coreutils-8.29/sbin:/nix/store/3ixa5cn578zz4pr81a0rdkbi4dal748a-findutils-4.6.0/sbin:/nix/store/xd4m1v7q7kn902p8hvnfn79c2wjijlif-gnugrep-3.1/sbin:/nix/store/r0wkp0vkw6wjfl0skmdpykabgj1bkyn2-gnused-4.4/sbin:/nix/store/aw6jabbci1k81j6hvyskkhb3va45wws2-systemd-237/sbin
QEMU_AUDIO_DRV=none /run/libvirt/nix-emulators/qemu-kvm -name
guest=nixops-0084610a-4150-11e8-aef5-309c233b770e-server,debug-threads=on
-S -object secret,id=masterKey0,format=raw,file=/var/lib/libvirt/qemu/domain-7-nixops-0084610a-4150/master-key.aes
-machine pc-i440fx-2.11,accel=kvm,usb=off,dump-guest-core=off -m 512
-realtime mlock=off -smp 1,sockets=1,cores=1,threads=1 -uuid
ad67fc0b-d93d-455d-a6e6-5549451e08ac -display none -no-user-config
-nodefaults -chardev
socket,id=charmonitor,path=/var/lib/libvirt/qemu/domain-7-nixops-0084610a-4150/monitor.sock,server,nowait
-mon chardev=charmonitor,id=monitor,mode=control -rtc base=utc
-no-shutdown -no-acpi -boot strict=on -device
piix3-usb-uhci,id=usb,bus=pci.0,addr=0x1.0x2 -device
virtio-serial-pci,id=virtio-serial0,bus=pci.0,addr=0x3 -drive
file=/var/lib/libvirt/images/nixops-0084610a-4150-11e8-aef5-309c233b770e-server.qcow2,format=qcow2,if=none,id=drive-ide0-0-0
-device ide-hd,bus=ide.0,unit=0,drive=drive-ide0-0-0,id=ide0-0-0,bootindex=1
-netdev tap,fd=21,id=hostnet0 -device
rtl8139,netdev=hostnet0,id=net0,mac=52:54:00:84:7f:ee,bus=pci.0,addr=0x2
-chardev pty,id=charserial0 -device
isa-serial,chardev=charserial0,id=serial0 -chardev
socket,id=charchannel0,path=/var/lib/libvirt/qemu/channel/target/domain-7-nixops-0084610a-4150/org.qemu.guest_agent.0,server,nowait
-device virtserialport,bus=virtio-serial0.0,nr=1,chardev=charchannel0,id=channel0,name=org.qemu.guest_agent.0
-device usb-kbd,id=input0,bus=usb.0,port=1 -device
usb-mouse,id=input1,bus=usb.0,port=2 -device
virtio-balloon-pci,id=balloon0,bus=pci.0,addr=0x4 -msg timestamp=on
2018-04-16T08:28:47.931670Z qemu-system-x86_64: -chardev
pty,id=charserial0: char device redirected to /dev/pts/4 (label
charserial0)
2018-04-16T08:32:04.730417Z qemu-system-x86_64: terminating on signal
15 from pid 1211
(/nix/store/ggqq9v3h5w66gnzbg3wg74s0ad7m0rjk-libvirt-4.1.0/sbin/libvirtd)
2018-04-16 08:32:04.931+0000: shutting down, reason=destroyed
```
Let me know what I can do to diagnose the error, or if any additionnal
details would help. I will happily provide them.

Best regards
Matt