Debian Bug report logs - #770135
systemd: ssh logins considerably delayed (until PAM timeout) when systemd is upgraded but the system not rebooted

Toggle useless messages

Message #5 received at submit@bugs.debian.org (full text, mbox, reply):

From: Christoph Anton Mitterer <calestyo@scientia.net>

To: Debian Bug Tracking System <submit@bugs.debian.org>

Subject: systemd: ssh logins considerably delayed (until PAM timeout) since 215-6

Date: Wed, 19 Nov 2014 04:31:32 +0100

Package: systemd
Version: 215-6
Severity: normal


Hi.

Since I've upgraded to -6 (and basically nothing else was upgraded
since then except gcc) I have the phenomenon that ssh logins take
considerably longer:

What auth.log shows on the server is this (right after the client
connects):
Nov 19 04:28:06 kronecker sshd[4408]: Accepted publickey for root from 2001:a60:14d9:9201:6267:20ff:fe09:9aa4 port 49020 ssh2: RSA da:9c:ab:70:74:de:16:6a:0f:3b:a3:4e:c9:7c:ab:d9
Nov 19 04:28:06 kronecker sshd[4408]: pam_unix(sshd:session): session opened for user root by (uid=0)

ssh hangs then until:
Nov 19 04:28:31 kronecker sshd[4408]: pam_systemd(sshd:session): Failed to create session: Connection timed out


So I guess something's wrong here.

Cheers,
Chris.


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

Kernel: Linux 3.16.0-4-amd64 (SMP w/8 CPU cores)
Locale: LANG=en_DE.utf8, LC_CTYPE=en_DE.utf8 (charmap=UTF-8)
Shell: /bin/sh linked to /bin/dash

Versions of packages systemd depends on:
ii  acl             2.2.52-2
ii  adduser         3.113+nmu3
ii  initscripts     2.88dsf-58
ii  libacl1         2.2.52-2
ii  libaudit1       1:2.4-1
ii  libblkid1       2.25.2-3
ii  libc6           2.19-13
ii  libcap2         1:2.24-6
ii  libcap2-bin     1:2.24-6
ii  libcryptsetup4  2:1.6.6-3
ii  libgcrypt20     1.6.2-4
ii  libkmod2        18-3
ii  liblzma5        5.1.1alpha+20120614-2+b1
ii  libpam0g        1.1.8-3.1
ii  libselinux1     2.3-2
ii  libsystemd0     215-6
ii  mount           2.25.2-3
ii  sysv-rc         2.88dsf-58
ii  udev            215-6
ii  util-linux      2.25.2-3

Versions of packages systemd recommends:
ii  dbus            1.8.10-1
ii  libpam-systemd  215-6

Versions of packages systemd suggests:
ii  systemd-ui  3-2

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

-- no debconf information

Message #10 received at submit@bugs.debian.org (full text, mbox, reply):

From: Martin Pitt <mpitt@debian.org>

To: Christoph Anton Mitterer <calestyo@scientia.net>, 770135@bugs.debian.org

Cc: Debian Bug Tracking System <submit@bugs.debian.org>

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

Date: Wed, 19 Nov 2014 07:40:57 +0100

Hey Christoph,

Christoph Anton Mitterer [2014-11-19  4:31 +0100]:
> Since I've upgraded to -6 (and basically nothing else was upgraded
> since then except gcc)

I. e. with -5 it worked? The only change in -6 which is even remotely
touching PAM is

  * Switch libpam-systemd dependencies to prefer systemd-shim over
    systemd-sysv, to implement the CTTE decision #746578. This is a no-op on
    systems which already have systemd-sysv installed, but will prevent
    installing that on upgrades. (Closes: #769747)

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).

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

> 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? "journalctl -u systemd-logind" might also give
something enlightening.

Thanks,

Martin
-- 
Martin Pitt                        | http://www.piware.de
Ubuntu Developer (www.ubuntu.com)  | Debian Developer  (www.debian.org)

Message #20 received at 770135@bugs.debian.org (full text, mbox, reply):

From: intrigeri <intrigeri@debian.org>

To: Christoph Anton Mitterer <calestyo@scientia.net>

Cc: 770135@bugs.debian.org

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

Date: Wed, 19 Nov 2014 11:30:47 +0100

Control: tag -1 + moreinfo

Hi,

Christoph Anton Mitterer wrote (19 Nov 2014 03:31:32 GMT) :
> ssh hangs then until:
> Nov 19 04:28:31 kronecker sshd[4408]: pam_systemd(sshd:session): Failed to create session: Connection timed out

Is there anything in `journalctl -ab' between the SSH client connects
and this time out message?

I see that you've modified logind.conf => may you please post the diff
between the default one and yours?

Cheers,
-- 
intrigeri

Message #27 received at 770135@bugs.debian.org (full text, mbox, reply):

From: Christoph Anton Mitterer <calestyo@scientia.net>

To: 770135@bugs.debian.org

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

Date: Wed, 19 Nov 2014 22:28:05 +0100

[Message part 1 (text/plain, inline)]

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@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.

[smime.p7s (application/x-pkcs7-signature, attachment)]

Message #34 received at 770135@bugs.debian.org (full text, mbox, reply):

From: Christoph Anton Mitterer <calestyo@scientia.net>

To: 770135@bugs.debian.org

Cc: control@bugs.debian.org

Date: Sat, 29 Nov 2014 16:50:18 +0100

[Message part 1 (text/plain, inline)]

retitle 770135 systemd: ssh logins considerably delayed (until PAM timeout) when systemd is upgraded but the system not rebooted
stop


Hi.

I've just confirmed the very same problem on the upgrade to -7.

ssh logins were considerably delayed until that PAM timeout happened
again,... no daemon-reexec and friends helped... after a reboot,
everything worked fine again.

There seems to be something in systemd which stops working correctly and
which is only recovered by a full reboot.


Cheers,
Chris.

[smime.p7s (application/x-pkcs7-signature, attachment)]

Message #41 received at 770135@bugs.debian.org (full text, mbox, reply):

From: Michael Biebl <biebl@debian.org>

To: Christoph Anton Mitterer <calestyo@scientia.net>, 770135@bugs.debian.org

Subject: Re: Bug#770135:

Date: Sun, 30 Nov 2014 22:05:59 +0100

[Message part 1 (text/plain, inline)]

Am 29.11.2014 um 16:50 schrieb Christoph Anton Mitterer:

> There seems to be something in systemd which stops working correctly and
> which is only recovered by a full reboot.

Can you try an restart journald and logind, and see if one of those
causes the issue.
I.e. run
systemctl restart systemd-journald.service
<test ssh login>
systemctl restart systemd-logind.service
<test ssh login>

-- 
Why is it that all of the instruments seeking intelligent life in the
universe are pointed away from Earth?

[signature.asc (application/pgp-signature, attachment)]

Message #46 received at 770135@bugs.debian.org (full text, mbox, reply):

From: Aljoscha Lautenbach <aljoscha.lautenbach@gmail.com>

To: Christoph Anton Mitterer <calestyo@scientia.net>, Michael Biebl <biebl@debian.org>, 770135@bugs.debian.org

Subject: Re: Bug#770135: ssh logins considerably delayed (until PAM timeout) when systemd is upgraded but the system not rebooted

Date: Tue, 9 Dec 2014 15:14:27 +0100

Hi,

I recently ran into the same problem, and I just tried Michael Biebl's
suggestions.

'systemctl restart systemd-journald.service': did not help.

'systemctl restart systemd-logind.service': fixed the problem.

Thanks.

Kind regards,
Aljoscha

Message #51 received at 770135@bugs.debian.org (full text, mbox, reply):

From: Christoph Anton Mitterer <calestyo@scientia.net>

To: 770135@bugs.debian.org

Cc: Michael Biebl <biebl@debian.org>

Subject: Re: Bug#770135: ssh logins considerably delayed (until PAM timeout) when systemd is upgraded but the system not rebooted

Date: Tue, 09 Dec 2014 19:40:56 +0100

[Message part 1 (text/plain, inline)]

Hey.


On Tue, 2014-12-09 at 15:14 +0100, Aljoscha Lautenbach wrote: 
> tried Michael Biebl's suggestions.
Oops... I've missed that mail,... sorry Michael.

Next time the issue happens (probably after the next update to systemd)
I'll check whether either of the two commands resolves the issue without
restarting.


Cheers,
Chris.

[smime.p7s (application/x-pkcs7-signature, attachment)]

Message #56 received at 770135@bugs.debian.org (full text, mbox, reply):

From: Christoph Anton Mitterer <calestyo@scientia.net>

To: 770135@bugs.debian.org

Cc: Michael Biebl <biebl@debian.org>

Subject: Re: Bug#770135: ssh logins considerably delayed (until PAM timeout) when systemd is upgraded but the system not rebooted

Date: Sun, 14 Dec 2014 17:07:34 +0100

[Message part 1 (text/plain, inline)]

On Tue, 2014-12-09 at 19:40 +0100, Christoph Anton Mitterer wrote: 
> Next time the issue happens
I can confirm now the same behaviour as Aljoscha described in message
#46.

Cheers,
Chris.

[smime.p7s (application/x-pkcs7-signature, attachment)]

Message #61 received at 770135@bugs.debian.org (full text, mbox, reply):

From: W Forum W <wforumw@gmail.com>

To: 770135@bugs.debian.org

Subject: Re: Bug#770135: ssh logins considerably delayed (until PAM timeout) when systemd is upgraded but the system not rebooted

Date: Mon, 2 Feb 2015 14:35:37 +0100

I can confirm the same behavior.
After restart the service
systemctl restart systemd-logind.service
login works normal again

thanks

Message #66 received at 770135@bugs.debian.org (full text, mbox, reply):

From: Christoph Anton Mitterer <calestyo@scientia.net>

To: 770135@bugs.debian.org

Cc: mpitt@debian.org

Subject: Re: systemd: ssh logins considerably delayed (until PAM timeout) when systemd is upgraded but the system not rebooted

Date: Fri, 10 Apr 2015 00:34:27 +0200

[Message part 1 (text/plain, inline)]

Hey Martin.

It seems your 215-15 upload also fixes #770135, or at least I didn't see
those delays this time.

Is it likely that this: 
>* debian/systemd.{triggers,postinst}: Trigger a systemctl daemon-reload
>  when init scripts are installed or removed (Closes: #766429)
also solved #770135?
Cause then we can close it :)

Cheers,
Chris.

[smime.p7s (application/x-pkcs7-signature, attachment)]

Message #71 received at 770135@bugs.debian.org (full text, mbox, reply):

From: Christoph Anton Mitterer <calestyo@scientia.net>

To: 770135@bugs.debian.org

Cc: mpitt@debian.org

Subject: Re: systemd: ssh logins considerably delayed (until PAM timeout) when systemd is upgraded but the system not rebooted

Date: Fri, 10 Apr 2015 20:41:13 +0200

[Message part 1 (text/plain, inline)]

On Fri, 2015-04-10 at 00:34 +0200, Christoph Anton Mitterer wrote: 
> It seems your 215-15 upload also fixes #770135, or at least I didn't see
> those delays this time.
> 
> Is it likely that this: 
> >* debian/systemd.{triggers,postinst}: Trigger a systemctl daemon-reload
> >  when init scripts are installed or removed (Closes: #766429)
> also solved #770135?

Spoken to early... the problem is actually still there,...

[smime.p7s (application/x-pkcs7-signature, attachment)]

Message #76 received at 770135@bugs.debian.org (full text, mbox, reply):

From: W Forum W <wforumw@gmail.com>

To: <770135@bugs.debian.org>, <770135@bugs.debian.org>

Subject: Re: systemd: ssh logins considerably delayed (until PAM timeout) when systemd is upgraded but the system not rebooted

Date: Thu, 11 Jun 2015 13:02:36 +0200

After upgrade to Jessie 8.1 problem still exist
ii  systemd                                215-17+deb8u1

systemctl restart systemd-logind.service
still have to manually restart the services

Message #81 received at 770135@bugs.debian.org (full text, mbox, reply):

From: Michał Skuza <micskuza@pg.gda.pl>

To: 770135@bugs.debian.org

Subject: Re: systemd: ssh logins considerably delayed (until PAM timeout) when systemd is upgraded but the system not rebooted

Date: Mon, 20 Jul 2015 15:17:45 +0200

Hi,

Just rebooted machine works ok:
Jul 20 14:25:22 sss sshd[8256]: pam_unix(sshd:session): session opened 
for user xxx by (uid=0)
Jul 20 14:25:22 sss systemd-logind[1129]: New session 233 of user xxx.
(no delay)

Problem appears after about 300 ssh logins (/var/log/auth.log):
Jul 20 15:07:02 sss sshd[10086]: pam_unix(sshd:session): session opened 
for user xxx by (uid=0)
Jul 20 15:07:32 sss sshd[10079]: pam_systemd(sshd:session): Failed to 
release session: Connection reset by peer
(15:07:32 - 15:07:02 = 30seconds delay)

After commenting out the line
"session    optional    pam_systemd.so "
from /etc/pam.d/common-session the system is working normally again even 
after 1000 logins.

apt-get upgrade was done today (20.07.2015) (reboot ofc) before tests
systemd 215-17+deb8u1 amd64

greetings,
Michał

Message #86 received at 770135@bugs.debian.org (full text, mbox, reply):

From: Felipe Sateler <fsateler@debian.org>

To: Steven Monai <smonai@sd57.bc.ca>, 793814@bugs.debian.org, 770135@bugs.debian.org

Subject: Re: Bug#793814: systemd-logind: Logins via ssh and su are delayed by 25 seconds

Date: Mon, 27 Jul 2015 18:16:05 -0300

Control: forcemerge 770135 793814
Control: found 770135 222-2

Hi Steven,

On 27 July 2015 at 15:05, Steven Monai <smonai@sd57.bc.ca> wrote:
> Dear Maintainer,
>
> There is an issue with the systemd-logind daemon that appears to be
> triggered whenever the dbus daemon is restarted.
>
> Specifically, after a recent 'apt-get upgrade' to install a security
> update (of libexpat1, if that matters), I restarted the 'dbus' daemon,
> since 'needrestart' had flagged it as one of the daemons requiring a
> restart.
>
> After that, I noticed that logins via ssh and 'su -' were being
> delayed by about 25 seconds. Here is what I see in /var/log/syslog
> after every login attempt:
>
>     Jul 27 09:27:59 ldb dbus[27174]: [system] Activating via systemd: service name='org.freedesktop.login1' unit='dbus-org.freedesktop.login1.service'
>     Jul 27 09:28:24 ldb dbus[27174]: [system] Failed to activate service 'org.freedesktop.login1': timed out
>
> Notice the 25-second timespan between log entries.
>
> The problem goes away after I restart the systemd-logind daemon.
>
> To reliably trigger the problem on my system (it is a headless
> server, no Xorg installed), I merely need to do this:
>
>     systemctl restart dbus
>
> All subsequent logins or su's then experience a 25 second delay
> before proceeding successfully. The following command then returns
> login processing to normal, without the delay:
>
>     systemctl restart systemd-logind
>

This was already reported as #770135 , but the dbus connection was not
mentioned before. I can confirm the same behavior on systemd 222-2
(inside an nspawn container).

-- 

Saludos,
Felipe Sateler

Message #99 received at 770135@bugs.debian.org (full text, mbox, reply):

From: Alasdair Campbell <alasdair@campbelldiagnostics.co.uk>

To: Debian Bug Tracking System <770135@bugs.debian.org>

Subject: systemd: Stalls just after debug1: Entering interactive session.

Date: Mon, 03 Aug 2015 17:06:55 +0100

This is a multi-part MIME message sent by reportbug.


--===============0015788417291632402==
MIME-Version: 1.0
Content-Transfer-Encoding: 8bit
Content-Type: text/plain; charset="UTF-8"
Content-Disposition: inline

Package: systemd
Version: 215-17+deb8u1
Followup-For: Bug #770135

Dear Maintainer,

*** Reporter, please consider answering these questions, where
appropriate ***

   * What led up to the situation?
   * What exactly did you do (or not do) that was effective (or
     ineffective)?
   * What was the outcome of this action?
   * What outcome did you expect instead?

*** End of the template - remove these template lines ***


-- Package-specific info:

-- System Information:
ebian Release: 8.1
  APT prefers stable-updates
  APT policy: (500, 'stable-updates'), (500, 'stable')
Architecture: amd64 (x86_64)
Foreign Architectures: i386

Kernel: Linux 3.16.0-4-amd64 (SMP w/8 CPU cores)
Locale: LANG=en_GB.UTF-8, LC_CTYPE=en_GB.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  acl             2.2.52-2
ii  adduser         3.113+nmu3
ii  initscripts     2.88dsf-59
ii  libacl1         2.2.52-2
ii  libaudit1       1:2.4-1+b1
ii  libblkid1       2.25.2-6
ii  libc6           2.19-18
ii  libcap2         1:2.24-8
ii  libcap2-bin     1:2.24-8
ii  libcryptsetup4  2:1.6.6-5
ii  libgcrypt20     1.6.3-2
ii  libkmod2        18-3
ii  liblzma5        5.1.1alpha+20120614-2+b3
ii  libpam0g        1.1.8-3.1
ii  libselinux1     2.3-2
ii  libsystemd0     215-17+deb8u1
ii  mount           2.25.2-6
ii  sysv-rc         2.88dsf-59
ii  udev            215-17+deb8u1
ii  util-linux      2.25.2-6

Versions of packages systemd recommends:
ii  dbus            1.8.18-0+deb8u1
ii  libpam-systemd  215-17+deb8u1

Versions of packages systemd suggests:
pn  systemd-ui  <none>

Connecting using the ssh -vvv options the delay occurs at debug1:
Entering interactive session.

extract of connection:

debug1: Authentication succeeded (publickey).
Authenticated to IP_REDACTED ([IP_REDACTED]:22).
debug1: channel 0: new [client-session]
debug3: ssh_session2_open: channel_new: 0
debug2: channel 0: send open
debug1: Requesting no-more-sessions@openssh.com
debug1: Entering interactive session.
[[[STALL]]]
debug2: callback start
debug2: fd 3 setting TCP_NODELAY
debug3: packet_set_tos: set IP_TOS 0x10
debug2: client_session2_setup: id 0
debug2: channel 0: request pty-req confirm 1

using the method outlined
http://www.depesz.com/2010/12/13/a-tale-of-slow-ssh-connections/  I
generated strace output and noticed the line 14:09:53.676004
ppoll([{fd=5, events=POLLIN}], 1, {24, 999645000}, NULL, 8) = 1
([{fd=5, revents=POLLIN}], left {0, 0}) <25.020764> which takes 25
seconds.

extract of strace output:

14:09:53.675567 clock_gettime(CLOCK_MONOTONIC, {4662549, 999741404}) =
0 <0.000024>
14:09:53.675651 recvmsg(5, {msg_name(0)=NULL,
msg_iov(1)=[{"l\4\1\1\n\0\0\0\2\0\0\0\215\0\0\0\1\1o\0\25\0\0\0",
24}], msg_controll
en=0, msg_flags=MSG_CMSG_CLOEXEC},
MSG_DONTWAIT|MSG_NOSIGNAL|MSG_CMSG_CLOEXEC) = 24 <0.000024>
14:09:53.675744 recvmsg(5, {msg_name(0)=NULL,
msg_iov(1)=[{"/org/freedesktop/DBus\0\0\0\2\1s\0\24\0\0\0"..., 146}],
msg_controllen
=0, msg_flags=MSG_CMSG_CLOEXEC},
MSG_DONTWAIT|MSG_NOSIGNAL|MSG_CMSG_CLOEXEC) = 146 <0.000025>
14:09:53.675842 recvmsg(5, 0x7ffe0ff1dfa0,
MSG_DONTWAIT|MSG_NOSIGNAL|MSG_CMSG_CLOEXEC) = -1 EAGAIN (Resource
temporarily unavailab
le) <0.000023>
14:09:53.675925 clock_gettime(CLOCK_MONOTONIC, {4662550, 96075}) = 0
<0.000024>
14:09:53.676004 ppoll([{fd=5, events=POLLIN}], 1, {24, 999645000},
NULL, 8) = 1 ([{fd=5, revents=POLLIN}], left {0, 0}) <25.020764>
14:10:18.696865 recvmsg(5, {msg_name(0)=NULL,
msg_iov(1)=[{"l\3\1\0013\0\0\0\3\0\0\0m\0\0\0\6\1s\0\5\0\0\0", 24}],
msg_controllen=0,     msg_flags=MSG_CMSG_CLOEXEC},
MSG_DONTWAIT|MSG_NOSIGNAL|MSG_CMSG_CLOEXEC) = 24 <0.000017>
14:10:18.696944 recvmsg(5, {msg_name(0)=NULL,
msg_iov(1)=[{":1.10\0\0\0\4\1s\0#\0\0\0org.freedesktop."..., 155}],
msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC},
MSG_DONTWAIT|MSG_NOSIGNAL|MSG_CMSG_CLOEXEC) = 155 <0.000018>

I have noticed an entry in the auth logs at the relevant time:

Jul 21 14:10:18 click sshd[8165]: pam_systemd(sshd:session): Failed to
create session: Activation of org.freedesktop.login1 timed out

extract of sudo service systemd-logind status:

systemd-logind.service - Login Service
   Loaded: loaded (/lib/systemd/system/systemd-logind.service; static)
   Active: active (running) since Tue 2015-06-16 14:10:57 BST; 1
months 12 days ago
     Docs: man:systemd-logind.service(8)
           man:logind.conf(5)
           http://www.freedesktop.org/wiki/Software/systemd/logind
           http://www.freedesktop.org/wiki/Software/systemd/multiseat
 Main PID: 1701 (systemd-logind)
   Status: "Processing requests..."
   CGroup: /system.slice/systemd-logind.service
           └─1701 /lib/systemd/systemd-logind

Jul 28 13:16:21 myhost systemd[1]: Started Login Service.
Jul 28 13:16:47 myhost systemd[1]: Started Login Service.
Jul 28 16:09:23 myhost systemd[1]: Started Login Service.
Jul 28 16:09:49 myhost systemd[1]: Started Login Service.
Jul 28 16:10:15 myhost systemd[1]: Started Login Service.
Jul 28 16:10:41 myhost systemd[1]: Started Login Service.
Jul 28 22:50:19 myhost systemd[1]: Started Login Service.
Jul 29 05:00:15 myhost systemd[1]: Started Login Service.
Jul 29 11:00:20 myhost systemd[1]: Started Login Service.
Jul 29 11:09:56 myhost systemd[1]: Started Login Service.

Can confim the command:
systemctl restart dbus.service
prompts this delay in ssh login and is only resolved by the command:
systemctl restart


--===============0015788417291632402==

Message #104 received at 770135@bugs.debian.org (full text, mbox, reply):

From: Alistair Turnbull <apt1002@goose.minworks.co.uk>

To: 770135@bugs.debian.org

Subject: Bug also present in systemd 215-17+deb8u2

Date: Mon, 7 Dec 2015 19:24:19 +0000 (GMT)

I too am seeing 25 second delays when I log in by ssh. I can turn 
the problem on and off exactly as described in #86:

	https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=770135#86

When the problem is "on", many things are broken in addition to slow ssh 
login. The "shutdown" and "reboot" commands do nothing. Starting and 
stopping services fails with a timeout. The latter in turn often breaks 
"apt-get upgrade".

Sometimes the problem turns "on" when the server has been up for a long 
time. I don't know what event triggers it.

	Alistair

Message #109 received at 770135@bugs.debian.org (full text, mbox, reply):

From: Andreas Schamanek <as2013+dbts@fam.tuwien.ac.at>

To: 770135@bugs.debian.org

Subject: How do I detect the need to restart

Date: Tue, 23 Feb 2016 23:31:22 +0100 (CET)

Sometimes `checkrestart` tells me that systemd-logind is in need to be 
restarted, but apparently it needs to be restarted more often than 
`checkrestart` is able to detect.

How can I programmatically detect that systemd-logind needs to be 
restarted? Or should we simply restart unconditionally on a daily 
basis until this bug gets fixed?

-- 
-- Andreas

Message #118 received at 770135@bugs.debian.org (full text, mbox, reply):

From: Philipp Nowak <philipp@nowak-at.net>

To: 770135@bugs.debian.org

Subject: Same behaviour, but systemd-logind restart doesn't fix

Date: Tue, 21 Jun 2016 17:44:01 +0200

[Message part 1 (text/plain, inline)]

Hi, I am too experiencing the same behaviour described in this report on
two of my systems, but I it doesn't stop when I restart systemd-logind. It
also seems to randomly occur after restarts, the 300 logins earlier seem
like a good estimate. Commenting out the pam_systemd module in
/etc/pam.d/common-session fixes it, but I would prefer a cleaner solution.

Jun 21 17:38:29 mt-mikey sshd[26999]: pam_unix(sshd:session): session
opened for user xxyy by (uid=0)
Jun 21 17:38:54 mt-mikey sshd[26999]: pam_systemd(sshd:session): Failed to
create session: Connection timed out

Regards,
Philipp

[Message part 2 (text/html, inline)]

Message #123 received at 770135@bugs.debian.org (full text, mbox, reply):

From: Sebastiaan Meijer <meijersebastiaan@gmail.com>

To: 770135@bugs.debian.org

Subject: Possible cause?

Date: Fri, 9 Sep 2016 23:00:16 +0200

[Message part 1 (text/plain, inline)]

Okay, CentOS user here, please don't kill me right away.

I believe I'm experiencing this same bug on CentOS 7 and, after months of
bashing my head into the wall while in the meantime switching servers,
server providers and even switching from bare metal to virtualized, I think
I've found the cause, as well as a workaround.
First off, at least on my systems, the issue seems to occur on servers with
lots of users and/or logins/login attempts.
In my case I have about 20 users running 2 cron jobs each every minute,
resulting in ~40 simultaneous logins every minute.
I heard from someone else that they experienced the same problem when
receiving many external (unsuccessful?) login attempts.

The bug seems to get triggered shortly after systemd updates for me.
When it happens, it seems systemd-logind ends up in a restart loop, causing
it to slow down logins and consume 100% CPU while initializing.
It used to be sufficient to restart a load of services like mentioned
earlier in this thread, but eventually this stopped working too.

Looking deeper into the logs, this line stands out:

systemd-logind.service watchdog timeout (limit 1min)!

It seems like the restart loops are caused by the Systemd watchdog killing
systemd-logind because it takes too long.

I've increased the WatchdogSec limit in the systemd-logind.service file to
5 minutes and reloaded/restarted systemd-logind. It consumed 100% CPU for
slightly over a minute and then started behaving as it should again.

Not sure why it would take over a minute to start, but at least for me this
allows me to work around the issue.

I don't know for sure if this is the same issue as on Debian, but as this
thread seems to have come to a standstill with no fix since 2014, and as it
helped me pinpoint the issue, I thought I'd share my findings here.


Sebastiaan

[Message part 2 (text/html, inline)]

Message #128 received at 770135@bugs.debian.org (full text, mbox, reply):

From: Wiebe Cazemier <wiebe@ytec.nl>

To: 770135@bugs.debian.org

Subject: Reproduced in Ubuntu 16.04

Date: Fri, 7 Oct 2016 15:33:59 +0200

[Message part 1 (text/plain, inline)]

Should it be relevant, this keeps hapenning on Ubuntu 16.04. Systemd and
libpam-systemd version 229-4ubuntu10.

[Message part 2 (text/html, inline)]

Message #133 received at 770135@bugs.debian.org (full text, mbox, reply):

From: Erik Braun <erik@minet.uni-jena.de>

To: 770135@bugs.debian.org

Subject: same with a fresh installed Testing

Date: Tue, 10 Jan 2017 13:40:22 +0100 (CET)

The 25 sec delay still exists:

Jan 10 12:48:40 pc66 sshd[1438]: pam_unix(sshd:session): session opened for user erik by (uid=0)
Jan 10 12:48:40 pc66 systemd-logind[1400]: New session 8 of user erik.
Jan 10 12:49:05 pc66 sshd[1438]: pam_systemd(sshd:session): Failed to create session: Connection timed out

It disappears, if "session optional pam_systemd.so" is removed from pam.

When strace-ing the ssh daemon, you'll see, that a ppoll() waits on 
/var/run/dbus/system_bus_socket.

Kernel: 4.8.0-2-amd64 (4.8.15-2)
systemd: 232-8
dbus: 1.10.14-1

Message #138 received at 770135@bugs.debian.org (full text, mbox, reply):

From: Michael Biebl <biebl@debian.org>

To: 770135@bugs.debian.org, Christoph Anton Mitterer <calestyo@scientia.net>

Subject: Re: systemd: ssh logins considerably delayed (until PAM timeout) since 215-6

Date: Tue, 10 Oct 2017 18:49:02 +0200

[Message part 1 (text/plain, inline)]

Control: tags -1 moreinfo, unreproducible

Hi

On Wed, 19 Nov 2014 04:31:32 +0100 Christoph Anton Mitterer
<calestyo@scientia.net> wrote:
> Package: systemd
> Version: 215-6
> Severity: normal
> 
> 
> Hi.
> 
> Since I've upgraded to -6 (and basically nothing else was upgraded
> since then except gcc) I have the phenomenon that ssh logins take
> considerably longer:
> 
> What auth.log shows on the server is this (right after the client
> connects):
> Nov 19 04:28:06 kronecker sshd[4408]: Accepted publickey for root from 2001:a60:14d9:9201:6267:20ff:fe09:9aa4 port 49020 ssh2: RSA da:9c:ab:70:74:de:16:6a:0f:3b:a3:4e:c9:7c:ab:d9
> Nov 19 04:28:06 kronecker sshd[4408]: pam_unix(sshd:session): session opened for user root by (uid=0)
> 
> ssh hangs then until:
> Nov 19 04:28:31 kronecker sshd[4408]: pam_systemd(sshd:session): Failed to create session: Connection timed out
> 
> 
> So I guess something's wrong here.

Is this issue still reproducible with a recent version from stretch or
buster? I failed to reproduce it myself with a stretch VM.

If you can you provide a minimal reproducer in that case, that would be
very helpful.

Regards,
Michael

-- 
Why is it that all of the instruments seeking intelligent life in the
universe are pointed away from Earth?

[signature.asc (application/pgp-signature, attachment)]

Message #145 received at 770135@bugs.debian.org (full text, mbox, reply):

From: Christoph Anton Mitterer <calestyo@scientia.net>

To: 770135@bugs.debian.org

Subject: Re: systemd: ssh logins considerably delayed (until PAM timeout) since 215-6

Date: Wed, 11 Oct 2017 14:19:30 +0200

[Message part 1 (text/plain, inline)]

Hey Michael.


On Tue, 2017-10-10 at 18:49 +0200, Michael Biebl wrote:
> Is this issue still reproducible with a recent version from stretch
> or
> buster? I failed to reproduce it myself with a stretch VM.

At least I haven't encountered it anymore since ages.
I did once or twice (even with the libpam thingy installed), but
wouldn't have noticed it since then.

So from my side it can probably be closed.


Thanks,
Chris.

[smime.p7s (application/x-pkcs7-signature, attachment)]

Message #150 received at 770135@bugs.debian.org (full text, mbox, reply):

From: Michael Biebl <biebl@debian.org>

To: Christoph Anton Mitterer <calestyo@scientia.net>, 770135@bugs.debian.org

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

Date: Wed, 11 Oct 2017 14:36:55 +0200

[Message part 1 (text/plain, inline)]

Am 11.10.2017 um 14:19 schrieb Christoph Anton Mitterer:
> Hey Michael.
> 
> 
> On Tue, 2017-10-10 at 18:49 +0200, Michael Biebl wrote:
>> Is this issue still reproducible with a recent version from stretch
>> or
>> buster? I failed to reproduce it myself with a stretch VM.
> 
> At least I haven't encountered it anymore since ages.
> I did once or twice (even with the libpam thingy installed), but
> wouldn't have noticed it since then.
> 
> So from my side it can probably be closed.

Ok, let's do this then (and reopen on demand).

Regards,
Michael


-- 
Why is it that all of the instruments seeking intelligent life in the
universe are pointed away from Earth?

[signature.asc (application/pgp-signature, attachment)]

Message #155 received at 770135-done@bugs.debian.org (full text, mbox, reply):

From: Christoph Anton Mitterer <calestyo@scientia.net>

To: 770135-done@bugs.debian.org

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

Date: Wed, 11 Oct 2017 15:16:43 +0200

[Message part 1 (text/plain, inline)]

Closing, as the issue seems to be either gone or not reproducible right
now.

Thanks,
Chris.

[smime.p7s (application/x-pkcs7-signature, attachment)]

Send a report that this bug log contains spam.