Verzögerung beim Start einer Sitzung

[Rüdiger Kupper]

Wir haben festgestellt, dass ssh-Logins auf den LtspServern derzeit sehr lange dauern -- oft bis zu 30 Sekunden. Auch beim Login an den LtspClients treten teilweise lange Verzögerungen auf.

Beobachtung 1:

Dabei ist es egal, ob man den Rechner per Name oder IP anspricht:

17:10/0 [kup@paedml] ~ $ ssh ltsp1
17:10/0 [kup@paedml] ~ $ ssh 10.32.2.1

Beide Aufrufe dauern etwa 30 Sekunden, bis die Verbindung hergestellt wird.

Beobachtung 2:

Trotzdem schein es ein Problem mit der lokalen Namensauflösung zu geben, denn der folgende Befehl bricht keineswegs sofort mit einer Fehlermeldung ab, sondern erst nach 60 Sekunden:

17:11/0 [kup@paedml] ~ $ ssh gibtsnicht

Können die beiden Sachen zusammenhängen?

[Rüdiger Kupper]

Hm, vermutlich die falsche Fährte:

• der Name "gibtsnicht" wird zur IP des OpenDNS-Servers aufgelöst, und der lehnt die Verbindung erst nach einer Minute ab. Das ist also nicht das Problem.
• ein "ssh -v 10.32.2.1" zeigt in den Debug-Meldungen, dass die Verbindung ohne Verzögerung aufgebaut und authentifiziert wird. Dann hängt es aber bei der Meldung "debug1: Entering interactive session." Das starten der Sitzung ist also, was so lange dauert.

--> also wohl kein DNS- und kein ssh-Problem.

[Rüdiger Kupper]

Okay, auch ein "su kup" auf dem ltsp1 dauert so lange. Hat also nichts mit ssh zu tun.
Was ist es dann, was da so lange dauert?

[Rüdiger Kupper]

Ein Hinweis findet sich in /var/log/auth.log:

Nov  2 17:31:35 ltsp2 su[4400]: (pam_mount.c:660): done opening session (ret=0)
Nov  2 17:32:00 ltsp2 su[4400]: pam_systemd(su:session): Failed to create session: Did not receive a reply. Possible causes include: the remote application did not send a reply, the message bus security policy blocked the reply, the reply timeout expired, or the network connection was broken.

Um 17:31:35 ist "pam_mount" fertig. Doch dann dauert es bin 17:32:00, bis "pam_systemd" mit einer Fehlermeldung abbricht. Erst dann erfolgt der Start der Sitzung.

[Rüdiger Kupper]

Wenn ich mich graphisch einlogge (über VNC auf ltsp6) steht da noch etwas anderes komisches im auth.log:

Nov  2 17:44:12 ltsp6 cupsd: nss_ldap: could not connect to any LDAP server as cn=admin,dc=kg-fds,dc=de - Can't contact LDAP server
Nov  2 17:44:12 ltsp6 cupsd: nss_ldap: failed to bind to LDAP server ldaps://10.32.1.1/: Can't contact LDAP server
Nov  2 17:44:12 ltsp6 cupsd: nss_ldap: could not search LDAP server - Server is unavailable

Warum sich gerade der cupsd beschwert weiß ich nicht, aber kann es ein Problem mit dem LDAP geben?

[Rüdiger Kupper]

Gibt es einen Zusammenhang mit Deiner LDAP-Upstellung von ticket:1201?

[bau]

LDAP-Abfragen gehen vom LTSP aus (ldapsearch -x "uid=bau"), die Option -ZZ gibt einen Fehler aus - komisch.
Ein su bau läuft prima durch bis zu dem Zeitpunkt, wo eine session gestartet wird - ich denke nicht, dass das an dieser Stelle was mit dem LDAP zu tun hat. Der CUPS versucht sich als cn=admin zu verbinden, wo ist denn das festgelegt, normalerweise ist doch ein anonymer bind ausreichend?
Wobei komisch: in der /etc/slapd.conf auf der paedml wird kein anonymer bind von 10.32.2.X erlaubt
Ich muss mal nachsehen, wo das definiert wird.

[Rüdiger Kupper]

Jedenfalls werden Sitzungen derzeit nur mit dieser 30-sekündigen Verzögerung aufgebaut. Das passiert auch, wenn ich mich an meinem virtuellen LtspClient einlogge: Da sehe ich erst für 30 Sekunden einen schwarzen Bildschirm, dann startet die Sitzung. Das war vor zwei Tagen noch nicht so.

[Rüdiger Kupper]

Stop! -- Es betrifft nur bestimmte LtspServer!
Ich habe gerade mal in meinen cssh-Fenstern ein "su linadmin" gemacht. Ergebnis:

• auf ltsp{1,2,6,l1} hängt's beim Starten der Sitzung
• auf ltsp{3,4,5,7} läuft der Login wie geschmiert.

Ich werde die betreffenden Server mal neu starten und sehen, ob sich dadurch etwas ändert.

[Rüdiger Kupper]

Bingo! Nach einem Neustart von ltsp{1,2,6,l1} klappt auch dort der Sitzungsstart wieder wie gewohnt.

Was war denn das nun wieder? Und wird es wieder auftauchen??

[Rüdiger Kupper]

Okay, das Problem ist bereits zurück:
Sobald man sich einmal graphisch eingeloggt hat, dauert der Sitzungsstart wieder, und zwar für alle Nutzer, inklusive linadmin.

[Rüdiger Kupper]

Die Meldung im auth.log erscheint nur bei den Rechnern, bei dem der Login verzögert ist

Nov  3 10:58:19 ltsp6 su[6464]: pam_systemd(su:session): Failed to create sessio
n: Did not receive a reply. Possible causes include: the remote application did 
not send a reply, the message bus security policy blocked the reply, the reply t
imeout expired, or the network connection was broken.

Bei den anderen taucht diese Meldung nicht auf.

[Rüdiger Kupper]

Im syslog steht noch ein einweiterer Kommentar:

Nov  3 10:57:04 ltsp6 gnome-session[5690]: WARNING: Could not get session id for
 session. Check that logind is properly installed and pam_systemd is getting use
d at login.

[Rüdiger Kupper]

Das Problem tritt übrigens erst auf, wenn sich ein Nichtlokaler Nutzer einmal graphisch eingeloggt hat. Linadmin kann sich z.B. problemlos graphisch einloggen, ohne dass das Problem entsteht. Sobald es aber ein LDAP-Nutzer tut, hängen von da ab alle weitern Logins.

Workaround

Ich schalte einstweilen das pam-Modul pam-systemd ab. Das ist aber keine langfristige Lösung, denn der Dienst scheint grundsätzlich sinnvoll zu sein: ​http://www.freedesktop.org/software/systemd/man/pam_systemd.html

Das geht auf dem LtspServern mittels pam-auth-update. Dort dann den Eintrag Register user sessions in the systemd control group hierarchy abwählen.

[Rüdiger Kupper]

Replying to kup:

Das Problem tritt übrigens erst auf, wenn sich ein Nichtlokaler Nutzer einmal graphisch eingeloggt hat. Linadmin kann sich z.B. problemlos graphisch einloggen, ohne dass das Problem entsteht. Sobald es aber ein LDAP-Nutzer tut, hängen von da ab alle weitern Logins.

--> also vielleicht doch ein Zusammenhang mit dem LDAP?

[bau]

OK, ich sehe mir mal die LDAP-Integration der LSP-Server an, das hatte damals Joachim Lutz gemacht und anschließend hast du es glaube ich so übernommen - oder?
Gibt es dazu irgendwo eine Beschreibung, wie LDAP ins System integriert ist?

[Rüdiger Kupper]

Die Authentifizierung läuft ebenfalls über ein PAM-Modul: pam_ldap.
Die Konfiguration steht meines Wissens in zwei Dateien:

• /etc/ldap.conf
• /etc/ldap/ldap.conf

Beide werden verwendet! Die eine ist für die Authentifizierung wichtig, die andere wohl für "normale" LDAP-Abfragen.

[Rüdiger Kupper]

Siehe auch comment:28:ticket:435.

Die /etc/ldap.conf ist also die, die für die Authentifizierung wichtig ist. Weitere Stichworte: nss_ldap, nssswitch.

Siehe auch ​http://www.webmasterpro.de/server/article/ldap-pam-authentifizierung.html

[Rüdiger Kupper]

Ich habe auch deshalb LDAP im Verdacht, weil das Problem zeitlich etwa dann aufgetaucht ist, als Du die Proxy-Authentifizierung auf LDAP umgestellt hast. Kann aber auch reiner Zufall sein.

[bau]

OK, beim LDAP war irgendwas nicht so ganz in Ordnung!
Ich habe zunächst mal ein Problem mit apparmor festgestellt, dadurch wurde verhindert, dass slapd auf /etc/pkcs11/modules/ zugreifen durfte (stand im syslog), geholfen hat die Anpassung der /etc/apparmor.d/usr.sbin.slapd wie in ​http://www.mail-archive.com/ubuntu-bugs@lists.ubuntu.com/msg4127969.html beschrieben (Hinzufügen von #include <abstractions/p11-kit>.

Außerdem war leider das CACertificate-File das Falsche (Richtig ist: /etc/ssl/private/sub.class1.server.ca.pem), ein

openssl s_client -connect localhost:636 -showcerts

liefert jetzt keine nennenswerten Fehler mehr (zu Beginn: verify-return:0).
Das könnte natürlich der Fehler gewesen sein!

[Rüdiger Kupper]

Okay. Ich prüfe mal, ob das Problem damit behoben ist...

[Rüdiger Kupper]

Leider noch immer das gleiche Problem: Mit aktiviertem pam_systemd Hänger und im auth.log:

Nov  3 21:11:32 ltsp6 su[5168]: pam_systemd(su:session): Failed to create session: Did not receive a reply. Possible causes include: the remote application did not send a reply, the message bus security policy blocked the reply, the reply timeout expired, or the network connection was broken.

Trotzdem gut, dass Du den LDAP-Login mal genauer angeschaut hast!

[bau]

Mit dem neuesten Update scheinen die Probleme der Vergangenheit anzugehören.

[Rüdiger Kupper]

Hm, der pam_systemd ist noch immer deaktiviert, ich muss bei Gelegenheit mal probieren, ob der sich nun auch wieder einschalten lässt.

[Rüdiger Kupper]

Replying to kup:

Hm, der pam_systemd ist noch immer deaktiviert, ich muss bei Gelegenheit mal probieren, ob der sich nun auch wieder einschalten lässt.

Test auf lstp1 ergab: Problem besteht weiter wie beschrieben. pam_systemd bleibt vorerst deaktiviert.

TODO

Prüfen, ob das gleiche für den neu aufgesetzten ltsp8 gilt!

[Rüdiger Kupper]

Beobachtung: Der neue ltsp8 läuft super mit aktiviertem pam_systemd. Bei einem neu aufgesetzten Server scheint das kein Problem zu machen.