diff --git a/docs/infra/prometheus-shadow-etap2-analiza-2026-07-15.md b/docs/infra/prometheus-shadow-etap2-analiza-2026-07-15.md new file mode 100644 index 0000000..3561402 --- /dev/null +++ b/docs/infra/prometheus-shadow-etap2-analiza-2026-07-15.md @@ -0,0 +1,226 @@ +# Prometheus cutover — Etap 2: analiza zgodności shadow-run (2026-07-15) + +Analiza READ-ONLY logów `SHADOW_LIVENESS_MISMATCH` observera (parallel-run od +2026-07-09, okno wiarygodne od ~2026-07-13 po naprawach event-shippingu PIHA +i zatrutego checkpointu leksykalnego). Zero zmian w kodzie serwisów. + +## TL;DR — werdykt + +**Zagadka rozwikłana: żaden ze 165 mismatchy nie jest błędem Prometheusa.** +Wszystkie 165 wpisów to **dwa wyłączenia węzłów wieczorem 2026-07-14** +(lustro 21:30 UTC — planowy nocny power-off, solaria 21:34 UTC), zalogowane +w oknie, w którym tor eventowy jeszcze „dożywał" swojego TTL. Wzorzec +`event=fresh prom=down` to **nie** „żywy węzeł, którego Prometheus nie widzi" — +to **martwy węzeł, którego Prometheus wykrył w ≤45 s, a tor eventowy potrzebował +600 s**. Prometheus był w każdym przypadku *szybszy i miał rację*. + +- **vps, piha**: 0 mismatchy, 0 próbek `up==0` przez całe 84 h okna + (07-12 → 07-15), 0 przejść liveness po stronie eventowej od ≥ 07-11. + → **Prometheus w pełni wiarygodny — kandydaci do przełączenia w Etapie 3.** +- **solaria, lustro**: `prom=down` zawsze = węzeł fizycznie wyłączony. + Zero przypadków „prom=down przy realnie żywym węźle". → **NIE dyskwalifikuje + ich z cutoveru**; nocne okna off to normalny stan, który już dziś generuje + `node_offline` (alert-path bez zmian, tylko ~9,5 min wcześniej). +- Kryterium wyjścia Etapu 2 („zero **niewyjaśnionych** rozbieżności") — **spełnione**: + każda rozbieżność sklasyfikowana jako znana różnica semantyk (detection lag + TTL vs scrape), nie bug. + +## Metodologia i ograniczenia danych + +Źródła (surowe dane w scratchpadzie sesji, komendy odtwarzalne): + +1. `docker logs control-plane-observer --since 2026-07-13` na VPS, grep + `SHADOW_LIVENESS_MISMATCH` + `query failed` + `Starting observer loop`. +2. `GET /api/v1/query_range?query=up{job="fleet-node"}&step=30` za 07-12 00:00 → + 07-15 12:50 UTC (10 181 próbek na serię; Prometheus działa nieprzerwanie + od 2026-06-30 15:04, RestartCount=0). +3. Syntetyczne eventy przejść observera (`source: "observer"`) z + `/opt/homelab/events//` na VPS — trwały zapis, pokrywa okres sprzed + dostępnych logów docker. + +**Ograniczenie:** kontener observera został odtworzony 2026-07-14 16:30 UTC +(StartedAt; RestartCount=0 — recreate, nie crash), więc logi docker pokrywają +tylko ~20 h (07-14 16:30 → 07-15 12:50). Mismatche z 07-13 (wyłączenia: solaria +19:22, lustro 21:30) przepadły z logami starego kontenera — ale okna te +zrekonstruowano z (2)+(3) i mają identyczny przebieg. Wszystkie wnioski +o vps/piha są dodatkowo podparte pełnymi 84 h historii `up{}` i brakiem +jakichkolwiek przejść liveness w eventach od 07-11. + +## A. Rozkład czasowy mismatchy + +**165/165 mismatchy leży w jednym zwartym oknie 2026-07-14 21:30:14 → 21:43:52 UTC.** +Zero rozproszonych wpisów w pozostałych ~20 h logów. Rozkład per węzeł: + +| węzeł | wzorzec | n | okno (UTC) | last_seen_age | +|---|---|---|---|---| +| lustro | `event=fresh prom=down` | 22 | 21:30:14 → 21:32:39 | 29 s → 174 s (monotonicznie ↑) | +| lustro | `event=stale prom=down` | 61 | 21:32:46 → 21:39:43 | 181 s → 597 s (monotonicznie ↑) | +| solaria | `event=fresh prom=down` | 21 | 21:34:31 → 21:36:50 | 36 s → 175 s (monotonicznie ↑) | +| solaria | `event=stale prom=down` | 61 | 21:36:57 → 21:43:52 | 182 s → 597 s (monotonicznie ↑) | +| piha / vps | — | 0 | — | — | + +Kadencja wpisów co ~6,9 s = jeden na cykl observera (5 s pętli + ~2 s +przetwarzania). Sekwencja per węzeł jest podręcznikowa: ostatni event węzła → +age rośnie liniowo → przy 180 s tier `fresh→stale` → przy 600 s tier +`stale→dead` → `event=dead prom=down` = zgoda → **mismatche ustają dokładnie +na granicy TTL-dead**. Okno mismatchy per wyłączenie ≈ 600 s − (lag scrape +~15–45 s) ≈ 9,5 min → ~82 wpisy. Bilans: 83 (lustro) + 82 (solaria) = 165. ✓ + +**Kluczowa obserwacja:** `last_seen_age` rośnie monotonicznie od pierwszego +wpisu. Węzeł **nie wysyłał** świeżych eventów w trakcie okna — jego *ostatni* +event był po prostu młodszy niż 180 s. „fresh" opisuje wiek ostatniego eventu, +nie bieżącą aktywność. + +## B. Korelacje + +**Pora nocna / harmonogram — TAK, to jest cała historia.** Pełna historia +`up{}` 07-12 → 07-15: + +| węzeł | okna `up==0` (UTC) | charakter | +|---|---|---| +| lustro | 07-12 21:30→04:31 · 07-13 21:30→04:30 · 07-14 21:30→04:30 (każde równo 7,00 h) | **idealnie regularny nocny power-off 21:30 UTC = 23:30 lokalnie; wstaje 04:30 UTC = 06:30** | +| solaria | 07-12 00:00→16:58 · 07-12 22:28→17:11 · 07-13 19:22→12:46 · 07-14 21:34→07-15 12:20 | nieregularne, wielogodzinne — węzeł włączany „do pracy", off przez większość doby | +| piha | brak (100% up, 84,8 h) | always-on | +| vps | brak (100% up, 84,8 h) | always-on | + +**Restarty Prometheusa/observera — NIE.** Prometheus up od 2026-06-30 bez +restartu. Observer odtworzony 07-14 16:30 — 5 h *przed* oknem mismatchy; +w logach zero `shadow-read: Prometheus query failed` (observer→9090 stabilne +przez całe 20 h). + +**Solaria ↔ lustro nawzajem — NIE (przyczyny niezależne).** Onset 4 min osobno +(21:30:00 ostro co noc dla lustro — timer/smart-plug; solaria zmiennie: 19:22, +21:34, 22:28 w różne dni). Wspólna przyczyna infrastrukturalna wykluczona: +piha i vps scrape'owane bez zakłóceń przez te same okna, po tym samym +Tailscale, przez ten sam Prometheus. + +**Krzyżowa weryfikacja obu torów** (eventy przejść vs `up{}`): każde +`node_stale`/`node_offline` w eventach = początek okna `up==0` + 2/9,5 min; +każde `node_online` = koniec okna `up==0` ± kilkanaście sekund. Przykład +(lustro 07-14): prom down 21:30, `node_stale` 21:32:46, `node_offline` +21:39:50; rano prom up 04:31, `node_online` 04:31:46. Oba tory opisują tę samą +rzeczywistość — różni je wyłącznie opóźnienie detekcji zgonu. + +**Power-on nie generuje mismatchy** — w 20 h logów są dwa powroty węzłów +(lustro 07-15 04:31, solaria 07-15 12:21) i **zero** wpisów `event=dead +prom=up`. Po bootzie node-agent wysyła pierwszy event w ~tej samej chwili, +w której Prometheus zalicza pierwszy scrape — oba tory flipują w obrębie +jednego cyklu observera. + +## C. Interpretacja `event=fresh prom=down` + +Hipotezy z zadania wobec danych: + +1. **node_exporter pada niezależnie od hosta — OBALONA.** Okna `up==0` są + długie (7–19 h), zwarte, o ostrych krawędziach, bez flappingu; dla lustro + co do minuty zgodne z harmonogramem 21:30→04:30. Crash-loop exportera + dawałby krótkie, poszarpane dziury w losowych porach. Dodatkowo eventy + `service_healthy-node-exporter` płyną z lustro do ostatniego cyklu przed + wyłączeniem. +2. **Flaky scrape po Tailscale — OBALONA.** Brak pojedynczych/krótkich dropów + `up` poza oknami off (step 30 s wykryłby ≥1-minutowe); piha po tym samym + mesh ma 100% czystych scrape'ów; zero timeoutów observer→Prometheus. +3. **Węzeł w trakcie wyłączania (event jeszcze „fresh" z natury TTL) — + POTWIERDZONA, z doprecyzowaniem.** To nie „bufor eventów" — po prostu + definicja `fresh` = ostatni event < 180 s temu. Po fizycznym wyłączeniu + węzła jego ostatni heartbeat starzeje się przez 180 s jako „fresh" + i przez kolejne 420 s jako „stale", podczas gdy Prometheus widzi `up==0` + już przy pierwszym nieudanym scrape (≤15–45 s). Mismatch = czysta + **asymetria opóźnień detekcji**, przewidziana w recon (E.3/E.4) jako znana + klasa rozbieżności semantyk. + +Wniosek: w całym analizowanym oknie **nie wystąpił ani jeden przypadek +fałszywego `prom=down`** (żywy węzeł, którego Prometheus nie scrape'uje). +Kierunek błędu jest odwrotny do obawy z zadania: to tor eventowy przez +~9,5 min pokazywał „żywy/stale" dla węzła realnie martwego. + +## D. Implikacje dla Etapu 3 (`PROM_LIVENESS_NODES`) + +### vps, piha — GO + +84 h nieprzerwanego `up==1`, zero mismatchy, zero przejść liveness od ≥ 07-11. +Oba źródła zgodne w 100%. Prometheus + istniejący alert `NodeDown` +(`up{node=~"vps|piha"}==0 for 5m`) dają im pełne pokrycie. **Kandydaci do +przełączenia bez zastrzeżeń.** + +### solaria, lustro — GO, `prom=down` NIE dyskwalifikuje + +Dane pokazują, że `up==0` dla tych węzłów zawsze znaczyło „węzeł naprawdę +wyłączony" — Prometheus nie wyprodukował ani jednego fałszywego down. Twardy +cutover klasyfikacji na `up` jest więc **bezpieczny i poprawia stan faktyczny**: +panel pokaże offline ~9,5 min wcześniej niż dziś. + +Skutek uboczny do zaakceptowania świadomie: syntetyczne `node_stale`/ +`node_offline` (→ alert_only supervisora) będą się emitować przy każdym nocnym +wyłączeniu **wcześniej, ale nie liczniej** — te eventy już dziś powstają co noc +(21:32/21:39 dla lustro, każdorazowo dla solaria). Cutover nie zwiększa wolumenu +alertów. Docelowe wyciszenie planowych okien off to wątek anomaly-detection +z backlogu (`docs/backlog.md:390-406`) — **niezależny od cutoveru i nieblokujący**; +`NodeDown` dla solaria/lustro słusznie pozostaje wyłączony. + +### Rekomendowany mapping (potwierdzenie rekomendacji z recon F/Etap 2) + +`prom-last_seen = timestamp(up)` wpuszczone w istniejące `compute_liveness` +z obecnymi TTL-ami — a nie surowe `up==0 → dead`. Uzasadnienie z danych: + +- zachowuje tier `stale` i histerezę na krótkie dziury scrape (w oknie ich nie + było, ale 30-sekundowa rozdzielczość nie wyklucza pojedynczych timeoutów), +- odporne na restart samego Prometheusa (brak serii ≠ węzeł martwy → UNKNOWN + → fail-open na tor eventowy, zgodnie z planem Etapu 3), +- przejścia liczone tym samym kodem co dziś → `_emit_node_transition` + i tor alertowy supervisora bez żadnych zmian. + +### Kolejność włączania + +Dane nie wskazują przeciwwskazań dla żadnego z 4 węzłów; kolejność z recon +(najpierw `solaria,lustro`, po tygodniu `vps,piha`) pozostaje rozsądna jako +minimalizacja blast-radius (brak NodeDown = pomyłka nie budzi nikogo w nocy). +Alternatywnie równie dobrze uzasadnione jest odwrotnie (vps/piha mają +mocniejszy dowód zgodności). **Rekomendacja: trzymać się kolejności z recon.** + +### Warunki towarzyszące (z recon, potwierdzone jako nadal aktualne) + +1. **Watchdog na sam Prometheus** (recon D.2 pkt 5) — po cutoverze `up{}` staje + się źródłem prawdy dla 4 węzłów; obecnie nikt nie alarmuje o jego śmierci. + Zrobić razem z Etapem 3. +2. **Fail-open na tor eventowy** przy braku odpowiedzi Prometheusa > TTL-fresh — + jak w planie Etapu 3; w 20 h obserwacji zero błędów zapytań, ale + `mem_limit 512m` + `oom_score_adj 200` czynią go ubijalnym przed control-plane. +3. **chelsty-infra pozostaje na torze eventowym** (brak serii `up`) — hybryda + per-node obowiązkowa, bez zmian względem recon. + +### Braki dowodowe / follow-up przed „GO" formalnym + +- Okno twardych danych log-level to ~20 h (recreate kontenera 07-14 16:30 + zjadł wcześniejsze logi docker). Kryterium recon mówi o ≥ 7 dniach. Wnioski + są mocno podparte pośrednio (84 h `up{}` + eventy przejść od 07-11), ale + formalnie warto: **(a)** pociągnąć shadow-run do ~2026-07-20 i powtórzyć + zliczenie mismatchy (oczekiwane: wyłącznie okna power-off solaria/lustro, + ~82/wyłączenie, zero na vps/piha), **(b)** rozważyć trwałość logów observera + (logging driver z rotacją / plik w `/opt/homelab/logs/`), żeby recreate + kontenera nie kasował materiału dowodowego Etapu 2. +- Scenariusz z recon Etap 1 „restart node-agenta przy żywym węźle" + (`event=dead prom=up` — zamierzona zmiana werdyktu po cutoverze) **nie + wystąpił naturalnie** w analizowanym oknie — jeśli ma być przetestowany, + wymaga kontrolowanego stopu node-agenta na solaria (czynność operatorska, + poza tym taskiem). + +## Załącznik: pełna oś czasu przejść (tor eventowy, z eventów `source=observer`) + +``` +solaria: + 07-11 22:36 stale → 22:43 dead | 07-12 16:58 online + 07-12 22:30 stale → 22:37 dead | 07-13 17:11 online + 07-13 19:24 stale → 19:31 dead | 07-14 12:46 online + 07-14 21:36 stale → 21:43 dead | 07-15 12:20 online ← okno 165 mismatchy +lustro: + 07-11 21:32 stale → 21:39 dead | 07-12 04:31 online + 07-12 21:32 stale → 21:39 dead | 07-13 04:31 online + 07-13 21:32 stale → 21:39 dead | 07-14 04:31 online + 07-14 21:32 stale → 21:39 dead | 07-15 04:30 online ← okno 165 mismatchy +piha, vps: brak przejść (ciągłe fresh) +``` + +Każdy wiersz `stale→dead` odpowiada 1:1 początkowi okna `up==0` w Prometheusie +(przesunięcie: prom leaduje o ~2 min względem `stale` i ~9,5 min względem +`dead`); każdy `online` = koniec okna `up==0` ± kilkanaście sekund.