fix: add embedded run logs and typing ttl

2026-01-03 14:09:19 +00:00
parent 4fcd89c3d9
commit 48731f494b
4 changed files with 90 additions and 11 deletions
--- 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.
--- 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: {
--- 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();
--- 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;