diff --git a/agents/claude.ts b/agents/claude.ts index c718f23..fb96af0 100644 --- a/agents/claude.ts +++ b/agents/claude.ts @@ -18,7 +18,7 @@ import { performance } from "node:perf_hooks"; import { pullfrogMcpName } from "../external.ts"; import { getIdleMs, markActivity } from "../utils/activity.ts"; -import { log } from "../utils/cli.ts"; +import { formatJsonValue, log } from "../utils/cli.ts"; import { installFromNpmTarball } from "../utils/install.ts"; import { detectProviderError } from "../utils/providerErrors.ts"; import { addSkill, installBundledSkills } from "../utils/skills.ts"; @@ -28,7 +28,7 @@ import type { TodoTracker } from "../utils/todoTracking.ts"; import { getDevDependencyVersion } from "../utils/version.ts"; import { buildLearningsReflectionPrompt, runPostRunRetryLoop } from "./postRun.ts"; import { REVIEWER_AGENT_NAME, REVIEWER_SYSTEM_PROMPT } from "./reviewer.ts"; -import { deriveLabelFromTaskInput } from "./sessionLabeler.ts"; +import { formatWithLabel, ORCHESTRATOR_LABEL, SessionLabeler } from "./sessionLabeler.ts"; import { type AgentResult, type AgentRunContext, @@ -114,13 +114,21 @@ interface ContentBlock { [key: string]: unknown; } +// SDK schema (per claude-agent-sdk docs) puts `session_id` and +// `parent_tool_use_id` at the top level of every Assistant/User/System/Result +// message, not inside `message`. Subagent events carry a non-null +// `parent_tool_use_id` pointing at the orchestrator's Task/Agent tool_use id. interface ClaudeSystemEvent { type: "system"; + session_id?: string; + parent_tool_use_id?: string | null; [key: string]: unknown; } interface ClaudeAssistantEvent { type: "assistant"; + session_id?: string; + parent_tool_use_id?: string | null; message?: { role?: string; content?: ContentBlock[]; @@ -138,6 +146,8 @@ interface ClaudeAssistantEvent { interface ClaudeUserEvent { type: "user"; + session_id?: string; + parent_tool_use_id?: string | null; message?: { role?: string; content?: ContentBlock[]; @@ -236,7 +246,37 @@ function tailLines(text: string, maxCodeUnits: number): string { export async function runClaude(params: RunParams): Promise { const startTime = performance.now(); let eventCount = 0; - const thinkingTimer = new ThinkingTimer(); + + // per-session labeler so parallel subagent log lines can be differentiated. + // claude-agent-sdk runs subagents inside the orchestrator's session — they + // share `session_id` — and stamps every subagent message with a non-null + // `parent_tool_use_id` pointing at the Agent tool_use that spawned them. + // we bind each Agent tool_use id to its dispatched label up front, then + // labelFor short-circuits to the direct mapping when parent_tool_use_id is + // set. orchestrator events (parent_tool_use_id === null) flow through the + // sessionID path and bind to ORCHESTRATOR_LABEL on first sighting. + const labeler = new SessionLabeler(); + function eventLabel(event: { session_id?: string; parent_tool_use_id?: string | null }): string { + return labeler.labelFor(event.session_id ?? null, event.parent_tool_use_id ?? null); + } + function withLabel(label: string, message: string): string { + return label === ORCHESTRATOR_LABEL ? message : formatWithLabel(label, message); + } + + // one ThinkingTimer per session — sharing a single timer across sessions + // conflated cross-session interleaving as parent thinking time. each timer + // formats its log lines through the session label so attribution is visible. + const thinkingTimers = new Map(); + function timerFor(label: string): ThinkingTimer { + let t = thinkingTimers.get(label); + if (!t) { + const formatLine = (line: string) => + label === ORCHESTRATOR_LABEL ? line : formatWithLabel(label, line); + t = new ThinkingTimer(formatLine); + thinkingTimers.set(label, t); + } + return t; + } let finalOutput = ""; let sessionId: string | undefined; @@ -280,18 +320,30 @@ export async function runClaude(params: RunParams): Promise { } const handlers = { - system: (_event: ClaudeSystemEvent) => { - log.debug(`» ${params.label} system event`); + system: (event: ClaudeSystemEvent) => { + // claude-agent-sdk only emits system:init for the top-level query, so + // this binds the orchestrator label and never appears in subagent flow. + // we still route through eventLabel so a subagent system event (if the + // SDK ever adds one) wouldn't go silently misattributed. + const label = eventLabel(event); + log.debug(withLabel(label, `» ${params.label} system event`)); }, assistant: (event: ClaudeAssistantEvent) => { const content = event.message?.content; if (!content) return; + const label = eventLabel(event); + const boxTitle = label === ORCHESTRATOR_LABEL ? params.label : `${params.label} [${label}]`; + for (const block of content) { if (block.type === "text" && block.text?.trim()) { const message = block.text.trim(); - log.box(message, { title: params.label }); - finalOutput = message; + log.box(message, { title: boxTitle }); + // only the orchestrator's text becomes the run's "output" — subagent + // report-back text would otherwise clobber the parent's final answer. + if (label === ORCHESTRATOR_LABEL) { + finalOutput = message; + } } else if (block.type === "tool_use") { const toolName = block.name || "unknown"; if (params.onToolUse) { @@ -300,23 +352,34 @@ export async function runClaude(params: RunParams): Promise { input: block.input, }); } - thinkingTimer.markToolCall(); - log.toolCall({ toolName, input: block.input || {} }); + timerFor(label).markToolCall(); + const inputFormatted = formatJsonValue(block.input || {}); + const toolCallLine = + inputFormatted !== "{}" ? `» ${toolName}(${inputFormatted})` : `» ${toolName}()`; + log.info(withLabel(label, toolCallLine)); - // surface the subagent identity when the orchestrator dispatches a - // Task — claude rolls subagent activity up into a single tool_result - // (no per-event session_id in its stream), so this log line is the - // only attribution available before the subagent's report-back. - if (toolName === "Task" && block.input && typeof block.input === "object") { + // when the orchestrator dispatches a subagent, bind the Agent + // tool_use id to the dispatched label so future events carrying + // `parent_tool_use_id === block.id` resolve directly to the right + // lens. v2.1.63+ renamed the tool to "Agent"; older versions + // emitted "Task". match both for forward-compat. + if ( + (toolName === "Task" || toolName === "Agent") && + block.input && + typeof block.input === "object" + ) { const taskInput = block.input as { description?: string; subagent_type?: string; prompt?: string; }; - const label = deriveLabelFromTaskInput(taskInput); + const dispatchedLabel = labeler.recordTaskDispatch(taskInput, block.id ?? null); log.info( - `» dispatching subagent: ${label}` + - (taskInput.subagent_type ? ` (subagent_type=${taskInput.subagent_type})` : "") + withLabel( + label, + `» dispatching subagent: ${dispatchedLabel}` + + (taskInput.subagent_type ? ` (subagent_type=${taskInput.subagent_type})` : "") + ) ); } @@ -326,8 +389,14 @@ export async function runClaude(params: RunParams): Promise { params.todoTracker.cancel(); } - // parse TodoWrite events for live progress tracking - if (toolName === "TodoWrite" && params.todoTracker?.enabled) { + // parse TodoWrite events for live progress tracking. only honor the + // orchestrator's todos — subagents emit their own todo lists which + // would otherwise clobber the visible progress comment. + if ( + toolName === "TodoWrite" && + params.todoTracker?.enabled && + label === ORCHESTRATOR_LABEL + ) { params.todoTracker.update(block.input); } } @@ -348,10 +417,12 @@ export async function runClaude(params: RunParams): Promise { const content = event.message?.content; if (!content) return; + const label = eventLabel(event); + for (const block of content) { if (typeof block === "string") continue; if (block.type === "tool_result") { - thinkingTimer.markToolResult(); + timerFor(label).markToolResult(); const outputContent = typeof block.content === "string" @@ -369,9 +440,9 @@ export async function runClaude(params: RunParams): Promise { : String(block.content); if (block.is_error) { - log.info(`» tool error: ${outputContent}`); + log.info(withLabel(label, `» tool error: ${outputContent}`)); } else { - log.debug(`» tool output: ${outputContent}`); + log.debug(withLabel(label, `» tool output: ${outputContent}`)); } } } diff --git a/agents/opencode.ts b/agents/opencode.ts index 7aefcc4..fadb42f 100644 --- a/agents/opencode.ts +++ b/agents/opencode.ts @@ -377,7 +377,6 @@ type RunParams = { async function runOpenCode(params: RunParams): Promise { const startTime = performance.now(); let eventCount = 0; - const thinkingTimer = new ThinkingTimer(); let finalOutput = ""; let accumulatedTokens = { input: 0, output: 0, cacheRead: 0, cacheWrite: 0 }; @@ -409,6 +408,23 @@ async function runOpenCode(params: RunParams): Promise { return label === ORCHESTRATOR_LABEL ? message : formatWithLabel(label, message); } + // one ThinkingTimer per session — sharing a single timer across sessions + // conflated cross-session interleaving (parent thinks → child tool_call, + // or child returns → parent dispatches next) as parent thinking time. each + // timer formats its log lines through the session label so the "thought + // for X" attribution is visible in the merged stream. + const thinkingTimers = new Map(); + function timerFor(label: string): ThinkingTimer { + let t = thinkingTimers.get(label); + if (!t) { + const formatLine = (line: string) => + label === ORCHESTRATOR_LABEL ? line : formatWithLabel(label, line); + t = new ThinkingTimer(formatLine); + thinkingTimers.set(label, t); + } + return t; + } + // tracks per-task dispatch metadata so the matching tool_result can log a // labeled "» subagent finished: lens=X duration=Ys" line. this is the most // useful per-lens observability available given that subagent-internal @@ -634,7 +650,7 @@ async function runOpenCode(params: RunParams): Promise { }); } - thinkingTimer.markToolCall(); + timerFor(label).markToolCall(); const inputFormatted = formatJsonValue(event.part?.state?.input || {}); const toolCallLine = inputFormatted !== "{}" ? `» ${toolName}(${inputFormatted})` : `» ${toolName}()`; @@ -671,7 +687,7 @@ async function runOpenCode(params: RunParams): Promise { const output = event.part?.state?.output || event.output; const label = eventLabel(event); - thinkingTimer.markToolResult(); + timerFor(label).markToolResult(); // surface subagent completion at info level — opencode otherwise hides // per-task timing in debug-only logs, so a parallel multi-lens fan-out diff --git a/agents/sessionLabeler.test.ts b/agents/sessionLabeler.test.ts index bd26c8d..983f967 100644 --- a/agents/sessionLabeler.test.ts +++ b/agents/sessionLabeler.test.ts @@ -146,6 +146,40 @@ describe("SessionLabeler", () => { ]); }); + test("Claude path: parent_tool_use_id resolves directly without consuming FIFO", () => { + // Claude runs subagents inside the orchestrator's session — they share + // session_id — and stamps subagent messages with parent_tool_use_id. + // recording dispatch with the Agent tool_use id binds it directly so + // future events resolve regardless of session_id. + const labeler = new SessionLabeler(); + expect(labeler.labelFor("shared-session", null)).toBe(ORCHESTRATOR_LABEL); + + labeler.recordTaskDispatch({ description: "correctness" }, "toolu_01"); + labeler.recordTaskDispatch({ description: "security" }, "toolu_02"); + + // subagent events come through with shared session_id but distinct + // parent_tool_use_id — direct mapping wins + expect(labeler.labelFor("shared-session", "toolu_01")).toBe("lens:correctness"); + expect(labeler.labelFor("shared-session", "toolu_02")).toBe("lens:security"); + + // orchestrator events on the same session still resolve correctly + expect(labeler.labelFor("shared-session", null)).toBe(ORCHESTRATOR_LABEL); + + // pendingLabels is unused on the Claude path — FIFO never consumed + expect(labeler.pendingDispatchCount()).toBe(2); + expect(labeler.size()).toBe(1); + }); + + test("Claude path: unknown parent_tool_use_id falls through to sessionID/FIFO logic", () => { + // defensive: if a subagent event arrives with a parent_tool_use_id we + // never recorded (e.g. orchestrator dispatched off-stream, or a tool we + // didn't track), the labeler shouldn't crash — it should fall through + // to the sessionID-keyed path. + const labeler = new SessionLabeler(); + labeler.labelFor("shared", null); + expect(labeler.labelFor("shared", "unknown-tool-id")).toBe(ORCHESTRATOR_LABEL); + }); + test("realistic four-lens parallel fan-out — interleaved tool_use stream", () => { // simulates the event order we'd see when the orchestrator dispatches // 4 lens subagents in a single assistant turn and they all start emitting diff --git a/agents/sessionLabeler.ts b/agents/sessionLabeler.ts index dec8ac4..7e8bd41 100644 --- a/agents/sessionLabeler.ts +++ b/agents/sessionLabeler.ts @@ -67,38 +67,68 @@ export function deriveLabelFromTaskInput(input: TaskDispatchInput): string { } /** - * Stateful tracker mapping sessionIDs to human labels. + * Stateful tracker mapping subagent activity back to human-readable labels. * - * Lifecycle: - * - First call to `labelFor()` returns ORCHESTRATOR_LABEL and binds that - * sessionID to it. Every subsequent event from that session gets the - * same label. - * - When the orchestrator emits a Task tool_use, the harness calls - * `recordTaskDispatch()` to push the dispatch's derived label onto a - * pending FIFO queue. - * - The next previously-unseen sessionID consumes the head of the queue. - * - If `labelFor()` is called for a new session with an empty queue - * (e.g. a subagent emitted events before the parent's tool_use was - * parsed, or the runtime spawned a session we didn't expect), the - * labeler falls back to `subagent#N` so log lines remain attributable. + * Two attribution channels are supported because the runtimes differ: + * + * - **OpenCode** spawns each subagent as its own opencode `Session` with + * a distinct `sessionID`. The harness records each Task dispatch into a + * pending FIFO queue; the next previously-unseen sessionID consumes the + * head of the queue and binds it to that label. + * + * - **Claude Code** runs subagents inside the orchestrator's session — they + * all share `session_id` — and instead stamps every subagent message with + * `parent_tool_use_id` pointing at the Agent tool_use id that spawned them. + * The harness binds each Agent tool_use id to its dispatched label up + * front, then `labelFor` looks the label up directly when an event arrives + * carrying that `parent_tool_use_id`. + * + * `labelFor(sessionID, parentToolUseId?)` accepts both: when + * `parentToolUseId` is set and known it short-circuits to the direct mapping; + * otherwise it falls through to the FIFO/sessionID path. */ export class SessionLabeler { private readonly labels = new Map(); + private readonly labelsByToolUseId = new Map(); private readonly pendingLabels: string[] = []; private fallbackCounter = 0; - recordTaskDispatch(input: TaskDispatchInput): string { + /** + * Record a Task/Agent tool dispatch. + * + * @param input Task tool input — used to derive the lens label. + * @param toolUseId Optional Agent tool_use id. When provided, future events + * carrying `parent_tool_use_id === toolUseId` resolve + * directly to this label without consuming the FIFO queue + * (Claude path). Always also pushed to the FIFO queue so + * the OpenCode path still works when toolUseId is absent. + */ + recordTaskDispatch(input: TaskDispatchInput, toolUseId?: string | null): string { const label = deriveLabelFromTaskInput(input); this.pendingLabels.push(label); + if (toolUseId) this.labelsByToolUseId.set(toolUseId, label); return label; } /** - * Return a label for the given sessionID. Binds on first call. - * Pass undefined/empty for events that lack a session id — the caller - * gets ORCHESTRATOR_LABEL so the line is still attributable. + * Return a label for the given event. + * + * @param sessionID Session id from the event (OpenCode: per-session; + * Claude: shared across orchestrator + subagents). + * @param parentToolUseId Claude's `parent_tool_use_id` — non-null on + * subagent messages. When set and known, takes + * priority over the FIFO/sessionID path. */ - labelFor(sessionID: string | undefined | null): string { + labelFor(sessionID: string | undefined | null, parentToolUseId?: string | null): string { + // Claude path: subagent messages carry parent_tool_use_id pointing at + // the Agent tool_use that spawned them. resolve directly without + // touching the sessionID-keyed map (which is bound to the orchestrator + // for the shared session_id and would otherwise misattribute). + if (parentToolUseId) { + const direct = this.labelsByToolUseId.get(parentToolUseId); + if (direct) return direct; + } + if (!sessionID) return ORCHESTRATOR_LABEL; const existing = this.labels.get(sessionID); if (existing) return existing; diff --git a/modes.ts b/modes.ts index d713824..7cec086 100644 --- a/modes.ts +++ b/modes.ts @@ -207,6 +207,8 @@ For simple, well-defined tasks, skip the plan phase and go straight to build.`, - **4–5 lenses (high-stakes subsystem touches)** — any billing/payments change (billing-subsystem + correctness + security + operational-readiness); new auth flow (auth-subsystem + correctness + security + test-integrity); schema migration (schema-migration-subsystem + correctness + operational-readiness + impact); cross-subsystem PR that touches billing AND auth AND schema (one subsystem lens per domain + correctness) - **6+ lenses** — almost always a smell; you're either covering overlapping ground or this PR should have been split. push back via the review body rather than expanding lens count. + **lens-add discipline.** Each lens needs to clear a specific bar before you dispatch it: name the concrete failure mode this lens would catch *that the diff plausibly introduces*, in one sentence. "Could apply", "good to have", "for completeness" do not qualify. If you can't name what the lens is going to find, drop it. The "when unsure, treat as non-trivial" rule above is for the trivial-vs-non-trivial gate at step 3 — it does not license expanding lens count without articulated risk. Every extra lens adds wall-time, log noise, and pulls subagent attention onto speculative angles, which biases the final review toward bloat-shaped findings. + lenses come in two flavors, and you can mix them: - **themed lenses** — a perspective applied across the whole diff (correctness, security, user-journey, performance, etc.). - **subsystem lenses** — a domain-scoped frame for high-stakes subsystems the PR touches (e.g. "the auth lens", "the billing lens", "the schema-migration lens"). a subsystem lens is "review the PR specifically for what could go wrong in this subsystem" and naturally combines theme + scope. **for high-stakes domains, lead with the subsystem lens rather than the generic themed equivalent** — "billing-subsystem" outperforms "correctness on billing code" because the framing primes the subagent to remember domain-specific failure modes (double-charges, refund races, currency rounding, dispute flows) the generic lens misses. @@ -214,7 +216,7 @@ For simple, well-defined tasks, skip the plan phase and go straight to build.`, starter menu (combine, omit, or invent your own): - **correctness & invariants** — bugs, races, error handling, edge cases, state-machine boundaries - **impact** — when the PR removes features, deletes exports, renames identifiers, or changes architectural patterns: stale references in code, tests, docs (\`docs/\`, \`wiki/\`), comments, configs, UI - - **research-validated assumptions** — third-party API contracts, SDK semantics, framework directives, version-gated behavior. the subagent must verify load-bearing claims via web search and quote source URLs. + - **research-validated assumptions** — third-party API contracts, SDK semantics, framework directives, version-gated behavior. **only pick when the PR's correctness depends on the contract behaving a specific way** — not when the API is merely used. An idempotency key as a backstop, a timeout as a hint, a retry as belt-and-suspenders: not load-bearing, skip this lens. The bar is "if the third-party contract differs from what the diff assumes, the PR is incorrect." When dispatched, the subagent must verify load-bearing claims via web search and quote source URLs. - **security** — new endpoints, authZ, input validation, secrets handling, replay/CSRF/injection, cross-tenant isolation - **user-journey** — UX-touching flows: walk through happy path and failure modes as a user - **operational readiness** — observability, alerting, migrations (forward + rollback), feature flags, on-call burden @@ -304,7 +306,7 @@ ${PR_SUMMARY_FORMAT}`, "Looks trivial but isn't" (do NOT skip — same anti-patterns as Review mode): 1-line changes to SQL/regex/auth/billing/permissions/signature-verification code; flipping feature-flag defaults or retry/timeout constants; money/tax/HTTP-method/redirect changes; tightening or loosening a comparison operator; mixed diffs with a semantic line buried in formatting. When unsure, treat as non-trivial. - otherwise pick lenses by where the new commits concentrate risk — **there's no fixed count**, same calibration as Review mode (1 lens for pure refactor / isolated fix; 2–3 for typical features; 4–5 for high-stakes subsystem touches; 6+ is a smell). lens framing follows Review mode: themed lenses (correctness & invariants, impact when new commits remove/rename/deprecate things, research-validated assumptions, security, user-journey, operational readiness, integration & cross-cutting, test integrity, performance, holistic) and subsystem lenses (auth, billing, schema migration, etc.) — for high-stakes domains lead with the subsystem lens rather than the generic themed equivalent. + otherwise pick lenses by where the new commits concentrate risk — **there's no fixed count**, same calibration as Review mode (1 lens for pure refactor / isolated fix; 2–3 for typical features; 4–5 for high-stakes subsystem touches; 6+ is a smell). same **lens-add discipline** as Review mode applies: each lens needs to name the concrete failure mode it would catch *that the new commits plausibly introduce* — "could apply" doesn't qualify, drop it. **research-validated assumptions** specifically: only pick when the new commits' correctness depends on a third-party contract behaving a specific way; merely using an API doesn't qualify. lens framing follows Review mode: themed lenses (correctness & invariants, impact when new commits remove/rename/deprecate things, research-validated assumptions, security, user-journey, operational readiness, integration & cross-cutting, test integrity, performance, holistic) and subsystem lenses (auth, billing, schema migration, etc.) — for high-stakes domains lead with the subsystem lens rather than the generic themed equivalent. dispatch one \`${REVIEWER_AGENT_NAME}\` subagent per lens — its baked-in system prompt enforces the non-mutative + non-recursive contract (read-only file/search/web tools and read-only MCP queries; no writes, shell side effects, state-changing MCP calls, or nested subagent dispatch). dispatch them in a **single assistant turn with multiple parallel subagent calls** (serial dispatch collapses the fan-out). if a subagent errors out, times out, or returns nothing usable, retry once with the same lens; if it still fails, proceed with partial coverage and note the missing lens in the review body — do not skip step 5 entirely on a single subagent failure. each subagent gets: - the diff scope (incremental diff path if available, full diff otherwise). do NOT tell them to skip pre-existing issues — that suppresses regressions the new commits amplified; the "issues must be NEW" filter lives at aggregation time (step 6), not in the subagent prompt diff --git a/utils/timer.test.ts b/utils/timer.test.ts index f8519a7..595ea9a 100644 --- a/utils/timer.test.ts +++ b/utils/timer.test.ts @@ -203,5 +203,18 @@ describe("ThinkingTimer", () => { expect(cli.log.info).toHaveBeenNthCalledWith(1, "» thought for 4 seconds"); expect(cli.log.info).toHaveBeenNthCalledWith(2, "» thought for 5 seconds"); }); + + it("routes log lines through the optional formatLine for per-session prefixing", () => { + const startTime = 1000000; + vi.mocked(performance.now) + .mockReturnValueOnce(startTime) // markToolResult + .mockReturnValueOnce(startTime + 4000); // markToolCall + + const timer = new ThinkingTimer((line) => `[lens:security] ${line}`); + timer.markToolResult(); + timer.markToolCall(); + + expect(cli.log.info).toHaveBeenCalledWith("[lens:security] » thought for 4 seconds"); + }); }); }); diff --git a/utils/timer.ts b/utils/timer.ts index c13e96b..e3fec80 100644 --- a/utils/timer.ts +++ b/utils/timer.ts @@ -22,6 +22,15 @@ export class Timer { const THINKING_THRESHOLD = 3000; // ms +/** + * Measures wall-clock gap between the last tool_result and the next tool_call, + * surfacing it as a "thought for Xs" log when over `THINKING_THRESHOLD`. + * + * Use one instance per logical session (orchestrator, each subagent) — sharing + * a single timer across sessions conflates cross-session interleaving as + * thinking time. The optional `formatLine` lets the caller prefix output with + * a session label so attribution is visible in the merged log stream. + */ export class ThinkingTimer { private readonly durationFormatter = new Intl.NumberFormat("en-US", { style: "unit", @@ -32,21 +41,32 @@ export class ThinkingTimer { }); private lastToolResultTimestamp: number | null = null; + private readonly formatLine: (line: string) => string; + + // node's native TS strip-only mode does not support parameter properties, + // so the formatter is declared as a field and assigned in the body. + constructor(formatLine: (line: string) => string = (l) => l) { + this.formatLine = formatLine; + } markToolResult(): void { this.lastToolResultTimestamp = performance.now(); - log.debug(`» thinking timer: markToolResult at ${this.lastToolResultTimestamp}`); + log.debug( + this.formatLine(`» thinking timer: markToolResult at ${this.lastToolResultTimestamp}`) + ); } markToolCall(): void { const now = performance.now(); log.debug( - `» thinking timer: markToolCall at ${now}, lastToolResult=${this.lastToolResultTimestamp}` + this.formatLine( + `» thinking timer: markToolCall at ${now}, lastToolResult=${this.lastToolResultTimestamp}` + ) ); if (this.lastToolResultTimestamp === null) return; const elapsed = now - this.lastToolResultTimestamp; if (elapsed < THINKING_THRESHOLD) return; const seconds = elapsed / 1000; - log.info(`» thought for ${this.durationFormatter.format(seconds)}`); + log.info(this.formatLine(`» thought for ${this.durationFormatter.format(seconds)}`)); } }