diff --git a/CHANGELOG.md b/CHANGELOG.md index 0c7b06af9..d7c079912 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -19,6 +19,7 @@ - Thinking: default to low for reasoning-capable models when no /think or config default is set. - Logging: decouple file log levels from console verbosity; verbose-only details are captured when `logging.level` is debug/trace. - Build: fix regex literal in tool-meta path detection (watch build error). +- Auto-reply: add run-level telemetry + typing TTL guardrails to diagnose stuck replies. ### Docs - Skills: add Sheets/Docs examples to gog skill (#128) — thanks @mbelinky. diff --git a/src/agents/pi-embedded-runner.ts b/src/agents/pi-embedded-runner.ts index 1fa5e83e0..164a27343 100644 --- a/src/agents/pi-embedded-runner.ts +++ b/src/agents/pi-embedded-runner.ts @@ -25,12 +25,14 @@ import { import type { ThinkLevel, VerboseLevel } from "../auto-reply/thinking.js"; import { formatToolAggregate } from "../auto-reply/tool-meta.js"; import type { ClawdisConfig } from "../config/config.js"; +import { logVerbose } from "../globals.js"; import { getMachineDisplayName } from "../infra/machine-name.js"; import { splitMediaFromOutput } from "../media/parse.js"; import { type enqueueCommand, enqueueCommandInLane, } from "../process/command-queue.js"; +import { defaultRuntime } from "../runtime.js"; import { CONFIG_DIR, resolveUserPath } from "../utils.js"; import { resolveClawdisAgentDir } from "./agent-paths.js"; import { DEFAULT_MODEL, DEFAULT_PROVIDER } from "./defaults.js"; @@ -376,12 +378,16 @@ export async function runEmbeddedPiAgent(params: { const apiKey = await getApiKeyForModel(model, authStorage); authStorage.setRuntimeApiKey(model.provider, apiKey); - const thinkingLevel = mapThinkingLevel(params.thinkLevel); + const thinkingLevel = mapThinkingLevel(params.thinkLevel); - await fs.mkdir(resolvedWorkspace, { recursive: true }); - await ensureSessionHeader({ - sessionFile: params.sessionFile, - sessionId: params.sessionId, + logVerbose( + `embedded run start: runId=${params.runId} sessionId=${params.sessionId} provider=${provider} model=${modelId} surface=${params.surface ?? "unknown"}`, + ); + + await fs.mkdir(resolvedWorkspace, { recursive: true }); + await ensureSessionHeader({ + sessionFile: params.sessionFile, + sessionId: params.sessionId, cwd: resolvedWorkspace, }); @@ -503,12 +509,21 @@ export async function runEmbeddedPiAgent(params: { enforceFinalTag: params.enforceFinalTag, }); - const abortTimer = setTimeout( - () => { - abortRun(); - }, - Math.max(1, params.timeoutMs), - ); + let abortWarnTimer: NodeJS.Timeout | undefined; + const abortTimer = setTimeout(() => { + defaultRuntime.warn?.( + `embedded run timeout: runId=${params.runId} sessionId=${params.sessionId} timeoutMs=${params.timeoutMs}`, + ); + abortRun(); + if (!abortWarnTimer) { + abortWarnTimer = setTimeout(() => { + if (!session.isStreaming) return; + defaultRuntime.warn?.( + `embedded run abort still streaming: runId=${params.runId} sessionId=${params.sessionId}`, + ); + }, 10_000); + } + }, Math.max(1, params.timeoutMs)); let messagesSnapshot: AgentMessage[] = []; let sessionIdUsed = session.sessionId; @@ -526,16 +541,28 @@ export async function runEmbeddedPiAgent(params: { } let promptError: unknown = null; try { + const promptStartedAt = Date.now(); + logVerbose( + `embedded run prompt start: runId=${params.runId} sessionId=${params.sessionId}`, + ); try { await session.prompt(params.prompt); } catch (err) { promptError = err; + } finally { + logVerbose( + `embedded run prompt end: runId=${params.runId} sessionId=${params.sessionId} durationMs=${Date.now() - promptStartedAt}`, + ); } await waitForCompactionRetry(); messagesSnapshot = session.messages.slice(); sessionIdUsed = session.sessionId; } finally { clearTimeout(abortTimer); + if (abortWarnTimer) { + clearTimeout(abortWarnTimer); + abortWarnTimer = undefined; + } unsubscribe(); flushToolDebouncer(); if (ACTIVE_EMBEDDED_RUNS.get(params.sessionId) === queueHandle) { @@ -613,6 +640,9 @@ export async function runEmbeddedPiAgent(params: { p.text || p.mediaUrl || (p.mediaUrls && p.mediaUrls.length > 0), ); + logVerbose( + `embedded run done: runId=${params.runId} sessionId=${params.sessionId} durationMs=${Date.now() - started} aborted=${aborted}`, + ); return { payloads: payloads.length ? payloads : undefined, meta: { diff --git a/src/agents/pi-embedded-subscribe.ts b/src/agents/pi-embedded-subscribe.ts index 7554f02f4..539a48b22 100644 --- a/src/agents/pi-embedded-subscribe.ts +++ b/src/agents/pi-embedded-subscribe.ts @@ -12,6 +12,7 @@ import { extractAssistantText, inferToolMetaFromArgs, } from "./pi-embedded-utils.js"; +import { logVerbose } from "../globals.js"; const THINKING_TAG_RE = /<\s*\/?\s*think(?:ing)?\s*>/gi; const THINKING_OPEN_RE = /<\s*think(?:ing)?\s*>/i; @@ -200,6 +201,9 @@ export function subscribeEmbeddedPiSession(params: { const args = (evt as AgentEvent & { args: unknown }).args; const meta = inferToolMetaFromArgs(toolName, args); toolMetaById.set(toolCallId, meta); + logVerbose( + `embedded run tool start: runId=${params.runId} tool=${toolName} toolCallId=${toolCallId}`, + ); emitAgentEvent({ runId: params.runId, @@ -440,9 +444,26 @@ export function subscribeEmbeddedPiSession(params: { } } + if (evt.type === "tool_execution_end") { + const toolName = String( + (evt as AgentEvent & { toolName: string }).toolName, + ); + const toolCallId = String( + (evt as AgentEvent & { toolCallId: string }).toolCallId, + ); + logVerbose( + `embedded run tool end: runId=${params.runId} tool=${toolName} toolCallId=${toolCallId}`, + ); + } + + if (evt.type === "agent_start") { + logVerbose(`embedded run agent start: runId=${params.runId}`); + } + if (evt.type === "auto_compaction_start") { compactionInFlight = true; ensureCompactionPromise(); + logVerbose(`embedded run compaction start: runId=${params.runId}`); } if (evt.type === "auto_compaction_end") { @@ -451,12 +472,14 @@ export function subscribeEmbeddedPiSession(params: { if (willRetry) { noteCompactionRetry(); resetForCompactionRetry(); + logVerbose(`embedded run compaction retry: runId=${params.runId}`); } else { maybeResolveCompactionWait(); } } if (evt.type === "agent_end") { + logVerbose(`embedded run agent end: runId=${params.runId}`); toolDebouncer.flush(); if (pendingCompactionRetry > 0) { resolveCompactionRetry(); diff --git a/src/auto-reply/reply.ts b/src/auto-reply/reply.ts index 619590584..dda1eb09b 100644 --- a/src/auto-reply/reply.ts +++ b/src/auto-reply/reply.ts @@ -782,17 +782,41 @@ export async function getReplyFromConfig( const typingIntervalSeconds = typeof configuredTypingSeconds === "number" ? configuredTypingSeconds : 6; const typingIntervalMs = typingIntervalSeconds * 1000; + const typingTtlMs = Math.min( + Math.max(15_000, typingIntervalMs * 5), + 60_000, + ); const cleanupTyping = () => { + if (typingTtlTimer) { + clearTimeout(typingTtlTimer); + typingTtlTimer = undefined; + } if (typingTimer) { clearInterval(typingTimer); typingTimer = undefined; } }; + let typingTtlTimer: NodeJS.Timeout | undefined; + const refreshTypingTtl = () => { + if (!typingIntervalMs || typingIntervalMs <= 0) return; + if (typingTtlMs <= 0) return; + if (typingTtlTimer) { + clearTimeout(typingTtlTimer); + } + typingTtlTimer = setTimeout(() => { + if (!typingTimer) return; + defaultRuntime.warn?.( + `typing TTL reached (${typingTtlMs}ms); stopping typing indicator`, + ); + cleanupTyping(); + }, typingTtlMs); + }; const startTypingLoop = async () => { if (!opts?.onReplyStart) return; if (typingIntervalMs <= 0) return; if (typingTimer) return; await onReplyStart(); + refreshTypingTtl(); typingTimer = setInterval(() => { void triggerTyping(); }, typingIntervalMs); @@ -801,6 +825,7 @@ export async function getReplyFromConfig( const trimmed = text?.trim(); if (!trimmed) return; if (trimmed === SILENT_REPLY_TOKEN) return; + refreshTypingTtl(); await startTypingLoop(); }; let transcribedText: string | undefined;