Slow ssh login - Activation of org.freedesktop.login1 timed out

Question

On one of my servers I've noticed really delay on SSH logins.

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 [email protected]
debug1: Entering interactive session.
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 here 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

Not knowing enough about this what is it trying to poll for and why is it now taking 25seconds on this particular server.

The journalctl -u systemd-logind command shows

Jul 20 11:33:06 click systemd-logind[19415]: Failed to abandon session scope: Transport endpoint is not connected
Jul 21 05:04:54 myhost systemd[1]: Started Login Service.
Jul 21 12:15:30 myhost systemd[1]: Started Login Service.
Jul 21 12:17:04 myhost systemd[1]: Started Login Service.
Jul 21 12:49:55 myhost systemd[1]: Started Login Service.
Jul 21 13:57:05 myhost systemd[1]: Started Login Service.
Jul 21 13:58:49 myhost systemd[1]: Started Login Service.
Jul 21 14:01:55 myhost systemd[1]: Started Login Service.
Jul 21 14:08:32 myhost systemd[1]: Started Login Service.
Jul 21 14:09:53 myhost systemd[1]: Started Login Service.
Jul 21 14:19:08 myhost systemd[1]: Started Login Service.
Jul 21 14:21:26 myhost systemd[1]: Started Login Service.
Jul 21 14:22:37 myhost systemd[1]: Started Login Service.
Jul 21 14:25:20 myhost systemd[1]: Started Login Service.
Jul 21 14:30:27 myhost systemd[1]: Started Login Service.
Jul 21 15:02:56 myhost systemd[1]: Started Login Service.

Issuing the command systemctl restart systemd-logind.service fixes it (for now probably).

What is the Activation of org.freedesktop.login1 it mentions? Is there a way I can prevent having to restart logind in future? I expect over time I will have this issue with the rest of the servers I manage.

Just noticed this starting to happen on another server.

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

EDIT - expanded journalctl output.

EDIT2 - added systemd-logind status as suggested in comments when noticed this starting on another server.

UPDATE - This is starting to happen to the rest of my Jessie servers. Am I the only one experiencing this? There must be some fix other than restarting systemd-logind, has anyone any thoughts?

There is a Debian bug report on this 770135.

Solution 1

This happens when dbus is restarted, but systemd-logind is not restarted. Just do the following:

systemctl restart systemd-logind

The solution is from here: https://major.io/2015/07/27/very-slow-ssh-logins-on-fedora-22/

Solution 2

Using:

systemctl restart systemd-logind

solves the problem only temporarily.

One workaround is to remove all the .scope files from a cron job, as stated here.

* 2,14 * * * root /bin/rm -f /run/systemd/system/*.scope

The related systemd bug report is here : Leak of scope units slowing down "systemctl list-unit-files" and delaying logins .

It seems that it's in fact a dbus bug : unix fd in-flight counting broken which is solved in dbus version 1.11.10

For a permanent fix of this bug, you just have to wait that this version of dbus appears in your distribution. For now, Debian Stretch is at dbus 1.10.18, Ubuntu 17.04 (Zesty) is at 1.10.10, CentOS 7 is at dbus 1.6.12.

Comments

[Jakuje]

It would be useful to see the output of systemcts status systemd-logind before restart to see what was wrong with it (exited, failed, whatever). ppoll is just a mediator who is waiting for response from systemd so you can't blame it.

[Alasdair]

there is no systemcts command

[Jakuje]

sorry. systemctl of course

[Alasdair]

I thought that was what you meant but wanted to be sure. Is that not the same output as is available from the command journalctl -u systemd-logind

[Jakuje]

it should show the log, but also status of service itself.

[Alasdair]

True, didnt run status but expanded journalctl output on question from what was left in my terminal.

[Alasdair]

@Jakuje Added status out put from other server started to notice slowdown on

[Halfgaar]

I still have the same Issue, on Ubuntu 16.04.

[Martin Schröder]

See also unix.stackexchange.com/q/239489/9454

[forresthopkinsa]

FYI, I had this issue with LXC containers in Proxmox and the solution was to enable nesting for the container. link

[Alasdair]

Already stated in question, bug report still unresolved, but thanks for reinstating it.

[unhammer]

Note: this can also give a "login loop" in the regular lightdm greeter; same solution applies.