fix(backend): record reasoning source for zero-metered reasoning models (#6187) (#6229)

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 `<mangled>` 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`/`<think>` 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)

src/lib/db/migrations/116_call_logs_reasoning_source.sql

@@ -0,0 +1,13 @@
+-- #6187: reasoning-token accounting is blind to reasoning_content / <think> 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;

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 / <think> 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,

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 = /<think>([\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 <think>...</think> 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.

tests/unit/reasoning-token-source-6187.test.ts

@@ -0,0 +1,149 @@
+/**
+ * Regression test for #6187 — reasoning-token accounting is blind to
+ * `reasoning_content` / `<think>` 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 <think> block → source=think", () => {
+  const observed = getObservedReasoning({
+    content: "<think>hidden chain of thought</think>final 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");
+});