Bug 1583261 - vdagent processes don't get cleaned up on logout
Summary: vdagent processes don't get cleaned up on logout
Keywords:
Status: CLOSED NOTABUG
Alias: None
Product: Fedora
Classification: Fedora
Component: spice-vdagent
Version: 30
Hardware: Unspecified
OS: Unspecified
unspecified
unspecified
Target Milestone: ---
Assignee: Christophe Fergeau
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2018-05-28 15:25 UTC by Alan Jenkins
Modified: 2019-05-03 17:30 UTC (History)
6 users (show)

Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2019-05-03 13:35:55 UTC
Type: Bug
Embargoed:


Attachments (Terms of Use)

Description Alan Jenkins 2018-05-28 15:25:37 UTC
Description of problem:

Logging out (or restarting gdm) leaves behind a stale vdagent process, one process for each logout.

Version-Release number of selected component (if applicable):

spice-vdagent-0.17.0-6.fc28.x86_64

gdm-3.28.1-1.fc28.x86_64
gnome-shell-3.28.2-1.fc28.x86_64
systemd-238-8.git0e0aa59.fc28.x86_64

How reproducible: in a VM


Steps to Reproduce:
1. Install Fedora Workstation 28 in a VM
2. Log in
3. ps -ax | grep spice-vdagent
4. Log out, log in
5. ps -ax | grep spice-vdagent
6. (repeat steps 4-5, to show continuous increase in spice-vdagent processes)

Actual results:

Number of spice-vdagent processes grows from 1, to 2, to 3.

Expected results:

Number of spice-vdagent processes does not grow with each log in/log out cycle.

Additional info:

I think maybe there's a transient spice-vdagent process during login, hence you may see a spurious jump from 1 to 2.  This transient process shows in "ps -ax" as associated with tty1.  But then it goes away, and none of the vdagent processes are associated with any tty.  But there are still more of them left than there should be.

I noticed this bug because it causes stale sessions to show up in "loginctl".

Comment 1 Alan Jenkins 2018-05-28 15:27:07 UTC
Ah, specifically I guess the VM technology needs to support spice.  I reproduced this using virt-manager on a Fedora 28 host system.

Comment 2 Ben Cotton 2019-05-02 21:41:35 UTC
This message is a reminder that Fedora 28 is nearing its end of life.
On 2019-May-28 Fedora will stop maintaining and issuing updates for
Fedora 28. It is Fedora's policy to close all bug reports from releases
that are no longer maintained. At that time this bug will be closed as
EOL if it remains open with a Fedora 'version' of '28'.

Package Maintainer: If you wish for this bug to remain open because you
plan to fix it in a currently maintained version, simply change the 'version' 
to a later Fedora version.

Thank you for reporting this issue and we are sorry that we were not 
able to fix it before Fedora 28 is end of life. If you would still like 
to see this bug fixed and are able to reproduce it against a later version 
of Fedora, you are encouraged  change the 'version' to a later Fedora 
version prior this bug is closed as described in the policy above.

Although we aim to fix as many bugs as possible during every release's 
lifetime, sometimes those efforts are overtaken by events. Often a 
more recent Fedora release includes newer upstream software that fixes 
bugs or makes them obsolete.

Comment 3 Alan Jenkins 2019-05-03 09:48:33 UTC
Retested on Fedora 30.  It is still present, except the progression is now 2 -> 4 -> 6 processes :-).

Comment 4 Victor Toso 2019-05-03 10:01:46 UTC
step 1-3
(f29box) ~ $ ps aux | grep -i spice.vdagent | grep -v grep
root      1327  0.0  0.0   8412   332 ?        Ss   Apr11   0:00 /usr/sbin/spice-vdagentd
gdm       2225  0.0  0.0 164392  7884 ?        Ssl  11:56   0:00 /usr/bin/spice-vdagent
toso      2605  0.0  0.0 164392  7760 ?        Ssl  11:56   0:00 /usr/bin/spice-vdagent

step 4-5
(f29box) ~ $ ps aux | grep -i spice.vdagent | grep -v grep
root      1327  0.0  0.0   8412   332 ?        Ss   Apr11   0:00 /usr/sbin/spice-vdagentd
gdm       3492  0.0  0.0 164392  7836 ?        Ssl  11:57   0:00 /usr/bin/spice-vdagent
toso      3864  0.0  0.0 164392  7840 ?        Ssl  11:57   0:00 /usr/bin/spice-vdagent

What I see here is what is expected, spice-vdagent is a session agent, one per user, that is gdm and toso. You see that the pid is different between the two scenarios above because of logout/login.

The spice-vdagentd is system one, used to talk with hypervisor, pid stays the same.

Can you please add some more info to what's going on with you?

The command above between logout/login would help, also attaching `journalctl -t spice-vdagent -t spice-vdagentd` could help.

Comment 5 Alan Jenkins 2019-05-03 13:08:07 UTC
Thanks for having a look.
I realized why there are twice as many processes now, compared to Fedora 28.
It is because since Fedora 29, the GDM greeter session automatically closes after you log in.

I should perhaps say that I am no longer testing such a clean Fedora install:
the VM I am testing is one that has been upgraded from F28 to F29 to F30.


I gave it a bit of time after login to let some transients go away, but it still builds up:

gdm       1375  0.0  0.0  82140   220 ?        Ssl  13:49   0:00 /usr/bin/spice-vdagent
alan-sy+  1893  0.0  0.0  82140   300 ?        Ssl  13:50   0:00 /usr/bin/spice-vdagent

logout/login #1:

immediate result:

gdm       1375  0.0  0.0  82140   184 ?        Ssl  13:49   0:00 /usr/bin/spice-vdagent
alan-sy+  1893  0.0  0.0  82140   284 ?        Ssl  13:50   0:00 /usr/bin/spice-vdagent
gdm       2922  0.0  0.0  82140   300 ?        Ssl  13:52   0:00 /usr/bin/spice-vdagent
alan-sy+  3490  0.0  0.1   8408  1848 tty2     S+   13:53   0:00 /usr/bin/spice-vdagent
alan-sy+  3492  0.0  0.0  82140   300 ?        Ssl  13:53   0:00 /usr/bin/spice-vdagent

let the transient go away:

gdm       1375  0.0  0.0  82140   184 ?        Ssl  13:49   0:00 /usr/bin/spice-vdagent
alan-sy+  1893  0.0  0.0  82140   280 ?        Ssl  13:50   0:00 /usr/bin/spice-vdagent
gdm       2922  0.0  0.0  82140   296 ?        Ssl  13:52   0:00 /usr/bin/spice-vdagent
alan-sy+  3492  0.0  0.0  82140   300 ?        Ssl  13:53   0:00 /usr/bin/spice-vdagent

logout/login #2:

gdm       1375  0.0  0.0  82140   148 ?        Ssl  13:49   0:00 /usr/bin/spice-vdagent
alan-sy+  1893  0.0  0.0  82140   196 ?        Ssl  13:50   0:00 /usr/bin/spice-vdagent
gdm       2922  0.0  0.0  82140   284 ?        Ssl  13:52   0:00 /usr/bin/spice-vdagent
alan-sy+  3492  0.0  0.0  82140   292 ?        Ssl  13:53   0:00 /usr/bin/spice-vdagent
gdm       3977  0.0  0.0  82140   296 ?        Ssl  13:53   0:00 /usr/bin/spice-vdagent
alan-sy+  4481  0.0  0.0  82140   300 ?        Ssl  13:53   0:00 /usr/bin/spice-vdagent


$ journalctl --b -t spice-vdagent -t spice-vdagentd
-- Logs begin at Wed 2018-02-28 17:30:45 GMT, end at Fri 2019-05-03 13:57:07 BST. --
May 03 13:49:38 fedora30-vm spice-vdagent[1375]: vdagent started
May 03 13:50:01 fedora30-vm spice-vdagent[1893]: vdagent started
May 03 13:52:27 fedora30-vm spice-vdagent[2922]: vdagent started
May 03 13:53:11 fedora30-vm spice-vdagent[3492]: vdagent started
May 03 13:53:49 fedora30-vm spice-vdagent[3977]: vdagent started
May 03 13:54:00 fedora30-vm spice-vdagent[4481]: vdagent started


$ loginctl
SESSION  UID USER       SEAT  TTY 
     11 1000 alan-sysop seat0 tty2
     13 1000 alan-sysop seat0 tty2
      3 1000 alan-sysop seat0 tty2
     c1   42 gdm        seat0 tty1
     c2   42 gdm        seat0 tty1
     c3   42 gdm        seat0 tty1

6 sessions listed.

$ loginctl session-status c1 -n0
c1 - gdm (42)
           Since: Fri 2019-05-03 13:49:06 BST; 12min ago
          Leader: 867
            Seat: seat0; vc1
             TTY: tty1
         Service: gdm-launch-environment; type wayland; class greeter
           State: closing
            Unit: session-c1.scope
                  └─1375 /usr/bin/spice-vdagent

$ loginctl session-status 3 -n0
3 - alan-sysop (1000)
           Since: Fri 2019-05-03 13:49:52 BST; 11min ago
          Leader: 1382
            Seat: seat0; vc2
             TTY: tty2
         Service: gdm-password; type wayland; class user
           State: closing
            Unit: session-3.scope
                  └─1893 /usr/bin/spice-vdagent

Comment 6 Alan Jenkins 2019-05-03 13:18:46 UTC
There is probably an error in my report :-).  If I `systemctl unmask spice-vdagentd.service`,
the problem stops happening.

It would be *nice* if spice-vdagent was more robust in this sense, but it looks mostly likely I inflicted this problem on myself.

Comment 7 Victor Toso 2019-05-03 13:34:00 UTC
> $ loginctl
> SESSION  UID USER       SEAT  TTY 
>      11 1000 alan-sysop seat0 tty2
>      13 1000 alan-sysop seat0 tty2
>       3 1000 alan-sysop seat0 tty2
>      c1   42 gdm        seat0 tty1
>      c2   42 gdm        seat0 tty1
>      c3   42 gdm        seat0 tty1

Interesting, first of all, is this the behavior you expect on logout? Do you want multiple gdm/alan-sysop users every time you logout/login?

Based on this doc [0] you have multi-session configured, that is:

> A multi-session system allows multiple user sessions on the same seat at the same time. Linux+systemd qualifies.

[0] https://www.freedesktop.org/wiki/Software/systemd/multiseat/

/etc/xdg/autostart/spice-vdagent.desktop is bein called for every login. I don't think we have consider multi-session in spice-vdagent design but not yet sure about the use case of it either.

Do you notice any other problem besides having multiple agents running?

Comment 8 Victor Toso 2019-05-03 13:35:55 UTC
> It would be *nice* if spice-vdagent was more robust in this sense, but it looks mostly likely I inflicted this problem on myself.

Not yet sure how, we do code to send spice-protocol messages to the active session but if you have three alan-sysop and three gdm, you have 1:1 spice-vdagent and spice-vdagentd would switch to the active one. That's by design.

Comment 9 Alan Jenkins 2019-05-03 14:29:24 UTC
The extra sessions are not any deliberate customization; I do not want them.  The extra sessions do not happen after I unmask spice-vdagentd.service and reboot.

The extra sessions were in state "closing", and contained only spice-vdagent.  Because spice-vdagent is not responding correctly when the session is closed.  Hence the title of this bug report :-).

Comment 10 Victor Toso 2019-05-03 15:03:16 UTC
Spice-vdagent itself is not aware of the session, the process is run by xdg on autostart. Spice-vdagentd (root) is the one dealing with systemd-logind.

I'm not sure how this is a bug in spice-vdagent and not in some configuration file. Could be that we are missing something somewhere. Could be a bug in fedora package on updating some config files between f28 -> f29 -> f30.

A quick look around the fact that spice-vdagent is pending on 'closing' state would blame systemd/desktop/dbus etc [1]

[1] https://www.centos.org/forums/viewtopic.php?t=65472

If you can reproduce this on fresh install of have understanding on what should be done to avoid this in the future, feel free to reopen and I'll patch the code/package later ;)

Cheers,

Comment 11 Alan Jenkins 2019-05-03 17:30:19 UTC
spice-vdagent is aware of when the session ends, because it loses its X11 connection :-D.  I think Xlib should normally call the default error handler, which abort()s , presumably when you call XPending() ...

The problem is you're stuck in the client_setup() loop, infinitely trying to connect to a spice-vdagentd that is not running.  Again, if you want to blame someone else, blame the user (me) who almost certainly masked spice-vdagentd.service at some point :-).

On native systemd you don't need the retry loop, because even if spice-vdagent.service is not started yet, spice-vdagentd.socket will be.  (sockets.target is ordered before sysinit.target).

Otherwise I guess it's a bit of a pain.  Your existing X11 code expects you already have a valid vdagentd connection, so you might have to sprinkle NULL checks in random places.

Feel free to ignore it as a "nice to have".  Just don't blame this on systemd, I might get irony poisoning :-).


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