coilyco-gaming/sirens-echo

Watch

A truncated tool result cannot reach the trace, because the tool span is closed before the bound is applied #640

New issue

Closed

opened 2026-08-13 17:41:47 +00:00 by coilyco-ops · 1 comment

coilyco-ops commented

2026-08-13 17:41:47 +00:00

Member

Filed by Angie (ENG, claude seat) as the engineer-owned slice of #635. Claiming, 17:42Z, for 20 minutes.

635 leaves this to Engineer explicitly, independent of the sizing decision Kai owns:

When a bound truncates, the turn records which bound and how much was dropped, so spill_path is a diagnosis rather than a file nobody reads.

There is a structural reason it is not one today, and it is not the missing fields.

The span is already closed

proxy.go, in order:

toolSpan.SetAttributes(
	attribute.String("mcp.tool.outcome", string(outcomeOf(result))),
	attribute.Int("mcp.tool.result_bytes", len(result.Text)),
)
toolSpan.End()                                              // <- closed here
...
reinjected, trimmed := boundToolResult(result.Text, budget.ToolResultBytes)
if trimmed {                                                // <- truncation is decided here
	spilled := spillToolResult(...)
	telemetry.Info(toolCtx, "mcp.tool.result.bounded", ...)
}

The bound is applied after the span ends, so no attribute can carry it. Truncation exists only as a log line, and a log line cannot be joined to the trace a reader is holding. That is the same gap #570 closed for tool outcomes, still open for tool truncation.

The practical cost showed up on 635 itself: establishing that 87% of a Steam library was dropped required reading logs and then reading two YAML files to learn what the cap was. None of it was answerable from the trace.

The record is also incomplete

mcp.tool.result.bounded  result_bytes=131072  reinjected_bytes=16573  spill_path=...

Two things a reader has to derive by hand:

which bound applied. reinjected_bytes is not the cap. It is the cap plus the truncation and spill notices, which is why 635 measured 16,568 to 16,582 against a 16,384 limit and reasonably concluded the value had moved. It had not.
how much was dropped. Derivable, but the subtraction is against the wrong number for the reason above, so it is derived wrongly.

What I am building

boundToolResult runs before toolSpan.End(), so the span carries mcp.tool.limit_bytes and mcp.tool.truncated.
The spill stays after End(). It writes a file, and folding that into the span would inflate every truncated tool call's measured latency by a disk write. The span should say what the bound did, not how long spilling took.
limit_bytes and dropped_bytes on the mcp.tool.result.bounded record, so it is readable without arithmetic against a definition file.

Not in scope

The per-tool bound, the sizing, and whether 16 KiB is right. All of that is 635 and #362. This changes no bound and no behaviour a member can see. It makes the existing bound legible, which is worth doing whichever way the numbers go.

**Filed by Angie (ENG, `claude` seat)** as the engineer-owned slice of https://forgejo.coilysiren.me/coilyco-gaming/sirens-echo/issues/635. **Claiming**, 17:42Z, for 20 minutes. 635 leaves this to Engineer explicitly, independent of the sizing decision Kai owns: > When a bound truncates, the turn records which bound and how much was dropped, so `spill_path` is a diagnosis rather than a file nobody reads. There is a structural reason it is not one today, and it is not the missing fields. ## The span is already closed `proxy.go`, in order: ```go toolSpan.SetAttributes( attribute.String("mcp.tool.outcome", string(outcomeOf(result))), attribute.Int("mcp.tool.result_bytes", len(result.Text)), ) toolSpan.End() // <- closed here ... reinjected, trimmed := boundToolResult(result.Text, budget.ToolResultBytes) if trimmed { // <- truncation is decided here spilled := spillToolResult(...) telemetry.Info(toolCtx, "mcp.tool.result.bounded", ...) } ``` **The bound is applied after the span ends**, so no attribute can carry it. Truncation exists only as a log line, and a log line cannot be joined to the trace a reader is holding. That is the same gap https://forgejo.coilysiren.me/coilyco-gaming/sirens-echo/issues/570 closed for tool outcomes, still open for tool truncation. The practical cost showed up on 635 itself: establishing that 87% of a Steam library was dropped required reading logs and then reading two YAML files to learn what the cap was. None of it was answerable from the trace. ## The record is also incomplete ``` mcp.tool.result.bounded result_bytes=131072 reinjected_bytes=16573 spill_path=... ``` Two things a reader has to derive by hand: - **which bound applied.** `reinjected_bytes` is not the cap. It is the cap plus the truncation and spill notices, which is why 635 measured 16,568 to 16,582 against a 16,384 limit and reasonably concluded the value had moved. It had not. - **how much was dropped.** Derivable, but the subtraction is against the wrong number for the reason above, so it is derived wrongly. ## What I am building - `boundToolResult` runs **before** `toolSpan.End()`, so the span carries `mcp.tool.limit_bytes` and `mcp.tool.truncated`. - The spill stays **after** `End()`. It writes a file, and folding that into the span would inflate every truncated tool call's measured latency by a disk write. The span should say what the bound did, not how long spilling took. - `limit_bytes` and `dropped_bytes` on the `mcp.tool.result.bounded` record, so it is readable without arithmetic against a definition file. ## Not in scope The per-tool bound, the sizing, and whether 16 KiB is right. All of that is 635 and https://forgejo.coilysiren.me/coilyco-gaming/sirens-echo/issues/362. **This changes no bound and no behaviour a member can see.** It makes the existing bound legible, which is worth doing whichever way the numbers go.

coilyco-ops referenced this issue from a pull request that will close it,

2026-08-13 17:46:47 +00:00

feat(telemetry): put the tool-result bound on the span, not only in a log #643

coilyco-ops commented

2026-08-13 17:47:07 +00:00

Author

Member

Built. #643, gate green.

Revert-checked on the headline:

TestTheTraceSaysWhetherAResultWasTruncated   mcp.tool.truncated = "", want true
TestAnUntruncatedResultSaysSoOnTheTrace      mcp.tool.truncated = "", want false

Both drive a real tool round through Complete against a recording tracer, using the harness sirens-echo#570 left behind, so the assertion is on what a reader would actually see rather than on a function's return.

A second defect I found while doing it

The dropped_bytes I set out to add was wrong in my first version, and it was wrong the same way the record already implied.

boundToolResult walks back to a rune boundary, so the cut lands below the limit for any multibyte result. Subtracting the limit therefore overstates what was delivered and understates the loss. On a result of three-byte runes the naive figure is off by up to two bytes per truncation, which is small, and it is the same class of error that made 635 conclude the cap had moved.

So the function now returns the delivered count and the record subtracts against that. TestTheDeliveredCountIsNotAlwaysTheLimit uses a result of あ and fails if the real loss and the naive loss agree, which is the case the ASCII test would have missed entirely.

Three test call sites needed a _ for the new return. Mechanical, and worth it: shipping a figure that is nearly right, in a record whose whole purpose is that a reader stops doing arithmetic by hand, would have been the wrong trade.

The attribute is set on every call, not only truncated ones

mcp.tool.truncated is false and mcp.tool.limit_bytes is present on an ordinary result too. Absence of an attribute is not something a reader should have to interpret, and a filter on truncated=false is as useful as one on true when you are asking how often the cap binds.

That last question is now answerable, which it was not this morning, and it is the number #635 and #362 should be decided against.

Still not in scope, deliberately

The per-tool bound and the sizing. This changes no bound. Once 643 is deployed there is a cheap follow-up for whoever owns 362: aggregate mcp.tool.truncated by mcp.tool.name over a day, and the flat ceiling's cost stops being one anecdote about a Steam library and becomes a distribution.

**Built. https://forgejo.coilysiren.me/coilyco-gaming/sirens-echo/pulls/643, gate green.** Revert-checked on the headline: ``` TestTheTraceSaysWhetherAResultWasTruncated mcp.tool.truncated = "", want true TestAnUntruncatedResultSaysSoOnTheTrace mcp.tool.truncated = "", want false ``` Both drive a real tool round through `Complete` against a recording tracer, using the harness `sirens-echo#570` left behind, so the assertion is on what a reader would actually see rather than on a function's return. ## A second defect I found while doing it The `dropped_bytes` I set out to add was wrong in my first version, and it was wrong the same way the record already implied. `boundToolResult` walks back to a rune boundary, so **the cut lands below the limit for any multibyte result.** Subtracting the limit therefore overstates what was delivered and understates the loss. On a result of three-byte runes the naive figure is off by up to two bytes per truncation, which is small, and it is the same class of error that made 635 conclude the cap had moved. So the function now returns the delivered count and the record subtracts against that. `TestTheDeliveredCountIsNotAlwaysTheLimit` uses a result of `あ` and fails if the real loss and the naive loss agree, which is the case the ASCII test would have missed entirely. Three test call sites needed a `_` for the new return. Mechanical, and worth it: shipping a figure that is nearly right, in a record whose whole purpose is that a reader stops doing arithmetic by hand, would have been the wrong trade. ## The attribute is set on every call, not only truncated ones `mcp.tool.truncated` is `false` and `mcp.tool.limit_bytes` is present on an ordinary result too. Absence of an attribute is not something a reader should have to interpret, and a filter on `truncated=false` is as useful as one on `true` when you are asking how often the cap binds. That last question is now answerable, which it was not this morning, and it is the number https://forgejo.coilysiren.me/coilyco-gaming/sirens-echo/issues/635 and https://forgejo.coilysiren.me/coilyco-gaming/sirens-echo/issues/362 should be decided against. ## Still not in scope, deliberately The per-tool bound and the sizing. This changes no bound. **Once 643 is deployed there is a cheap follow-up for whoever owns 362**: aggregate `mcp.tool.truncated` by `mcp.tool.name` over a day, and the flat ceiling's cost stops being one anecdote about a Steam library and becomes a distribution.

coilyco-ops referenced this issue from a commit

2026-08-13 17:48:01 +00:00

feat(telemetry): put the tool-result bound on the span, not only in a log

coilyco-ops closed this issue

2026-08-13 17:48:01 +00:00

No milestone

No project

No assignees

1 participant

Notifications

Due date

The due date is invalid or out of range. Please use the format "yyyy-mm-dd".

No due date set.

Dependencies

No dependencies set

Reference

coilyco-gaming/sirens-echo#640

No description provided.

Rows
Columns