diff --git a/CHANGELOG.md b/CHANGELOG.md index bfff654..4fa7a8c 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 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). - **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..31486e0 100644 --- a/spec/mcp/protocol_spec.cr +++ b/spec/mcp/protocol_spec.cr @@ -62,3 +62,72 @@ 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. + # + # 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") + process = nil + + 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 + # 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 + 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 8902457..c08bfaa 100644 --- a/src/smith/mcp/protocol.cr +++ b/src/smith/mcp/protocol.cr @@ -172,6 +172,14 @@ 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 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 + # 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 +200,21 @@ module Smith::MCP # Time a terminated server gets to exit before it is killed outright. GRACE = 3.seconds + # 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. + # + # 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) # How long SIGTERM gets before SIGKILL follows. Zero sends both at once, @@ -228,8 +251,29 @@ 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 + # `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 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 + # 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 @@ -242,6 +286,8 @@ module Smith::MCP end rescue IO::Error # The process is gone; nothing left to drain. + ensure + @drained.close end end end @@ -263,6 +309,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 +332,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