Skip to content

fix(db): make call-log ids collision-free across module instances - #14343

Closed
sxh313 wants to merge 6 commits into
diegosouzapw:release/v3.8.51from
sxh313:fix/call-log-id-collision
Closed

sxh313 wants to merge 6 commits into
diegosouzapw:release/v3.8.51from
sxh313:fix/call-log-id-collision

Conversation

@sxh313

@sxh313 sxh313 commented Sep 21, 2026 •

Copy link
Copy Markdown
Contributor

Summary

generateLogId() in src/lib/usage/callLogs.ts built call-log ids as `${Date.now()}-${logIdCounter}` where logIdCounter is a module-level counter. Two independent instances of that module - worker threads, separate route bundles, anything that evaluates the file twice - both start at 0, so a call logged by each in the same millisecond produces byte-identical ids. call_logs.id is UNIQUE, so SQLite rejected the second insert and the surrounding catch only logs a line: the row was lost silently. Closes #14338.

Motivation

Reported from a production container: 8 [callLogs] Failed to save call log: SqliteError: UNIQUE constraint failed: call_logs.id lines in one hour, in bursts coinciding with high-concurrency traffic (chat fan-out, sub-agents). Consequences are invisible at the request layer - the completion succeeds - and land in analytics: call_logs undercounts, so #12832's provider-stats reads and the $/day cost rollups are computed over a subset that "is not recoverable", as the reporter put it.

The counter never helped in the first place: within one instance a timestamp plus a counter is fine, and that is exactly the case that was already safe. It only appears unique, and the failure mode is the multi-instance case that the counter cannot cover.

What changed

One expression, no schema, no migration, no read-path change:

function generateLogId() {
  // The millisecond prefix keeps ids readable and roughly time-ordered; the
  // suffix has to be unique per call, not per process. ... See #14338.
  return `${Date.now()}-${randomUUID()}`;
}
  • Option 1 from the issue (crypto.randomUUID()), with the Date.now() prefix kept so existing ids keep the same rough shape and text ordering, and so any human reading a log line still sees the millisecond.
  • The now-unused let logIdCounter = 0; is removed with it.
  • The id is also embedded in a filename, and that was checked: buildArtifactRelativePath
    (src/lib/usage/callLogArtifacts.ts:112-118) writes YYYY-MM-DD/<iso-with-dashes>_<id>.json. The new
    id is 13 digits, one hyphen and a 36-character UUID, i.e. digits, hyphens and hex only - no :, /
    or other character that is unsafe in a path on Windows or POSIX, ~50 characters so no length limit is
    approached, and strictly less collision-prone than before, which matters because the filename is the
    artifact's identity.
  • Ids remain opaque strings; getCallLogById, the artifact/detail loaders and log export treat them as keys only, so no read path parses the id. Checked two ways: grep -rn "id.split\|parseInt(.*id\|Number(.*logId" src/lib/usage/ src/lib/db/ src/app/api/v1/ returns no call-log id parsing, and the full call-log and log-export suites pass unchanged.

How to test

New regression test reproduces the production shape rather than poking the generator: it imports the writer twice (two independent module instances, as two workers are), points both at one temp DATA_DIR SQLite file, freezes the clock inside one millisecond, and writes through the public saveCallLog().

# red, before the change
$ node --import tsx/esm --test tests/unit/call-log-id-generator-collision-14338.test.ts
AssertionError [ERR_ASSERTION]: both call logs must persist, got ["1758470400000-1"]
1 !== 2

One of the two logs was already gone by the time the test looked - the exact silent drop from the container log.

# green, after the change
$ node --import tsx/esm --test tests/unit/call-log-id-generator-collision-14338.test.ts
tests 1  pass 1  fail 0

# every call-log suite (23 files, incl. cap, artifacts, error-type, worker, retention)
$ node --import tsx/esm --test tests/unit/call-log-*.test.ts
tests 97  pass 97  fail 0

# the other readers/writers of call_logs
$ node --import tsx/esm --test tests/unit/*log-export*.test.ts
tests 62  pass 62  fail 0

$ npx prettier --check src/lib/usage/callLogs.ts tests/unit/call-log-id-generator-collision-14338.test.ts
All matched files use Prettier code style!

ESLint note so CI noise is not attributed here: bare npx eslint on src/lib/usage/callLogs.ts reports exactly one problem, 'DeleteResult' is defined but never used, which is pre-existing and already frozen in config/quality/eslint-suppressions.json:1722 as no-unused-vars: { count: 1 } for that file. The count does not grow with this change (the only symbol removed was logIdCounter, which was used only by the replaced line), and npm run lint applies the suppression layer.

Base: release/v3.8.51 at 34113170f (highest active release/v*, the repo default).

Relationship to #14341 (found while re-auditing my own claims)

#14341, opened eleven minutes before this PR, also cites #14338 and adds a test at the path this PR
originally used. It is a different fix, not a duplicate of it: it widens the trace id handling in
open-sse/handlers/chatCore/traceId.ts, while this PR changes generateLogId() in
src/lib/usage/callLogs.ts, which #14341 does not touch. Because two open PRs adding the same file path
would conflict for whichever merges second, this PR's test was renamed to
call-log-id-generator-collision-14338.test.ts (commits 8060b21e0, 4010b1c73; no behaviour change).
Merging both should be clean; if the maintainers would rather take one, the id-collision half is the one
that loses log rows today.

Migrations, feature flags, generated artifacts

A changelog fragment was added to this branch after I re-read CONTRIBUTING.md line 409: user-facing changes ship a file under the changelog directory rather than editing CHANGELOG.md, so this PR now carries one. It is the only addition beyond the fix and its test.

None. No schema change (option 2, INTEGER PRIMARY KEY, was not taken: it needs a migration plus read-path type coercion for every existing id consumer, and a UUID suffix removes the collision with none of that). Option 3 (INSERT OR IGNORE) was rejected for the reason the issue gives: it makes the loss silent instead of fixing it.

CI-only validation still pending

npm run typecheck:core, npm run lint, npm run test:unit, npm run test:vitest, the coverage ratchet and the ecosystem jobs run on the PR. Locally: the 97-test call-log family and the 62-test log-export family above, plus focused eslint/prettier. The full unit suite was not run locally.

base-red note

⚠️ base-red inherited: #13866 ("Release branch not green: release/v3.8.51") is open against this base; anything that also fails on 34113170f is inherited, not from this branch. The focused suites above are green on that tip.

generateLogId() combined Date.now() with a module-level counter, so two
instances of the writer - worker threads, separate route bundles - both starting
at 0 produced byte-identical ids inside the same millisecond. call_logs.id is
UNIQUE, the insert threw SqliteError and the surrounding catch only logged, so
the second call log was dropped silently and analytics undercounted. Keep the
millisecond prefix and make the suffix per-id with crypto.randomUUID(); the
counter is gone because it only protected the case that was already safe.
PR diegosouzapw#14341, filed eleven minutes before mine for the same issue, adds
tests/unit/call-log-id-collision-14338.test.ts for the trace-id widening half of diegosouzapw#14338. That is a
different fix, not a duplicate, but the identical file path would conflict whichever of the two merges
second, so this one is renamed. No behaviour change.
@diegosouzapw

Copy link
Copy Markdown
Owner

The hardening is correct and the cross-module-instance reasoning is sound, so thank you for it —
but it is not the surface that was failing in the report. The chat path passes an explicit
id: traceId (open-sse/handlers/chatCore/attemptLogging.ts:465), which takes precedence at
src/lib/usage/callLogs.ts:521, so generateLogId() is never reached there; the collisions in the
reporter's table come from randomUUID().slice(0, 6) at chatCore.ts:549.

I'm recommending #14474 to land, which already contains your generateLogId() change plus the
explicit-id fix. Since all three PRs edit the same two locations only one can land as-is, so this
one would be closed as subsumed rather than merged — if the owner prefers the minimal route
(#14341 for the trace id), yours becomes the required second half and we'd land the pair instead.

@sxh313

sxh313 commented Sep 22, 2026

Copy link
Copy Markdown
Contributor Author

Your trace is right, and I confirmed it against the base rather than from the comment. On release/v3.8.51 @ 8bf6b60a4:

  • open-sse/handlers/chatCore.ts:549 is still const traceId = globalThis.crypto.randomUUID().slice(0, 6); — a 6-hex-char token, ~16.7M space, so the reporter's duplicate-key table is expected behaviour, not a coincidence.
  • src/lib/usage/callLogs.ts:521 is id: typeof entry.id === "string" && entry.id.length > 0 ? entry.id : generateLogId(), so an explicit id always wins and generateLogId() is indeed unreachable on the chat path. My hardening therefore cannot fix the reported collisions on its own — it only makes the fallback branch unique.

I read #14474's diff: it removes the slice(0, 6) truncation, keys the row on a fresh UUID from saveCallLog, keeps traceId as correlationId, and retries when an explicit id still hits UNIQUE. That is the complete fix and it subsumes what is in this branch, so please do not hold up #14474 for mine.

I will not add commits here — all three PRs edit the same two locations, so the useful thing I can do is stay out of the way. Your call on routing, and I will act on it either way: land #14474 and I will close this one as subsumed myself, or take the minimal route (#14341) and I will re-push this branch as the second half.

@sxh313

sxh313 commented Sep 25, 2026

Copy link
Copy Markdown
Contributor Author

Closing this as subsumed — the routing question from your 2026-09-22 review comment resolved itself in favour of #14474, and the minimal-route alternative #14341 was closed without merging, so the "this branch becomes the required second half" branch never opened.

Measured against the current base, not from memory:

$ gh api repos/diegosouzapw/OmniRoute/pulls/14474 -q '"\(.user.login) \(.merged) \(.merged_at)"'
HouMinXi true 2026-09-25T16:25:50Z

$ gh api "repos/diegosouzapw/OmniRoute/contents/src/lib/usage/callLogs.ts?ref=86870a8233355de977c064781da6c02d62e5d188" -q .content | base64 -d | grep -n -A2 'function generateLogId'
142:function generateLogId() {
143-  return globalThis.crypto.randomUUID();
144-}

$ ... -q .content | base64 -d | grep -c 'logIdCounter'
0

The let logIdCounter = 0 module-level counter that this PR deleted is gone upstream, replaced by a per-call UUID — a strictly broader version of the same fix (mine kept a Date.now()- prefix, theirs does not need one), plus the retry path at :749 and the explicit-id precedence this PR could not reach. That is why mergeable_state flipped to dirty here: #14474's merge touched the exact lines this branch edits, which is the "only one can land as-is" condition spelled out in the review.

So I am not rebasing. Doing so would re-introduce a second, weaker implementation of a guard that already landed, in the same two locations the reviewer said only one PR may occupy.

The only part of this branch that upstream does not carry is tests/unit/call-log-id-generator-collision-14338.test.ts, which pins the cross-module-instance property. I am not re-opening it as a standalone test PR unilaterally; if a regression test for the collision property is still wanted on top of #14474, say so and I will re-push that file alone against the current base.

No code from this branch is being dropped silently — everything it fixed is already in release/v3.8.51.

@sxh313 sxh313 closed this Sep 25, 2026
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

fix(backend): call_logs.id UNIQUE constraint race on concurrent inserts

2 participants