Trace gatekeeper session resolution and stamp identity on loopback invocations

[ndisidore]

Looking at production trace data, nearly every retained GatekeeperLoopback.jsrpc record was a "code had hung" cancellation, arriving in bursts tied to agent-initiated gatekeeper calls. The canceled invocations carry no vendor or caller identity, and the traces don't show which stage stalled, so the investigation had to infer both from sibling spans.

This adds three small instruments to workshop-backend so the next investigation can read the answer straight off the trace:

• Every loopback invocation stamps a gatekeeper.loopback.identity span with vendorId, target, callerFrom, and chatId. Canceled invocations become directly groupable by vendor.
• A gatekeeper.loopback.resolve span times session resolution. It uses a new createPipelinedTracer helper that returns the RpcPromise unchanged, since the existing traced helper would break capnweb pipelining here.
• A gatekeeper.session.open span (plus a failure-only log event) wraps openSession in the overseer DO. Comparing it against the loopback spans localizes a hang to overseer dispatch, connector session open, or the downstream connector call.

Connector-side instrumentation of the tool call itself is deferred to a follow-up.

[ask-bonk]

Review: Trace gatekeeper session resolution and stamp identity on loopback invocations

Reviewed all five files and verified locally (deps installed, checks run).

Verified locally

• pnpm --filter @gadgets/backend-utils types:check — pass
• pnpm --filter @gadgets/workshop-backend types:check — pass (format-blueprints generator ran first)
• pnpm --filter @gadgets/backend-utils test — 30/30 passed, including the tracedPipelined reference-identity, settle, sync-throw, reject, and the unended-span visibility pin. (The Error: reporter down line is expected test output per vitest.config.ts.)
• pnpm lint:check — exit 0, 0 errors; only pre-existing no-shadow/consistent-function-scoping warnings elsewhere, none on lines this PR touches.

Correctness confirmed

• createPipelinedTracer preserves Cap'n Web pipelining. startActiveSpan + manual end() returns result by reference; expect(result).toBe(original) pins it, so the loopback Proxy (overseer.ts:6887) still pipelines startGatekeeperSession(...). This is the right choice over traced, whose .catch wrapper (tracing.ts:41) would replace the RpcPromise with a new promise and collapse pipelining.
• Dual-span design is justified. The unended-span test (tracing.test.ts:128-154) genuinely pins that a never-settling pipelined span streams spanOpen but drops attributes (they flush only at close), which is exactly why the separately-ended gatekeeper.loopback.identity stamp exists to identify a hung invocation.
• openSession await is safe. startGatekeeperSession (overseer.ts:2595) already returns Promise<any> and loopback consumers pipeline onto its resolution; the added await only folds session-open duration into that resolution — precisely what the span measures. No caller-side pipelining is lost.
• Constructor-per-invocation is correct. The identity/resolve spans live in the GatekeeperLoopback constructor, which (per the comment at overseer.ts:6848) runs on each method call against the ServiceStub, matching the PR's "every loopback invocation stamps" intent.
• Types read as consistent. bindingTargetId is a WorkpieceId (number) so setAttribute is fine; the fields object in openSession uses only valid WorkshopObservabilityFields keys with correct types (callerGadgetId: number, outcome: "error", durationMs).

Non-blocking notes (all previously raised, addressed in follow-up commits; I concur)

1. The resolve span's side observer void result.then(...) (tracing.ts:73) subscribes to the top-level RpcPromise, materializing the session stub locally that pure-pipelining consumers would otherwise skip. The updated comment (tracing.ts:71-72) correctly notes the RPC return message flows regardless, so the observation is off the critical path — accurate.
2. stampIdentity passes possibly-undefined vendorId straight to setAttribute (relying on undefined-as-no-op), bypassing stampContext's primitive guard. Fine per the value?: Attribute signature, just asymmetric with the helper.
3. bindingTargetId (identity span) and gatekeeperId (session.open span) name the same workpiece id — now called out in the code comment (overseer.ts:6867-6868), good for the next investigator.
4. span-recorder clear() is now invoked at the top of the unended-span test, addressing the earlier cross-test accumulation concern.

Verdict: LGTM. Clean, well-scoped observability change; types, tests, and lint are green locally.

[ask-bonk]

Review posted to PR #145.

Summary

I independently verified this PR rather than relying on CI — installed deps and ran everything:

Checks run locally:

• types:check on both backend-utils and workshop-backend — pass
• backend-utils tests — 30/30 pass (including the new tracedPipelined reference-identity and unended-span visibility pins)
• lint:check — exit 0, 0 errors (only pre-existing warnings elsewhere)

Correctness confirmed:

• createPipelinedTracer preserves Cap'n Web pipelining by returning the RpcPromise by reference (pinned by toBe(original)), which is why the loopback Proxy still pipelines startGatekeeperSession. traced's .catch wrapper would have broken this.
• The dual-span design (immediately-ended identity stamp + pipelined resolve span) is justified by the pinned workerd behavior that an unended span drops its attributes.
• The await added in openSession doesn't lose caller-side pipelining.
• The identity/resolve spans correctly live in the per-invocation GatekeeperLoopback constructor, and all fields keys are valid WorkshopObservabilityFields.

Verdict: LGTM — a clean, well-scoped observability change. All four earlier non-blocking notes were addressed in follow-up commits or are defensible as-is.

github run

[kentonv]

I'm not necessarily against adding more trace info, but if we're specifically chasing the "Worker's code had hung and would never generate a response." errors, I think it's not worth it. I'm pretty confident this is a runtime bug that has no visible impact: the error is being reported spuriously at the time the event was about to end anyway. I would guess that this error is actually being produced commonly in local testing, even, but it doesn't get reported anywhere since there's no tail worker installed. We should try installing one and see what happens, then if we can reproduce, report it to the runtime team.