fix(logging): widen the trace id so it can key call_logs - #14341
abhisheksharma2411 wants to merge 1 commit into
Conversation
`call_logs.id` is `id TEXT PRIMARY KEY` and is fed by the trace id chatCore mints for each attempt, which also pairs the row with its `request.started` dashboard event (diegosouzapw#13481). That id was `randomUUID().slice(0, 6)` — 6 hex chars, 24 bits, 16,777,216 values. The resulting collision is birthday-shaped against the rows already stored, not a concurrency race between simultaneous inserts: with N rows in the table every insert collides with probability N/2^24, which is ~1.6% at 268k rows and matches the reported handful of failures per hour under ordinary traffic. The losing insert throws inside `saveCallLogOperation`, which logs and swallows it, so the row disappears with no signal to the caller — call analytics, combo provider stats and cost rollups undercount with nothing but a container log line to show for it. Move the generator into `chatCore/traceId.ts` so the constraint is stated where the value is produced, and widen it to 16 hex chars (64 bits). That matches `randomHex(16)` in grok-web and `randomId(16)` in the OTEL exporter, keeps log lines short, and takes the same 268k-row collision probability to roughly 1.5e-14 per insert. Tests reproduce the silent drop through the real save path (the second write is lost and `saveCallLog` still resolves), assert the id width and charset, and draw 200k ids without a duplicate. Reverting the width to 6 fails the latter two with a real collision; dropping the dash-strip fails the charset assertion. Fixes diegosouzapw#14338
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.
|
CI is red on this PR and none of it comes from this change. I chased it properly rather than asserting it, because the sibling PR #14356 (same base, dashboard files only) is fully green, which made "pre-existing" look like a weak excuse. The diff touches four files: Why the two PRs differ. The fast path is impact-selected — Verified by running the failures on a clean
Nine of eleven, failing with nothing of mine applied. The The remaining two are not mine either:
Worth flagging separately: shard membership is a function of the file list, so adding any test file re-partitions all four shards and can surface order-dependent failures that have nothing to do with the change. That is a property of Local verification of the change itself is unchanged from the description: the new suite is 3 pass / 0 fail, mutation-tested 3/3, and Happy to rebase if #14331 (the base-red drain) lands first and you'd rather see a clean matrix. |
|
Your diagnosis landed first and it was the correct one — the 24-bit id space, On the code, I'm recommending #14474 as the one to merge: it decouples the primary key from the |
…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>
|
Agreed on all of it — closing in favour of #14474, and thank you for the credit offer, though the analysis being useful is enough. Your second point is the one worth me writing down, because it's a defect in how I wrote the test rather than a preference:
That's correct, and it's worse than it looks. The test is called "a duplicate call-log id is dropped silently, not surfaced" and it asserts The lesson I'm taking: a test that documents current-broken behaviour needs to say so in its name and its assertion message, or it becomes a defence of the bug. Something like Your first point stands too. Widening 24 → 64 bits takes the collision probability from ~1.6% at 268k rows to ~1.5e-14, which fixes the arithmetic while leaving I've left a review on #14474. One finding there worth flagging here since it touches the same seam: Closing this. No wasted effort from my side — thanks for reading the analysis carefully enough to find the test problem in it. |
…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>
…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>
…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>
Fixes #14338.
The id is 24 bits, and it is a primary key
call_logs.idisid TEXT PRIMARY KEY. The value written to it is the trace id chatCore mints for each attempt:Six hex characters — 16,777,216 values. That id was introduced as a log-correlation token (its own comment said so: "this id is a log-correlation token, not a security secret"), and #13481 later made it the
call_logsrow key so each combo attempt gets its own row and pairs with itsrequest.starteddashboard event. The width was never revisited for the second job.It is not a concurrency race
The report's suggested repro — fire ~50 parallel requests — is the wrong experiment, and worth correcting because it makes the bug look load-dependent when it isn't. Two inserts in the same millisecond are not required. The collision is birthday-shaped against every row already stored: with N rows in the table, each new insert collides with probability N / 2²⁴.
call_logsThat is exactly the reported shape — 8 failures in a 1-hour window under normal workload on a container whose table holds a few hundred thousand rows — and it explains why it reads as "periodic bursts": the bursts are just where the requests are, not where the contention is. It also means the rate grows as the table fills and drops after rotation, which no amount of insert serialisation would change.
Why the row vanishes silently
The losing insert throws inside
saveCallLogOperation, and thecatchlogs and swallows:saveCallLogstill resolves, so nothing upstream can tell. The chat completion succeeds; only the analytics row is gone — which is why it surfaces as under-counted combo provider stats and cost rollups rather than as an error.Reproduced first
The new test drives the real save path and shows the second write lost with
saveCallLogstill resolving happily:— the same line as the container log in the report.
Fix
Move the generator into
open-sse/handlers/chatCore/traceId.ts, so the constraint is written down where the value is produced rather than inferred from a call site 500 lines away, and widen it to 16 hex chars (64 bits):16 hex chars matches the width already used in this codebase —
randomHex(16)ingrok-web.ts,randomId(16)in the OTEL exporter — so[STAGE_TRACE]lines stay readable, and it takes the 268k-row collision probability from 1.6% to about 1.5 × 10⁻¹⁴ per insert.Deliberately not changed: the id remains a single value shared by
call_logs.id,request.startedandrequest.completed.resolveRequestLifecycleEvent's contract is that the rowidmirrors the paired event'straceId, so giving the row its own key would have broken dashboard pairing to fix an entropy problem.Checks
tests/unit/call-log-id-collision-14338.test.tstsc --noEmit)The single failure is
call-log-file-rotation.test.ts→ "orphan cleanup scans at most 100 candidates". I stashed the change and re-ran it on an otherwise cleanrelease/v3.8.51— it fails identically there, so it is a pre-existing base red and not this change.Mutation-tested 2/2:
TRACE_ID_HEX_CHARSback to6(the original id)0a7381) inside 200k draws.replace(/-/g, "")so a dash lands in the idThe 200k-draw test is sized so it fails ~certainly on a 24-bit id (P ≈ 1 by 50k draws) while staying non-flaky on 64 bits (P ≈ 1e-9 across the whole run).
One thing I did not fix
The swallow in
saveCallLogOperationmeans any future persistence failure is invisible the same way — a full disk, a locked DB, a schema drift. Widening the id removes the cause we know about, not the blind spot. Happy to follow up with a counter or a throttled warn if you'd like that separated out; it changes error-handling behaviour, so it didn't belong in a fix aimed at the collision itself.