diff --git a/agents/claude.ts b/agents/claude.ts index 143da23..f5a8fa0 100644 --- a/agents/claude.ts +++ b/agents/claude.ts @@ -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(); + 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 = ( data: Extract, - bashToolIds: Set + bashToolIds: Set, + thinkingTimer: ThinkingTimer ) => void | Promise; 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); diff --git a/agents/codex.ts b/agents/codex.ts index 718ffca..c66163c 100644 --- a/agents/codex.ts +++ b/agents/codex.ts @@ -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(); + 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 = ( event: Extract, - commandExecutionIds: Set + commandExecutionIds: Set, + thinkingTimer: ThinkingTimer ) => void | Promise; 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) { diff --git a/agents/cursor.ts b/agents/cursor.ts index 6ae2060..9f858c1 100644 --- a/agents/cursor.ts +++ b/agents/cursor.ts @@ -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(); + 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) { diff --git a/agents/gemini.ts b/agents/gemini.ts index ba62a3d..bc8e466 100644 --- a/agents/gemini.ts +++ b/agents/gemini.ts @@ -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 diff --git a/agents/opencode.ts b/agents/opencode.ts index 17d6b99..1d7493b 100644 --- a/agents/opencode.ts +++ b/agents/opencode.ts @@ -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 { @@ -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) { diff --git a/entry b/entry index 834939e..dca7efa 100755 --- a/entry +++ b/entry @@ -135752,7 +135752,7 @@ var log = { toolCall: ({ toolName, input }) => { const inputFormatted = formatJsonValue(input); const timestamp = isDebugEnabled() ? ` [${(/* @__PURE__ */ new Date()).toISOString()}]` : ""; - const output = inputFormatted !== "{}" ? `\u2192 ${toolName}(${inputFormatted})${timestamp}` : `\u2192 ${toolName}()${timestamp}`; + const output = inputFormatted !== "{}" ? `\xBB ${toolName}(${inputFormatted})${timestamp}` : `\xBB ${toolName}()${timestamp}`; log.info(output.trimEnd()); } }; @@ -140257,7 +140257,7 @@ function detectSandboxMethod() { }); if (result.status === 0) { detectedSandboxMethod = "unshare"; - log.info("PID namespace isolation enabled (unprivileged unshare)"); + log.debug("PID namespace isolation enabled (unprivileged unshare)"); return "unshare"; } } catch { @@ -140269,7 +140269,7 @@ function detectSandboxMethod() { }); if (result.status === 0) { detectedSandboxMethod = "sudo-unshare"; - log.info("PID namespace isolation enabled (sudo unshare)"); + log.debug("PID namespace isolation enabled (sudo unshare)"); return "sudo-unshare"; } } catch { @@ -144200,6 +144200,45 @@ async function installFromCurl(params) { return cliPath; } +// utils/timer.ts +var Timer = class { + initialTimestamp; + lastCheckpointTimestamp = null; + constructor() { + this.initialTimestamp = Date.now(); + } + checkpoint(name) { + const now = Date.now(); + const duration4 = this.lastCheckpointTimestamp ? now - this.lastCheckpointTimestamp : now - this.initialTimestamp; + log.debug(`\xBB ${name}: ${duration4}ms`); + this.lastCheckpointTimestamp = now; + } +}; +var THINKING_THRESHOLD = 3e3; +var ThinkingTimer = class { + durationFormatter = new Intl.NumberFormat("en-US", { + style: "unit", + unit: "second", + unitDisplay: "long", + minimumFractionDigits: 0, + maximumFractionDigits: 1 + }); + lastToolResultTimestamp = null; + markToolResult() { + this.lastToolResultTimestamp = Date.now(); + log.debug(`\xBB thinking timer: markToolResult at ${this.lastToolResultTimestamp}`); + } + markToolCall() { + const now = Date.now(); + log.debug(`\xBB 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 / 1e3; + log.info(`\xBB thought for ${this.durationFormatter.format(seconds)}`); + } +}; + // agents/shared.ts var agent = (input) => { return { @@ -144297,6 +144336,7 @@ var claude = agent({ let stdoutBuffer = ""; let finalOutput2 = ""; const bashToolIds = /* @__PURE__ */ new Set(); + const thinkingTimer = new ThinkingTimer(); const result = await spawn2({ cmd: "node", args: args3, @@ -144317,7 +144357,7 @@ var claude = agent({ log.debug(JSON.stringify(message, null, 2)); const handler2 = messageHandlers[message.type]; if (handler2) { - await handler2(message, bashToolIds); + await handler2(message, bashToolIds, thinkingTimer); } } catch { log.debug(`[claude] non-JSON stdout line: ${trimmed.substring(0, 200)}`); @@ -144350,7 +144390,7 @@ var claude = agent({ } }); var messageHandlers = { - 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()) { @@ -144359,6 +144399,7 @@ var messageHandlers = { if (content.name === "bash" && content.id) { bashToolIds.add(content.id); } + thinkingTimer.markToolCall(); log.toolCall({ toolName: content.name, input: content.input @@ -144367,10 +144408,11 @@ var messageHandlers = { } } }, - 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.tool_use_id; const isBashTool = toolUseId && bashToolIds.has(toolUseId); const outputContent = typeof content.content === "string" ? content.content : Array.isArray(content.content) ? content.content.map((c) => typeof c === "string" ? c : c.text || JSON.stringify(c)).join("\n") : String(content.content); @@ -144525,6 +144567,7 @@ var codex = agent({ let stdoutBuffer = ""; let finalOutput2 = ""; const commandExecutionIds = /* @__PURE__ */ new Set(); + const thinkingTimer = new ThinkingTimer(); const env3 = { ...process.env, CODEX_HOME: codexDir, @@ -144550,7 +144593,7 @@ var codex = agent({ log.debug(JSON.stringify(event, null, 2)); const handler2 = messageHandlers2[event.type]; if (handler2) { - await handler2(event, commandExecutionIds); + await handler2(event, commandExecutionIds, thinkingTimer); } } catch { log.debug(`[codex] non-JSON stdout line: ${trimmed.substring(0, 200)}`); @@ -144604,16 +144647,18 @@ var messageHandlers2 = { "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.args || {} }); } else if (item.type === "agent_message") { } else if (item.type === "mcp_tool_call") { + thinkingTimer.markToolCall(); log.toolCall({ toolName: item.tool, input: { @@ -144630,13 +144675,14 @@ var messageHandlers2 = { } } }, - "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 !== void 0 && item.exit_code !== 0) { log.warning(item.aggregated_output || "Command failed"); @@ -144647,6 +144693,7 @@ var messageHandlers2 = { 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.output) { @@ -144716,6 +144763,7 @@ var cursor = agent({ log.info(`\xBB using default model, effort=${ctx.payload.effort}`); } const loggedModelCallIds = /* @__PURE__ */ new Set(); + const thinkingTimer = new ThinkingTimer(); const messageHandlers5 = { system: (_event) => { }, @@ -144739,6 +144787,7 @@ var cursor = agent({ if (event.subtype === "started") { const mcpToolCall = event.tool_call?.mcpToolCall; const builtinToolCall = event.tool_call?.builtinToolCall; + thinkingTimer.markToolCall(); if (mcpToolCall?.args?.toolName && mcpToolCall?.args?.args) { log.toolCall({ toolName: mcpToolCall.args.toolName, @@ -144751,6 +144800,7 @@ var cursor = agent({ }); } } else if (event.subtype === "completed") { + thinkingTimer.markToolResult(); const result = event.tool_call?.mcpToolCall?.result?.success; const isError = result?.isError; if (isError) { @@ -144940,17 +144990,19 @@ var messageHandlers3 = { assistantMessageBuffer = ""; } }, - tool_use: (event) => { + tool_use: (event, 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) => { + tool_result: (event, 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); log.warning(`Tool call failed: ${errorMsg}`); @@ -145016,6 +145068,7 @@ var gemini = agent({ ]; let finalOutput2 = ""; let stdoutBuffer = ""; + const thinkingTimer = new ThinkingTimer(); try { const result = await spawn2({ cmd: "node", @@ -145036,7 +145089,7 @@ var gemini = agent({ markActivity(); const handler2 = messageHandlers3[event.type]; if (handler2) { - await handler2(event); + await handler2(event, thinkingTimer); } } catch { log.debug(`[gemini] non-JSON stdout line: ${trimmed.substring(0, 200)}`); @@ -145164,6 +145217,7 @@ var opencode = agent({ log.debug(`\xBB XDG_CONFIG_HOME: ${env3.XDG_CONFIG_HOME}`); const startTime = Date.now(); let eventCount = 0; + const thinkingTimer = new ThinkingTimer(); let output = ""; let stdoutBuffer = ""; const result = await spawn2({ @@ -145200,7 +145254,7 @@ var opencode = agent({ markActivity(); const handler2 = messageHandlers4[event.type]; if (handler2) { - await handler2(event); + await handler2(event, thinkingTimer); } else { log.info( `\xBB OpenCode event (unhandled): type=${event.type}, data=${JSON.stringify(event).substring(0, 500)}` @@ -145354,7 +145408,7 @@ var messageHandlers4 = { currentStepType = null; } }, - tool_use: (event) => { + tool_use: (event, thinkingTimer) => { const toolName = event.part?.tool; const toolId = event.part?.callID; const parameters = event.part?.state?.input; @@ -145367,6 +145421,7 @@ var messageHandlers4 = { if (stepHistory.length > 0) { stepHistory[stepHistory.length - 1].toolCalls.push(toolName); } + thinkingTimer.markToolCall(); log.toolCall({ toolName, input: parameters || {} @@ -145376,10 +145431,11 @@ var messageHandlers4 = { } } }, - tool_result: (event) => { + tool_result: (event, thinkingTimer) => { 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) { @@ -146266,7 +146322,6 @@ async function setupGit(params) { `Failed to set git config: ${error49 instanceof Error ? error49.message : String(error49)}` ); } - log.info("\xBB setting up git authentication..."); try { execSync3("git config --local --unset-all http.https://github.com/.extraheader", { cwd: repoDir, @@ -146276,6 +146331,24 @@ async function setupGit(params) { } catch { log.debug("\xBB no existing authentication headers to remove"); } + try { + const configOutput = execSync3("git config --local --get-regexp ^includeif\\.", { + cwd: repoDir, + encoding: "utf-8", + stdio: "pipe" + }); + for (const line of configOutput.trim().split("\n")) { + const key = line.split(" ")[0]; + if (!key) continue; + execSync3(`git config --local --unset "${key}"`, { + cwd: repoDir, + stdio: "pipe" + }); + } + log.info("\xBB removed includeIf credential entries"); + } catch { + log.debug("\xBB no includeIf credential entries to remove"); + } const originUrl = `https://github.com/${params.owner}/${params.name}.git`; $("git", ["remote", "set-url", "origin", originUrl], { cwd: repoDir }); params.toolState.pushUrl = originUrl; @@ -146300,21 +146373,6 @@ function parseTimeString(input) { return (hours * 3600 + minutes * 60 + seconds) * 1e3; } -// utils/timer.ts -var Timer = class { - initialTimestamp; - lastCheckpointTimestamp = null; - constructor() { - this.initialTimestamp = Date.now(); - } - checkpoint(name) { - const now = Date.now(); - const duration4 = this.lastCheckpointTimestamp ? now - this.lastCheckpointTimestamp : now - this.initialTimestamp; - log.debug(`\xBB ${name}: ${duration4}ms`); - this.lastCheckpointTimestamp = now; - } -}; - // utils/workflow.ts async function resolveRun(params) { const runId = process.env.GITHUB_RUN_ID || ""; diff --git a/get-installation-token/entry b/get-installation-token/entry index 0a481d8..9484c95 100755 --- a/get-installation-token/entry +++ b/get-installation-token/entry @@ -25665,7 +25665,7 @@ var log = { toolCall: ({ toolName, input }) => { const inputFormatted = formatJsonValue(input); const timestamp = isDebugEnabled() ? ` [${(/* @__PURE__ */ new Date()).toISOString()}]` : ""; - const output = inputFormatted !== "{}" ? `\u2192 ${toolName}(${inputFormatted})${timestamp}` : `\u2192 ${toolName}()${timestamp}`; + const output = inputFormatted !== "{}" ? `\xBB ${toolName}(${inputFormatted})${timestamp}` : `\xBB ${toolName}()${timestamp}`; log.info(output.trimEnd()); } }; diff --git a/mcp/bash.ts b/mcp/bash.ts index 1eb613d..b7a5e82 100644 --- a/mcp/bash.ts +++ b/mcp/bash.ts @@ -55,7 +55,7 @@ function detectSandboxMethod(): SandboxMethod { }); if (result.status === 0) { detectedSandboxMethod = "unshare"; - log.info("PID namespace isolation enabled (unprivileged unshare)"); + log.debug("PID namespace isolation enabled (unprivileged unshare)"); return "unshare"; } } catch { @@ -70,7 +70,7 @@ function detectSandboxMethod(): SandboxMethod { }); if (result.status === 0) { detectedSandboxMethod = "sudo-unshare"; - log.info("PID namespace isolation enabled (sudo unshare)"); + log.debug("PID namespace isolation enabled (sudo unshare)"); return "sudo-unshare"; } } catch { diff --git a/post b/post index 734c2f4..eeee004 100755 --- a/post +++ b/post @@ -41133,7 +41133,7 @@ var log = { toolCall: ({ toolName, input }) => { const inputFormatted = formatJsonValue(input); const timestamp = isDebugEnabled() ? ` [${(/* @__PURE__ */ new Date()).toISOString()}]` : ""; - const output = inputFormatted !== "{}" ? `\u2192 ${toolName}(${inputFormatted})${timestamp}` : `\u2192 ${toolName}()${timestamp}`; + const output = inputFormatted !== "{}" ? `\xBB ${toolName}(${inputFormatted})${timestamp}` : `\xBB ${toolName}()${timestamp}`; log.info(output.trimEnd()); } }; diff --git a/utils/log.ts b/utils/log.ts index 2389a52..21bd424 100644 --- a/utils/log.ts +++ b/utils/log.ts @@ -261,8 +261,8 @@ export const log = { const timestamp = isDebugEnabled() ? ` [${new Date().toISOString()}]` : ""; const output = inputFormatted !== "{}" - ? `→ ${toolName}(${inputFormatted})${timestamp}` - : `→ ${toolName}()${timestamp}`; + ? `» ${toolName}(${inputFormatted})${timestamp}` + : `» ${toolName}()${timestamp}`; log.info(output.trimEnd()); }, diff --git a/utils/setup.ts b/utils/setup.ts index 069914c..abbb518 100644 --- a/utils/setup.ts +++ b/utils/setup.ts @@ -120,8 +120,6 @@ export async function setupGit(params: SetupGitParams): Promise { } // 2. setup authentication - log.info("» setting up git authentication..."); - // remove existing git auth headers that actions/checkout might have set try { execSync("git config --local --unset-all http.https://github.com/.extraheader", { @@ -133,6 +131,29 @@ export async function setupGit(params: SetupGitParams): Promise { log.debug("» no existing authentication headers to remove"); } + // remove includeIf entries that actions/checkout@v6 uses for credential persistence. + // v6 stores credentials in an external file loaded via includeIf.gitdir, which our + // --unset-all above doesn't catch. without this, $git() would produce duplicate + // Authorization headers (one from includeIf, one from GIT_CONFIG_PARAMETERS). + try { + const configOutput = execSync("git config --local --get-regexp ^includeif\\.", { + cwd: repoDir, + encoding: "utf-8", + stdio: "pipe", + }); + for (const line of configOutput.trim().split("\n")) { + const key = line.split(" ")[0]; + if (!key) continue; + execSync(`git config --local --unset "${key}"`, { + cwd: repoDir, + stdio: "pipe", + }); + } + log.info("» removed includeIf credential entries"); + } catch { + log.debug("» no includeIf credential entries to remove"); + } + // SECURITY: set origin URL without token - auth is injected via GIT_CONFIG_PARAMETERS // in $git() calls. this prevents token leakage to git hooks and subprocesses. const originUrl = `https://github.com/${params.owner}/${params.name}.git`; diff --git a/utils/timer.test.ts b/utils/timer.test.ts index 12a3881..42a1ec2 100644 --- a/utils/timer.test.ts +++ b/utils/timer.test.ts @@ -1,5 +1,5 @@ import * as cli from "./cli.ts"; -import { Timer } from "./timer.ts"; +import { ThinkingTimer, Timer } from "./timer.ts"; describe("Timer", () => { beforeEach(() => { @@ -104,3 +104,109 @@ describe("Timer", () => { }); }); }); + +describe("ThinkingTimer", () => { + beforeEach(() => { + vi.spyOn(cli.log, "info"); + vi.useFakeTimers(); + }); + + afterEach(() => { + vi.restoreAllMocks(); + vi.useRealTimers(); + }); + + describe("markToolResult", () => { + it("should store the current timestamp", () => { + const startTime = 1000000; + vi.setSystemTime(startTime); + + const timer = new ThinkingTimer(); + timer.markToolResult(); + + vi.setSystemTime(startTime + 5000); + timer.markToolCall(); + + expect(cli.log.info).toHaveBeenCalled(); + }); + }); + + describe("markToolCall", () => { + it("should not log if markToolResult was never called", () => { + const timer = new ThinkingTimer(); + timer.markToolCall(); + + expect(cli.log.info).not.toHaveBeenCalled(); + }); + + it("should not log if elapsed time is below threshold (3000ms)", () => { + const startTime = 1000000; + vi.setSystemTime(startTime); + + const timer = new ThinkingTimer(); + timer.markToolResult(); + + vi.setSystemTime(startTime + 2999); + timer.markToolCall(); + + expect(cli.log.info).not.toHaveBeenCalled(); + }); + + it("should log if elapsed time equals threshold (3000ms)", () => { + const startTime = 1000000; + vi.setSystemTime(startTime); + + const timer = new ThinkingTimer(); + timer.markToolResult(); + + vi.setSystemTime(startTime + 3000); + timer.markToolCall(); + + expect(cli.log.info).toHaveBeenCalledWith("» thought for 3 seconds"); + }); + + it("should log if elapsed time exceeds threshold", () => { + const startTime = 1000000; + vi.setSystemTime(startTime); + + const timer = new ThinkingTimer(); + timer.markToolResult(); + + vi.setSystemTime(startTime + 5500); + timer.markToolCall(); + + expect(cli.log.info).toHaveBeenCalledWith("» thought for 5.5 seconds"); + }); + + it("should format large durations correctly", () => { + const startTime = 1000000; + vi.setSystemTime(startTime); + + const timer = new ThinkingTimer(); + timer.markToolResult(); + + vi.setSystemTime(startTime + 15000); + timer.markToolCall(); + + expect(cli.log.info).toHaveBeenCalledWith("» thought for 15 seconds"); + }); + + it("should handle multiple markToolCall invocations", () => { + const startTime = 1000000; + vi.setSystemTime(startTime); + + const timer = new ThinkingTimer(); + timer.markToolResult(); + + vi.setSystemTime(startTime + 4000); + timer.markToolCall(); + + vi.setSystemTime(startTime + 5000); + timer.markToolCall(); + + expect(cli.log.info).toHaveBeenCalledTimes(2); + expect(cli.log.info).toHaveBeenNthCalledWith(1, "» thought for 4 seconds"); + expect(cli.log.info).toHaveBeenNthCalledWith(2, "» thought for 5 seconds"); + }); + }); +}); diff --git a/utils/timer.ts b/utils/timer.ts index bdde14e..056a870 100644 --- a/utils/timer.ts +++ b/utils/timer.ts @@ -18,3 +18,32 @@ export class Timer { this.lastCheckpointTimestamp = now; } } + +const THINKING_THRESHOLD = 3000; // ms + +export class ThinkingTimer { + private readonly durationFormatter = new Intl.NumberFormat("en-US", { + style: "unit", + unit: "second", + unitDisplay: "long", + minimumFractionDigits: 0, + maximumFractionDigits: 1, + }); + + private lastToolResultTimestamp: number | null = null; + + markToolResult(): void { + this.lastToolResultTimestamp = Date.now(); + log.debug(`» thinking timer: markToolResult at ${this.lastToolResultTimestamp}`); + } + + markToolCall(): void { + const now = Date.now(); + log.debug(`» 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)}`); + } +}