diff --git a/docs/incidents/2026-07-30-ollama-solaria-vanish.md b/docs/incidents/2026-07-30-ollama-solaria-vanish.md new file mode 100644 index 0000000..66c637b --- /dev/null +++ b/docs/incidents/2026-07-30-ollama-solaria-vanish.md @@ -0,0 +1,248 @@ +# Incydent: zniknięcie kontenera `ollama` na SOLARII — 2026-07-30 + +**Status:** root-cause ustalony, potwierdzony logiem i kodem. Fix NIE zaimplementowany (świadomie — patrz §7). +**Dotknięty serwis:** `ollama` @ SOLARIA. Dane przetrwały (bind `/opt/homelab/data/ollama`). +**Klasa:** utrata zasobu przez automatykę (destructive cleanup), nie awaria serwisu. +**Werdykt jednym zdaniem:** `node-agent` na SOLARII wywołuje `docker container prune` **bez filtrów co 60 s** — 19 sekund po operatorskim `docker stop ollama` prune usunął kontener. + +--- + +## 1. TL;DR + +Operator zatrzymał `ollama` celowo (test „sol-down" dla KB). Kontener miał `restart: unless-stopped`, +czyli w Dockerze status `exited`. W następnym cyklu (19 s później) `node-agent` wykonał +`docker_client.containers.prune()` — API Dockera usuwa **każdy** kontener nie-`running`, +niezależnie od restart policy, labeli compose czy intencji operatora. Kontener przestał istnieć. + +To **nie jest** kolejna odsłona backlogowego `ollama-solaria-start-race` (reboot / network-detach / +bind-race z tailscale0). To osobna, nowa przyczyna, która **uzbroiła się dzień wcześniej**: +prune istniał w kodzie od zawsze, ale na SOLARII `node-agent` nie miał dostępu do `docker.sock` +(GID 996 vs 999) aż do commita `ddae57c` (2026-07-29), wdrożonego na node 2026-07-30 o 15:58. + +Skutek uboczny do zapamiętania: **`docker stop ` jest teraz na SOLARII i VPS operacją +destrukcyjną** — kontener znika w ≤60 s. Wzorzec „stop bez rm jako bezpieczny rollback", +używany w tym repo (por. `docker stop homeassistant5` … „Rollback: `docker start homeassistant5`"), +przestał działać. + +--- + +## 2. Timeline (czas lokalny CEST; logi kontenerów są w UTC = CEST−2h) + +| Czas (CEST) | Zdarzenie | Źródło dowodu | +|---|---|---| +| 2026-07-29 19:20 | commit `ddae57c fix(solaria): node-agent group_add for host docker gid 996` | `git log -1 ddae57c` | +| 2026-07-30 15:58:55 | `node-agent` odtworzony na SOLARII (z działającym docker.sock) | `docker ps -a` CreatedAt | +| 2026-07-30 15:59:05 | `node-agent starting: node=solaria type=ai_node` / `Docker SDK connected` | logi node-agent | +| 2026-07-30 15:59:06 | **pierwszy** `Pruned stopped containers` — mina uzbrojona, cykl 60 s | logi node-agent | +| 2026-07-30 18:45:14 | operator: `docker ps --filter name=ollama … && docker stop ollama` | `~/.zsh_history` epoch `1785429914` | +| **18:45:33.528** | `WARNING - Container exited: ollama (restart=unless-stopped)` | logi node-agent | +| **18:45:33.563** | `INFO - Pruned stopped containers (57 MB reclaimed)` ← **usunięcie** | logi node-agent | +| 2026-07-30 18:51:48 | operator: `docker start ollama && …` → `No such container` | `~/.zsh_history` epoch `1785430308` | +| 2026-07-30 18:53:56 | `docker ps -a --filter name=ollama` → pusto | `~/.zsh_history` epoch `1785430436` | +| 2026-07-30 18:55:39 | odtworzenie: `docker compose -f services/ollama/docker-compose.yml … up -d` | `~/.zsh_history` epoch `1785430539` | +| 2026-07-30 18:55:39 | `dockerd: sbJoin … ep=ollama net=ollama_default` — kontener wstał | `journalctl -u docker` | + +**Korekta względem zgłoszenia:** przerwa między `stop` a nieudanym `start` wyniosła +**6 min 34 s**, nie ~1,5 h. Okno ekspozycji było jeszcze krótsze — **19 sekund**. +Kontener zniknął natychmiast, nie „gdzieś przez półtorej godziny". + +--- + +## 3. Dowód bezpośredni + +Log `node-agent`, ten sam cykl, dwie kolejne linie (pełny fragment okna 16:44–16:47 UTC): + +``` +2026-07-30 16:44:30,760 - INFO - Pruned dangling images (0 MB reclaimed) +2026-07-30 16:44:30,763 - INFO - Pruned stopped containers (0 MB reclaimed) +2026-07-30 16:44:30,786 - INFO - Pruned build cache (0 MB reclaimed) +2026-07-30 16:45:33,528 - WARNING - Container exited: ollama (restart=unless-stopped) +2026-07-30 16:45:33,536 - INFO - Pruned dangling images (0 MB reclaimed) +2026-07-30 16:45:33,563 - INFO - Pruned stopped containers (57 MB reclaimed) +2026-07-30 16:45:33,574 - INFO - Pruned build cache (0 MB reclaimed) +2026-07-30 16:46:37,004 - INFO - Pruned dangling images (0 MB reclaimed) +2026-07-30 16:46:37,004 - INFO - Pruned stopped containers (0 MB reclaimed) +``` + +Trzy niezależne potwierdzenia, że to właśnie ta linia usunęła `ollamę`: + +1. **Wartość.** `SpaceReclaimed` jest **0 MB w każdym innym cyklu dnia** (setki linii) — i **57 MB + dokładnie w tym jednym**. 57 MB = writable layer kontenera ollama (modele siedzą w bindzie, nie w warstwie). +2. **Korelacja.** W całym oknie 16:00–17:10 UTC log `node-agent` ma **dokładnie jedną** linię + nie-prune: `Container exited: ollama`. Żaden inny kontener nie był wtedy zatrzymany — + `docker ps` pokazuje pozostałe cztery z ciągłym uptime obejmującym okno incydentu + (`node-agent` Up 4 h, `planner-agent`/`stability-agent`/`node_exporter` Up 5 h). +3. **Kolejność w kodzie.** `check_containers()` (wykrycie `exited`) jest wołane w `run_once()` + linia po linii przed `run_safe_cleanup()` — stąd 35 ms między WARNING a prune. + +--- + +## 4. Root cause w kodzie + +`services/node-agent/src/node_agent.py` + +```python +# linia 625 +def _prune_stopped_containers(self): + if not self.docker_client: + return + try: + result = self.docker_client.containers.prune() # ← BEZ filtrów + reclaimed = result.get("SpaceReclaimed", 0) // (1024 * 1024) + logger.info(f"Pruned stopped containers ({reclaimed} MB reclaimed)") +``` + +```python +# linia 646 +def run_safe_cleanup(self): + if self.node_type == "lte_node": + return # chelsty-* — nic nie robi + if self.node_type == "sd_card": + if not self._sd_card_rate_ok(): # piha/saturn — limit 24 h + return + self._prune_dangling_images() + self._prune_stopped_containers() + self._mark_cleanup_done() + return + # ai_node (solaria) i standard (vps): BEZ ŻADNEGO rate-limitu + self._prune_dangling_images() + self._prune_stopped_containers() + self._prune_build_cache() +``` + +```python +# linia 1071 — run_safe_cleanup w każdym cyklu pętli +def run_once(self): + ... + self.check_containers() + self.run_safe_cleanup() + ... +# linia 1101: loop(interval=HEALTH_CHECK_INTERVAL), CHECK_INTERVAL=60 (override solarii) +``` + +Trzy niezależne defekty składają się na incydent: + +1. **`containers.prune()` bez filtrów.** docker-py przekazuje to 1:1 do + `POST /containers/prune`. Docker usuwa **wszystkie** kontenery w stanie innym niż `running`. + API nie zna pojęcia „zatrzymany celowo": nie patrzy na `RestartPolicy`, nie patrzy na labele + `com.docker.compose.*`. `restart: unless-stopped` to dosłownie zapisana intencja operatora + („zatrzymany świadomie — nie ruszaj") i prune ją ignoruje. +2. **Brak rate-limitu dla `ai_node`/`standard`.** Rate-limit 24 h (`CLEANUP_INTERVAL_SECS = 86_400`) + istnieje **wyłącznie** dla `sd_card`. Na SOLARII prune leci co 60 s — okno na uratowanie + zatrzymanego kontenera to maksymalnie jeden cykl. Logi dowodzą, że ta częstotliwość jest + zresztą bezużyteczna: `0 MB reclaimed` w praktycznie każdym cyklu. +3. **Logowanie nie mówi, co usunięto.** `prune_containers()` zwraca `ContainersDeleted` + (lista ID) obok `SpaceReclaimed`, ale kod loguje tylko megabajty. Dlatego usunięcie + `ollamy` było w logu niewidzialne — wyglądało jak każdy inny wiersz „Pruned stopped containers". + Gdyby logowano nazwy, diagnoza trwałaby 30 sekund zamiast całej sesji. + +**Dlaczego dopiero teraz.** Funkcja pochodzi z `01b7758 feat(node-agent): implement health monitor +and safe cleanup policy` — jest w repo od początku istnienia agenta. Na SOLARII nie strzelała, +bo `node-agent` startował z `Docker unavailable: Permission denied` na `/var/run/docker.sock` +(host ma docker GID **996**, base compose zakładał 999) — `self.docker_client` był `None` +i `_prune_stopped_containers()` wychodziło pierwszym `return`. Commit `ddae57c` +(2026-07-29 19:20) dołożył `group_add: ["996"]` w `hosts/solaria/runtime/node-agent/docker-compose.override.yml`. +Naprawiając monitoring, uzbroił prune. Pierwszy `Pruned stopped containers` na SOLARII: +2026-07-30 15:59:06 CEST — **2 h 46 min przed incydentem**. + +--- + +## 5. Hipotezy wykluczone + +| # | Hipoteza | Werdykt | Dowód | +|---|---|---|---| +| 1 | `docker events` / journal wskaże inicjatora | **Bez danych** (nie wyklucza ani nie potwierdza) | bufor `docker events` sięga tylko 19:42 (in-memory ring); `journalctl -u docker` w oknie 17:00–19:30 to **3 linie**, jedyna istotna to `sbJoin … ep=ollama` z 18:55:39, czyli już odtworzenie. Daemon na poziomie `info` nie loguje usunięć kontenerów. | +| 2 | Remediation pipeline (akcja z control-plane wykonana przez node-agent) | **Wykluczone** | `/opt/homelab/actions/dispatch/solaria/` **pusty**; w logach node-agent zero linii wykonania akcji; whitelist `ALLOWED_DISPATCH_ACTION_TYPES = {"container_restart"}` (linia 105, egzekwowana w 951) nie zawiera niczego, co usuwa kontener — a `container_restart` i tak by go nie skasował. | +| 3 | `stability-agent` usuwa zatrzymane kontenery | **Wykluczone** | `grep -n "prune\|\.remove(\|docker rm\|force=True\|down\b" services/stability-agent/src/stability_agent.py` → **zero trafień**. Brak jakiejkolwiek ścieżki usuwającej. | +| 4 | Config compose (auto-remove / `compose down`) | **Wykluczone** | `docker inspect`: `AutoRemove=false`, `RestartPolicy={"Name":"unless-stopped"}`; brak `--rm` w `services/ollama/docker-compose.yml`; brak `docker compose down` w `~/.zsh_history` w okolicy okna. **Uwaga poboczna:** `hosts/solaria/runtime/ollama/docker-compose.override.yml` **nie istnieje** — komenda odtwarzająca miała guard `test -f`, więc po cichu użyła samego base compose. | +| 5 | Cron / systemd timer z `docker prune` | **Wykluczone** | crontab root (tylko `@reboot /root/update.sh`), crontab oskar (pusty), `/etc/cron.{d,daily,hourly}` + `/etc/crontab` — jedyne trafienia `prune` to `find -prune` w `/etc/cron.daily/apport`. 19 systemd timerów + 4 user timery — żaden nie dotyka Dockera. | + +--- + +## 6. Zasięg (blast radius) + +Wyliczony z kodu (`_resolve_node_type`, linie 76–78 + `run_safe_cleanup`), **nie weryfikowany +na żywo na innych nodach** — SOLARIA to jedyny node, do którego ta sesja miała dostęp. + +| Node | node_type | Zachowanie | Ryzyko | +|---|---|---|---| +| **SOLARIA** | `ai_node` | prune bez filtrów **co 60 s** | **Krytyczne** — potwierdzone w boju | +| **VPS** | `standard` (fallback) | prune bez filtrów, **bez rate-limitu**, cykl = `CHECK_INTERVAL` | **Krytyczne** — ta sama ścieżka kodu, w tym npm/outline/joplin/ai-cluster | +| **PIHA, SATURN** | `sd_card` | ten sam prune bez filtrów, ale gated 24 h | Wysokie, ale okno wąskie (1 strzał/dobę) | +| **CHELSTY-INFRA/HA** | `lte_node` | `return` przed cleanupem | Brak | + +Konsekwencja operacyjna: na 4 z 6 nodów `docker stop ` — standardowy ruch +diagnostyczny i rollbackowy — jest operacją niszczącą. Na VPS dodatkowo dotyczy to +kontenerów spoza repo (`humanai-mailer`, `humanai-landing` odtwarzane ręcznie z `docker inspect`, +bez pliku compose) — tam utrata kontenera oznacza utratę jedynej definicji konfiguracji. + +--- + +## 7. Rekomendacje (świadomie NIE zaimplementowane w tej sesji) + +Zgodnie ze zleceniem: root-cause wskazał kod w repo → opis fixa, bez zmiany kodu. + +**R1 (krytyczne) — `_prune_stopped_containers` nie może kasować kontenerów zarządzanych.** +`containers.prune()` bez filtrów jest nie do uratowania parametrami (`until` filtruje po czasie +utworzenia, nie po czasie zatrzymania — nie chroni długo żyjącego serwisu). Zamiast tego jawna enumeracja: + +```python +for c in self.docker_client.containers.list(all=True, filters={"status": "exited"}): + if c.attrs["HostConfig"]["RestartPolicy"]["Name"] in ("unless-stopped", "always", "on-failure"): + continue # intencja operatora — nie ruszaj + if c.labels.get("com.docker.compose.project"): + continue # zarządzane przez compose + # dopiero teraz: c.remove() +``` +Uzasadnienie: docstring modułu już deklaruje listę „NEVER TOUCHED" (`data/`, `config/`, +`state/`, żywa kolejka akcji). Kontener z `restart: unless-stopped` należy do tej samej klasy — +jest zapisaną intencją, nie śmieciem. Prune dangling images i build cache może zostać bez zmian. + +**R2 (wysokie) — rate-limit dla `ai_node` i `standard`.** Obecnie `CLEANUP_INTERVAL_SECS` +działa wyłącznie dla `sd_card`. Prune co 60 s odzyskuje `0 MB` w praktycznie każdym cyklu — +to czysty koszt I/O i 1440 okazji dziennie na przypadkowe skasowanie. Ten sam guard +(`_sd_card_rate_ok` → przemianować na `_cleanup_rate_ok`) powinien objąć wszystkie typy nodów. + +**R3 (średnie) — logować, co zostało usunięte.** `result.get("ContainersDeleted")` do linii +logu, poziom WARNING gdy lista niepusta. Bez tego każde następne takie zdarzenie znów będzie +niewidzialne. + +**R4 (proces) — osobny task w backlogu.** Ten incydent **nie należy** do +`ollama-solaria-start-race` (reboot 15.07 / network-detach 21.07 / bind-race 22.07 — +wszystkie o *starcie* kontenera). Tutaj kontener wstawał bez zarzutu; problem jest w +*cleanupie node-agenta* i dotyczy każdego serwisu na każdym nodzie. Sklejenie obu +zamaskuje jedno albo drugie. + +**M1 — mitygacja doraźna do czasu R1** (do decyzji operatora, nie zastosowana): +na czas prac utrzymaniowych albo `docker stop node-agent`, albo tymczasowo +`NODE_TYPE=lte_node` w `hosts/solaria/runtime/node-agent/docker-compose.override.yml`. +Zweryfikowane: `self.node_type` jest używane wyłącznie w `run_safe_cleanup()` (linie 648, 654) +i w dwóch liniach logu (250, 1103) — podmiana wyłącza cleanup i **nic poza nim** +(monitoring, eventy, dispatch akcji działają dalej). + +--- + +## 8. Co wymaga dostępu do VPS (poza zakresem tej sesji) + +Root-cause jest kompletny bez tego — poniższe domyka jedynie obraz skutków ubocznych. + +1. **Los eventu `containers_not_running` dla `ollama`** (wyemitowanego 16:45:33 UTC). + Lokalnie `/opt/homelab/events/solaria/` jest **pusty**, bo `_ship_events_to_vps()` używa + `rsync -az --remove-source-files` (linia 792) — event fizycznie przeniósł się na VPS. + Do sprawdzenia: `/opt/homelab/events/solaria/` **na VPS**, grep `ollama` z 2026-07-30. +2. **Czy supervisor wygenerował akcję.** Wg tabeli routingu w `CLAUDE.md` + `containers_not_running` → `container_restart`. Jeśli akcja powstała i została zatwierdzona, + executor/node-agent trafiłby na nieistniejący kontener → `failed`. + Do sprawdzenia na VPS: `/opt/homelab/actions/{pending,approved,failed}/` z 2026-07-30 wieczór. +3. **Czy VPS-owy `node-agent` też prune'uje co cykl** — `docker logs node-agent | grep "Pruned stopped"` + na VPS. Potwierdzenie/zaprzeczenie wiersza „VPS = krytyczne" z §6. + +--- + +## 9. Stan końcowy + +- `ollama` działa: odtworzony 18:55:39, `Up`, `curl localhost:11434/api/tags` OK. +- Dane nienaruszone — modele w bindzie `/opt/homelab/data/ollama:/root/.ollama`, + prune nigdy nie dotyka bind mountów. +- **Przyczyna nadal aktywna.** Do czasu R1 każdy kontener zatrzymany na SOLARII + lub VPS znika w ≤60 s.