feat: add pre-prompt context size diagnostic logging (openclaw#8930) thanks @Glucksberg

Verified:
- pnpm build
- pnpm check
- pnpm test

Co-authored-by: Glucksberg <80581902+Glucksberg@users.noreply.github.com>
Co-authored-by: Tak Hoffman <781889+Takhoffman@users.noreply.github.com>

CHANGELOG.md

@@ -10,6 +10,7 @@ Docs: https://docs.openclaw.ai
 - Discord: send voice messages with waveform previews from local audio files (including silent delivery). (#7253) Thanks @nyanjou.
 - Discord: add configurable presence status/activity/type/url (custom status defaults to activity text). (#10855) Thanks @h0tp-ftw.
 - Slack/Plugins: add thread-ownership outbound gating via `message_sending` hooks, including @-mention bypass tracking and Slack outbound hook wiring for cancel/modify behavior. (#15775) Thanks @DarlingtonDeveloper.
+- Agents: add pre-prompt context diagnostics (`messages`, `systemPromptChars`, `promptChars`, provider/model, session file) before embedded runner prompt calls to improve overflow debugging. (#8930) Thanks @Glucksberg.
 
 ### Fixes
 

src/agents/pi-embedded-runner/compact.ts

@@ -1,3 +1,4 @@
+import type { AgentMessage } from "@mariozechner/pi-agent-core";
 import {
   createAgentSession,
   estimateTokens,
@@ -79,6 +80,7 @@ import { flushPendingToolResultsAfterIdle } from "./wait-for-idle-before-flush.j
 
 export type CompactEmbeddedPiSessionParams = {
   sessionId: string;
+  runId?: string;
   sessionKey?: string;
   messageChannel?: string;
   messageProvider?: string;
@@ -105,12 +107,132 @@ export type CompactEmbeddedPiSessionParams = {
   reasoningLevel?: ReasoningLevel;
   bashElevated?: ExecElevatedDefaults;
   customInstructions?: string;
+  trigger?: "overflow" | "manual" | "cache_ttl" | "safeguard";
+  diagId?: string;
+  attempt?: number;
+  maxAttempts?: number;
   lane?: string;
   enqueue?: typeof enqueueCommand;
   extraSystemPrompt?: string;
   ownerNumbers?: string[];
 };
 
+type CompactionMessageMetrics = {
+  messages: number;
+  historyTextChars: number;
+  toolResultChars: number;
+  estTokens?: number;
+  contributors: Array<{ role: string; chars: number; tool?: string }>;
+};
+
+function createCompactionDiagId(): string {
+  return `cmp-${Date.now().toString(36)}-${Math.random().toString(36).slice(2, 8)}`;
+}
+
+function getMessageTextChars(msg: AgentMessage): number {
+  const content = (msg as { content?: unknown }).content;
+  if (typeof content === "string") {
+    return content.length;
+  }
+  if (!Array.isArray(content)) {
+    return 0;
+  }
+  let total = 0;
+  for (const block of content) {
+    if (!block || typeof block !== "object") {
+      continue;
+    }
+    const text = (block as { text?: unknown }).text;
+    if (typeof text === "string") {
+      total += text.length;
+    }
+  }
+  return total;
+}
+
+function resolveMessageToolLabel(msg: AgentMessage): string | undefined {
+  const candidate =
+    (msg as { toolName?: unknown }).toolName ??
+    (msg as { name?: unknown }).name ??
+    (msg as { tool?: unknown }).tool;
+  return typeof candidate === "string" && candidate.trim().length > 0 ? candidate : undefined;
+}
+
+function summarizeCompactionMessages(messages: AgentMessage[]): CompactionMessageMetrics {
+  let historyTextChars = 0;
+  let toolResultChars = 0;
+  const contributors: Array<{ role: string; chars: number; tool?: string }> = [];
+  let estTokens = 0;
+  let tokenEstimationFailed = false;
+
+  for (const msg of messages) {
+    const role = typeof msg.role === "string" ? msg.role : "unknown";
+    const chars = getMessageTextChars(msg);
+    historyTextChars += chars;
+    if (role === "toolResult") {
+      toolResultChars += chars;
+    }
+    contributors.push({ role, chars, tool: resolveMessageToolLabel(msg) });
+    if (!tokenEstimationFailed) {
+      try {
+        estTokens += estimateTokens(msg);
+      } catch {
+        tokenEstimationFailed = true;
+      }
+    }
+  }
+
+  return {
+    messages: messages.length,
+    historyTextChars,
+    toolResultChars,
+    estTokens: tokenEstimationFailed ? undefined : estTokens,
+    contributors: contributors.toSorted((a, b) => b.chars - a.chars).slice(0, 3),
+  };
+}
+
+function classifyCompactionReason(reason?: string): string {
+  const text = (reason ?? "").trim().toLowerCase();
+  if (!text) {
+    return "unknown";
+  }
+  if (text.includes("nothing to compact")) {
+    return "no_compactable_entries";
+  }
+  if (text.includes("below threshold")) {
+    return "below_threshold";
+  }
+  if (text.includes("already compacted")) {
+    return "already_compacted_recently";
+  }
+  if (text.includes("guard")) {
+    return "guard_blocked";
+  }
+  if (text.includes("summary")) {
+    return "summary_failed";
+  }
+  if (text.includes("timed out") || text.includes("timeout")) {
+    return "timeout";
+  }
+  if (
+    text.includes("400") ||
+    text.includes("401") ||
+    text.includes("403") ||
+    text.includes("429")
+  ) {
+    return "provider_error_4xx";
+  }
+  if (
+    text.includes("500") ||
+    text.includes("502") ||
+    text.includes("503") ||
+    text.includes("504")
+  ) {
+    return "provider_error_5xx";
+  }
+  return "unknown";
+}
+
 /**
  * Core compaction logic without lane queueing.
  * Use this when already inside a session/global lane to avoid deadlocks.
@@ -118,6 +240,12 @@ export type CompactEmbeddedPiSessionParams = {
 export async function compactEmbeddedPiSessionDirect(
   params: CompactEmbeddedPiSessionParams,
 ): Promise<EmbeddedPiCompactResult> {
+  const startedAt = Date.now();
+  const diagId = params.diagId?.trim() || createCompactionDiagId();
+  const trigger = params.trigger ?? "manual";
+  const attempt = params.attempt ?? 1;
+  const maxAttempts = params.maxAttempts ?? 1;
+  const runId = params.runId ?? params.sessionId;
   const resolvedWorkspace = resolveUserPath(params.workspaceDir);
   const prevCwd = process.cwd();
 
@@ -132,10 +260,17 @@ export async function compactEmbeddedPiSessionDirect(
     params.config,
   );
   if (!model) {
+    const reason = error ?? `Unknown model: ${provider}/${modelId}`;
+    log.warn(
+      `[compaction-diag] end runId=${runId} sessionKey=${params.sessionKey ?? params.sessionId} ` +
+        `diagId=${diagId} trigger=${trigger} provider=${provider}/${modelId} ` +
+        `attempt=${attempt} maxAttempts=${maxAttempts} outcome=failed reason=${classifyCompactionReason(reason)} ` +
+        `durationMs=${Date.now() - startedAt}`,
+    );
     return {
       ok: false,
       compacted: false,
-      reason: error ?? `Unknown model: ${provider}/${modelId}`,
+      reason,
     };
   }
   try {
@@ -162,10 +297,17 @@ export async function compactEmbeddedPiSessionDirect(
       authStorage.setRuntimeApiKey(model.provider, apiKeyInfo.apiKey);
     }
   } catch (err) {
+    const reason = describeUnknownError(err);
+    log.warn(
+      `[compaction-diag] end runId=${runId} sessionKey=${params.sessionKey ?? params.sessionId} ` +
+        `diagId=${diagId} trigger=${trigger} provider=${provider}/${modelId} ` +
+        `attempt=${attempt} maxAttempts=${maxAttempts} outcome=failed reason=${classifyCompactionReason(reason)} ` +
+        `durationMs=${Date.now() - startedAt}`,
+    );
     return {
       ok: false,
       compacted: false,
-      reason: describeUnknownError(err),
+      reason,
     };
   }
 
@@ -475,6 +617,22 @@ export async function compactEmbeddedPiSessionDirect(
             });
         }
 
+        const diagEnabled = log.isEnabled("debug");
+        const preMetrics = diagEnabled ? summarizeCompactionMessages(session.messages) : undefined;
+        if (diagEnabled && preMetrics) {
+          log.debug(
+            `[compaction-diag] start runId=${runId} sessionKey=${params.sessionKey ?? params.sessionId} ` +
+              `diagId=${diagId} trigger=${trigger} provider=${provider}/${modelId} ` +
+              `attempt=${attempt} maxAttempts=${maxAttempts} ` +
+              `pre.messages=${preMetrics.messages} pre.historyTextChars=${preMetrics.historyTextChars} ` +
+              `pre.toolResultChars=${preMetrics.toolResultChars} pre.estTokens=${preMetrics.estTokens ?? "unknown"}`,
+          );
+          log.debug(
+            `[compaction-diag] contributors diagId=${diagId} top=${JSON.stringify(preMetrics.contributors)}`,
+          );
+        }
+
+        const compactStartedAt = Date.now();
         const result = await session.compact(params.customInstructions);
         // Estimate tokens after compaction by summing token estimates for remaining messages
         let tokensAfter: number | undefined;
@@ -510,6 +668,21 @@ export async function compactEmbeddedPiSessionDirect(
             });
         }
 
+        const postMetrics = diagEnabled ? summarizeCompactionMessages(session.messages) : undefined;
+        if (diagEnabled && preMetrics && postMetrics) {
+          log.debug(
+            `[compaction-diag] end runId=${runId} sessionKey=${params.sessionKey ?? params.sessionId} ` +
+              `diagId=${diagId} trigger=${trigger} provider=${provider}/${modelId} ` +
+              `attempt=${attempt} maxAttempts=${maxAttempts} outcome=compacted reason=none ` +
+              `durationMs=${Date.now() - compactStartedAt} retrying=false ` +
+              `post.messages=${postMetrics.messages} post.historyTextChars=${postMetrics.historyTextChars} ` +
+              `post.toolResultChars=${postMetrics.toolResultChars} post.estTokens=${postMetrics.estTokens ?? "unknown"} ` +
+              `delta.messages=${postMetrics.messages - preMetrics.messages} ` +
+              `delta.historyTextChars=${postMetrics.historyTextChars - preMetrics.historyTextChars} ` +
+              `delta.toolResultChars=${postMetrics.toolResultChars - preMetrics.toolResultChars} ` +
+              `delta.estTokens=${typeof preMetrics.estTokens === "number" && typeof postMetrics.estTokens === "number" ? postMetrics.estTokens - preMetrics.estTokens : "unknown"}`,
+          );
+        }
         return {
           ok: true,
           compacted: true,
@@ -532,10 +705,17 @@ export async function compactEmbeddedPiSessionDirect(
       await sessionLock.release();
     }
   } catch (err) {
+    const reason = describeUnknownError(err);
+    log.warn(
+      `[compaction-diag] end runId=${runId} sessionKey=${params.sessionKey ?? params.sessionId} ` +
+        `diagId=${diagId} trigger=${trigger} provider=${provider}/${modelId} ` +
+        `attempt=${attempt} maxAttempts=${maxAttempts} outcome=failed reason=${classifyCompactionReason(reason)} ` +
+        `durationMs=${Date.now() - startedAt}`,
+    );
     return {
       ok: false,
       compacted: false,
-      reason: describeUnknownError(err),
+      reason,
     };
   } finally {
     restoreSkillEnv?.();

src/agents/pi-embedded-runner/run.ts

@@ -97,6 +97,10 @@ const createUsageAccumulator = (): UsageAccumulator => ({
   lastInput: 0,
 });
 
+function createCompactionDiagId(): string {
+  return `ovf-${Date.now().toString(36)}-${Math.random().toString(36).slice(2, 8)}`;
+}
+
 const hasUsageValues = (
   usage: ReturnType<typeof normalizeUsage>,
 ): usage is NonNullable<ReturnType<typeof normalizeUsage>> =>
@@ -515,13 +519,15 @@ export async function runEmbeddedPiAgent(
             : null;
 
           if (contextOverflowError) {
+            const overflowDiagId = createCompactionDiagId();
             const errorText = contextOverflowError.text;
             const msgCount = attempt.messagesSnapshot?.length ?? 0;
             log.warn(
               `[context-overflow-diag] sessionKey=${params.sessionKey ?? params.sessionId} ` +
                 `provider=${provider}/${modelId} source=${contextOverflowError.source} ` +
                 `messages=${msgCount} sessionFile=${params.sessionFile} ` +
-                `compactionAttempts=${overflowCompactionAttempts} error=${errorText.slice(0, 200)}`,
+                `diagId=${overflowDiagId} compactionAttempts=${overflowCompactionAttempts} ` +
+                `error=${errorText.slice(0, 200)}`,
             );
             const isCompactionFailure = isCompactionFailureError(errorText);
             // Attempt auto-compaction on context overflow (not compaction_failure)
@@ -529,6 +535,13 @@ export async function runEmbeddedPiAgent(
               !isCompactionFailure &&
               overflowCompactionAttempts < MAX_OVERFLOW_COMPACTION_ATTEMPTS
             ) {
+              if (log.isEnabled("debug")) {
+                log.debug(
+                  `[compaction-diag] decision diagId=${overflowDiagId} branch=compact ` +
+                    `isCompactionFailure=${isCompactionFailure} hasOversizedToolResults=unknown ` +
+                    `attempt=${overflowCompactionAttempts + 1} maxAttempts=${MAX_OVERFLOW_COMPACTION_ATTEMPTS}`,
+                );
+              }
               overflowCompactionAttempts++;
               log.warn(
                 `context overflow detected (attempt ${overflowCompactionAttempts}/${MAX_OVERFLOW_COMPACTION_ATTEMPTS}); attempting auto-compaction for ${provider}/${modelId}`,
@@ -548,11 +561,16 @@ export async function runEmbeddedPiAgent(
                 senderIsOwner: params.senderIsOwner,
                 provider,
                 model: modelId,
+                runId: params.runId,
                 thinkLevel,
                 reasoningLevel: params.reasoningLevel,
                 bashElevated: params.bashElevated,
                 extraSystemPrompt: params.extraSystemPrompt,
                 ownerNumbers: params.ownerNumbers,
+                trigger: "overflow",
+                diagId: overflowDiagId,
+                attempt: overflowCompactionAttempts,
+                maxAttempts: MAX_OVERFLOW_COMPACTION_ATTEMPTS,
               });
               if (compactResult.compacted) {
                 autoCompactionCount += 1;
@@ -576,6 +594,13 @@ export async function runEmbeddedPiAgent(
                 : false;
 
               if (hasOversized) {
+                if (log.isEnabled("debug")) {
+                  log.debug(
+                    `[compaction-diag] decision diagId=${overflowDiagId} branch=truncate_tool_results ` +
+                      `isCompactionFailure=${isCompactionFailure} hasOversizedToolResults=${hasOversized} ` +
+                      `attempt=${overflowCompactionAttempts} maxAttempts=${MAX_OVERFLOW_COMPACTION_ATTEMPTS}`,
+                  );
+                }
                 toolResultTruncationAttempted = true;
                 log.warn(
                   `[context-overflow-recovery] Attempting tool result truncation for ${provider}/${modelId} ` +
@@ -598,8 +623,26 @@ export async function runEmbeddedPiAgent(
                 log.warn(
                   `[context-overflow-recovery] Tool result truncation did not help: ${truncResult.reason ?? "unknown"}`,
                 );
+              } else if (log.isEnabled("debug")) {
+                log.debug(
+                  `[compaction-diag] decision diagId=${overflowDiagId} branch=give_up ` +
+                    `isCompactionFailure=${isCompactionFailure} hasOversizedToolResults=${hasOversized} ` +
+                    `attempt=${overflowCompactionAttempts} maxAttempts=${MAX_OVERFLOW_COMPACTION_ATTEMPTS}`,
+                );
               }
             }
+            if (
+              (isCompactionFailure ||
+                overflowCompactionAttempts >= MAX_OVERFLOW_COMPACTION_ATTEMPTS ||
+                toolResultTruncationAttempted) &&
+              log.isEnabled("debug")
+            ) {
+              log.debug(
+                `[compaction-diag] decision diagId=${overflowDiagId} branch=give_up ` +
+                  `isCompactionFailure=${isCompactionFailure} hasOversizedToolResults=unknown ` +
+                  `attempt=${overflowCompactionAttempts} maxAttempts=${MAX_OVERFLOW_COMPACTION_ATTEMPTS}`,
+              );
+            }
             const kind = isCompactionFailure ? "compaction_failure" : "context_overflow";
             return {
               payloads: [

src/agents/pi-embedded-runner/run/attempt.ts

@@ -140,6 +140,69 @@ export function injectHistoryImagesIntoMessages(
   return didMutate;
 }
 
+function summarizeMessagePayload(msg: AgentMessage): { textChars: number; imageBlocks: number } {
+  const content = (msg as { content?: unknown }).content;
+  if (typeof content === "string") {
+    return { textChars: content.length, imageBlocks: 0 };
+  }
+  if (!Array.isArray(content)) {
+    return { textChars: 0, imageBlocks: 0 };
+  }
+
+  let textChars = 0;
+  let imageBlocks = 0;
+  for (const block of content) {
+    if (!block || typeof block !== "object") {
+      continue;
+    }
+    const typedBlock = block as { type?: unknown; text?: unknown };
+    if (typedBlock.type === "image") {
+      imageBlocks++;
+      continue;
+    }
+    if (typeof typedBlock.text === "string") {
+      textChars += typedBlock.text.length;
+    }
+  }
+
+  return { textChars, imageBlocks };
+}
+
+function summarizeSessionContext(messages: AgentMessage[]): {
+  roleCounts: string;
+  totalTextChars: number;
+  totalImageBlocks: number;
+  maxMessageTextChars: number;
+} {
+  const roleCounts = new Map<string, number>();
+  let totalTextChars = 0;
+  let totalImageBlocks = 0;
+  let maxMessageTextChars = 0;
+
+  for (const msg of messages) {
+    const role = typeof msg.role === "string" ? msg.role : "unknown";
+    roleCounts.set(role, (roleCounts.get(role) ?? 0) + 1);
+
+    const payload = summarizeMessagePayload(msg);
+    totalTextChars += payload.textChars;
+    totalImageBlocks += payload.imageBlocks;
+    if (payload.textChars > maxMessageTextChars) {
+      maxMessageTextChars = payload.textChars;
+    }
+  }
+
+  return {
+    roleCounts:
+      [...roleCounts.entries()]
+        .toSorted((a, b) => a[0].localeCompare(b[0]))
+        .map(([role, count]) => `${role}:${count}`)
+        .join(",") || "none",
+    totalTextChars,
+    totalImageBlocks,
+    maxMessageTextChars,
+  };
+}
+
 export async function runEmbeddedAttempt(
   params: EmbeddedRunAttemptParams,
 ): Promise<EmbeddedRunAttemptResult> {
@@ -826,6 +889,25 @@ export async function runEmbeddedAttempt(
             note: `images: prompt=${imageResult.images.length} history=${imageResult.historyImagesByIndex.size}`,
           });
 
+          // Diagnostic: log context sizes before prompt to help debug early overflow errors.
+          if (log.isEnabled("debug")) {
+            const msgCount = activeSession.messages.length;
+            const systemLen = systemPromptText?.length ?? 0;
+            const promptLen = effectivePrompt.length;
+            const sessionSummary = summarizeSessionContext(activeSession.messages);
+            log.debug(
+              `[context-diag] pre-prompt: sessionKey=${params.sessionKey ?? params.sessionId} ` +
+                `messages=${msgCount} roleCounts=${sessionSummary.roleCounts} ` +
+                `historyTextChars=${sessionSummary.totalTextChars} ` +
+                `maxMessageTextChars=${sessionSummary.maxMessageTextChars} ` +
+                `historyImageBlocks=${sessionSummary.totalImageBlocks} ` +
+                `systemPromptChars=${systemLen} promptChars=${promptLen} ` +
+                `promptImages=${imageResult.images.length} ` +
+                `historyImageMessages=${imageResult.historyImagesByIndex.size} ` +
+                `provider=${params.provider}/${params.modelId} sessionFile=${params.sessionFile}`,
+            );
+          }
+
           // Only pass images option if there are actually images to pass
           // This avoids potential issues with models that don't expect the images parameter
           if (imageResult.images.length > 0) {

src/logging/subsystem.test.ts

@@ -0,0 +1,56 @@
+import { afterEach, describe, expect, it } from "vitest";
+import { setConsoleSubsystemFilter } from "./console.js";
+import { resetLogger, setLoggerOverride } from "./logger.js";
+import { createSubsystemLogger } from "./subsystem.js";
+
+afterEach(() => {
+  setConsoleSubsystemFilter(null);
+  setLoggerOverride(null);
+  resetLogger();
+});
+
+describe("createSubsystemLogger().isEnabled", () => {
+  it("returns true for any/file when only file logging would emit", () => {
+    setLoggerOverride({ level: "debug", consoleLevel: "silent" });
+    const log = createSubsystemLogger("agent/embedded");
+
+    expect(log.isEnabled("debug")).toBe(true);
+    expect(log.isEnabled("debug", "file")).toBe(true);
+    expect(log.isEnabled("debug", "console")).toBe(false);
+  });
+
+  it("returns true for any/console when only console logging would emit", () => {
+    setLoggerOverride({ level: "silent", consoleLevel: "debug" });
+    const log = createSubsystemLogger("agent/embedded");
+
+    expect(log.isEnabled("debug")).toBe(true);
+    expect(log.isEnabled("debug", "console")).toBe(true);
+    expect(log.isEnabled("debug", "file")).toBe(false);
+  });
+
+  it("returns false when neither console nor file logging would emit", () => {
+    setLoggerOverride({ level: "silent", consoleLevel: "silent" });
+    const log = createSubsystemLogger("agent/embedded");
+
+    expect(log.isEnabled("debug")).toBe(false);
+    expect(log.isEnabled("debug", "console")).toBe(false);
+    expect(log.isEnabled("debug", "file")).toBe(false);
+  });
+
+  it("honors console subsystem filters for console target", () => {
+    setLoggerOverride({ level: "silent", consoleLevel: "info" });
+    setConsoleSubsystemFilter(["gateway"]);
+    const log = createSubsystemLogger("agent/embedded");
+
+    expect(log.isEnabled("info", "console")).toBe(false);
+  });
+
+  it("does not apply console subsystem filters to file target", () => {
+    setLoggerOverride({ level: "info", consoleLevel: "silent" });
+    setConsoleSubsystemFilter(["gateway"]);
+    const log = createSubsystemLogger("agent/embedded");
+
+    expect(log.isEnabled("info", "file")).toBe(true);
+    expect(log.isEnabled("info")).toBe(true);
+  });
+});

src/logging/subsystem.ts

@@ -6,13 +6,14 @@ import { defaultRuntime, type RuntimeEnv } from "../runtime.js";
 import { clearActiveProgressLine } from "../terminal/progress-line.js";
 import { getConsoleSettings, shouldLogSubsystemToConsole } from "./console.js";
 import { type LogLevel, levelToMinLevel } from "./levels.js";
-import { getChildLogger } from "./logger.js";
+import { getChildLogger, isFileLogLevelEnabled } from "./logger.js";
 import { loggingState } from "./state.js";
 
 type LogObj = { date?: Date } & Record<string, unknown>;
 
 export type SubsystemLogger = {
   subsystem: string;
+  isEnabled: (level: LogLevel, target?: "any" | "console" | "file") => boolean;
   trace: (message: string, meta?: Record<string, unknown>) => void;
   debug: (message: string, meta?: Record<string, unknown>) => void;
   info: (message: string, meta?: Record<string, unknown>) => void;
@@ -271,9 +272,26 @@ export function createSubsystemLogger(subsystem: string): SubsystemLogger {
     });
     writeConsoleLine(level, line);
   };
+  const isConsoleEnabled = (level: LogLevel): boolean => {
+    const consoleSettings = getConsoleSettings();
+    return (
+      shouldLogToConsole(level, { level: consoleSettings.level }) &&
+      shouldLogSubsystemToConsole(subsystem)
+    );
+  };
+  const isFileEnabled = (level: LogLevel): boolean => isFileLogLevelEnabled(level);
 
   const logger: SubsystemLogger = {
     subsystem,
+    isEnabled: (level, target = "any") => {
+      if (target === "console") {
+        return isConsoleEnabled(level);
+      }
+      if (target === "file") {
+        return isFileEnabled(level);
+      }
+      return isConsoleEnabled(level) || isFileEnabled(level);
+    },
     trace: (message, meta) => emit("trace", message, meta),
     debug: (message, meta) => emit("debug", message, meta),
     info: (message, meta) => emit("info", message, meta),