Bug 2224994 - Destroying VM takes more than 1 minute after vsock is hotplugged [NEEDINFO]
Summary: Destroying VM takes more than 1 minute after vsock is hotplugged
Keywords:
Status: NEW
Alias: None
Product: Fedora
Classification: Fedora
Component: libvirt
Version: 38
Hardware: Unspecified
OS: Linux
unspecified
high
Target Milestone: ---
Assignee: Libvirt Maintainers
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard: CockpitTest
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2023-07-24 08:11 UTC by Simon Kobyda
Modified: 2023-07-24 12:18 UTC (History)
8 users (show)

Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed:
Type: ---
Embargoed:
berrange: needinfo? (skobyda)


Attachments (Terms of Use)

Description Simon Kobyda 2023-07-24 08:11:33 UTC
Destroying VM takes > 1 minute after vsock is hotplugged

Versions:
$ virsh -v
9.0.0

$ qemu-kvm --version
QEMU emulator version 7.2.1 (qemu-7.2.1-2.fc38)

Reproducible: Always

Steps to Reproduce:
1. Have a running VM (in this case, we have "subVmTest1")
2. virt-xml subVmTest1 --add-device --vsock cid.auto=yes --update
3. time virsh destroy subVmTest1
Actual Results:  
Domain 'subVmTest1' destroyed

real    1m21.333s
user    0m0.029s
sys     0m0.028s

Expected Results:  
Destroying VM should take much less time

Also it seems like other libvirt functionalities are blocked, e.g. spawning "virsh list" in right after spawning "virsh destroy ..." will also take a long time:

[root@fedora-testing-127-0-0-2-2201 admin]# virsh destroy subVmTest1 &
[1] 2487
[root@fedora-testing-127-0-0-2-2201 admin]# time virsh list
 Id   Name         State
--------------------------------
 1    subVmTest1   in shutdown


real    0m29.029s
user    0m0.034s
sys     0m0.027s


And lastly, here are is the journal:

[root@fedora-testing-127-0-0-2-2201 admin]# journalctl -g libvirt
Jul 21 22:50:04 fedora-testing-127-0-0-2-2201 systemd[1]: Listening on virtinterfaced.socket - Libvirt interface local socket.
Jul 21 22:50:04 fedora-testing-127-0-0-2-2201 systemd[1]: Listening on virtnetworkd.socket - Libvirt network local socket.
Jul 21 22:50:04 fedora-testing-127-0-0-2-2201 systemd[1]: Listening on virtnodedevd.socket - Libvirt nodedev local socket.
Jul 21 22:50:04 fedora-testing-127-0-0-2-2201 systemd[1]: Listening on virtproxyd.socket - Libvirt proxy local socket.
Jul 21 22:50:04 fedora-testing-127-0-0-2-2201 systemd[1]: Listening on virtqemud.socket - Libvirt qemu local socket.
Jul 21 22:50:04 fedora-testing-127-0-0-2-2201 systemd[1]: Listening on virtqemud-admin.socket - Libvirt qemu admin socket.
Jul 21 22:50:04 fedora-testing-127-0-0-2-2201 systemd[1]: Listening on virtqemud-ro.socket - Libvirt qemu local read-only socket.
Jul 21 22:50:04 fedora-testing-127-0-0-2-2201 systemd[1]: Listening on virtstoraged.socket - Libvirt storage local socket.
Jul 21 22:50:08 fedora-testing-127-0-0-2-2201 systemd[1]: Closed virtinterfaced.socket - Libvirt interface local socket.
Jul 21 22:50:08 fedora-testing-127-0-0-2-2201 systemd[1]: Closed virtnetworkd.socket - Libvirt network local socket.
Jul 21 22:50:08 fedora-testing-127-0-0-2-2201 systemd[1]: Closed virtnodedevd.socket - Libvirt nodedev local socket.
Jul 21 22:50:08 fedora-testing-127-0-0-2-2201 systemd[1]: Closed virtproxyd.socket - Libvirt proxy local socket.
Jul 21 22:50:08 fedora-testing-127-0-0-2-2201 systemd[1]: Closed virtqemud-admin.socket - Libvirt qemu admin socket.
Jul 21 22:50:08 fedora-testing-127-0-0-2-2201 systemd[1]: Closed virtqemud-ro.socket - Libvirt qemu local read-only socket.
Jul 21 22:50:08 fedora-testing-127-0-0-2-2201 systemd[1]: Closed virtqemud.socket - Libvirt qemu local socket.
Jul 21 22:50:08 fedora-testing-127-0-0-2-2201 systemd[1]: Closed virtstoraged.socket - Libvirt storage local socket.
-- Boot 3e1676cae2de49309a9d3bec60158612 --
Jul 23 15:08:03 fedora-testing-127-0-0-2-2201 systemd[1]: Listening on virtinterfaced.socket - Libvirt interface local socket.
Jul 23 15:08:03 fedora-testing-127-0-0-2-2201 systemd[1]: Listening on virtnetworkd.socket - Libvirt network local socket.
Jul 23 15:08:03 fedora-testing-127-0-0-2-2201 systemd[1]: Listening on virtnodedevd.socket - Libvirt nodedev local socket.
Jul 23 15:08:03 fedora-testing-127-0-0-2-2201 systemd[1]: Listening on virtproxyd.socket - Libvirt proxy local socket.
Jul 23 15:08:03 fedora-testing-127-0-0-2-2201 systemd[1]: Listening on virtqemud.socket - Libvirt qemu local socket.
Jul 23 15:08:03 fedora-testing-127-0-0-2-2201 systemd[1]: Listening on virtqemud-admin.socket - Libvirt qemu admin socket.
Jul 23 15:08:03 fedora-testing-127-0-0-2-2201 systemd[1]: Listening on virtqemud-ro.socket - Libvirt qemu local read-only socket.
Jul 23 15:08:03 fedora-testing-127-0-0-2-2201 systemd[1]: Listening on virtstoraged.socket - Libvirt storage local socket.
Jul 23 15:08:19 fedora-testing-127-0-0-2-2201 systemd[1]: Closed virtinterfaced.socket - Libvirt interface local socket.
Jul 23 15:08:19 fedora-testing-127-0-0-2-2201 systemd[1]: Closed virtnetworkd.socket - Libvirt network local socket.
Jul 23 15:08:19 fedora-testing-127-0-0-2-2201 systemd[1]: Closed virtnodedevd.socket - Libvirt nodedev local socket.
Jul 23 15:08:19 fedora-testing-127-0-0-2-2201 systemd[1]: Closed virtproxyd.socket - Libvirt proxy local socket.
Jul 23 15:08:19 fedora-testing-127-0-0-2-2201 systemd[1]: Closed virtqemud-admin.socket - Libvirt qemu admin socket.
Jul 23 15:08:19 fedora-testing-127-0-0-2-2201 systemd[1]: Closed virtqemud-ro.socket - Libvirt qemu local read-only socket.
Jul 23 15:08:19 fedora-testing-127-0-0-2-2201 systemd[1]: Closed virtqemud.socket - Libvirt qemu local socket.
Jul 23 15:08:19 fedora-testing-127-0-0-2-2201 systemd[1]: Closed virtstoraged.socket - Libvirt storage local socket.
-- Boot 851cf98dc5c44826b7242b31e655d2f1 --
Jul 23 18:12:39 fedora-testing-127-0-0-2-2201 systemd[1]: Listening on virtinterfaced.socket - Libvirt interface local socket.
Jul 23 18:12:39 fedora-testing-127-0-0-2-2201 systemd[1]: Listening on virtnetworkd.socket - Libvirt network local socket.
Jul 23 18:12:39 fedora-testing-127-0-0-2-2201 systemd[1]: Listening on virtnodedevd.socket - Libvirt nodedev local socket.
Jul 23 18:12:39 fedora-testing-127-0-0-2-2201 systemd[1]: Listening on virtproxyd.socket - Libvirt proxy local socket.
Jul 23 18:12:39 fedora-testing-127-0-0-2-2201 systemd[1]: Listening on virtqemud.socket - Libvirt qemu local socket.
Jul 23 18:12:39 fedora-testing-127-0-0-2-2201 systemd[1]: Listening on virtqemud-admin.socket - Libvirt qemu admin socket.
Jul 23 18:12:39 fedora-testing-127-0-0-2-2201 systemd[1]: Listening on virtqemud-ro.socket - Libvirt qemu local read-only socket.
Jul 23 18:12:39 fedora-testing-127-0-0-2-2201 systemd[1]: Listening on virtstoraged.socket - Libvirt storage local socket.
Jul 23 18:12:48 fedora-testing-127-0-0-2-2201 systemd[1]: Listening on virtnetworkd-admin.socket - Libvirt network admin socket.
Jul 23 18:12:48 fedora-testing-127-0-0-2-2201 systemd[1]: Listening on virtnetworkd-ro.socket - Libvirt network local read-only socket.
Jul 23 18:12:48 fedora-testing-127-0-0-2-2201 dnsmasq[1638]: read /var/lib/libvirt/dnsmasq/default.addnhosts - 0 names
Jul 23 18:12:48 fedora-testing-127-0-0-2-2201 dnsmasq-dhcp[1638]: read /var/lib/libvirt/dnsmasq/default.hostsfile
Jul 23 18:12:48 fedora-testing-127-0-0-2-2201 virtnetworkd[1538]: libvirt version: 9.0.0, package: 3.fc38 (Fedora Project, 2023-05-07-17:31:32, )
Jul 23 18:12:48 fedora-testing-127-0-0-2-2201 virtqemud[677]: libvirt version: 9.0.0, package: 3.fc38 (Fedora Project, 2023-05-07-17:31:32, )
Jul 23 18:12:49 fedora-testing-127-0-0-2-2201 dnsmasq[1638]: read /var/lib/libvirt/dnsmasq/default.addnhosts - 0 names
Jul 23 18:12:49 fedora-testing-127-0-0-2-2201 dnsmasq-dhcp[1638]: read /var/lib/libvirt/dnsmasq/default.hostsfile
Jul 23 18:12:51 fedora-testing-127-0-0-2-2201 systemd[1]: Listening on virtstoraged-admin.socket - Libvirt storage admin socket.
Jul 23 18:12:51 fedora-testing-127-0-0-2-2201 systemd[1]: Listening on virtstoraged-ro.socket - Libvirt storage local read-only socket.
Jul 23 18:12:58 fedora-testing-127-0-0-2-2201 systemd[2009]: Created slice app-dbus\x2d:1.2\x2dorg.libvirt.slice - Slice /app/dbus-:1.2-org.libvirt.
Jul 23 18:12:58 fedora-testing-127-0-0-2-2201 systemd[2009]: Started dbus-:1.2-org.libvirt.
Jul 23 18:12:58 fedora-testing-127-0-0-2-2201 virtqemud[2076]: libvirt version: 9.0.0, package: 3.fc38 (Fedora Project, 2023-05-07-17:31:32, )
Jul 23 18:12:58 fedora-testing-127-0-0-2-2201 systemd[1]: Created slice system-dbus\x2d:1.4\x2dorg.libvirt.slice - Slice /system/dbus-:1.4-org.libvirt.
Jul 23 18:12:58 fedora-testing-127-0-0-2-2201 systemd[1]: Started dbus-:1.4-org.libvirt.
Jul 23 18:12:58 fedora-testing-127-0-0-2-2201 audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=dbus-:1.4-org.libvirt@0 com>
Jul 23 18:12:58 fedora-testing-127-0-0-2-2201 systemd[1]: Listening on virtnodedevd-admin.socket - Libvirt nodedev admin socket.
Jul 23 18:12:58 fedora-testing-127-0-0-2-2201 systemd[1]: Listening on virtnodedevd-ro.socket - Libvirt nodedev local read-only socket.
Jul 23 18:12:59 fedora-testing-127-0-0-2-2201 virtqemud[677]: Failed to connect socket to '/var/run/libvirt/virtsecretd-sock': No such file or directory
Jul 23 18:12:59 fedora-testing-127-0-0-2-2201 systemd[1]: Listening on virtinterfaced-admin.socket - Libvirt interface admin socket.
Jul 23 18:12:59 fedora-testing-127-0-0-2-2201 systemd[1]: Listening on virtinterfaced-ro.socket - Libvirt interface local read-only socket.
Jul 23 18:13:04 fedora-testing-127-0-0-2-2201 virtqemud[2076]: Failed to connect socket to '/run/user/1000/libvirt/virtsecretd-sock': No such file or directory
Jul 23 18:13:20 fedora-testing-127-0-0-2-2201 virtlogd[2324]: libvirt version: 9.0.0, package: 3.fc38 (Fedora Project, 2023-05-07-17:31:32, )
Jul 23 18:13:21 fedora-testing-127-0-0-2-2201 audit[677]: VIRT_RESOURCE pid=677 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:virtd_t:s0-s0:c0.c1023 msg='virt=qemu resrc>
Jul 23 18:13:21 fedora-testing-127-0-0-2-2201 audit[677]: VIRT_RESOURCE pid=677 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:virtd_t:s0-s0:c0.c1023 msg='virt=qemu resrc>
Jul 23 18:13:21 fedora-testing-127-0-0-2-2201 audit[677]: VIRT_RESOURCE pid=677 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:virtd_t:s0-s0:c0.c1023 msg='virt=qemu resrc>
Jul 23 18:14:57 fedora-testing-127-0-0-2-2201 virtqemud[677]: Unable to remove /sys/fs/cgroup/machine.slice/machine-qemu\x2d1\x2dsubVmTest1.scope//libvirt/emulator (16)
Jul 23 18:14:57 fedora-testing-127-0-0-2-2201 virtqemud[677]: Unable to remove /sys/fs/cgroup/machine.slice/machine-qemu\x2d1\x2dsubVmTest1.scope//libvirt (16)
Jul 23 18:14:57 fedora-testing-127-0-0-2-2201 virtqemud[677]: Unable to remove /sys/fs/cgroup/machine.slice/machine-qemu\x2d1\x2dsubVmTest1.scope//libvirt/emulator (16)
Jul 23 18:14:57 fedora-testing-127-0-0-2-2201 virtqemud[677]: Unable to remove /sys/fs/cgroup/machine.slice/machine-qemu\x2d1\x2dsubVmTest1.scope//libvirt (16)
Jul 23 18:14:58 fedora-testing-127-0-0-2-2201 virtqemud[677]: Unable to remove /sys/fs/cgroup/machine.slice/machine-qemu\x2d1\x2dsubVmTest1.scope//libvirt/emulator (16)
Jul 23 18:14:58 fedora-testing-127-0-0-2-2201 virtqemud[677]: Unable to remove /sys/fs/cgroup/machine.slice/machine-qemu\x2d1\x2dsubVmTest1.scope//libvirt (16)
Jul 23 18:14:58 fedora-testing-127-0-0-2-2201 virtqemud[677]: Unable to remove /sys/fs/cgroup/machine.slice/machine-qemu\x2d1\x2dsubVmTest1.scope//libvirt/emulator (16)
Jul 23 18:14:58 fedora-testing-127-0-0-2-2201 virtqemud[677]: Unable to remove /sys/fs/cgroup/machine.slice/machine-qemu\x2d1\x2dsubVmTest1.scope//libvirt (16)
Jul 23 18:14:58 fedora-testing-127-0-0-2-2201 virtqemud[677]: Unable to remove /sys/fs/cgroup/machine.slice/machine-qemu\x2d1\x2dsubVmTest1.scope//libvirt/emulator (16)
Jul 23 18:14:58 fedora-testing-127-0-0-2-2201 virtqemud[677]: Unable to remove /sys/fs/cgroup/machine.slice/machine-qemu\x2d1\x2dsubVmTest1.scope//libvirt (16)
Jul 23 18:14:58 fedora-testing-127-0-0-2-2201 virtqemud[677]: Unable to remove /sys/fs/cgroup/machine.slice/machine-qemu\x2d1\x2dsubVmTest1.scope//libvirt/emulator (16)
Jul 23 18:14:58 fedora-testing-127-0-0-2-2201 virtqemud[677]: Unable to remove /sys/fs/cgroup/machine.slice/machine-qemu\x2d1\x2dsubVmTest1.scope//libvirt (16)

Comment 1 Daniel Berrangé 2023-07-24 12:18:42 UTC
There was a recent regression in systemd causing service shutdown issues, so please check you have the systemd fix mentioned here installed: https://bugzilla.redhat.com/show_bug.cgi?id=2213660


Note You need to log in before you can comment on or make changes to this bug.