From 973bbac4379f49d58769ef1f1d9d50f1eae44667 Mon Sep 17 00:00:00 2001 From: diegosouzapw <8016841+diegosouzapw@users.noreply.github.com> Date: Mon, 21 Sep 2026 19:28:12 -0300 Subject: [PATCH] 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). --- .../fixes/13928-search-cache-hit-log.md | 1 + src/app/api/v1/search/route.ts | 28 ++++ src/lib/db/callLogStats.ts | 2 +- tests/unit/db-call-log-stats-3500.test.ts | 9 +- ...rch-analytics-cache-hit-rate-13928.test.ts | 129 ++++++++++++++++++ .../search-cache-hit-call-log-13928.test.ts | 105 ++++++++++++++ 6 files changed, 270 insertions(+), 4 deletions(-) create mode 100644 changelog.d/fixes/13928-search-cache-hit-log.md create mode 100644 tests/unit/search-analytics-cache-hit-rate-13928.test.ts create mode 100644 tests/unit/search-cache-hit-call-log-13928.test.ts diff --git a/changelog.d/fixes/13928-search-cache-hit-log.md b/changelog.d/fixes/13928-search-cache-hit-log.md new file mode 100644 index 0000000000..dd1615230b --- /dev/null +++ b/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) diff --git a/src/app/api/v1/search/route.ts b/src/app/api/v1/search/route.ts index ceb78643ec..02ba32ffe1 100644 --- a/src/app/api/v1/search/route.ts +++ b/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 { diff --git a/src/lib/db/callLogStats.ts b/src/lib/db/callLogStats.ts index 24debd628e..8059c33d85 100644 --- a/src/lib/db/callLogStats.ts +++ b/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()}` diff --git a/tests/unit/db-call-log-stats-3500.test.ts b/tests/unit/db-call-log-stats-3500.test.ts index 907b9c9306..f3d1857b59 100644 --- a/tests/unit/db-call-log-stats-3500.test.ts +++ b/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"); }); diff --git a/tests/unit/search-analytics-cache-hit-rate-13928.test.ts b/tests/unit/search-analytics-cache-hit-rate-13928.test.ts new file mode 100644 index 0000000000..48c772bee5 --- /dev/null +++ b/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); +}); diff --git a/tests/unit/search-cache-hit-call-log-13928.test.ts b/tests/unit/search-cache-hit-call-log-13928.test.ts new file mode 100644 index 0000000000..6e7df7af8b --- /dev/null +++ b/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 = ` + Cache hit fixture result + Fixture snippet + `; + + 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; + } +});