From d7db2d1a56791a0d433cad348644871a4d9ca744 Mon Sep 17 00:00:00 2001 From: Markus Hartung Date: Wed, 5 Aug 2026 03:31:06 +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 (both required — tests/unit/issue-7793-env-doc-sync-repro.test.ts and check-env-doc-sync.test.ts enforce this pairing). Found and fixed a real bug while wiring this up: estimateSize.ts's estimateSizeFast() had its own hardcoded 256KB early-exit optimization ("stop walking once bytes clearly exceeds the caller's threshold"), so it could never report a size above ~256KB regardless of the object's true size — meaning any caller threshold configured above 256KB (like the new 1MB default) was silently unreachable; every payload would look "under threshold" and truncation would never fire, letting arbitrarily large bodies through unbounded (the opposite of intended, and a real memory- protection regression). Fixed by giving estimateSizeFast() a parameterized earlyExitAt (default unchanged at 262144, so isSmallEnoughForSemanticCache's existing behavior is untouched), with truncateForLog() now passing its own configured getChatLogMaxBodyBytes() value through. Also adds a "Conversation" field to the request detail panel's metadata grid (last, after "Combo"), showing the request's conversation id (sessionTag) for quick reference/copy. Test plan: - New TDD tests for both fixes (Responses API messageCount capture — from the previous commit — and the estimateSizeFast earlyExitAt parameter), confirmed failing before each fix and passing after - Bumped the two truncateForLog test fixtures that were sized against the old 8KB threshold so they still genuinely exceed the new ~1MB default - npm run typecheck:core / npm run lint / npm run check:file-size — clean - npm run test:unit — 27132 tests, same 4 pre-existing/unrelated failures as the last confirmed-clean run (no new regressions) — including the two env/doc-sync contract tests that initially caught the missing CHAT_LOG_MAX_BODY_KB documentation, now fixed - npm run test:vitest — 291/291 passed - Rebuilt and redeployed to omniroute-dev --- .env.example | 5 ++++ config/quality/file-size-baseline.json | 4 +-- docs/reference/ENVIRONMENT.md | 1 + open-sse/handlers/chatCore/logTruncation.ts | 17 +++++++---- open-sse/utils/estimateSize.ts | 14 ++++++--- src/lib/logEnv.ts | 17 +++++++++++ src/shared/components/RequestLoggerDetail.tsx | 21 ++++++++++++- tests/unit/chatcore-log-truncation.test.ts | 10 +++---- tests/unit/estimateSizeFast.test.ts | 30 +++++++++++++++++-- 9 files changed, 98 insertions(+), 21 deletions(-) diff --git a/.env.example b/.env.example index 4cb877425c..6c84f25b3b 100644 --- a/.env.example +++ b/.env.example @@ -1360,6 +1360,11 @@ 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 # Whole request/response body size before it's replaced by a bare + # {_truncated, messageCount, ...} summary instead of the full clone + # (default: 1024 KB / 1MB). Raise this if the dashboard's "Full + # Conversation" transcript panel shows a placeholder instead of the + # actual messages for long agentic conversations. # Maximum rows in the proxy_logs SQLite table. # Default: 100000 diff --git a/config/quality/file-size-baseline.json b/config/quality/file-size-baseline.json index a0f4d43780..5bf5a1a3f4 100644 --- a/config/quality/file-size-baseline.json +++ b/config/quality/file-size-baseline.json @@ -158,7 +158,7 @@ "_rebaseline_2026_06_20_4389_thinking_toolchoice": "Re-baseline base.ts 1387->1399 (#4389): tool_choice-forced thinking guard at the existing Claude wire-image injection chokepoint (effThinking gate avoids the Anthropic 400 when tool_choice forces a tool). Cohesive guard; structural shrink tracked in #3501.", "_rebaseline_2026_07_18_6979_codex_test": "PR #6979 own growth: executor-codex.test.ts 1340->1347 (+7 = generalized ensureThinkingBudget assertion added to the existing codex thinking-budget cases). antigravity-test bump 942->977 REVERTED here: #7408's test split dropped that file to 888, so this PR's +35 fits under the original 942 frozen cap.", "_rebaseline_2026_07_24_8354_logs_timeline_sidebar": "PR #8354 (hartmark, feature/scrolling-log) own growth: src/shared/constants/sidebarVisibility/sections.ts 812->820 (+8, the single new logs-timeline SidebarItemDefinition entry added to LOGS_GROUP.items for the new /dashboard/logs/timeline scrolling request-timeline page). Irreducible data-literal wiring at the existing sidebar-sections chokepoint, same shape as every other item in the file; not extractable without an ad-hoc single-item exception to the file's otherwise-uniform multi-line item style.", - "_rebaseline_2026_08_04_9439_agentic_conversation_tracking": "PR #9439 (hartmark, feat/agentic-conversation-tracking) own growth: adds agentic multi-turn conversation tracking (X-ConversationId, fingerprint+prefix-hash continuation detection) plus a full dashboard surface for it. src/sse/handlers/chat.ts 1845->1868 (+23, conversationId resolution + X-ConversationId header wiring at the existing chat-request chokepoint, threaded to executeChatWithBreaker). open-sse/handlers/chatCore.ts 5020->5024 (+4, sessionTag passthrough on the trackPendingRequest() call so an in-flight/streaming request's conversation transcript can be reconstructed live — see #9315 fix in the same PR). src/shared/components/RequestLoggerV2.tsx 1629->1643 (+14, onNavigateToLog wiring so a turn/next-message click in the new conversation panel can open another request's detail without leaving the logs list). Two files cross the 1000-line new-file cap because they gained the actual UI feature body, not incidental wiring: src/shared/components/RequestLoggerDetail.tsx (new cap, 1241) gained the 'Full Conversation' transcript section (Markdown rendering, per-turn timestamps, turn-relative view, click-to-navigate, live auto-refresh/auto-follow fed from the in-flight SSE buffer, mobile-responsive header) and src/shared/components/RequestTimeline.tsx (new cap, 1037) gained conversation-aware lane grouping/connector-arrow rendering, mobile responsiveness, and configurable poll-interval controls; both are the dashboard-side half of this PR's actual feature, not extractable without splitting an existing single-modal/single-canvas component mid-feature. open-sse/executors/base.ts 1578->1623 (+45) is NOT this PR's change — confirmed via `git diff upstream/release/v3.8.50 HEAD -- open-sse/executors/base.ts` (empty) — it is release/v3.8.50's own pre-existing drift past its frozen cap, inherited via this branch's rebase onto the current release tip; rebaselined here only because check:file-size runs against the full merged tree and this PR's rebase is what surfaced it. Covered by tests/unit/conversationTracker.test.ts, agenticConversations.test.ts, multiRowConversation.test.ts, request-timeline-lane-allocation.test.ts, stream-payload-collector.test.ts. Structural shrink of RequestLoggerDetail.tsx/RequestTimeline.tsx tracked in #3501.", + "_rebaseline_2026_08_04_9439_agentic_conversation_tracking": "PR #9439 (hartmark, feat/agentic-conversation-tracking) own growth: adds agentic multi-turn conversation tracking (X-ConversationId, fingerprint+prefix-hash continuation detection) plus a full dashboard surface for it. src/sse/handlers/chat.ts 1845->1868 (+23, conversationId resolution + X-ConversationId header wiring at the existing chat-request chokepoint, threaded to executeChatWithBreaker). open-sse/handlers/chatCore.ts 5020->5024 (+4, sessionTag passthrough on the trackPendingRequest() call so an in-flight/streaming request's conversation transcript can be reconstructed live — see #9315 fix in the same PR). src/shared/components/RequestLoggerV2.tsx 1629->1643 (+14, onNavigateToLog wiring so a turn/next-message click in the new conversation panel can open another request's detail without leaving the logs list). Two files cross the 1000-line new-file cap because they gained the actual UI feature body, not incidental wiring: src/shared/components/RequestLoggerDetail.tsx (new cap, 1241->1256 after a follow-up +15: a 'Conversation' field added to the metadata grid, last after 'Combo', showing the request's sessionTag/conversation id) gained the 'Full Conversation' transcript section (Markdown rendering, per-turn timestamps, turn-relative view, click-to-navigate, live auto-refresh/auto-follow fed from the in-flight SSE buffer, mobile-responsive header) and src/shared/components/RequestTimeline.tsx (new cap, 1037) gained conversation-aware lane grouping/connector-arrow rendering, mobile responsiveness, and configurable poll-interval controls; both are the dashboard-side half of this PR's actual feature, not extractable without splitting an existing single-modal/single-canvas component mid-feature. open-sse/executors/base.ts 1578->1623 (+45) is NOT this PR's change — confirmed via `git diff upstream/release/v3.8.50 HEAD -- open-sse/executors/base.ts` (empty) — it is release/v3.8.50's own pre-existing drift past its frozen cap, inherited via this branch's rebase onto the current release tip; rebaselined here only because check:file-size runs against the full merged tree and this PR's rebase is what surfaced it. Covered by tests/unit/conversationTracker.test.ts, agenticConversations.test.ts, multiRowConversation.test.ts, request-timeline-lane-allocation.test.ts, stream-payload-collector.test.ts. Structural shrink of RequestLoggerDetail.tsx/RequestTimeline.tsx tracked in #3501.", "cap": 1000, "testCap": 1000, "testFrozen": { @@ -404,7 +404,7 @@ "src/shared/components/analytics/charts.tsx": 1035, "src/shared/services/cliRuntime.ts": 1122, "src/sse/handlers/chat.ts": 1868, - "src/shared/components/RequestLoggerDetail.tsx": 1241, + "src/shared/components/RequestLoggerDetail.tsx": 1256, "src/shared/components/RequestTimeline.tsx": 1037, "src/sse/services/auth.ts": 2508, "tests/unit/account-fallback-service.test.ts": 1572, diff --git a/docs/reference/ENVIRONMENT.md b/docs/reference/ENVIRONMENT.md index 1bf2f0f064..765b34aecb 100644 --- a/docs/reference/ENVIRONMENT.md +++ b/docs/reference/ENVIRONMENT.md @@ -723,6 +723,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` | Whole request/response body size (KB) before it's replaced by a bare summary instead of the full clone. Raise this if long agentic conversations show a placeholder instead of the real messages in the dashboard. | | `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 666e483fef..3b42e25a15 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. + * getChatLogMaxBodyBytes() (default 1MB; CHAT_LOG_MAX_BODY_KB env override), + * return a lightweight summary instead of the full clone. This prevents + * persistAttemptLogs from holding unbounded 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,12 @@ 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 maxBytes = getChatLogMaxBodyBytes(); + // Pass maxBytes as the early-exit point — otherwise estimateSizeFast's own + // default 256KB early-exit caps what it can ever report, silently making + // any configured threshold above 256KB unreachable (#trunc-limit-config). + const estimatedSize = estimateSizeFast(value, maxBytes); + if (estimatedSize <= maxBytes) 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 ac320f9aad..6bc578b1b6 100644 --- a/open-sse/utils/estimateSize.ts +++ b/open-sse/utils/estimateSize.ts @@ -1,9 +1,14 @@ /** * Fast object-tree size estimator — walks without JSON.stringify. * Safe for circular references (uses WeakSet). - * Early-exits at 256KB to avoid wasting CPU on huge payloads. + * Early-exits once `bytes` crosses `earlyExitAt` (default 256KB) to avoid + * wasting CPU on huge payloads — the caller only needs "is this over my + * threshold", not an exact total for values that are already way over it. + * 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. */ -export function estimateSizeFast(value: unknown): number { +export function estimateSizeFast(value: unknown, earlyExitAt = 262144): number { let bytes = 0; const stack: unknown[] = [value]; const seen = new WeakSet(); @@ -12,7 +17,7 @@ export function estimateSizeFast(value: unknown): number { if (v === null || v === undefined) continue; if (typeof v === "string") { bytes += v.length; - if (bytes > 262144) return bytes; + if (bytes > earlyExitAt) return bytes; } else if (typeof v === "number") bytes += 8; else if (typeof v === "boolean") bytes += 4; else if (typeof v === "object") { @@ -22,7 +27,8 @@ export function estimateSizeFast(value: unknown): number { for (let i = 0; i < v.length; i++) stack.push(v[i]); } else { for (const key in v) { - if (Object.prototype.hasOwnProperty.call(v, key)) stack.push((v as Record)[key]); + if (Object.prototype.hasOwnProperty.call(v, key)) + stack.push((v as Record)[key]); } } } diff --git a/src/lib/logEnv.ts b/src/lib/logEnv.ts index 8486628b4e..cee425a9c0 100644 --- a/src/lib/logEnv.ts +++ b/src/lib/logEnv.ts @@ -158,6 +158,23 @@ export function getChatLogMaxObjectKeys(): number { return parseNonNegativeInt(process.env.CHAT_LOG_MAX_OBJECT_KEYS, 80); } +/** + * Cap for a single logged request/response body before it gets replaced by a + * bare {_truncated, _originalBytes, messageCount, ...} summary instead of the + * full clone (open-sse/handlers/chatCore/logTruncation.ts::truncateForLog()). + * Was a hardcoded 8KB — trivially exceeded by any real multi-turn agentic + * conversation, which meant the dashboard's "Full Conversation" transcript + * panel could only ever show a placeholder instead of the actual messages + * for nearly every logged row. Bumped 128x (to 1MB) by default and exposed + * as an operator override for anyone who needs it even larger (or smaller, + * on a memory-constrained box) — see the same "protect memory across many + * call sites per request" reasoning truncateForLog()'s own doc comment + * explains for why some cap must still exist. + */ +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/src/shared/components/RequestLoggerDetail.tsx b/src/shared/components/RequestLoggerDetail.tsx index c50472d2b6..c8ea965bd9 100644 --- a/src/shared/components/RequestLoggerDetail.tsx +++ b/src/shared/components/RequestLoggerDetail.tsx @@ -254,7 +254,11 @@ function ConversationTranscriptSection({
)} +
+
+ Conversation +
+ {detail?.sessionTag || log.sessionTag ? ( +
+ {(detail?.sessionTag || log.sessionTag).slice(0, 20)}\u2026 +
+ ) : ( +
\u2014
+ )} +
)} diff --git a/tests/unit/chatcore-log-truncation.test.ts b/tests/unit/chatcore-log-truncation.test.ts index 635ce34d23..5d4b31eded 100644 --- a/tests/unit/chatcore-log-truncation.test.ts +++ b/tests/unit/chatcore-log-truncation.test.ts @@ -134,7 +134,7 @@ test("truncateForLog summarizes oversized payloads instead of cloning", () => { provider: "openai", stream: true, // distinct object references so estimateSizeFast (WeakSet-dedup) counts each one - messages: Array.from({ length: 50000 }, () => ({ role: "user", content: "x".repeat(64) })), + messages: Array.from({ length: 50000 }, () => ({ role: "user", content: "x".repeat(500) })), contents: [{ a: 1 }], }; const summary = truncateForLog(huge) as Record; @@ -159,11 +159,11 @@ test("truncateForLog captures a message count for Responses API bodies too (inpu const huge = { model: "gpt-5", stream: true, - input: Array.from({ length: 400 }, () => ({ role: "user", content: "x".repeat(64) })), + input: Array.from({ length: 50000 }, () => ({ role: "user", content: "x".repeat(500) })), }; const summary = truncateForLog(huge) as Record; assert.equal(summary._truncated, true); - assert.equal(summary.messageCount, 400); + assert.equal(summary.messageCount, 50000); }); test("truncateForLog keeps a bounded `tools` field alive when the request is summarized", () => { @@ -200,7 +200,7 @@ test("truncateForLog keeps a bounded `tools` field alive when the request is sum model: "gpt-4o", provider: "openai", stream: true, - messages: Array.from({ length: 50000 }, () => ({ role: "user", content: "x".repeat(64) })), + messages: Array.from({ length: 50000 }, () => ({ role: "user", content: "x".repeat(500) })), tools, }; @@ -226,7 +226,7 @@ test("truncateForLog bounds an oversized `tools` array to the configured tail-it })); const huge = { model: "gpt-4o", - messages: Array.from({ length: 50000 }, () => ({ role: "user", content: "x".repeat(64) })), + messages: Array.from({ length: 50000 }, () => ({ role: "user", content: "x".repeat(500) })), tools: manyTools, }; diff --git a/tests/unit/estimateSizeFast.test.ts b/tests/unit/estimateSizeFast.test.ts index d84fc75086..12b9b72ea2 100644 --- a/tests/unit/estimateSizeFast.test.ts +++ b/tests/unit/estimateSizeFast.test.ts @@ -1,9 +1,8 @@ import test from "node:test"; import assert from "node:assert/strict"; -const { estimateSizeFast, isSmallEnoughForSemanticCache } = await import( - "../../open-sse/utils/estimateSize.ts" -); +const { estimateSizeFast, isSmallEnoughForSemanticCache } = + await import("../../open-sse/utils/estimateSize.ts"); test("estimateSizeFast returns 0 for null/undefined", () => { assert.equal(estimateSizeFast(null), 0); @@ -65,6 +64,31 @@ test("estimateSizeFast early-exits at 262144 bytes (256KB)", () => { assert.ok(result >= 262144, `Should early-exit, got ${result}`); }); +test("estimateSizeFast accepts a custom earlyExitAt so a raised caller threshold is actually reachable", () => { + // Bug: chatCore/logTruncation.ts's truncateForLog() compares estimateSizeFast's + // result against a configurable threshold (getChatLogMaxBodyBytes(), default + // 1MB) — but estimateSizeFast's own early-exit was hardcoded at 256KB. Many + // small chunks (the realistic shape — a message array) stop accumulating the + // instant the running total crosses the early-exit point, so with the old + // hardcoded 256KB exit the reported size could never signal "still under a + // 1MB threshold" for an object whose true size sits between the two. + const chunks = Array.from({ length: 6000 }, () => "x".repeat(100)); // ~600KB true size + const defaultResult = estimateSizeFast(chunks); + assert.ok( + defaultResult <= 262144 + 100, + `default earlyExitAt should stop accumulating around 256KB, got ${defaultResult}` + ); + const oneMbResult = estimateSizeFast(chunks, 1024 * 1024); + assert.ok( + oneMbResult > 262144, + `with a 1MB earlyExitAt, ~600KB of chunks must be measurable past the old 256KB cap, got ${oneMbResult}` + ); + assert.ok( + oneMbResult <= 1024 * 1024 + 100, + `should not exceed the true ~600KB size, got ${oneMbResult}` + ); +}); + test("estimateSizeFast handles mixed object/array nesting", () => { const data = { choices: [