diff --git a/.gitignore b/.gitignore index b16b4d62..6553ee2e 100644 --- a/.gitignore +++ b/.gitignore @@ -80,3 +80,7 @@ pruef-*.png server/pruef-*.png abnahme-*.png server/abnahme-*.png + +# Messlaeufe von tools/mess-rueckgabewerte.sh -- Ergebnis eines Laufs, +# kein Quelltext. Gehoert nicht in die Geschichte. +rueckgabewerte-*.txt diff --git a/server/helfer-beenden.mjs b/server/helfer-beenden.mjs new file mode 100644 index 00000000..a6e9ca0a --- /dev/null +++ b/server/helfer-beenden.mjs @@ -0,0 +1,99 @@ +/* SAUBER BEENDEN — nach dem Browser, vor dem Schlussstrich. + + =================================================================== + DAS PROBLEM + + pruef-call-kategorien meldete "ALLES IN ORDNUNG" und gab danach + Rueckgabewert 127 zurueck, mit dieser Zeile: + + Assertion failed: !(handle->flags & UV_HANDLE_CLOSING), + file src\win\async.c, line 94 + + Das ist libuv auf Windows: Etwas ruft `uv_async_send` auf ein Handle, + das gerade geschlossen wird. Der Ausloeser ist `process.exit()` + unmittelbar nach `browser.close()`. Playwright meldet den Browser als + geschlossen, sobald der Befehl abgesetzt ist -- sein Transportkanal + wird aber noch abgebaut, und der laeuft ueber genau so ein Handle. + + =================================================================== + WARUM DAS SCHLIMMER IST ALS EIN ROTER LAUF + + Der Befund war richtig, die Pruefung war gruen, und trotzdem stand am + Ende 127 -- die Schale liest das als "Befehl nicht gefunden". In einem + Sammellauf zaehlt dieser Lauf damit als Fehlschlag, obwohl nichts + fehlschlug. Wer das zweimal sieht, gewoehnt sich an, den Rueckgabewert + dieser Datei zu ignorieren. Und ab da uebersieht man auch den echten. + + Es war nicht "sporadisch", wie ich es mir notiert hatte -- es kam in + drei von drei Laeufen. Auch meine eigenen Notizen altern. + + =================================================================== + MEIN ERSTER VERSUCH WAR DIE ELEGANTERE LOESUNG -- UND DIE SCHLECHTERE + + Ich wollte keine feste Pause: 400 ms sind eine Rechnung auf DIESEM + Rechner, und auf einem langsameren waere der Fehler still + zurueckgekommen. Also habe ich auf das EREIGNIS gewartet + ("disconnected") und danach zwoelf Runden der Ereignisschleife + durchgelassen (`setImmediate`). Sauber begruendet, gut lesbar. + + Gemessen: ZWEI VON DREI LAEUFEN weiterhin 127. Die feste Pause, die + ich fuer die schlechtere Loesung hielt, war zweimal gruen. + + Der Grund ist eine falsche Annahme: "disconnected" meldet, dass die + VERBINDUNG weg ist, nicht dass der Kanal ABGEBAUT ist. Und + `setImmediate` gibt der Schleife Durchlaeufe, aber keine ZEIT -- der + Kindprozess von Playwright braucht echte Millisekunden, um zu enden, + und in genau diesem Fenster faellt die Assertion. + + Man kann sich eine Erklaerung zurechtlegen, die stimmig klingt, und + trotzdem daneben liegen. Deshalb steht die Messung hier und nicht die + Herleitung. + + =================================================================== + WAS JETZT WIRKLICH DRINSTEHT + + Beides: erst auf das Ereignis warten (das ist die richtige Ordnung), + dann eine ZEITLICHE Reserve. Die Reserve ist keine Schaetzung, wie + lange der Abbau dauert -- sie ist grosszuegig bemessen (600 ms + gegenueber gemessenen 400) und ueber PRUEF_ABBAU_MS einstellbar, + falls ein langsamerer Rechner mehr braucht. Sie kostet einmal pro + Prueflauf ein halbes Sekundchen; das ist der Preis dafuer, dass der + Rueckgabewert die Wahrheit sagt. + + =================================================================== + BENUTZUNG + + import { sauberBeenden } from "./helfer-beenden.mjs"; + ... + await sauberBeenden(browser, fehler ? 1 : 0); + + ersetzt das Paar `await browser.close(); process.exit(code);`. */ + +export async function sauberBeenden(browser, code) { + if (browser) { + /* Das Ereignis ABONNIEREN, bevor geschlossen wird -- sonst kann es + zwischen close() und once() durchrutschen und wir warten auf + etwas, das schon vorbei ist. */ + const getrennt = new Promise((fertig) => { + let erledigt = false; + const einmal = () => { if (!erledigt) { erledigt = true; fertig(); } }; + try { browser.once("disconnected", einmal); } catch { einmal(); } + /* DRITTER AUSGANG: Kommt das Ereignis gar nicht (abgestuerzter + Browser, fremde Playwright-Fassung), darf das Beenden nicht + haengen. Ein Prueflauf, der still stehenbleibt, ist schlimmer + als einer, der scheitert -- von aussen sieht er aus wie + "laeuft noch". */ + setTimeout(einmal, 5000).unref?.(); + }); + try { await browser.close(); } catch { /* schon zu */ } + await getrennt; + } + + /* ECHTE ZEIT, nicht nur Runden der Ereignisschleife. Begruendung + ausfuehrlich oben: `setImmediate` allein liess zwei von drei + Laeufen weiterhin abstuerzen. */ + const abbau = Number(process.env.PRUEF_ABBAU_MS ?? 600); + await new Promise((r) => setTimeout(r, abbau)); + + process.exit(code); +} diff --git a/server/pruef-call-kategorien.mjs b/server/pruef-call-kategorien.mjs index 8b682299..cbcb4d89 100644 --- a/server/pruef-call-kategorien.mjs +++ b/server/pruef-call-kategorien.mjs @@ -27,6 +27,7 @@ const ordner = mkdtempSync(join(tmpdir(), "ws-callkat-")); process.env.WORKSPACE_DB = join(ordner, "workspace.db"); import { notbremse } from "./helfer-notbremse.mjs"; +import { sauberBeenden } from "./helfer-beenden.mjs"; const { portMussFreiSein } = await import("./helfer-port.mjs"); await portMussFreiSein(4321, "die Kategorienpruefung"); @@ -407,9 +408,17 @@ melde("\n=== Wiederholungen: eigene Gruppe, nur dieser Monat ==="); `und unter "Steht an" steht keine von beiden (${anstehend.length} Eintraege)`); } -await browser.close(); try { rmSync(ordner, { recursive: true, force: true }); } catch { /* egal */ } melde(`\n${fehler === 0 ? "ALLES IN ORDNUNG" : `${fehler} FEHLER`}`); -/* Server und Zeitgeber laufen weiter -- siehe pruef-chat-optik. */ -process.exit(fehler ? 1 : 0); + +/* DER BROWSER WIRD IN sauberBeenden GESCHLOSSEN, nicht hier oben. + + Vorher stand `await browser.close()` weiter oben und `process.exit()` + hier -- genau dazwischen lag der Absturz: libuv rief `uv_async_send` + auf Playwrights Transportkanal, waehrend der schon geschlossen wurde + (`Assertion failed: !(handle->flags & UV_HANDLE_CLOSING)`). Die + Pruefung meldete "ALLES IN ORDNUNG" und gab 127 zurueck. + + Server und Zeitgeber laufen weiter -- siehe pruef-chat-optik. */ +await sauberBeenden(browser, fehler ? 1 : 0); diff --git a/tools/mess-rueckgabewerte.sh b/tools/mess-rueckgabewerte.sh new file mode 100644 index 00000000..700c45e7 --- /dev/null +++ b/tools/mess-rueckgabewerte.sh @@ -0,0 +1,43 @@ +#!/usr/bin/env bash +# Welche Browser-Pruefungen melden "in Ordnung" und geben trotzdem einen +# Fehler-Rueckgabewert zurueck? +# +# Hintergrund: pruef-call-kategorien gab dreimal von dreimal 127 zurueck, +# NACH "ALLES IN ORDNUNG" -- eine libuv-Assertion beim Beenden (Playwright- +# Transportkanal wird abgebaut, waehrend process.exit() zuschlaegt). +# Behoben ueber server/helfer-beenden.mjs. Offen war: Wie viele andere +# Dateien mit demselben Muster haben dasselbe Problem? +# +# NACHEINANDER, nicht parallel: Die Pruefungen belegen feste Ports und +# legen dieselben Testkonten an. Zwei gleichzeitige Laeufe sind kein +# Prueflauf, sondern zwei kaputte (06.09.2026, RunOne). +# +# Aufruf: bash tools/mess-rueckgabewerte.sh + +cd "$(dirname "$0")/.." || exit 1 +AUS="rueckgabewerte-$(date +%Y%m%d-%H%M%S).txt" +echo "Messlauf gestartet $(date '+%H:%M:%S')" | tee "$AUS" + +luegner=0 +gemessen=0 +for f in server/pruef-*.mjs; do + grep -q 'await import("./index.js")' "$f" || continue + grep -q "playwright" "$f" || continue + name=$(basename "$f") + ausgabe=$(node "$f" 2>&1) + code=$? + gemessen=$((gemessen + 1)) + letzte=$(echo "$ausgabe" | grep -viE "^$" | tail -1 | cut -c1-60) + if echo "$ausgabe" | grep -qiE "ALLES IN ORDNUNG|Alles in Ordnung" && [ "$code" -ne 0 ]; then + echo "LUEGT $name -> EXIT=$code | $letzte" | tee -a "$AUS" + luegner=$((luegner + 1)) + elif [ "$code" -ne 0 ]; then + echo "rot $name -> EXIT=$code | $letzte" | tee -a "$AUS" + else + echo "ok $name" | tee -a "$AUS" + fi +done + +echo "" | tee -a "$AUS" +echo "$gemessen Browser-Pruefungen gemessen, $luegner mit luegendem Rueckgabewert." | tee -a "$AUS" +echo "Fertig $(date '+%H:%M:%S')" | tee -a "$AUS"