From 620917fbc07ef8e9a25dafab73792835149b5927 Mon Sep 17 00:00:00 2001 From: Markus Hartung Date: Sat, 8 Aug 2026 00:51:41 +0200 Subject: [PATCH] feat(logging): make the chat-log truncation limit configurable, bumped default 128x MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The 8KB cap on logged request/response bodies (open-sse/handlers/chatCore/logTruncation.ts::truncateForLog()) was hardcoded — trivially exceeded by any real multi-turn agentic conversation, meaning the dashboard's "Full Conversation" panel could only ever show a placeholder instead of the actual messages for nearly every logged row of any conversation with real substance. - Added CHAT_LOG_MAX_BODY_KB env var (src/lib/logEnv.ts:: getChatLogMaxBodyBytes()), default 1024 KB (1MB) — a 128x bump from the old hardcoded 8KB — following the same configurable-limit pattern as the sibling CHAT_LOG_TEXT_LIMIT/CHAT_LOG_ARRAY_TAIL_ITEMS/etc. vars. - Documented in .env.example and docs/reference/ENVIRONMENT.md. estimateSizeFast() (open-sse/utils/estimateSize.ts) has been substantially rewritten upstream since this bug was first found (now an iterative Frame-based walker with a separate node-visit budget, not the simple stack loop originally patched) — re-implemented the fix against the current algorithm rather than porting the old diff: the byte early-exit was unconditionally the module-level ESTIMATE_SIZE_BYTE_LIMIT (256 KiB) with no way for a caller to raise it, so any caller comparing against a bigger configured threshold could never see a size above ~256 KiB — every payload between 256 KiB and the caller's real limit looked "under threshold" and truncation never fired, the opposite of intended. Added an optional byteLimit parameter (default unchanged at ESTIMATE_SIZE_BYTE_LIMIT, so isSmallEnoughForSemanticCache's existing behavior is untouched) threaded through both the byte-check early-exit and the node-budget-exhaustion fail-closed fallback, with truncateForLog() now passing its own configured getChatLogMaxBodyBytes() value through. --- .env.example | 1 + docs/reference/ENVIRONMENT.md | 1 + open-sse/handlers/chatCore/logTruncation.ts | 14 +++--- open-sse/utils/estimateSize.ts | 25 ++++++++--- src/lib/logEnv.ts | 10 +++++ tests/unit/chatcore-log-truncation.test.ts | 32 ++++++++++++++ tests/unit/estimateSizeFast.test.ts | 49 +++++++++++++++++++++ 7 files changed, 120 insertions(+), 12 deletions(-) diff --git a/.env.example b/.env.example index d3b3f4b364..f021b0d8c5 100644 --- a/.env.example +++ b/.env.example @@ -1429,6 +1429,7 @@ APP_LOG_TO_FILE=true # CHAT_LOG_ARRAY_TAIL_ITEMS=24 # Number of array items retained from tail (default: 24) # CHAT_LOG_MAX_DEPTH=6 # Max nesting depth before truncation (default: 6) # CHAT_LOG_MAX_OBJECT_KEYS=80 # Max object keys retained (default: 80, 0 = no limit) +# CHAT_LOG_MAX_BODY_KB=1024 # Max request/response body size before summarizing, in KB (default: 1024) # Maximum rows in the proxy_logs SQLite table. # Default: 100000 diff --git a/docs/reference/ENVIRONMENT.md b/docs/reference/ENVIRONMENT.md index 161b9f1252..ee24d26c63 100644 --- a/docs/reference/ENVIRONMENT.md +++ b/docs/reference/ENVIRONMENT.md @@ -744,6 +744,7 @@ The logging system writes to both stdout and rotated log files. All configuratio | `CHAT_LOG_ARRAY_TAIL_ITEMS` | `24` | Number of array items retained from the tail when truncating chat log payloads. | | `CHAT_LOG_MAX_DEPTH` | `6` | Max nesting depth before chat log payloads are truncated. | | `CHAT_LOG_MAX_OBJECT_KEYS` | `80` | Max object keys retained in chat log payloads (0 = unlimited). | +| `CHAT_LOG_MAX_BODY_KB` | `1024` | Max request/response body size before `truncateForLog()` summarizes it, in KB. | | `CHAT_DEBUG_FILE` | `false` | When true, `serializeArtifactForStorage` skips size-based truncation. Debug only. | --- diff --git a/open-sse/handlers/chatCore/logTruncation.ts b/open-sse/handlers/chatCore/logTruncation.ts index e2a4b51c96..03a854ae57 100644 --- a/open-sse/handlers/chatCore/logTruncation.ts +++ b/open-sse/handlers/chatCore/logTruncation.ts @@ -3,11 +3,11 @@ import { getChatLogMaxDepth, getChatLogArrayTailItems, getChatLogMaxObjectKeys, + getChatLogMaxBodyBytes, } from "@/lib/logEnv"; import { estimateSizeFast } from "../../utils/estimateSize.ts"; export const MEMORY_EXTRACTION_TEXT_LIMIT = 64 * 1024; -const MAX_LOG_BODY_CHARS = 8 * 1024; // 8KB cap for logged request/response bodies export function capMemoryExtractionText(value: string): string { if (value.length <= MEMORY_EXTRACTION_TEXT_LIMIT) return value; @@ -60,9 +60,10 @@ export function cloneBoundedChatLogPayload(value: unknown, depth = 0): unknown { /** * Truncate a large object for logging. If its JSON representation exceeds - * MAX_LOG_BODY_CHARS, return a lightweight summary instead of the full clone. - * This prevents persistAttemptLogs from holding multi-MB references to - * translatedBody across 17 call sites per request. + * the configured max body size (getChatLogMaxBodyBytes()), return a + * lightweight summary instead of the full clone. This prevents + * persistAttemptLogs from holding multi-MB references to translatedBody + * across 17 call sites per request. * * When the summarized object carries a `tools` definition, re-attach it * (bounded via `cloneBoundedChatLogPayload`) so the request-details view can @@ -75,8 +76,9 @@ export function cloneBoundedChatLogPayload(value: unknown, depth = 0): unknown { export function truncateForLog(value: unknown): Record | null | undefined { if (value === null || value === undefined) return value as null | undefined; if (typeof value !== "object") return value as unknown as Record; - const estimatedSize = estimateSizeFast(value); - if (estimatedSize <= MAX_LOG_BODY_CHARS) return value as Record; + const maxBodyBytes = getChatLogMaxBodyBytes(); + const estimatedSize = estimateSizeFast(value, maxBodyBytes); + if (estimatedSize <= maxBodyBytes) return value as Record; // Object is too large — return a summary instead of a deep clone const obj = value as Record; const summary: Record = { diff --git a/open-sse/utils/estimateSize.ts b/open-sse/utils/estimateSize.ts index 8a6f5ef76d..9eb7f178fd 100644 --- a/open-sse/utils/estimateSize.ts +++ b/open-sse/utils/estimateSize.ts @@ -3,15 +3,20 @@ * Safe for circular references (WeakSet). Iterative frames only (no recursive call stack). * * Budgets: - * - ESTIMATE_SIZE_BYTE_LIMIT (256 KiB): early-exit once counted bytes exceed the limit + * - byteLimit param (default ESTIMATE_SIZE_BYTE_LIMIT, 256 KiB): early-exit + * once counted bytes exceed the limit — pass the caller's own threshold + * explicitly rather than relying on the default, since a caller comparing + * against a bigger configured limit would otherwise never see a size + * above 256 KiB. * - ESTIMATE_SIZE_NODE_BUDGET: max value visits (containers + primitives/elements) * * Arrays are walked by index frame (never pre-push/copy every element reference). * Plain objects yield own enumerable values incrementally (no Object.keys materialization). - * Node-budget exhaustion returns a value strictly above 256 KiB so callers fail closed. + * Node-budget exhaustion returns a value strictly above the effective byteLimit + * so callers fail closed. */ -/** Byte early-exit threshold (256 KiB). */ +/** Default byte early-exit threshold (256 KiB) when a caller doesn't pass its own. */ export const ESTIMATE_SIZE_BYTE_LIMIT = 262_144; /** @@ -74,14 +79,22 @@ function expandContainerFrame(stack: Frame[], frame: Exclude) stack.push({ t: "v", v: (frame.o as Record)[next.value] }); } -export function estimateSizeFast(value: unknown): number { +/** + * @param byteLimit - early-exit threshold (default ESTIMATE_SIZE_BYTE_LIMIT, + * 256 KiB). Pass the actual threshold you're comparing against (see + * chatCore/logTruncation.ts::truncateForLog) so raising that threshold + * doesn't silently cap what this function is even capable of reporting — + * the byte check and the node-budget fail-closed fallback both key off this + * value, not the fixed module constant, when a caller supplies one. + */ +export function estimateSizeFast(value: unknown, byteLimit = ESTIMATE_SIZE_BYTE_LIMIT): number { let bytes = 0; let visitsLeft = ESTIMATE_SIZE_NODE_BUDGET; const seen = new WeakSet(); const stack: Frame[] = [{ t: "v", v: value }]; while (stack.length > 0) { - if (visitsLeft <= 0) return ESTIMATE_SIZE_BYTE_LIMIT + 1; + if (visitsLeft <= 0) return byteLimit + 1; const frame = stack.pop()!; if (!isValueFrame(frame)) { @@ -96,7 +109,7 @@ export function estimateSizeFast(value: unknown): number { const ty = typeof v; if (ty === "string" || ty === "number" || ty === "boolean") { bytes = addPrimitiveBytes(bytes, v as string | number | boolean); - if (bytes > ESTIMATE_SIZE_BYTE_LIMIT) return bytes; + if (bytes > byteLimit) return bytes; continue; } if (ty === "object") { diff --git a/src/lib/logEnv.ts b/src/lib/logEnv.ts index 8486628b4e..9f438f1eec 100644 --- a/src/lib/logEnv.ts +++ b/src/lib/logEnv.ts @@ -158,6 +158,16 @@ export function getChatLogMaxObjectKeys(): number { return parseNonNegativeInt(process.env.CHAT_LOG_MAX_OBJECT_KEYS, 80); } +/** + * Was a hardcoded/default 8KB — trivially exceeded by any real multi-turn + * agentic conversation, meaning the dashboard's "Full Conversation" panel + * could only ever show a placeholder instead of the actual messages for + * nearly every logged row of any conversation with real substance. + */ +export function getChatLogMaxBodyBytes(): number { + return parsePositiveInt(process.env.CHAT_LOG_MAX_BODY_KB, 1024) * 1024; +} + export function isChatDebugFileEnabled(): boolean { if (parseBoolean(process.env.CHAT_DEBUG_FILE, false)) return true; return process.env.APP_LOG_LEVEL?.trim().toLowerCase() === "debug"; diff --git a/tests/unit/chatcore-log-truncation.test.ts b/tests/unit/chatcore-log-truncation.test.ts index d050b4f90a..ef4b79fa0c 100644 --- a/tests/unit/chatcore-log-truncation.test.ts +++ b/tests/unit/chatcore-log-truncation.test.ts @@ -242,3 +242,35 @@ test("truncateForLog leaves small requests with `tools` unchanged (no regression // untouched — same reference, not a summary or a clone assert.equal(result, small); }); + +/** + * Real bug: the 8KB cap on logged request/response bodies was hardcoded, + * trivially exceeded by any real multi-turn agentic conversation — the + * dashboard's "Full Conversation" panel could only ever show a placeholder + * instead of the actual messages for nearly every logged row of any + * conversation with real substance. CHAT_LOG_MAX_BODY_KB makes this + * configurable; this pins that truncateForLog() actually reads it (not a + * baked-in literal) by proving a payload just over the OLD 8KB default + * survives untouched under a raised limit, then gets summarized again once + * the limit is lowered below it. + */ +test("truncateForLog honors a configured CHAT_LOG_MAX_BODY_KB instead of a hardcoded cap", () => { + const saved = process.env.CHAT_LOG_MAX_BODY_KB; + const payload = { + model: "gpt-4o", + // ~12KB of content — comfortably over the old hardcoded 8KB cap. + messages: [{ role: "user", content: "x".repeat(12 * 1024) }], + }; + try { + process.env.CHAT_LOG_MAX_BODY_KB = "1"; // 1KB — payload must be summarized + const summarized = truncateForLog(payload) as Record; + assert.equal(summarized._truncated, true, "expected summarization under a 1KB limit"); + + process.env.CHAT_LOG_MAX_BODY_KB = "64"; // 64KB — payload must pass through untouched + const untouched = truncateForLog(payload); + assert.equal(untouched, payload, "expected the payload untouched under a 64KB limit"); + } finally { + if (saved === undefined) delete process.env.CHAT_LOG_MAX_BODY_KB; + else process.env.CHAT_LOG_MAX_BODY_KB = saved; + } +}); diff --git a/tests/unit/estimateSizeFast.test.ts b/tests/unit/estimateSizeFast.test.ts index d7e5a7b6a8..84893097a6 100644 --- a/tests/unit/estimateSizeFast.test.ts +++ b/tests/unit/estimateSizeFast.test.ts @@ -68,6 +68,55 @@ test("estimateSizeFast early-exits at 262144 bytes (256KB)", () => { assert.ok(result >= 262144, `Should early-exit, got ${result}`); }); +/** + * Real bug: the byte early-exit was unconditionally ESTIMATE_SIZE_BYTE_LIMIT + * (256 KiB) with no way for a caller to raise it, so any caller comparing + * against a bigger configured threshold (e.g. logTruncation.ts's + * getChatLogMaxBodyBytes(), default 1 MiB) could never see a size above + * ~256 KiB — every payload up to their real threshold looked "under + * threshold" and truncation never fired for anything between 256 KiB and + * the caller's actual limit, silently letting oversized bodies through. + */ +test("estimateSizeFast respects a caller-supplied byteLimit above the 256KB default", () => { + const oneMiB = 1024 * 1024; + // Multiple 200KB elements: the 2nd element alone already crosses the + // default 256KB limit, so a hardcoded-256KB implementation early-exits + // there and never accumulates the 3rd/4th elements — only a truly + // caller-configurable limit reports the full, accurate total. + const payload = Array.from({ length: 4 }, () => "x".repeat(200_000)); + const trueTotal = payload.reduce((sum, s) => sum + s.length, 0); + + const withDefaultLimit = estimateSizeFast(payload); + assert.ok( + withDefaultLimit < trueTotal, + `sanity: default 256KB limit must early-exit before the true total, got ${withDefaultLimit}` + ); + + const withCustomLimit = estimateSizeFast(payload, oneMiB); + assert.equal( + withCustomLimit, + trueTotal, + "must report the true accumulated size instead of early-exiting at the default 256KB" + ); + assert.ok(withCustomLimit <= oneMiB, "payload must be recognized as under the caller's own limit"); +}); + +test("estimateSizeFast node-budget fail-closed return respects a caller-supplied byteLimit", () => { + const oneMiB = 1024 * 1024; + const hugeSparseArray = new Proxy([] as unknown[], { + get(target, prop, receiver) { + if (prop === "length") return 5_000_000; + if (typeof prop === "string" && /^[0-9]+$/.test(prop)) return null; + return Reflect.get(target, prop, receiver); + }, + }); + const result = estimateSizeFast(hugeSparseArray, oneMiB); + assert.ok( + result > oneMiB, + `node-budget exhaustion must fail closed above the CALLER's limit (${oneMiB}), not the default 256KB — got ${result}` + ); +}); + test("estimateSizeFast checks byte limit after numbers and booleans", () => { const almostForNumber = "x".repeat(ESTIMATE_SIZE_BYTE_LIMIT - 4); const withNumber = estimateSizeFast([almostForNumber, 1]);