Files
bf-infra/docs/handoff-20260901-fund-e-hebel1-zurueckgebaut.md
Christoph Emsenhuber 07b595c45a TP25 Fund E: Hebel 1 widerlegt und zurueckgebaut -- Ringpuffer-Messfehler korrigiert
Zwei Sessions haben denselben Fall bewertet und kamen zu entgegengesetzten
Schluessen. Aufgeloest zugunsten der Kollektor-Messung.

Der Widerspruch und sein Beleg:
- Die Nacht-Session las `get_log ... sinceMinutes=1440` -> total 0 und schloss
  auf "Fund E geheilt, Hebel 1 committen". Das ist der FLUECHTIGE Ringpuffer des
  Routers: live nachgemessen 1000 Zeilen, aeltester Eintrag 01.09. 00:38:58 --
  keine 9 h Tiefe. Der Core-Reboot 14:36 hatte ihn geleert, der 31.08. Vormittag
  war darin nicht enthalten. "total 0" hiess "im Puffer nichts", nicht "in 24 h
  nichts" -- genau die Falle, wegen der am 30.08. der Kollektor gebaut wurde.
- Im Kollektor stehen fuer 08:09-14:36 (Hebel 1 ALLEIN, vor dem Upgrade) 124x
  reauthenticating: 09h=1, 11h=2, 12h=20, 13h=31, 14h=70 -- alle vom iPhone
  allein, also Client-Befund nach der eigenen Merkregel. Dazu Christophs zwei
  erlebte Ausfaelle 13:16 und 14:23. Zwischen 09:00 und 14:36 lag kein Reboot.

Daraus gehandelt (User-Entscheid: symmetrisch am Geraet, jetzt):
- Backup pre-tp25-funde-rollback, dann ft-over-ds=yes + remote-cap provision
- Rueckbau-Diff zeigte genau eine Abweichung, kein Kollateral
- Abnahme: CAPs durchgehend Ok, ap2 9/9 und ap3 9/9 running, frische DHCP-Lease
  (~1 min alt), Transaktion "zurueckgebaut", Compliance 140/140
- Der Rueckbau IST das Experiment: bleibt es ruhig, war 7.24.1 die Ursache;
  kehrt das Haemmern zurueck, hatte die Nacht-Session recht. Bis zur Messung
  am 2026-09-02 frueh committet niemand.

Zwei Nebenbefunde:
- gc-configplan.py --refresh-compliance scheitert STILL ohne NAUTOBOT_TOKEN:
  Meldung ausgegeben, aber Exit-Code 0. Gehoert gefixt.
- Compliance ist 140/140, nicht 135/135: es gibt eine 28. ComplianceRule
  `interface-veth`, angelegt 31.08. 20:04, Urheber offen.

Der ap2-Befund der Nacht-Session (2 m Abstand, -80 dBm, 0 Clients auf ap2)
bleibt unberuehrt gueltig und ist weiter der beste Hinweis auf die
23:02-Stoerung. CLAUDE.md enthaelt in diesem Commit auch deren TP16.3-Zeile
(gemeinsame Datei, Hunks nicht trennbar).

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
2026-09-01 09:21:46 +02:00

10 KiB
Raw Permalink Blame History

Handoff 2026-09-01 — Hebel 1 widerlegt und zurückgebaut, 7.24.1 ist der Verdächtige

Vorgänger: handoff-20260831-tp27-upgrade-und-hebel1-befund.md. Dieses Dokument ist der Stand danach. Offene Aufgabe: eine Messung am 2026-09-02 früh.

Die Messung, die Hebel 1 widerlegt

Fenster Bedingung iPhone-reauthenticating pro Stunde
31.08. 07:00–08:00 Baseline 79 79
31.08. 08:09–14:36 nur Hebel 1 (ROS 7.24) 124 ~19
31.08. 14:37–24:00 Hebel 1 + 7.24.1 17 ~1,8
01.09. 00:00–07:57 Hebel 1 + 7.24.1 0 0

6,4 Stunden Hebel 1 allein haben nichts verbessert. Der Einbruch fällt exakt auf den Core-Reboot um 14:36 — also auf das TP27-Upgrade, nicht auf den Hebel.

Beide Gegenproben bestanden — ohne sie wäre die Null wertlos:

  • War das Telefon da? Ja: 27 Zeilen am 01.09., mehrfaches Roaming, live verbunden.
  • Lief das Logging? Ja: keine Lücke > 15 min in der Tagesdatei.

🔴 Widerspruch zu einer Parallelsession — und wie er aufzulösen ist

Eine zweite Session hat in der Nacht denselben Fall bearbeitet und kam zum gegenteiligen Schluss: handoff-20260901-tp25-ap2-verdacht.md wertet Fund E als geheilt durch Hebel 1 und empfiehlt, ihn zu committen.

Ihr Beleg war eine Fehlmessung. Zitiert wird get_log topics=[wireless] prefix=reauthenticating sinceMinutes=1440 → total 0. Das ist der flüchtige Ringpuffer des Routers, nicht der Kollektor:

/log am Core, live geprüft 2026-09-01 09:1x:
  1000 Zeilen im Ringpuffer, ältester Eintrag 2026-09-01 00:38:58   ← keine 9 Stunden Tiefe

Der Core wurde am 31.08. um 14:36 neu gestartet; der Puffer war danach leer und um 01:18 längst überschrieben. Eine 1440-Minuten-Abfrage konnte den 31.08. Vormittag nicht sehen — total 0 heißt „im Puffer nichts", nicht „in 24 h nichts". Genau diese Falle war der Anlass, am 30.08. das persistente Logging einzurichten (CLAUDE.md: „ein seit Wochen gemeldetes Client-Problem war rückwirkend nicht diagnostizierbar").

Der zweite Einwand — die 124 seien Reboot-Artefakte — trägt ebenfalls nicht. Die Upgrade-Reboots waren ap2 08:56, core 14:36, ap1 14:50, branch 14:52. Zwischen 09:00 und 14:36 gab es keinen Reboot, und in diesem Fenster stehen im Kollektor 09h=1, 11h=2, 12h=20, 13h=31, 14h=70 — alle vom iPhone allein, also nach dem eigenen Gotcha der Session (viele MACs = Infrastruktur, eine MAC = Client) ein Client-Befund. Dazu Christophs zwei erlebte Ausfälle um 13:16 und 14:23.

⚖️ Auflösung: der Rückbau IST das Experiment, das den Streit entscheidet. Steht ft-over-ds wieder auf yes und bleibt es trotzdem ruhig, war 7.24.1 die Ursache. Kommt das Hämmern zurück, hatte die Parallelsession recht und Hebel 1 wird als neue Transaktion erneut gezogen. Vor dem 2026-09-02 früh sollte niemand committen.

✅ Unabhängig davon wertvoll: ihr ap2-Befund. Am 31.08. um 23:02 meldete Christoph eine Störung am Schreibtisch; die Session maß −80 dBm bei 2 m Abstand zu ap2, not responding bei −82, und 0 Clients auf ap2 bei 29 auf ap3. Das ist weder Coverage noch FT, sondern ein Hardware-/Störungsverdacht (Kandidat: DTU auf ch11, Transaktion TP17.1-dtu-pin-ap2). Das erklärt den 23:02-Schmerz, den mein Rückbau nicht adressiert — eigener Strang, braucht eine In-situ-Messung.

Was heute getan wurde: Rückbau statt Commit

Warum nicht committen: Solange Hebel 1 steht, sind zwei Änderungen gleichzeitig aktiv. Der Rückbau isoliert das Upgrade — er ist der Test, nicht bloß Aufräumen. Und weil das GC-Template in Z. 220 ohnehin ft-over-ds=yes führt, kommt die Compliance ohne Template-Änderung zurück.

Weg symmetrisch zum Hinweg (Christoph-Entscheid), also am Gerät, nicht über GC:

/system backup save name=pre-tp25-funde-rollback      # 0
/interface wifi security set [find name="sec-main"] ft-over-ds=yes
/interface wifi capsman remote-cap provision [find]

Der Rückbau-Vorschlag aus dem Snapshot zeigte genau eine Abweichung — kein Kollateral-Drift:

JETZT NUR AM GERAET  ... ft=yes ft-over-ds=no  name=sec-main
IM SNAPSHOT, FEHLT   ... ft=yes ft-over-ds=yes name=sec-main

Abnahme

Prüfung Ergebnis
ft-over-ds am Core ft=yes ft-over-ds=yes ✓
CAPs 3 × Ok, CAPWAP-Verbindung ununterbrochen (17 h) — provision trennt sie nicht
VAPs am CAP gelesen ap2 9/9 running, ap3 9/9 running
Frische DHCP-Lease (die vorgeschriebene Abnahme) iPhone 10.40.10.196, bound, expires-after 23h58m56s bei 24 h Laufzeit ⇒ ~1 min alt
Clients 25 → 28 zurück
Transaktion gc-transaktion.py status → zurueckgebaut, kein Drift im Scope
Compliance 140/140, 0 Drifts — ohne jede Template-Änderung, wie vorhergesagt

⚠️ Zwei Nebenbefunde beim Compliance-Lauf

1. gc-configplan.py --refresh-compliance scheitert STILL, wenn NAUTOBOT_TOKEN fehlt — Ausgabe „NAUTOBOT_TOKEN nicht gesetzt", danach Exit-Code 0. Wer nur den Rückgabewert prüft, hält einen nie gelaufenen Compliance-Check für erfolgreich. Behelf in dieser Session:

NAUTOBOT_TOKEN="$(sed -n 's/^[[:space:]]*-[[:space:]]*NAUTOBOT_SUPERUSER_API_TOKEN=//p' \
  docs/nas-vlan20/stacks/210-nautobot.yml | head -1)" python3 nautobot/gc-configplan.py --refresh-compliance

Dauerhafte Antwort wäre NAUTOBOT_TOKEN in ~/.secrets/exports.zsh (steht schon im Handoff vom 31.08. als offener Punkt). ⇒ Der Exit-Code gehört gefixt, sonst wiederholt sich das.

2. Die Compliance-Zahl ist von 135 auf 140 gestiegen — das ist erklärt, nicht übergangen. Es gibt jetzt 28 ComplianceRules statt 27 (5 Geräte × 28 = 140). Neu ist interface-veth, angelegt 2026-08-31 20:04, also nach der Session vom 31.08. und nicht in dieser hier. 🔴 Wer sie angelegt hat, ist offen — veth betrifft Container auf RouterOS. Bitte klären, bevor jemand die Zahl als Basislinie zitiert.

🔴 Die cap-wifiN-Karte ist beim Provisionieren SOFORT wieder gewandert

Innerhalb dieser Session, zwischen zwei Reads im Abstand von Minuten:

vor dem Rückbau (galt 31.08. 14:52 – 01.09. 08:2x) ab jetzt
ap3 cap-wifi3 / cap-wifi4 cap-wifi3 / cap-wifi5
ap2 cap-wifi5 / cap-wifi6 cap-wifi4 / cap-wifi6
ap1 cap-wifi1 / cap-wifi2 getauscht (cap-wifi2 / cap-wifi1)

Belastbar ist nur die radio-mac, weil sie am Gerät hängt: ap3 …:9F = 5 GHz → cap-wifi3 · ap3 …:A0 = 2,4 GHz → cap-wifi5 · ap2 …:3E → cap-wifi4 · ap2 …:3F → cap-wifi6 · ap1 …:E5 → cap-wifi2 · …:E6 → cap-wifi1 (Bandzuordnung für ap2/ap1 in dieser Session nicht nachgemessen — nicht raten.)

⚠️ Folge für die Auswertung: Logzeilen vom 01.09. vor ca. 08:25 gehören zur linken Spalte. Sie sind zuschreibbar, weil im ganzen Messfenster 0 caps-Ereignisse standen — das war Glück, kein Verdienst.

Die Messung am 2026-09-02

ssh root@10.40.20.100 "pct exec 400 -- sh -c '
  D=/opt/tp5-syslog/log/10.40.20.1;
  echo -n \"caps:   \"; grep -c \" caps,\" $D/2026-09-02.log;
  echo -n \"reauth: \"; grep reauthenticating $D/2026-09-02.log | grep -c E1:AF:09;
  echo -n \"iPhone da? \"; grep -c E1:AF:09 $D/2026-09-02.log'"

Reihenfolge einhalten: erst caps (Rejoins erzeugen Bursts, die wie ein Client-Problem aussehen), dann reauth, dann die Anwesenheitsprobe. Vergleichszeitraum ist 07:00–08:00 — dort standen am 31.08. 79 Ereignisse, am 01.09. null.

Ergebnis Schluss Nächster Schritt
weiter ~0 7.24.1 hat es behoben, Hebel 1 war wirkungslos Fund E schließen; offen bleibt das Band-Ping-Pong (s. u.)
Hämmern kommt zurück Hebel 1 hat doch beigetragen neue Transaktion, ft-over-ds=no erneut — diesmal auf 7.24.1 isoliert

Neues Symptom, das die Reauth-Schleife ablöst: Band-Ping-Pong

Am 01.09. hämmert nichts mehr, aber das iPhone oszilliert zwischen den beiden Bändern desselben AP (alte Karte, also ap3 5 GHz ↔ ap3 2,4 GHz):

01:49:14  ap3-2,4G → ap3-5G   (−65)
01:49:32  ap3-5G  → ap3-2,4G  (−55)   ← 18 s später zurück
01:50:28  ap3-2,4G → ap3-5G   (−69)
07:45 / 07:46 / 07:47   dasselbe im Minutentakt

Verbindungsalter beim Nachsehen: 1:26 min bei −72 dBm. Das ist kein Auth-Problem mehr, sondern genau das, wofür Hebel 3 (2g-probe-delay=yes) gedacht war. Nicht in diesem Durchgang.

⚠️ Zwei Anomalien aus dem Gesamtlog — eigener Durchgang, nicht nebenbei

1. Das Log besteht zu 98,4 % aus Rauschen. 5457 von 5548 Zeilen sind Firewall-Drops, davon 3810 MNDP-Broadcasts (udp/5678) der eigenen Netzgeräte (ap1/ap2/ap3/branch, je ~950/Tag). Nutzsignal 1,6 % — in genau dem Log, das unser Diagnosewerkzeug ist.

2. 🔴 IGMP aus VLAN30 wird verworfen (funktional, nicht kosmetisch):

in:vlan30 proto 2, 10.40.30.211->224.0.0.251
in:vlan30 proto 2, 10.40.30.215->224.0.0.251

Membership-Reports für die mDNS-Gruppe von zwei IoT-Geräten. Der Core betreibt mdns-repeat-ifaces — er verwirft also Anmeldungen für genau den Dienst, den er weiterreichen soll. Kandidat für Matter/HomeKit-Discovery-Probleme (TP12.1).

3. Nebenbefund zur Hypothese: dirtyvader-iot (mit ft=no) hatte am 31.08. 7 reauthenticating, und association rejected, no cached PMK tritt dort ebenfalls auf. Die ursprüngliche Trennschärfe „93/93 nur auf der ft=yes-SSID" galt für die Nacht-Baseline, nicht für den vollen Tag. no cached PMK ist PMKSA-Caching und nicht FT-spezifisch.

Unverändert offen

  1. TP25-Messrunde mit Rundgang (bash docs/tp25-runde.sh) — Terrasse und Arbeitszimmer; ap-map dabei neu einfrieren (s. o., sie wandert bei jedem Provision).
  2. Passwort-Rotation TP30 (Admin-PW am 08-30 verbrannt).
  3. ap1-Umzug ans Sideboard (core ether3, 5260/Ce, Frequenz-Liste, tx-power vorher messen).