Note: This is a public test instance of Red Hat Bugzilla. The data contained within is a snapshot of the live data so any changes you make will not be reflected in the production Bugzilla. Email is disabled so feel free to test any aspect of the site that you want. File any problems you find or give feedback at bugzilla.redhat.com.
Bug 1813667 - shutdown of a VM system takes 90 seconds longer due to spice-vdagentd.service
Summary: shutdown of a VM system takes 90 seconds longer due to spice-vdagentd.service
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Fedora
Classification: Fedora
Component: spice-vdagent
Version: 32
Hardware: Unspecified
OS: Unspecified
unspecified
medium
Target Milestone: ---
Assignee: Christophe Fergeau
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard: https://fedoraproject.org/wiki/Common...
: 1814758 (view as bug list)
Depends On:
Blocks: F32FinalFreezeException
TreeView+ depends on / blocked
 
Reported: 2020-03-15 10:59 UTC by Ed Greshko
Modified: 2020-04-04 03:22 UTC (History)
11 users (show)

Fixed In Version: spice-vdagent-0.20.0-2.fc32 spice-vdagent-0.20.0-2.fc31
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2020-03-28 00:15:25 UTC
Type: Bug
Embargoed:
kparal: fedora_prioritized_bug?

Attachments (Terms of Use)
system shutdown screenshot (19.20 KB, image/png)
2020-03-16 17:17 UTC, Kamil Páral 		no flags Details
View All

Description Ed Greshko 2020-03-15 10:59:22 UTC 
Description of problem: When shutting down a guest it takes an additional 1 minute and 30 seconds due to spice-vdagentd.


Version-Release number of selected component (if applicable): spice-vdagent-0.20.0-1.fc32


How reproducible: Just shutdown the gues


Steps to Reproduce:
1.
2.
3.

Actual results:


Expected results:


Additional info: downgrading to spice-vdagent-0.19.0-5.fc32 fixes the problem.
The relevant journal entries are

Mar 15 16:46:25 f32k.greshko.com systemd[1]: spice-vdagentd.service: State 'stop-sigterm' timed out. Killing.
Mar 15 16:46:25 f32k.greshko.com systemd[1]: spice-vdagentd.service: Killing process 1146 (spice-vdagentd) with signal SIGKILL.
Mar 15 16:46:25 f32k.greshko.com systemd[1]: spice-vdagentd.service: Main process exited, code=killed, status=9/KILL
Mar 15 16:46:25 f32k.greshko.com systemd[1]: spice-vdagentd.service: Failed with result 'timeout'.
Mar 15 16:46:25 f32k.greshko.com systemd[1]: Stopped Agent daemon for Spice guests.
Mar 15 16:46:25 f32k.greshko.com audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=spice-vdagentd comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=failed'
Mar 15 16:46:25 f32k.greshko.com systemd[1]: Stopped target Basic System.
Comment 1 Ed Greshko 2020-03-16 00:50:36 UTC 
I should have also added that the qemu/kvm VM is running on an F31 system.

Simply booting and then shutting down the VM with the newer version of spice-vdagent will demonstrate the problem.
Comment 2 Kamil Páral 2020-03-16 16:24:25 UTC 
I can confirm this with a clean install of F32 Beta Workstation into a libvirt VM. Every system shutdown is delayed by 90 seconds due to spice-vdagent (see screenshot). It's not just during system shutdown, each stopping of the service takes 90 seconds (times out). Also "dnf downgrade spice-vdagent" takes +90 seconds.

$ sudo systemctl status spice-vdagentd
● spice-vdagentd.service - Agent daemon for Spice guests
     Loaded: loaded (/usr/lib/systemd/system/spice-vdagentd.service; indirect; vendor preset: enabled)
     Active: active (running) since Mon 2020-03-16 17:00:11 CET; 30s ago
TriggeredBy: ● spice-vdagentd.socket
    Process: 1123 ExecStart=/usr/sbin/spice-vdagentd $SPICE_VDAGENTD_EXTRA_ARGS (code=exited, status=0/SUCCESS)
   Main PID: 1131 (spice-vdagentd)
      Tasks: 1 (limit: 3451)
     Memory: 1.1M
        CPU: 21ms
     CGroup: /system.slice/spice-vdagentd.service
             └─1131 /usr/sbin/spice-vdagentd

Mar 16 17:00:11 f32 systemd[1]: Starting Agent daemon for Spice guests...
Mar 16 17:00:11 f32 systemd[1]: Started Agent daemon for Spice guests.
Mar 16 17:00:13 f32 spice-vdagentd[1131]: opening vdagent virtio channel
Mar 16 17:00:13 f32 spice-vdagentd[1131]: Set max clipboard: 104857600
Mar 16 17:00:13 f32 spice-vdagentd[1131]: Set max clipboard: 104857600

$ time sudo systemctl stop spice-vdagentd
Warning: Stopping spice-vdagentd.service, but it can still be activated by:
  spice-vdagentd.socket

real	1m30.218s
user	0m0.021s
sys	0m0.019s

$ time sudo systemctl start spice-vdagentd

real	0m1.565s
user	0m0.041s
sys	0m0.041s

$ sudo systemctl status spice-vdagentd
● spice-vdagentd.service - Agent daemon for Spice guests
     Loaded: loaded (/usr/lib/systemd/system/spice-vdagentd.service; indirect; vendor preset: enabled)
     Active: active (running) since Mon 2020-03-16 17:02:19 CET; 16min ago
TriggeredBy: ● spice-vdagentd.socket
    Process: 1747 ExecStart=/usr/sbin/spice-vdagentd $SPICE_VDAGENTD_EXTRA_ARGS (code=exited, status=0/SUCCESS)
   Main PID: 1751 (spice-vdagentd)
      Tasks: 1 (limit: 3451)
     Memory: 964.0K
        CPU: 16ms
     CGroup: /system.slice/spice-vdagentd.service
             └─1751 /usr/sbin/spice-vdagentd

Mar 16 17:02:19 f32 systemd[1]: Starting Agent daemon for Spice guests...
Mar 16 17:02:19 f32 systemd[1]: Started Agent daemon for Spice guests.
Mar 16 17:02:19 f32 spice-vdagentd[1751]: opening vdagent virtio channel
Mar 16 17:02:19 f32 spice-vdagentd[1751]: Set max clipboard: 104857600
Mar 16 17:02:19 f32 spice-vdagentd[1751]: Set max clipboard: 104857600
[kparal@f32 ~]$ sudo systemctl status spice-vdagentd
● spice-vdagentd.service - Agent daemon for Spice guests
     Loaded: loaded (/usr/lib/systemd/system/spice-vdagentd.service; indirect; vendor preset: enabled)
     Active: active (running) since Mon 2020-03-16 17:00:11 CET; 30s ago
TriggeredBy: ● spice-vdagentd.socket
    Process: 1123 ExecStart=/usr/sbin/spice-vdagentd $SPICE_VDAGENTD_EXTRA_ARGS (code=exited, status=0/SUCCESS)
   Main PID: 1131 (spice-vdagentd)
      Tasks: 1 (limit: 3451)
     Memory: 1.1M
        CPU: 21ms
     CGroup: /system.slice/spice-vdagentd.service
             └─1131 /usr/sbin/spice-vdagentd

Mar 16 17:00:11 f32 systemd[1]: Starting Agent daemon for Spice guests...
Mar 16 17:00:11 f32 systemd[1]: Started Agent daemon for Spice guests.
Mar 16 17:00:13 f32 spice-vdagentd[1131]: opening vdagent virtio channel
Mar 16 17:00:13 f32 spice-vdagentd[1131]: Set max clipboard: 104857600
Mar 16 17:00:13 f32 spice-vdagentd[1131]: Set max clipboard: 104857600
[kparal@f32 ~]$ time sudo systemctl stop spice-vdagentd
Warning: Stopping spice-vdagentd.service, but it can still be activated by:
  spice-vdagentd.socket

real	1m30.218s
user	0m0.021s
sys	0m0.019s
[kparal@f32 ~]$ time sudo systemctl start spice-vdagentd
[sudo] password for kparal: 

real	0m1.565s
user	0m0.041s
sys	0m0.041s
[kparal@f32 ~]$ time sudo systemctl status spice-vdagentd
● spice-vdagentd.service - Agent daemon for Spice guests
     Loaded: loaded (/usr/lib/systemd/system/spice-vdagentd.service; indirect; vendor preset: enabled)
     Active: active (running) since Mon 2020-03-16 17:02:19 CET; 16min ago
TriggeredBy: ● spice-vdagentd.socket
    Process: 1747 ExecStart=/usr/sbin/spice-vdagentd $SPICE_VDAGENTD_EXTRA_ARGS (code=exited, status=0/SUCCESS)
   Main PID: 1751 (spice-vdagentd)
      Tasks: 1 (limit: 3451)
     Memory: 964.0K
        CPU: 16ms
     CGroup: /system.slice/spice-vdagentd.service
             └─1751 /usr/sbin/spice-vdagentd

Mar 16 17:02:19 f32 systemd[1]: Starting Agent daemon for Spice guests...
Mar 16 17:02:19 f32 systemd[1]: Started Agent daemon for Spice guests.
Mar 16 17:02:19 f32 spice-vdagentd[1751]: opening vdagent virtio channel
Mar 16 17:02:19 f32 spice-vdagentd[1751]: Set max clipboard: 104857600
Mar 16 17:02:19 f32 spice-vdagentd[1751]: Set max clipboard: 104857600

$ time sudo systemctl stop spice-vdagentd
Warning: Stopping spice-vdagentd.service, but it can still be activated by:
  spice-vdagentd.socket

real	1m30.207s
user	0m0.020s
sys	0m0.019s



It doesn't happen with spice-vdagent-0.19.0-5.fc32.x86_64 inside the VM.


F32 host:
qemu-ui-spice-app-4.2.0-5.fc32.x86_64
spice-glib-0.37-6.fc32.x86_64
spice-gtk3-0.37-6.fc32.x86_64
spice-server-0.14.3-1.fc32.x86_64
spice-vdagent-0.20.0-1.fc32.x86_64

F32 guest:
qemu-ui-spice-app-4.2.0-5.fc32.x86_64
spice-glib-0.37-6.fc32.x86_64
spice-gtk3-0.37-6.fc32.x86_64
spice-server-0.14.3-1.fc32.x86_64
spice-vdagent-0.20.0-1.fc32.x86_64
Comment 3 Kamil Páral 2020-03-16 16:26:20 UTC 
Eh, the terminal log got copied twice over and intermingled (sorry), but you get the gist. Starting the service is immediate, no problem is reported, but shutting it down takes 90 seconds.
Comment 4 Kamil Páral 2020-03-16 17:17:44 UTC 
Created attachment 1670611 [details]
system shutdown screenshot
Comment 5 Chris Murphy 2020-03-16 17:52:58 UTC 
Yep, I'm seeing this in virt-manager VM's as well. Not on baremetal.
Comment 6 Kamil Páral 2020-03-17 08:20:23 UTC 
We've failed to stop https://bodhi.fedoraproject.org/updates/FEDORA-2020-6ff500948d from reaching stable updates :-/

Proposing as a Prioritized Bug. This is a very bad experience for anyone using F32 in VMs.
Comment 7 Kamil Páral 2020-03-20 11:22:18 UTC 
Christophe, any chance you can look into this soon, or revert to the previous version?
Comment 8 Steve 2020-03-23 13:41:56 UTC 
As a workaround, you can install the previous version. Unfortunately, it is not in an F32 repo, so:

$ dnf repoquery spice-vdagent --releasever=31 --location
$ wget http://path.to.mirror
# dnf downgrade spice-vdagent-0.19.0-4.fc31.x86_64.rpm

NB: dnf will appear to stall while systemctl attempts to kill the running spice-vdagentd. You can "watch" from another terminal tab:

$ ps -ef | grep spice

Tested in an F32 VM.
Comment 9 Victor Toso 2020-03-23 13:59:49 UTC 
Thanks for the report, we are working on a fix for this upstream:

issue: https://gitlab.freedesktop.org/spice/linux/vd_agent/issues/18

current merge request: https://gitlab.freedesktop.org/spice/linux/vd_agent/-/merge_requests/7

As soon as a fix is merged, I'll make new builds.
Comment 10 Victor Toso 2020-03-23 14:00:22 UTC 
*** Bug 1814758 has been marked as a duplicate of this bug. ***
Comment 11 Kamil Páral 2020-03-25 17:07:53 UTC 
Awesome, thanks Victor. It would be great if you could make it before the final version of Fedora 32, so that the problem is not embedded in F32 Live images forever.

Nominating for a freeze exception.
Comment 12 Fedora Update System 2020-03-26 17:45:31 UTC 
FEDORA-2020-45698e4ed9 has been submitted as an update to Fedora 32. https://bodhi.fedoraproject.org/updates/FEDORA-2020-45698e4ed9
Comment 13 Ed Greshko 2020-03-26 23:32:39 UTC 
Fix Verified and Karma Given
Comment 14 Kamil Páral 2020-03-27 09:07:27 UTC 
(In reply to Fedora Update System from comment #12)
> FEDORA-2020-45698e4ed9 has been submitted as an update to Fedora 32.
> https://bodhi.fedoraproject.org/updates/FEDORA-2020-45698e4ed9

Awesome, thank you. The service now exits properly.
Comment 15 Fedora Update System 2020-03-27 15:58:33 UTC 
FEDORA-2020-45698e4ed9 has been pushed to the Fedora 32 testing repository.
In short time you'll be able to install the update with the following command:
`sudo dnf upgrade --enablerepo=updates-testing --advisory=FEDORA-2020-45698e4ed9`
You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-2020-45698e4ed9

See also https://fedoraproject.org/wiki/QA:Updates_Testing for more information on how to test updates.
Comment 16 Fedora Update System 2020-03-27 19:12:22 UTC 
FEDORA-2020-8c234611fd has been pushed to the Fedora 31 testing repository.
In short time you'll be able to install the update with the following command:
`sudo dnf upgrade --enablerepo=updates-testing --advisory=FEDORA-2020-8c234611fd`
You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-2020-8c234611fd

See also https://fedoraproject.org/wiki/QA:Updates_Testing for more information on how to test updates.
Comment 17 Fedora Update System 2020-03-28 00:15:25 UTC 
FEDORA-2020-45698e4ed9 has been pushed to the Fedora 32 stable repository.
If problem still persists, please make note of it in this bug report.
Comment 18 Fedora Update System 2020-04-04 03:22:00 UTC 
FEDORA-2020-8c234611fd has been pushed to the Fedora 31 stable repository.
If problem still persists, please make note of it in this bug report.
Note You need to log in before you can comment on or make changes to this bug.