From 9bd2ccb017438987ab037d1834d0e6b90ecd60a4 Mon Sep 17 00:00:00 2001 From: Glucksberg <80581902+Glucksberg@users.noreply.github.com> Date: Fri, 13 Feb 2026 19:54:22 -0400 Subject: [PATCH] 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 | 1 + src/agents/pi-embedded-runner/compact.ts | 186 ++++++++++++++++++- src/agents/pi-embedded-runner/run.ts | 45 ++++- src/agents/pi-embedded-runner/run/attempt.ts | 82 ++++++++ src/logging/subsystem.test.ts | 56 ++++++ src/logging/subsystem.ts | 20 +- 6 files changed, 385 insertions(+), 5 deletions(-) create mode 100644 src/logging/subsystem.test.ts diff --git a/CHANGELOG.md b/CHANGELOG.md index 98e88317a..7264ce568 100644 --- a/CHANGELOG.md +++ b/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 diff --git a/src/agents/pi-embedded-runner/compact.ts b/src/agents/pi-embedded-runner/compact.ts index f50dfd7bc..4adca9dfe 100644 --- a/src/agents/pi-embedded-runner/compact.ts +++ b/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 { + 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?.(); diff --git a/src/agents/pi-embedded-runner/run.ts b/src/agents/pi-embedded-runner/run.ts index 6cbd3dd4c..96dc8db03 100644 --- a/src/agents/pi-embedded-runner/run.ts +++ b/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, ): usage is NonNullable> => @@ -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: [ diff --git a/src/agents/pi-embedded-runner/run/attempt.ts b/src/agents/pi-embedded-runner/run/attempt.ts index dbb69e73e..5f76d3bdf 100644 --- a/src/agents/pi-embedded-runner/run/attempt.ts +++ b/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(); + 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 { @@ -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) { diff --git a/src/logging/subsystem.test.ts b/src/logging/subsystem.test.ts new file mode 100644 index 000000000..e389d78ba --- /dev/null +++ b/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); + }); +}); diff --git a/src/logging/subsystem.ts b/src/logging/subsystem.ts index a1ec00abc..89671b7b9 100644 --- a/src/logging/subsystem.ts +++ b/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; export type SubsystemLogger = { subsystem: string; + isEnabled: (level: LogLevel, target?: "any" | "console" | "file") => boolean; trace: (message: string, meta?: Record) => void; debug: (message: string, meta?: Record) => void; info: (message: string, meta?: Record) => 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),