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:	CLOSED EOL	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:	---
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:	2024-05-28 13:34:43 UTC	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

Comment 2 Simon Kobyda 2023-10-12 13:21:03 UTC

(In reply to Daniel Berrangé from comment #1)
> 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

That doesn't seem related. We just run into this issue on fedora 40, where systemd version is 254 (254.5-2.fc40)
But the systemd bug https://bugzilla.redhat.com/show_bug.cgi?id=2213660 is fixed since 253.7-1 , so perhaps the root issue is somewhere else?

Comment 3 Aoife Moloney 2024-05-28 13:34:43 UTC

Fedora Linux 38 entered end-of-life (EOL) status on 2024-05-21.

Fedora Linux 38 is no longer maintained, which means that it
will not receive any further security or bug fix updates. As a result we
are closing this bug.

If you can reproduce this bug against a currently maintained version of Fedora Linux
please feel free to reopen this bug against that version. Note that the version
field may be hidden. Click the "Show advanced fields" button if you do not see
the version field.

If you are unable to reopen this bug, please file a new report against an
active release.

Thank you for reporting this bug and we are sorry it could not be fixed.