feat(agents): add thinking time logging between tool calls (#244)
* feat(agents): add thinking time logging between tool calls Adds a ThinkingTimer utility that tracks the gap between tool results and the next tool call. When the gap exceeds 3 seconds, it logs the duration with a stopwatch emoji (⏱️ 4.2s). Uses performance.now() for high-resolution timing and Intl.NumberFormat for rendering duration in seconds with optional fraction digits. Integrated across all 5 agents: Claude, Codex, Cursor, Gemini, OpenCode. Closes #127 * fix: adjusting tests for mocking performance.now. * fix: reducing diff for claude. * fix: rm unused args for claude. * rm unused args for codex. * fix: rm unused args for gemini. * fix: rm unused args for opencode. * mv THINKING_THRESHOLD. * rev: I decided to pospone node:perf_hooks integration since it requires more comprehensive refactoring. * fix: using Intl unit formatting. * tests for ThinkingTimer. * fix: narrow unit. * fix: making durationFormatter a class instance property since using one agent per run. * fix: inverting condition in markToolCall. * thinking timer improvements and fix actions/checkout v6 auth - thinking timer: use » chevron and "thought for X seconds" format - thinking timer: add debug timestamps for sanity checking - demote PID namespace isolation logs to debug - remove redundant "setting up git authentication" log - fix duplicate Authorization header with actions/checkout v6: clean up includeIf credential entries that v6 persists via external config files Co-authored-by: Cursor <cursoragent@cursor.com> * standardize tool call log prefix to » double chevron Co-authored-by: Cursor <cursoragent@cursor.com> * update timer tests for new thinking log format Co-authored-by: Cursor <cursoragent@cursor.com> --------- Co-authored-by: pullfrog[bot] <226033991+pullfrog[bot]@users.noreply.github.com> Co-authored-by: Robin Tail <robin_tail@me.com> Co-authored-by: Colin McDonnell <colinmcd94@gmail.com> Co-authored-by: Cursor <cursoragent@cursor.com>
This commit is contained in:
pullfrog[bot]
committed by
pullfrog[bot]
pullfrog[bot]
parent
f67cc25f74
commit
fb80343ffd
+10
-4
@@ -11,6 +11,7 @@ import { markActivity } from "../utils/activity.ts";
|
||||
import { log } from "../utils/cli.ts";
|
||||
import { installFromNpmTarball } from "../utils/install.ts";
|
||||
import { spawn } from "../utils/subprocess.ts";
|
||||
import { ThinkingTimer } from "../utils/timer.ts";
|
||||
import { type AgentRunContext, agent } from "./shared.ts";
|
||||
|
||||
// model selection based on effort level
|
||||
@@ -119,6 +120,7 @@ export const claude = agent({
|
||||
|
||||
// Track bash tool IDs to identify when bash tool results come back
|
||||
const bashToolIds = new Set<string>();
|
||||
const thinkingTimer = new ThinkingTimer();
|
||||
|
||||
const result = await spawn({
|
||||
cmd: "node",
|
||||
@@ -147,7 +149,7 @@ export const claude = agent({
|
||||
|
||||
const handler = messageHandlers[message.type];
|
||||
if (handler) {
|
||||
await handler(message as never, bashToolIds);
|
||||
await handler(message as never, bashToolIds, thinkingTimer);
|
||||
}
|
||||
} catch {
|
||||
// ignore parse errors - might be non-JSON output
|
||||
@@ -192,7 +194,8 @@ type SDKMessageType = SDKMessage["type"];
|
||||
|
||||
type SDKMessageHandler<type extends SDKMessageType = SDKMessageType> = (
|
||||
data: Extract<SDKMessage, { type: type }>,
|
||||
bashToolIds: Set<string>
|
||||
bashToolIds: Set<string>,
|
||||
thinkingTimer: ThinkingTimer
|
||||
) => void | Promise<void>;
|
||||
|
||||
type SDKMessageHandlers = {
|
||||
@@ -200,7 +203,7 @@ type SDKMessageHandlers = {
|
||||
};
|
||||
|
||||
const messageHandlers: SDKMessageHandlers = {
|
||||
assistant: (data, bashToolIds) => {
|
||||
assistant: (data, bashToolIds, thinkingTimer) => {
|
||||
if (data.message?.content) {
|
||||
for (const content of data.message.content) {
|
||||
if (content.type === "text" && content.text?.trim()) {
|
||||
@@ -211,6 +214,7 @@ const messageHandlers: SDKMessageHandlers = {
|
||||
bashToolIds.add(content.id);
|
||||
}
|
||||
|
||||
thinkingTimer.markToolCall();
|
||||
log.toolCall({
|
||||
toolName: content.name,
|
||||
input: content.input,
|
||||
@@ -219,10 +223,12 @@ const messageHandlers: SDKMessageHandlers = {
|
||||
}
|
||||
}
|
||||
},
|
||||
user: (data, bashToolIds) => {
|
||||
user: (data, bashToolIds, thinkingTimer) => {
|
||||
if (data.message?.content) {
|
||||
for (const content of data.message.content) {
|
||||
if (content.type === "tool_result") {
|
||||
thinkingTimer.markToolResult();
|
||||
|
||||
const toolUseId = (content as any).tool_use_id;
|
||||
const isBashTool = toolUseId && bashToolIds.has(toolUseId);
|
||||
|
||||
|
||||
+11
-4
@@ -10,6 +10,7 @@ import { markActivity } from "../utils/activity.ts";
|
||||
import { log } from "../utils/cli.ts";
|
||||
import { installFromNpmTarball } from "../utils/install.ts";
|
||||
import { spawn } from "../utils/subprocess.ts";
|
||||
import { ThinkingTimer } from "../utils/timer.ts";
|
||||
import { type AgentRunContext, agent } from "./shared.ts";
|
||||
|
||||
// configuration based on effort level
|
||||
@@ -136,6 +137,7 @@ export const codex = agent({
|
||||
|
||||
// Track command execution IDs to identify when command results come back
|
||||
const commandExecutionIds = new Set<string>();
|
||||
const thinkingTimer = new ThinkingTimer();
|
||||
|
||||
const env: NodeJS.ProcessEnv = {
|
||||
...process.env,
|
||||
@@ -170,7 +172,7 @@ export const codex = agent({
|
||||
|
||||
const handler = messageHandlers[event.type as keyof typeof messageHandlers];
|
||||
if (handler) {
|
||||
await handler(event as never, commandExecutionIds);
|
||||
await handler(event as never, commandExecutionIds, thinkingTimer);
|
||||
}
|
||||
} catch {
|
||||
// ignore parse errors - might be non-JSON output
|
||||
@@ -210,7 +212,8 @@ export const codex = agent({
|
||||
|
||||
type ThreadEventHandler<type extends ThreadEvent["type"]> = (
|
||||
event: Extract<ThreadEvent, { type: type }>,
|
||||
commandExecutionIds: Set<string>
|
||||
commandExecutionIds: Set<string>,
|
||||
thinkingTimer: ThinkingTimer
|
||||
) => void | Promise<void>;
|
||||
|
||||
const messageHandlers: {
|
||||
@@ -239,10 +242,11 @@ const messageHandlers: {
|
||||
"turn.failed": (event) => {
|
||||
log.error(`Turn failed: ${event.error.message}`);
|
||||
},
|
||||
"item.started": (event, commandExecutionIds) => {
|
||||
"item.started": (event, commandExecutionIds, thinkingTimer) => {
|
||||
const item = event.item;
|
||||
if (item.type === "command_execution") {
|
||||
commandExecutionIds.add(item.id);
|
||||
thinkingTimer.markToolCall();
|
||||
log.toolCall({
|
||||
toolName: item.command,
|
||||
input: (item as any).args || {},
|
||||
@@ -250,6 +254,7 @@ const messageHandlers: {
|
||||
} else if (item.type === "agent_message") {
|
||||
// Will be handled on completion
|
||||
} else if (item.type === "mcp_tool_call") {
|
||||
thinkingTimer.markToolCall();
|
||||
log.toolCall({
|
||||
toolName: item.tool,
|
||||
input: {
|
||||
@@ -268,13 +273,14 @@ const messageHandlers: {
|
||||
}
|
||||
}
|
||||
},
|
||||
"item.completed": (event, commandExecutionIds) => {
|
||||
"item.completed": (event, commandExecutionIds, thinkingTimer) => {
|
||||
const item = event.item;
|
||||
if (item.type === "agent_message") {
|
||||
log.box(item.text.trim(), { title: "Codex" });
|
||||
} else if (item.type === "command_execution") {
|
||||
const isTracked = commandExecutionIds.has(item.id);
|
||||
if (isTracked) {
|
||||
thinkingTimer.markToolResult();
|
||||
log.startGroup(`bash output`);
|
||||
if (item.status === "failed" || (item.exit_code !== undefined && item.exit_code !== 0)) {
|
||||
log.warning(item.aggregated_output || "Command failed");
|
||||
@@ -285,6 +291,7 @@ const messageHandlers: {
|
||||
commandExecutionIds.delete(item.id);
|
||||
}
|
||||
} else if (item.type === "mcp_tool_call") {
|
||||
thinkingTimer.markToolResult();
|
||||
if (item.status === "failed" && item.error) {
|
||||
log.warning(`MCP tool call failed: ${item.error.message}`);
|
||||
} else if ((item as any).output) {
|
||||
|
||||
@@ -10,6 +10,7 @@ import { ghPullfrogMcpName } from "../external.ts";
|
||||
import { markActivity } from "../utils/activity.ts";
|
||||
import { log } from "../utils/cli.ts";
|
||||
import { installFromCurl } from "../utils/install.ts";
|
||||
import { ThinkingTimer } from "../utils/timer.ts";
|
||||
import { type AgentRunContext, agent } from "./shared.ts";
|
||||
|
||||
// effort configuration for Cursor
|
||||
@@ -144,6 +145,7 @@ export const cursor = agent({
|
||||
// track logged model_call_ids to avoid duplicates
|
||||
// cursor emits each assistant message twice: once without model_call_id, then again with it
|
||||
const loggedModelCallIds = new Set<string>();
|
||||
const thinkingTimer = new ThinkingTimer();
|
||||
|
||||
const messageHandlers = {
|
||||
system: (_event: CursorSystemEvent) => {
|
||||
@@ -182,6 +184,7 @@ export const cursor = agent({
|
||||
const mcpToolCall = event.tool_call?.mcpToolCall;
|
||||
const builtinToolCall = (event.tool_call as any)?.builtinToolCall;
|
||||
|
||||
thinkingTimer.markToolCall();
|
||||
if (mcpToolCall?.args?.toolName && mcpToolCall?.args?.args) {
|
||||
log.toolCall({
|
||||
toolName: mcpToolCall.args.toolName,
|
||||
@@ -194,6 +197,7 @@ export const cursor = agent({
|
||||
});
|
||||
}
|
||||
} else if (event.subtype === "completed") {
|
||||
thinkingTimer.markToolResult();
|
||||
const result = event.tool_call?.mcpToolCall?.result?.success;
|
||||
const isError = result?.isError;
|
||||
if (isError) {
|
||||
|
||||
+7
-3
@@ -10,6 +10,7 @@ import { markActivity } from "../utils/activity.ts";
|
||||
import { log } from "../utils/cli.ts";
|
||||
import { installFromGithub } from "../utils/install.ts";
|
||||
import { spawn } from "../utils/subprocess.ts";
|
||||
import { ThinkingTimer } from "../utils/timer.ts";
|
||||
import { getGitHubInstallationToken } from "../utils/token.ts";
|
||||
import { type AgentRunContext, agent } from "./shared.ts";
|
||||
|
||||
@@ -112,17 +113,19 @@ const messageHandlers = {
|
||||
assistantMessageBuffer = "";
|
||||
}
|
||||
},
|
||||
tool_use: (event: GeminiToolUseEvent) => {
|
||||
tool_use: (event: GeminiToolUseEvent, thinkingTimer: ThinkingTimer) => {
|
||||
log.debug(JSON.stringify(event, null, 2));
|
||||
if (event.tool_name) {
|
||||
thinkingTimer.markToolCall();
|
||||
log.toolCall({
|
||||
toolName: event.tool_name,
|
||||
input: event.parameters || {},
|
||||
});
|
||||
}
|
||||
},
|
||||
tool_result: (event: GeminiToolResultEvent) => {
|
||||
tool_result: (event: GeminiToolResultEvent, thinkingTimer: ThinkingTimer) => {
|
||||
log.debug(JSON.stringify(event, null, 2));
|
||||
thinkingTimer.markToolResult();
|
||||
if (event.status === "error") {
|
||||
const errorMsg =
|
||||
typeof event.output === "string" ? event.output : JSON.stringify(event.output);
|
||||
@@ -202,6 +205,7 @@ export const gemini = agent({
|
||||
|
||||
let finalOutput = "";
|
||||
let stdoutBuffer = "";
|
||||
const thinkingTimer = new ThinkingTimer();
|
||||
|
||||
try {
|
||||
const result = await spawn({
|
||||
@@ -230,7 +234,7 @@ export const gemini = agent({
|
||||
markActivity(); // reset activity timeout on every event
|
||||
const handler = messageHandlers[event.type as keyof typeof messageHandlers];
|
||||
if (handler) {
|
||||
await handler(event as never);
|
||||
await handler(event as never, thinkingTimer);
|
||||
}
|
||||
} catch {
|
||||
// ignore parse errors - might be non-JSON output from gemini cli
|
||||
|
||||
+8
-3
@@ -8,6 +8,7 @@ import { getIdleMs, markActivity } from "../utils/activity.ts";
|
||||
import { log } from "../utils/cli.ts";
|
||||
import { installFromNpmTarball } from "../utils/install.ts";
|
||||
import { spawn } from "../utils/subprocess.ts";
|
||||
import { ThinkingTimer } from "../utils/timer.ts";
|
||||
import { type AgentRunContext, agent } from "./shared.ts";
|
||||
|
||||
async function installOpencode(): Promise<string> {
|
||||
@@ -61,6 +62,7 @@ export const opencode = agent({
|
||||
|
||||
const startTime = Date.now();
|
||||
let eventCount = 0;
|
||||
const thinkingTimer = new ThinkingTimer();
|
||||
|
||||
let output = "";
|
||||
let stdoutBuffer = ""; // buffer for incomplete lines across chunks
|
||||
@@ -109,7 +111,7 @@ export const opencode = agent({
|
||||
markActivity(); // reset activity timeout on every event
|
||||
const handler = messageHandlers[event.type as keyof typeof messageHandlers];
|
||||
if (handler) {
|
||||
await handler(event as never);
|
||||
await handler(event as never, thinkingTimer);
|
||||
} else {
|
||||
// log unhandled event types for visibility
|
||||
log.info(
|
||||
@@ -441,7 +443,7 @@ const messageHandlers = {
|
||||
currentStepType = null;
|
||||
}
|
||||
},
|
||||
tool_use: (event: OpenCodeToolUseEvent) => {
|
||||
tool_use: (event: OpenCodeToolUseEvent, thinkingTimer: ThinkingTimer) => {
|
||||
const toolName = event.part?.tool;
|
||||
const toolId = event.part?.callID;
|
||||
const parameters = event.part?.state?.input;
|
||||
@@ -459,6 +461,7 @@ const messageHandlers = {
|
||||
stepHistory[stepHistory.length - 1].toolCalls.push(toolName);
|
||||
}
|
||||
|
||||
thinkingTimer.markToolCall();
|
||||
log.toolCall({
|
||||
toolName,
|
||||
input: parameters || {},
|
||||
@@ -470,12 +473,14 @@ const messageHandlers = {
|
||||
}
|
||||
}
|
||||
},
|
||||
tool_result: (event: OpenCodeToolResultEvent) => {
|
||||
tool_result: (event: OpenCodeToolResultEvent, thinkingTimer: ThinkingTimer) => {
|
||||
// handle both new part structure and legacy flat structure
|
||||
const toolId = event.part?.callID || event.tool_id;
|
||||
const status = event.part?.state?.status || event.status || "unknown";
|
||||
const output = event.part?.state?.output || event.output;
|
||||
|
||||
thinkingTimer.markToolResult();
|
||||
|
||||
if (toolId) {
|
||||
const toolStartTime = toolCallTimings.get(toolId);
|
||||
if (toolStartTime) {
|
||||
|
||||
Reference in New Issue
Block a user