Bug#823987: systemd: after upgrading some libs, login takes much longer until systemd-logind is restarted

Wed May 11 02:27:31 BST 2016

Package: systemd
Version: 229-5
Severity: normal

Hi.

This issue happens since quote a while (> 1 year?).

When "some" packages are upgraded, logins, at least via ssh, are considerably
delayed.

journalctl output when trying to log in via ssh:
May 11 03:03:43 kronecker sshd[3051]: Postponed publickey for root from 2001:[snipsnap] port 44890 ssh2 [preauth]
May 11 03:03:43 kronecker sshd[3051]: Accepted publickey for root from 2001:[snipsnap] port 44890 ssh2: ED25519 SHA256:[snipsnap]
May 11 03:03:43 kronecker sshd[3051]: pam_unix(sshd:session): session opened for user root by (uid=0)
May 11 03:03:43 kronecker systemd-logind[2552]: New session 386 of user root.
May 11 03:04:04 kronecker systemd[1]: systemd-logind.service: Start operation timed out. Terminating.
May 11 03:04:04 kronecker systemd[1]: Failed to start Login Service.
May 11 03:04:04 kronecker sshd[3051]: pam_systemd(sshd:session): Failed to create session: Message recipient disconnected from message bus without replying
May 11 03:04:04 kronecker systemd[1]: systemd-logind.service: Unit entered failed state.
May 11 03:04:04 kronecker systemd[1]: systemd-logind.service: Failed with result 'timeout'.
May 11 03:04:04 kronecker systemd[1]: systemd-logind.service: Service has no hold-off time, scheduling restart.
May 11 03:04:04 kronecker systemd[1]: Stopped Login Service.
May 11 03:04:04 kronecker systemd[1]: Starting Login Service...
May 11 03:04:04 kronecker systemd-logind[3054]: New seat seat0.
May 11 03:04:04 kronecker systemd[1]: Started User Manager for UID 0.
May 11 03:04:04 kronecker systemd-logind[3054]: New session 331 of user root.
May 11 03:04:04 kronecker systemd-logind[3054]: New session 386 of user root.
May 11 03:04:04 kronecker systemd-logind[3054]: New session 385 of user root.

I think to remeber that it also happened on local logins, but I couldn't
reproduce this anymore right now.

In the current case I've had these packages upgraded:
[UPGRADE] gcc-6-base:amd64 6.1.1-1 -> 6.1.1-2
[UPGRADE] lib32atomic1:amd64 6.1.1-1 -> 6.1.1-2
[UPGRADE] lib32cilkrts5:amd64 6.1.1-1 -> 6.1.1-2
[UPGRADE] lib32gcc1:amd64 1:6.1.1-1 -> 1:6.1.1-2
[UPGRADE] lib32gomp1:amd64 6.1.1-1 -> 6.1.1-2
[UPGRADE] lib32itm1:amd64 6.1.1-1 -> 6.1.1-2
[UPGRADE] lib32quadmath0:amd64 6.1.1-1 -> 6.1.1-2
[UPGRADE] lib32stdc++6:amd64 6.1.1-1 -> 6.1.1-2
[UPGRADE] lib32ubsan0:amd64 6.1.1-1 -> 6.1.1-2
[UPGRADE] libatomic1:amd64 6.1.1-1 -> 6.1.1-2
[UPGRADE] libcc1-0:amd64 6.1.1-1 -> 6.1.1-2
[UPGRADE] libcilkrts5:amd64 6.1.1-1 -> 6.1.1-2
[UPGRADE] libgcc1:amd64 1:6.1.1-1 -> 1:6.1.1-2
[UPGRADE] libgfortran3:amd64 6.1.1-1 -> 6.1.1-2
[UPGRADE] libgomp1:amd64 6.1.1-1 -> 6.1.1-2
[UPGRADE] libgpg-error0:amd64 1.22-1 -> 1.22-2
[UPGRADE] libitm1:amd64 6.1.1-1 -> 6.1.1-2
[UPGRADE] liblsan0:amd64 6.1.1-1 -> 6.1.1-2
[UPGRADE] libobjc4:amd64 6.1.1-1 -> 6.1.1-2
[UPGRADE] libquadmath0:amd64 6.1.1-1 -> 6.1.1-2
[UPGRADE] libsctp1:amd64 1.0.16+dfsg-3 -> 1.0.17+dfsg-1
[UPGRADE] libstdc++6:amd64 6.1.1-1 -> 6.1.1-2
[UPGRADE] libtsan0:amd64 6.1.1-1 -> 6.1.1-2
[UPGRADE] libubsan0:amd64 6.1.1-1 -> 6.1.1-2
[UPGRADE] libwacom-common:amd64 0.18-1 -> 0.19-1
[UPGRADE] libwacom2:amd64 0.18-1 -> 0.19-1
[UPGRADE] libx32atomic1:amd64 6.1.1-1 -> 6.1.1-2
[UPGRADE] libx32cilkrts5:amd64 6.1.1-1 -> 6.1.1-2
[UPGRADE] libx32gcc1:amd64 1:6.1.1-1 -> 1:6.1.1-2
[UPGRADE] libx32gomp1:amd64 6.1.1-1 -> 6.1.1-2
[UPGRADE] libx32itm1:amd64 6.1.1-1 -> 6.1.1-2
[UPGRADE] libx32quadmath0:amd64 6.1.1-1 -> 6.1.1-2
[UPGRADE] libx32stdc++6:amd64 6.1.1-1 -> 6.1.1-2
[UPGRADE] libx32ubsan0:amd64 6.1.1-1 -> 6.1.1-2
[UPGRADE] lksctp-tools:amd64 1.0.16+dfsg-3 -> 1.0.17+dfsg-1

... before, logins worked without delay.

After upgrading, needrestart proposed a number of services
to be restarted, which yield in this:
May 11 03:02:33 kronecker systemd[1]: Stopping LSB: Start/stop apache2 web server...
May 11 03:02:33 kronecker systemd[1]: Stopping BIND Domain Name Server...
May 11 03:02:33 kronecker systemd[1]: Stopping D-Bus System Message Bus...
May 11 03:02:33 kronecker systemd[1]: Stopping Fail2Ban Service...
May 11 03:02:33 kronecker systemd[1]: Stopping A distributed, fault-tolerant Jabber/XMPP server...
May 11 03:02:33 kronecker systemd[1]: Stopped D-Bus System Message Bus.
May 11 03:02:33 kronecker systemd[1]: Stopping LSB: Start NTP daemon...
May 11 03:02:33 kronecker systemd[1]: Started D-Bus System Message Bus.
May 11 03:02:33 kronecker systemd[1]: Failed to subscribe to NameOwnerChanged signal for 'org.freedesktop.login1': Device or resource busy
May 11 03:02:33 kronecker systemd[1]: systemd-logind.service: Service has no hold-off time, scheduling restart.
May 11 03:02:33 kronecker systemd[1]: Stopped BIND Domain Name Server.
May 11 03:02:33 kronecker systemd[1]: Stopping OpenBSD Secure Shell server...
May 11 03:02:33 kronecker systemd[1]: Stopping Self Monitoring and Reporting Technology (SMART) Daemon...
May 11 03:02:33 kronecker systemd[1]: Stopping LSB: lm-sensors daemon...
May 11 03:02:33 kronecker systemd[1]: Started BIND Domain Name Server.
May 11 03:02:33 kronecker systemd[1]: Stopped target Mail Transport Agent.
May 11 03:02:33 kronecker systemd[1]: Stopping Mail Transport Agent.
May 11 03:02:33 kronecker systemd[1]: Stopping LSB: Postfix Mail Transport Agent...
May 11 03:02:33 kronecker systemd[1]: Stopped Login Service.
May 11 03:02:33 kronecker systemd[1]: Starting Login Service...
May 11 03:02:33 kronecker systemd[1]: Stopped OpenBSD Secure Shell server.
May 11 03:02:33 kronecker systemd[1]: Stopped Self Monitoring and Reporting Technology (SMART) Daemon.
May 11 03:02:33 kronecker systemd[1]: Stopped LSB: Start NTP daemon.
May 11 03:02:33 kronecker systemd-logind[2552]: New seat seat0.
May 11 03:02:33 kronecker systemd-logind[2552]: New session 331 of user root.
May 11 03:02:34 kronecker systemd[1]: Started User Manager for UID 0.
May 11 03:02:34 kronecker systemd[1]: Stopping Journal Service...
May 11 03:02:34 kronecker systemd[1]: Started Self Monitoring and Reporting Technology (SMART) Daemon.
May 11 03:02:34 kronecker systemd[1]: Starting LSB: Start NTP daemon...
May 11 03:02:34 kronecker systemd[1]: Stopped Flush Journal to Persistent Storage.
May 11 03:02:34 kronecker systemd[1]: Stopping Flush Journal to Persistent Storage...
May 11 03:02:34 kronecker systemd-journald[545]: Journal stopped
May 11 03:02:34 kronecker systemd-journald[2618]: Runtime journal (/run/log/journal/) is 19.7M, max 39.4M, 19.7M free.
May 11 03:02:34 kronecker systemd-journald[545]: Received SIGTERM from PID 1 (systemd).
May 11 03:02:34 kronecker systemd[1]: Starting OpenBSD Secure Shell server...
May 11 03:02:34 kronecker systemd[1]: Stopped Journal Service.
May 11 03:02:34 kronecker systemd[1]: Stopped LSB: lm-sensors daemon.
May 11 03:02:34 kronecker systemd[1]: Starting LSB: lm-sensors daemon...
May 11 03:02:34 kronecker systemd[1]: Starting Journal Service...
May 11 03:02:34 kronecker systemd[1]: Started OpenBSD Secure Shell server.
May 11 03:02:34 kronecker systemd-journald[2618]: Journal started
May 11 03:02:34 kronecker systemd[1]: Started Journal Service.
May 11 03:02:34 kronecker systemd[1]: Starting Flush Journal to Persistent Storage...
May 11 03:02:34 kronecker systemd[1]: Started LSB: Start NTP daemon.
May 11 03:02:34 kronecker systemd[1]: Started Flush Journal to Persistent Storage.
May 11 03:02:34 kronecker systemd[1]: Started LSB: lm-sensors daemon.
May 11 03:02:34 kronecker systemd[1]: Stopped LSB: Postfix Mail Transport Agent.
May 11 03:02:34 kronecker systemd[1]: Starting LSB: Postfix Mail Transport Agent...
May 11 03:02:35 kronecker systemd[22063]: Time has been changed
May 11 03:02:35 kronecker systemd[1]: Time has been changed
May 11 03:02:35 kronecker systemd[1]: apt-daily.timer: Adding 8h 47min 52.364411s random time.
May 11 03:02:36 kronecker systemd[1]: Started LSB: Postfix Mail Transport Agent.
May 11 03:02:36 kronecker systemd[1]: Reached target Mail Transport Agent.
May 11 03:02:37 kronecker systemd[1]: Stopped LSB: Start/stop apache2 web server.
May 11 03:02:37 kronecker systemd[1]: Starting LSB: Start/stop apache2 web server...
May 11 03:02:37 kronecker systemd[1]: Started LSB: Start/stop apache2 web server.
May 11 03:02:40 kronecker systemd[1]: Stopped Fail2Ban Service.
May 11 03:02:40 kronecker systemd[1]: Starting Fail2Ban Service...
May 11 03:02:40 kronecker systemd[1]: Stopped A distributed, fault-tolerant Jabber/XMPP server.
May 11 03:02:40 kronecker systemd[1]: Stopping Erlang Port Mapper Daemon...
May 11 03:02:40 kronecker systemd[1]: Stopped Erlang Port Mapper Daemon.
May 11 03:02:40 kronecker systemd[1]: Started Erlang Port Mapper Daemon.
May 11 03:02:40 kronecker systemd[1]: Starting A distributed, fault-tolerant Jabber/XMPP server...
May 11 03:02:40 kronecker systemd[1]: ejabberd.service: PID file /run/ejabberd/ejabberd.pid not readable (yet?) after start: No such file or directory
May 11 03:02:42 kronecker systemd[1]: Started Fail2Ban Service.
May 11 03:02:43 kronecker systemd[1]: Started A distributed, fault-tolerant Jabber/XMPP server.
May 11 03:02:45 kronecker systemd-logind[2552]: New session 385 of user root.
May 11 03:03:10 kronecker sshd[2997]: pam_systemd(sshd:session): Failed to create session: Connection timed out
May 11 03:03:43 kronecker systemd-logind[2552]: New session 386 of user root.
May 11 03:04:04 kronecker systemd[1]: systemd-logind.service: Start operation timed out. Terminating.
May 11 03:04:04 kronecker systemd[1]: Failed to start Login Service.
May 11 03:04:04 kronecker sshd[3051]: pam_systemd(sshd:session): Failed to create session: Message recipient disconnected from message bus without replying

It didn't propose systemd-logind to be restarted.
So either I'd guess systemd-logind may be doing something that - while it would
require it to be restarted - makes it not decteable by e.g. needrestart.

And even if one would say this is a needrestart issue, I'd still say
it shouldn't happen, that systemd-logind get's in an broken state
where it's not restarted automatically when somehow related packages
are upgraded.

Any ideas?

Cheers,
Chris.

-- Package-specific info:

-- System Information:
Debian Release: stretch/sid
  APT prefers unstable
  APT policy: (500, 'unstable')
Architecture: amd64 (x86_64)

Kernel: Linux 4.5.0-2-amd64 (SMP w/8 CPU cores)
Locale: LANG=en_DE.UTF-8, LC_CTYPE=en_DE.UTF-8 (charmap=UTF-8)
Shell: /bin/sh linked to /bin/dash
Init: systemd (via /run/systemd/system)

Versions of packages systemd depends on:
ii  adduser         3.114
ii  libacl1         2.2.52-3
ii  libapparmor1    2.10-4
ii  libaudit1       1:2.5.2-1
ii  libblkid1       2.28-5
ii  libc6           2.22-7
ii  libcap2         1:2.24-12
ii  libcap2-bin     1:2.24-12
ii  libcryptsetup4  2:1.7.0-2
ii  libgcrypt20     1.7.0-2
ii  libgpg-error0   1.22-2
ii  libkmod2        22-1.1
ii  liblzma5        5.1.1alpha+20120614-2.1
ii  libmount1       2.28-5
ii  libpam0g        1.1.8-3.2
ii  libseccomp2     2.3.0-1
ii  libselinux1     2.5-2
ii  libsystemd0     229-5
ii  mount           2.28-5
ii  util-linux      2.28-5

Versions of packages systemd recommends:
ii  dbus            1.10.8-1
ii  libpam-systemd  229-5

Versions of packages systemd suggests:
ii  systemd-container  229-5
ii  systemd-ui         3-4

Versions of packages systemd is related to:
ii  udev  229-5

-- Configuration Files:
/etc/systemd/logind.conf changed [not included]

-- no debconf information