Read a server's last words before reaping the process that wrote them

[webmatze]

Closes #114

The stderr line an MCP server writes on its way out is the whole answer to "why will this not start" — a missing argument, a token refused on sight. Whether it survived was a race between two fibers over one file descriptor.

The cause is not the one the issue named

The issue supposed the drain fiber might not have been scheduled before failure_message read stderr_tail. That is half of it. The other half is worse, and it is in the stdlib:

# process.cr:644
def wait : Process::Status
  ...
ensure
  close          # <- closes @input, @output AND @error
  @process_info.release
end

StdioTransport spawns a fiber whose only job is @process.wait. That fiber closes the stderr pipe. So reaping the process is itself a way to end the drain — not by reaching the end of the stream, but by taking the descriptor away from it, discarding whatever the process wrote and nothing had read yet.

And close did the same thing from the other side: close_pipe(@process.error) with the drain possibly still parked on data it had not read.

Neither is a wait on anything. The drain fiber only had to have been given a turn first — and usually it was, because wait blocks on a channel before it closes anything, and the drain got that turn as a side effect of the blocking. "Usually" is the whole complaint. It surfaced as spec/mcp/manager_spec.cr:208 failing on macOS CI for PRs that touch nothing nearby (including #123, in this session), green on a re-run of the same commit.

The fix

Reaping waits for the drain. Not a delay: stderr reaches its end when the last write end closes, which is the same event wait is about to report. It costs a hop.

close waits too, capped at 250 ms. With grace: 0 — which smith doctor asks for deliberately — exited? returns without waiting, so close never yields at all, and a fiber that is never scheduled never reads. The cap is for the case where the end never comes.

Nothing deadlocks. A grandchild that inherited stderr and outlived its parent is that case: close closes the descriptor itself once its grace runs out, which ends the drain and releases the reaper.

Specs, and what each one actually pins

Being honest about this, because it matters for reviewing the second half:

1. keeps what a server wrote to stderr when nothing has drained it yet — deterministic, fails without the close half. It builds the losing state instead of racing for it: the child is watched until it has written, which happens before the transport and therefore before the drain fiber exists, so waiting there cannot drain anything. grace: 0 then leaves close with no reason to yield. Verified failing with only that half reverted, both alone and under the full suite.

2. reads a server's stderr before reaping the process that wrote it — pins the invariant, not the race: by the time the transport reports the process gone, its stderr has been read. I could not make the reaping half fail deterministically, and I would rather say so than dress it up — wait's internal channel.receive yields, which hands the drain its turn most of the time. The justification for that half is the stdlib's ensure close plus the observed loss, not this spec. What the spec does is lock the ordering against a future reordering.

The first spec was reworked twice before it was honest. The version that used Process#wait to settle the child was wrong — wait closes the pipes, so the spec was destroying the evidence itself and failing for its own reason under load.

crystal spec: 1427 examples, 0 failures. spec/mcp/ run three times over, stable. crystal tool format --check: clean.

🤖 Generated with Claude Code

[webmatze]

Review durch einen Reviewer-Agenten, zwei Runden. Erste Runde REQUEST CHANGES mit zwei Blockern, zweite APPROVE WITH NITS.

Runde 1: ein Regress, schlimmer als der Bug

Die erste Fassung koppelte das Einsammeln des Prozesses unbegrenzt an den Drain. Das erzeugt einen Kreis: close wartet auf @done, der Reaper auf @drained, und @drained schließt erst, wenn das letzte Schreibende von stderr zugeht — was ein Enkelprozess, der fd 2 geerbt hat, lange offen hält. Ein Wrapper, der etwas in den Hintergrund schickt, docker run, ein Server mit Worker. Gebrochen wurde der Kreis nur dadurch, dass beide Graces ausliefen.

Vor jeder Änderung unabhängig reproduziert — committeter Stand gegen echtes main in einem Worktree:

	close geduldig	close zero	alive? nach Exit
main	0,0 ms	0,0 ms	false
erste Fassung	6263 ms	254,8 ms	true, dauerhaft
jetzt	0,0 ms	0,0 ms	false

Nebenwirkung war, dass @status nie gesetzt wurde: der Kindprozess wurde nie eingesammelt, alive? blieb dauerhaft true.

Die Auflösung: deckeln, nicht streichen

Beide Wartepunkte sind jetzt auf STDERR_GRACE gedeckelt. Der Kreis kann sich nicht mehr bilden — der Reaper gibt am Cap frei, unabhängig davon, was close tut.

Dass die Reaper-Hälfte trotzdem bleibt, ist gemessen und nicht behauptet: mit nur der close-Hälfte fällt Spec 1 rundheraus, mit nur dem gedeckelten Reaper blieb in einem Lastprobe-Lauf Restverlust. Beide sind tragend.

Was der Review korrigiert hat, wo ich falsch lag

• Spec 1 hält beide Hälften fest, nicht nur die close-Hälfte. Das stand falsch im PR-Text. Der Reviewer hat jede Hälfte einzeln zurückgedreht und nachgemessen.
• Spec 2 ist gelöscht. Es war in jeder Konfiguration grün — auf blankem main und sogar bei genau der Umordnung, die sein eigener Kommentar zu verhindern behauptete. Ein Spec, das nicht fallen kann, ist kein Beleg.
• Die Zahlen im CHANGELOG sind raus. „3 von 30, jede Hälfte einzeln notwendig" ließ sich beim Nachmessen nicht reproduzieren: 0/150 für alle Varianten, main eingeschlossen. Die Probe ist last- und temperaturabhängig, n=30 trägt den Satz nicht. Was bleibt, sagt, dass der Verlust auftrat, dass er beidseitig gedeckt ist und dass die Deckung begrenzt ist — das übersteht einen zweiten Lauf.
• Der Preis ist jetzt richtig beziffert: max(0, Cap − Laufzeit des Transports), einmal pro Transport, nebenläufig über Server hinweg — nicht „bis zu 250 ms in close", was sich als pro Aufruf und additiv liest. Meine ursprüngliche Sorge um smith doctor war damit unbegründet: doctor führt einen vollen Handshake durch, bevor es irgendetwas herunterfährt, ist also längst über dem Cap.
• Spec 1 sagt jetzt, was es deckt und was nicht. Die close-Hälfte deterministisch, die Reaper-Hälfte in etwa zwei von drei Läufen — das Deckeln hat sie probabilistisch gemacht. Genau die Unehrlichkeit, an der Spec 2 gestorben ist.

Was der Review gegengeprüft und sauber gefunden hat

Kein Deadlock in irgendeinem konstruierbaren Szenario; das Drain-Fiber schließt @drained auch bei einer Ausnahme, die nicht IO::Error ist (nachgewiesen über Redirect::Inherit); close_pipe weckt ein in gets geparktes Fiber korrekt; manager_spec.cr:165 behält seine volle Marge (0,6 ms gegen 3000 ms); alive? hat außerhalb von protocol.cr null Leser; der gemeldete Flake-Pfad ist end-to-end nachverfolgt und behoben.

crystal spec: 1426 Beispiele, 0 Fehler. spec/mcp/ sechsfach wiederholt stabil. crystal tool format --check: sauber. CI grün auf beiden Plattformen.

Bekannt und nicht behoben

manager.cr:232 — der await_stderr-Aufruf in failure_message — ist von keinem Spec gedeckt. Er existiert, um eine stille Kopplung zu töten (dass connects Rescue den Transport zwei Dateien entfernt bereits geschlossen hat), die heute noch hält. Sein Entfernen würde nichts bemerken.