From 542bba469330ff2df398ea42a0742397f86b5012 Mon Sep 17 00:00:00 2001 From: oskar Date: Thu, 16 Jul 2026 14:28:04 +0200 Subject: [PATCH] docs(infra): recon lustro event=dead prom=up 1507 mismatchy --- .../infra/lustro-shipping-recon-2026-07-16.md | 213 ++++++++++++++++++ 1 file changed, 213 insertions(+) create mode 100644 docs/infra/lustro-shipping-recon-2026-07-16.md diff --git a/docs/infra/lustro-shipping-recon-2026-07-16.md b/docs/infra/lustro-shipping-recon-2026-07-16.md new file mode 100644 index 0000000..8650e12 --- /dev/null +++ b/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).