Ein einzelner übersprungener Lauf ist kein Ausfall

Die Konsole meldete „kommt seit HH:MM nicht an die Arbeit", sobald der
Agent EINMAL an der Sperre vorbeilief. Gemessen wurde das bei einem
Überholen von neun Sekunden: Zeitgeber und Wächter laufen beide
minütlich, einer nimmt die Sperre, der andere geht weg. Das ist Betrieb,
kein Fehler — und der Besitzer hat daraufhin eine Stunde lang eine
gesunde Anlage auseinandergenommen.

Der Kopfkommentar an der Stelle kannte den Unterschied längst („ließe
sich von einem gesunden Überholen zweier Läufe nicht unterscheiden").
Die Dauer wurde mitgeführt, nur gegen nichts verglichen.

Der Agent zählt die Serie jetzt mit (`skips` im Lebenszeichen), die
Konsole macht ab zwei Läufen eine Meldung daraus. Gezählt wird in
LÄUFEN, nicht in Minuten: wie oft der Zeitgeber wirklich auslöst, steht
in der systemd-Unit auf dem Wirt, die diese Anwendung nicht sehen kann.

Die Schwelle gilt für den ganzen Zustand, nicht nur für den Satz. Nur
die Meldung zu unterdrücken hätte den Fehlalarm gegen einen stilleren
getauscht: `blocked_since` blendet auch „N Aktualisierungen zurück" und
die Zielversion aus, und die wären beim ersten übersprungenen Lauf
verschwunden, ohne dass irgendwo stünde warum.

Geprüft wird der Zähler am echten Skript, nicht an einer Nachbildung
seiner Logik: der Zweig liegt vor allem Teuren, also läuft der Agent im
Test gegen eine gehaltene Sperre und steigt aus, bevor `git fetch` oder
`docker compose` in die Nähe kommen.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
claude/nice-moser-521659
nexxo 2026-08-04 09:42:07 +02:00
parent 5eef03d267
commit 6a5609cfc7
4 changed files with 284 additions and 7 deletions

View File

@ -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<string, mixed> $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
{

View File

@ -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 <<EOF || return 0
@ -104,7 +104,8 @@ write_alive() {
"at": "$(date -u +%Y-%m-%dT%H:%M:%SZ)",
"state": "$state",
"since": "$since",
"held_by": "$held_by"
"held_by": "$held_by",
"skips": ${skips}
}
EOF
mv -f "$ALIVE.tmp" "$ALIVE" 2>/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

View File

@ -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.

View File

@ -0,0 +1,142 @@
<?php
use Illuminate\Support\Facades\File;
use Illuminate\Support\Facades\Process;
/**
* Der Agent zählt, wie oft er hintereinander nicht an die Arbeit kam.
*
* Die Konsole macht daraus erst ab zwei Läufen eine Meldung (siehe
* UpdateChannel::BLOCKED_AFTER_SKIPS). Damit sie das kann, muss der Agent die
* Zahl liefern ausrechnen kann die Konsole sie nicht: dafür müsste sie das
* Taktintervall kennen, und das steht in der systemd-Unit auf dem Wirt.
*
* Hier läuft das ECHTE Skript, nicht eine Nachbildung seiner Logik. Das geht,
* weil der Zweig, um den es hier geht, vor allem Teuren liegt: der Agent nimmt
* die Sperre in der ersten Handvoll Zeilen, und wer sie nicht bekommt, steigt
* aus, bevor irgendein `git fetch` oder `docker compose` in die Nähe kommt.
* Ein Test, der die Zählung nachrechnet statt sie auszuführen, prüft nichts
* das steht schon in R19 im Repo.
*/
/**
* Lässt den Agenten $times mal gegen eine gehaltene Sperre laufen.
*
* @param array<string, mixed>|null $seedAlive Lebenszeichen, das vorher liegt
* @return array<int, array<string, mixed>> 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(<<<BASH
set -e
flock storage/app/deploy/.agent.lock -c 'touch storage/app/deploy/.held; sleep 30' &
halter=\$!
until [ -f storage/app/deploy/.held ]; do sleep 0.05; done
{$runs}
kill \$halter 2>/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);
});