Frage Slow ssh login - Aktivierung von org.freedesktop.login1 abgelaufen


Auf einem meiner Server habe ich bemerkt, dass sich SSH-Logins wirklich verzögern.

Bei der Verbindung mit den Optionen ssh -vvv erfolgt die Verzögerung um debug1: Entering interactive session.

Auszug der Verbindung:

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

mit der beschriebenen Methode Hier Ich erzeugte strace-Ausgabe und bemerkte die Linie 14:09:53.676004 ppoll([{fd=5, events=POLLIN}], 1, {24, 999645000}, NULL, 8) = 1 ([{fd=5, revents=POLLIN}], left {0, 0}) <25.020764> Das dauert 25 Sekunden.

Auszug der Strace-Ausgabe:

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>

Ich habe einen Eintrag in den Auth-Logs zur relevanten Zeit bemerkt:

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

Ich weiß nicht genug darüber, wonach es zu suchen versucht und warum dauert es jetzt 25 Sekunden auf diesem bestimmten Server.

Das journalctl -u systemd-logind Befehl zeigt an

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.

Ausgabe des Befehls systemctl restart systemd-logind.service behebt es (vorerst wahrscheinlich).

Was ist der Activation of org.freedesktop.login1 es erwähnt? Kann ich verhindern, dass ich in Zukunft logind neu starten muss? Ich erwarte im Laufe der Zeit dieses Problem mit den anderen Servern, die ich verwalte.

Habe gerade bemerkt, dass dies auf einem anderen Server geschieht.

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

BEARBEITEN - erweitert journalctl Ausgabe.

EDIT2 - hinzugefügt systemd-logind Status wie in den Kommentaren vorgeschlagen, wenn dies auf einem anderen Server beginnend bemerkt.

UPDATE - Dies beginnt mit dem Rest meiner Jessie-Server zu passieren. Bin ich der Einzige, der das erlebt? Es muss eine andere Lösung geben, als systemd-logind neu zu starten, hat jemand irgendwelche Gedanken?

Es gibt einen Debian-Fehlerbericht dazu 770135.


39
2017-07-21 14:21


Ursprung


Es wäre nützlich, die Ausgabe von zu sehen systemcts status systemd-logind vor dem Neustart, um zu sehen, was damit nicht stimmt (beendet, fehlgeschlagen, was auch immer). ppoll ist nur ein Mediator, der auf eine Antwort von Systemd wartet, damit Sie es nicht beschuldigen können. - Jakuje
es gibt kein systemcts Befehl - Alasdair
Es tut uns leid. systemctl Na sicher - Jakuje
Ich dachte, dass du das meintest, aber du wolltest sicher sein. Ist das nicht die gleiche Ausgabe wie der Befehl? journalctl -u systemd-logind - Alasdair
Es sollte das Protokoll, aber auch den Status des Dienstes selbst anzeigen. - Jakuje


Antworten:


Dies passiert, wenn dbus neu gestartet wird, aber systemd-logind nicht neu gestartet wird. Mach einfach folgendes:

systemctl restart systemd-logind

Die Lösung ist von hier: https://major.io/2015/07/27/very-slow-ssh-logins-on-fedora-22/


46
2017-12-10 09:37



Bereits in Frage gestellt, Fehlerbericht noch nicht gelöst, aber danke für die Wiederherstellung. - Alasdair
Hinweis: Dies kann auch eine "Login-Schleife" im regulären Lightdm Greeter geben; gleiche Lösung gilt. - unhammer


Verwenden:

systemctl restart systemd-logind

behebt das Problem nur vorübergehend.

Eine Problemumgehung besteht darin, alle zu entfernen .scope Dateien von einem Cron-Job, wie angegeben Hier.

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

Der zugehörige Systemd Fehlerbericht ist hier: Der Verlust von Scope-Units verlangsamt "systemctl list-unit-files" und verzögert Logins .

Es scheint tatsächlich ein dbus-Bug zu sein: Unix fd Bordzählung gebrochen welches ist gelöst in dbus Version 1.11.10

Für eine dauerhafte Behebung dieses Fehlers müssen Sie nur warten, dass diese Version von dbus in Ihrer Distribution erscheint. Vorläufig ist Debian Stretch bei dbus 1.10.18, Ubuntu 17.04 (Zesty) ist bei 1.10.10, CentOS 7 ist bei dbus 1.6.12.


0
2018-06-14 07:46