Langsame SSH-Anmeldung - Zeitüberschreitung bei der Aktivierung von org.freedesktop.login1

39

Auf einem meiner Server ist mir bei SSH-Anmeldungen eine Verzögerung aufgefallen.

Beim Verbinden mit den Optionen ssh -vvv tritt die Verzögerung bei auf 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 [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

Mit der hier beschriebenen Methode habe ich eine Strace-Ausgabe generiert und festgestellt, dass die Zeile 14:09:53.676004 ppoll([{fd=5, events=POLLIN}], 1, {24, 999645000}, NULL, 8) = 1 ([{fd=5, revents=POLLIN}], left {0, 0}) <25.020764>25 Sekunden dauert.

Auszug aus dem 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>

Ich habe einen Eintrag in den Authentifizierungsprotokollen zum relevanten Zeitpunkt 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 abgefragt werden soll und warum es auf diesem bestimmten Server jetzt 25 Sekunden dauert.

Der journalctl -u systemd-logindBefehl zeigt

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.

Das Ausgeben des Befehls systemctl restart systemd-logind.servicebehebt es ( vorerst wahrscheinlich).

Was ist die Activation of org.freedesktop.login1Erwähnung? Kann ich verhindern, dass ich logind in Zukunft neu starten muss? Ich gehe davon aus, dass dieses Problem mit der Zeit auch bei den anderen von mir verwalteten Servern auftreten wird.

Ich habe gerade bemerkt, dass dies auf einem anderen Server beginnt. 

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

EDIT2 - Systemd-Logind-Status hinzugefügt, wie in Kommentaren vorgeschlagen, wenn dies auf einem anderen Server gestartet wird.

UPDATE - Dies geschieht allmählich auf den übrigen Jessie-Servern. Bin ich der einzige, der das erlebt? Es muss außer dem Neustart von systemd-logind ein Fix geben. Hat jemand irgendwelche Gedanken?

Es gibt einen Debian-Fehlerbericht zu dieser 770135 .

ssh debian pam systemd Alasdair
quelle
Es wäre nützlich, die Ausgabe von systemcts status systemd-logindvor dem Neustart zu überprüfen, um festzustellen, was daran falsch war (beendet, fehlgeschlagen, was auch immer). ppollist nur ein Vermittler, der auf die Antwort von systemd wartet, Sie können es also nicht beschuldigen.
Jakuje
Es gibt keinen systemctsBefehl
Alasdair
Es tut uns leid. systemctlnatürlich
Jakuje
Ich dachte, das war es, was Sie meinten, aber ich wollte sicher sein. Ist das nicht die gleiche Ausgabe, die vom Befehl verfügbar istjournalctl -u systemd-logind
Alasdair
Es sollte das Protokoll, aber auch den Status des Dienstes selbst anzeigen.
Jakuje,

Antworten:

48

Dies geschieht, wenn dbus neu gestartet wird, systemd-logind jedoch 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/

asv
quelle
1
Bereits in Frage gestellt, Fehlerbericht noch ungelöst, aber danke für die Wiederherstellung.
Alasdair
Hinweis: Dies kann auch eine "Anmeldeschleife" im regulären lightdm-Begrüßer ergeben. Die gleiche Lösung gilt.
Unhammer
1

Verwenden von:

systemctl restart systemd-logind

löst das problem nur vorübergehend.

Eine Problemumgehung besteht darin, alle .scopeDateien aus einem Cron-Job zu entfernen , wie hier angegeben .

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

Der dazugehörige systemd-Fehlerbericht ist hier: Durchsickern von Bereichseinheiten, die "systemctl list-unit-files" verlangsamen und Anmeldungen verzögern .

Es scheint tatsächlich ein dbus-Fehler zu sein: Unix fd in-flight counting broken, der in der dbus-Version 1.11.10 behoben wurde

Um diesen Fehler dauerhaft zu beheben, müssen Sie nur warten, bis diese Version von dbus in Ihrer Distribution angezeigt wird. Derzeit ist Debian Stretch bei dbus 1.10.18, Ubuntu 17.04 (Zesty) bei 1.10.10, CentOS 7 bei dbus 1.6.12.

Ortomala Lokni
quelle