From bb962c3bfd63de272dae61ff3eafc3d7804c9044 Mon Sep 17 00:00:00 2001 From: Rhys Sullivan <39114868+RhysSullivan@users.noreply.github.com> Date: Sat, 29 Aug 2026 18:19:17 -0700 Subject: [PATCH 1/2] Measure execute result size once per result object --- .changeset/dedupe-result-size-walk.md | 7 ++ packages/core/execution/src/engine.test.ts | 138 ++++++++++++++++++++- packages/core/execution/src/engine.ts | 35 ++++-- packages/hosts/mcp/src/tool-server.test.ts | 61 +++++++++ 4 files changed, 232 insertions(+), 9 deletions(-) create mode 100644 .changeset/dedupe-result-size-walk.md diff --git a/.changeset/dedupe-result-size-walk.md b/.changeset/dedupe-result-size-walk.md new file mode 100644 index 000000000..99f70d6e2 --- /dev/null +++ b/.changeset/dedupe-result-size-walk.md @@ -0,0 +1,7 @@ +--- +"@executor-js/execution": patch +--- + +**Large execute results are measured once, not once per span** + +The result-size telemetry probe serializes the whole returned value to count its characters, and that cost grows with the payload. The same result object was walked again every time it was stamped onto another span: an operator-approved run measured it twice (inner and outer span), and every retried `resume` that replayed a settled outcome measured it again. The measurement is now computed once per result object and reused, so a large result pays one size walk no matter how many spans report it. Response text, structured content, and span attribute values are unchanged. diff --git a/packages/core/execution/src/engine.test.ts b/packages/core/execution/src/engine.test.ts index da0efab1f..e05c9f8c9 100644 --- a/packages/core/execution/src/engine.test.ts +++ b/packages/core/execution/src/engine.test.ts @@ -5,7 +5,7 @@ import { createExecutor, definePlugin } from "@executor-js/sdk"; import { makeTestConfig } from "@executor-js/sdk/testing"; import type { CodeExecutor, ExecuteResult } from "@executor-js/codemode-core"; -import { createExecutionEngine, formatPausedExecution } from "./engine"; +import { createExecutionEngine, formatExecuteResult, formatPausedExecution } from "./engine"; import { FormElicitation } from "@executor-js/sdk/core"; // Regression for the hang reported as the executor-MCP "180s timeout" against @@ -140,3 +140,139 @@ describe("formatPausedExecution approval terms", () => { expect((result.structured["interaction"] as Record)["meta"]).toBeUndefined(); }); }); + +// Pins the exact preview and structured shapes so the serialization dedupe in +// the engine cannot drift them: the preview stays pretty-printed (indent 2), +// truncation keeps its exact suffix, and structured carries the raw value. +describe("formatExecuteResult output identity", () => { + const MAX_PREVIEW_CHARS = 30_000; + + it("renders an object result as pretty-printed JSON and keeps the raw value in structured", () => { + const value = { café: "naïve — ✓", emoji: "🎉", nested: { π: 3.14159 } }; + const formatted = formatExecuteResult({ result: value, logs: [] }); + + expect(formatted.text).toBe(JSON.stringify(value, null, 2)); + expect(formatted.structured).toEqual({ status: "completed", result: value, logs: [] }); + expect(formatted.structured["result"]).toBe(value); + expect(formatted.isError).toBe(false); + }); + + it("truncates a long preview with the exact suffix and untouched structured value", () => { + const value = { data: "é🎉".repeat(12_000) }; + const pretty = JSON.stringify(value, null, 2); + expect(pretty.length).toBeGreaterThan(MAX_PREVIEW_CHARS); + + const formatted = formatExecuteResult({ result: value }); + + expect(formatted.text).toBe( + `${pretty.slice(0, MAX_PREVIEW_CHARS)}\n... [truncated ${pretty.length - MAX_PREVIEW_CHARS} chars]`, + ); + expect(formatted.structured["result"]).toBe(value); + }); + + it("returns a string result verbatim", () => { + const formatted = formatExecuteResult({ result: "plain — ✓", logs: ["l1", "l2"] }); + + expect(formatted.text).toBe("plain — ✓\n\nLogs:\nl1\nl2"); + expect(formatted.structured).toEqual({ + status: "completed", + result: "plain — ✓", + logs: ["l1", "l2"], + }); + }); + + it("renders an error result with logs and truncation", () => { + const formatted = formatExecuteResult({ + result: null, + error: "boom", + errorKind: "tool_error", + logs: ["x".repeat(MAX_PREVIEW_CHARS)], + }); + + const untruncated = `Error: boom\n\nLogs:\n${"x".repeat(MAX_PREVIEW_CHARS)}`; + expect(formatted.text).toBe( + `${untruncated.slice(0, MAX_PREVIEW_CHARS)}\n... [truncated ${untruncated.length - MAX_PREVIEW_CHARS} chars]`, + ); + expect(formatted.isError).toBe(true); + expect(formatted.structured).toEqual({ + status: "error", + error: "boom", + logs: ["x".repeat(MAX_PREVIEW_CHARS)], + }); + }); +}); + +// The result-size span metric walks the whole result value with +// `JSON.stringify`. A `toJSON` probe inside the fixture counts full walks: +// every complete stringify of the value visits the probe exactly once. +describe("execute outcome measurement cost", () => { + const instrumented = () => { + let walks = 0; + const probe = { + toJSON: () => { + walks += 1; + return "probe"; + }, + }; + return { value: { data: [1, 2, 3], probe }, walks: () => walks }; + }; + + const executorFor = (result: ExecuteResult): CodeExecutor => ({ + execute: () => Effect.succeed(result), + }); + + it.effect("walks the result value once on the pausable path", () => + Effect.gen(function* () { + const executor = yield* makeExecutor(); + const fixture = instrumented(); + const engine = createExecutionEngine({ + executor, + codeExecutor: executorFor({ result: fixture.value, logs: [] }), + }); + + const outcome = yield* engine.executeWithPause("noop"); + + expect(outcome.status).toBe("completed"); + expect(fixture.walks()).toBe(1); + }), + ); + + it.effect("walks the result value once even when autoApprove stamps two spans", () => + Effect.gen(function* () { + const executor = yield* makeExecutor(); + const fixture = instrumented(); + const engine = createExecutionEngine({ + executor, + codeExecutor: executorFor({ result: fixture.value, logs: [] }), + }); + + // autoApprove runs the inline path (inner span annotation) and then + // annotates the outer pausable span with the same result. + const outcome = yield* engine.executeWithPause("noop", { autoApprove: true }); + + expect(outcome.status).toBe("completed"); + expect(fixture.walks()).toBe(1); + }), + ); + + it.effect("a completed execution plus its preview pays two walks total", () => + Effect.gen(function* () { + const executor = yield* makeExecutor(); + const fixture = instrumented(); + const engine = createExecutionEngine({ + executor, + codeExecutor: executorFor({ result: fixture.value, logs: [] }), + }); + + const outcome = yield* engine.executeWithPause("noop"); + expect(outcome.status).toBe("completed"); + if (outcome.status !== "completed") return; + + // One compact walk for the span size metric, one pretty walk for the + // preview. They produce different strings (compact vs indent 2), so + // neither can be derived from the other. + formatExecuteResult(outcome.result); + expect(fixture.walks()).toBe(2); + }), + ); +}); diff --git a/packages/core/execution/src/engine.ts b/packages/core/execution/src/engine.ts index 81098864f..5113f9f46 100644 --- a/packages/core/execution/src/engine.ts +++ b/packages/core/execution/src/engine.ts @@ -80,6 +80,32 @@ const measureResultChars = (value: unknown): number => { } }; +/** + * Outcome attributes are a pure function of an immutable `ExecuteResult`, but + * the same result object is annotated more than once: the `autoApprove` path + * stamps both the inner inline span and the outer pausable span, and resume + * retries replay the settled result cached per execution id. The size probe + * walks the whole result value (`JSON.stringify`), so its cost grows with the + * payload — memoize the record per result object so each result is walked + * once, no matter how many spans it is stamped onto. + */ +const executeOutcomeAttributesCache = new WeakMap>(); + +const executeOutcomeAttributes = (result: ExecuteResult): Record => { + const cached = executeOutcomeAttributesCache.get(result); + if (cached) return cached; + const attributes = { + "mcp.execute.result_chars": measureResultChars(result.result), + "mcp.execute.log_chars": result.logs?.reduce((total, line) => total + line.length, 0) ?? 0, + "mcp.execute.emitted": result.output?.length ?? 0, + ...(result.error + ? { "mcp.execute.outcome": "fail", "mcp.execute.error_kind": result.errorKind ?? "unknown" } + : { "mcp.execute.outcome": "ok" }), + }; + executeOutcomeAttributesCache.set(result, attributes); + return attributes; +}; + /** * Stamp the current `mcp.execute` / `mcp.execute.resume` span with how the * execution ended and how much data it sent back toward model context. @@ -89,14 +115,7 @@ const measureResultChars = (value: unknown): number => { * or result content itself. */ const annotateExecuteOutcome = (result: ExecuteResult) => - Effect.annotateCurrentSpan({ - "mcp.execute.result_chars": measureResultChars(result.result), - "mcp.execute.log_chars": result.logs?.reduce((total, line) => total + line.length, 0) ?? 0, - "mcp.execute.emitted": result.output?.length ?? 0, - ...(result.error - ? { "mcp.execute.outcome": "fail", "mcp.execute.error_kind": result.errorKind ?? "unknown" } - : { "mcp.execute.outcome": "ok" }), - }); + Effect.annotateCurrentSpan(executeOutcomeAttributes(result)); const annotateExecutionOutcome = (execution: ExecutionResult) => execution.status === "paused" diff --git a/packages/hosts/mcp/src/tool-server.test.ts b/packages/hosts/mcp/src/tool-server.test.ts index 311d6ee26..f355fc164 100644 --- a/packages/hosts/mcp/src/tool-server.test.ts +++ b/packages/hosts/mcp/src/tool-server.test.ts @@ -1973,3 +1973,64 @@ describe("MCP host server — hang-visibility tracing", () => { ); }); }); + +// Pins that formatting a completed execution for MCP walks the result value +// exactly once (`formatExecuteResult`'s pretty print), with or without emit() +// output — the with-output and without-output branches are alternatives, never +// stacked. A `toJSON` probe counts full `JSON.stringify` walks of the value. +describe("formatMcpExecutionOutcome serialization cost", () => { + const instrumented = () => { + let walks = 0; + const probe = { + toJSON: () => { + walks += 1; + return "probe"; + }, + }; + return { value: { data: [1, 2, 3], probe }, walks: () => walks }; + }; + + it("stringifies the result value once for a plain completed outcome", () => { + const fixture = instrumented(); + const outcome: ExecutionResult = { + status: "completed", + result: { result: fixture.value, logs: [] }, + }; + + const result = formatMcpExecutionOutcome(outcome); + + expect(fixture.walks()).toBe(1); + const first = result.content[0]; + expectDefined(first); + expect(first).toEqual({ + type: "text", + text: JSON.stringify(fixture.value, null, 2), + }); + expectDefined(result.structuredContent); + expect(result.structuredContent["result"]).toBe(fixture.value); + // The identity probe above walked the value once more; discount it. + expect(fixture.walks()).toBe(2); + }); + + it("stringifies the result value once when emit() output is present", () => { + const fixture = instrumented(); + const outcome: ExecutionResult = { + status: "completed", + result: { + result: fixture.value, + logs: [], + output: [{ type: "content", content: { type: "text", text: "emitted" } }], + }, + }; + + const result = formatMcpExecutionOutcome(outcome); + + expect(fixture.walks()).toBe(1); + expect(result.content[0]).toEqual({ type: "text", text: "emitted" }); + const returned = result.content[1]; + expectDefined(returned); + expect(returned.type).toBe("text"); + if (returned.type !== "text") return; + expect(returned.text).toContain('"data"'); + }); +}); From f8354953674f391bb6c470b6accff8278b413558 Mon Sep 17 00:00:00 2001 From: Rhys Sullivan <39114868+RhysSullivan@users.noreply.github.com> Date: Sat, 29 Aug 2026 19:30:17 -0700 Subject: [PATCH 2/2] Pin execute output fidelity end-to-end --- e2e/scenarios/mcp-execute.test.ts | 145 ++++++++++++++++++- e2e/scenarios/run-panel-auto-approve.test.ts | 18 ++- 2 files changed, 161 insertions(+), 2 deletions(-) diff --git a/e2e/scenarios/mcp-execute.test.ts b/e2e/scenarios/mcp-execute.test.ts index 925bd8efa..472b7b18e 100644 --- a/e2e/scenarios/mcp-execute.test.ts +++ b/e2e/scenarios/mcp-execute.test.ts @@ -1,11 +1,23 @@ // Cross-target: the MCP surface — connect with fully headless OAuth (DCR → // consent → code → token) and run code in the sandbox, exactly as an MCP // client (Claude, Cursor, …) would. +import { randomUUID } from "node:crypto"; + import { expect } from "@effect/vitest"; import { Effect } from "effect"; +import { composePluginApi } from "@executor-js/api/server"; import { scenario } from "../src/scenario"; -import { Mcp, Target } from "../src/services"; +import { Api, Mcp, Target } from "../src/services"; + +const coreApi = composePluginApi([] as const); + +/** The raw MCP tool result shape the fidelity scenarios assert against. */ +const rawResultOf = (result: { readonly raw: unknown }) => + result.raw as { + content?: ReadonlyArray<{ type: string; text?: string }>; + structuredContent?: Record; + }; scenario( "MCP · OAuth connect, then execute code in the sandbox", @@ -24,6 +36,137 @@ scenario( }), ); +// The exact value a sandbox script returns, non-ASCII included. The server +// renders it into the text channel (pretty-printed JSON) and mirrors it into +// `structuredContent`; both must reach the client byte-identical — a client +// diffing retries or hashing results must never see the payload drift. +const structuredPayload = { + greeting: "héllo — こんにちは ✅", + emoji: "🚀", + values: [1, 2, 3], + nested: { ok: true, label: "Zoë" }, +}; + +scenario( + "MCP · a structured return value reaches the client byte-identical in text and structuredContent", + {}, + Effect.gen(function* () { + const target = yield* Target; + const mcp = yield* Mcp; + const identity = yield* target.newIdentity(); + const session = mcp.session(identity); + yield* session.listTools(); + + const result = yield* session.call("execute", { + code: `return ${JSON.stringify(structuredPayload)};`, + }); + expect(result.ok, "the sandbox run completes without error").toBe(true); + + const expectedText = JSON.stringify(structuredPayload, null, 2); + const raw = rawResultOf(result); + expect(raw.content?.length, "the result arrives as a single text block").toBe(1); + expect(raw.content?.[0]?.text, "the text channel carries the exact rendered value").toBe( + expectedText, + ); + expect(result.text, "the joined text content matches byte-for-byte").toBe(expectedText); + expect(raw.structuredContent, "structuredContent mirrors the exact returned value").toEqual({ + status: "completed", + result: structuredPayload, + logs: [], + }); + }), +); + +/** Sandbox code that runs ONE approval-gated call (the `policies.create` core + * tool gates itself via its `requiresApproval` annotation — same hermetic + * device as policy-tool-approval.test.ts) and then returns a deterministic + * payload. The pattern is unique-per-run and matches no real tool, so the + * created `block` rule is inert even if leaked. */ +const gatedThenReturnCode = (pattern: string, payload: unknown) => ` +await tools.executor.coreTools.policies.create({ + owner: "user", + pattern: ${JSON.stringify(pattern)}, + action: "block", +}); +return ${JSON.stringify(payload)}; +`; + +scenario( + "MCP · a duplicate resume replays the identical settled result without re-running the tool", + {}, + Effect.gen(function* () { + const target = yield* Target; + const apiSurface = yield* Api; + const mcp = yield* Mcp; + const identity = yield* target.newIdentity(); + const client = yield* apiSurface.client(coreApi, identity); + const pattern = `mcp-resume-replay-${randomUUID().slice(0, 8)}.*`; + const replayPayload = { note: "resumed — résultat 完了 ✅", pattern }; + + const cleanup = client.policies.list().pipe( + Effect.flatMap((list) => + Effect.forEach( + list.filter((p) => p.pattern === pattern), + (p) => + client.policies + .remove({ params: { policyId: p.id }, payload: { owner: "user" } }) + .pipe(Effect.ignore), + ), + ), + Effect.ignore, + ); + + yield* Effect.gen(function* () { + const session = mcp.session(identity); + yield* session.listTools(); + + const paused = yield* session.call("execute", { + code: gatedThenReturnCode(pattern, replayPayload), + }); + expect(paused.text, "the gated call pauses for approval").toContain("Execution paused"); + const match = /\bexecutionId:\s*(\S+)/.exec(paused.text); + expect(match, "the pause carries an executionId to resume").not.toBeNull(); + + // MCP clients retry `resume` when a response is lost in transit, so the + // duplicate uses the exact same arguments as the first delivery. + const resumeArgs = { + executionId: match![1]!, + action: "accept", + content: JSON.stringify({}), + }; + + const resumed = yield* session.call("resume", resumeArgs); + expect(resumed.ok, "the approved execution completes without error").toBe(true); + const expectedText = JSON.stringify(replayPayload, null, 2); + expect(resumed.text, "the resumed result carries the exact returned value").toBe( + expectedText, + ); + expect( + rawResultOf(resumed).structuredContent, + "the resumed structuredContent mirrors the exact returned value", + ).toEqual({ status: "completed", result: replayPayload, logs: [] }); + + const replayed = yield* session.call("resume", resumeArgs); + expect(replayed.ok, "the duplicate resume succeeds instead of erroring").toBe(true); + expect(replayed.text, "the replayed text is byte-identical to the first delivery").toBe( + resumed.text, + ); + expect( + rawResultOf(replayed).structuredContent, + "the replayed structuredContent is identical to the first delivery", + ).toEqual(rawResultOf(resumed).structuredContent); + + // The replay served the recorded outcome — the gated tool did not run a + // second time. + const afterReplay = yield* client.policies.list(); + expect( + afterReplay.filter((p) => p.pattern === pattern).length, + "the gated tool ran exactly once despite the duplicate resume", + ).toBe(1); + }).pipe(Effect.ensuring(cleanup)); + }), +); + scenario( "MCP · a syntax error returns a descriptive message, not an opaque internal error", {}, diff --git a/e2e/scenarios/run-panel-auto-approve.test.ts b/e2e/scenarios/run-panel-auto-approve.test.ts index 009c0abd9..f6a3e581e 100644 --- a/e2e/scenarios/run-panel-auto-approve.test.ts +++ b/e2e/scenarios/run-panel-auto-approve.test.ts @@ -26,14 +26,24 @@ import { Api, Target } from "../src/services"; const coreApi = composePluginApi([] as const); +/** The deterministic value the gated script returns once approved. Asserting + * the completed response against it byte-for-byte (non-ASCII included) pins + * output fidelity on the autoApprove path — the panel must render exactly + * what the script returned. */ +const approvedPayload = { + note: "auto-approved — résultat 完了 ✅", + values: [1, 2, 3], +}; + /** Sandbox code that creates a policy through the approval-gated core tool. The * pattern is unique-per-run and matches no real tool, so the rule is inert. */ const createPolicyCode = (pattern: string) => ` -return await tools.executor.coreTools.policies.create({ +await tools.executor.coreTools.policies.create({ owner: "user", pattern: ${JSON.stringify(pattern)}, action: "block", }); +return ${JSON.stringify(approvedPayload)}; `; // Why this was long skipped: `autoApprove: true` came back `"paused"` instead of @@ -97,6 +107,12 @@ scenario( expect(approved.status, "autoApprove runs the gated tool to completion").toBe("completed"); if (approved.status !== "completed") return; // narrowing only expect(approved.isError, "the auto-approved run is not an error").toBe(false); + expect(approved.text, "the returned value reaches the panel byte-identical").toBe( + JSON.stringify(approvedPayload, null, 2), + ); + expect(approved.structured, "the structured result mirrors the exact returned value").toEqual( + { status: "completed", result: approvedPayload, logs: [] }, + ); const afterApproval = yield* client.policies.list(); expect(