loginctl list-sessions shows ghost sessions that are never completely closed

[Amos]

I setup a new VPS with ubuntu 18.04.4, including virtualmin/usermin. In auth.log I see a lot of

    su[12936]: Successful su for domain by root
    su[12936]: + ??? root:domain
    systemd-logind[148]: New session c315 of user domain .
    su[12936]: pam_unix(su:session): session opened for user domain by (uid=0)
    su[12936]: pam_unix(su:session): session closed for user domain

in syslog, I see a lot of

    systemd[1]: Started Session c314 of user domain.
    systemd[1]: Started Session c315 of user domain.

domain is the user of my virtual server defined in the VPS. c314/c315 increased by 1 each time, every 5 minutes (see explanation below). When running `loginctl list-sessions` those sessions number grow as "active=yes" and "state=closing" and never disappear from the list.

a random session as an example:

    loginctl session-status c315
    c315 - domain (1000)
               Since: Sat 2020-02-08 20:27:08 UTC; 23h ago
              Leader: 12936
                 TTY: ???
              Remote: user root
             Service: su; type tty; class user
               State: closing
                Unit: session-c315.scope

I did a simple test: logged in with ssh, logged out (exit) and re-logged in. I saw 2 sessions in loginctl list-sessions and the previous one, which I obviously closed, never disappeared from the list.

as a "bonus": Virtualmin apparently open/close a session for the virtual server user to do its stuff causing the number of ghost sessions to grow forever...

I posted this question in server fault, askubuntu, ubuntuforums and virtualmin - no one knew what to tell me. I have no idea what/where to look for... Please advice :) Thanks in advance.

FWIW: Someone from virtualmin forum told me that he had a similar problem with debian 9 and it was fixed in debian 10.

After a boot I see this, maybe related?

Feb 13 06:39:48 domain systemd[1]: Starting User Manager for UID 1000...
Feb 13 06:39:48 domain systemd[636]: Failed to create /user.slice/user-1000.slice/[e-mail]/init.scope control group: Permission denied
Feb 13 06:39:48 domain systemd[636]: Failed to allocate manager object: Permission denied
Feb 13 06:39:48 domain systemd[1]: [e-mail]: Failed with result 'protocol'.
Feb 13 06:39:48 domain systemd[1]: Failed to start User Manager for UID 1000

lsb_release -a; uname -a; grep 1000 /etc/passwd
No LSB modules are available.
Distributor ID: Ubuntu
Description: Ubuntu 18.04.4 LTS
Release: 18.04
Codename: bionic
Linux domain.com 4.15.0 #1 SMP Mon Dec 9 19:36:21 MSK 2019 x86_64 x86_64 x86_64 GNU/Linux
domain:x:1000:1000::/home/domain:/bin/bash

[Ubuntu Foundations Team Bug Bot (crichton)]

Thank you for taking the time to report this bug and helping to make Ubuntu better. It seems that your bug report is not filed about a specific source package though, rather it is just filed against Ubuntu in general. It is important that bug reports be filed about source packages so that people interested in the package can find the bugs about it. You can find some hints about determining what package your bug might be about at https://wiki.ubuntu.com/Bugs/FindRightPackage. You might also ask for help in the #ubuntu-bugs irc channel on Freenode.

To change the source package that this bug is filed about visit https://bugs.launchpad.net/ubuntu/+bug/1863228/+editstatus and add the package name in the text box next to the word Package.

[This is an automated message. I apologize if it reached you inappropriately; please just reply to this message indicating so.]

[Amos (amosss)]

I don't mean to sound rude, just want to understand how this is working.

I gave it a week and now loginctl list-sessions have 1955 sessions like that and it keeps growing... How the bug reports are handled?

Thanks

[Dan Streetman (ddstreet)]

To clarify, you're not logging in yourself as 'domain' user, right?

Also can you paste/attach the output of:

$ ps -elx

[Amos (amosss)]

I login to domain user using ssh from time to time...

as a "bonus", Virtualmin open/close a session for that same user to do its stuff:
https://www.cloudmin.com/node/54674
The above is causing the number of ghost sessions to grow even more rapidly

Regarding "ps -elx", just to make sure: you want me to run it while I connect (ssh) using domain user?

[Dan Streetman (ddstreet)]

> Regarding "ps -elx", just to make sure: you want me to run it while I connect (ssh) using domain user?

Any user on the system is fine; it will show info about all processes.

[Amos (amosss)]

Looks "quiet" but I have 1994 sessions in "loginctl list-sessions"

domain@domain:~$ ps -elx
F UID PID PPID PRI NI VSZ RSS WCHAN STAT TTY TIME COMMAND
5 1000 25901 25885 20 0 101548 1960 ? S ? 0:00 sshd: domain@pts/0
0 1000 25902 25901 20 0 18628 2132 wait Ss pts/0 0:00 -bash USER=domain LOGNAME=domain HOME=/home/sto
0 1000 26403 25902 20 0 25936 1276 - R+ pts/0 0:00 ps -elx LS_COLORS=rs=0:di=01;34:ln=01;36:mh=00:pi=4
domain@domain:~$

[Dan Streetman (ddstreet)]

sorry, can you use -a instead of -e:

$ ps -alx

also would be useful to see:

$ journalctl -b -u systemd-logind

[Amos (amosss)]

I did loginctl terminate-user domain before so now I have 47 such sessions.

domain@domain:~$ ps -alx
F UID PID PPID PRI NI VSZ RSS WCHAN STAT TTY TIME COMMAND
4 0 1 0 20 0 232712 10960 ep_pol Ss ? 152:21 /lib/systemd/systemd --system --deserialize 12
1 0 2 1 20 0 0 0 kthrea S ? 0:00 [kthreadd/79baa9]
1 0 3 2 20 0 0 0 kthrea S ? 0:00 [khelper]
4 105 139 1 20 0 189016 988 poll_s Ssl ? 0:03 /usr/sbin/rsyslogd -n
4 0 149 1 20 0 88660 19704 ep_pol Ss ? 1:32 /lib/systemd/systemd-logind
4 0 152 1 20 0 28344 376 hrtime Ss ? 0:02 /usr/sbin/cron -f
4 100 153 1 20 0 48428 1944 ep_pol Ss ? 2:57 /usr/bin/dbus-daemon --system --address=systemd: --4 0 163 1 20 0 196840 18732 poll_s Ssl ? 0:00 /usr/bin/python3 -Es /usr/sbin/firewalld --nofork -1 0 204 1 20 0 100968 80 skb_wa Ss ? 0:00 /usr/sbin/saslauthd -a pam -c -m /var/spool/postfix1 0 205 204 20 0 100968 92 lock_f S ? 0:00 /usr/sbin/saslauthd -a pam -c -m /var/spool/postfix5 118 261 1 20 0 76184 15964 poll_s Ss ? 0:00 postgrey --pidfile=/var/run/postgrey/postgrey.pid -4 106 478 1 20 0 287428 12804 sigsus Ssl ? 0:00 /usr/sbin/named -f -u bind
4 0 489 1 20 0 184288 7800 poll_s Ssl ? 0:00 /usr/bin/python3 /usr/share/unattended-upgrades/una4 0 505 1 20 0 1036648 13412 poll_s Ssl ? 39:19 /usr/bin/python3 /usr/bin/fail2ban-server -xf start4 0 523 1 20 0 72288 916 poll_s Ss ? 0:00 /usr/sbin/sshd -D
0 999 526 1 20 0 4192092 693668 futex_ Sl ? 42:25 /usr/lib/jvm/java-11-openjdk-amd64/bin/java -Djava.1 0 542 1 20 0 24176 256 poll_s Ss ? 0:00 /usr/sbin/xinetd -pidfile /run/xinetd.pid -stayaliv5 0 555 1 20 0 400524 16044 poll_s Ss ? 0:44 /usr/sbin/apache2 -k start
1 0 579 1 20 0 81052 18024 poll_s Ss ? 0:12 /usr/bin/perl /usr/share/usermin/miniserv.pl /etc/u1 0 581 1 20 0 87416 15492 poll_s Ss ? 0:34 /usr/bin/perl /usr/share/webmin/miniserv.pl /etc/we5 33 3714 555 20 0 400956 9468 ep_pol S ? 0:00 /usr/sbin/apache2 -k start
5 33 3716 555 20 0 400892 9352 SYSC_s S ? 0:00 /usr/sbin/apache2 -k start
4 0 5194 1 20 0 76500 1740 ep_pol Ss ? 0:00 /lib/systemd/systemd --user
5 0 5195 5194 20 0 261960 7528 sigtim S ? 0:00 (sd-pam)
4 0 5342 1 20 0 289044 2016 poll_s Ssl ? 0:07 /usr/lib/policykit-1/polkitd --no-debug
4 101 5968 1 20 0 71848 156 ep_pol Ss ? 0:00 /lib/systemd/systemd-networkd
4 0 5975 1 20 0 197976 49068 ep_pol Ss ? 0:12 /lib/systemd/systemd-journald
4 0 6087 1 20 0 42092 308 ep_pol Ss ? 0:00 /lib/systemd/systemd-udevd
5 114 6831 1 20 0 120580 2148 poll_s Ss ? 0:02 proftpd: (accepting conne...

[Dan Streetman (ddstreet)]

Well launchpad really messed up the formatting of that output, didn't it :(

If the journalctl output is large, you can attach the file to this bug, i.e.:

$ journalctl -b -u systemd-logind > /tmp/journal-logind.txt

then attach '/tmp/journal-logind.txt'

[Amos (amosss)]

I attached an excel file of the ps -alx command.

Regarding the other command, It is long because of the problem :) here is its content
Feb 07 10:09:08 vps.server.local systemd[1]: Starting Login Service... Feb 07 10:09:08 vps.server.local systemd-logind[122]: New seat seat0. Feb 07 10:09:08 vps.server.local systemd[1]: Started Login Service. Feb 07 10:09:19 vps.server.local systemd[1]: Stopping Login Service... Feb 07 10:09:19 vps.server.local systemd[1]: Stopped Login Service. Feb 07 10:09:33 vps.server.local systemd[1]: Starting Login Service... Feb 07 10:09:33 vps.server.local systemd-logind[104]: New seat seat0. Feb 07 10:09:33 vps.server.local systemd[1]: Started Login Service. Feb 07 10:10:45 vps.server.local systemd[1]: Stopping Login Service... Feb 07 10:10:45 vps.server.local systemd[1]: Stopped Login Service. Feb 07 10:11:03 vps48064754.local systemd[1]: Starting Login Service... Feb 07 10:11:04 vps48064754.local systemd-logind[163]: New seat seat0. Feb 07 10:11:04 vps48064754.local systemd[1]: Started Login Service. Feb 07 10:13:53 vps48064754.local systemd-logind[163]: New session c1 of user root. Feb 07 10:15:34 vps48064754.local systemd[1]: /lib/systemd/system/systemd-logind.service:32: Unknown lvalue 'RestrictSUIDSGID' in section 'Service' ...

[Dan Streetman (ddstreet)]

can you just attach it so I can look at the entire log please?

[Dan Streetman (ddstreet)]

also please attach text in *text* format, not excel.

[Amos (amosss)]

I attached the xls because of the indentation problem.

Here is the logind output in text (which is ok with indentation).

[Dan Streetman (ddstreet)]

I think you'll need to enable logind debug and reboot or restart systemd-logind:

$ sudo systemctl edit systemd-logind

in the editor that opens, put:

[Service]
Environment=SYSTEMD_LOG_LEVEL=debug

then save the file, and reboot (or restart systemd-logind).

After the number of sessions have grown for a while, re-capture the journalctl logs for logind and attach here.

[Amos (amosss)]

Before doing so, is there anything I should be aware of like the consequence of such editing and restarting?

You wrote reboot or restart, reboot you mean VPS and restart you mean systemd-logind service?

Ofcourse I prefer to restart the service only and not the whole vps, is there a recommended way to do it without breaking anything?

I ask because during my searches for the problem, I read that it should be done with cautious.

Thanks

[Dan Streetman (ddstreet)]

> is there anything I should be aware of like the consequence of such editing and restarting?

enabling debug logging will significantly increase the amount of log messages that logind sends to your log journal/syslog.

> You wrote reboot or restart, reboot you mean VPS and restart you mean systemd-logind service?

yes

[Amos (amosss)]

One last thing if I may:
what do you think is better, restart of the service or reboot of the vps?
except for the additional logging, is there something I should be aware of when editing the above?
Thanks

[Launchpad Janitor (janitor)]

[Expired for systemd (Ubuntu) because there has been no activity for 60 days.]