diff --git a/CHANGELOG.md b/CHANGELOG.md index 31ad6f7ad7..2c4ca2b8f5 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -9,6 +9,7 @@ ### 🔧 Bug Fixes - **fix(api):** relay worker now binds the SSRF guard to a stable `const` name so minified standalone (Docker) builds resolve it ([#6149](https://github.com/diegosouzapw/OmniRoute/issues/6149)) — the Vercel/Deno relay generators embedded the shared `resolveRelayTarget` guard as a bare `${fn.toString()}` declaration while the worker body called the hardcoded literal name; SWC minification mangled the source function's name, so the deployed worker defined `` but still called `resolveRelayTarget` → `ReferenceError`. Both templates now emit `const resolveRelayTarget = ${fn.toString()};` (the const name is a template literal, immune to minification). Regression guard: `tests/unit/relay-minified-fn-6149.test.ts` (4). (thanks @SeaXen) +- **fix(backend):** call logs now record a **reasoning source/char-count** (migration 116, `reasoning_source`/`reasoning_chars`) for models that emit `reasoning_content`/`` but report zero reasoning tokens in usage, so `tokens_reasoning` no longer silently under-represents reasoning — cost math is unchanged (the priced `tokens_reasoning` stays usage-derived) ([#6187](https://github.com/diegosouzapw/OmniRoute/issues/6187)). Regression guard: `tests/unit/reasoning-token-source-6187.test.ts`. (thanks @andrea-kingautomation) - **fix(auth):** a stale/changed `STORAGE_ENCRYPTION_KEY` now surfaces as a clear **424 `storage_encryption_stale`** ("re-enter the API key") instead of a misleading "Auth failed: 401" — the connection's ciphertext failed to decrypt and was coerced to an empty Bearer, hiding the real cause ([#6148](https://github.com/diegosouzapw/OmniRoute/issues/6148)). Regression guard: `tests/unit/decrypt-stale-key-hint-6148.test.ts`. (thanks @chirag127) - **fix(backend):** memory injection now keeps the injected system message **first** for providers that require it (via a `PROVIDERS_SYSTEM_MUST_BE_FIRST` capability), instead of the cache-safe mid-array splice that made strict providers reject the request with a 400 ([#6135](https://github.com/diegosouzapw/OmniRoute/issues/6135)). Regression guard: `tests/unit/memory-system-first-6135.test.ts`. - **fix(services):** 9Router embed panel no longer 404s (optional catch-all route) and the supervisor probes the port before spawning to avoid raw EADDRINUSE ([#6205](https://github.com/diegosouzapw/OmniRoute/issues/6205)). Regression guards: `tests/unit/ninerouter-embed-port-6205.test.ts`, `tests/unit/services/ServiceSupervisor.test.ts`. (thanks @jonlwheat2-gif) diff --git a/src/lib/db/migrations/116_call_logs_reasoning_source.sql b/src/lib/db/migrations/116_call_logs_reasoning_source.sql new file mode 100644 index 0000000000..8cd507985c --- /dev/null +++ b/src/lib/db/migrations/116_call_logs_reasoning_source.sql @@ -0,0 +1,13 @@ +-- #6187: reasoning-token accounting is blind to reasoning_content / models. +-- Some providers (e.g. stepfun step-3.7-flash) emit reasoning content in the +-- assistant message but report reasoning_tokens=0 in usage, so the usage-derived +-- tokens_reasoning column under-represents reasoning. +-- +-- These two columns record reasoning PRESENCE/SOURCE and the raw CHARACTER count +-- of observed reasoning content. They are deliberately SEPARATE from the priced +-- tokens_reasoning column: reasoning_chars is a character count, NOT a token +-- count, and must never enter cost math. +-- reasoning_source: NULL | 'usage' | 'content' | 'think' +-- reasoning_chars : NULL when unknown, else raw char count of observed reasoning +ALTER TABLE call_logs ADD COLUMN reasoning_source TEXT DEFAULT NULL; +ALTER TABLE call_logs ADD COLUMN reasoning_chars INTEGER DEFAULT NULL; diff --git a/src/lib/usage/callLogs.ts b/src/lib/usage/callLogs.ts index 3c0cc5deb9..961cd0f8c2 100644 --- a/src/lib/usage/callLogs.ts +++ b/src/lib/usage/callLogs.ts @@ -18,6 +18,7 @@ import { getPromptCacheReadTokensOrNull, getPromptCacheCreationTokensOrNull, getReasoningTokensOrNull, + getObservedReasoning, } from "./tokenAccounting"; import { isNoLog } from "../compliance/noLog"; import { protectPayloadForLog, parseStoredPayload } from "../logPayloads"; @@ -240,6 +241,37 @@ function buildArtifact( }; } +// #6187: extract the assistant message from a chat-completion-shaped response +// body so we can inspect its reasoning_content / content. +function extractAssistantMessage(responseBody: unknown): unknown { + if (!responseBody || typeof responseBody !== "object") return responseBody; + const choices = (responseBody as JsonRecord).choices; + if (Array.isArray(choices) && choices.length > 0) { + const first = choices[0] as JsonRecord; + return first?.message ?? first?.delta ?? first; + } + return responseBody; +} + +// #6187: decide the reasoning SOURCE and (char-only) count recorded alongside +// the usage-derived tokens_reasoning. Usage is authoritative when it reports +// non-zero reasoning tokens; otherwise we fall back to observed reasoning +// content so "reasoned but metered 0" stays distinguishable. reasoning_chars is +// a CHARACTER count, never a token count — it must not touch cost math. +function resolveReasoningObservation( + usageReasoning: number | null, + responseBody: unknown +): { source: string | null; chars: number | null } { + if (usageReasoning != null && usageReasoning > 0) { + return { source: "usage", chars: null }; + } + const observed = getObservedReasoning(extractAssistantMessage(responseBody)); + if (observed.chars > 0) { + return { source: observed.source, chars: observed.chars }; + } + return { source: null, chars: null }; +} + function hasTable(tableName: string): boolean { const db = getDbInstance(); return Boolean( @@ -534,6 +566,10 @@ export async function saveCallLog(entry: any) { const nodePrefix = await resolveProviderPrefix(rawProvider); resolvedRequestedModel = applyNodePrefix(rawRequestedModel, rawProvider, nodePrefix); } + // #6187: usage-derived reasoning tokens stay UNCHANGED (cost math reads this), + // while reasoning source/char-count are recorded separately for observability. + const tokensReasoning = getReasoningTokensOrNull(entry.tokens); + const reasoningObservation = resolveReasoningObservation(tokensReasoning, entry.responseBody); const logEntry = { id: typeof entry.id === "string" && entry.id.length > 0 ? entry.id : generateLogId(), timestamp: typeof entry.timestamp === "string" ? entry.timestamp : new Date().toISOString(), @@ -550,7 +586,9 @@ export async function saveCallLog(entry: any) { tokensOut: toNumber(getLoggedOutputTokens(entry.tokens)), tokensCacheRead: getPromptCacheReadTokensOrNull(entry.tokens), tokensCacheCreation: getPromptCacheCreationTokensOrNull(entry.tokens), - tokensReasoning: getReasoningTokensOrNull(entry.tokens), + tokensReasoning, + reasoningSource: reasoningObservation.source, + reasoningChars: reasoningObservation.chars, tokensCompressed: entry.tokensCompressed != null ? toNumber(entry.tokensCompressed) : null, cacheSource: entry.cacheSource === "semantic" ? "semantic" : "upstream", requestType: entry.requestType || null, @@ -606,6 +644,7 @@ export async function saveCallLog(entry: any) { id, timestamp, method, path, status, model, requested_model, provider, account, connection_id, duration, tokens_in, tokens_out, tokens_cache_read, tokens_cache_creation, tokens_reasoning, tokens_compressed, + reasoning_source, reasoning_chars, cache_source, request_type, source_format, target_format, api_key_id, api_key_name, combo_name, combo_step_id, combo_execution_key, error_summary, detail_state, artifact_relpath, artifact_size_bytes, artifact_sha256, @@ -616,6 +655,7 @@ export async function saveCallLog(entry: any) { @id, @timestamp, @method, @path, @status, @model, @requestedModel, @provider, @account, @connectionId, @duration, @tokensIn, @tokensOut, @tokensCacheRead, @tokensCacheCreation, @tokensReasoning, @tokensCompressed, + @reasoningSource, @reasoningChars, @cacheSource, @requestType, @sourceFormat, @targetFormat, @apiKeyId, @apiKeyName, @comboName, @comboStepId, @comboExecutionKey, @errorSummary, @detailState, @artifactRelPath, @artifactSizeBytes, @artifactSha256, diff --git a/src/lib/usage/tokenAccounting.ts b/src/lib/usage/tokenAccounting.ts index 92dd83f21c..4131107902 100644 --- a/src/lib/usage/tokenAccounting.ts +++ b/src/lib/usage/tokenAccounting.ts @@ -93,6 +93,48 @@ export function getReasoningTokens(tokens: unknown): number { ); } +// Non-greedy, single-capture, no nested variable-length quantifiers → ReDoS-safe. +const THINK_BLOCK_RE = /([\s\S]*?)<\/think>/gi; + +/** + * Inspect an assistant message for reasoning/thinking content that the usage + * object may not have metered (#6187 — e.g. stepfun step-3.7-flash emits + * `reasoning_content` but reports `reasoning_tokens=0`). + * + * Returns the reasoning SOURCE and the raw CHARACTER count of the observed + * reasoning text. + * + * IMPORTANT: `chars` is a CHARACTER count, NOT a token count. It must NEVER be + * fed into cost math (`costCalculator` prices `tokens.reasoning`). It exists + * only so call logs can distinguish "reasoned but metered 0" from + * "did not reason at all" without corrupting billing. + */ +export function getObservedReasoning(message: unknown): { + source: "content" | "think" | null; + chars: number; +} { + const record = asRecord(message); + + // Explicit reasoning field: `reasoning_content` is the raw provider field; + // `reasoning` is what sseTextTransform maps it to. + const explicit = record.reasoning_content ?? record.reasoning; + if (typeof explicit === "string" && explicit.trim().length > 0) { + return { source: "content", chars: explicit.length }; + } + + // Inline ... blocks embedded in message content. + const content = record.content; + if (typeof content === "string" && content.length > 0) { + let chars = 0; + for (const match of content.matchAll(THINK_BLOCK_RE)) { + chars += (match[1] ?? "").length; + } + if (chars > 0) return { source: "think", chars }; + } + + return { source: null, chars: 0 }; +} + // ─── Nullable variants ────────────────────────────────────────────────── // Return `null` when the provider simply doesn't report the field, // vs `0` when the provider explicitly reported zero. diff --git a/tests/unit/reasoning-token-source-6187.test.ts b/tests/unit/reasoning-token-source-6187.test.ts new file mode 100644 index 0000000000..f95095a199 --- /dev/null +++ b/tests/unit/reasoning-token-source-6187.test.ts @@ -0,0 +1,149 @@ +/** + * Regression test for #6187 — reasoning-token accounting is blind to + * `reasoning_content` / `` models. + * + * Some providers (e.g. stepfun step-3.7-flash) emit reasoning content in the + * assistant message but report `reasoning_tokens=0` in usage. The usage-derived + * `tokens_reasoning` column then under-represents reasoning. The conservative + * fix records the reasoning SOURCE and raw CHARACTER count in two new, + * non-cost-touching columns (`reasoning_source`, `reasoning_chars`) while + * leaving `tokens_reasoning` (what cost math uses) untouched. + */ + +import test from "node:test"; +import assert from "node:assert/strict"; +import { getDbInstance, resetDbInstance } from "../../src/lib/db/core.ts"; +import { saveCallLog } from "../../src/lib/usage/callLogs.ts"; +import { getObservedReasoning } from "../../src/lib/usage/tokenAccounting.ts"; +import { computeCostFromPricing } from "../../src/lib/usage/costCalculator.ts"; + +test.after(() => { + try { + const db = getDbInstance(); + db.prepare("DELETE FROM call_logs WHERE id LIKE 'test-6187-%'").run(); + } catch { + // best-effort cleanup + } + try { + resetDbInstance(); + } catch { + // best-effort handle release (per DB-handle hang rule) + } +}); + +// ── getObservedReasoning helper ──────────────────────────────────────────── + +test("getObservedReasoning: reasoning_content field → source=content", () => { + const observed = getObservedReasoning({ reasoning_content: "Let me think about this." }); + assert.equal(observed.source, "content"); + assert.equal(observed.chars, "Let me think about this.".length); +}); + +test("getObservedReasoning: reasoning field (sse-mapped) → source=content", () => { + const observed = getObservedReasoning({ reasoning: "step one, step two" }); + assert.equal(observed.source, "content"); + assert.ok(observed.chars > 0); +}); + +test("getObservedReasoning: inline block → source=think", () => { + const observed = getObservedReasoning({ + content: "hidden chain of thoughtfinal answer", + }); + assert.equal(observed.source, "think"); + assert.equal(observed.chars, "hidden chain of thought".length); +}); + +test("getObservedReasoning: no reasoning → source=null, chars=0", () => { + const observed = getObservedReasoning({ content: "just a plain answer" }); + assert.equal(observed.source, null); + assert.equal(observed.chars, 0); +}); + +// ── Persistence: reasoning_content present but usage reports 0 ────────────── + +test("saveCallLog records reasoning_source=content when usage under-reports reasoning", async () => { + const db = getDbInstance(); + const testId = `test-6187-content-${Date.now()}`; + const reasoning = "The model reasoned internally but reported zero reasoning tokens."; + + await saveCallLog({ + id: testId, + method: "POST", + path: "/v1/chat/completions", + status: 200, + model: "step-3.7-flash", + provider: "stepfun", + duration: 100, + // usage EXPLICITLY reports reasoning_tokens=0 (the bug trigger) + tokens: { prompt_tokens: 10, completion_tokens: 20, reasoning_tokens: 0 }, + responseBody: { + choices: [{ message: { role: "assistant", content: "answer", reasoning_content: reasoning } }], + }, + }); + + const row = db + .prepare( + "SELECT tokens_reasoning, reasoning_source, reasoning_chars FROM call_logs WHERE id = ?" + ) + .get(testId) as { + tokens_reasoning: number | null; + reasoning_source: string | null; + reasoning_chars: number | null; + }; + + assert.ok(row, "row should exist"); + // Reasoning presence is now recorded from the message content... + assert.equal(row.reasoning_source, "content", "source should be content"); + assert.equal(row.reasoning_chars, reasoning.length, "char count should match reasoning content"); + // ...while the usage-derived, cost-relevant column stays exactly 0. + assert.equal(row.tokens_reasoning, 0, "tokens_reasoning stays usage-derived (0)"); + + // Cost math is untouched: reasoning_chars never enters cost; tokens.reasoning is 0. + const cost = computeCostFromPricing( + { input: 5, output: 10, reasoning: 100 }, + { prompt_tokens: 10, completion_tokens: 20, reasoning: 0 } + ); + const costNoReasoning = computeCostFromPricing( + { input: 5, output: 10, reasoning: 100 }, + { prompt_tokens: 10, completion_tokens: 20 } + ); + assert.equal(cost, costNoReasoning, "reasoning contributes 0 to cost when metered 0"); +}); + +// ── Regression: normal usage-reported reasoning keeps source=usage ────────── + +test("saveCallLog keeps reasoning_source=usage when usage reports reasoning tokens", async () => { + const db = getDbInstance(); + const testId = `test-6187-usage-${Date.now()}`; + + await saveCallLog({ + id: testId, + method: "POST", + path: "/v1/chat/completions", + status: 200, + model: "o3-mini", + provider: "openai", + duration: 100, + tokens: { + prompt_tokens: 5, + completion_tokens: 100, + completion_tokens_details: { reasoning_tokens: 57 }, + }, + responseBody: { + choices: [{ message: { role: "assistant", content: "answer" } }], + }, + }); + + const row = db + .prepare("SELECT tokens_reasoning, reasoning_source, reasoning_chars FROM call_logs WHERE id = ?") + .get(testId) as { + tokens_reasoning: number | null; + reasoning_source: string | null; + reasoning_chars: number | null; + }; + + assert.ok(row, "row should exist"); + assert.equal(row.reasoning_source, "usage", "usage-reported reasoning keeps source=usage"); + assert.equal(row.tokens_reasoning, 57, "tokens_reasoning stays usage-derived (57)"); + assert.equal(row.reasoning_chars, null, "no char count needed when usage is authoritative"); +});