Bug#770135: systemd: ssh logins considerably delayed (until PAM timeout) since 215-6

Wed Nov 19 21:28:05 GMT 2014

Control: tag -1 - moreinfo

Hey Martin, intrigeri.

On Wed, 2014-11-19 at 07:40 +0100, Martin Pitt wrote: 
> I. e. with -5 it worked?
Let me triple-check:

a) with -6: 
Nov 19 21:46:56 kronecker sshd[30685]: Accepted publickey for root from 2001:a60:14d9:9201:6267:20ff:fe09:9aa4 port 35506 ssh2: RSA da:9c:ab:70:74:de:16:6a:0f:3b:a3:4e:c9:7c:ab:d9
Nov 19 21:46:56 kronecker sshd[30685]: pam_unix(sshd:session): session opened for user root by (uid=0)
Nov 19 21:47:21 kronecker sshd[30685]: pam_systemd(sshd:session): Failed to create session: Connection timed out

b) downgrading to -5+b1 
i A  libpam-systemd          +48,1 kB  215-6          215-5+b1
i A  libsystemd-daemon0      +31,7 kB  215-6          215-5+b1
i A  libsystemd-id128-0      +31,7 kB  215-6          215-5+b1
i A  libsystemd-journal0     +31,7 kB  215-6          215-5+b1
i A  libsystemd-login0       +30,7 kB  215-6          215-5+b1
i A  libsystemd0             +30,7 kB  215-6          215-5+b1
i A  python3-systemd         +39,9 kB  215-6          215-5+b1
i    systemd                 +370 kB   215-6          215-5+b1
i A  systemd-sysv            +38,9 kB  215-6          215-5+b1

login via ssh:
Nov 19 21:56:59 kronecker sshd[16269]: Accepted publickey for root from 2001:a60:14d9:9201:6267:20ff:fe09:9aa4 port 35537 ssh2: RSA da:9c:ab:70:74:de:16:6a:0f:3b:a3:4e:c9:7c:ab:d9
Nov 19 21:56:59 kronecker sshd[16269]: pam_unix(sshd:session): session opened for user root by (uid=0)
Nov 19 21:57:24 kronecker sshd[16269]: pam_systemd(sshd:session): Failed to create session: Connection timed out
=> okay... that's weird..

c) rebooted (still on -5+b1)
# systemctl status
● kronecker
    State: running
     Jobs: 0 queued
   Failed: 0 units
    Since: Wed 2014-11-19 22:01:32 CET; 3min 43s ago
   CGroup: /
           ├─1 /sbin/init
=> so systemd is pid 1

login via ssh:
Nov 19 22:03:35 kronecker sshd[4174]: Accepted publickey for root from 2001:a60:14d9:9201:6267:20ff:fe09:9aa4 port 35588 ssh2: RSA da:9c:ab:70:74:de:16:6a:0f:3b:a3:4e:c9:7c:ab:d9
Nov 19 22:03:35 kronecker sshd[4174]: pam_unix(sshd:session): session opened for user root by (uid=0)
Nov 19 22:03:35 kronecker systemd-logind[2653]: New session 3 of user root.
=> okay now it works again

d) upgrading again to -6
(not having rebooted)

login via ssh:
Nov 19 22:10:59 kronecker sshd[18279]: Accepted publickey for root from 2001:a60:14d9:9201:6267:20ff:fe09:9aa4 port 35601 ssh2: RSA da:9c:ab:70:74:de:16:6a:0f:3b:a3:4e:c9:7c:ab:d9
Nov 19 22:10:59 kronecker sshd[18279]: pam_unix(sshd:session): session opened for user root by (uid=0)
Nov 19 22:11:18 kronecker sshd[18279]: pam_systemd(sshd:session): Failed to create session: Activation of org.freedesktop.login1 timed out
Nov 19 22:11:18 kronecker sshd[4174]: pam_systemd(sshd:session): Failed to release session: Activation of org.freedesktop.login1 timed out
Nov 19 22:11:18 kronecker systemd-logind[6954]: Failed to abandon session scope: Transport endpoint is not connected
=> okay it hangs again for a while, but with a different error message

the same (login via ssh) directly afterwards again:
Nov 19 22:11:55 kronecker sshd[18303]: Accepted publickey for root from 2001:a60:14d9:9201:6267:20ff:fe09:9aa4 port 35604 ssh2: RSA da:9c:ab:70:74:de:16:6a:0f:3b:a3:4e:c9:7c:ab:d9
Nov 19 22:11:55 kronecker sshd[18303]: pam_unix(sshd:session): session opened for user root by (uid=0)
Nov 19 22:12:20 kronecker sshd[18303]: pam_systemd(sshd:session): Failed to create session: Connection timed out
=> ah... back to the old message (ssh login is still hanging as you can see from the times)

systemctl daemon-reload and daemon-reexec each didn't change the issue (just the different error message came back):
Nov 19 22:14:10 kronecker sshd[18356]: Accepted publickey for root from 2001:a60:14d9:9201:6267:20ff:fe09:9aa4 port 35606 ssh2: RSA da:9c:ab:70:74:de:16:6a:0f:3b:a3:4e:c9:7c:ab:d9
Nov 19 22:14:10 kronecker sshd[18356]: pam_unix(sshd:session): session opened for user root by (uid=0)
Nov 19 22:14:35 kronecker sshd[18303]: Received disconnect from 2001:a60:14d9:9201:6267:20ff:fe09:9aa4: 11: disconnected by user

Nov 19 22:14:35 kronecker sshd[18303]: pam_unix(sshd:session): session closed for user root
Nov 19 22:14:35 kronecker sshd[18356]: pam_systemd(sshd:session): Failed to create session: Activation of org.freedesktop.login1 timed out
Nov 19 22:14:36 kronecker sshd[18356]: Received disconnect from 2001:a60:14d9:9201:6267:20ff:fe09:9aa4: 11: disconnected by user
Nov 19 22:14:36 kronecker sshd[18356]: pam_unix(sshd:session): session closed for user root

e) rebooted (with on -6)
# systemctl status
● kronecker
    State: running
     Jobs: 0 queued
   Failed: 0 units
    Since: Wed 2014-11-19 22:16:42 CET; 2min 38s ago
   CGroup: /
           ├─1 /sbin/init

Nov 19 22:20:13 kronecker sshd[4174]: Accepted publickey for root from 2001:a60:14d9:9201:6267:20ff:fe09:9aa4 port 35621 ssh2: RSA da:9c:ab:70:74:de:16:6a:0f:3b:a3:4e:c9:7c:ab:d9
Nov 19 22:20:13 kronecker sshd[4174]: pam_unix(sshd:session): session opened for user root by (uid=0)
Nov 19 22:20:13 kronecker systemd-logind[2636]: New session 6 of user root.

=> okay... so after reboot it even works with -6 without any delays

Kinda weird.... needrestart doesn't mask systemd-stuff to not be
reported if they need a restart,... and I though the daemon-reexec
should have "re-started" systemd? 

So even though it works now again, there's something still fishy.

btw: After all these upgrades/downgrades, needrestart suggested me to restart ssh, dbus and user at 0.service (which I did).

> Can you please check your /var/log/dpkg.log whether the upgrade
> happened to touch anything else? I. e. did it by chance remove
> systemd-sysv or so? (It really shouldn't have, but let's confirm).
No systemd-sysv is still there,... if you need excerpts from dpkg.log
(or anything else), tell me.

> Please check with "systemctl" that you are still actually running
> systemd.
see above

> > Nov 19 04:28:31 kronecker sshd[4408]: pam_systemd(sshd:session): Failed to create session: Connection timed out
> 
> Can you please check if there's a corresponding error message in
> /var/log/auth.log?
actually all these were from auth.log on the server

On Wed, 2014-11-19 at 11:30 +0100, intrigeri wrote:
Is there anything in `journalctl -ab' between the SSH client connects
> and this time out message?
> I can re-try the whole thing again, if you still need to know.

I see that you've modified logind.conf => may you please post the diff
> between the default one and yours?
> Uhm on the node where ssh runs, logind.conf *is* default,... I just
reported the bug from my notebook, where the only difference is
HandleLidSwitch=ignore

Cheers,
Chris.
-------------- next part --------------
A non-text attachment was scrubbed...
Name: smime.p7s
Type: application/x-pkcs7-signature
Size: 5313 bytes
Desc: not available
URL: <http://lists.alioth.debian.org/pipermail/pkg-systemd-maintainers/attachments/20141119/2c3fc404/attachment.bin>