Verzeichnisanmeldung: Wiederholversuch, weniger Runden, Zeiten

apps/tesm/pyproject.toml

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

apps/tesm/src/tesm/blueprints/terminal.py

@@ -211,7 +211,17 @@ def init_app(app) -> None:  # type: ignore[no-untyped-def]
 
 
 def _send(ws, kind: str, text: str) -> None:  # type: ignore[no-untyped-def]
-    ws.send(json.dumps({"type": kind, "data": text}))
+    """Schickt eine Nachricht. Ein geschlossener Socket ist kein Fehler.
+
+    Bricht der Browser die Sitzung ab, schlaegt das Senden fehl -- und die
+    Ausnahme daraus verdeckte bisher den eigentlichen Grund, warum die
+    Sitzung endete: im Protokoll stand ein Stapelverlauf aus ``ws.send``,
+    nicht die Meldung des Switches.
+    """
+    try:
+        ws.send(json.dumps({"type": kind, "data": text}))
+    except Exception:  # noqa: BLE001 - der Browser ist weg, das ist keine Stoerung
+        logger.debug("Konsolennachricht nicht mehr zustellbar (%s)", kind)
 
 
 def _transcript_name(label: str) -> str:
@@ -220,8 +230,17 @@ def _transcript_name(label: str) -> str:
 
 
 def _handle_socket(ws, kind: str, target_id: int) -> None:  # type: ignore[no-untyped-def]
+    """Eine Konsolensitzung, von der Berechtigung bis zum Abmelden.
+
+    Jede Stufe schickt eine Zeile in die Oberflaeche. Das ist keine Zierde:
+    eine Konsole, die nichts sagt, laesst offen, ob die Berechtigung fehlt,
+    die Zugangsdaten, die Verbindung oder die Antwort des Geraets -- und genau
+    diese Frage stand im Betrieb im Raum. Sichtbar sind die Zeilen erst
+    nuetzlich, wenn sie **vor** dem Warten kommen, nicht danach.
+    """
     extension = core()
     conn = db()
+    _send(ws, "info", "Sitzung wird geöffnet …")
 
     # -- Berechtigungen: dieselben Pruefungen wie in der HTTP-Route. Ein
     #    WebSocket umgeht Dekoratoren, also stehen sie hier ausdruecklich.
@@ -255,6 +274,7 @@ def _handle_socket(ws, kind: str, target_id: int) -> None:  # type: ignore[no-un
         / f"{stamp}-{_transcript_name(current_user.username)}-{_transcript_name(target.label)}.log"
     )
 
+    _send(ws, "info", f"Ziel: {target.label} ({target.host}:{target.port})")
     try:
         username, password = inventory.credential_secret(
             conn, extension.keystore, target.credential_id
@@ -262,6 +282,7 @@ def _handle_socket(ws, kind: str, target_id: int) -> None:  # type: ignore[no-un
     except inventory.ValidationError as exc:
         _send(ws, "error", str(exc))
         return
+    _send(ws, "info", f"Anmeldung als {username} …")
 
     with extension.database.transaction(conn):
         audit.log(
@@ -343,6 +364,7 @@ def _run_switch_session(  # type: ignore[no-untyped-def]
     ws, conn, target: Target, username: str, password: str, transcript, idle_timeout: int
 ) -> int:
     commands = 0
+    _send(ws, "info", "Warte auf die Eingabeaufforderung des Switches …")
     with switchcli.SwitchCli(
         conn, host=target.host, port=target.port, username=username, password=password
     ) as cli:
@@ -375,6 +397,7 @@ def _run_client_session(  # type: ignore[no-untyped-def]
     ws, conn, target: Target, username: str, password: str, transcript, idle_timeout: int
 ) -> int:
     commands = 0
+    _send(ws, "info", "Verbindung wird aufgebaut …")
     with shellcli.ShellSession(
         conn, host=target.host, port=target.port, username=username, password=password
     ) as session:

apps/tesm/src/tesm/cli.py

@@ -216,6 +216,123 @@ def cmd_web_setup(args: argparse.Namespace) -> int:
     return run_web_setup(app, extension, args)
 
 
+def cmd_switch_test(args: argparse.Namespace) -> int:
+    """Prueft Stufe fuer Stufe, wo eine Switch-Sitzung haengt.
+
+    Warum ein eigener Befehl und nicht die Konsole im Browser: dort liegen
+    zwischen dem Switch und dem Auge ein WebSocket, ein Reverse Proxy und
+    JavaScript. Wenn nichts ankommt, ist die erste Frage, *welche* dieser
+    Schichten schweigt. Hier gibt es keine davon -- und jede Stufe sagt, was
+    sie bekommen hat, notfalls als rohe Bytes.
+
+    Liest nur, ausser mit ``--zyklus``: dann wird der Port wirklich
+    geschaltet.
+    """
+    from .services import inventory, switchcli
+    from .services.ssh import SshError
+    from tesm_core.db import Database
+    from tesm_core.extension import core
+
+    app = create_app()
+    erweiterung = core(app)
+
+    def sagen(stufe: str, text: str = "") -> None:
+        print(f"  {stufe:<28} {text}".rstrip())
+
+    with app.app_context():
+        with erweiterung.database.session() as conn:
+            zeile = Database.one(
+                conn,
+                "SELECT id, hostname, ip, ssh_port, credential_id FROM switches "
+                "WHERE (hostname=? COLLATE NOCASE OR ip=?) AND deleted_at IS NULL",
+                (args.switch, args.switch),
+            )
+            if zeile is None:
+                print(f"Kein Switch mit Name oder Adresse {args.switch!r}.")
+                print("Vorhanden:")
+                for andere in Database.all(
+                    conn, "SELECT hostname, ip FROM switches WHERE deleted_at IS NULL"
+                ):
+                    print(f"  {andere['hostname']} ({andere['ip']})")
+                return 2
+
+            host = str(zeile["ip"])
+            ssh_port = int(zeile["ssh_port"] or 22)
+            print(f"Switch {zeile['hostname']} ({host}:{ssh_port})")
+            print()
+
+            if not zeile["credential_id"]:
+                sagen("Zugangsdaten", "FEHLT -- dem Switch sind keine zugeordnet")
+                return 1
+            try:
+                benutzer, passwort = inventory.credential_secret(
+                    conn, erweiterung.keystore, int(zeile["credential_id"])
+                )
+            except Exception as fehler:  # noqa: BLE001
+                sagen("Zugangsdaten", f"nicht lesbar: {fehler}")
+                return 1
+            sagen("Zugangsdaten", f"{benutzer} (Passwort {len(passwort)} Zeichen)")
+
+            from .services import ssh as ssh_modul
+
+            for record in ssh_modul.all_known_keys(conn, host, ssh_port):
+                sagen("Freigegebener Schluessel", f"{record.key_type} {record.fingerprint}")
+
+            try:
+                sitzung = switchcli.SwitchCli(
+                    conn,
+                    host=host,
+                    port=ssh_port,
+                    username=benutzer,
+                    password=passwort,
+                )
+                with sitzung as cli:
+                    sagen("Anmeldung", "erfolgreich")
+                    erstes = cli.full_transcript
+                    sagen("Erste Antwort", f"{len(erstes)} Zeichen")
+                    print()
+                    print("--- was der Switch nach der Anmeldung geschickt hat ---")
+                    print(erstes if erstes.strip() else "(nichts)")
+                    print("--- Ende ---")
+                    print()
+
+                    if args.port:
+                        ausgabe = cli.send(
+                            f"show power-over-ethernet {args.port}", tolerate_error=True
+                        )
+                        sagen("Zustandsabfrage", f"{len(ausgabe)} Zeichen")
+                        print("--- show power-over-ethernet ---")
+                        print(ausgabe)
+                        print("--- Ende ---")
+                        sagen("Erkannter Zustand", cli.poe_state(args.port))
+
+                    if args.zyklus:
+                        if not args.port:
+                            print("Fuer --zyklus braucht es --port.")
+                            return 2
+                        ergebnis = cli.cycle_poe(args.port)
+                        sagen("Portzyklus", "erfolgreich" if ergebnis.ok else ergebnis.error)
+                        for schritt in ergebnis.steps:
+                            sagen("", schritt)
+                        if not ergebnis.ok:
+                            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.")
+    return 0
+
+
 def cmd_convert_legacy(args: argparse.Namespace) -> int:
     """Uebersetzt einen Export des alten TESM in das neue Format.
 
@@ -418,6 +535,22 @@ def build_parser() -> argparse.ArgumentParser:
     check = sub.add_parser("check-now", help="Einen Überwachungsdurchlauf sofort ausführen")
     check.set_defaults(func=cmd_check_now)
 
+    pruefung = sub.add_parser(
+        "switch-test",
+        help="Eine Switch-Sitzung Stufe fuer Stufe pruefen",
+        description=(
+            "Meldet sich am Switch an und zeigt, was er schickt -- ohne Browser, "
+            "ohne WebSocket, ohne Reverse Proxy. Liest nur; mit --zyklus wird der "
+            "Port wirklich geschaltet."
+        ),
+    )
+    pruefung.add_argument("switch", help="Name oder IP des Switches, wie in TESM hinterlegt")
+    pruefung.add_argument("--port", help="Portbezeichnung, z. B. 1/8 -- fragt den Zustand ab")
+    pruefung.add_argument(
+        "--zyklus", action="store_true", help="PoE wirklich aus- und wieder einschalten"
+    )
+    pruefung.set_defaults(func=cmd_switch_test)
+
     legacy = sub.add_parser(
         "convert-legacy",
         help="Export des alten TESM in das neue Format übersetzen",

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
-                if PAGER_RE.search(collected[-200:]):
+                sichtbar = ANSI_RE.sub(b"", sichtbar + chunk)
+                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: