Pruefungen: der Rueckgabewert 127, der "in Ordnung" meldete
pruef-call-kategorien gab dreimal von dreimal 127 zurueck -- NACH der Zeile "ALLES IN ORDNUNG". Ursache ist eine libuv-Assertion auf Windows: Assertion failed: !(handle->flags & UV_HANDLE_CLOSING), file src\win\async.c, line 94 `process.exit()` schlaegt zu, waehrend Playwright seinen Transportkanal noch abbaut. Das Ergebnis stimmte, der Rueckgabewert log. In einem Sammellauf zaehlt so ein Lauf als Fehlschlag, obwohl nichts fehlschlug -- und wer sich angewoehnt, den Rueckgabewert dieser einen Datei zu ignorieren, uebersieht spaeter den echten. Meine Notiz sagte "sporadisch". Es war drei von drei. Auch eigene Notizen altern. MEIN ERSTER FIX 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: auf das Ereignis "disconnected" warten, danach zwoelf Runden der Ereignisschleife (setImmediate). Sauber begruendet. Gemessen: ZWEI VON DREI Laeufen weiterhin 127. Die feste Pause, die ich fuer schlechter hielt, war zweimal gruen. Die Annahme war falsch: "disconnected" meldet, dass die Verbindung weg ist, nicht dass der Kanal abgebaut ist -- und setImmediate gibt der Schleife Durchlaeufe, aber keine ZEIT. Der Kindprozess braucht echte Millisekunden. Eine stimmige Herleitung ersetzt keine Messung. Jetzt beides: erst das Ereignis (richtige Ordnung), dann eine zeitliche Reserve von 600 ms gegen gemessene 400, ueber PRUEF_ABBAU_MS einstellbar. Fuenf Laeufe hintereinander gruen. Neu: server/helfer-beenden.mjs (sauberBeenden) und tools/mess-rueckgabewerte.sh -- letzteres misst alle 42 Browser- Pruefungen mit demselben Muster daraufhin, ob noch weitere "in Ordnung" melden und trotzdem einen Fehlercode zurueckgeben. Laeuft nacheinander, nicht parallel: Zwei gleichzeitige Prueflaeufe sind kein Prueflauf. Co-Authored-By: Claude Opus 5 <[email protected]>
This commit is contained in:
@@ -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
|
||||
|
||||
@@ -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);
|
||||
}
|
||||
@@ -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);
|
||||
|
||||
@@ -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"
|
||||
Reference in New Issue
Block a user