docs(incidents): root-cause zniknięcia ollama@SOLARIA — node-agent prune bez filtrów co 60 s
Kontener nie padł ani nie zniknął przy starcie: usunął go własny node-agent. 19 s po operatorskim `docker stop ollama` cykl cleanupu wywołał `containers.prune()` bez filtrów — Docker kasuje każdy kontener nie-running, ignorując restart policy i labele compose. Dowód: ten sam cykl logu node-agent, dwie kolejne linie — 16:45:33,528 WARNING Container exited: ollama (restart=unless-stopped) 16:45:33,563 INFO Pruned stopped containers (57 MB reclaimed) 57 MB to jedyna niezerowa wartość SpaceReclaimed w całym dniu (reszta 0 MB). Mina uzbroiła się dzień wcześniej: prune istnieje od01b7758, ale na SOLARII node-agent nie miał dostępu do docker.sock (GID 996 vs 999) do czasuddae57c. Wykluczone: remediation pipeline (dispatch/solaria pusty, whitelist tylko container_restart), stability-agent (zero ścieżek usuwających), config compose (AutoRemove=false, brak --rm, brak compose down), cron/systemd (brak prune). To NIE jest ollama-solaria-start-race — tamte dotyczyły startu kontenera. Tu problem jest w cleanupie node-agenta i dotyczy każdego serwisu: ai_node (solaria) i standard (vps) prune'ują bez rate-limitu, sd_card raz na 24 h. `docker stop` jest obecnie na 4 z 6 nodów operacją destrukcyjną. Fix świadomie niezaimplementowany — rekomendacje R1-R4 + mitygacja M1 w §7. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
This commit is contained in:
oskar
parent
3474744607
commit
ffe2a0c35b
248
docs/incidents/2026-07-30-ollama-solaria-vanish.md
Normal file
248
docs/incidents/2026-07-30-ollama-solaria-vanish.md
Normal file
|
|
@ -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 <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 = 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 <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.
|
||||
Loading…
Reference in a new issue