fix(coding-agents): record why an automatic reflect failed (#4316)

A reflect_failed diag line read either "reflect 500" or "This operation
was aborted (20)", with no bank, so neither could be traced server-side.

- reflect() keeps the server's response body (first 1000 chars) on a
  non-2xx reply, like req() already does.
- Our own deadline now reads "reflect timed out after Nms" (the abort
  stays on the cause chain).
- reflect_failed records the bank and the timeout, and no longer cuts the
  error at describeError's 200-char default.
This commit is contained in:
Nicolò Boschi
2026-09-11 11:15:56 +02:00
committed by GitHub
parent d9df6d2a4d
commit e33debb958
4 changed files with 81 additions and 3 deletions
@@ -518,3 +518,34 @@ describe("every client-building entrypoint forwards observationScopes", () => {
expect(dropped).toEqual([]);
});
});
describe("HindsightClient.reflect failures", () => {
it("keeps the server's error body, not just the status", async () => {
vi.stubGlobal(
"fetch",
vi.fn(async () => jsonResponse(500, { detail: "tool_call ids must be unique" }))
);
const client = new HindsightClient({ apiUrl: "http://x", bank: "b" });
await expect(client.reflect("why?", { timeoutMs: 5_000 })).rejects.toThrow(
/^reflect 500 .*tool_call ids must be unique/
);
});
it("names its own deadline instead of a bare 'operation was aborted'", async () => {
vi.stubGlobal(
"fetch",
vi.fn(
(_url: string | URL | Request, init?: RequestInit) =>
new Promise<Response>((_resolve, reject) => {
init?.signal?.addEventListener("abort", () => reject(init.signal?.reason));
})
)
);
const client = new HindsightClient({ apiUrl: "http://x", bank: "b" });
await expect(client.reflect("why?", { timeoutMs: 10 })).rejects.toThrow(
"reflect timed out after 10ms"
);
});
});
@@ -525,9 +525,18 @@ export class HindsightClient {
body: JSON.stringify({ query, budget: opts.budget ?? "high" }),
signal: ctrl.signal,
});
if (!resp.ok) throw new Error(`reflect ${resp.status}${this.authHint(resp.status)}`);
// Keep the server's body: a bare "reflect 500" in the diag trail is undebuggable after the fact.
if (!resp.ok)
throw new Error(
`reflect ${resp.status} ${(await resp.text()).slice(0, 1000)}${this.authHint(resp.status)}`
);
const data = (await resp.json()) as { text?: string };
return (data.text || "").trim();
} catch (e) {
// Our own deadline surfaces as a generic "This operation was aborted"; name it.
if (ctrl.signal.aborted)
throw new Error(`reflect timed out after ${opts.timeoutMs}ms`, { cause: e });
throw e;
} finally {
clearTimeout(timer);
}
@@ -16,6 +16,7 @@ beforeEach(() => {
});
afterEach(() => {
vi.unstubAllEnvs();
rmSync(root, { recursive: true, force: true });
});
@@ -155,6 +156,37 @@ describe("buildHookOutput", () => {
expect(client.reflect).toHaveBeenCalledTimes(1);
});
it("reflect_failed records the bank, the deadline, and the server's full error body", async () => {
const diagFile = join(root, "diag.log");
vi.stubEnv("HINDSIGHT_DIAG_FILE", diagFile);
const body = `{"detail":"${"x".repeat(400)} upstream LLM rejected the turn"}`;
const client = {
...makeClient({
reflect: vi.fn(async () => {
throw new Error(`reflect 500 ${body}`);
}),
}),
bank: "coding-agent::demo",
};
await buildHookOutput({
harness: "claude-code",
prompt: UNRELATED_PROMPT,
cfg: resolveConfig({}),
client,
cacheFile,
});
const failed = readFileSync(diagFile, "utf8")
.trim()
.split("\n")
.map((line) => JSON.parse(line))
.find((entry) => entry.event === "reflect_failed");
expect(failed.bank).toBe("coding-agent::demo");
expect(failed.timeoutMs).toBe(25_000);
// Past describeError's default 200-char cut, where the root cause usually sits.
expect(failed.error).toContain("upstream LLM rejected the turn");
});
it("the notice fires ONCE — the turn reflect failed, not on later turns", async () => {
const cfg = resolveConfig({});
const client = makeClient({
@@ -67,6 +67,8 @@ interface HookClient {
reflect(query: string, opts: { budget?: string; timeoutMs: number }): Promise<string>;
listPages(): Promise<unknown>;
knowledgePagesSupported?: boolean;
/** Recorded on reflect failures so the diag trail says which bank to look at server-side. */
readonly bank?: string;
}
/**
@@ -120,13 +122,14 @@ export async function buildHookOutput(args: {
} else if (cfg.autoReflect && reflectAnswer === undefined) {
reflectRanThisTurn = true;
const t0 = Date.now();
const timeoutMs = Math.min(cfg.reflectTimeoutMs, HOOK_REFLECT_CAP_MS);
try {
reflectAnswer = await client.reflect(buildReflectQuery(prompt), {
// Automatic reflection runs inside a hard 25s hook window. Hindsight's low budget is the
// supported default for bounded reflect calls; callers that explicitly invoke the MCP
// tool still get the deeper high-budget path.
budget: "low",
timeoutMs: Math.min(cfg.reflectTimeoutMs, HOOK_REFLECT_CAP_MS),
timeoutMs,
});
diag(harness, reflectAnswer ? "reflect_ok" : "reflect_empty", {
ms: Date.now() - t0,
@@ -144,7 +147,10 @@ export async function buildHookOutput(args: {
});
diag(harness, "reflect_failed", {
ms: Date.now() - t0,
error: describeError(e),
bank: client.bank,
timeoutMs,
// Wider than describeError's default: the server's error body is the useful part.
error: describeError(e, 1500),
query: prompt.slice(0, 80),
});
}