Instrumentation: context restored after send, public instrumentation option, store hygiene, body-drain diagnostics, log-level wiring (#80) by Wahbeh-Mohammad · Pull Request #95 · dexpace/nodejs-sdk

Wahbeh-Mohammad · 2026-09-05T09:11:50Z

Closes #80. Part of the audit-remediation umbrella #67 (milestone 4, wave 5). Every bullet of the
ledger's D18 landed test-first; the two D18 items marked done elsewhere (CTX-15, per D3) were
skipped as instructed.

What changed

1. `send()` scopes its async stores with `run`, not `enterWith` (HIGH, the two leaks)

Runtime.send entered both async-scoped stores — the diagnostic fields and the active span — with
AsyncLocalStorage.enterWith, restoring them from a closure called in its finally. enterWith
installs on the async resource that runs it, which for send's synchronous prefix is the
caller's; the finally runs on a resource created by the first await inside. The restore
therefore reached nothing the caller could observe:

after await runtime.send(...) the ended operation span was still the active span, so
startOperationSpan's isRecording guard suppressed the next call's span and only the first
operation per async context ever got an http.client.operation span — OBS-29's 1:1 binding was
stated in the code and not delivered;
the LOGGING pillar's OBS-23 correlation fields rode out of the call, so every later application
log through any core Logger carried that request's trace.id / span.id.

send() now re-runs the caller's own diagnostic store through
runWithSnapshot(captureDiagnosticSnapshot(), …) and activates the operation span through a new
@internal runWithActiveSpan, both AsyncLocalStorage.run forms that unwind structurally —
including over an enterWith a step below left open. AsyncScopedStore grows the matching
run(value, fn). The handle forms stay, because OBS-22 specifies one, with TSDoc stating what
their restore can and cannot reach.

2. A public way to instrument a pipeline (HIGH)

createInstrumentationBundle was public with nowhere public to pass its result, and CTX-16's
operation name never reached promoteToRequest. PipelineBuilder's constructor takes an optional
second argument — the new @public PipelineOptions ({instrumentation?, operationName?}) —
threaded to createRuntime's contextInit; StandardResilienceOptions extends it and forwards
both. Additive: every existing one-argument construction compiles and behaves unchanged.

seedFrom(runtime, 'flatten') carries the seed runtime's options across, read through a new
@internal friend accessor (pipelineOptionsOf) rather than a getter, which would publish
ContextInit's in-package key slot. Flatten produces the pipeline that replaces the one it
seeded from, so dropping the bundle there would silently un-trace a client that seeded from a traced
preset. 'nest' needs no carry — the seeded runtime is still there, driving its own contexts.
This part is not in D18's letter; see "Deviations from the brief" below.

3. Store hygiene and a single `end()`

contextStore.install and startOperationSpan are inside one try: a tracerFactory that threw
used to skip the finally that evicts, growing the process-wide store by one entry per failed send
(CTX-11). The operation span ends behind an ended latch — a throwing end() on the success path
landed in the catch, which called end() a second time. The LOGGING step's per-request span moved
to a single finally, nested inside the scope close so a throwing end() cannot also leak the
scope.

4. Body-drain diagnostics (`OBS-20`)

Both capture paths caught and returned an empty result, emitting nothing: a fileBody() over a
deleted file logged "http.request.body.preview": "" with no trace of why. Both now emit
http.instrumentation.bodyCaptureFailed with the direction and the cause, through the same
safeEmit that swallows a secondary failure, and still return the empty capture as before (D18).

5. `DEXPACE_LOG_LEVEL` (`OBS-35`)

The key name is now LoggingStepSettings.configKey, defaulting to CFG_KEY_LOG_LEVEL. The global
configuration slot deliberately stays empty (defaulting it would make an import-time process.env
read the SDK's default behaviour), and setGlobalConfiguration(defaultConfiguration()) is documented
as the required wiring in a new pipelines.md section, "Turning logging on from the environment" —
which is what makes the variable live at all.

6. Smaller

redactUrl's WHATWG normalisation (host case, default port, empty path) is documented as inherent to
parsing and left as is, with a test pinning it. InstrumentationBundle.tracerFactory's TSDoc says
what the two consumers ask it for and how a caller now supplies one; its six stale file:line
citations are re-derived. Runtime.send states the async-context guarantee.

Test rows added

Where	Rows
`packages/core/src/pipeline/runtime.test.ts`	active span restored after `send()` resolves; after it rejects; a step's diagnostic fields do not outlive the call; a second `send()` opens its own operation span; a throwing `tracerFactory` leaves `contextStore.size` unchanged; a throwing `end()` is not called twice
`packages/core/src/pipeline/builder.test.ts`	the supplied bundle opens the per-operation span (twice, two sends); `operationName` reaches the request context; no options bag means no name; `seedFrom('flatten')` carries both
`packages/core/src/auth/preset.test.ts`	`standardResilience` forwards the bundle and the name — one operation tracer per send, one `GetUser`-labelled tracer per attempt
`packages/core/src/observability/logging-step.test.ts`	`bodyCaptureFailed` on a failing response drain, with the cause; the same on a failing request-body probe; `configKey` names the key; an explicit `granularity` still wins; the per-request span ends once when `end()` throws
`packages/core/src/observability/diagnostic-context.test.ts`	`AsyncScopedStore.run` restores across an `await`; it unwinds an `enter()` its callback left open, and on a throw
`packages/core/src/observability/redaction.test.ts`	the two WHATWG normalisations the new TSDoc names
`tests/node-conformance/observability.test.mjs`	after `await runtime.send()` on Node: `NOOP_SPAN` is active again, a fresh application log carries no `trace.id`/`span.id`, and a second send opens its own operation span

Four of the runtime rows were red before the fix. The two that were not (store size, double end())
were checked against reverted counterfactuals, as was the Node case (reverting send()'s two run
calls and rebuilding turns it red) and the preset row.

Deviation rows added (`docs/deviations.md`, per D0)

OBS-29 — the row that has said "IN PROGRESS — see Instrumentation: enterWith leak, operation span reachable from the public API, context-store eviction, body-drain diagnostics, DEXPACE_LOG_LEVEL wiring #80" since 2026-09-04 is finished. Both
halves are met, caller-reachability is closed, and what remains a deviation is only the vocabulary
(startSpan/end/recordException, not operationStarted/operationSucceeded/operationFailed);
appendix C's "not yet runtime-enforced" note is now out of date for this port. Anchors re-derived
and checked by script.
OBS-35 (new, appended at the table's end) — the default key name is baked in and is now only a
default; a required key was rejected because it would mean no caller gets ambient logging without
naming one first. The row also records the quieter half: the configuration slot starts empty, so no
key of any name resolves until a host wires defaultConfiguration().

No phase ledger and no §10 edit.

Gates

node .claude/skills/ci-preflight/run-ci.mjs --clean (pinned Bun 1.3.14, swept tree): all 20 steps
passed. --node-floor was not run — other agents are working in parallel worktrees; test:node
ran on Node v26.2.0.

  PASS  install / verify:knowledge-structure / typecheck / lint / build / test / test:scripts / api
  PASS  lint:publish / verify:dual-consumption / verify:consumer-types / verify:seam-1 / verify:sse-37
  PASS  verify:runtime-floor / verify:test-partition / test:examples / verify:import-cycles
  PASS  verify:reproducible-build / audit / test:node
CI preflight: all 20 steps passed.

Also run by hand: node .claude/skills/housekeeping/probe.mjs (no drift) and
node .claude/skills/housekeeping/check-fences.mjs (49 fences, PASS).

Deviations from the brief

seedFrom('flatten') carrying the options is not in D18. D18 specifies the constructor option
and the forward to createRuntime; it says nothing about seeding. Implemented anyway, because the
documented derivation path (seedFrom(standardResilience(…), 'flatten') is pipelines.md's own
example) would otherwise drop the bundle silently and no public API could recover it. No public
signature changed. Revert is one line in builder.ts plus one test row if the supervisor disagrees.
The ended latch has two call sites, not one exit. D18 says "span.end() runs once, behind an
ended flag". A single finally would make the flag unreachable, so the success and failure paths
keep their own endOnce() and the latch is what makes the second a no-op — which is testable, and
is tested. The LOGGING step, where D18 asked for a finally, got a finally.
The request-side empty preview stays. D18 says "then return the empty capture as today", so
"http.request.body.preview": "" is still emitted on a failed probe; the test pins that, beside the
new diagnostic. (The response side has always emitted no preview field at all on failure. The
asymmetry is pre-existing.)

Things the issue got wrong

The issue's "redactUrl(string) normalizes port, path and host case (redaction.ts:83)" reads as a
string-only defect. It applies to a URL argument equally — the output is re-rendered from parsed
components either way.
The issue lists noopInstrumentationBundle.activeSpan as still undefined; Record unledgered deviations and open decisions found outside a phase #69 fixed it (D3), and
it was skipped here as the ledger instructs.
The partition names "the observability guide" in docs/sdk-documentation/. There is no such file —
the eleven are architecture, auth, bodies, errors, http, pipelines, quality-gates and
the four write-a-*. All observability prose is in pipelines.md, which is where these two
sections went.

Deferred — release machinery (D1)

Minor changeset for @dexpace/core, not written. New @public export PipelineOptions; new
optional second constructor argument on PipelineBuilder; StandardResilienceOptions extends
PipelineOptions; new LoggingStepSettings.configKey. All additive — no existing call breaks.
Patch-note material in the same changeset, not written. Runtime.send no longer leaks the
active span or the diagnostic fields into the caller's async context (behaviour change, visible to
anyone who was — accidentally — reading them after the call); every send now opens its own
operation span; ctx.context.operationName is populated when the pipeline was built with one; a
failed body capture emits http.instrumentation.bodyCaptureFailed at verbose; shipped .d.ts
prose changed for InstrumentationBundle.tracerFactory, Runtime.send, LoggingStepSettings and
PipelineBuilder.
.changeset/2026-09-04-per-operation-span.md left untouched. Its example still shows
createRuntime(...), which is @internal and never was the public route — the public route is now
new PipelineBuilder(transport, {instrumentation}). It is a dated release note; per D18 it is
listed here rather than edited.
docs/first-release.md untouched, per D1.

`Runtime.send` entered both async-scoped stores -- the diagnostic fields and the active span -- with `AsyncLocalStorage.enterWith` and restored them from a closure called in its `finally`. `enterWith` installs on the async resource that runs it, which for `send`'s synchronous prefix is the CALLER's; the `finally` runs on a resource created by the first `await` inside. So the restore reached nothing the caller could observe: * after `await runtime.send(...)` the ended operation span was still the active span, so `startOperationSpan`'s `isRecording` guard suppressed the NEXT call's span and only the first operation per async context ever got an `http.client.operation` span (OBS-29's 1:1 binding); * the LOGGING pillar's OBS-23 correlation fields rode out of the call, and every later application log through any core `Logger` carried that request's `trace.id` / `span.id`. `send()` now re-runs the caller's own diagnostic store through `runWithSnapshot(captureDiagnosticSnapshot(), ...)` and activates the operation span through a new `runWithActiveSpan`, both `AsyncLocalStorage.run` forms that unwind structurally -- including over an `enterWith` a step below left open. `AsyncScopedStore` grows the matching `run(value, fn)`. The handle forms stay for callers (OBS-22 specifies one) with TSDoc that states what their restore can and cannot reach. Two hygiene fixes ride along, both from the same audit item: * `contextStore.install` and `startOperationSpan` are inside one `try`. A `tracerFactory` that throws used to skip the `finally` that evicts, so the process-wide store grew by one entry per failed send (CTX-11). * the operation span ends behind an `ended` latch. A throwing `end()` on the success path landed in the `catch`, which called `end()` a second time. Found by audit #67 / #80; four of the six new cases were red before the fix, and the other two were checked against reverted counterfactuals. Refs #80, #67

`createInstrumentationBundle` was public with nowhere public to pass its result. `PipelineBuilder.build()` called `createRuntime(flattened, transport)` with no `contextInit`, `createRuntime` is `@internal`, and `standardResilience()` had no slot for one -- so every pipeline a consumer could build carried `noopInstrumentationBundle`, and `OBS-29`'s `http.client.operation` span was unreachable from outside this package. `CTX-16`'s operation name had the same problem one layer down: `send()` called `promoteToRequest(dispatchContext, request)` without it, so `ctx.context.operationName` was `undefined` on every drive. `PipelineBuilder`'s constructor takes an optional second argument, the new `@public` `PipelineOptions` (`{instrumentation?, operationName?}`), threaded to `createRuntime`'s `contextInit`; `StandardResilienceOptions` extends it and forwards both. `send()` hands the name to `promoteToRequest`, and the LOGGING pillar's `resolveTracer` -- which has always read `ctx.context.operationName` -- starts seeing it. `seedFrom(runtime, 'flatten')` carries the seed runtime's options across, read through a new `@internal` friend accessor (`pipelineOptionsOf`) rather than a getter, which would publish `ContextInit`'s in-package `key` slot. Flatten produces the pipeline that replaces the one it seeded from; dropping the bundle there would silently un-trace a client that seeded from a traced preset, with no way for the derived builder to recover it. `nest` needs no carry -- the seeded runtime is still there, driving its own contexts. Additive: every existing one-argument construction compiles and behaves unchanged. `core.api.md` regenerated. Refs #80, #67

… its config key (#80) Three OBS items in the LOGGING pillar step, all found by audit #67 / #80. **Body-drain failures were silent (OBS-20).** Both capture paths caught and returned an empty result, emitting nothing: a `fileBody()` over a deleted file logged `"http.request.body.preview": ""` and a response whose stream errored mid-drain logged no preview at all, in both cases with nothing anywhere to say why. OBS-20 asks for the opposite of silence -- "catch any exception and re-surface it as a best-effort `http.instrumentation.*` diagnostic". Both catches now emit `http.instrumentation.bodyCaptureFailed` with the direction and the `cause`, through the same `safeEmit` that swallows a secondary failure, and still return the empty capture as before. `captureResponseBody` and `prepareRequestBody` take the `EmitContext` instead of loose granularity/preview arguments -- they needed the logger, and the context already carries it, the cap and the granularity. **`OBS-35` says the SDK MUST NOT bake in a default config key name**, and `resolveGranularity` read `CFG_KEY_LOG_LEVEL` unconditionally. `LoggingStepSettings.configKey` names the key instead; the constant stays as its default, because a required key would mean no caller gets ambient logging without naming one first. The residue -- that the default key IS baked in -- is a `deviations.md` row in a later commit. **The per-request span ended on two paths.** If `end()` threw on the success path it landed in `executePipeline`'s own `catch`, which recorded the exception and called `end()` again. It now ends once, in `handleRequestExecution`'s `finally`, nested inside the scope close so a throwing `end()` -- uncaught by design, per OBS-20/OBS-30 -- cannot also leak the activation scope. `core.api.md` regenerated for `configKey`. Refs #80, #67

…ctUrl renders (#80) `InstrumentationBundle.tracerFactory` documented a consumer with no way to supply one. It now says what the two consumers ask it for -- `send()`'s one-per-operation span (`OBS-29`) and the LOGGING step's per-transmission children, the latter under `CTX-16`'s operation name -- and how a caller reaches either: `createInstrumentationBundle(factory)` into `PipelineOptions.instrumentation`. Its three stale `file:line` citations, and the interface note's three, are re-derived against the current tree. `redactUrl` states that its output is re-rendered from the parsed `URL`, so WHATWG normalisation (host case, a default port, an empty path, percent-encoding) shows in the result and a log line need not match the request line byte for byte. Audited and left as is: re-rendering the caller's authority by hand would be a second URL renderer maintained against WHATWG, for no gain in what OBS-11..15 asks for. One `redaction.test.ts` case pins the two normalisations the note names, so the claim is checked rather than asserted. Refs #80, #67

…end (#80) The leak this pins is Node's `AsyncLocalStorage` semantics, and it is exactly the shape `tests/node-conformance/`'s membership rule names: the Bun suite ran green over it for nine phases because every assertion sat in the continuation that opened the scope. Drives a pipeline built the public way -- `new PipelineBuilder(transport, {instrumentation})` with the LOGGING pillar inside it, so OBS-23's correlation push actually fires -- and asserts, after `await send()` resolves: the active span is `NOOP_SPAN` again, a fresh application log carries neither `trace.id` nor `span.id`, and a second send opens its own `http.client.operation` span, each ended once. Red against the `enterWith` form on Node (checked by reverting `send()`'s two `run` calls and rebuilding): the caller's active span is the ended operation span. Refs #80, #67

…live (#80) `pipelines.md` gains two sections. "Instrumenting a pipeline" documents the options bag both constructors now take: what `instrumentation` buys (one `http.client.operation` span per call, the LOGGING pillar's per-transmission spans as its children), what `operationName` is for and what it deliberately does not influence, that both are per-pipeline rather than per-call, and which `seedFrom` mode carries them. "Turning logging on from the environment" closes the gap the audit found: the process-wide configuration slot starts empty (`CFG-13`), so `DEXPACE_LOG_LEVEL=headers` on its own has never done anything, and nothing in `packages/` or the guides said so. `setGlobalConfiguration(defaultConfiguration())` is the wiring; `configKey` is how a host application names its own variable instead. The same section states that a failed body capture now emits `http.instrumentation.bodyCaptureFailed` at `verbose`. The "Execution context" section states what a call leaves behind — nothing — and the pillar table lists `configKey`. Fences typecheck (`check-fences.mjs`: 49 fences, PASS); probe reports no drift. Refs #80, #67

…ey name (#80) The `OBS-29` row has carried "IN PROGRESS — see #80" since 2026-09-04, with caller-reachability of the operation span as the open half. That half is closed: `PipelineOptions` is `@public` and both constructors take it. The row now records what is met (ordering, under `startSpan`/`end` rather than the requirement's method names; the 1:1 binding, which was *stated* before this week and only became true when the `enterWith` leak went), what remains a deviation (the vocabulary), and that appendix C's "not yet runtime-enforced" note is out of date for this port. Anchors re-derived — every `file:line` in the row was checked against the tree by script. A new row records `OBS-35`: the SDK does bake in a default config key name, `configKey` makes it only a default, and a required key was rejected because it would mean no caller gets ambient logging without naming one first. The row also states the quieter half — the configuration slot starts empty, so no key of any name resolves until a host wires `defaultConfiguration()`. Per D0: appended at the end of "Deviations recorded outside a phase", dated, with `file:line` evidence and audit #67 / #80 in the Found-by column. No phase ledger touched. Refs #80, #67

…ext (#80) Two `@remarks` on the one public method the guarantee is about: where the tracer comes from now that there is a public route (`PipelineOptions`), and that the active span and diagnostic fields are the caller's own again once `send()` settles either way. Refs #80, #67

Wahbeh-Mohammad added 8 commits September 5, 2026 11:50

Wahbeh-Mohammad merged commit b9eef12 into audit/remediation-67 Sep 5, 2026
3 checks passed

This was referenced Sep 5, 2026

Audit #67 remediation: milestones 1–5 (#68–#82) #98

Merged

Instrumentation: enterWith leak, operation span reachable from the public API, context-store eviction, body-drain diagnostics, DEXPACE_LOG_LEVEL wiring #80

Closed

Wahbeh-Mohammad deleted the audit/67/80-instrumentation branch September 7, 2026 18:42

Navigation Menu

Uh oh!

Instrumentation: context restored after send, public instrumentation option, store hygiene, body-drain diagnostics, log-level wiring (#80) - #95

Instrumentation: context restored after send, public instrumentation option, store hygiene, body-drain diagnostics, log-level wiring (#80)#95
Wahbeh-Mohammad merged 8 commits into
audit/remediation-67from
audit/67/80-instrumentation

Wahbeh-Mohammad commented Sep 5, 2026

Uh oh!

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

1 participant

Uh oh!

Conversation

Wahbeh-Mohammad commented Sep 5, 2026

What changed

1. send() scopes its async stores with run, not enterWith (HIGH, the two leaks)

2. A public way to instrument a pipeline (HIGH)

3. Store hygiene and a single end()

4. Body-drain diagnostics (OBS-20)

5. DEXPACE_LOG_LEVEL (OBS-35)

6. Smaller

Test rows added

Deviation rows added (docs/deviations.md, per D0)

Gates

Deviations from the brief

Things the issue got wrong

Deferred — release machinery (D1)

Uh oh!

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

1 participant

1. `send()` scopes its async stores with `run`, not `enterWith` (HIGH, the two leaks)

3. Store hygiene and a single `end()`

4. Body-drain diagnostics (`OBS-20`)

5. `DEXPACE_LOG_LEVEL` (`OBS-35`)

Deviation rows added (`docs/deviations.md`, per D0)