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

# 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).