homelab-codex-ws/kb/incidents/2026-07-30-ollama-solaria-vanish.md

258 lines
15 KiB
Markdown
Raw Permalink Normal View History

---
okf: "0.1"
type: incident
visibility: private
status: active
updated: 2026-07-30
links: []
---
2026-07-30 20:06:14 +02:00
# 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 <serwis>` 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 = CEST2h)
| 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:4416: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:0017: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:0019: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 7678 + `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 <serwis>` — 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.