Verzeichnisanmeldung: Wiederholversuch, weniger Runden, Zeiten

apps/tesm/pyproject.toml

@@ -4,7 +4,7 @@ build-backend = "setuptools.build_meta"
 
 [project]
 name = "tesm"
-version = "2.8.4"
+version = "2.8.6"
 description = "TESM -- Verwaltung und Ueberwachung von PoE-Endgeraeten und Aruba-Switchen"
 requires-python = ">=3.11"
 dependencies = [

apps/tesm/src/tesm/cli.py

@@ -318,6 +318,15 @@ def cmd_switch_test(args: argparse.Namespace) -> int:
                             return 1
             except SshError as fehler:
                 sagen("FEHLGESCHLAGEN", str(fehler))
+                # Gerade dann sind die Bytes interessant: "kein Prompt" kann
+                # heissen, dass nichts kam -- oder dass etwas kam, das nicht
+                # erkannt wurde. Das sieht man nur im Rohtext, und
+                # Steuerzeichen sieht man nur als repr().
+                roh = "".join(sitzung.transcript)
+                print()
+                print("--- rohe Antwort des Switches (mit Steuerzeichen) ---")
+                print(repr(roh) if roh else "(nichts)")
+                print("--- Ende ---")
                 return 1
     print()
     print("Fertig.")

apps/tesm/src/tesm/services/switchcli.py

@@ -30,9 +30,26 @@ from .ssh import SshError, open_transport
 
 logger = logging.getLogger(__name__)
 
+#: Steuerzeichen eines Terminals -- ANSI-Sequenzen, Glocke, Einzelbefehle.
+#:
+#: Ein ArubaOS-Switch an einem Pseudoterminal zeichnet seine Zeile neu und
+#: haengt dabei Sequenzen wie ``ESC [ K`` ("bis Zeilenende loeschen") an. Im
+#: Terminal sieht man davon **nichts** -- und genau das war der Fehler, der
+#: Konsole und PoE-Neustart lahmgelegt hat: der Prompt stand da, aber hinter
+#: ihm standen drei unsichtbare Bytes, und das verankerte Muster traf nicht
+#: mehr. Im Protokoll las man "kein Prompt", waehrend der Prompt im Text
+#: stand. Deshalb kommen die Steuerzeichen weg, bevor irgendetwas gesucht
+#: wird -- das macht zugleich die Ausgabe in der Konsole lesbar.
+ANSI_RE = re.compile(rb"\x1b\[[0-9;?]*[ -/]*[@-~]|\x1b[@-Z\\-_]|[\x07\x00]")
+
 #: Erkennt Operator- (``>``) und privilegierten Modus (``#``) sowie den
 #: Konfigurationsmodus (``switch(config)#``).
-PROMPT_RE = re.compile(rb"[\r\n][^\r\n]{0,80}?[>#]\s?$")
+#:
+#: Zwei Lockerungen gegenueber der ersten Fassung, beide aus dem Betrieb:
+#: der Prompt darf am Anfang des Puffers stehen (nicht nur nach einem
+#: Zeilenumbruch -- so kommt er nach einem geleerten Puffer), und hinter ihm
+#: darf beliebiger Leerraum stehen (nicht genau eines).
+PROMPT_RE = re.compile(rb"(?:^|[\r\n])[^\r\n]{0,120}?[>#]\s*$")
 PAGER_RE = re.compile(rb"(--\s?MORE\s?--|Press any key to continue)", re.IGNORECASE)
 ERROR_RE = re.compile(
     r"(invalid input|unknown command|incomplete|ambiguous|not supported|% *error)", re.IGNORECASE
@@ -175,27 +192,30 @@ class SwitchCli:
         """
         assert self._channel is not None
         deadline = time.monotonic() + timeout
-        collected = b""
+        # Zwei Puffer: das Rohe kommt herein, gesucht wird im Sichtbaren.
+        # Ohne diese Trennung entscheiden unsichtbare Steuerzeichen darueber,
+        # ob ein Prompt erkannt wird.
+        sichtbar = b""
         prompt_gesehen = False
         while time.monotonic() < deadline:
             if self._channel.recv_ready():
                 chunk = self._channel.recv(READ_CHUNK)
                 if not chunk:
                     break
-                collected += chunk
+                sichtbar = ANSI_RE.sub(b"", sichtbar + chunk)
-                if PAGER_RE.search(collected[-200:]):
+                if PAGER_RE.search(sichtbar[-300:]):
                     self._channel.send(" ")
-                    collected = PAGER_RE.sub(b"", collected)
+                    sichtbar = PAGER_RE.sub(b"", sichtbar)
                     continue
-                if PROMPT_RE.search(collected[-200:]):
+                if PROMPT_RE.search(sichtbar[-300:]):
                     prompt_gesehen = True
                     break
                 # Der Login-Banner mancher Geraete verlangt eine Bestaetigung.
-                if initial and collected.rstrip().endswith(b"continue"):
+                if initial and sichtbar.rstrip().endswith(b"continue"):
                     self._channel.send("\r\n")
             else:
                 time.sleep(0.05)
-        text = collected.decode("utf-8", errors="replace")
+        text = sichtbar.decode("utf-8", errors="replace")
         self.transcript.append(text)
         if not prompt_gesehen:
             letzte = " ".join(text.split())[-200:]

packages/tesm-core/pyproject.toml

@@ -4,7 +4,7 @@ build-backend = "setuptools.build_meta"
 
 [project]
 name = "tesm-core"
-version = "2.8.1"
+version = "2.8.2"
 description = "Gemeinsames Anwendungsgeruest (Auth, RBAC, Navigation, Design-System, Migrationen) fuer TESM und TESM-Lizenzserver"
 requires-python = ">=3.11"
 dependencies = [

packages/tesm-core/src/tesm_core/auth/directory.py

@@ -26,6 +26,7 @@ import re
 import socket
 import sqlite3
 import ssl
+import time
 from dataclasses import dataclass, field
 from datetime import datetime, timezone
 from typing import Any, Literal
@@ -162,19 +163,82 @@ def _tls_object(config: dict[str, Any]):
 
 
 def _server(config: dict[str, Any]):
+    """Das Server-Objekt -- so sparsam wie moeglich.
+
+    ``get_info`` entscheidet, was ldap3 beim Verbinden **zusaetzlich** holt.
+    Mit ``ALL`` ist das die Beschreibung des Verzeichnisses *und sein ganzes
+    Schema*: bei einem Active Directory sind das Tausende Attribut- und
+    Klassendefinitionen, mehrere Megabyte, bei jeder Verbindung neu. Fuer eine
+    Anmeldung braucht davon nichts -- gelesen wird hoechstens der
+    ``defaultNamingContext``, wenn kein Basis-DN eingetragen ist, und dafuer
+    genuegt ``DSA`` (nur die Serverinformation, ein Datensatz).
+
+    Liegt der Domain-Controller in einem anderen Netz, ist genau das der
+    Unterschied zwischen "geht sofort" und "dauert manchmal".
+    """
     from ldap3 import Server
 
     security = str(config["ldap_security"])
+    braucht_basis = not str(config.get("ldap_base_dn") or "").strip()
     return Server(
         str(config["ldap_host"]),
         port=int(config["ldap_port"]),
         use_ssl=security == "ldaps",
         tls=_tls_object(config) if security in {"ldaps", "starttls"} else None,
-        get_info="ALL",
+        get_info="DSA" if braucht_basis else "NO_INFO",
         connect_timeout=int(config["ldap_timeout"]),
     )
 
 
+#: Fehler, die nur "gerade jetzt nicht" bedeuten -- nicht "falsches Passwort".
+#:
+#: Die Liste stammt aus der Fassung 1.2.8, wo dieses Problem schon einmal
+#: geloest war. Der Kommentar dort beschreibt es genauer, als ich es koennte:
+#: ein Domain-Controller in einem anderen, langsameren Netzsegment -- die
+#: allererste Verbindung dorthin ist oft spuerbar langsamer als jede folgende,
+#: und der erste Login schlug mit "Benutzer/Passwort ungueltig" fehl, waehrend
+#: ein sofortiger zweiter Versuch klappte.
+TRANSIENTE_FEHLER: tuple[type[Exception], ...] = ()
+
+
+def _transiente_fehler() -> tuple[type[Exception], ...]:
+    """Die Ausnahmeklassen von ldap3, die einen Wiederholversuch verdienen."""
+    global TRANSIENTE_FEHLER
+    if TRANSIENTE_FEHLER:
+        return TRANSIENTE_FEHLER
+    from ldap3.core.exceptions import (
+        LDAPResponseTimeoutError,
+        LDAPSocketOpenError,
+        LDAPSocketReceiveError,
+        LDAPSocketSendError,
+    )
+
+    TRANSIENTE_FEHLER = (
+        LDAPSocketOpenError,
+        LDAPSocketReceiveError,
+        LDAPSocketSendError,
+        LDAPResponseTimeoutError,
+    )
+    return TRANSIENTE_FEHLER
+
+
+def mit_wiederholung(aufbau: Any) -> Any:
+    """Genau ein zweiter Versuch -- und nur bei einem Netzfehler.
+
+    Nicht bei einer abgelehnten Anmeldung: ein Tippfehler im Passwort wuerde
+    sonst den Sperrzaehler des Kontos zweimal statt einmal hochzaehlen. Das
+    ist die Regel aus 1.2.8, und sie ist richtig.
+    """
+    try:
+        return aufbau()
+    except _transiente_fehler() as fehler:
+        logger.info(
+            "Verzeichnisdienst antwortete nicht (%s) -- ein zweiter Versuch",
+            type(fehler).__name__,
+        )
+        return aufbau()
+
+
 def _connect(config: dict[str, Any], user: str, password: str):
     """Baut eine Verbindung auf und bindet. Wirft bei Netz-/TLS-Problemen."""
     from ldap3 import Connection
@@ -192,6 +256,12 @@ def _connect(config: dict[str, Any], user: str, password: str):
         auto_bind=False,
         raise_exceptions=False,
         receive_timeout=int(config["ldap_timeout"]),
+        # Ein Active Directory antwortet auf eine Suche ab der Domaenenwurzel
+        # mit Verweisen auf andere Controller. ldap3 folgt ihnen von sich aus
+        # -- und baut dafuer neue Verbindungen auf, womoeglich in ein anderes
+        # Netz. Fuer eine Anmeldung ist das nicht nur unnoetig, sondern die
+        # Quelle genau der Wartezeiten, die niemand erklaeren kann.
+        auto_referrals=False,
     )
     if security == "starttls":
         if not connection.open():
@@ -253,8 +323,19 @@ def authenticate(conn: sqlite3.Connection, username: str, password: str) -> Dire
     if not config["ldap_verify_cert"]:
         warnings.append("Serverzertifikat des Verzeichnisdienstes wird nicht geprüft")
 
+    begonnen = time.monotonic()
+    zeiten: list[str] = []
+
+    def gemessen(name: str, seit: float) -> float:
+        """Haelt eine Stufe mit ihrer Dauer fest und gibt die neue Marke."""
+        jetzt = time.monotonic()
+        zeiten.append(f"{name} {int((jetzt - seit) * 1000)}ms")
+        return jetzt
+
     try:
-        service_conn, bound = _connect(config, bind_user, bind_password)
+        service_conn, bound = mit_wiederholung(
+            lambda: _connect(config, bind_user, bind_password)
+        )
     except (PermissionError, ConnectionError) as exc:
         logger.error("Verzeichnisdienst: %s", exc)
         return DirectoryResult("unavailable", message=str(exc), warnings=tuple(warnings))
@@ -271,8 +352,10 @@ def authenticate(conn: sqlite3.Connection, username: str, password: str) -> Dire
             warnings=tuple(warnings),
         )
 
+    marke = gemessen("Dienstbindung", begonnen)
     try:
         base = _base_dn(service_conn, config)
+        marke = gemessen("Basis-DN", marke)
         if not base:
             return DirectoryResult(
                 "unavailable", message="Basis-DN konnte nicht ermittelt werden.", warnings=tuple(warnings)
@@ -288,8 +371,10 @@ def authenticate(conn: sqlite3.Connection, username: str, password: str) -> Dire
             attributes=list(dict.fromkeys(wanted)),
             size_limit=2,
         )
+        marke = gemessen("Benutzersuche", marke)
         entries = list(service_conn.entries)
         if len(entries) != 1:
+            logger.info("Verzeichnisanmeldung %s: %s", username, ", ".join(zeiten))
             return DirectoryResult("invalid", warnings=tuple(warnings))
 
         entry = entries[0]
@@ -300,9 +385,18 @@ def authenticate(conn: sqlite3.Connection, username: str, password: str) -> Dire
 
         # Zweite, unabhaengige Verbindung mit den Benutzerdaten -- die eigentliche
         # Passwortpruefung. Niemals ueber die Dienstkonto-Verbindung rebinden.
-        user_conn, user_bound = _connect(config, dn, password)
+        #
+        # Mit Wiederholversuch, und genau hier zeigte sich das Symptom: bei
+        # einem Domain-Controller in einem anderen Netz schlug der erste
+        # Versuch mit "Benutzer/Passwort ungueltig" fehl, der zweite gleich
+        # darauf klappte. Wiederholt wird nur bei einem Netzfehler -- eine
+        # abgelehnte Anmeldung bleibt abgelehnt, sonst zaehlt ein Tippfehler
+        # den Sperrzaehler des Kontos zweimal hoch.
+        user_conn, user_bound = mit_wiederholung(lambda: _connect(config, dn, password))
+        marke = gemessen("Passwortpruefung", marke)
         try:
             if not user_bound:
+                logger.info("Verzeichnisanmeldung %s: %s", username, ", ".join(zeiten))
                 return DirectoryResult("invalid", warnings=tuple(warnings))
         finally:
             try:
@@ -313,6 +407,7 @@ def authenticate(conn: sqlite3.Connection, username: str, password: str) -> Dire
         group_dns: tuple[str, ...] = ()
         if config["ldap_group_sync"]:
             group_dns = _resolve_groups(service_conn, base, dn)
+            marke = gemessen("Gruppen", marke)
 
         profile = DirectoryProfile(
             username=_attr(entry, attribute) or username,
@@ -322,6 +417,15 @@ def authenticate(conn: sqlite3.Connection, username: str, password: str) -> Dire
             email=_attr(entry, email_attribute),
             group_dns=group_dns,
         )
+        # Eine Zeile je Anmeldung mit den Dauern der Stufen. Aus "dauert
+        # manchmal laenger" wird damit eine Zahl -- und man sieht, ob es die
+        # Verbindung ist, die Suche oder die Gruppen.
+        logger.info(
+            "Verzeichnisanmeldung %s: %s, gesamt %dms",
+            username,
+            ", ".join(zeiten),
+            int((time.monotonic() - begonnen) * 1000),
+        )
         return DirectoryResult("ok", profile=profile, warnings=tuple(warnings))
     finally:
         try: