Fix #1464: Claude Code sessions recorded twice since OTEL attach: transcript backfill and OTEL lanes never dedupe - #1468
Conversation
…#1464) On an OTEL-attached machine both the telemetry listener and the transcript backfill sweep capture the same session. Content events carry `message.uuid`, so their rows already share identity with the sweep's. The blocks events do not carry - tool_use, tool_result, thinking - reach the OTEL lane only through a spooled body, which has no uuid, so the gateway synthesized a content hash for them while the sweep wrote the same block under the transcript line's uuid. The `part_id` dedupe LLP 0262 relies on never fired, and every tool call and its token usage was stored twice. Stamp the LLP 0027 match-key on the messages a spooled body produces, as the proxy projector already does for its fallback rows, so flush-time settlement upgrades them to the transcript uuid and the overlap collapses whichever lane wrote first. LLP 0389 records that a body-derived row is provisional and narrows LLP 0254 to the rows a content event produces. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
neutral review round 1 - findingsReviewed One MEDIUM finding, not fixed here and not a merge blocker. Nothing pushed.
VerdictThe fix does what it claims: the identity convergence is correct, the regression test is genuinely load-bearing, the LLP work follows the repo's discipline, and there is no CPU or memory concern. It eliminates the duplicated tool-call rows in every ordering. But collapsing those rows exposes a pre-existing disagreement between the two lanes about which row carries a turn's F1 (MEDIUM, not fixed) - the two lanes put
|
| text row from | tool row from | usage counted |
|---|---|---|
| OTEL | OTEL | 1x (correct) |
| sweep | sweep | 1x (correct) |
| OTEL | sweep | 2x (the pre-existing over-count, surviving) |
| sweep | OTEL | 0x (new) |
The same-lane rows are the common case, so the dominant outcome is the correct one and the PR is a clear net improvement. The 0x row needs a mixed commit order, which needs the cron sweep (backfill.sweep_cron) to observe a partial transcript - the text line written, the tool_use line not yet - so it commits the text row while the OTEL lane later wins the tool row. Narrow, but the sweep is cron-driven and can fire mid-turn.
Why not fixed here. The divergence lives entirely in code this diff does not touch, and it is a pre-existing violation of an Accepted LLP. Aligning the OTEL lane to one-carrier means moving usage off the assistant_response row onto the response's last block, which changes usage placement on a shipped lane and has to coordinate with messageFromEvent's usageByRequestId claim. That is its own decision with its own doc, not a rider on a part_id identity fix. Under CLAUDE.md ("land the small one and defer the rest") the right disposition is a tracked follow-up: concrete, consequential, and clearly outside this task. I have not filed it, since a review rung should not mint repo artifacts beyond this record - please raise it.
Two findings raised by a parallel reviewer that do not survive probing
Claimed: a new part_id collision drops the assistant's answer text when assistant_response's message.uuid names a non-text line (the thinking line of a thinking+text response), because the body-derived reasoning row now settles onto that same uuid. Refuted as attributed to this PR. I ran the premise with the body lane entirely absent - the event lane and the sweep only, i.e. unmodified master:
SWEEP rows: text <P>#0 | reasoning <U_THINK>#0 | text <U_TEXT>#0
OTEL EVENT-LANE rows only: text <P>#0 | text <U_THINK>#0
clash: <U_THINK>#0 - event lane says text, sweep says reasoning
If assistant_response's uuid really named a non-text line, the two already-shipped producers would already collide on it today, and the event row would already be inheriting the wrong parent_uuid and provenance. So the premise, if ever true, is a pre-existing event-lane identity defect that this PR neither creates nor worsens in kind. The underlying structural remark is fair and worth keeping on the record - part_type is not part of the dedupe key, so any part_id collision drops content silently - but it is not a defect of this diff, and claude_otel_shape_check is precisely the acceptance gate that would catch the upstream shape it depends on.
Claimed: a tool-only turn's usage is lost when the transcript tool_use line has no message.usage. Refuted at the premise. backfill.js:517-518 records, from real capture, that "usage is a response-level (per API message) figure that Claude Code duplicates onto every block line of an assistant turn" - that duplication is the entire reason the one-carrier rule exists. A transcript block line without message.usage is not a shape Claude Code produces, so that probe's fixture is synthetic. The valid concern underneath it is F1 above, which reaches the same "usage can go to zero" outcome by a different and real mechanism.
What I verified about the fix itself (all still holds)
Identity convergence. matchKey (transcripts.js:494) is the same call that builds the transcript index key (transcripts.js:690) and that settlement looks up (settle.js:148). Gap-message content is always [block] (bodies.js gapMessage), and Claude Code writes one transcript line per block - a premise already encoded here by findTranscriptMatch's "an API message split across several lines" note and by byMessageId being a list. Both sides canonicalize the same single-element array under the same role, and part_index is 0 on both, giving <uuid>#0 on both. Coverage is type-agnostic across all six GAP_BLOCK_TYPES (bodies.js:34); the PR names three as exemplars.
The rows really reach settlement. Gap messages carry no message_id, so resolveIdentity (message_projector.js:1053) returns fromFallback: true and expansion stamps gateway.identity_source = 'gateway_fallback' (message_projector.js:827) - exactly what isFallbackRow (dataset.js:588) selects - under client_name = 'claude', the key the enricher is registered with (index.js:146).
A check the PR's own tests could not make. The two lanes write different conversation_source values, and that is a cache source-partition column. scanExistingPartIds discovers partitions dataset-wide (discoverCachePartitions({ datasets: [DATASET_NAME] }), dataset.js:846), so neither lane is hidden from the other. Had it been partition-scoped the fix would have been inert in production with both new tests green.
Convergence in both write orders. OTEL-first is caught by the backfill materializer's pre-write dedupe (createBackfillDedupe, dataset.js:676); sweep-first by dedupeByPartId at flush (dataset.js:501).
foldClaudeAttributes merges rather than clobbers. { ...attributes, claude: { ...claude, ...fields } } (projection.js:297) preserves a top-level usage (anthropic.js:338 returns { usage: {...} }) and an existing claude.query_source, and the ordering is right: the body assigns message.attributes = usage before projection.js:138 folds. One correction to the PR body: the old stampQuerySource already merged this way, so it was never clobbering anything - the rename is a generalization, not the repair of a live clobber.
Regression test is load-bearing - verified both ways, not taken from the PR body. With projection.js and bodies.js reverted to origin/master and the test kept, both cases fail (tool call lands 1b6f9cb7fc436b47#0 against the sweep's 5233b3fa-...#0); on head both pass. Adjacent identity suites (claude-otel-proxy-overlap, claude-settlement, claude-projector-identity: 31 tests) green.
LLP discipline. node scripts/llp-numbers.js check - no collision on 0389. LLP 0254 is Accepted and its only edit is an appended **Extended-by:** forward ref, the sanctioned mechanical edit, matching the convention on 0027/0016/0017/0044; nothing it decided was rewritten. All @ref anchors resolve (0389#match-key-on-bodies and #scope-of-0254 explicit; 0262#migration and 0027#decision are heading slugs already used by 8+ annotations here). The narrowed 0254#identity-at-ingest gloss at projection.js:73 was updated rather than left stale.
Explicit CPU and memory pass
- New per-record work is one
matchKeyper body-derived gap block:stripVolatileBlockFields, onecanonicalJsonstring, one sha256 - the identical triplecomputeMessageId(message_projector.js:1228) already runs, so each gap block is now hashed twice. Same 2x the proxy fallback path has carried since LLP 0027. - The accumulating shape:
requestGapMessageswalks the wholebody.messageshistory every turn, so per-session hashing is O(turns^2) in history bytes, overtool_resultpayloads that can be tens of KB, and it runs before thestate.seenMessagesdedupe that discards the repeats, so nothing short-circuits it. Pre-existing (the fallback id already paid it); this doubles the constant, and the formulas differ so the two hashes cannot share. LLP 0389's Consequences acknowledges the double hash but describes it as "on a path that only runs for blocks a body carries", which understates the request-body history replay - worth a sentence if that doc is ever extended. - Allocation: two small objects per gap message, nothing retained.
- Settlement adds no I/O: these rows were already
gateway_fallback, sohasFallbackwas already true, the enricher already loaded and indexed the transcript per session per flush, anddedupeByPartIdalready ran. New work is oneMap.getper row plus oneupgradeRowshallow clone on a hit. - Storage: an unsettled row carries a 64-char hex
match_key, stripped bycleanAttributeson upgrade. Net storage strongly negative - one duplicate row per tool call removed. - No busy loops, no unbounded caches, nothing that worsens with uptime.
Conclusion: no CPU or memory concern.
Judgement on the two deliberate omissions
(a) No repair of already-written rows - correct, and I would have rejected a repair. Pre-fix rows carry neither a uuid nor a match-key. Re-deriving the key from content_text / tool_* is lossy, because per-part expansion discarded the block array those columns came from, and would risk collapsing genuinely distinct rows - worse than leaving a known-inflated window alone. The documented query-time rule is the honest disposition. For the release notes: say the cache does not self-heal, so dashboards over the pre-fix window stay inflated until an operator applies it.
(b) Subagent body-derived rows still not settling - correct to leave, and it fails safe. attributeMessageToEvent (projection.js:271) sets agent_id from agent.name while transcripts scope by agentId, so agentScopedKey misses. I checked the failure mode rather than assuming: the miss is a Map.get returning undefined, and because agent names and hex ids cannot collide, a subagent row cannot false-match a main-loop entry. One hash probe per row. Recording it in 0389's Consequences is right; it deserves its own issue, and does not block this.
Nits (recorded, not fixed)
projection.js:138stamps the key unconditionally where the sibling proxy producer guards withif (projected.message_id) continue(projector.js:320). Equivalent today -gapMessagenever setsmessage_id- but a future gap message with native identity would carry dead weight settlement never cleans. A no-op guard is churn, so left alone.- LLP 0389 and
projection.js:130name three block types;GAP_BLOCK_TYPEScovers six. Exemplars, not an error.
Tests and typecheck, against a baseline I ran myself
Baseline was an origin/master (66c1f9a4) worktree in the same environment, not an assumption.
npm test |
npm run typecheck |
|
|---|---|---|
baseline 66c1f9a4 |
6156 tests, 3 fail (not ok 1910/1913/1915, the icebird/hyparquet pin tests) |
1 error: hypaware-plugin-kernel-types.d.ts(14,58) TS2305 'squirreling' has no exported member 'ScannableDataSource' |
head f83a4b7d |
6158 tests, the same 3 fail, the 2 new tests pass | the same single error |
Both pre-existing failures reproduce identically on the baseline. No new test failure and no new type error.
What was fixed
Nothing. F1 is deliberately out of scope for this diff (reasoning above), and the other two raised findings do not hold. No commit, no push - the head reviewed is the head as submitted.
neutral review round 2 - findingsReviewed Verdict: ship it. One MEDIUM finding, confirmed by probe, deliberately not fixed here and not a merge blocker. Nothing pushed to the branch. The round-1 finding is now tracked as #1470 (round 1 asked a human to raise it and nobody had; it is concrete, consequential, and clearly outside this task, which is exactly CLAUDE.md's bar for filing autonomously). What I verified about the fixIt works, end to end. I built my own harness (real backfill provider, real The convergence is structurally sound, not incidental.
No new I/O and no new settlement candidates. Gap rows carried no Both write orders converge: OTEL-first via the backfill materializer's pre-write dedupe (
No content leak. Failure modes fail safe. A multi-block transcript line would simply not match (no settlement, duplicate persists as today, nothing mis-joined). Two identical blocks in a session collapse onto one index entry, but they already collapsed under the identical fallback hash, so no row is newly lost. A subagent gap row keys on the agent name while the index keys on the hex LLP discipline holds. Style: no em dashes, no code semicolons, no NUL bytes, no new runtime dependency, no invented column or config key. Types are JSDoc; the new import is a plain F1 (MEDIUM, not fixed, tracked as #1470) - the two lanes put
|
| text row from | tool row from | usage counted |
|---|---|---|
| OTEL | OTEL | 1x (correct) |
| sweep | sweep | 1x (correct) |
| OTEL | sweep | 2x (the pre-existing over-count, surviving) |
| sweep | OTEL | 0x (new) |
The same-lane cases dominate, so the PR is still a clear net improvement on the issue it fixes.
Addendum (mechanism, added after a parallel reviewer supplied it and I verified it in the source). My first draft said the mixed orders need an unusual commit sequence. There is a concrete and more ordinary path to the 2x row, and it is worth stating precisely because #1464 counts token double-counting as part of the bug:
A body-derived row only gets its transcript uuid at flush; until then it sits in the spool under its fallback part_id. The backfill dedupe deliberately folds the spool into its seen-set (dataset.js:530-535: "a spool hit means another producer already wrote this part"), unlike the flush-path dedupe, which deliberately does not (dataset.js:485-489). So if the sweep fires while an OTEL turn is still spooled:
- the sweep skips the OTEL text row (already uuid-keyed, so its
part_idis recognized), - the sweep does not skip the still-fallback OTEL tool row, and writes its own tool row carrying usage,
- at flush the OTEL tool row settles onto that uuid and
dedupeByPartIddrops it.
Survivors: OTEL text row (usage) + sweep tool row (usage) = the turn counted twice. So inside the spool window the row duplication #1464 reports is fixed but the token over-count is not. Outside it (OTEL flushed before the sweep runs) the sweep skips both rows and the total is a correct 1x, which should be the dominant case given a frequent flush against a cron sweep.
This does not change the verdict: the PR strictly improves every ordering and halves the row count, and the residual is the pre-existing carrier misalignment, not something this diff introduces. It does mean the release notes should not claim #1464's token over-count is fully closed until #1470 lands.
Why not fixed here. The divergence lives entirely in code this diff does not touch and is a pre-existing violation of an Accepted LLP. Aligning the OTEL lane means moving usage off the assistant_response row onto the response's last block, but the event and the body arrive as separate events and possibly separate export batches, so projection cannot know at assistant_response time whether a gap block follows; it also has to coordinate with the usageByRequestId claim (projection.js:344-347) and restoreUnclaimedUsage (source.js:709). That is a design change on a shipped lane with its own LLP, not a rider on a part_id identity fix. CLAUDE.md: "land the small one and defer the rest." Tracked in #1470 with the full probe.
Test-strength note (LOW, no change requested)
test/plugins/claude-otel-body-overlap.test.js uses a tool-only response (content: [TOOL_BLOCK]), which is exactly the shape where the two lanes agree on the usage carrier, so it is structurally blind to F1. That is fine for what the test is pinning, and I confirmed the test is genuinely load-bearing for that: it exercises the real provider, the real projection and the real enricher, not fixtures of the fix's own output. A [text, tool_use] case belongs with the F1 fix, and #1470 says so.
Explicit CPU and memory pass
Required by CLAUDE.md; done over the changed code and the affected paths.
- New per-record work is one
matchKeyper body-derived gap block:stripVolatileBlockFields(one array map), onecanonicalJson, one sha256. That is the identical triple the gateway'scomputeMessageIdalready runs on the same block, so each gap block is now canonicalized and hashed twice. Exactly the 2x the proxy fallback path has paid since LLP 0027, and the two formulas differ so they cannot share a digest. - The accumulating shape, and the one thing worth stating plainly:
requestGapMessages(bodies.js:330-345) walks the wholebody.messageshistory on every turn, so per-session gap-block hashing is O(turns^2) in history bytes, overtool_resultpayloads that can be tens of KB. It runs at projection, before thestate.seenMessagesdedupe (message_projector.js:800) that discards the repeats, so nothing short-circuits it. This is pre-existing - the fallback id already paid it - and this PR doubles the constant, dominated bycanonicalJsonrather than sha256. LLP 0389's Consequences calls the added work "one sha256 over content already canonicalized for the fallback id, on a path that only runs for blocks a body carries", which understates it on two counts: the content is canonicalized again, not reused, and the request-body history replay is the volume driver. Worth a sentence if that doc is ever extended; not worth blocking a fix for an active data-corruption bug. - Allocation: two small objects per gap message in
foldClaudeAttributes, both short-lived, nothing retained.upgradeRowadds one shallow clone per settled row. - Settlement adds no I/O and no new scans: these rows were already fallback rows, so the transcript load, the index build and
dedupeByPartIdall already ran for this batch.dedupeByPartId's committed scan stays restricted to the batch's ownpart_ids (dataset.js:494-497, LLP 0204#fix), so nothing here reopens that GC-thrash path. - Unbounded growth: none. No new cache, map or set.
usageByRequestIdis untouched and still capped bytrimUsageIndex. No busy loop, nothing that degrades with uptime. - Storage: an unsettled row carries a 64-char hex
match_key, stripped bycleanAttributeson upgrade. Net storage is strongly negative - one duplicate row per tool call removed.
Conclusion: no CPU or memory concern that should block this change. The one item to keep on the record is the pre-existing O(turns^2) request-body replay hashing, whose constant this PR doubles; it is bounded per session, dominated by work the path already did, and outside this diff's scope.
Judgement on the two deliberate omissions
(a) No repair of already-written rows - correct. Pre-fix rows carry neither a uuid nor a match-key, and per-part expansion discarded the block array content_text / tool_* came from, so re-deriving the key would be lossy and could collapse genuinely distinct rows: worse than leaving a known-inflated window alone. The documented query-time rule is the honest disposition. For the release notes: say plainly that the cache does not self-heal, so dashboards over the 09-03-onward window stay inflated until an operator collapses on session_id + tool_call_id or reads a single conversation_source.
(b) Subagent body-derived rows still not settling - correct to leave. It fails safe (a missed Map.get, never a false match), it is unchanged by this diff, and LLP 0389 records it. It deserves its own issue but does not block this.
Tests and typecheck, against a baseline I ran myself
npm test |
npm run typecheck |
|
|---|---|---|
head f83a4b7d |
6156 tests, 3 fail (not ok 1910 / 1913 / 1915, the icebird / hyparquet dependency-pin tests) |
1 error: hypaware-plugin-kernel-types.d.ts(14,58) TS2305 'squirreling' has no exported member 'ScannableDataSource' |
Both are pre-existing and unrelated to this diff (dependency pinning and a kernel type export). The 2 new tests pass. No new test failure and no new type error.
What was fixed
Nothing in the diff. F1 is deliberately out of scope for this change and is now tracked as #1470 with a full reproduction. No commit, no push - the head reviewed is the head as submitted.
Two Consequences bullets in the doc this PR introduces overstate what the change costs and what the backstop does. LLP 0027 #re-settle-sweep's de-twin is a single-partition rewrite (scanNativePartIds reads one table dir), justified there by "twins always live in the same partition". That holds for the proxy path, where one lane produces both rows. It does not hold for the pair this decision creates: the transcript sweep's row lives under conversation_source = 'claude' and the body-derived row under 'claude_code', and the cache partitions on client_name / conversation_source / provider. So a row that misses the flush-time pass keeps its duplicate rather than being repaired at compaction. The flush-time pass is the one that collapses it, and its committed scan is dataset-wide. The cost bullet also said the match-key is "one sha256 over content already canonicalized for the fallback id". The two formulas differ (the fallback id folds in thread scope and agent), so the canonicalization is repeated, and it rides requestGapMessages' replay of the whole request history, which makes it quadratic in a session's turns. Doc precision only, no behavior change. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
neutral review round 2 - findingsReviewed Verdict: ship it. I did not take round 1's conclusions on trust: every central claim below was re-derived from the source or from a probe I ran myself, and I went after the areas round 1 covered lightly (error and edge paths, ordering beyond its two cases, schema and migration effects, compatibility with rows already written, test gaps). Two things are new at this head.
Round 1's F1 stands as filed in #1470; I did not re-litigate it or the two probe-refuted findings. NEW (MEDIUM, not fixed, recorded on #1470) - a collapsed text-less turn loses per-request cost, latency and the cache-token split
Exactly one row can hold that block: Before this PR that row had a content-hash Token counts survive: the sweep stamps Why not fixed here. The only in-diff way to preserve it is to withhold the match-key from a gap row carrying claimed usage, which re-opens #1464 for precisely the tool-only turns it is about: a worse trade. The real answer is that a It does not change the verdict: the PR halves the row count in every ordering and the residual is narrower than what it removes. It does mean the release notes should say the OTEL-only cost fields can go missing on tool-only turns the sweep won, alongside the pre-fix window that does not self-heal. NEW (LOW, fixed in
|
neutral triage - deferred findings fanned outTriaged head Resolved at this head (no issue): the round-2 LOW (LLP 0389 overstated the LLP 0027 re-settle backstop) was fixed by the head commit
Both issues carry the |
philcunliffe
added
the
neutral:approved
Ship risk:
|
1 participant
Feature or issue
Since the OTEL attach every Claude Code session is written to
ai_gateway_messagestwice: once by the transcript backfill sweep (conversation_source = 'claude', keyed by the transcript uuid) and once by the OTEL listener (claude_code). Content events carrymessage.uuid, so their rows already share identity with the sweep's, but the blocks events do not carry (tool_use, tool_result, thinking) reach the OTEL lane only through a spooled body, which has no uuid anywhere, so the gateway synthesized a content hash for them. Thepart_iddedupe LLP 0262 relies on never fired: on the reporting machine 29 of 50 sessions were dual-captured, 1,155 tool calls and 571k output tokens counted twice, inflating every report over that window by about a third.Solution
part_id = <uuid>#<part_index>and the dataset's dedupe collapses the overlap whichever lane wrote first.stampQuerySourcegeneralizes tofoldClaudeAttributesso the key merges beside a row's existing usage block instead of clobbering it.Extended-byforward ref narrowing "final when written" to the rows a content event produces.test/plugins/claude-otel-body-overlap.test.jsruns the real backfill provider over an on-disk transcript and the real listener projection over a spooled response and request body for the same session. Before the fix the tool call landed as3a39d0e53ae68dc0#0against the sweep's5233b3fa-...#0and the duplicate survived the dedupe carrying a second copy of the turn's usage; after it, both lanes agree and a session the sweep already stored adds no body-derived row.npm testandnpm run typecheckare otherwise unchanged from the base (3 pre-existing dependency-pin test failures and 1 pre-existingsquirrelingtype error reproduce on an unmodified checkout in the same environment).session_idplustool_call_idor read a singleconversation_source. LLP 0389 states that consequence.Code: +29 / -12 lines
Fixes #1464