Bug 2224994

Summary:	Destroying VM takes more than 1 minute after vsock is hotplugged
Product:	[Fedora] Fedora	Reporter:	Simon Kobyda <skobyda>
Component:	libvirt	Assignee:	Libvirt Maintainers <libvirt-maint>
Status:	NEW ---	QA Contact:	Fedora Extras Quality Assurance <extras-qa>
Severity:	high	Docs Contact:
Priority:	unspecified
Version:	38	CC:	berrange, clalancette, crobinso, jforbes, laine, libvirt-maint, mpitt, virt-maint
Target Milestone:	---	Keywords:	Regression
Target Release:	---	Flags:	berrange: needinfo? (skobyda)
Hardware:	Unspecified
OS:	Linux
Whiteboard:	CockpitTest
Fixed In Version:		Doc Type:	If docs needed, set a value
Doc Text:		Story Points:	---
Clone Of:		Environment:
Last Closed:		Type:	---
Regression:	---	Mount Type:	---
Documentation:	---	CRM:
Verified Versions:		Category:	---
oVirt Team:	---	RHEL 7.3 requirements from Atomic Host:
Cloudforms Team:	---	Target Upstream Version:
Embargoed:

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