docs(infra): recon lustro event=dead prom=up 1507 mismatchy

docs/infra/lustro-shipping-recon-2026-07-16.md

@@ -0,0 +1,213 @@
+# Recon: lustro `event=dead prom=up` — 1507 mismatchy w shadow-liveness.log (2026-07-16)
+
+READ-ONLY recon. Zero zmian w kodzie/serwisach. Wszystkie czasy **UTC**
+(lokalny CEST = UTC+2). Źródła: `/opt/homelab/logs/observer/shadow-liveness.log`
+(VPS), `/opt/homelab/events/lustro/` (VPS), Prometheus
+`query_range up{node="lustro"}` 07-14 12:00 → 07-16 12:15 step 60 s,
+`docker logs/inspect node-agent` na lustro (pimirror2, 100.99.85.73)
+i porównawczo na PIHA.
+
+## TL;DR — werdykt: (1) test + boot-race, shipping DZIAŁA
+
+**1507 wpisów `node=lustro event=dead prom=up` to dokładnie 2 epizody,
+oba wyjaśnione, żaden nie jest przerwą w shippingu eventów:**
+
+- **1499 wpisów = wczorajszy kontrolowany test** (stop node-agenta na żywym
+  węźle) — tyle że node-agent stał **3 h 20 min** (13:55:08 → 17:14:56),
+  a nie ~15 min. Przy kadencji observera ~7,6 s daje to arytmetycznie
+  1499 wpisów. Prometheus przez całe okno widział `up==1` (poprawnie —
+  host żył). To jest zamierzony scenariusz z Etapu 1 recon, tylko dłuższy
+  niż zapamiętany.
+- **8 wpisów = dzisiejszy poranny boot-race** (04:30:51 → 04:31:47, ~56 s):
+  po power-onie Prometheus zaliczył scrape szybciej, niż dotarł pierwszy
+  poprawny event node-agenta. `last_seen_age=25346s` (~7 h) to wiek
+  *ostatniego eventu sprzed nocnego power-off 21:29*, a nie długość
+  mismatcha — samo okno dead/up trwało niecałą minutę.
+
+Nocne 7 h (21:39 → 04:30) nie generuje wpisów, bo oba tory zgodnie mówią
+"dead/down". **Nie ma recurring problemu shippingu** — eventy płyną ~233/h
+(najświeższy dziś 12:19). Są za to dwa realne, chroniczne quirki opisane
+w C (log-noise rsync exit 23 od 06-11 + stale-timestamp pierwszego batcha
+po boocie przez fake-hwclock), oba nieblokujące i oba **wzmacniające**
+rekomendację cutoveru na Prometheus (E).
+
+## A. Rozkład czasowy 1507 wpisów
+
+Klastrowanie po przerwach > 60 s między kolejnymi wpisami daje **2 epizody**
+(suma 1499 + 8 = 1507 ✓):
+
+| ep | okno (UTC) | n | czas trwania | last_seen_age | implikowany ostatni event |
+|---|---|---|---|---|---|
+| 1 | 07-15 14:05:14 → 17:14:54 | 1499 | 3 h 10 min | 606 s → 11 987 s (monotonicznie ↑) | 07-15 13:55:08 |
+| 2 | 07-16 04:30:51 → 04:31:47 | 8 | 56 s | 25 297 s → 25 354 s | 07-15 21:29:14 |
+
+- **Ep1 = test.** Pierwszy wpis dokładnie na granicy TTL-dead (606 s po
+  ostatnim evencie 13:55:08). Kadencja ~7,6 s/wpis (cykl observera);
+  11 380 s / 7,6 ≈ 1497 ✓. Zero świeżych eventów w całym oknie
+  (age rośnie liniowo bez resetu) i **zero backlogu** — po wznowieniu nie
+  spłynęły żadne eventy ze stemplami 14:00–17:14, czyli agent nie działał
+  (nie "działał, ale nie wysyłał"). Granice z katalogu eventów na VPS:
+  ostatni batch 13:55:08, pierwszy po przerwie 17:14:56, syntetyczny
+  `node_online` 17:15:02. **Test trwał 3 h 20 min, nie ~15 min** —
+  rozjazd z pamięcią operatora *do weryfikacji* (dane są jednoznaczne).
+- **Ep2 = boot-race po nocnym power-off.** 8 cykli × ~7,5 s = 56 s.
+  Szczegóły i przyczyna wydłużenia w C2.
+- Log zawiera też (poza zakresem zagadki): 16× lustro `fresh prom=down` +
+  53× `stale prom=down` (wczorajszy power-off 21:30–21:39 — znany wzorzec
+  z analizy Etapu 2), analogiczne wpisy solaria oraz **1 wpis
+  `node=solaria event=dead prom=up`** (07-16 12:03:36, age 60 931 s) —
+  pojedynczy cykl przy dzisiejszym power-onie solarii, ten sam boot-race
+  co ep2, wygasł natychmiast (brak kolejnych wpisów do 12:19).
+
+## B. Korelacja z cyklem lustro i historią Prometheusa
+
+`up{node="lustro"}` 07-14 12:00 → 07-16 12:15 (2896 próbek, step 60 s) ma
+**dokładnie 4 przejścia** — idealny nocny cykl, zero flappingu:
+
+```
+07-14 21:30 up=1→0   07-15 04:31 up=0→1   (noc 1: 7,0 h off)
+07-15 21:30 up=1→0   07-16 04:31 up=0→1   (noc 2: 7,0 h off)
+```
+
+- **Okno ep1 (07-15 14:05–17:14) leży w całości w `up==1`** → lustro żyło,
+  a nie wysyłało eventów = definicja scenariusza testowego. Realny problem
+  shippingu wyglądałby identycznie — rozstrzyga tu brak backlogu (A) +
+  `docker logs` z lustro (C): agent był zatrzymany, nie "wysyłający w próżnię".
+- **7 h `event=dead` do 04:31 pokrywa się z `up==0`** (21:30 → 04:31) —
+  czyli przez noc oba tory były zgodne (dead/down, zero mismatchy).
+  Mismatch dead/up pojawia się wyłącznie w 56-sekundowym oknie na styku
+  boot ↔ pierwszy event. Task-owa hipoteza "7 h okno event=dead prom=up"
+  nie potwierdza się: 7 h to wiek stempla, nie długość rozbieżności.
+- Trwały log istnieje dopiero od 07-15 13:44 (deploy `9e7ed3e`), więc
+  wcześniejszych poranków w nim nie ma — dominacja lustro w liczniku (1507
+  vs 1 solaria) to artefakt tego, że test odbył się 21 min po włączeniu
+  trwałego logu i trwał 3 h.
+
+## C. Stan shippingu na lustro (pimirror2)
+
+Dostęp: klucz na `pi@100.99.85.73` działa bez hasła (autoryzowany
+najpóźniej od wczorajszej sesji). Host: boot ~04:30 UTC (uptime 7 h 51 min
+o 12:21), `System clock synchronized: yes`, NTP active.
+
+**Kontener node-agent: `Up (healthy)`, `RestartCount=0`, restart policy
+`unless-stopped`, bez OOM.** Eventy płyną (najświeższy batch na VPS 12:19).
+Mounty: `/home/pi/.ssh → /home/homelab/.ssh` (ro), `/opt/homelab` (rw),
+docker.sock; kontener działa jako `1000:1000` = uid `pi` → **brak uid
+mismatch po stronie lustro** (klucz czytelny).
+
+### C1. Chroniczny WARNING „Event shipping failed" — kosmetyczny, ale zaśmieca od 06-11
+
+`docker logs node-agent` zawiera **34 325** wpisów
+`Event shipping failed: … rsync: failed to set times on
+"/opt/homelab/events/lustro/.": Operation not permitted … (code 23)` —
+**co cykl (~62 s), nieprzerwanie od 2026-06-11** (pierwszy wpis 19 s po
+starcie kontenera). Mimo WARNING **pliki się przenoszą**: exit 23 = "some
+files/attrs were not transferred" i dotyczy wyłącznie mtime **katalogu**
+docelowego. Przyczyna po stronie VPS: `/opt/homelab/events/lustro/` należy
+do `aerbot:aerbot` (uid 1000), a rsync loguje się jako `oskar` (uid 1002,
+członek grupy aerbot) — może pisać pliki (group-write), nie może dotykać
+atrybutów katalogu. **To ta sama klasa co na PIHA.**
+
+**Fix już istnieje w repo** — `f37f85f` (`--omit-dir-times`) + `cc5c792`
+(`--no-perms/--no-owner/--no-group`), oba 2026-07-13, w
+`services/node-agent/src/node_agent.py:648-671` — ale **lustro działa na
+obrazie zbudowanym 2026-06-09** (kontener created 06-11), czyli sprzed
+fixa. Porównawczo PIHA: obraz z 07-13 21:17 (3 min po `cc5c792`),
+**0 błędów shippingu w ostatnich 24 h**. To kolejna manifestacja buga
+`deploy-node.sh` bez `--build` (backlog `c858dbc`) — fix w repo, runtime
+na starym obrazie.
+
+Ryzyko realne tego quirku to nie utrata eventów, lecz **maskowanie**:
+skoro każdy cykl od 35 dni loguje "failed", prawdziwa awaria shippingu
+wyglądałaby w logu identycznie (boy-who-cried-wolf).
+
+### C2. Fake-hwclock: pierwszy batch po boocie ma stempel sprzed power-off i jest cicho gubiony
+
+Dowód z dzisiejszego poranka:
+
+- `docker inspect node-agent`: `StartedAt=2026-07-15T21:30:34Z` przy
+  hoście zabootowanym **dziś 04:30** — RPi wystartował z zegarem
+  przywróconym przez fake-hwclock do wartości zapisanej przy wczorajszym
+  shutdownie (21:30). Stąd też mylące `docker ps` „Up 15 hours" przy
+  uptime hosta 7 h 51 min.
+- Batch `evt-lustro-1784151037-*` (stempel „07-15 21:30:37") jest **poza
+  kadencją** (62 s: po 21:29:14 następny byłby ~21:30:16; 21:30:37 =
+  StartedAt 21:30:34 + ~3 s startu agenta) → wyemitowany **dziś ~04:30:37
+  realnego czasu**, przy jeszcze niezsynchronizowanym zegarze.
+- Że nie istniał wczoraj wieczorem, dowodzi shadow-log: wczoraj o 21:39:12
+  observer liczył `last_seen_age=598s` → last_seen 21:29:14 (nie 21:30:37);
+  dziś w ep2 o 04:31:47 `age=25354s` → last_seen **nadal 21:29:14**.
+  Czyli batch dotarł na VPS dziś rano, ale **observer nigdy go nie
+  policzył**: checkpoint lustro stał po syntetycznym `node_offline`
+  (ts 21:39:20) > 21:30:37, więc timestampowy checkpoint (fix `d5139c9`)
+  odrzucił go jako "starszy" — **cichy drop**. (Mtime pliku na VPS
+  „21:30:37" niczego nie rozstrzyga — rsync `-t` przenosi mtime źródła.)
+- Skutek praktyczny dziś: ep2 wydłużony o ~45 s (gdyby pierwszy batch miał
+  poprawny stempel, mismatch skończyłby się ~04:31:00, a nie po batchu
+  04:31:44). Skutek systemowy: **każdego ranka pierwszy cykl node-agenta
+  ściga się z NTP**; przegrana = batch z 7-godzinnym wstecznym stemplem,
+  na zawsze niewidzialny dla observera. Wczorajszy poranek (07-15 04:31)
+  śladu stale-batcha nie ma — race bywa wygrywany. Uwaga: `timedatectl`
+  na lustro pokazuje „RTC time" — czy istnieje fizyczny RTC (i czemu nie
+  trzyma czasu) — *do weryfikacji*.
+
+## D. Werdykt: (1) — test + jednorazowy artefakt boot, NIE recurring bug shippingu
+
+**1507 = 1499 (test, 3 h 20 min) + 8 (boot-race, 56 s).** Shipping eventów
+z lustro działa ciągle i dziś (233 batche/h, zero utraconych okien poza
+zatrzymanym agentem podczas testu). Nie ma dowodu na jakąkolwiek
+niezamierzoną przerwę shippingu po nocnym power-cycle.
+
+Niuans do (1): recon ujawnił dwa chroniczne, **nieblokujące** defekty
+niższego rzędu, oba z gotowym lub znanym kierunkiem fixa:
+
+1. **Log-noise rsync exit 23** (C1) — od 06-11, fix w repo od 07-13,
+   niezdeployowany na lustro (stary obraz; bug `deploy-node.sh --build`).
+2. **Stale-timestamp po boocie** (C2) — fake-hwclock vs NTP race; dziś
+   przegrany (batch zgubiony + ~45 s dłuższy dead/up), wczoraj wygrany.
+   Klasyka motywu "nazwa/stempel ≠ tożsamość" z sesji 07-15: observer
+   cicho dropuje zamiast kwarantannować.
+
+## E. Implikacja dla Etapu 3 — POTWIERDZONA, recon wzmacnia cutover
+
+- **Prometheus w całym 48 h oknie ani razu się nie pomylił**: `up==1`
+  przez cały test (host żył — racja), `up==0` równo w oknach power-off
+  (racja), `up==1` w ≤60 s od porannego bootu (szybszy niż event-tor).
+  Problem C1/C2 w ogóle nie dotyka toru Prometheusa.
+- **Tor eventowy lustro jest strukturalnie kruchy wokół cyklu dobowego**:
+  (a) po boocie przegrywa wyścig z NTP i potrafi zgubić pierwszy batch,
+  (b) jego wiarygodność zależy od działania node-agenta (test = 3 h 20 min
+  fałszywego "dead" na żywym węźle — semantycznie poprawne, ale operacyjnie
+  ślepe), (c) jego log błędów jest od 35 dni nieodróżnialny od realnej
+  awarii. Po cutoverze na `up{}` każdy z tych trybów awarii przestaje
+  wpływać na liveness lustro.
+- Wniosek zgodny z analizą Etapu 2: **cutover lustro na Prometheus — GO**;
+  ten recon dostarcza dodatkowo brakujący w analizie 07-15 przypadek
+  `event=dead prom=up` na dużej próbce (1499 cykli) z poprawnym werdyktem
+  Prometheusa w 100% próbek.
+
+## Rekomendacje
+
+1. **Redeploy node-agent na lustro z rebuildem obrazu** (fix rsync już
+   w repo; przy okazji wejdzie `4746ebe`). Potwierdza też pilność fixa
+   `deploy-node.sh --build` (backlog).
+2. **Observer: kwarantanna zamiast cichego dropu** eventów ze stemplem <
+   checkpoint (dokładnie przypadek C2; spójne z istniejącym TODO walidacji
+   `node` w treści vs katalog).
+3. **Lustro: związać start node-agenta z synchronizacją czasu** (np.
+   warunek `time-sync.target` / sprawdzenie `timedatectl` przed pierwszą
+   emisją) albo chrony `makestep` przed startem Dockera — eliminuje C2
+   u źródła. Wyjaśnić status RTC (*do weryfikacji*).
+4. Bez zmian dla planu Etapu 3 (kolejność solaria/lustro → vps/piha,
+   mapping `timestamp(up)` → `compute_liveness`).
+
+## Do weryfikacji (nie do ustalenia z dostępnych danych)
+
+- Dlaczego test 07-15 trwał 3 h 20 min zamiast ~15 min (przebieg po
+  stronie operatora; dane wykluczają samoczynny restart — `RestartCount=0`,
+  wznowienie 17:14:56 wygląda na ręczny `docker start`).
+- Czy lustro ma fizyczny RTC (timedatectl raportuje „RTC time"), a jeśli
+  tak — czemu nie trzyma czasu przez noc.
+- Częstość przegrywania race'u NTP (C2): dziś tak, wczoraj nie; 1 próbka
+  „tak" nie wystarcza do oceny częstości — obserwować poranki w trwałym
+  logu (wpisy dead/up ~04:31 z age ~25 000 s).