diff --git a/deploy/update-agent.sh b/deploy/update-agent.sh index 931f6a7..0b5cd9d 100755 --- a/deploy/update-agent.sh +++ b/deploy/update-agent.sh @@ -106,6 +106,18 @@ mkdir -p "$STATE_DIR" # und hier oben darf noch nichts von unten gebraucht werden): der einzige freie # Text ist die Ausgabe von ps, aus der Anfuehrungszeichen, Backslashes und # Zeilenumbrueche entfernt werden. +# Ins Journal. systemd sammelt die Standardausgabe ohnehin ein; `logger` setzt +# zusaetzlich die Kennung, unter der die Zeile auch ohne -u zu finden ist. +# +# `|| true` an beiden Stellen: dieses Skript laeuft unter `set -e`, und an einer +# Meldung darf ein Lauf nicht sterben. +say() { + if command -v logger >/dev/null 2>&1; then + logger -t clupilot-update-agent -- "$*" || true + fi + printf '%s\n' "$*" || true +} + write_alive() { local state="$1" since="${2-}" held_by="${3-}" skips="${4-0}" held_by="$(printf '%s' "$held_by" | tr -d '"\\' | tr '\n\r\t' ' ')" @@ -220,6 +232,19 @@ if ! flock -n 9; then write_alive blocked "$PREVIOUS_SINCE" "${HOLDER_CMD:-$HOLDER}" "$SKIPS" + # Und ins Journal. Bis hierher war ein uebersprungener Lauf dort NICHT von + # einem erfolgreichen zu unterscheiden: der Agent beendet sich sauber, also + # meldet systemd `Starting` → `Deactivated`, genau wie sonst. Wer mit + # `journalctl -u clupilot-update-agent.service` nachsah, sah einen Dienst, + # der laeuft und nichts zu beanstanden hat — waehrend er in Wahrheit seit + # Stunden nicht an die Arbeit kam. Das hat die Fehlersuche zweimal in die + # falsche Richtung geschickt. + # + # Der Halter steht in der Zeile, weil er die Frage sofort beantwortet, um + # die es dann geht: der Waechter fuer einen Lauf ist Betrieb, ein Update + # ist Betrieb, derselbe Halter seit vierzig Laeufen ist es nicht. + say "Uebersprungen (${SKIPS}. Lauf in Folge, seit ${PREVIOUS_SINCE}): die Sperre haelt ${HOLDER_CMD:-${HOLDER:-jemand anderes}}" + # Und hier — und NUR hier — wird eine Bitte gelesen, die haengende Sperre # zu loesen. Dies ist der einzige Zweig, den ein blockierter Lauf erreicht, # und die Blockade ist der einzige Zustand, in dem die Bitte einen Sinn diff --git a/deploy/watchdog.sh b/deploy/watchdog.sh index 45aebe2..120a9d2 100755 --- a/deploy/watchdog.sh +++ b/deploy/watchdog.sh @@ -17,8 +17,8 @@ # nicht kennt, protokolliert er und lässt es in Ruhe. Ein Wächter, der bei # Unbekanntem herumprobiert, ist der nächste Ausfall. # -# Er fasst NICHTS an, solange ein Update läuft — er nimmt dieselbe Sperre wie -# der Update-Agent und geht weg, wenn er sie nicht bekommt. +# Er fasst NICHTS an, solange ein Update läuft — er nimmt dafür dieselbe Sperre +# wie der Update-Agent. Aber erst, wenn es etwas zu richten gibt: siehe unten. set -uo pipefail cd "$(cd "$(dirname "$0")/.." && pwd)" @@ -39,10 +39,65 @@ say() { printf '%s\n' "$*" } -# Solange ein Update läuft, ist Stillstand normal und Eingreifen schädlich. mkdir -p "$STATE_DIR" 2>/dev/null || true -exec 9>"$LOCK" 2>/dev/null || exit 0 -flock -n 9 || exit 0 + +# ── Kein Aufruf nach draußen ohne Frist ────────────────────────────────────── +# +# Der Update-Agent hat das am 4. August 2026 gelernt, der Wächter nicht: ein +# `docker compose exec`, das auf den Docker-Daemon wartet, hängt unbegrenzt. +# Der Agent hielt dabei die Sperre stundenlang, und die Konsole meldete „kommt +# seit 08:02 nicht an die Arbeit" — vierzehn Aufrufe hier hatten dieselbe +# Lücke. +# +# `-k`, weil eine Frist ohne Nachdruck keine Frist ist: `timeout` schickt nach +# der Zeit ein SIGTERM, und `docker compose exec` stirbt daran nicht, wenn es +# auf den Daemon wartet — danach wartet `timeout` selbst unbegrenzt weiter. +# +# Zwei Längen, weil Nachsehen und Eingreifen nicht dasselbe kosten: ein Blick +# ist in Sekunden vorbei oder er ist krank, ein Neuerzeugen von Containern darf +# dauern. +frist() { timeout -k 5 20 "$@"; } +lange_frist() { timeout -k 10 120 "$@"; } + +# ── Die Sperre — erst beim Eingriff, nicht beim Nachsehen ──────────────────── +# +# Bis hierher nahm der Wächter die Sperre in seinen ersten Zeilen, für den +# ganzen Lauf. Das war der Fehler, und er kostete Wochen Fehlsuche: +# +# Wächter und Update-Agent haben BEIDE einen minütlichen Zeitgeber und nahmen +# BEIDE dieselbe Sperre, bevor sie wussten, ob sie überhaupt etwas tun würden. +# Der Wächter tut an fast jedem Tag nichts — alle vier Prüfungen unten sind +# lesend. Er hielt die Sperre trotzdem, jede Minute; der Agent kam eine Sekunde +# später, ging leer aus und schrieb einen Übersprung-Vermerk. Und weil der +# Agent der ist, der an die Konsole berichtet, stand dort eine Dauerstörung, +# während beide Dienste genau das taten, was sie sollten. +# +# Versetzte Zeitgeber hätten das nur seltener gemacht, nicht weg: zwei Takte +# derselben Länge wandern gegeneinander, und systemd zieht sie über AccuracySec +# aktiv auf gemeinsame Weckpunkte zusammen. Eine zweite Sperre wäre schlimmer +# als der Fehler — dann liefe der Wächter mitten in ein Update hinein. +# +# Also: nachsehen ohne Sperre, und die Sperre erst nehmen, wenn wirklich etwas +# zu richten ist. Im gesunden Fall fasst der Wächter sie nie an. +SPERRE=frei + +darf_eingreifen() { + [[ "$SPERRE" == genommen ]] && return 0 + [[ "$SPERRE" == verwehrt ]] && return 1 + + exec 9>"$LOCK" 2>/dev/null || { SPERRE=verwehrt; return 1; } + + if flock -n 9; then + SPERRE=genommen + return 0 + fi + + # Einmal gemerkt und einmal gesagt: die folgenden Prüfungen sollen es nicht + # erneut versuchen und die Meldung nicht wiederholen. + SPERRE=verwehrt + say "Es gaebe etwas zu richten, aber die Sperre wird gehalten — ein Update laeuft. Dieser Lauf greift nicht ein." + return 1 +} geheilt=false @@ -50,17 +105,17 @@ geheilt=false # # `config --services` liest die Profile aus der .env mit, vpn-dns und # vpn-gateway zählen also nur, wo der Tunnel überhaupt eingerichtet ist. -soll="$(docker compose config --services 2>/dev/null | sort || true)" -ist="$(docker compose ps --services --status running 2>/dev/null | sort || true)" +soll="$(frist docker compose config --services 2>/dev/null | sort || true)" +ist="$(frist docker compose ps --services --status running 2>/dev/null | sort || true)" if [[ -n "$soll" ]]; then fehlt="$(comm -23 <(printf '%s\n' "$soll") <(printf '%s\n' "$ist") | tr '\n' ' ' | sed 's/ *$//')" - if [[ -n "$fehlt" ]]; then + if [[ -n "$fehlt" ]] && darf_eingreifen; then say "Es fehlen Dienste: $fehlt — starte sie." - docker compose up -d >/dev/null 2>&1 || true + lange_frist docker compose up -d >/dev/null 2>&1 || true geheilt=true sleep 10 - ist="$(docker compose ps --services --status running 2>/dev/null | sort || true)" + ist="$(frist docker compose ps --services --status running 2>/dev/null | sort || true)" fi fi @@ -74,11 +129,19 @@ fi # # Ein Neustart hilft dabei NICHT; die Container müssen neu erzeugt werden. if printf '%s\n' "$ist" | grep -qx app && printf '%s\n' "$ist" | grep -qx redis; then - if ! docker compose exec -T -u www-data app getent hosts redis >/dev/null 2>&1; then - say "Die Container finden einander nicht mehr (redis nicht auflösbar) — erzeuge sie neu." - docker compose up -d --force-recreate >/dev/null 2>&1 || true - geheilt=true - sleep 15 + if ! frist docker compose exec -T -u www-data app getent hosts redis >/dev/null 2>&1; then + # Der einzige Griff hier, der weh tut: `--force-recreate` reißt jede + # offene Verbindung ab. Deshalb wird NACH dem Nehmen der Sperre noch + # einmal nachgesehen — der Blick oben war ungesperrt, und genau + # dazwischen kann ein Update fertig geworden sein, das die Auflösung + # längst wieder in Ordnung gebracht hat. Ohne diese zweite Frage + # erzeugte der Wächter gesunde Container neu. + if darf_eingreifen && ! frist docker compose exec -T -u www-data app getent hosts redis >/dev/null 2>&1; then + say "Die Container finden einander nicht mehr (redis nicht auflösbar) — erzeuge sie neu." + lange_frist docker compose up -d --force-recreate >/dev/null 2>&1 || true + geheilt=true + sleep 15 + fi fi fi @@ -87,17 +150,19 @@ fi # Der wichtigste Punkt: ohne wg0 ist kein Host erreichbar, keine Provisionierung # möglich und kein Terminal. Ohne Konfiguration ist der Tunnel auf diesem Server # schlicht nicht eingerichtet — dann gibt es nichts zu heilen. -if docker compose ps --services --status running 2>/dev/null | grep -qx vpn-hub; then - if docker compose exec -T vpn-hub test -f /etc/wireguard/wg0.conf >/dev/null 2>&1; then - if ! docker compose exec -T vpn-hub wg show wg0 >/dev/null 2>&1; then - say "wg0 steht nicht — ziehe den Tunnel hoch." - docker compose exec -T vpn-hub wg-quick up wg0 >/dev/null 2>&1 || true - geheilt=true +if printf '%s\n' "$ist" | grep -qx vpn-hub; then + if frist docker compose exec -T vpn-hub test -f /etc/wireguard/wg0.conf >/dev/null 2>&1; then + if ! frist docker compose exec -T vpn-hub wg show wg0 >/dev/null 2>&1; then + if darf_eingreifen; then + say "wg0 steht nicht — ziehe den Tunnel hoch." + lange_frist docker compose exec -T vpn-hub wg-quick up wg0 >/dev/null 2>&1 || true + geheilt=true - if docker compose exec -T vpn-hub wg show wg0 >/dev/null 2>&1; then - say "wg0 steht wieder." - else - say "ACHTUNG: wg0 liess sich nicht hochziehen. Siehe docs/runbooks/tunnel-recovery.md." + if frist docker compose exec -T vpn-hub wg show wg0 >/dev/null 2>&1; then + say "wg0 steht wieder." + else + say "ACHTUNG: wg0 liess sich nicht hochziehen. Siehe docs/runbooks/tunnel-recovery.md." + fi fi fi fi @@ -108,22 +173,29 @@ fi # Ein Update, das mittendrin abbricht, lässt die Seite unten. Bis hierher blieb # sie das, bis jemand nachsah — im Ernstfall stundenlang. # -# Die Sperre oben ist der eigentliche Schutz: läuft ein Update, kommt dieser -# Code gar nicht erst dran. Die halbe Stunde darunter ist der zweite Riegel für -# einen Lauf, der ohne Aufräumen gestorben ist und seine Sperre nie freigab. +# Die Sperre ist der eigentliche Schutz: läuft ein Update, bekommt der Wächter +# sie nicht und lässt den Wartungsmodus in Ruhe. Die halbe Stunde darunter ist +# der zweite Riegel für einen Lauf, der ohne Aufräumen gestorben ist und seine +# Sperre nie freigab. # # `maintenance-hold` ist die Handbremse: wer die Seite bewusst unten haben will, # legt die Datei an, und der Wächter fasst den Wartungsmodus nicht mehr an. -if [[ ! -f "$HOLD" ]] && docker compose exec -T -u www-data app test -f storage/framework/down >/dev/null 2>&1; then +if [[ ! -f "$HOLD" ]] && frist docker compose exec -T -u www-data app test -f storage/framework/down >/dev/null 2>&1; then phase_alt=true if [[ -f "$PHASE_FILE" ]]; then alter=$(( $(date +%s) - $(stat -c %Y "$PHASE_FILE" 2>/dev/null || echo 0) )) [[ "$alter" -lt 1800 ]] && phase_alt=false fi - if [[ "$phase_alt" == true ]]; then + # Auch hier die zweite Frage nach dem Nehmen der Sperre: die Seite hochzu- + # holen, während ein Update gerade migriert, ist der Schaden, gegen den + # dieser ganze Block abgesichert gehört. Zwischen dem ungesperrten Blick + # oben und der Sperre kann ein Update fertig geworden sein — dann ist die + # Seite längst oben und es gibt nichts zu tun. + if [[ "$phase_alt" == true ]] && darf_eingreifen \ + && frist docker compose exec -T -u www-data app test -f storage/framework/down >/dev/null 2>&1; then say "Der Wartungsmodus haengt seit ueber einer halben Stunde ohne laufendes Update — beende ihn." - docker compose exec -T -u www-data app php artisan up >/dev/null 2>&1 || true + lange_frist docker compose exec -T -u www-data app php artisan up >/dev/null 2>&1 || true geheilt=true fi fi diff --git a/tests/Feature/DeploymentRunsAsTheAppUserTest.php b/tests/Feature/DeploymentRunsAsTheAppUserTest.php index 6c4a0f1..0cdc5c9 100644 --- a/tests/Feature/DeploymentRunsAsTheAppUserTest.php +++ b/tests/Feature/DeploymentRunsAsTheAppUserTest.php @@ -343,7 +343,19 @@ it('haelt einen Waechter bereit, der einen halb liegengebliebenen Stapel selbst // Er fasst nichts an, solange ein Update laeuft: dieselbe Sperre wie der // Update-Agent, und weg, wenn er sie nicht bekommt. - expect($watchdog)->toContain('flock -n 9 || exit 0') + // + // Aber er nimmt sie ERST BEIM EINGRIFF. Bis August 2026 stand hier + // `flock -n 9 || exit 0` als erste Handlung des Skripts — der Waechter + // hielt die Sperre also jede Minute, auch wenn er nur nachsah, und der + // Update-Agent kam nicht mehr an die Arbeit. Diese Zeile darf nicht + // zurueckkommen; dass die Zurueckhaltung trotzdem wirkt, fuehrt + // WatchdogLockContentionTest mit zwei echten Prozessen vor. + expect($watchdog)->toContain('flock -n 9') + ->and($watchdog)->toContain('darf_eingreifen') + ->and($watchdog)->not->toContain('flock -n 9 || exit 0') + // Kein Aufruf nach draussen ohne Frist — sonst haengt ein Waechter am + // Docker-Daemon und haelt die Sperre, die er gerade genommen hat. + ->and($watchdog)->toContain('timeout -k') // Die vier Fehlerbilder, die heute wirklich passiert sind. ->and($watchdog)->toContain('docker compose up -d') ->and($watchdog)->toContain('--force-recreate') diff --git a/tests/Feature/WatchdogLockContentionTest.php b/tests/Feature/WatchdogLockContentionTest.php new file mode 100644 index 0000000..bc09fdd --- /dev/null +++ b/tests/Feature/WatchdogLockContentionTest.php @@ -0,0 +1,161 @@ +> "\$STUB_LOG" + touch "\$STUB_STARTED" + sleep "\${STUB_SLEEP:-1}" + case "\$*" in + *config*) printf '%s\\n' app redis ;; + *"ps "*) printf '%s\\n' $running ;; + *getent*) exit "\${STUB_REDIS_RC:-0}" ;; + *storage/framework/down*) exit 1 ;; + *" up "*) touch "\$STUB_UP_CALLED" ;; + esac + exit 0 + SH); + + // Ein `git`, das sofort scheitert. Der Agent fängt das ab; dieser Test hat + // keinen Grund, die Gegenstelle abzurufen. + File::put($stub.'/git', "#!/bin/sh\nexit 1\n"); + + Process::run("chmod +x {$stub}/docker {$stub}/git"); + + return $stub; +} + +afterEach(function () { + File::deleteDirectory(storage_path('app/deploy')); +}); + +it('lets the agent work while the watchdog is only looking', function () { + // Der gemeldete Fall: nichts ist kaputt, der Wächter sieht nur nach — und + // der Agent kommt trotzdem nicht an die Arbeit. + $dir = deployDir(); + $stub = dockerStub(); + + $result = Process::path(base_path()) + ->timeout(90) + ->env([ + 'PATH' => $stub.':'.env('PATH', '/usr/local/bin:/usr/bin:/bin'), + 'STUB_LOG' => $dir.'/.stub-log', + 'STUB_STARTED' => $dir.'/.stub-started', + 'STUB_UP_CALLED' => $dir.'/.stub-up-called', + ]) + ->run(<</dev/null 2>&1 & + waechter=\$! + # Nachweislich MITTEN im Lauf des Wächters, nicht davor und nicht + # danach: erst wenn die Attrappe angefasst wurde, ist er drin. + until [ -f "\$STUB_STARTED" ]; do sleep 0.05; done + bash deploy/update-agent.sh >/dev/null 2>&1 || true + kill \$waechter 2>/dev/null || true + wait \$waechter 2>/dev/null || true + BASH); + + expect($result->successful())->toBeTrue($result->errorOutput()); + + $alive = json_decode(File::get($dir.'/agent-alive.json'), true); + + expect($alive['state'])->toBe('running') + ->and($alive['skips'])->toBe(0); +}); + +it('keeps the watchdog away while an update holds the lock', function () { + // Die andere Hälfte, und die teurere: der Wächter darf NICHT eingreifen, + // während ein Update läuft. Er sieht hier einen fehlenden Dienst — also + // etwas, das er sonst sofort richten würde — und muss die Hände trotzdem + // stillhalten, weil die Sperre gehalten wird. + $dir = deployDir(); + $stub = dockerStub(running: 'redis'); + + $result = Process::path(base_path()) + ->timeout(90) + ->env([ + 'PATH' => $stub.':'.env('PATH', '/usr/local/bin:/usr/bin:/bin'), + 'STUB_LOG' => $dir.'/.stub-log', + 'STUB_STARTED' => $dir.'/.stub-started', + 'STUB_UP_CALLED' => $dir.'/.stub-up-called', + ]) + ->run(<< storage/app/deploy/.watchdog-out 2>&1 || true + kill \$halter 2>/dev/null || true + BASH); + + expect($result->successful())->toBeTrue($result->errorOutput()); + + expect(File::exists($dir.'/.stub-up-called')) + ->toBeFalse('Der Waechter hat eingegriffen, obwohl die Sperre gehalten wurde.'); +}); + +it('says in the journal that a run was skipped', function () { + // Ein übersprungener Lauf sah im Journal aus wie ein erfolgreicher — der + // Agent beendet sich sauber, systemd meldet Starting → Deactivated. Das + // hat die Fehlersuche zweimal in die falsche Richtung geschickt. + $dir = deployDir(); + + $result = Process::path(base_path()) + ->timeout(60) + ->run(<<<'BASH' + flock storage/app/deploy/.agent.lock -c 'touch storage/app/deploy/.held; sleep 20' & + halter=$! + until [ -f storage/app/deploy/.held ]; do sleep 0.05; done + bash deploy/update-agent.sh 2>&1 + kill $halter 2>/dev/null || true + BASH); + + // Die Zeile nennt den Halter mit: der Waechter fuer einen Lauf ist + // Betrieb, derselbe Halter seit vierzig Laeufen ist es nicht — und genau + // diese Unterscheidung war im Journal bisher nicht zu treffen. + expect($result->output()) + ->toContain('Uebersprungen') + ->toContain('die Sperre haelt'); +});