Commit Detail
Commit 062aef3
Make user tracing propagate through JS async context, like Jaeger tracing
User tracing was asymmetric with internal/Jaeger tracing in a way that
produced incorrect parent/child relationships in streaming tail worker
events.
## Background
workerd has two tracing systems:
* Internal (Jaeger) tracing uses `jsg::AsyncContextFrame::StorageKey`
to propagate the current span through JS async boundaries. The root
is pushed at every handler entrypoint via
`IoContext::makeAsyncTraceScope(lock)`, and `getCurrentTraceSpan()`
reads from whichever AsyncContextFrame is live when a span is built.
* User tracing (visible in streaming tail worker events) did *not* use
AsyncContextFrame. `currentUserTraceSpan` was a plain member of
`IoContext_IncomingRequest` set once in `delivered()`, and
`getCurrentUserTraceSpan()` returned it via
`getCurrentIncomingRequest()` - which just walks the IoContext's
intrusive list and returns the most recently delivered request.
So user tracing had no awareness of the JS async call graph. Whichever
request was delivered most recently on a given IoContext "won" as the
parent for any span created anywhere on that IoContext, even for
spans originating from a promise continuation that logically belongs
to a different, earlier request. This is most visible on Durable
Objects where one IoContext serves many requests, but applies any
time a promise chain outlives the dispatch of another request on the
same IoContext.
## What this change does
### New AsyncContextFrame key and `makeUserAsyncTraceScope`
`Worker::Isolate` owns a second `AsyncContextFrame::StorageKey`,
`userTraceAsyncContextKey`, alongside the existing
`traceAsyncContextKey`. A new `IoContext::makeUserAsyncTraceScope` is
the exact analogue of `makeAsyncTraceScope`: it returns an RAII
`StorageScope` that pushes a frame carrying the user-trace root. V8
captures the frame when a promise continuation is enqueued inside the
scope, so the continuation sees the same root when it later runs.
`makeUserAsyncTraceScope` is called immediately after
`makeAsyncTraceScope` at every call site in the codebase:
`WorkerEntrypoint::request`/`connect`/`runScheduled`/`runAlarmImpl`/
`test`, `QueueCustomEventImpl::run`, and `sendTracesToExportedHandler`.
### `getCurrentUserTraceSpan` is now async-context-aware
If the JS lock is held, look up the current AsyncContextFrame under
the user-trace key and return `holder->getSpan()` (see below).
Otherwise fall back to the current IncomingRequest's root, preserving
behavior for code paths without the JS lock.
### `UserTraceSpanHolder` - preventing tracer lifetime extension
A naive implementation (`IoOwn<SpanParent>` keyed off the new storage
key) works for stateless workers but is catastrophically broken for
actors. The `UserSpanObserver` holds a `kj::Own<BaseTracer>` via its
submitter. Things in `IoOwn<T>` live on the IoContext's delete queue
and are only destroyed at IoContext teardown - for an actor, that can
be hours or days after any individual request. And the `BaseTracer`'s
destructor is what emits the final `outcome` streaming-tail event, so
a leaked tracer means the request's tail stream never receives an
`outcome`.
`UserTraceSpanHolder` is a refcounted indirection that decouples the
identity of the slot from the lifetime of its contents:
class UserTraceSpanHolder final: public kj::Refcounted {
SpanParent getSpan(); // null if cleared
void setSpan(SpanParent);
void clear();
private:
kj::Maybe<SpanParent> span;
};
The IncomingRequest owns the holder, populates it in `delivered()`,
and `clear()`s it in its destructor before `metrics`
(`RequestObserverWithTracer`) is destroyed. Other references to the
holder - specifically the one placed in `IoOwn<UserTraceSpanHolder>`
via the AsyncContextFrame - observe the same object but cannot
prevent the span and its tracer ref from being released at
end-of-request. The ordering of `clear()` before `metrics` destruction
ensures the tracer's refcount hits zero right after
`setOutcome` is called, so its destructor emits the outcome promptly.
### `makeUserTraceSpan` intentionally unchanged
Same semantics as before and as `makeTraceSpan`: build a span whose
parent is `getCurrentUserTraceSpan()`, but do *not* push it. The ~45
existing `makeUserTraceSpan` call sites in `api/*.c++` are unchanged
and continue to parent under the IncomingRequest root via the
fallback path when no enclosing user-trace scope has been pushed.
Future work can (a) opt specific call sites into
`makeUserAsyncTraceScope` where nested scopes are desired and (b) add
a JS user-tracing API analogous to `InternalJaegerTrace::enterSpan`
that wraps user callbacks in a `makeUserAsyncTraceScope`.
## Test expectation change
`src/workerd/api/tests/tail-worker-test.js` expectations for the
actor-alarm test (expected lines 111 and 112) are updated. This test
is the only place in the workerd test corpus that exercises
cross-request async context propagation for user spans, and its old
expectations encoded the pre-existing bug.
The test case (`actor-alarms-test.js`) does 1 setAlarm + 3 getAlarm:
async fetch() {
await setAlarm(time) [F1]
await getAlarm() [F2]
await waitForAlarm(time):
await promise [W1] yields
// alarm() runs here, calls getAlarm() [A1], resolves promise
await getAlarm() [W2]
}
Under the old code, [W2] ran after alarm() had been delivered on the
same IoContext. `getCurrentIncomingRequest()` returned the alarm
request (most recently delivered), so [W2]'s span was parented under
alarm's root even though it is logically part of fetch's call chain.
Under the new code, fetch's entrypoint pushed a
`makeUserAsyncTraceScope` seeded with fetch's root holder. V8
captured that frame when [W1] suspended. When [W2] runs on resumption,
the frame is restored and `getCurrentUserTraceSpan()` returns fetch's
root.
Old expectations: fetch=[F1, F2], alarm=[A1, W2] // W2 misattributed
New expectations: fetch=[F1, F2, W2], alarm=[A1]
Total getAlarm count is unchanged (3). Only attribution changed, and
the new attribution matches the async call graph - which is what every
other tracing system (internal Jaeger in workerd itself,
OpenTelemetry, Sentry, Zipkin) does, and what developers expect when
reading their code.
This is a user-observable change in streaming tail worker event
structure for any case where a promise chain from one request is
resumed after another request on the same IoContext has been
delivered. If staged rollout is desired, gating the async-context
lookup in `getCurrentUserTraceSpan()` behind an autogate or compat
flag would be a small targeted change; this commit does not add one -
defer to the reviewer.