From eabb34ebd722598ff06b130e64b44b6f8ffe2177 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Mathias=20Karst=C3=A4dt?= Date: Fri, 11 Sep 2026 00:03:31 +0200 Subject: [PATCH 1/3] fix: a server's last words are read before the process that wrote them is reaped MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The stderr line an MCP server writes on its way out is the whole answer to "why will this not start". Whether it survived was a race between two fibers over one file descriptor, and the losing side was not the one the issue named. `Process#wait` closes all three pipes in its `ensure` (process.cr:652). So the fiber that reaps the process ends the stderr 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. `close` did the same from the other side, closing the read end before the drain had got there. Neither was waiting for 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 that turn fell out of the blocking. "Usually" is the entire complaint: it surfaced as manager_spec.cr:208 failing on macOS CI for pull requests that touch nothing nearby, green on a re-run of the same commit — and it stands for `smith mcp list` printing a bare `Broken pipe` for a server that said exactly why it quit. Reaping now waits for the drain to reach the end of stderr. That is a hop, not a wait: stderr ends when the last write end closes, which is the event `wait` is about to report. `close` waits too, capped at 250ms, because with `grace: 0` — what `smith doctor` asks for, and deliberately — it has nothing to wait for and so never yields at all, and a fiber that is never scheduled never reads. Nothing deadlocks if the end never comes; 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. Two specs. The first builds the losing state rather than racing for it — the child is watched until it has written, before the transport and therefore the drain fiber exist, so waiting there cannot drain anything — and fails without the `close` half. The second pins the invariant that makes the question go away: by the time the transport reports the process gone, its stderr has been read. Closes #114 Co-Authored-By: Claude Opus 5 --- CHANGELOG.md | 2 + spec/mcp/protocol_spec.cr | 85 +++++++++++++++++++++++++++++++++++++++ src/smith/mcp/protocol.cr | 60 +++++++++++++++++++++++++++ 3 files changed, 147 insertions(+) diff --git a/CHANGELOG.md b/CHANGELOG.md index bfff654..1b9bc34 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -15,6 +15,8 @@ All notable changes to smith. The format follows [Keep a Changelog](https://keep ### Fixed +- **A server that explains itself and exits is no longer quoted as having said nothing**: the line an MCP server writes to stderr on its way out is the whole answer to "why will this not start" — a missing argument, a token refused on sight — and whether it survived was a race between two fibers holding the same file descriptor. `Process#wait` closes all three pipes in its `ensure`, so the fiber that reaps the process ends the stderr drain not by reaching the end of the stream but by pulling the descriptor out from under it, discarding whatever the process wrote and nothing had read yet; and `close` did the same again from the other side, closing the read end before the drain had got there. Neither was waiting for anything — the drain fiber simply had to have been given a turn first, and sometimes it was not. It showed up as `spec/mcp/manager_spec.cr:208` failing on macOS CI for pull requests that touch nothing nearby, `TOKEN-from-the-child` missing from a line that read `could not write to the MCP server: … Broken pipe`, green on a re-run of the same commit — and the loss it stands for is `smith mcp list` printing a bare `Broken pipe` for a server that said exactly why it quit. Reaping now waits for the drain to reach the end of stderr, which costs a hop and not a wait: stderr ends when the last write end closes, which is the event `wait` is about to report anyway. `close` waits too, capped, because with `grace: 0` — which is what `smith doctor` asks for, deliberately — it has nothing to wait for and so never yields at all, and a fiber that is never scheduled never reads. Nothing deadlocks if the end never comes, a grandchild that inherited stderr and outlived its parent being the case: `close` closes the descriptor itself once its grace runs out, which ends the drain and releases the reaper (#114). + - **The url from `mcp.json` no longer reaches the model's context through a failed tool call**: `HttpTransport#die!` composed its reason around the url whole — `"could not reach the MCP server at #{@url}: …"`, userinfo, path, query and fragment and all — and kept it as `failure_hint`. That value has two readers, and both put it somewhere it must not be: `send` raises it at the next write, and `Client#abandon_pending` hands it to every caller still waiting as an `RpcError` whose `safe_message` was *the same string*, from where `McpTool` prints it into the tool result. So a server that failed a call while it was running wrote `http://user:pass@host/v1/TOKEN/mcp?token=…` into the model's context, into `transcript.jsonl` and into every `smith sessions export` of that session — where #110 was a line a human reads once and throws away, this one outlives the run that made it and travels with anything handed on. The url is cut back where the message is *composed* rather than at either place it is read: `die!` runs it through `scrub_urls` on the way in, so nothing raw is left in the ivar and a reader added later cannot become a new way out. That `safe_message` did not already cover it is the point — it answers "are these a server's words?", `scrub_urls` answers "is this out of the configuration file?", and a message smith composed itself passes the first question while failing the second. Everything the line is read for survives: the reason word for word (`answered HTTP 500`, `could not reach`, a timeout), scheme, host and port, and the server's name, which `McpTool` already prints beside it. The server's own body still travels apart as `failure_body` and still reaches no tool result (#112). - **Compaction no longer summarizes its own summary while the turn that is actually growing sits untouched**: the recency window counts *turns*, and a long agentic run — one prompt, then a hundred tool calls — is a single turn, so the window that exists to protect the last three turns covered the entire history instead. All four cheap stages became no-ops (`window_start` returns 0 once there are no more real turns than the window is wide, and every stage breaks on the first message), `safe_cut_index` found no boundary whose tail fit and fell back to the newest one, and the prefix left to summarize was — from the second compaction onward — the summary the first one had written, and nothing else. The reported result was `~105421 → ~105341 tokens, 0% of the budget reclaimed · summarize`, every turn, each one paying for a provider call and a full prompt-cache invalidation to swap one summary for another while the 76k of tool results behind the cut were never a candidate. The escape hatch that ignores the recency window already existed but was wired to `cut.zero?` — the one shape this case never takes. It now runs whenever the tail that would survive the cut is itself over target, which is the same dead end reached by a different road: `cut.zero?` is the case where there is no boundary, this is the case where no boundary helps. Afterwards the boundary is re-chosen against the shortened history, and a history that now fits is returned as it is rather than summarized for nothing. Two guards stand behind that: a prefix that is only a previous summary is refused before the call is made, recognised by the `SUMMARY_PREFIX` the writer and the reader now share rather than by a flag, which a resumed session's JSON round trip would not carry; and a summary that comes back longer than the turns it replaced is discarded, because paying for the call, losing the detail and growing the request is the one outcome with nothing to recommend it. On the reproduction — a short turn, then thirty 8 KB tool results — the same history now goes `60212 → 34249`, 74% of the budget reclaimed, target reached, and no provider call at all (#118). diff --git a/spec/mcp/protocol_spec.cr b/spec/mcp/protocol_spec.cr index 0c4884a..29e6b3d 100644 --- a/spec/mcp/protocol_spec.cr +++ b/spec/mcp/protocol_spec.cr @@ -62,3 +62,88 @@ describe Smith::MCP::Message do Smith::MCP::Message.parse("[1,2,3]").should be_nil end end + +describe Smith::MCP::StdioTransport do + # A server's complaint on stderr is the whole answer to "why will this not + # start", and closing the transport is what lost it: the bytes sit in the + # pipe until the drain fiber reads them, and closing the read end throws + # away whatever is still there. Whether anything survived came down to + # whether that fiber had been given a turn since the bytes arrived, which is + # why the loss showed up as an occasional red CI job rather than as a + # missing feature. + # + # Racing for that state would be the same coin toss, so it is built instead. + # The child is watched to the point where it has written — before the + # transport, and therefore before the drain fiber, exists at all, which is + # what makes waiting here safe: there is nothing yet that could drain it. + # `grace: 0` then leaves `close` with nothing to wait for and so no reason to + # yield, which is what `smith doctor` asks for; any yield in there would hand + # the fiber a turn by accident and the spec would pass for a reason that has + # nothing to do with the fix. + it "keeps what a server wrote to stderr when nothing has drained it yet" do + script = File.tempname("smith-mcp-lastwords", ".sh") + written = File.tempname("smith-mcp-lastwords", ".written") + + begin + File.write(script, <<-SH) + #!/bin/sh + echo 'TOKEN-from-the-child' >&2 + touch "#{written}" + exit 1 + SH + File.chmod(script, 0o755) + + process = Process.new( + script, + shell: false, + input: Process::Redirect::Pipe, + output: Process::Redirect::Pipe, + error: Process::Redirect::Pipe + ) + + 100.times do + break if File.exists?(written) + sleep 10.milliseconds + end + File.exists?(written).should be_true + + transport = Smith::MCP::StdioTransport.new(process, grace: Time::Span.zero) + transport.close + + transport.stderr_tail.join(" ").should contain("TOKEN-from-the-child") + ensure + File.delete(script) if File.exists?(script) + File.delete(written) if File.exists?(written) + end + end + + # The other half of the same descriptor race, and the half no spec can force: + # `Process#wait` closes all three pipes in its `ensure`, so reaping is itself + # a way to end the drain early. It usually does not, because `wait` blocks on + # a channel first and the drain fiber gets that turn — "usually" being the + # whole complaint. + # + # What can be pinned is the invariant that makes the question go away: by the + # time the transport reports the process gone, its stderr has been read. A + # reordering that reaps first would leave this empty. + it "reads a server's stderr before reaping the process that wrote it" do + script = File.tempname("smith-mcp-reap", ".sh") + + begin + File.write(script, "#!/bin/sh\necho 'TOKEN-from-the-child' >&2\nexit 1\n") + File.chmod(script, 0o755) + + transport = Smith::MCP::StdioTransport.spawn_server(script) + + 100.times do + break unless transport.alive? + sleep 10.milliseconds + end + transport.alive?.should be_false + + transport.stderr_tail.join(" ").should contain("TOKEN-from-the-child") + ensure + File.delete(script) if File.exists?(script) + end + end +end diff --git a/src/smith/mcp/protocol.cr b/src/smith/mcp/protocol.cr index 8902457..78ad6a5 100644 --- a/src/smith/mcp/protocol.cr +++ b/src/smith/mcp/protocol.cr @@ -172,6 +172,13 @@ module Smith::MCP nil end + # Wait, briefly, for whatever the server wrote to stderr to have been read. + # Only stdio has a stderr to drain, and only a transport knows when its + # own draining is finished — so the caller that is about to quote + # `stderr_tail` asks here rather than guessing with a sleep. + def await_stderr : Nil + end + # A subprocess's own stderr, kept so a failed handshake can say what the # process actually complained about. Only stdio has one. def stderr_tail : Array(String) @@ -192,6 +199,15 @@ module Smith::MCP # Time a terminated server gets to exit before it is killed outright. GRACE = 3.seconds + # How long `close` waits for the stderr drain to reach the end of the pipe + # before closing it anyway. It is reached, not waited out: by this point + # the process has been signalled and what it wrote is already sitting in + # the pipe buffer, so the fiber needs one turn to read it and see EOF. The + # cap is for the case where it will not come at all — a process that + # survived SIGKILL long enough to hold the write end open — because losing + # a server's last words is better than never shutting down. + STDERR_GRACE = 250.milliseconds + getter stderr_tail : Array(String) # How long SIGTERM gets before SIGKILL follows. Zero sends both at once, @@ -228,8 +244,30 @@ module Smith::MCP def initialize(@process : Process, @grace : Time::Span = GRACE) @stderr_tail = Array(String).new @done = Channel(Nil).new(1) + # Closed rather than sent to: the end of the drain is a fact, not a + # message, and every later reader has to be able to observe it. A send + # would be taken by whoever asked first and leave the next caller + # waiting out the cap for something that already happened. + @drained = Channel(Nil).new spawn do + # Draining comes first, and this is why: `Process#wait` closes all + # three pipes on its way out (`ensure close`), so calling it is what + # ends the drain — not by reaching the end of stderr but by pulling + # the file descriptor out from under it, discarding whatever the + # process wrote and had not been read yet. Two fibers were racing for + # the same descriptor, and the winner decided whether a server that + # explains itself and exits is quoted or misquoted as silent. + # + # Waiting here is not a delay: stderr reaches its end when the last + # write end closes, which is when the process exits — the same event + # `wait` is about to report. It costs a hop, not a wait. + # + # Nothing deadlocks if the end never comes — a grandchild that + # inherited stderr and outlives its parent is the case — because + # `close` closes the descriptor itself once its grace runs out, which + # ends the drain and releases this fiber to reap. + @drained.receive? @status = @process.wait @done.send(nil) end @@ -242,6 +280,8 @@ module Smith::MCP end rescue IO::Error # The process is gone; nothing left to drain. + ensure + @drained.close end end end @@ -263,6 +303,15 @@ module Smith::MCP nil end + # The drain fiber is done, or the cap ran out. A closed channel answers + # every caller and answers again, so asking twice costs nothing. + def await_stderr : Nil + select + when @drained.receive? + when timeout(STDERR_GRACE) + end + end + # SIGTERM, then SIGKILL. Both are needed: a server that ignores TERM would # otherwise be left behind as an orphan holding whatever it opened. def close : Nil @@ -277,6 +326,17 @@ module Smith::MCP exited?(@grace) end + # Before the read end goes, not after: what the process wrote is in the + # pipe buffer, and closing this side discards whatever has not been read + # yet. A server that fails by writing to stderr and exiting at once — + # the commonest way a misconfigured one fails — writes its explanation + # into that buffer and dies before smith's first write returns, so the + # drain fiber may not have been scheduled even once. Closing here first + # is what threw the explanation away, and only sometimes: whether the + # fiber got a turn depended on whether the write blocked, which is why + # it read as a flake rather than as the loss it is. + await_stderr + close_pipe(@process.output) close_pipe(@process.error) end From 39f34b5683355f2234f8d5e267f52340bec45c23 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Mathias=20Karst=C3=A4dt?= Date: Fri, 11 Sep 2026 00:26:18 +0200 Subject: [PATCH 2/3] fix: bound both waits, and stop reaping from waiting on what shutdown unblocks MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Review measured a regression worse than the bug: gating the reaper on the drain without a bound cost 6.3 seconds per server at shutdown, and left `alive?` true forever. The circle: `close` waits on `@done`, the reaper waits on `@drained`, and `@drained` closes when the *last* write end of stderr closes — which a grandchild that inherited fd 2 holds open long after its parent is gone. A wrapper that backgrounds something, `docker run`, a server with a worker. The only thing that broke it was `close_pipe`, which runs after both graces have timed out. Reproduced at 6263ms, and `alive?` never flipped, so the child was never reaped either. Both waits are capped now. Bounded, the reaper's wait ends in a scheduler turn wherever the drain can finish and gives up where it never will, so the window it closes costs 250ms in the pathological case instead of 6.3s. Measured on the same lingering-helper server: 6263ms to 50ms, `alive?` false again. Both halves stay, because both are load-bearing. Measured on a server with four hundred lines to say and no grace to say them in — runs losing its last line, out of 30: main 3 capped reaper only 1 close half only (spec fails) both 0 `failure_message` now asks the transport for the drain itself, rather than relying on `connect`'s rescue having closed the transport two files away. Below the `with_server_output` guard, so the summary form — the only one `smith doctor` reads — does not pay for a wait whose result it discards. The second spec is gone. Review showed it green in every configuration, including plain `main` and with the exact reordering its comment claimed would break it; a spec that cannot fail is not evidence. The first spec is kept and its claim corrected: it pins *both* halves, not the close half alone, verified by reverting each in turn. It also kills its child on the way out now, which it did not do if the assertion failed first. The `STDERR_GRACE` doc no longer blames a process for surviving SIGKILL. Nothing does; the cause is a second process holding the same write end. Co-Authored-By: Claude Opus 5 --- CHANGELOG.md | 2 +- spec/mcp/protocol_spec.cr | 37 ++++++--------------------- src/smith/mcp/manager.cr | 15 +++++++++++ src/smith/mcp/protocol.cr | 53 ++++++++++++++++++++------------------- 4 files changed, 50 insertions(+), 57 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 1b9bc34..bf01974 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -15,7 +15,7 @@ All notable changes to smith. The format follows [Keep a Changelog](https://keep ### Fixed -- **A server that explains itself and exits is no longer quoted as having said nothing**: the line an MCP server writes to stderr on its way out is the whole answer to "why will this not start" — a missing argument, a token refused on sight — and whether it survived was a race between two fibers holding the same file descriptor. `Process#wait` closes all three pipes in its `ensure`, so the fiber that reaps the process ends the stderr drain not by reaching the end of the stream but by pulling the descriptor out from under it, discarding whatever the process wrote and nothing had read yet; and `close` did the same again from the other side, closing the read end before the drain had got there. Neither was waiting for anything — the drain fiber simply had to have been given a turn first, and sometimes it was not. It showed up as `spec/mcp/manager_spec.cr:208` failing on macOS CI for pull requests that touch nothing nearby, `TOKEN-from-the-child` missing from a line that read `could not write to the MCP server: … Broken pipe`, green on a re-run of the same commit — and the loss it stands for is `smith mcp list` printing a bare `Broken pipe` for a server that said exactly why it quit. Reaping now waits for the drain to reach the end of stderr, which costs a hop and not a wait: stderr ends when the last write end closes, which is the event `wait` is about to report anyway. `close` waits too, capped, because with `grace: 0` — which is what `smith doctor` asks for, deliberately — it has nothing to wait for and so never yields at all, and a fiber that is never scheduled never reads. Nothing deadlocks if the end never comes, a grandchild that inherited stderr and outlived its parent being the case: `close` closes the descriptor itself once its grace runs out, which ends the drain and releases the reaper (#114). +- **A server that explains itself and exits is no longer quoted as having said nothing**: the line an MCP server writes to stderr on its way out is the whole answer to "why will this not start" — a missing argument, a token refused on sight — and whether it survived was a race between two fibers over one file descriptor. `Process#wait` closes all three pipes in its `ensure`, so the fiber that reaps the process ends the stderr 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; `close` did the same from the other side, closing the read end before the drain had got there. Neither was waiting for 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 that turn fell out of the blocking. "Usually" is the whole complaint: it showed as `spec/mcp/manager_spec.cr:208` failing on macOS CI for pull requests that touch nothing nearby, `TOKEN-from-the-child` missing from a line reading `could not write to the MCP server: … Broken pipe`, green on a re-run of the same commit — and what it stands for is `smith mcp list` printing a bare `Broken pipe` for a server that said exactly why it quit. Both sides now yield to the drain first, and both are capped, which is the part that took a second attempt: an *unbounded* wait before reaping turned out to cost 6.3 seconds per server at shutdown, because stderr ends when the **last** write end closes and a grandchild that inherited fd 2 — a wrapper that backgrounds something, a server with a worker — holds it open long after its parent is gone, so reaping waited for a shutdown that was waiting for the reaping and only both graces timing out broke the circle. Bounded at 250 ms, the same wait ends in a scheduler turn wherever the drain can finish, and gives up where it never will. Measured against a server with four hundred lines to say and no grace to say them in: 3 runs in 30 lost its last line before, 0 in 30 after, with each half of the change independently necessary to get there. The price is bounded and named: a server that leaves a helper holding stderr open costs up to 250 ms in `close`, which `smith doctor` pays without printing a byte of stderr — it reads only the summary form, which never quoted it (#114). - **The url from `mcp.json` no longer reaches the model's context through a failed tool call**: `HttpTransport#die!` composed its reason around the url whole — `"could not reach the MCP server at #{@url}: …"`, userinfo, path, query and fragment and all — and kept it as `failure_hint`. That value has two readers, and both put it somewhere it must not be: `send` raises it at the next write, and `Client#abandon_pending` hands it to every caller still waiting as an `RpcError` whose `safe_message` was *the same string*, from where `McpTool` prints it into the tool result. So a server that failed a call while it was running wrote `http://user:pass@host/v1/TOKEN/mcp?token=…` into the model's context, into `transcript.jsonl` and into every `smith sessions export` of that session — where #110 was a line a human reads once and throws away, this one outlives the run that made it and travels with anything handed on. The url is cut back where the message is *composed* rather than at either place it is read: `die!` runs it through `scrub_urls` on the way in, so nothing raw is left in the ivar and a reader added later cannot become a new way out. That `safe_message` did not already cover it is the point — it answers "are these a server's words?", `scrub_urls` answers "is this out of the configuration file?", and a message smith composed itself passes the first question while failing the second. Everything the line is read for survives: the reason word for word (`answered HTTP 500`, `could not reach`, a timeout), scheme, host and port, and the server's name, which `McpTool` already prints beside it. The server's own body still travels apart as `failure_body` and still reaches no tool result (#112). diff --git a/spec/mcp/protocol_spec.cr b/spec/mcp/protocol_spec.cr index 29e6b3d..975ba4d 100644 --- a/spec/mcp/protocol_spec.cr +++ b/spec/mcp/protocol_spec.cr @@ -83,6 +83,7 @@ describe Smith::MCP::StdioTransport do it "keeps what a server wrote to stderr when nothing has drained it yet" do script = File.tempname("smith-mcp-lastwords", ".sh") written = File.tempname("smith-mcp-lastwords", ".written") + process = nil begin File.write(script, <<-SH) @@ -112,38 +113,14 @@ describe Smith::MCP::StdioTransport do transport.stderr_tail.join(" ").should contain("TOKEN-from-the-child") ensure - File.delete(script) if File.exists?(script) - File.delete(written) if File.exists?(written) - end - end - - # The other half of the same descriptor race, and the half no spec can force: - # `Process#wait` closes all three pipes in its `ensure`, so reaping is itself - # a way to end the drain early. It usually does not, because `wait` blocks on - # a channel first and the drain fiber gets that turn — "usually" being the - # whole complaint. - # - # What can be pinned is the invariant that makes the question go away: by the - # time the transport reports the process gone, its stderr has been read. A - # reordering that reaps first would leave this empty. - it "reads a server's stderr before reaping the process that wrote it" do - script = File.tempname("smith-mcp-reap", ".sh") - - begin - File.write(script, "#!/bin/sh\necho 'TOKEN-from-the-child' >&2\nexit 1\n") - File.chmod(script, 0o755) - - transport = Smith::MCP::StdioTransport.spawn_server(script) - - 100.times do - break unless transport.alive? - sleep 10.milliseconds + # The assertion above can fail before `close` has run, and a child that + # nothing signals outlives the spec run. + process.try do |running| + running.terminate rescue nil + running.wait rescue nil end - transport.alive?.should be_false - - transport.stderr_tail.join(" ").should contain("TOKEN-from-the-child") - ensure File.delete(script) if File.exists?(script) + File.delete(written) if File.exists?(written) end end end diff --git a/src/smith/mcp/manager.cr b/src/smith/mcp/manager.cr index d78dc8b..5244c33 100644 --- a/src/smith/mcp/manager.cr +++ b/src/smith/mcp/manager.cr @@ -216,6 +216,21 @@ module Smith::MCP parts = [base] + # Asked for here rather than assumed: the tail is filled by a fiber of + # the transport's own, and this is the line that quotes it. It is + # normally already complete, because the route to this point runs + # through `connect`'s rescue, which closes the transport — and closing + # is what waits. Relying on that would make an ordering two files apart + # load-bearing and silent; asking costs nothing when the answer is + # already in, and is the difference between a server quoted and a server + # misquoted as silent when it is not. + # + # Below the `with_server_output` guard on purpose: the summary form does + # not quote stderr, so `smith doctor` — which reads only that form, and + # builds its servers with no grace precisely because it cannot wait — + # does not pay for a wait whose result it would discard. + @transport.try(&.await_stderr) + tail = stderr_tail.last(3).map(&.strip).reject(&.empty?) parts << "(stderr: #{tail.join(" / ")})" unless tail.empty? diff --git a/src/smith/mcp/protocol.cr b/src/smith/mcp/protocol.cr index 78ad6a5..fc51877 100644 --- a/src/smith/mcp/protocol.cr +++ b/src/smith/mcp/protocol.cr @@ -173,9 +173,10 @@ module Smith::MCP end # Wait, briefly, for whatever the server wrote to stderr to have been read. - # Only stdio has a stderr to drain, and only a transport knows when its - # own draining is finished — so the caller that is about to quote - # `stderr_tail` asks here rather than guessing with a sleep. + # Only stdio has a stderr to drain, and only a transport knows when its own + # draining has finished — so `ServerHandle#failure_message`, which is about + # to quote `stderr_tail`, asks here rather than guessing with a sleep. An + # HTTP transport has nothing to drain and answers at once. def await_stderr : Nil end @@ -200,12 +201,16 @@ module Smith::MCP GRACE = 3.seconds # How long `close` waits for the stderr drain to reach the end of the pipe - # before closing it anyway. It is reached, not waited out: by this point - # the process has been signalled and what it wrote is already sitting in - # the pipe buffer, so the fiber needs one turn to read it and see EOF. The - # cap is for the case where it will not come at all — a process that - # survived SIGKILL long enough to hold the write end open — because losing - # a server's last words is better than never shutting down. + # before closing it anyway. Normally it is reached rather than waited out: + # what the process wrote is already in the pipe buffer, and the fiber needs + # a turn to read it and see EOF. + # + # The cap is for the case where the end does not come, which is not a + # process outliving SIGKILL — nothing does — but a *second* process holding + # the same write end: a grandchild that inherited fd 2 from a wrapper keeps + # stderr open long after the server is gone. Waiting for that would be + # waiting for something unrelated to finish, so it is bounded, and losing a + # server's last words is the better end of that trade. STDERR_GRACE = 250.milliseconds getter stderr_tail : Array(String) @@ -251,23 +256,19 @@ module Smith::MCP @drained = Channel(Nil).new spawn do - # Draining comes first, and this is why: `Process#wait` closes all - # three pipes on its way out (`ensure close`), so calling it is what - # ends the drain — not by reaching the end of stderr but by pulling - # the file descriptor out from under it, discarding whatever the - # process wrote and had not been read yet. Two fibers were racing for - # the same descriptor, and the winner decided whether a server that - # explains itself and exits is quoted or misquoted as silent. - # - # Waiting here is not a delay: stderr reaches its end when the last - # write end closes, which is when the process exits — the same event - # `wait` is about to report. It costs a hop, not a wait. - # - # Nothing deadlocks if the end never comes — a grandchild that - # inherited stderr and outlives its parent is the case — because - # `close` closes the descriptor itself once its grace runs out, which - # ends the drain and releases this fiber to reap. - @drained.receive? + # `Process#wait` closes all three pipes on its way out (`ensure + # close`), so reaping is itself a way to end the drain early — not by + # reaching the end of stderr but by taking the descriptor away from it. + # Yielding to the drain first closes that window. Capped, and the cap + # is the whole design: stderr ends when the *last* write end closes, + # and a grandchild that inherited fd 2 — a wrapper that backgrounds + # something, a server with a worker — holds it open long after its + # parent is gone. Waiting without a bound made reaping wait for a + # shutdown that was waiting for the reaping, and only both graces + # timing out broke the circle: 6.3 seconds per server, measured. + # Bounded, the same wait costs a scheduler turn where the drain can + # finish and 250 ms where it never will. + await_stderr @status = @process.wait @done.send(nil) end From 823b779faa3dc044cc0ad7703623a24310ec8a1a Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Mathias=20Karst=C3=A4dt?= Date: Fri, 11 Sep 2026 00:40:32 +0200 Subject: [PATCH 3/3] docs: say what the spec guards and drop a measurement that will not reproduce MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Review, second round. All four are claims that were stronger than the evidence. The CHANGELOG quoted "3 runs in 30" and "each half independently necessary". Re-measured on the same machine, the same probe gave 0/150 for every variant, `main` included — it is load- and thermal-sensitive, and n=30 does not support the sentence. The counts are gone. What is left says the loss happened, that it is covered from both sides, and that the covering is bounded, which is what survives a re-run. The price is stated as what it is: `max(0, cap − uptime)`, once per transport, concurrent across servers rather than additive — not "up to 250ms in close", which reads as per-close and per-server. Doctor performs a full handshake before shutting anything down, so it is past the cap by then. Spec 1 now says what it guards and what it does not: removing the wait in `close` makes it red every time, removing the reaper's makes it red about two runs in three. Bounding that wait is what made it probabilistic. A spec whose comment implies more coverage than it has is how the deleted spec 2 got written. `STDERR_GRACE` has three waiters now, not one, and says so. The reaper's comment no longer claims to close the window outright — it closes it for the length of the cap, which is where a write-and-exit server lives, and `close` covers it from there. Co-Authored-By: Claude Opus 5 --- CHANGELOG.md | 2 +- spec/mcp/protocol_spec.cr | 7 +++++++ src/smith/mcp/protocol.cr | 13 +++++++++---- 3 files changed, 17 insertions(+), 5 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index bf01974..4fa7a8c 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -15,7 +15,7 @@ All notable changes to smith. The format follows [Keep a Changelog](https://keep ### Fixed -- **A server that explains itself and exits is no longer quoted as having said nothing**: the line an MCP server writes to stderr on its way out is the whole answer to "why will this not start" — a missing argument, a token refused on sight — and whether it survived was a race between two fibers over one file descriptor. `Process#wait` closes all three pipes in its `ensure`, so the fiber that reaps the process ends the stderr 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; `close` did the same from the other side, closing the read end before the drain had got there. Neither was waiting for 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 that turn fell out of the blocking. "Usually" is the whole complaint: it showed as `spec/mcp/manager_spec.cr:208` failing on macOS CI for pull requests that touch nothing nearby, `TOKEN-from-the-child` missing from a line reading `could not write to the MCP server: … Broken pipe`, green on a re-run of the same commit — and what it stands for is `smith mcp list` printing a bare `Broken pipe` for a server that said exactly why it quit. Both sides now yield to the drain first, and both are capped, which is the part that took a second attempt: an *unbounded* wait before reaping turned out to cost 6.3 seconds per server at shutdown, because stderr ends when the **last** write end closes and a grandchild that inherited fd 2 — a wrapper that backgrounds something, a server with a worker — holds it open long after its parent is gone, so reaping waited for a shutdown that was waiting for the reaping and only both graces timing out broke the circle. Bounded at 250 ms, the same wait ends in a scheduler turn wherever the drain can finish, and gives up where it never will. Measured against a server with four hundred lines to say and no grace to say them in: 3 runs in 30 lost its last line before, 0 in 30 after, with each half of the change independently necessary to get there. The price is bounded and named: a server that leaves a helper holding stderr open costs up to 250 ms in `close`, which `smith doctor` pays without printing a byte of stderr — it reads only the summary form, which never quoted it (#114). +- **A server that explains itself and exits is no longer quoted as having said nothing**: the line an MCP server writes to stderr on its way out is the whole answer to "why will this not start" — a missing argument, a token refused on sight — and whether it survived was a race between two fibers over one file descriptor. `Process#wait` closes all three pipes in its `ensure`, so the fiber that reaps the process ends the stderr 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; `close` did the same from the other side, closing the read end before the drain had got there. Neither was waiting for 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 that turn fell out of the blocking. "Usually" is the whole complaint: it showed as `spec/mcp/manager_spec.cr:208` failing on macOS CI for pull requests that touch nothing nearby, `TOKEN-from-the-child` missing from a line reading `could not write to the MCP server: … Broken pipe`, green on a re-run of the same commit — and what it stands for is `smith mcp list` printing a bare `Broken pipe` for a server that said exactly why it quit. Both sides now yield to the drain first, and both are capped, which is the part that took a second attempt: an *unbounded* wait before reaping turned out to cost 6.3 seconds per server at shutdown, because stderr ends when the **last** write end closes and a grandchild that inherited fd 2 — a wrapper that backgrounds something, a server with a worker — holds it open long after its parent is gone, so reaping waited for a shutdown that was waiting for the reaping and only both graces timing out broke the circle. Bounded at 250 ms, the same wait ends in a scheduler turn wherever the drain can finish, and gives up where it never will. The price is bounded and named: a server that both answers in under a quarter of a second *and* leaves a helper holding stderr open pays the remainder of the cap once, at `max(0, 250 ms − however long the transport has been up)` — not per shutdown, and concurrently rather than one after another where several servers are involved, so `smith doctor`, which performs a full handshake before it shuts anything down, is past the cap before it gets there. How often the loss actually struck is not quoted here on purpose: it is a scheduling race, the probe that reproduces it does so only on a loaded machine, and the honest summary is that it happened, that it is now covered from both sides, and that the covering is bounded (#114). - **The url from `mcp.json` no longer reaches the model's context through a failed tool call**: `HttpTransport#die!` composed its reason around the url whole — `"could not reach the MCP server at #{@url}: …"`, userinfo, path, query and fragment and all — and kept it as `failure_hint`. That value has two readers, and both put it somewhere it must not be: `send` raises it at the next write, and `Client#abandon_pending` hands it to every caller still waiting as an `RpcError` whose `safe_message` was *the same string*, from where `McpTool` prints it into the tool result. So a server that failed a call while it was running wrote `http://user:pass@host/v1/TOKEN/mcp?token=…` into the model's context, into `transcript.jsonl` and into every `smith sessions export` of that session — where #110 was a line a human reads once and throws away, this one outlives the run that made it and travels with anything handed on. The url is cut back where the message is *composed* rather than at either place it is read: `die!` runs it through `scrub_urls` on the way in, so nothing raw is left in the ivar and a reader added later cannot become a new way out. That `safe_message` did not already cover it is the point — it answers "are these a server's words?", `scrub_urls` answers "is this out of the configuration file?", and a message smith composed itself passes the first question while failing the second. Everything the line is read for survives: the reason word for word (`answered HTTP 500`, `could not reach`, a timeout), scheme, host and port, and the server's name, which `McpTool` already prints beside it. The server's own body still travels apart as `failure_body` and still reaches no tool result (#112). diff --git a/spec/mcp/protocol_spec.cr b/spec/mcp/protocol_spec.cr index 975ba4d..31486e0 100644 --- a/spec/mcp/protocol_spec.cr +++ b/spec/mcp/protocol_spec.cr @@ -80,6 +80,13 @@ describe Smith::MCP::StdioTransport do # yield, which is what `smith doctor` asks for; any yield in there would hand # the fiber a turn by accident and the spec would pass for a reason that has # nothing to do with the fix. + # + # What it guards, precisely, because the two halves are not guarded equally: + # removing the wait in `close` makes this red every time. Removing the one in + # the reaper makes it red about two runs in three — bounding that wait is + # what made it probabilistic, and there is no honest way to write "two in + # three" as an assertion. So the reaper's half rests on the measurement in + # the commit that introduced it, and on this spec only as far as it goes. it "keeps what a server wrote to stderr when nothing has drained it yet" do script = File.tempname("smith-mcp-lastwords", ".sh") written = File.tempname("smith-mcp-lastwords", ".written") diff --git a/src/smith/mcp/protocol.cr b/src/smith/mcp/protocol.cr index fc51877..c08bfaa 100644 --- a/src/smith/mcp/protocol.cr +++ b/src/smith/mcp/protocol.cr @@ -200,8 +200,10 @@ module Smith::MCP # Time a terminated server gets to exit before it is killed outright. GRACE = 3.seconds - # How long `close` waits for the stderr drain to reach the end of the pipe - # before closing it anyway. Normally it is reached rather than waited out: + # How long anyone waits for the stderr drain to reach the end of the pipe + # before giving up on it — the reaper before it calls `wait`, `close` + # before it closes the descriptor, and `ServerHandle#failure_message` + # before it quotes the tail. Normally it is reached rather than waited out: # what the process wrote is already in the pipe buffer, and the fiber needs # a turn to read it and see EOF. # @@ -259,8 +261,11 @@ module Smith::MCP # `Process#wait` closes all three pipes on its way out (`ensure # close`), so reaping is itself a way to end the drain early — not by # reaching the end of stderr but by taking the descriptor away from it. - # Yielding to the drain first closes that window. Capped, and the cap - # is the whole design: stderr ends when the *last* write end closes, + # Yielding to the drain first closes that window for as long as the cap + # below lasts, which is where a server that writes and exits lives — + # afterwards this fiber sits in `wait` and the old race is back, and + # `close` is what covers it from there. Capped, and the cap is the + # whole design: stderr ends when the *last* write end closes, # and a grandchild that inherited fd 2 — a wrapper that backgrounds # something, a server with a worker — holds it open long after its # parent is gone. Waiting without a bound made reaping wait for a