diff --git a/src/app/api/logs/[id]/route.ts b/src/app/api/logs/[id]/route.ts index e632d36908..7c20cfb819 100644 --- a/src/app/api/logs/[id]/route.ts +++ b/src/app/api/logs/[id]/route.ts @@ -3,11 +3,22 @@ import { requireManagementAuth } from "@/lib/api/requireManagementAuth"; import { getCallLogById } from "@/lib/usageDb"; import { getCompletedDetails, getPendingById } from "@/lib/usage/usageHistory"; +// Each logged chunk-array element is one raw network read, timestamp-prefixed +// for the debug display — NOT one complete SSE `data:` line. A single JSON +// value (e.g. a `reasoning_content` delta) routinely splits across two or +// more elements, so parsing each element in isolation intermittently fails +// JSON.parse and silently drops that piece, leaving gaps that read as +// garbled/scrambled text once the survivors are concatenated. Strip each +// element's `[HH:MM:SS.mmm] ` prefix and concatenate the WHOLE array into one +// continuous string first, so a value split across elements rejoins correctly +// before it's parsed. +const CHUNK_LOG_TIMESTAMP_PREFIX = /^\[\d{2}:\d{2}:\d{2}\.\d{3}\]\s*/; + // Best-effort parse of the accumulated SSE `data:` lines captured live for an // in-flight request (open-sse/utils/requestLogger.ts's appendConvertedChunk // mutates these arrays in place as chunks arrive, so this reflects "the reply // so far", not just the final text) into the concatenated assistant text. -function extractPartialAssistantText( +export function extractPartialAssistantText( streamChunks: { provider?: string[]; openai?: string[]; client?: string[] } | null | undefined ): string { if (!streamChunks) return ""; @@ -15,20 +26,21 @@ function extractPartialAssistantText( if (!Array.isArray(chunkArr) || chunkArr.length === 0) continue; let text = ""; let reasoning = ""; - for (const raw of chunkArr) { - for (const line of String(raw).split("\n")) { - const idx = line.indexOf("data:"); - if (idx === -1) continue; - const jsonStr = line.slice(idx + 5).trim(); - if (!jsonStr || jsonStr === "[DONE]") continue; - try { - const parsed = JSON.parse(jsonStr); - const delta = parsed?.choices?.[0]?.delta ?? parsed?.choices?.[0]?.message; - if (typeof delta?.content === "string") text += delta.content; - if (typeof delta?.reasoning_content === "string") reasoning += delta.reasoning_content; - } catch { - // partial/malformed chunk line (e.g. cut mid-write) — skip it - } + const joined = chunkArr + .map((raw) => String(raw).replace(CHUNK_LOG_TIMESTAMP_PREFIX, "")) + .join(""); + for (const line of joined.split("\n")) { + const idx = line.indexOf("data:"); + if (idx === -1) continue; + const jsonStr = line.slice(idx + 5).trim(); + if (!jsonStr || jsonStr === "[DONE]") continue; + try { + const parsed = JSON.parse(jsonStr); + const delta = parsed?.choices?.[0]?.delta ?? parsed?.choices?.[0]?.message; + if (typeof delta?.content === "string") text += delta.content; + if (typeof delta?.reasoning_content === "string") reasoning += delta.reasoning_content; + } catch { + // partial/malformed chunk line (e.g. cut mid-write) — skip it } } if (text) return text; diff --git a/tests/unit/logs-detail-partial-reasoning-chunk-split.test.ts b/tests/unit/logs-detail-partial-reasoning-chunk-split.test.ts new file mode 100644 index 0000000000..34513c1791 --- /dev/null +++ b/tests/unit/logs-detail-partial-reasoning-chunk-split.test.ts @@ -0,0 +1,101 @@ +/** + * Regression test — the live "Generating… / Thinking…" preview in + * /api/logs/[id] read the request's in-flight stream-chunk log by parsing + * each logged chunk-array element independently. Each element is one raw + * network read (timestamp-prefixed for the debug display), not one complete + * SSE `data:` line, so a single JSON value (e.g. a `reasoning_content` delta) + * routinely splits across two or more elements. Parsing per-element in + * isolation intermittently fails JSON.parse and silently drops that piece, + * leaving gaps in the reconstructed text that read as garbled/scrambled + * reasoning once the survivors are concatenated — reported live via a + * dashboard screenshot showing exactly this on /dashboard/conversations. + */ +import test from "node:test"; +import assert from "node:assert/strict"; + +const { extractPartialAssistantText } = await import("../../src/app/api/logs/[id]/route.ts"); + +function chunkLine(timestamp: string, json: unknown): string { + return `[${timestamp}] data: ${JSON.stringify(json)}\n\n`; +} + +test("extractPartialAssistantText: reasoning_content split across two chunk-log entries reassembles cleanly", () => { + const fullDelta = "Let me analyze this conversation carefully to create a checkpoint."; + // Simulate the exact real-world failure: a raw network read boundary lands + // mid-JSON-string, so the JSON text for one `reasoning_content` delta value + // is split across two separately-timestamped chunk-log array elements. + const splitPoint = 30; + const firstHalfJson = JSON.stringify({ + choices: [{ delta: { reasoning_content: fullDelta.slice(0, splitPoint) } }], + }); + const secondHalfJson = JSON.stringify({ + choices: [{ delta: { reasoning_content: fullDelta.slice(splitPoint) } }], + }); + const splitAt = firstHalfJson.indexOf(fullDelta.slice(0, splitPoint)) + splitPoint; + + const chunkArr = [ + `[23:55:00.100] data: ${firstHalfJson.slice(0, splitAt)}`, + `[23:55:00.101] ${firstHalfJson.slice(splitAt)}\n\n`, + chunkLine("23:55:00.102", { choices: [{ delta: { reasoning_content: "" } }] }), + ]; + // The second delta value is itself split too, to prove multi-split survives. + const secondSplitAt = 10; + chunkArr.push(`[23:55:00.103] data: ${secondHalfJson.slice(0, secondSplitAt)}`); + chunkArr.push(`[23:55:00.104] ${secondHalfJson.slice(secondSplitAt)}\n\n`); + + const result = extractPartialAssistantText({ client: chunkArr }); + + assert.equal( + result, + `_Thinking…_\n\n${fullDelta}`, + "the reasoning text must reassemble whole, with no gaps from the split JSON values" + ); +}); + +test("extractPartialAssistantText: without concatenation-first, the split would silently drop reasoning text (documents the bug this test guards against)", () => { + // Direct demonstration of the OLD (buggy) per-element parsing behavior, so + // this test file also documents exactly what broke: parsing each element + // in isolation, a fragment split mid-JSON-string is unparseable on its own. + const fullDelta = "some reasoning text"; + const json = JSON.stringify({ choices: [{ delta: { reasoning_content: fullDelta } }] }); + const splitAt = Math.floor(json.length / 2); + const first = `[00:00:00.000] data: ${json.slice(0, splitAt)}`; + const second = `[00:00:00.001] ${json.slice(splitAt)}`; + + const oldBuggyParse = (raw: string): string | null => { + const idx = raw.indexOf("data:"); + if (idx === -1) return null; + try { + JSON.parse(raw.slice(idx + 5).trim()); + return "parsed"; + } catch { + return null; + } + }; + + assert.equal(oldBuggyParse(first), null, "first fragment alone is not valid JSON"); + assert.equal(oldBuggyParse(second), null, "second fragment alone is not valid JSON either"); + + // But the fixed function, which concatenates before parsing, recovers it fully. + const result = extractPartialAssistantText({ client: [first, second] }); + assert.equal(result, `_Thinking…_\n\n${fullDelta}`); +}); + +test("extractPartialAssistantText: content (not just reasoning) also survives a chunk-log split", () => { + const fullText = "The answer is forty-two."; + const json = JSON.stringify({ choices: [{ delta: { content: fullText } }] }); + const splitAt = Math.floor(json.length / 2); + const chunkArr = [ + `[10:00:00.000] data: ${json.slice(0, splitAt)}`, + `[10:00:00.001] ${json.slice(splitAt)}`, + ]; + + const result = extractPartialAssistantText({ provider: chunkArr }); + assert.equal(result, fullText); +}); + +test("extractPartialAssistantText: no reasoning/content anywhere returns empty string", () => { + assert.equal(extractPartialAssistantText(null), ""); + assert.equal(extractPartialAssistantText({}), ""); + assert.equal(extractPartialAssistantText({ client: [] }), ""); +});