fix(api): log cache-hit search requests so cacheHitRate reflects real hits (#13928)

A cache-hit POST /v1/search response never wrote a call_logs row at all:
getOrCoalesce() short-circuits handleSearch() (the only place that called
saveCallLog() for search requests) on a hit, and route.ts never logged its
own row. getSearchAggregateStats() also identified cached rows via a
'duration < 5ms' latency heuristic instead of the real cache_source column.

- route.ts now logs its own call_logs row (cache_source='semantic') when
  getOrCoalesce() reports a cache hit.
- getSearchAggregateStats() now counts cache_source='semantic' rows
  instead of guessing from latency.
- Aligned the pre-existing #3500 DB-level test to the corrected contract
  (cache_source drives 'cached', not duration).

changelog.d/fixes/13928-search-cache-hit-log.md

@@ -0,0 +1 @@
+- fix(api): log cache-hit search requests so cacheHitRate reflects real hits (#13928)

src/app/api/v1/search/route.ts

@@ -39,6 +39,7 @@ import {
 import { getSettings } from "@/lib/db/settings";
 import { isProviderBlockedByIdOrAlias } from "@/shared/utils/noAuthProviders";
 import { withInjectionGuard } from "@/middleware/promptInjectionGuard";
+import { saveCallLog } from "@/lib/usageDb";
 
 const CORS_HEADERS = {
   "Access-Control-Allow-Methods": "GET, POST, OPTIONS",
@@ -119,6 +120,7 @@ function buildDomainFilter(filters?: {
  * POST /v1/search — execute a web search
  */
 async function postHandler(request: Request, context: unknown) {
+  const requestStartTime = Date.now();
   let rawBody: unknown;
   try {
     rawBody = await request.json();
@@ -379,6 +381,32 @@ async function postHandler(request: Request, context: unknown) {
       return result.data!;
     });
 
+    // A cache hit short-circuits handleSearch() entirely, so none of its
+    // saveCallLog() calls (open-sse/handlers/search.ts) ever run — log this
+    // hit's own call_logs row here, or it never gets counted (#13928).
+    if (cached) {
+      saveCallLog({
+        method: "POST",
+        path: "/v1/search",
+        status: 200,
+        model: providerConfig.id,
+        provider: providerConfig.id,
+        duration: Date.now() - requestStartTime,
+        requestType: "search",
+        cacheSource: "semantic",
+        tokens: { prompt_tokens: 0, completion_tokens: 0 },
+        requestBody: {
+          query: body.query.slice(0, 200),
+          search_type: body.search_type,
+          max_results: clampedMaxResults,
+        },
+        responseBody: { results_count: searchResult.results?.length ?? 0, cached: true },
+        apiKeyId: policy.apiKeyInfo?.id || undefined,
+      }).catch(() => {
+        /* non-critical — logging must not block search response */
+      });
+    }
+
     // Record cost for budget tracking (skip cache hits — no provider cost)
     if (!cached && policy.apiKeyInfo?.id && searchResult.usage?.search_cost_usd > 0) {
       try {

src/lib/db/callLogStats.ts

@@ -284,7 +284,7 @@ export function getSearchAggregateStats(todayIso: string): SearchAggregateStats
           COALESCE(SUM(CASE WHEN c.timestamp >= ? THEN 1 ELSE 0 END), 0) as today,
           COALESCE(SUM(CASE WHEN c.status >= 400 OR c.error_summary IS NOT NULL THEN 1 ELSE 0 END), 0) as errors,
           AVG(CASE WHEN c.duration > 0 THEN c.duration END) as avg_duration,
-          COALESCE(SUM(CASE WHEN c.duration > 0 AND c.duration < 5 THEN 1 ELSE 0 END), 0) as cached
+          COALESCE(SUM(CASE WHEN c.cache_source = 'semantic' THEN 1 ELSE 0 END), 0) as cached
          FROM call_logs c
          WHERE c.request_type = 'search'
           AND ${getSearchLiveProviderGuardSql()}`

tests/unit/db-call-log-stats-3500.test.ts

@@ -234,7 +234,9 @@ test("#3500 getSearchAggregateStats — correct totals, today, errors, avg, cach
 
   // Rows inserted after todayStart qualify as "today"
   const nowIso = new Date().toISOString();
-  // duration=0 → excluded from avg_duration; duration=3 → cached (>0 && <5)
+  // #13928: "cached" is driven by cache_source='semantic', not duration —
+  // this row's duration is deliberately >5ms to prove the fix no longer
+  // uses the old `duration < 5` latency heuristic.
   insertCallLog({
     provider: "brave",
     status: 200,
@@ -245,7 +247,8 @@ test("#3500 getSearchAggregateStats — correct totals, today, errors, avg, cach
   insertCallLog({
     provider: "brave",
     status: 200,
-    duration: 3,
+    duration: 50,
+    cache_source: "semantic",
     request_type: "search",
     timestamp: nowIso,
   });
@@ -271,7 +274,7 @@ test("#3500 getSearchAggregateStats — correct totals, today, errors, avg, cach
   assert.ok(result.total >= 4, "total includes all search rows (across all tests in file)");
   assert.ok(result.today >= 3, "today counts rows from today");
   assert.ok(result.errors >= 1, "errors counts status >= 400");
-  assert.ok(result.cached >= 1, "cached counts duration in (0,5)");
+  assert.ok(result.cached >= 1, "cached counts cache_source='semantic' rows (#13928)");
   assert.ok(result.avg_duration !== null, "avg_duration not null when rows have duration > 0");
 });
 

tests/unit/search-analytics-cache-hit-rate-13928.test.ts

@@ -0,0 +1,129 @@
+/**
+ * Issue #13928 — search analytics cacheHitRate was always 0%.
+ *
+ * Root cause had two layers:
+ *   1. A cache HIT on POST /v1/search never wrote a call_logs row at all
+ *      (getOrCoalesce() short-circuits handleSearch(), the only place that
+ *      called saveCallLog() for search requests) — fixed in
+ *      src/app/api/v1/search/route.ts (logs its own row when `cached`).
+ *   2. Even when a row existed, getSearchAggregateStats() identified
+ *      "cached" rows via a `duration < 5ms` latency heuristic instead of
+ *      the real `cache_source` column — fixed in src/lib/db/callLogStats.ts.
+ *
+ * This test covers layer 2 directly at the DB level with four real
+ * saveCallLog() rows chosen so the OLD `duration < 5` heuristic and the NEW
+ * `cache_source = 'semantic'` check disagree on the total `cached` count
+ * (not just on which row counts, so a coincidental count match can't mask
+ * the regression):
+ *   - TWO genuinely fast UPSTREAM calls (duration 1-2ms, cache_source=
+ *     'upstream') — the old heuristic would wrongly count both as cached.
+ *   - a coalesced-but-slower CACHE HIT (duration 50ms, cache_source='semantic')
+ *     — the old heuristic would wrongly exclude this.
+ *   - a normal slow upstream MISS (duration 250ms, cache_source='upstream')
+ *     — excluded by both the old and the new logic (sanity control).
+ * Old heuristic: cached=2 (the two fast rows, wrong). New: cached=1 (only
+ * the real hit, correct).
+ */
+import test from "node:test";
+import assert from "node:assert/strict";
+import fs from "node:fs";
+import os from "node:os";
+import path from "node:path";
+
+const TEST_DATA_DIR = fs.mkdtempSync(path.join(os.tmpdir(), "omni-db-search-cachehit-13928-"));
+process.env.DATA_DIR = TEST_DATA_DIR;
+
+const core = await import("../../src/lib/db/core.ts");
+const { saveCallLog } = await import("../../src/lib/usage/callLogs.ts");
+const { getSearchAggregateStats } = await import("../../src/lib/db/callLogStats.ts");
+
+test.after(() => {
+  core.resetDbInstance();
+  fs.rmSync(TEST_DATA_DIR, { recursive: true, force: true, maxRetries: 5, retryDelay: 100 });
+});
+
+function todayStartIso(): string {
+  const todayStart = new Date();
+  todayStart.setUTCHours(0, 0, 0, 0);
+  return todayStart.toISOString();
+}
+
+test("issue #13928: getSearchAggregateStats counts cache hits via cache_source, not latency", async () => {
+  // Fast upstream miss: the OLD `duration < 5` heuristic would wrongly
+  // count this as cached. cache_source is the real signal — it must not.
+  await saveCallLog({
+    id: "log-13928-fast-upstream",
+    method: "POST",
+    path: "/v1/search",
+    status: 200,
+    model: "duckduckgo-free",
+    provider: "duckduckgo-free",
+    duration: 1,
+    requestType: "search",
+    cacheSource: "upstream",
+    tokens: {},
+    requestBody: { query: "fast-upstream" },
+    responseBody: { results_count: 1, cached: false },
+  });
+
+  // A second fast upstream call — same effect as above, so the old
+  // heuristic's miscount (2) can't coincidentally match the correct
+  // cache-hit count (1) below.
+  await saveCallLog({
+    id: "log-13928-fast-upstream-2",
+    method: "POST",
+    path: "/v1/search",
+    status: 200,
+    model: "duckduckgo-free",
+    provider: "duckduckgo-free",
+    duration: 2,
+    requestType: "search",
+    cacheSource: "upstream",
+    tokens: {},
+    requestBody: { query: "fast-upstream-2" },
+    responseBody: { results_count: 1, cached: false },
+  });
+
+  // Coalesced cache hit that took longer than 5ms (e.g. joined an inflight
+  // request): the OLD heuristic would wrongly exclude this from `cached`.
+  await saveCallLog({
+    id: "log-13928-slow-hit",
+    method: "POST",
+    path: "/v1/search",
+    status: 200,
+    model: "duckduckgo-free",
+    provider: "duckduckgo-free",
+    duration: 50,
+    requestType: "search",
+    cacheSource: "semantic",
+    tokens: {},
+    requestBody: { query: "slow-hit" },
+    responseBody: { results_count: 1, cached: true },
+  });
+
+  // Normal slow upstream miss — excluded by both heuristics (sanity control).
+  await saveCallLog({
+    id: "log-13928-slow-miss",
+    method: "POST",
+    path: "/v1/search",
+    status: 200,
+    model: "duckduckgo-free",
+    provider: "duckduckgo-free",
+    duration: 250,
+    requestType: "search",
+    cacheSource: "upstream",
+    tokens: {},
+    requestBody: { query: "slow-miss" },
+    responseBody: { results_count: 1, cached: false },
+  });
+
+  const stats = getSearchAggregateStats(todayStartIso());
+  assert.equal(stats.total, 4);
+  assert.equal(
+    stats.cached,
+    1,
+    "only the cache_source='semantic' row must count as cached, regardless of duration"
+  );
+  const cacheHitRate = Math.round((stats.cached / stats.total) * 100);
+  assert.equal(cacheHitRate, 25);
+});

tests/unit/search-cache-hit-call-log-13928.test.ts

@@ -0,0 +1,105 @@
+/**
+ * Issue #13928 — a cache-hit POST /v1/search response never wrote a
+ * call_logs row, so search analytics cacheHitRate was always 0%.
+ *
+ * Root cause (confirmed by reading the real source):
+ *   - open-sse/services/searchCache.ts::getOrCoalesce() returns the cached
+ *     entry directly on a hit and never invokes the passed-in fetch
+ *     function.
+ *   - src/app/api/v1/search/route.ts passed the ENTIRE search execution
+ *     (handleSearch(), the only place that calls saveCallLog() for search
+ *     requests — open-sse/handlers/search.ts) as that fetch function.
+ *   - route.ts itself never called saveCallLog() on its own.
+ *   - So a cache HIT produced zero call_logs rows, regardless of any SQL
+ *     fix on the read side.
+ *
+ * This test drives the real POST handler twice with an identical body
+ * (miss then hit) and asserts BOTH requests produce a call_logs row for
+ * '/v1/search', with the second one carrying cache_source='semantic'.
+ */
+import test from "node:test";
+import assert from "node:assert/strict";
+import fs from "node:fs";
+import os from "node:os";
+import path from "node:path";
+
+const TEST_DATA_DIR = fs.mkdtempSync(path.join(os.tmpdir(), "omniroute-search-cachehit-13928-"));
+process.env.DATA_DIR = TEST_DATA_DIR;
+
+const core = await import("../../src/lib/db/core.ts");
+const { waitForCallLogSaves } = await import("../../src/lib/usage/callLogs.ts");
+const searchRoute = await import("../../src/app/api/v1/search/route.ts");
+
+test.after(() => {
+  core.resetDbInstance();
+  fs.rmSync(TEST_DATA_DIR, { recursive: true, force: true, maxRetries: 5, retryDelay: 100 });
+});
+
+test("issue #13928: a cache-hit /v1/search response logs its own call_logs row", async () => {
+  const originalFetch = globalThis.fetch;
+  let fetchCalls = 0;
+
+  const liteHtml = `<html><body>
+    <a href="https://example.com/cache-hit-result" class='result-link'>Cache hit fixture result</a>
+    <td class='result-snippet'>Fixture snippet</td>
+  </body></html>`;
+
+  globalThis.fetch = async () => {
+    fetchCalls++;
+    return new Response(liteHtml, { status: 200, headers: { "content-type": "text/html" } });
+  };
+
+  // No `provider` — mirrors PR #11097's contract: zero-credential /v1/search
+  // auto-promotes the fallback-only duckduckgo-free provider. An explicit
+  // `provider: "duckduckgo-free"` would instead route through
+  // getProviderCredentialsWithQuotaPreflight()'s live-network preflight.
+  const makeRequest = () =>
+    new Request("http://localhost/api/v1/search", {
+      method: "POST",
+      headers: { "Content-Type": "application/json" },
+      body: JSON.stringify({
+        query: "issue 13928 cache hit repro",
+        search_type: "web",
+      }),
+    });
+
+  try {
+    const missResponse = await searchRoute.POST(makeRequest());
+    const missBody = (await missResponse.json()) as { cached: boolean };
+    assert.equal(missResponse.status, 200);
+    assert.equal(missBody.cached, false, "first identical request must be a cache miss");
+
+    const hitResponse = await searchRoute.POST(makeRequest());
+    const hitBody = (await hitResponse.json()) as { cached: boolean };
+    assert.equal(hitResponse.status, 200);
+    assert.equal(hitBody.cached, true, "second identical request must be a cache hit");
+
+    // handleSearch() (and therefore the upstream fetch) must run exactly
+    // once — the hit must be served from cache, not by re-fetching.
+    assert.equal(fetchCalls, 1, "cache hit must not re-invoke the upstream provider");
+
+    const drained = await waitForCallLogSaves(15_000);
+    assert.ok(drained, "call log saves must drain before the assertions below");
+
+    const rows = core
+      .getDbInstance()
+      .prepare(
+        `SELECT status, cache_source FROM call_logs
+         WHERE path = '/v1/search' AND provider = 'duckduckgo-free'
+         ORDER BY timestamp ASC`
+      )
+      .all() as Array<{ status: number; cache_source: string }>;
+
+    assert.equal(
+      rows.length,
+      2,
+      "expected one call_logs row per client-facing request (1 miss + 1 hit), " +
+        `but got ${rows.length} — the cache-hit request never reached any code ` +
+        "path that calls saveCallLog()."
+    );
+    assert.equal(rows[0].cache_source, "upstream", "the miss row must be cache_source=upstream");
+    assert.equal(rows[1].cache_source, "semantic", "the hit row must be cache_source=semantic");
+  } finally {
+    globalThis.fetch = originalFetch;
+  }
+});