fix(telemetry): cache_tier streaming-race — read tracer AFTER body consumption

[klappy]

Summary

Every tool call in production telemetry has been recording cache_tier="none" for the entire E0008.1 lifetime of the field — across all 7 days of available data, all 16 distinct tool names, including oddkit_search (286 calls) and oddkit_orient (20 calls) which definitely call getIndex() and emit index spans.

The bug isn't missing instrumentation. It's a timing race: the outer read of tracer.indexSource in workers/src/index.ts happens before the streaming tool handler has finished populating the tracer.

Diagnostic evidence

Captured during the session that found this bug:

oddkit_search call ──► response.debug.trace.index_source = "cache"
                       (correct — read inside handleUnifiedAction
                       at orchestrate.ts:2806, AFTER action ran)

                       telemetry blob9 = "none"
                       (incorrect — read at index.ts:981, BEFORE
                       the streaming tool handler completed)

Same tracer instance. Two read sites. Two different values. Proves the race.

Root cause

agents/mcp returns a streaming Response. await handler(request, env, ctx) resolves with the Response object once headers are flushed and the body stream is constructed — but before the tool handler closure has finished running. The tool handler is what calls fetcher.getIndex(), which is what records the index span on the tracer.

So at line 981 of workers/src/index.ts, when we read cacheTier = tracer.indexSource:

• _indexSource is still null
• The getter returns the fallback "none"
• That value is captured in the closure for recordTelemetry
• Production sees cache_tier="none" for every call

The trace embedded in the response's debug envelope had the correct value because that snapshot is captured inside handleUnifiedAction at orchestrate.ts:2806, after the action ran. The outer reader was just too early.

Fix

Move the cacheTier = tracer.indexSource read inside the ctx.waitUntil callback, after await responseClone.text() resolves. Reading the response body to completion forces the streaming tool handler to have finished, which means the tracer is fully populated.

Three lines of code change. Heavy comment explaining why.

Regression test

cache_tier reads must happen after the streaming response body completes — uses setImmediate to model a streaming tool handler that has not yet recorded its index access at the moment the outer handler's await resolves. Asserts:

• (a) OLD pattern (read immediately after await) returns "none" — reproduces the production bug
• (b) FIXED pattern (read after body consumption) returns the actual span source
• (c) Round-trip through recordTelemetry → blob9 carries the correct value

Without this test, a future refactor that hoists the read back out of waitUntil for "performance" would silently revert the fix and CI would not catch it.

Test results

18 passed, 0 failed
(was 17 — added 1)

Open issue (out of scope, follow-up)

getFile emits file:${path} spans, not "index" / "index-build" spans. The tracer's _indexSource setter only recognizes the latter two labels. This means that even with this race-fix, oddkit_get calls will record cache_tier reflecting the index tier (resolved when runGet calls getIndex first) rather than the file tier (where the document was actually fetched from).

Whether oddkit_get's blob9 should track the index tier (current behavior post-fix), the file tier (would need new span label or setter logic), or both is a separate scope decision. Filing as a follow-up.

What this means for the cache_tier dashboards

After this lands and deploys, expect to see actual values populating blob9:

• memory — module-level cache hit (fastest, ~0ms)
• cache — Cloudflare Cache API edge hit (~1ms)
• r2 — R2 durable storage read (~40ms)
• build — cold build from ZIP (worst case, seconds)
• none — no index loaded (e.g. oddkit_version, oddkit_time)

Aggregate latency will be queryable by tier. Module cache hit rates become visible. The dashboard the field was added for will finally have data.

---

Note

Medium Risk
Telemetry behavior changes for all MCP tool calls by deferring cache_tier capture until after the streaming body is consumed; risk is mainly around response-cloning/body-consumption timing and potential performance/edge-case impacts in the deferred waitUntil path.

Overview
Fixes a streaming timing race where telemetry always recorded cache_tier="none" by moving the tracer.indexSource read into the deferred ctx.waitUntil callback after responseClone.text() completes.

Extends telemetry-integration.test.mjs to compile/import tracing.ts and adds a regression test that simulates the streaming race and verifies cache_tier (blob9) reflects the post-body tracer value rather than the premature fallback.

^{Reviewed by Cursor Bugbot for commit 262693c. Bugbot is set up for automated code reviews on this repo. Configure here.}

[cloudflare-workers-and-pages]

Deploying with    Cloudflare Workers

The latest updates on your project. Learn more about integrating Git with Workers.

Status	Name	Latest Commit	Preview URL	Updated (UTC)
✅ Deployment successful! View logs	oddkit	262693c	Commit Preview URL Branch Preview URL	Apr 26 2026, 02:36 AM