Skip to content

fix(call_logs): prevent primary key collisions on retry and fallback attempts - #14474

Merged
diegosouzapw merged 5 commits into
diegosouzapw:release/v3.8.51from
HouMinXi:fix/call-logs-traceid-unique
Sep 25, 2026
Merged

diegosouzapw merged 5 commits into
diegosouzapw:release/v3.8.51from
HouMinXi:fix/call-logs-traceid-unique

Conversation

@HouMinXi

@HouMinXi HouMinXi commented Sep 22, 2026 •

Copy link
Copy Markdown
Contributor

Description

A 6-character slice of crypto.randomUUID() was stored as call_logs.id. That is a 24-bit key on a TEXT PRIMARY KEY. Against the rows already in the table, a new attempt collides and SQLite drops it with UNIQUE constraint failed: call_logs.id. An explicit id that is already taken fails the same way. This is a birthday collision against stored rows, not a concurrency race. That diagnosis was already in #14341, about 14 hours before #14451.

  • Use the full crypto.randomUUID() for the request trace in chatCore.ts.
  • persistAttemptLogs no longer uses traceId as the primary key. The dashboard correlation token is unchanged.
  • saveCallLog catches UNIQUE on an explicit id and retries once with a generated UUID instead of dropping the row.
  • Regression coverage is in tests/unit/call-logs-id-collision.test.ts.

One handleChatCore invocation does not persist twice at the current tip. Of the 16 persistAttemptLogs call sites, 14 return immediately and the other two are mutually exclusive branches. The test calls persistAttemptLogs twice directly to show that a shared dashboard traceId no longer means a shared primary key.

Production reports of UNIQUE constraint failed: call_logs.id came from @VIPKaiser in #14338.

Fixes #14451

Verification

  • tests/unit/call-logs-id-collision.test.ts: 4/4 PASS
  • tests/unit/chatcore-attempt-logging.test.ts: 7/7 PASS
  • tests/unit/attempt-logging-early-keepalive-merge.test.ts: 4/4 PASS
  • tests/unit/video-bridge-log-redaction.test.ts: 7/7 PASS
  • Combined: 22/22 PASS
  • npm run typecheck:core: clean on the previous head. This follow-up only drops a duplicate after(), replaces a stale comment, and credits the changelog.

#14341 and #14343 touch the same two locations. Only one of the three can land as-is.

Maintainer rework (merge-batch 2026-09-24)

  • Merged release/v3.8.51 into the branch (clean).
  • Confirmed the early-keepalive poll fix (d99a77f): video-bridge-log-redaction.test.ts is 13/13 with it.
  • Restored pendingRequestId: ctx.pendingRequestId on the saveCallLog entry in persistAttemptLogs. It is not the row key; saveCallLog uses it to route token usage to the live in-memory request row (fix(dashboard): retain token usage for in-memory request rows #14324). Without it, call-log-in-memory-usage.test.ts "chat attempt logging connects its trace id to the live pending request id" fails (red on the merged tree, green after the fix).
  • Validation: 554 tests across every unit file that touches call-log persistence / trace ids, typecheck:core, open-sse typecheck, eslint on the changed files, file-size.
  • Still open for the squash: Co-authored-by for @abhisheksharma2411 (fix(logging): widen the trace id so it can key call_logs #14341 carried the same diagnosis first). The "second mechanism" in the body (one handleChatCore persisting twice) was not reproducible at the tip.

@HouMinXi

Copy link
Copy Markdown
Contributor Author

Code Review Status

  • Commit: b66f298f7b
  • Forge Review Pipeline:
    • 3 Passes: qodo, expert, adversarial (all completed)
    • Product Findings: 0 CONFIRMED
    • Status: Clean
  • Test Matrix:
    • tests/unit/call-logs-id-collision.test.ts: 4/4 PASS
    • tests/unit/chatcore-attempt-logging.test.ts: 7/7 PASS
    • tests/unit/attempt-logging-early-keepalive-merge.test.ts: 4/4 PASS
    • tests/unit/video-bridge-log-redaction.test.ts: 7/7 PASS
    • Combined suite: 22/22 PASS

@diegosouzapw

Copy link
Copy Markdown
Owner

This is the right shape and the one I'd like to land of the three — decoupling the primary key from
the trace id fixes the actual cause rather than widening it, and the generateLogId() change closes
the second surface at the same time. Two credit items before merge, though: PR #14341
(@abhisheksharma2411) already carried this exact diagnosis — 24-bit id space, id TEXT PRIMARY KEY,
the birthday-against-stored-rows table, and the explicit "this is not a concurrency race" — about 14
hours before #14451 was filed, so a Co-authored-by trailer for him belongs on the squash, and
@VIPKaiser's production evidence in #14338 should get a changelog credit.

Three small things: tests/unit/call-logs-id-collision.test.ts registers after() twice (double
resetDbInstance); the #13481 comment above the now-idless saveCallLog call is stale; and the
second mechanism in the body ("one handleChatCore invocation persists more than once, giving a
deterministic UNIQUE") does not reproduce at the tip — 14 of the 16 persistAttemptLogs call sites
are immediately followed by return and the other two are mutually exclusive branches, and your own
test proves it by calling persistAttemptLogs twice directly rather than by driving chatCore.
Either drop that claim or point at the real double-persist path. Note also that #14341 and #14343
touch the same two locations, so only one of the three can land as-is.

@HouMinXi

Copy link
Copy Markdown
Contributor Author

Addressed the three items, and the two credits.

  • Co-authored-by: Abhishek Sharma <abhicse24@gmail.com> is on the squash. The 24-bit id space, id TEXT PRIMARY KEY, birthday-against-stored-rows, and "not a concurrency race" were already in fix(logging): widen the trace id so it can key call_logs #14341.
  • Changelog fragment now credits @VIPKaiser's production UNIQUE constraint failed: call_logs.id reports in fix(backend): call_logs.id UNIQUE constraint race on concurrent inserts #14338.
  • Dropped the second after() in tests/unit/call-logs-id-collision.test.ts. One resetDbInstance remains.
  • Replaced the #13481 comment above the now-idless saveCallLog call. The primary key is a fresh UUID. correlationId still pairs the row with request.started.
  • Dropped the claim that one handleChatCore invocation persists more than once. I could not find that path at the tip: 14 of the 16 persistAttemptLogs sites return immediately, and the other two are mutually exclusive. The test still calls persistAttemptLogs twice directly, which is what it actually proves.

Head is ca22bb6b3e. The four related test files are 22/22.

Understood that #14341 and #14343 touch the same two locations, so only one of the three can land as-is.

@abhisheksharma2411 abhisheksharma2411 left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Hi @HouMinXi — I had a branch on this (#14341) and @diegosouzapw has picked yours, which I think is the right call: decoupling the primary key from the trace id closes #13099's surface at the same time, where widening the id (what mine did) leaves the column carrying two concerns. Went through this one properly rather than just standing down. It's a good change — the retry-on-UNIQUE for explicit ids is a nicer touch than I expected, and all four of your tests pass locally for me.

One thing I think is a genuine gap, and I ran it rather than eyeballing it.

correlationId || traceId makes the traceId → row link conditional

After this PR the only column carrying traceId is correlation_id, written as:

correlationId: correlationId || traceId,

correlationId is a caller-supplied parameter of handleChatCore (chatCore.ts:484, default null). When a caller does pass one, it wins, and traceId then lives on no column at all — while request.started / request.completed are still emitted with id: traceId. So the dashboard event and its row become unlinkable for exactly those requests.

Before this PR the link was unconditional, because call_logs.id was the traceId. So it's a narrow regression rather than a pre-existing gap.

Every test and fixture here passes correlationId: null — including dashboard-request-failed-redaction-probe.ts:74, which is why its new getCallLogs({ correlationId: traceId }) lookup at :103 finds the row. Nothing currently exercises the other branch.

I wrote a probe against your head (ca22bb6b) with a control, so it isn't just my reading of the code:

✔ CONTROL: with correlationId null, the row is findable by traceId
✔ PROBE:   with a caller-supplied correlationId, traceId is on no column at all
      row.id=540c8016-91a6-41f0-b17a-b098639e6242
      row.correlation_id=caller-supplied-abc
      traceId=22222222-2222-4222-8222-222222222222
      rows findable by traceId: 0

Happy to push the probe to your branch as a test if that's useful — say the word and it's yours, no credit needed.

On the fix, I'd lean toward a dedicated trace_id column over overloading correlation_id, for the same reason your PR is better than mine: correlation_id already means "the caller's identifier for this request", and making it sometimes mean "our internal trace token" is the two-concerns-in-one-column problem moved one column across. A trace_id column written unconditionally keeps the dashboard pairing exact and leaves correlation_id meaning one thing. If that's more surgery than you want here, correlationId ?? traceId wouldn't help (the issue is a non-null caller value), so the cheap version is probably storing traceId unconditionally somewhere and leaving correlation_id alone.

Two much smaller things

  • isCallLogIdCollision matches /UNIQUE constraint failed: call_logs\.id/i on the message as a fallback. That's fine today, but it's a string match on a driver message — worth a comment saying the code checks above it are the real path and this is the belt-and-braces, so nobody later "simplifies" it down to only the regex.
  • The retry comment says "Keep the already-written artifact path; only the SQLite primary key is regenerated." I couldn't find anywhere the artifact path is derived from the row id, so I believe this is correct — but since it's the one place where the row and its artifact could drift apart, a one-line assertion in the retry test that the retried row still opens its artifact would make that guarantee non-accidental.

Thanks for picking this up — and sorry for the duplicate effort, mine was open before the issue was filed and I didn't see yours until Diego pointed at it.

@HouMinXi
HouMinXi force-pushed the fix/call-logs-traceid-unique branch from 813d8e7 to d0debff Compare September 24, 2026 08:39
@maxmad64bis

Copy link
Copy Markdown
Contributor

Independent corroboration from a single-node production install (image deploy-v3.8.51-20260921, one Node process): 21 UNIQUE constraint failed: call_logs.id lines in two days (14 on 2026-09-23, 7 on 2026-09-24, latest 13:46Z today), against 32,681 6-char ids out of 35,567 call_logs rows. Each error is a silently dropped row while the chat itself succeeds, matching the birthday-collision mechanism in #14451 exactly.

This is the PR of the three I would like to see land: decoupling the primary key from the display token fixes the cause, and the retry-on-UNIQUE closes the residual surface instead of dropping the row. Supporting a merge.

@HouMinXi
HouMinXi force-pushed the fix/call-logs-traceid-unique branch from d0debff to 3dafb31 Compare September 24, 2026 15:16
HouMinXi and others added 3 commits September 24, 2026 13:14
…attempts

When requests retry or fallback, a 6-character trace id prefix used as
call_logs.id collides with rows already stored, and an explicit primary
key that is already taken drops the new row.

- Use full randomUUID for request trace identifiers in chatCore.
- In saveCallLog, catch UNIQUE on an explicit id and retry with a
  generated UUID instead of dropping the row.
- persistAttemptLogs no longer keys the row on traceId. The dashboard
  correlation token is unchanged.

The diagnosis (24-bit id space, id TEXT PRIMARY KEY, birthday collision
against stored rows, not a concurrency race) was already in diegosouzapw#14341.

Fixes diegosouzapw#14451

Co-authored-by: Abhishek Sharma <abhicse24@gmail.com>
Signed-off-by: Minxi Hou <houminxi@gmail.com>
…apw#14338)

Co-authored-by: diegosouzapw <8016841+diegosouzapw@users.noreply.github.com>
fd19e33016 switched pollForCallLog to a correlation-column lookup but left
this test polling by pendingRequestId, so the row (written under the
overridden correlationId) was never found and the test burned the full 30 s
poll deadline before failing. Align the lookup key with the ctx override.

Signed-off-by: Minxi Hou <houminxi@gmail.com>
@HouMinXi
HouMinXi force-pushed the fix/call-logs-traceid-unique branch from 2ae3de5 to d99a77f Compare September 24, 2026 18:47
…request

The primary-key change dropped pendingRequestId from the saveCallLog entry.
saveCallLog uses it (not the row id) to update token usage on the live
in-memory request row (diegosouzapw#14324), so the dashboard lost the counters of every
chat attempt. call-log-in-memory-usage.test.ts 'chat attempt logging connects
its trace id to the live pending request id' fails without this line.
@diegosouzapw
diegosouzapw merged commit 309d0a1 into diegosouzapw:release/v3.8.51 Sep 25, 2026
11 of 16 checks passed
diegosouzapw pushed a commit that referenced this pull request Sep 25, 2026
…14525)

Merged in the 2026-09-25 maintainer merge-batch — thank you for the contribution!

The maintainer rework applied to this branch (if any) is described in the "Maintainer rework (merge-batch)" section of the PR body. Re-validated in a combined tree with the other ready Track-B PRs (#14474, #14188, #14525, #14807, #14796) on the current `release/v3.8.51` tip:
- 182/183 focused node tests. The one red (`combo-skipped-reset-timing`) passes 1/1 when run on its own; it is a timing flake under devbox load 95.
- `typecheck:core`: 0 errors; the tests these PRs previously broke (video-bridge-log-redaction, quota-reset-timing, flagship-0day-discovery, provider-models-discovery-split) are all green in the combined tree.
diegosouzapw pushed a commit that referenced this pull request Sep 25, 2026
Merged in the 2026-09-25 maintainer merge-batch — thank you for the contribution!

The maintainer rework applied to this branch (if any) is described in the "Maintainer rework (merge-batch)" section of the PR body. Re-validated in a combined tree with the other ready Track-B PRs (#14474, #14188, #14525, #14807, #14796) on the current `release/v3.8.51` tip:
- 182/183 focused node tests. The one red (`combo-skipped-reset-timing`) passes 1/1 when run on its own; it is a timing flake under devbox load 95.
- `typecheck:core`: 0 errors; the tests these PRs previously broke (video-bridge-log-redaction, quota-reset-timing, flagship-0day-discovery, provider-models-discovery-split) are all green in the combined tree.
diegosouzapw pushed a commit that referenced this pull request Sep 25, 2026
Merged in the 2026-09-25 maintainer merge-batch — thank you for the contribution!

The maintainer rework applied to this branch (if any) is described in the "Maintainer rework (merge-batch)" section of the PR body. Re-validated in a combined tree with the other ready Track-B PRs (#14474, #14188, #14525, #14807, #14796) on the current `release/v3.8.51` tip:
- 182/183 focused node tests. The one red (`combo-skipped-reset-timing`) passes 1/1 when run on its own; it is a timing flake under devbox load 95.
- `typecheck:core`: 0 errors; the tests these PRs previously broke (video-bridge-log-redaction, quota-reset-timing, flagship-0day-discovery, provider-models-discovery-split) are all green in the combined tree.
diegosouzapw pushed a commit that referenced this pull request Sep 25, 2026
…l logs (#14810)

Maintainer rework: reconciled with release/v3.8.51 after #14795 (migration 190) landed — migration 191 now sits contiguous (temporary 190 KNOWN_GAPS reservation dropped), the INSERT keeps has_content/usage_provenance plus the optional resilience_actions column (spliced instead of a duplicated statement) and the #14474 id-collision retry loop, buildContinuationLogHooks takes (log, correlationId, resilience), and the resilience-actions parser moved to src/lib/usage/resilienceActionsParse.ts to keep callLogs.ts under the cap. Tests: 131/131 node (resilience-actions context/sink/notes/badges, migration-191, stream-recovery-trace-logging, call-log id-collision/persistence/reasoning/provenance) + 2/2 vitest UI badges; typecheck:core and check:open-sse-typecheck clean; check-file-size and check-migration-numbering OK. Thank you @maxmad64bis!
diegosouzapw pushed a commit that referenced this pull request Sep 25, 2026
)

Maintainer rework: reconciled with release/v3.8.51 after #14750/#14795/#14810/#14659 — migration 192 now follows 190/191 with no gap, the call_logs INSERT carries has_content/usage_provenance + added_wait_ms/added_wait_cause + the optional resilience_actions column and the #14474 id-collision retry, attempt logging keeps the fresh-UUID row key and reads the added wait late, opencode keeps both the served-account tracker and the park/throttle added-wait counters, the unused getAddedWaitPercentiles was dropped, and file-size-baseline.json was rebuilt from the tip with only this PR's own ceilings (opencode.ts, proxyFetch.ts, core.ts, RequestLoggerDetail.tsx) instead of rewinding unrelated entries. Tests: 133/133 focused (opencode-added-wait, applied-egress-key, egress-throttle, attempt-logging, call-log persistence/id-collision/provenance, resilience-actions); typecheck:core and check:open-sse-typecheck clean; check-file-size and check-migration-numbering OK. opencode-429-park-resume / opencode-429-pool-reselect fail identically on the pure release tip (inherited, not from this PR). Thank you @maxmad64bis!
fouadSalkini added a commit to fouadSalkini/OmniRoute that referenced this pull request Sep 26, 2026
Slice 2/3 rewrote open-sse/handlers/chatCore.ts from an older snapshot,
silently undoing four merged fixes. Rebuild the file as the base version
plus only this PR's own hunks: stripNonStreamingForwardedHeaders on the
non-streaming path and apiKeyInfo on the streaming headers meta.

Restored:
- handleChatCore -> withResilienceActionsContext -> handleChatCoreInner
  wrapper, previousResponseResumed handling, notePreviousResponseResumed
  and the three noteBufferedVerdictOutcome calls (diegosouzapw#14810)
- pendingRequestId in every trackPendingRequest call, the pipeline
  options and finalizeToolLoopError (diegosouzapw#14797)
- the full-UUID traceId and its collision comment (diegosouzapw#14474)
- correlationId on buildContinuationLogHooks (diegosouzapw#14793)
deptrai pushed a commit to deptrai/OmniRoute that referenced this pull request Sep 28, 2026
…iegosouzapw#14525)

Merged in the 2026-09-25 maintainer merge-batch — thank you for the contribution!

The maintainer rework applied to this branch (if any) is described in the "Maintainer rework (merge-batch)" section of the PR body. Re-validated in a combined tree with the other ready Track-B PRs (diegosouzapw#14474, diegosouzapw#14188, diegosouzapw#14525, diegosouzapw#14807, diegosouzapw#14796) on the current `release/v3.8.51` tip:
- 182/183 focused node tests. The one red (`combo-skipped-reset-timing`) passes 1/1 when run on its own; it is a timing flake under devbox load 95.
- `typecheck:core`: 0 errors; the tests these PRs previously broke (video-bridge-log-redaction, quota-reset-timing, flagship-0day-discovery, provider-models-discovery-split) are all green in the combined tree.
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 uses a 6-char UUID prefix as the primary key

4 participants