diff --git a/app/Services/Deployment/UpdateChannel.php b/app/Services/Deployment/UpdateChannel.php index dca5d86..5601d36 100644 --- a/app/Services/Deployment/UpdateChannel.php +++ b/app/Services/Deployment/UpdateChannel.php @@ -181,6 +181,28 @@ final class UpdateChannel */ private const AGENT_STALE_AFTER_MINUTES = 20; + /** + * Wie viele Läufe hintereinander übersprungen sein müssen, ehe das eine + * Blockade heißt. + * + * Ein einzelner übersprungener Lauf ist Betrieb: der Zeitgeber läuft + * minütlich, der Wächter (deploy/watchdog.sh) kommt dazu, einer nimmt die + * Sperre und der andere geht weg. Gemessen wurde ein Überholen von NEUN + * SEKUNDEN — und die Konsole meldete dafür bereits „kommt seit 15:21 nicht + * an die Arbeit". Der Besitzer hat daraufhin eine Stunde lang eine gesunde + * Anlage auseinandergenommen. + * + * Zwei, nicht zehn: lieber früh gewarnt werden. Weg soll nur die Warnung + * beim allerersten übersprungenen Lauf. + * + * Gezählt wird in LÄUFEN, nicht in Minuten. `check_interval_minutes` ist + * eine Behauptung des Agentenskripts; wie oft der Zeitgeber wirklich + * auslöst, steht in der systemd-Unit auf dem Wirt, die diese Anwendung + * nicht sehen kann. Zwei übersprungene Läufe sind zwei übersprungene + * Läufe, wie der Takt auch stehen mag. + */ + private const BLOCKED_AFTER_SKIPS = 2; + /** * What the panel needs to show, in one read. * @@ -202,7 +224,17 @@ final class UpdateChannel // Der Agent läuft, kommt aber nicht an die Sperre. Ein eigener // Zustand, weil er weder „tot" ist noch „in Ordnung": seine Zahlen // stammen von vor der Blockade und altern still weiter. - $blockedSince = ($alive['state'] ?? null) === 'blocked' && $agentAlive + // + // Erst ab BLOCKED_AFTER_SKIPS übersprungenen Läufen — und zwar für den + // GANZEN Zustand, nicht nur für den Satz weiter unten in der Ansicht. + // Nur die Meldung zu unterdrücken hätte den Fehlalarm gegen einen + // stilleren getauscht: `blocked_since` blendet über $agentWorking auch + // „N Aktualisierungen zurück" und die Zielversion aus, und die wären + // dann beim ersten übersprungenen Lauf verschwunden, ohne dass + // irgendwo stünde warum. Eine Schwelle, eine Stelle. + $blockedSince = ($alive['state'] ?? null) === 'blocked' + && $agentAlive + && $this->skippedRuns($alive) >= self::BLOCKED_AFTER_SKIPS ? $this->timestamp($alive['since'] ?? null) : null; @@ -417,6 +449,27 @@ final class UpdateChannel && $checkedAt->gt(Carbon::now()->subMinutes(self::AGENT_STALE_AFTER_MINUTES)); } + /** + * Wie viele Läufe der Agent ununterbrochen übersprungen hat. + * + * Vom Agenten mitgezählt (deploy/update-agent.sh), weil nur er weiß, wie + * oft er angetreten ist. Aus `since` eine Zahl auszurechnen hieße, das + * Taktintervall zu raten — und das steht auf dem Wirt, nicht hier. + * + * Fehlt das Feld, gilt EINS: das ist das Lebenszeichen eines Agenten von + * vor dieser Zählung, das nach einem Update noch eine Minute liegen + * bleibt. Darauf eine Blockade zu melden hieße raten; der nächste Takt + * schreibt die Zahl und korrigiert es von selbst. + * + * @param array $alive + */ + private function skippedRuns(array $alive): int + { + return isset($alive['skips']) && is_numeric($alive['skips']) + ? (int) $alive['skips'] + : 1; + } + /** Is the agent in the middle of a run right now? */ public function isRunning(): bool { diff --git a/deploy/update-agent.sh b/deploy/update-agent.sh index a7773a5..b044b6e 100755 --- a/deploy/update-agent.sh +++ b/deploy/update-agent.sh @@ -96,7 +96,7 @@ mkdir -p "$STATE_DIR" # Text ist die Ausgabe von ps, aus der Anfuehrungszeichen, Backslashes und # Zeilenumbrueche entfernt werden. write_alive() { - local state="$1" since="${2-}" held_by="${3-}" + local state="$1" since="${2-}" held_by="${3-}" skips="${4-0}" held_by="$(printf '%s' "$held_by" | tr -d '"\\' | tr '\n\r\t' ' ')" cat > "$ALIVE.tmp" 2>/dev/null </dev/null || true @@ -125,6 +126,18 @@ if ! flock -n 9; then # laeuft — sonst stuende dort immer "seit einer Minute", und ein Zustand, # der seit einer Stunde klemmt, laese sich von einem gesunden Ueberholen # zweier Laeufe nicht unterscheiden. + # + # Und mit `skips` wird die Serie GEZAEHLT, nicht nur datiert. Bis hierher + # meldete die Konsole schon beim ERSTEN uebersprungenen Lauf eine Blockade; + # gemessen wurde das bei einem Ueberholen von neun Sekunden — Zeitgeber und + # Waechter laufen beide minuetlich, einer nimmt die Sperre, der andere geht + # weg. Das ist Betrieb. Der Besitzer hat daraufhin eine Stunde lang eine + # gesunde Anlage auseinandergenommen. + # + # Gezaehlt wird HIER und nicht in der Konsole: aus `since` eine Zahl von + # Laeufen zu machen hiesse, das Taktintervall zu raten, und das steht in + # der systemd-Unit auf dem Wirt. Ab wann die Zahl eine Meldung wert ist, + # entscheidet die Konsole (UpdateChannel::BLOCKED_AFTER_SKIPS). HOLDER="$( { fuser "$LOCK" 2>/dev/null || true; } | tr -s ' ' | sed 's/^ *//;s/ *$//' )" HOLDER_CMD='' if [[ -n "$HOLDER" ]]; then @@ -133,11 +146,21 @@ if ! flock -n 9; then PREVIOUS_SINCE="$(sed -n 's/.*"since"[[:space:]]*:[[:space:]]*"\([^"]*\)".*/\1/p' "$ALIVE" 2>/dev/null | head -1 || true)" PREVIOUS_STATE="$(sed -n 's/.*"state"[[:space:]]*:[[:space:]]*"\([^"]*\)".*/\1/p' "$ALIVE" 2>/dev/null | head -1 || true)" + PREVIOUS_SKIPS="$(sed -n 's/.*"skips"[[:space:]]*:[[:space:]]*\([0-9]*\).*/\1/p' "$ALIVE" 2>/dev/null | head -1 || true)" + if [[ "$PREVIOUS_STATE" != "blocked" || -z "$PREVIOUS_SINCE" ]]; then + # Kein Anschluss an eine laufende Serie: dieser Lauf ist der erste. PREVIOUS_SINCE="$(date -u +%Y-%m-%dT%H:%M:%SZ)" + SKIPS=1 + else + # Ein Lebenszeichen von vor dieser Zaehlung hat kein `skips`. Es bleibt + # nach einem Update eine Minute lang liegen; solange zaehlt die Serie + # ab eins weiter, statt eine Zahl zu erfinden. + [[ "$PREVIOUS_SKIPS" =~ ^[0-9]+$ ]] || PREVIOUS_SKIPS=0 + SKIPS=$(( PREVIOUS_SKIPS + 1 )) fi - write_alive blocked "$PREVIOUS_SINCE" "${HOLDER_CMD:-$HOLDER}" + write_alive blocked "$PREVIOUS_SINCE" "${HOLDER_CMD:-$HOLDER}" "$SKIPS" exit 0 fi diff --git a/tests/Feature/Admin/UpdateButtonTest.php b/tests/Feature/Admin/UpdateButtonTest.php index cb08c65..4b79106 100644 --- a/tests/Feature/Admin/UpdateButtonTest.php +++ b/tests/Feature/Admin/UpdateButtonTest.php @@ -1026,7 +1026,7 @@ function writeAlive(array $alive): void */ it('calls the agent alive on its heartbeat, even when its last check is old', function () { writeStatus(['state' => 'idle', 'checked_at' => now()->subHour()->toIso8601String(), 'behind' => 3]); - writeAlive(['at' => now()->toIso8601String(), 'state' => 'blocked', 'since' => now()->subMinutes(40)->toIso8601String(), 'held_by' => '4242 40:12 git fetch']); + writeAlive(['at' => now()->toIso8601String(), 'state' => 'blocked', 'since' => now()->subMinutes(40)->toIso8601String(), 'held_by' => '4242 40:12 git fetch', 'skips' => 40]); $state = app(UpdateChannel::class)->state(); @@ -1039,7 +1039,7 @@ it('does not pass off an hour-old figure as current while the agent is blocked', // Die Zahlen stammen von VOR der Blockade und altern still weiter. „Drei // Updates zurueck" von vor einer Stunde liest sich genau wie von jetzt. writeStatus(['state' => 'idle', 'checked_at' => now()->subHour()->toIso8601String(), 'behind' => 3, 'target_release' => 'v9.9.9']); - writeAlive(['at' => now()->toIso8601String(), 'state' => 'blocked', 'since' => now()->subMinutes(40)->toIso8601String(), 'held_by' => '']); + writeAlive(['at' => now()->toIso8601String(), 'state' => 'blocked', 'since' => now()->subMinutes(40)->toIso8601String(), 'held_by' => '', 'skips' => 40]); $state = app(UpdateChannel::class)->state(); @@ -1050,7 +1050,7 @@ it('does not pass off an hour-old figure as current while the agent is blocked', it('says the service is blocked, not that it is not running', function () { writeStatus(['state' => 'idle', 'checked_at' => now()->subHour()->toIso8601String(), 'behind' => 1]); - writeAlive(['at' => now()->toIso8601String(), 'state' => 'blocked', 'since' => now()->subMinutes(40)->toIso8601String(), 'held_by' => '4242 40:12 git fetch']); + writeAlive(['at' => now()->toIso8601String(), 'state' => 'blocked', 'since' => now()->subMinutes(40)->toIso8601String(), 'held_by' => '4242 40:12 git fetch', 'skips' => 40]); Livewire::actingAs(operator('Owner'), 'operator') ->test(AdminSettings::class) @@ -1058,6 +1058,65 @@ it('says the service is blocked, not that it is not running', function () { ->assertSee('4242 40:12 git fetch'); }); +/** + * ── Ein einzelner uebersprungener Lauf ist Betrieb, kein Fehler ─────────── + * + * Der Zeitgeber laeuft minuetlich, der Waechter kommt dazu, einer nimmt die + * Sperre und der andere ueberspringt. Gemessen am 4. August 2026: neun + * Sekunden Ueberholen — und die Konsole meldete bereits eine Blockade. Der + * Besitzer hat daraufhin eine Stunde lang eine gesunde Anlage auseinander- + * genommen. + * + * Gezaehlt wird in LAEUFEN, nicht in Minuten: CHECK_INTERVAL_MINUTES ist eine + * Behauptung des Skripts, das tatsaechliche Intervall steht in der + * systemd-Unit auf dem Wirt. + */ +it('does not cry blockade over a single skipped run', function () { + writeStatus(['state' => 'idle', 'checked_at' => now()->subMinute()->toIso8601String(), 'behind' => 3, 'target_release' => 'v9.9.9']); + writeAlive(['at' => now()->toIso8601String(), 'state' => 'blocked', 'since' => now()->subSeconds(9)->toIso8601String(), 'held_by' => '4242 00:09 watchdog', 'skips' => 1]); + + $state = app(UpdateChannel::class)->state(); + + // Und die Zahlen bleiben stehen. Nur die Meldung zu unterdruecken haette + // den Fehlalarm gegen einen stilleren getauscht: „drei Aktualisierungen + // zurueck" waere beim ersten uebersprungenen Lauf verschwunden, ohne dass + // irgendwo stuende warum. + expect($state['blocked_since'])->toBeNull() + ->and($state['blocked_by'])->toBeNull() + ->and($state['behind'])->toBe(3) + ->and($state['target_release'])->toBe('v9.9.9'); + + Livewire::actingAs(operator('Owner'), 'operator') + ->test(AdminSettings::class) + ->assertDontSee(__('admin_settings.update_agent_blocked', ['since' => '00:00'])); +}); + +it('reports the blockade from the second skipped run on', function () { + // Bewusst zwei und nicht zehn: lieber frueh gewarnt werden, nur nicht + // beim allerersten Lauf. + writeStatus(['state' => 'idle', 'checked_at' => now()->subMinutes(2)->toIso8601String(), 'behind' => 3]); + writeAlive(['at' => now()->toIso8601String(), 'state' => 'blocked', 'since' => now()->subMinutes(2)->toIso8601String(), 'held_by' => '4242 02:03 docker compose exec', 'skips' => 2]); + + $state = app(UpdateChannel::class)->state(); + + expect($state['blocked_since'])->not->toBeNull() + ->and($state['blocked_by'])->toBe('4242 02:03 docker compose exec') + ->and($state['behind'])->toBeNull(); +}); + +it('says nothing about a blockade on a heartbeat from before the counter existed', function () { + // Ein Lebenszeichen, das der vorige Stand geschrieben hat, bleibt nach + // einem Update eine Minute lang liegen. Es hat kein `skips`, und daraus + // eine Blockade zu machen waere geraten. + writeStatus(['state' => 'idle', 'checked_at' => now()->toIso8601String(), 'behind' => 2]); + writeAlive(['at' => now()->toIso8601String(), 'state' => 'blocked', 'since' => now()->subMinutes(40)->toIso8601String(), 'held_by' => '4242 40:12 git fetch']); + + $state = app(UpdateChannel::class)->state(); + + expect($state['blocked_since'])->toBeNull() + ->and($state['behind'])->toBe(2); +}); + it('keeps the old rule for an agent that writes no heartbeat at all', function () { // Ein Agent von vor dieser Aenderung kennt die Datei nicht. Ihn dafuer fuer // tot zu erklaeren waere derselbe Fehler mit umgekehrtem Vorzeichen. diff --git a/tests/Feature/UpdateAgentSkipCountTest.php b/tests/Feature/UpdateAgentSkipCountTest.php new file mode 100644 index 0000000..702534c --- /dev/null +++ b/tests/Feature/UpdateAgentSkipCountTest.php @@ -0,0 +1,142 @@ +|null $seedAlive Lebenszeichen, das vorher liegt + * @return array> je ein Lebenszeichen pro Lauf + */ +function runBlockedAgent(int $times, ?array $seedAlive = null): array +{ + $dir = storage_path('app/deploy'); + File::ensureDirectoryExists($dir); + File::delete(File::glob($dir.'/.alive-*')); + File::delete($dir.'/agent-alive.json'); + File::delete($dir.'/.held'); + + if ($seedAlive !== null) { + File::put($dir.'/agent-alive.json', json_encode($seedAlive)); + } + + $runs = ''; + for ($i = 1; $i <= $times; $i++) { + $runs .= "bash deploy/update-agent.sh >/dev/null 2>&1\n"; + $runs .= "cp storage/app/deploy/agent-alive.json storage/app/deploy/.alive-{$i}\n"; + } + + // Die Sperre wird nachweislich gehalten, bevor der Agent startet: der + // Halter legt erst die Marke an, dann wird auf sie gewartet. Ohne diesen + // Nachweis liefe der Agent bei einem Fehlschlag von flock in seinen + // NORMALEN Weg — mit Abruf der Gegenstelle und allem, was daran hängt — + // und der Test hätte still etwas ganz anderes gemessen. + $result = Process::path(base_path()) + ->timeout(60) + ->run(<</dev/null || true + BASH); + + expect($result->successful())->toBeTrue($result->errorOutput()); + + return array_map( + fn (int $i) => json_decode(File::get($dir."/.alive-{$i}"), true), + range(1, $times) + ); +} + +afterEach(function () { + File::deleteDirectory(storage_path('app/deploy')); +}); + +it('counts a single skipped run as one, not as a blockade', function () { + // Der gemessene Fall: neun Sekunden Überholen zwischen Zeitgeber und + // Wächter. Betrieb, kein Fehler. + [$first] = runBlockedAgent(1); + + expect($first['state'])->toBe('blocked') + ->and($first['skips'])->toBe(1); +}); + +it('keeps counting while the same blockade holds', function () { + [$first, $second] = runBlockedAgent(2); + + expect($first['skips'])->toBe(1) + ->and($second['skips'])->toBe(2) + // Und `since` bleibt stehen — sonst stünde dort immer „seit einer + // Minute" und eine Stunde Stillstand sähe aus wie ein Überholen. + ->and($second['since'])->toBe($first['since']); +}); + +it('starts the count over after a run that got the lock', function () { + // Ein Lebenszeichen aus einem Lauf, der gearbeitet hat, beendet die Serie. + // Ohne diesen Schnitt liefe der Zähler über eine gesunde Zwischenzeit + // hinweg weiter und meldete eine Blockade, die längst vorbei war. + [$first] = runBlockedAgent(1, [ + 'at' => '2026-08-04T05:00:00Z', + 'state' => 'running', + 'since' => '', + 'held_by' => '', + 'skips' => 0, + ]); + + expect($first['state'])->toBe('blocked') + ->and($first['skips'])->toBe(1); +}); + +it('says zero skipped runs while it is working', function () { + // Der Zustand, in dem der Agent die Sperre HAT. Ohne die ausdrückliche + // Null bliebe die Zahl des letzten blockierten Laufs im Lebenszeichen + // stehen, und die Konsole läse sie als fortdauernde Blockade. + // + // Hier läuft der Agent auf der freien Sperre — also durch seinen normalen + // Weg. `git` und `docker` liegen dafür als Attrappen im PATH, die sofort + // scheitern: dieser Test prüft, was der Agent ins Lebenszeichen schreibt, + // und hat keinen Grund, dafür die Gegenstelle abzurufen oder den + // Docker-Daemon anzufassen. Beide Fehlschläge sind Wege, die der Agent + // ohnehin abfängt. + $dir = storage_path('app/deploy'); + File::ensureDirectoryExists($dir); + File::delete($dir.'/agent-alive.json'); + + // Der Ausgang des Laufs wird NICHT geprüft: mit einem `git`, das immer + // scheitert, kann der Agent nicht bis zum Ende kommen, und ans Ende zu + // kommen ist hier auch nicht die Frage. Das Lebenszeichen steht als + // ERSTES, noch vor allem, was scheitern kann — genau deshalb gibt es die + // Datei überhaupt. + Process::path(base_path())->timeout(60)->run(<<<'BASH' + stub="$(mktemp -d)" + printf '#!/bin/sh\nexit 1\n' > "$stub/git" + printf '#!/bin/sh\nexit 1\n' > "$stub/docker" + chmod +x "$stub/git" "$stub/docker" + PATH="$stub:$PATH" bash deploy/update-agent.sh >/dev/null 2>&1 + rm -rf "$stub" + BASH); + + $alive = json_decode(File::get($dir.'/agent-alive.json'), true); + + expect($alive['state'])->toBe('running') + ->and($alive['skips'])->toBe(0); +});