diff --git a/docs/deviations.md b/docs/deviations.md index 6cd1179..60f8df4 100644 --- a/docs/deviations.md +++ b/docs/deviations.md @@ -466,7 +466,7 @@ frozen tree and is amended only deliberately, by hand. When §10 is next amended |---|---|---|---|---| | **`HTTP-11`'s range classifications are on `Status` only, not mirrored onto `Response`.** The spec places them on both: `docs/product-spec/04-core-http-domain-model.md:23` reads "Status MUST classify by range … **and a response MUST expose these derived from its status**", and appendix C (`appendix-c-consolidated-normative-requirement-index.md:47`) restates it as "Response MUST expose these same classifications derived from its status." The port ships them once, on `Status`, reachable as `response.status.isSuccess`. Six delegating getters on `Response` would duplicate surface that cannot drift, since there would be one implementation behind both — but the letter of the requirement does name the response, so the reading is recorded rather than assumed | the dissolved register's A3, register audit | 2026-09-02 | `packages/core/src/http/status.ts` carries all six; `packages/core/src/http/response.ts` carries `status` and no classification of its own | not yet in §10 | | **`REDIR-20`'s "fully override" is read as scoped to code/method eligibility, not to the safety mechanics that follow it.** A configured redirect predicate replaces the built-in follow decision; it does **not** bypass userinfo stripping, credential hygiene, the downgrade guard, body replayability, or loop/cap detection. Those are stated as unconditional MUSTs elsewhere in the same chapter and are not "should this kind of redirect be followed" policy — a caller predicate opting to follow a 307 with a single-use body still cannot make that body re-sendable. Genuinely ambiguous wording, decided one way and now recorded as decided | the dissolved register's G4, register audit | 2026-09-02 | `packages/core/src/redirect/decide.ts` consults `settings.predicate` at the eligibility gate and runs every later guard unconditionally; pinned by "the predicate does NOT bypass the safety mechanics" in `decide.test.ts`. Phase 9's conformance sweep was to re-confirm this and closed without doing so | not yet in §10 | -| **`OBS-29` is carried by spans rather than by the named tracer callbacks. IN PROGRESS — see [#80](https://github.com/dexpace/nodejs-sdk/issues/80) for the final disposition.** `OBS-29` (MUST) requires `operationStarted` once at the start, `operationSucceeded`/`operationFailed` mutually exclusive and once each at the end, and **one tracer instance per logical operation**. The port has no method of those names; it has `Tracer.startSpan(name): Span`. The **ordering half is satisfied** under different names, at both levels: `Runtime.send` opens one span before the drive and ends it on exactly one of two paths — `span.end()` for success, or `span.recordException(error)` then `span.end()` for failure (`pipeline/runtime.ts:193,198-199`) — and the per-attempt spans the LOGGING pillar step opens follow the same shape (`observability/logging-step.ts:427`, then `:398` or `:414-415`). **The 1:1-binding half was recorded here on 2026-09-02 as NOT met, and that reading is out of date.** `Runtime.send` is the one place that runs exactly once per logical operation, and it is where the operation span is opened, outside every pillar, so a retry's second attempt and a redirect's second hop stay inside the same span (`pipeline/runtime.ts:33-48,171-175`; `send`'s own `@remarks` at `:154-157` states the binding). `PIPE-2` still fixes the LOGGING step *inside* the RETRY and REDIRECT pipelines, so its spans remain per transmission — they are now children of the operation span rather than the only spans there are. What stays open is what a *caller* can reach: appendix C's entry (`appendix-c-consolidated-normative-requirement-index.md:509`) says "pipeline/transport wiring to emit it is a follow-up, so it is not yet runtime-enforced", and the operation span is not reachable from the public API. #80 decides that and rewrites this row; anchors re-derived by audit #67 / #68 | the dissolved register's L1/V2, register audit; anchors re-derived by audit #67 / #68 | 2026-09-02, re-anchored 2026-09-04 | `packages/core/src/observability/span.ts:54-56` (`Tracer`, one method — declared in `tracing.ts` until 2026-09-04, when audit #67 / #69 moved the inert tracing declarations into their own module to break an import cycle; `tracing.ts` re-exports them, so the public path is unchanged); `packages/core/src/pipeline/runtime.ts:33-48,154-157,171-175,193,198-199` (the operation span and its 1:1 binding); `observability/logging-step.ts:398,414-415,427` (the per-attempt span); `docs/product-spec/15-instrumentation-and-observability.md:54` (the requirement) | not yet in §10 | +| **`OBS-29` is carried by spans rather than by the named tracer callbacks; both halves are now met, and the operation span is reachable from the public API.** `OBS-29` (MUST) requires `operationStarted` once at the start, `operationSucceeded`/`operationFailed` mutually exclusive and once each at the end, and **one tracer instance per logical operation**. The port has no method of those names; it has `Tracer.startSpan(name): Span`, and the requirement is discharged under that vocabulary. **Ordering:** `Runtime.send` opens one span before the drive and ends it exactly once, behind an `ended` latch that a throwing `end()` cannot get past (`pipeline/runtime.ts:78-96`), and the per-attempt spans the LOGGING pillar step opens follow the same shape from a single `finally` (`observability/logging-step.ts:469`, then `:457,494`). **1:1 binding:** the span is opened outside every pillar, so a retry's second attempt and a redirect's second hop stay inside the first call's span (`pipeline/runtime.ts:57-67,280-282`); before 2026-09-05 a leaked `enterWith` made the *previous* call's ended span read as active and suppressed the next one, so only the first operation per async context got a span at all — the binding was stated and not delivered. **Caller reachability**, which this row carried as the open half from 2026-09-02 to 2026-09-05, is closed: `PipelineOptions` (`pipeline/builder.ts:32-50`) is `@public`, is the second constructor argument of `PipelineBuilder` (`:71`) and is extended by `StandardResilienceOptions` (`auth/preset.ts:23,115-118`), so `createInstrumentationBundle`'s result has somewhere public to go. What remains a deviation is only the **vocabulary**: a consumer sees `startSpan`/`end`/`recordException`, not `operationStarted`/`operationSucceeded`/`operationFailed`, and appendix C's own note that "pipeline/transport wiring to emit it is a follow-up, so it is not yet runtime-enforced" (`appendix-c-consolidated-normative-requirement-index.md:509`) is now out of date for this port | the dissolved register's L1/V2, register audit; anchors re-derived by audit #67 / #68; finished by audit #67 / #80 | 2026-09-02, re-anchored 2026-09-04, closed 2026-09-05 | `packages/core/src/observability/span.ts:54-56` (`Tracer`, one method — declared in `tracing.ts` until 2026-09-04, when audit #67 / #69 moved the inert tracing declarations into their own module to break an import cycle; `tracing.ts` re-exports them, so the public path is unchanged); `packages/core/src/pipeline/runtime.ts:57-67,78-96,206-233,280-282` (the operation span, its single `end()`, and the `run`-scoped stores that keep the binding true across calls); `packages/core/src/pipeline/builder.ts:32-50,71,293` and `packages/core/src/auth/preset.ts:23,115-118` (the public route to a bundle); `observability/logging-step.ts:457,469,494` (the per-attempt span); `docs/product-spec/15-instrumentation-and-observability.md:54` (the requirement) | not yet in §10 | | **`invariant()` density is not a target, project-wide.** `docs/knowledge/harvested/assertions.md:6-7` sets a 2-per-function module average. The port's position: a module gains an `invariant()` when it has an internal precondition worth asserting, and `recovery/`, `http/`, `seams/` and `generated/` have none — measured 2026-09-02, all four at zero. Adding assertions to reach an average would assert nothing. `recovery/` is the sharp case: an `invariant()` inside `ResponseRecoveryChain.apply()` throws, and `RECOV-8` forbids `apply()` from throwing, so a density rule would push that module toward a shape the specification forbids | the dissolved register's F3/H6 and the deferral register's *Assertion-density rule applied project-wide* row (retired to [the purge note](./work/mvp/2026-09-04-register-retirement-purge.md)), register audit | 2026-09-02 | `packages/core/src/recovery/`, `http/`, `seams/`: zero `invariant(` calls. `pipeline/` and `context/` both carry them, so the rule is applied where it earns its place. Counted qualitatively on purpose — the two figures this cell used to state were wrong by the time anyone read them; re-derive with `grep -rn 'invariant(' packages/core/src/ --include='*.ts' \| grep -v '\.test\.'` | not yet in §10 | | **`PIPE-40` and `REDIR-22` contradict each other on the non-replayable-body path, and the port implements `REDIR-22`.** Two MUSTs name the same trigger and prescribe opposite dispositions. `docs/product-spec/08-execution-pipelines.md:20` (`PIPE-40`): "on paths that abandon a re-drive (redirect cycle, **non-replayable body**, budget exhausted) the in-flight response MUST be returned unclosed." `docs/product-spec/10-redirect-handling.md:22` (`REDIR-22`): "if building the follow-up throws (**non-replayable body**, downgrade rejection) the current response MUST be closed before the error propagates." The port closes, then throws, on three grounds: `REDIR-6` independently fixes the control flow ("the operation MUST fail with a clear error naming replayability"), so the path throws and a response never *returned* cannot be "returned unclosed"; specific governs general, since §10 of the spec owns the redirect step's lifecycle; and closing is the safer reading, because the alternative leaks a body on an error path with no caller holding a reference to close it. `PIPE-40`'s other two named paths do genuinely return, and both return unclosed as it requires. **The erratum this needs is proposed below and is not applied here**, because `docs/product-spec/` is frozen and correcting a normative sentence is the specification owner's act, not a maintenance one | the dissolved register's G1, Phase 5b design's Deviation Ledger | 2026-09-04 | `packages/core/src/redirect/redirect-step.ts` closes before throwing, with the reasoning asserted inline in `redirect-step.test.ts`; nothing in the code waits on the erratum | not yet in §10 | | **`PIPE-37`'s outermost pre-redirect status-mapping step was never built, and until this row nothing recorded that.** `PIPE-37` (MUST) requires a step whose correctness depends on the single terminal response — status-to-typed-error mapping is its own worked example — to occupy the outermost pre-redirect slot, so it runs outside both the redirect and the retry loop. The port ships the *mapping*, but as `statusMappingStep`, a `ResponseStep` on the response-recovery chain (RECOV-15/RECOV-16), not as a pipeline `Step` carrying `stage: 'PRE_REDIRECT'`. The slot itself exists and is installable — `config/clientIdentityStep` occupies it today — so this is a wiring gap, not a missing mechanism. It has an owner in writing and the owner never took it: Phase 4's checklist marked the row ⏳ and said "the obligation lands on whichever phase wires 4b's `statusMappingStep` into a real pipeline — **Phase 5**", and Phase 5 shipped without it, with no deferral carrying the hand-off forward. That is why a code audit found it and no checklist did. **Ledgered rather than implemented.** Installing a `PRE_REDIRECT` mapping step is public pipeline surface with a real behaviour change behind it, and the petstore spike arrives at the same work from the other side: its finding 2 wants a declarative `StatusErrorMap` applied *at* the `toHttpError` call site rather than wrapped around it, so a mapped error class can see a decoded payload instead of raw bytes. Whoever does one does both | audit #67 / #69 | 2026-09-04 | `packages/core/src/recovery/status-mapping.ts:26` (`statusMappingStep(response: Response): Promise` — a `ResponseStep`, with no `StepDescriptor` and no stage); `packages/core/src/pipeline/stage.ts:39` (`PRE_REDIRECT` heads `STAGE_ORDER`) and `packages/core/src/config/client-identity-step.ts:124` (the one shipped step that occupies it); `docs/work/mvp/phase4/2026-07-26-phase4-execution-context-and-pipelines-checklist.md:141` (the dropped hand-off); `docs/product-spec/08-execution-pipelines.md:26` (PIPE-37 shares that line with PIPE-25/36/38); `examples/petstore/FINDINGS.md:96-97` | not yet in §10 | @@ -485,6 +485,7 @@ frozen tree and is amended only deliberately, by hand. When §10 is next amended | **`RETRY-44`'s "downstream chain" is read as everything BELOW the retry point, which in the recovery stack excludes the request chain.** The requirement has two clauses: each attempt re-executes the downstream chain with fresh per-attempt state, and "upstream steps MUST NOT mutate the shared in-flight request between attempts". The port originally read the first clause as covering the *whole* recovery chain and re-ran `RequestRecoveryChain.apply()` per attempt, with a test that said so by name. That makes `packages/core/src/recovery/idempotency-key.ts` generate a fresh key on every attempt, so three attempts of one logical request reach the server as three unrelated writes — the precise failure `RECOV-32` exists to prevent, and the opposite of what that step's own `@public` TSDoc promises. **The chain is now applied once, above the loop; each attempt re-executes transport plus response chain over `stampAttempt`'s fresh copy of the prepared request.** Under this reading both clauses hold and the second holds *by construction*: upstream steps cannot mutate the in-flight request between attempts because they no longer run between attempts. The pillar stack is untouched — there "downstream" is the forked continuation (`ctx.fork()`), and `retryStep` still re-drives it per attempt. *Rejected:* memoizing the key on the template (a `WeakMap` keyed by the `Request` instance) — a caller who deliberately sends one immutable `Request` value twice would replay the key and have the server drop a genuine second call. *Rejected:* re-running the chain over the *prepared* request each attempt — the chain would read its own output, which is clause two's mutation in different clothes, and every shipped and caller-written step would have to be proven idempotent. One consequence recorded rather than assumed: the re-send gate (`RETRY-5`/`RECOV-18`) now judges the prepared request rather than the caller's, which is what a retry would actually re-send | audit #67 / #73 | 2026-09-05 | `packages/core/src/retry/retry-dispatch.ts:83-88` (the chain applied once, then `runWithRetry`) against `:27-33` (the per-attempt half); `packages/core/src/recovery/orchestrator.ts:62` (`prepareRequest`) and `:117` (`dispatchPrepared`); `packages/core/src/retry/engine.ts:243` is the gate that now reads the prepared request. `RETRY-44`'s wording is `docs/product-spec/09-retry-and-resilience.md:35` and `docs/product-spec/appendix-c-consolidated-normative-requirement-index.md:306`. Pinned by `packages/core/src/retry/retry-dispatch.test.ts:126` (chain applied once), `:169` (one `generate()`, one key on three sends), `:201` (the `RETRY-38` ordinal varies while the key does not) and `:227` (a request-chain throw is not retried and meets the recovery phase exactly once) | not yet in §10 | | **`HTTP-35`'s timeout check is read as the FULL range `AbortSignal.timeout()` accepts, not the lower bound the requirement enumerates.** `HTTP-35` says the options builder "MUST reject a non-null timeout that is zero or negative". `RequestOptionsBuilder.timeoutMs` rejects three more classes: non-finite (shipped unledgered before this audit), non-integer, and anything above `2**32 - 1`. **Strictly stricter than the letter, and deliberately so.** The field has exactly one consumer — `composeSignal` hands it to `AbortSignal.timeout()` — so a value this setter admits and that function refuses is `HTTP-35`'s own failure mode with the seam moved: the error surfaces inside a transport, as an unwrapped platform `RangeError`, one frame away from the call that supplied it. The earlier reading accepted `1.5` and argued in TSDoc that "a timeout is a duration and a fractional millisecond is meaningful"; no consumer of the field can express one. **The range checked is Node's, and that is the point:** `AbortSignal.timeout(1.5)` and `AbortSignal.timeout(2 ** 32)` raise `RangeError` on Node and are ACCEPTED on Bun, and a negative delay is `RangeError` on Node against `TypeError` on Bun (measured 2026-09-05), so leaving the check to the runtime would make an SDK-level contract depend on which runtime the caller happens to be on. *Rejected:* rounding with `Math.ceil` and clamping inside `composeSignal`, which hides the caller's mistake in the one place `HTTP-35` exists to surface it. `composeSignal` is documented as still able to raise, because a transport's own `defaultTimeoutMs` construction option bypasses this setter and is not validated by core — recorded for #81/#82, not fixed here | audit #67 / #76 | 2026-09-05 | `docs/product-spec/04-core-http-domain-model.md:48` is `HTTP-35`'s wording. `packages/core/src/http/request-options.ts:12` (`MAX_TIMEOUT_MS`) and `:204-214` (the check and the rewritten TSDoc paragraph); `packages/core/src/seams/transport.ts:86-92` is `composeSignal`'s new `@throws`, which states the two-runtime divergence rather than naming one error class. Pinned by "rejects a fractional timeout, which no transport deadline can honor" (`packages/core/src/http/request-options.test.ts:128`, the FLIPPED case — it pinned acceptance until this audit), "rejects a timeout above AbortSignal.timeout()'s ceiling of 2**32 - 1" (`:134`), "accepts the ceiling itself" (`:143`) and the `every accepted timeout is an integer in 1..2**32 - 1` property (`:157`); the Node half is `composeSignal timeout range on Node (HTTP-35)` in `tests/node-conformance/seams.test.mjs:105`, which cannot live in `bun test` because Bun accepts both rejected values | not yet in §10 | | **`HTTP-31`'s "falls back to raw text rather than throwing" is satisfied for an unpaired surrogate by SUBSTITUTING U+FFFD, not by keeping the raw text.** `HTTP-31` (MUST) makes `QueryParams.parse` lenient and enumerates the lenient cases, ending with "malformed percent-encoding falling back to raw text rather than throwing". An unpaired surrogate is a fourth kind of malformed input the enumeration does not name, and the fallback it prescribes is not available for it: the raw text has no UTF-8 form, so keeping it produces a `QueryParams` whose `encode()` throws `URIError` — the throw merely deferred out of `parse` and into an accessor that documents no throw at all. **The port repairs instead.** `parse` runs `toWellFormed()` over each decoded name and value, so every instance it returns is encodable, which is what "parsing MUST invert encode" needs to mean. The strict half of the rule is unaffected and is where `#76` puts the rejection: `QueryParamsBuilder.add` throws `UrlConstructionError` for the same input, and `substitutePathParams` throws `OperationAssemblyError`. That asymmetry is not new to the query model — it is exactly the outbound/inbound split `Headers` already draws for `HTTP-18` against `HTTP-19`, applied to the one requirement pair that needs it here. Substitution matches the platform rather than inventing a policy: `new URL('https://x/?a=\uD800').search` is `?a=%EF%BF%BD` (measured 2026-09-05). *Rejected:* letting `parse` throw the builder's error, which breaks a MUST. *Rejected:* dropping the offending parameter, which loses a name the caller may be matching on | audit #67 / #76 | 2026-09-05 | `docs/product-spec/04-core-http-domain-model.md:42` carries `HTTP-31`'s wording (shared with `HTTP-30`). `packages/core/src/http/rfc3986.ts:17-18` are the two patterns, `:31` `hasLoneSurrogate` (strict) and `:44` `toWellFormed` (lenient) — one rule, two entry points, so no caller can pick the wrong one; `packages/core/src/http/query-params.ts:144-150` is `parse`'s repair with the `HTTP-18`/`HTTP-19` comparison stated inline, against `:44-50` and `:240-241` for the strict `add` path; `packages/core/src/seams/operation.ts:139-144` is the path-param half. `/\p{Surrogate}/u` rather than `String.prototype.isWellFormed()` because the latter is ES2024 and `tsconfig.base.json:5-11` pins `lib: ES2023`, though the `engines.node >= 20.3` runtime has it. Pinned by the `lone surrogates are rejected where they are supplied (HTTP-29, HTTP-31)` block in `packages/core/src/http/query-params.test.ts:170` — "parse() stays lenient and substitutes U+FFFD, because HTTP-31 forbids throwing" (`:197`) and the `no anything escapes parse()` property (`:233`) | not yet in §10 | +| **`OBS-35`'s "MUST NOT bake in a default config key name" is satisfied by making the key configurable, not by removing the default.** `OBS-35` (SHOULD) asks for a tolerant, layered log-level resolution and adds one MUST: no baked-in default key name. The port ships `CFG_KEY_LOG_LEVEL` (`DEXPACE_LOG_LEVEL`) as `CFG-14`'s well-known key and, until 2026-09-05, read it unconditionally. It is now `LoggingStepSettings.configKey`'s default: a caller names their own key and the resolution is otherwise identical. **Why the default stays.** A required key would mean no caller gets ambient granularity without naming one first, which trades a MUST about *naming* for a worse default experience, and `CFG-14` — which this port also implements — exists precisely to standardise the name. The layered resolution itself is `CFG-1`'s (override → environment → normalised property → default) and is tolerant as the requirement asks. **A second, quieter half:** the process-wide configuration slot starts empty (`CFG-13`), so no key of any name resolves until a host calls `setGlobalConfiguration(defaultConfiguration())`. That is deliberate — defaulting the slot to a configuration that reads `process.env` would make an import-time environment read the SDK's default behaviour — and it is now documented as the required wiring rather than left to be discovered | audit #67 / #80 | 2026-09-05 | `packages/core/src/observability/logging-step.ts:64-79,94-104` (the setting and the resolution); `packages/core/src/config/configuration.ts:311,354-358,368` (`CFG_KEY_LOG_LEVEL`, `defaultConfiguration`, the empty default slot); `docs/sdk-documentation/pipelines.md` "Turning logging on from the environment"; `docs/product-spec/15-instrumentation-and-observability.md:66` (the requirement) | not yet in §10 | ### Proposed erratum for `PIPE-40` (drafted 2026-09-04, not applied) diff --git a/docs/sdk-documentation/pipelines.md b/docs/sdk-documentation/pipelines.md index 0ff6532..93fb6e7 100644 --- a/docs/sdk-documentation/pipelines.md +++ b/docs/sdk-documentation/pipelines.md @@ -144,6 +144,58 @@ All three carry the same `InstrumentationBundle`, so trace and span identity sur `AsyncLocalStorage`-based, which is why `@dexpace/rx` installs no RxJS scheduler — adding `observeOn`/`subscribeOn` downstream makes reinstating the context the caller's job. +**What a call leaves behind is nothing.** `send()` scopes both async-scoped stores with +`AsyncLocalStorage.run`, so the moment it settles — resolved or rejected — the active span and the +diagnostic fields are what they were before it. That is a guarantee about *your* context, not only the +pipeline's: an application log emitted after `await client.send(...)` carries no `trace.id` from it. +Inside the call the usual rules apply, and a step that pushes fields with the handle form +(`activateSpanForCorrelation`) should still close its scope in the same continuation that opened it. + +## Instrumenting a pipeline + +Both constructors take an options bag that the built pipeline carries into every call: + +```typescript +import { + PipelineBuilder, + createInstrumentationBundle, + standardResilience, + type PipelineOptions, + type Runtime, + type Tracer, +} from '@dexpace/core'; +import {fetchTransport} from '@dexpace/transport-fetch'; + +declare const otelTracer: Tracer; // whatever your tracing library hands you + +const instrumented: PipelineOptions = { + instrumentation: createInstrumentationBundle(() => otelTracer), + operationName: 'GetUser', +}; + +// `StandardResilienceOptions` extends `PipelineOptions`, so the preset takes the same two fields +// beside its per-pillar ones. +export const preset: Runtime = standardResilience(fetchTransport(), instrumented); +export const handBuilt: Runtime = new PipelineBuilder( + fetchTransport(), + instrumented, +).build(); +``` + +- **`instrumentation`** is the bundle every context of the call carries, and its `tracerFactory` is + what opens spans. `send()` asks it for `'http.client.operation'` once per call and opens **one** + span there (`OBS-29`), outside every pillar — a retry attempt and a redirect hop stay inside it. The + LOGGING pillar asks again per transmission, and those spans are its children. Omitted, the pipeline + carries the no-op bundle (`CTX-15`) and opens no span at all. +- **`operationName`** is `CTX-16`'s advisory label. It is carried unchanged across every promotion, + readable from a custom step as `ctx.context.operationName`, and used to name the tracer the LOGGING + pillar asks for. It never influences the request, the dispatch decision, or the store key. + +Both are per-pipeline, not per-call: build a second pipeline for a second operation name. +`PipelineBuilder.seedFrom(runtime, 'flatten')` carries them over, since the flattened builder replaces +the runtime it seeded from; `'nest'` does not need to, because the seeded runtime is still there, +driving its own contexts as the terminal transport. + ## The four shipped pillars | Pillar | Factory | Key settings | @@ -151,7 +203,7 @@ All three carry the same `InstrumentationBundle`, so trace and span identity sur | Retry | `retryStep(options?)` | `maxAttempts`, `retryableStatuses`, `totalTimeoutMs`, `attemptHeaderName`, backoff (`initialDelayMs`, `multiplier`, `maxDelayMs`, `jitter`, `fixedDelayMs`), injectable `clock`/`random` | | Redirect | `redirectStep(overrides?)` | `maxHops`, `allowedMethods`, `allow303`, `allowSchemeDowngrade`, `locationHeader`, `predicate` | | Auth | `authStep(settings)` | `credentials`, `tiers`, `challengeHook`, `bearerMarginMs` — see [`auth.md`](./auth.md) | -| Logging | `loggingStep(settings?)` | `granularity`, `severity`, `previewSizeBytes`, `droppedHeaderPolicy`, `logger`, `meter`, `tracerFactory` | +| Logging | `loggingStep(settings?)` | `granularity`, `configKey`, `severity`, `previewSizeBytes`, `droppedHeaderPolicy`, `logger`, `meter`, `tracerFactory` | Retry and redirect are worth a few notes each, because both surprise people: @@ -211,6 +263,47 @@ Retry and redirect are worth a few notes each, because both surprise people: - **A non-replayable body ends a redirect.** `PIPE-40` and `REDIR-22` disagree about what should happen; this port closes the response and throws (`docs/work/mvp/2026-09-04-open-items-dissolution.md` G1). +### Turning logging on from the environment + +`loggingStep()` with no `granularity` resolves one from layered configuration (`OBS-35`), and the +default is `'none'`. What it reads is the process-wide configuration slot — **which starts empty**. +`CFG-13` makes that slot last-write-wins with no ambient default, so nothing in this SDK reads +`process.env` until you say so, and `DEXPACE_LOG_LEVEL=headers` on its own changes nothing: + +```typescript +import { + defaultConfiguration, + loggingStep, + setGlobalConfiguration, + standardResilience, + type Runtime, +} from '@dexpace/core'; +import {fetchTransport} from '@dexpace/transport-fetch'; + +// Once, at start-up. `defaultConfiguration()` is the production wiring: its environment seam reads +// the live `process.env` on every lookup, and its property seam finds nothing (Node has no ambient +// key/value store distinct from the environment). +setGlobalConfiguration(defaultConfiguration()); + +// Now `DEXPACE_LOG_LEVEL=headers` reaches the step. `configKey` renames the variable it reads — +// `OBS-35` says an SDK must not bake a key name in, and `DEXPACE_LOG_LEVEL` is only the default. +export const client: Runtime = standardResilience(fetchTransport(), { + logging: {configKey: 'ACME_HTTP_LOG_LEVEL'}, +}); +export const step = loggingStep({configKey: 'ACME_HTTP_LOG_LEVEL'}); +``` + +Parsing is tolerant either way: `' Headers '` and `'HEADERS'` both resolve to `'headers'`, and an +absent, empty or unrecognised value falls back to `'none'`. An explicit `granularity` in the settings +wins over both, and is the right choice for a library that does not want to read a host application's +environment at all. + +Body-preview capture is best-effort and says so when it fails: a request body that cannot be probed +or a response body that errors mid-drain emits `http.instrumentation.bodyCaptureFailed`, carrying the +direction and the cause, and the request still completes (`OBS-20`). Like every +`http.instrumentation.*` diagnostic it emits at `verbose`, so a logger that filters that level will +not show it. + ## Testing a pipeline Nothing here needs a socket. A `Transport` is two methods, so the test double is a literal: diff --git a/packages/core/etc/core.api.md b/packages/core/etc/core.api.md index ac916ca..cfcf87d 100644 --- a/packages/core/etc/core.api.md +++ b/packages/core/etc/core.api.md @@ -668,6 +668,7 @@ export function loggingStep(settings?: LoggingStepSettings): StepDescriptor; // @public export interface LoggingStepSettings { readonly clock?: Clock | undefined; + readonly configKey?: string | undefined; readonly droppedHeaderPolicy?: DroppedHeaderPolicy | undefined; readonly granularity?: LoggingGranularity | undefined; readonly logger?: Logger | undefined; @@ -914,7 +915,7 @@ export class PillarCollisionError extends DexpaceError { // @public export class PipelineBuilder { - constructor(transport: Transport); + constructor(transport: Transport, options?: PipelineOptions); append(descriptor: StepDescriptor): this; appendAll(descriptors: readonly StepDescriptor[]): this; build(): Runtime; @@ -928,6 +929,12 @@ export class PipelineBuilder { static seedFrom(runtime: Runtime, mode: 'flatten' | 'nest'): PipelineBuilder; } +// @public +export interface PipelineOptions { + readonly instrumentation?: InstrumentationBundle | undefined; + readonly operationName?: string | undefined; +} + // @public export class PlaintextCredentialError extends DexpaceError { constructor(stepName: string, scheme: string); @@ -1380,7 +1387,7 @@ export const STAGE_ORDER: readonly Stage[]; export function standardResilience(transport: Transport, options?: StandardResilienceOptions): Runtime; // @public -export interface StandardResilienceOptions { +export interface StandardResilienceOptions extends PipelineOptions { readonly auth?: AuthStepSettings | undefined; readonly logging?: LoggingStepSettings | undefined; readonly redirect?: Partial | undefined; diff --git a/packages/core/src/auth/preset.test.ts b/packages/core/src/auth/preset.test.ts index 1c1a614..733207b 100644 --- a/packages/core/src/auth/preset.test.ts +++ b/packages/core/src/auth/preset.test.ts @@ -3,10 +3,16 @@ // Exercises: PIPE-24 ("installs into empty pillar slots only" -- true by construction, since the preset // always starts from a fresh PipelineBuilder), PIPE-39 (installs exactly the pillars that exist), and // jointly with 5b: PIPE-2's "auth executes per redirect hop, not once for the whole call" plus -// AUTH-29's marker-CONSUMPTION side (5b produced the marker and routed consumption here). +// AUTH-29's marker-CONSUMPTION side (5b produced the marker and routed consumption here), OBS-29 + +// CTX-16 (the preset forwards an instrumentation bundle and an operation name to the built pipeline). import {describe, expect, test} from 'bun:test'; import {Request} from '../http/request.js'; import type {Response} from '../http/response.js'; +import { + createInstrumentationBundle, + type Span, + type Tracer, +} from '../observability/tracing.js'; import {PipelineBuilder} from '../pipeline/builder.js'; import type {StepDescriptor} from '../pipeline/step.js'; import {CROSS_ORIGIN_MARKER_HEADER} from '../redirect/cross-origin.js'; @@ -216,3 +222,67 @@ describe('standardResilience logging options (Phase 7b)', () => { expect(events).toEqual(['http.request', 'http.response']); }); }); + +describe('standardResilience instrumentation options (OBS-29, CTX-16)', () => { + test('the supplied bundle opens one operation span per send, and the name reaches the step', async () => { + const spanNames: string[] = []; + const factoryNames: string[] = []; + const span: Span = { + isRecording: true, + setAttribute: (): Span => span, + recordException: (): Span => span, + end: (): void => undefined, + }; + const tracer: Tracer = { + startSpan(name: string): Span { + spanNames.push(name); + return span; + }, + }; + let seen: string | undefined; + const probe: StepDescriptor = { + type: Symbol('operation-name-probe'), + stage: 'PRE_SERDE', + fn: async (request, ctx) => { + seen = + 'operationName' in ctx.context + ? ctx.context.operationName + : undefined; + return ctx.next(request); + }, + }; + + const runtime = PipelineBuilder.seedFrom( + standardResilience( + new FakeTransport([ + countingResponse(200).response, + countingResponse(200).response, + ]), + { + instrumentation: createInstrumentationBundle(operationName => { + factoryNames.push(operationName); + return tracer; + }), + operationName: 'GetUser', + }, + ), + 'flatten', + ) + .append(probe) + .build(); + + await runtime.send(aRequest()); + await runtime.send(aRequest()); + + // `Runtime.send()` asks the factory for the operation's own tracer once per call (OBS-29's 1:1 + // binding), and the LOGGING pillar asks for one labelled with CTX-16's operation name per attempt. + expect( + factoryNames.filter(name => name === 'http.client.operation'), + ).toHaveLength(2); + expect(factoryNames.filter(name => name === 'GetUser')).toHaveLength(2); + expect( + spanNames.filter(name => name === 'http.client.operation'), + ).toHaveLength(2); + expect(seen).toBe('GetUser'); + }); +}); diff --git a/packages/core/src/auth/preset.ts b/packages/core/src/auth/preset.ts index 965ca4a..6317375 100644 --- a/packages/core/src/auth/preset.ts +++ b/packages/core/src/auth/preset.ts @@ -1,6 +1,6 @@ // SPDX-License-Identifier: MIT // packages/core/src/auth/preset.ts -import {PipelineBuilder} from '../pipeline/builder.js'; +import {PipelineBuilder, type PipelineOptions} from '../pipeline/builder.js'; import type {Runtime} from '../pipeline/runtime.js'; import type {RedirectSettings} from '../redirect/settings.js'; import {withRedirect} from '../redirect/strip-marker-step.js'; @@ -20,7 +20,7 @@ import { * * @public */ -export interface StandardResilienceOptions { +export interface StandardResilienceOptions extends PipelineOptions { /** Retry settings and injected seams; omitted yields 5a's spec defaults. */ readonly retry?: RetryStepOptions | undefined; /** Redirect policy overrides; omitted yields 5b's spec defaults. */ @@ -62,6 +62,12 @@ function noAuthSettings(): AuthStepSettings { * `LOGGING` installs {@link loggingStep} to emit telemetry and metrics around dispatches. `SERDE` remains * reserved with no shipped behavior anywhere in this roadmap's current scope. * + * The two inherited {@link PipelineOptions} fields are pipeline-wide rather than per-pillar: + * `instrumentation` is the bundle every context of every call carries, and the source of the one + * `http.client.operation` span each `send()` opens (`OBS-29`); `operationName` is `CTX-16`'s advisory + * label. Omitting `instrumentation` leaves the no-op bundle in place, which opens no span at all — it + * is the only way to switch tracing on for a preset-built pipeline. + * * This function only assembles the pipeline. The failures below surface from the returned runtime's * `send()`, and are documented here because this factory is where a caller chooses the auth * configuration that determines whether they can occur at all. @@ -104,7 +110,12 @@ export function standardResilience( transport: Transport, options: StandardResilienceOptions = {}, ): Runtime { - const builder = new PipelineBuilder(transport); + // The two `PipelineOptions` fields are pipeline-wide rather than per-pillar, so they go to the + // builder rather than into a step's settings; everything below installs one pillar each. + const builder = new PipelineBuilder(transport, { + instrumentation: options.instrumentation, + operationName: options.operationName, + }); return withRedirect(builder, options.redirect) .append(retryStep(options.retry)) .append(authStep(options.auth ?? noAuthSettings())) diff --git a/packages/core/src/context/instrumentation.ts b/packages/core/src/context/instrumentation.ts index cabc79a..5eb7b08 100644 --- a/packages/core/src/context/instrumentation.ts +++ b/packages/core/src/context/instrumentation.ts @@ -10,9 +10,9 @@ import {NOOP_SPAN} from '../observability/span.js'; * `activeSpan` and `tracerFactory` are `unknown` rather than a `Span`/`Tracer`. The original reason — * "nothing in the package consumes either yet, pending Phase 7a" — expired when Phase 7a landed * (`bd37a08`) and shipped `Span` and `Tracer` in `observability/tracing.ts`. That phase did not narrow - * these two: `tracerFactory` is consumed, by `pipeline/runtime.ts:52` and - * `observability/logging-step.ts:263`, both of which reach a `Tracer` through a cast; - * `createInstrumentationBundle` fills `activeSpan` (`observability/tracing.ts:222`), and nothing in + * these two: `tracerFactory` is consumed, by `pipeline/runtime.ts:60-65` and + * `observability/logging-step.ts:305-312`, both of which reach a `Tracer` through a cast; + * `createInstrumentationBundle` fills `activeSpan` (`observability/tracing.ts:191`), and nothing in * this package reads it back. * * They stay `unknown` because narrowing a published member is a breaking change rather than a @@ -46,11 +46,24 @@ export interface InstrumentationBundle { /** * Returns the tracer to open `operationName`'s span from — a **tracer**, not a started span. Every * consumer in this package narrows the result and calls `startSpan()` on it itself - * (`packages/core/src/pipeline/runtime.ts:52-57`, `observability/logging-step.ts:263-269`), and + * (`packages/core/src/pipeline/runtime.ts:60-65`, `observability/logging-step.ts:305-312`), and * `createInstrumentationBundle` supplies a `(operationName: string) => Tracer` - * (`observability/tracing.ts:212,223`). A no-op returning `undefined` when tracing is disabled; + * (`observability/tracing.ts:180,191`). A no-op returning `undefined` when tracing is disabled; * both consumers substitute `NOOP_TRACER` for that `undefined`. * + * **It is asked twice per call, for two different scopes.** `Runtime.send()` asks for + * `'http.client.operation'`'s tracer once per call and opens `OBS-29`'s one-per-operation span from + * it, outside every pillar, so a retry attempt and a redirect hop stay inside it. The LOGGING pillar + * step asks again per transmission, under `CTX-16`'s operation name when the pipeline was built with + * one and `'http.client.request'` otherwise, and its spans are children of the first. Returning one + * shared tracer for both is fine; `OBS-29`'s 1:1 clause is about the operation *span*, which + * `send()` opens exactly once whatever this returns. + * + * A consumer reaches this by building a bundle with `createInstrumentationBundle(tracerFactory)` and + * passing it as `PipelineOptions.instrumentation` — to `new PipelineBuilder(transport, options)` or + * to `standardResilience(transport, options)`. Before 2026-09-05 there was no public route: every + * pipeline a consumer could build carried the no-op bundle (audit #67 / #80). + * * PROVISIONAL: the return type is `unknown`, and narrowing it is a version-bump decision — see this * interface's own note for why Phase 7a landing did not settle it. * diff --git a/packages/core/src/index.ts b/packages/core/src/index.ts index 43cc879..49eadf2 100644 --- a/packages/core/src/index.ts +++ b/packages/core/src/index.ts @@ -157,6 +157,10 @@ export type { RequestContext, } from './context/context.js'; export type {InstrumentationBundle} from './context/instrumentation.js'; +// `PipelineOptions` is what a caller passes to `new PipelineBuilder(transport, options)` and, by +// extension, to `standardResilience`; it is the only public route to `OBS-29`'s per-operation span +// and `CTX-16`'s operation name, so it is exported beside the bundle it carries. +export type {PipelineOptions} from './pipeline/builder.js'; export type {BackoffSettings} from './retry/backoff.js'; export type {RetrySettings} from './retry/settings.js'; export type {RetryStepOptions} from './retry/retry-step.js'; diff --git a/packages/core/src/observability/diagnostic-context.test.ts b/packages/core/src/observability/diagnostic-context.test.ts index 7ec1c79..ba80ff5 100644 --- a/packages/core/src/observability/diagnostic-context.test.ts +++ b/packages/core/src/observability/diagnostic-context.test.ts @@ -1,7 +1,9 @@ // SPDX-License-Identifier: MIT // packages/core/src/observability/diagnostic-context.test.ts // Exercises: OBS-10 (default allow-list {trace.id, span.id}, null allow-list folds all, null values skipped), -// OBS-24 (immutable snapshot bridge: capture, reinstall, restore including on throw). +// OBS-24 (immutable snapshot bridge: capture, reinstall, restore including on throw), OBS-22/OBS-23's +// scoping mechanics (AsyncScopedStore.run unwinds across an await and over an enter() its callback made, +// where the enter() handle alone does not). import {describe, expect, test} from 'bun:test'; import { captureDiagnosticSnapshot, @@ -156,6 +158,38 @@ describe('pushDiagnosticFields', () => { }); describe('createAsyncScopedStore', () => { + test('run installs the value for the callback and restores across an await', async () => { + const store = createAsyncScopedStore(); + expect(store.get()).toBeUndefined(); + + await store.run('scoped', async () => { + expect(store.get()).toBe('scoped'); + await Promise.resolve(); + expect(store.get()).toBe('scoped'); + }); + + expect(store.get()).toBeUndefined(); + }); + + test('run unwinds an enter() its callback left open, and restores on a throw', () => { + const store = createAsyncScopedStore(); + store.run('outer', () => { + // The handle form, deliberately never closed -- what the LOGGING pillar's correlation scope + // effectively does once its close() lands in a later continuation. + store.enter('inner'); + expect(store.get()).toBe('inner'); + }); + expect(store.get()).toBeUndefined(); + + expect(() => { + store.run('outer', () => { + store.enter('inner'); + throw new Error('boom'); + }); + }).toThrow('boom'); + expect(store.get()).toBeUndefined(); + }); + test('enter installs value and returned restore function resets prior value', () => { const store = createAsyncScopedStore(); expect(store.get()).toBeUndefined(); diff --git a/packages/core/src/observability/diagnostic-context.ts b/packages/core/src/observability/diagnostic-context.ts index 9cfa324..4c0ecf5 100644 --- a/packages/core/src/observability/diagnostic-context.ts +++ b/packages/core/src/observability/diagnostic-context.ts @@ -77,6 +77,15 @@ export function runWithSnapshot( * The scope-handle form of `withDiagnosticFields`, for callers that cannot express their scope as a single * callback -- OBS-23's span-correlation scope is one: a pipeline step pushes before `await next(...)` and * restores after, with the two halves in different statements. Returns the restore function. + * + * **The restore reaches only the continuation that called it.** `enterWith` installs the store on the + * *current* async resource and every resource created from it; the returned function does the same with + * the previous store. Call it after an `await` and it runs on a different resource, so the caller that + * pushed keeps the pushed fields for the rest of its own continuation -- which is a leak when that caller + * is a library entry point and the continuation is the application's. Use `withDiagnosticFields` whenever + * the scope CAN be written as one callback; that form is `AsyncLocalStorage.run`, which restores on exit + * by construction. `Runtime.send` used this handle until 2026-09-05 and leaked `trace.id`/`span.id` into + * every subsequent application log (audit #67 / #80). */ export function pushDiagnosticFields( fields: Readonly>, @@ -105,14 +114,37 @@ export function pushDiagnosticFields( */ export interface AsyncScopedStore { get(): T | undefined; - /** Installs `value` for the rest of this async context; the returned function restores the prior value. */ + /** + * Installs `value` for the rest of this async context; the returned function restores the prior value. + * + * Carries `pushDiagnosticFields`' caveat verbatim: the restore is an `enterWith` of its own, so it takes + * effect only on the async resource that runs it. A handle closed after an `await` leaves `value` + * installed on the resource that entered it. Prefer {@link AsyncScopedStore.run} for any scope that can + * be written as one callback. + */ enter(value: T): () => void; + /** + * Runs `fn` with `value` installed, restoring whatever was installed before when `fn` returns -- + * including on a throw, and including for anything `fn` itself entered with the handle form. This is + * `AsyncLocalStorage.run`, so the restore is structural rather than a call a later continuation has to + * remember to make, and it is what a library entry point must use if the caller's context is to survive + * the call. + * + * `fn`'s return value is passed through untouched: an `async` callback hands back its promise, and the + * store is restored when the callback's synchronous prefix returns, not when the promise settles. That + * is the intended scoping -- everything the promise chain does inherits the store from the resource it + * was created on. + */ + run(value: T, fn: () => R): R; } export function createAsyncScopedStore(): AsyncScopedStore { const scoped = new AsyncLocalStorage(); return { get: () => scoped.getStore(), + run(value: T, fn: () => R): R { + return scoped.run(value, fn); + }, enter(value: T): () => void { const previous = scoped.getStore(); scoped.enterWith(value); diff --git a/packages/core/src/observability/logging-step.test.ts b/packages/core/src/observability/logging-step.test.ts index 82894e6..ba7e12d 100644 --- a/packages/core/src/observability/logging-step.test.ts +++ b/packages/core/src/observability/logging-step.test.ts @@ -6,7 +6,11 @@ // OBS-34 (granularity gates log events, not span/metrics), OBS-35 (level resolves from // Configuration, tolerant/case-insensitive), OBS-39 (stable http.request/http.response event names/keys, // url.full always redacted), OBS-20 (a throwing Logger is caught and re-surfaced as http.instrumentation.*; -// a throwing tracer/meter propagates, NOT caught), OBS-36, OBS-37, OBS-38 (body previews). +// a throwing tracer/meter propagates, NOT caught), OBS-36, OBS-37, OBS-38 (body previews), OBS-20's +// body-drain half (a failed request-side probe or response-side drain emits +// http.instrumentation.bodyCaptureFailed and the request still completes), OBS-35's "MUST NOT bake in a +// default config key name" (the configKey setting), OBS-21 (the per-request span ends exactly once, +// even when end() itself throws). import {afterEach, describe, expect, test} from 'bun:test'; import {Headers} from '../http/headers.js'; import {Protocol} from '../http/protocol.js'; @@ -21,6 +25,7 @@ import { ConfigurationBuilder, setGlobalConfiguration, } from '../config/configuration.js'; +import type {Body} from '../body/body.js'; import {stringBody} from '../body/simple-bodies.js'; import type {Logger, LogEvent} from './logger.js'; import type {Meter} from './metrics.js'; @@ -616,3 +621,160 @@ describe('request body preview and validation (OBS-36, OBS-38)', () => { expect(responseEvent?.['http.response.body.preview']).toBeUndefined(); }); }); + +/** A declared-length response whose body errors on the first read -- a drain that cannot finish. */ +function failingResponse(error: Error): Response { + const failingStream = new ReadableStream({ + start(controller) { + controller.error(error); + }, + }); + return Response.newBuilder() + .request(Request.newBuilder().url('https://example.com').build()) + .protocol(Protocol.HTTP_1_1) + .status(Status.of(200)) + .headers( + Headers.newBuilder() + .set('content-type', 'text/plain') + .set('content-length', '100') + .build(), + ) + .body(failingStream) + .build(); +} + +describe('body-drain diagnostics (OBS-20)', () => { + test('a failing response drain emits http.instrumentation.bodyCaptureFailed with the cause', async () => { + const {logger, events} = spyLogger(); + const broke = new Error('stream broke'); + + const response = await send( + loggingStep({logger, granularity: 'body'}), + new FakeTransport([failingResponse(broke)]), + ); + + expect(response.status.code).toBe(200); // OBS-20: the request still completes + const diagnostic = events.find( + e => e.event === 'http.instrumentation.bodyCaptureFailed', + ); + expect(diagnostic).toBeDefined(); + expect(diagnostic?.['http.message.direction']).toBe('response'); + expect(diagnostic?.cause).toBe(broke); + const responseEvent = events.find(e => e.event === 'http.response'); + expect(responseEvent?.['http.response.body.preview']).toBeUndefined(); + }); + + test('a failing request-body probe emits the same diagnostic and still sends the request', async () => { + const {logger, events} = spyLogger(); + const gone = new Error('ENOENT: the file went away'); + // What `fileBody()` over a deleted file looks like to the step: replayable, so the tap probes + // it, and the probe is the thing that fails. + const brokenBody: Body = { + kind: 'file', + mediaType: 'application/octet-stream', + contentLength: 3, + replayable: true, + writeTo: () => Promise.reject(gone), + }; + const request = Request.newBuilder() + .url('https://example.com/upload') + .method('POST') + .body(brokenBody) + .build(); + + const response = await send( + loggingStep({logger, granularity: 'body'}), + new FakeTransport([countingResponse(200).response]), + request, + ); + + expect(response.status.code).toBe(200); + const diagnostic = events.find( + e => e.event === 'http.instrumentation.bodyCaptureFailed', + ); + expect(diagnostic).toBeDefined(); + expect(diagnostic?.['http.message.direction']).toBe('request'); + expect(diagnostic?.cause).toBe(gone); + // The empty capture still ships, as it did before: the tap saw no bytes, and the preview field is + // what the tap holds. What changed is that the empty string is no longer the ONLY evidence -- the + // diagnostic above says which direction failed and why. + const requestEvent = events.find(e => e.event === 'http.request'); + expect(requestEvent?.['http.request.body.preview']).toBe(''); + }); +}); + +describe('the config key the ambient granularity is read from (OBS-35)', () => { + test('configKey names the key, so the baked-in default is not the only one', async () => { + setGlobalConfiguration( + new ConfigurationBuilder() + .put('ACME_SDK_LOG_LEVEL', 'headers') + .put(CFG_KEY_LOG_LEVEL, 'none') + .build(), + ); + const {logger, events} = spyLogger(); + + await send( + loggingStep({logger, configKey: 'ACME_SDK_LOG_LEVEL'}), + new FakeTransport([countingResponse(200).response]), + ); + + expect(events.map(e => e.event)).toEqual(['http.request', 'http.response']); + }); + + test('an explicit granularity still wins over the configured key (OBS-34)', async () => { + setGlobalConfiguration( + new ConfigurationBuilder().put('ACME_SDK_LOG_LEVEL', 'headers').build(), + ); + const {logger, events} = spyLogger(); + + await send( + loggingStep({ + logger, + configKey: 'ACME_SDK_LOG_LEVEL', + granularity: 'none', + }), + new FakeTransport([countingResponse(200).response]), + ); + + expect(events).toHaveLength(0); + }); +}); + +describe('the per-request span ends exactly once (OBS-21, OBS-29)', () => { + test('an end() that throws on the success path is not called a second time', async () => { + const {logger} = spyLogger(); + let ends = 0; + const endFailed = new Error('end failed'); + const exceptions: unknown[] = []; + const span = { + isRecording: true, + setAttribute: () => span, + recordException: (error: unknown) => { + exceptions.push(error); + return span; + }, + end: (): void => { + ends += 1; + throw endFailed; + }, + }; + + let caught: unknown; + try { + await send( + loggingStep({ + logger, + granularity: 'headers', + tracerFactory: () => ({startSpan: () => span}), + }), + new FakeTransport([countingResponse(200).response]), + ); + } catch (error) { + caught = error; + } + + expect(caught).toBe(endFailed); + expect(ends).toBe(1); + expect(exceptions).toEqual([]); + }); +}); diff --git a/packages/core/src/observability/logging-step.ts b/packages/core/src/observability/logging-step.ts index 11f60d7..dfd5cd2 100644 --- a/packages/core/src/observability/logging-step.ts +++ b/packages/core/src/observability/logging-step.ts @@ -59,8 +59,24 @@ export interface LoggingStepSettings { * Default: 'info' (failures always emit at 'error'). */ readonly severity?: LogLevel | undefined; - /** Granularity of logging (default: resolved from Configuration via CFG_KEY_LOG_LEVEL, fallback 'none'). */ + /** Granularity of logging (default: resolved from Configuration via {@link LoggingStepSettings.configKey}, fallback 'none'). */ readonly granularity?: LoggingGranularity | undefined; + /** + * The configuration key the ambient granularity is read from when `granularity` is omitted (OBS-35). + * + * OBS-35 says the SDK MUST NOT bake in a default key name, and `CFG_KEY_LOG_LEVEL` + * (`DEXPACE_LOG_LEVEL`) is exactly that — CFG-14's well-known key, kept as the default because a + * required key would mean no caller gets ambient logging without naming one first. Set this to read + * a host application's own key instead; the resolution is the same layered, tolerant one either way. + * + * Nothing installs a configuration that reads the process environment by default: the global slot + * starts empty (CFG-13), so `setGlobalConfiguration(defaultConfiguration())` is the wiring that + * makes any environment variable — this one included — reachable. See + * `docs/sdk-documentation/pipelines.md`, "Turning logging on from the environment". + * + * @defaultValue {@link CFG_KEY_LOG_LEVEL} + */ + readonly configKey?: string | undefined; /** Byte limit for request/response body previews (default: 8192). */ readonly previewSizeBytes?: number | undefined; /** Optional custom tracer factory. */ @@ -82,7 +98,7 @@ function resolveGranularity(settings: LoggingStepSettings): LoggingGranularity { return 'none'; } const raw = getGlobalConfiguration() - .getString(CFG_KEY_LOG_LEVEL, 'none') + .getString(settings.configKey ?? CFG_KEY_LOG_LEVEL, 'none') ?.trim() .toLowerCase(); if (raw === 'headers' || raw === 'body') return raw; @@ -162,6 +178,32 @@ function safeEmit(logger: Logger, build: () => void): void { } } +/** + * OBS-20's body-drain clause. A capture failure is contained -- the request completes and the caller's + * body is untouched -- but containment is not silence: the failure re-surfaces as a best-effort + * `http.instrumentation.*` diagnostic, through the same {@link safeEmit} every other emission uses, so a + * secondary failure while reporting it is swallowed in turn. + * + * `verbose`, the level its sibling `http.instrumentation.logFailure` already emits at: nothing about the + * request changed, and what was lost is a diagnostic preview. Before 2026-09-05 both catches returned an + * empty capture and emitted nothing at all, so a `fileBody()` over a deleted file logged + * `"http.request.body.preview": ""` with no trace of why (audit #67 / #80). + */ +function emitBodyCaptureFailure( + logger: Logger, + direction: 'request' | 'response', + error: unknown, +): void { + safeEmit(logger, () => { + logger + .atLevel('verbose') + .event('http.instrumentation.bodyCaptureFailed') + .field('http.message.direction', direction) + .cause(error) + .emit(); + }); +} + /** * Stable identity symbol for the LOGGING pillar step. * @@ -273,12 +315,13 @@ function resolveTracer( /** Captures response body preview safely when content-length is declared (OBS-36, OBS-37). */ async function captureResponseBody( response: Response, - previewSizeBytes: number, + context: EmitContext, ): Promise<{ readonly response: Response; readonly preview: string | undefined; readonly size: number | undefined; }> { + const previewSizeBytes = context.previewSizeBytes; try { const hasContentLength = response.headers.has('content-length'); if (response.body === null || !hasContentLength) { @@ -306,33 +349,34 @@ async function captureResponseBody( ); const size = snap.length > 0 ? snap.length : undefined; return {response: captured, preview, size}; - } catch { - // OBS-20: body-drain failure must never fail the request + } catch (error) { + // OBS-20: a body-drain failure must never fail the request -- and must not vanish either. + emitBodyCaptureFailure(context.logger, 'response', error); return {response, preview: undefined, size: undefined}; } } async function prepareRequestBody( request: Request, - granularity: LoggingGranularity, - previewSizeBytes: number, + context: EmitContext, ): Promise<{ readonly outbound: Request; readonly preview: string | undefined; readonly size: number | undefined; }> { - if (granularity !== 'body' || request.body === undefined) { + if (context.granularity !== 'body' || request.body === undefined) { return {outbound: request, preview: undefined, size: undefined}; } - const logged = withRequestLogging(request.body, previewSizeBytes); + const logged = withRequestLogging(request.body, context.previewSizeBytes); if (logged.replayable) { const probeSink = new WritableStream({ write: () => undefined, }); try { await logged.writeTo(probeSink); - } catch { - // probe error is ignored per OBS-20 + } catch (error) { + // OBS-20: the probe is diagnostic-only, so its failure is contained -- and reported. + emitBodyCaptureFailure(context.logger, 'request', error); } } const snap = logged.snapshot(); @@ -368,7 +412,7 @@ interface PipelineExecutionArgs { async function executePipeline(args: PipelineExecutionArgs): Promise { const {ctx, plan, outbound, startedAt, span} = args; - const {emitContext, instruments, previewSizeBytes} = plan; + const {emitContext, instruments} = plan; try { const response = await ctx.next(outbound); const { @@ -376,7 +420,7 @@ async function executePipeline(args: PipelineExecutionArgs): Promise { preview, size, } = emitContext.granularity === 'body' - ? await captureResponseBody(response, previewSizeBytes) + ? await captureResponseBody(response, emitContext) : {response, preview: undefined, size: undefined}; const elapsedMs = instruments.clock.monotonic() - startedAt; @@ -395,7 +439,6 @@ async function executePipeline(args: PipelineExecutionArgs): Promise { size, }); - span.end(); return captured; } catch (caught) { const error = toError(caught); @@ -412,7 +455,6 @@ async function executePipeline(args: PipelineExecutionArgs): Promise { emitFailureEvent(emitContext, {error, elapsedMs}); span.recordException(error); - span.end(); throw caught; } } @@ -422,7 +464,7 @@ async function handleRequestExecution( ctx: StepContext, plan: ExecutionPlan, ): Promise { - const {settings, emitContext, instruments, previewSizeBytes} = plan; + const {settings, emitContext, instruments} = plan; const tracer = resolveTracer(settings, ctx); const span = tracer.startSpan('http.client.request'); const scope = activateSpanForCorrelation(span); @@ -431,8 +473,7 @@ async function handleRequestExecution( try { const {outbound, preview, size} = await prepareRequestBody( request, - emitContext.granularity, - previewSizeBytes, + emitContext, ); emitRequestEvent(emitContext, outbound, {preview, size}); return await executePipeline({ @@ -443,7 +484,17 @@ async function handleRequestExecution( span, }); } finally { - scope.close(); + // ONE exit for `end()`, and it is here rather than on each path inside `executePipeline`: an + // `end()` that threw on the success path used to land in that function's own `catch`, which + // recorded the exception and called `end()` a second time on a span the tracer had already + // closed (OBS-21's idempotent-end clause is the tracer's promise, not this step's licence). + // Nested rather than sequential so a throwing `end()` -- which OBS-20 deliberately does not + // catch, because OBS-30 makes it the SPI's promise not to -- still cannot leak the scope. + try { + span.end(); + } finally { + scope.close(); + } } } diff --git a/packages/core/src/observability/redaction.test.ts b/packages/core/src/observability/redaction.test.ts index 6374a3c..8ce88ff 100644 --- a/packages/core/src/observability/redaction.test.ts +++ b/packages/core/src/observability/redaction.test.ts @@ -102,6 +102,15 @@ describe('redactUrl: delimiters and total safety (OBS-14..15)', () => { expect(redactUrl('not a url at all ###')).toBe('[malformed url]'); }); + test('the output is re-rendered from the parsed URL, so WHATWG normalisation shows (OBS-14)', () => { + // Pinned, not fixed: the result is assembled from `URL`'s components, so host case, a default + // port and an empty path normalise on the way through. Documented on `redactUrl` as inherent to + // parsing, and left as is by audit #67 / #80 -- re-rendering the caller's authority by hand would + // be a second URL renderer for no gain in what OBS-11..15 asks for. + expect(redactUrl('https://EXAMPLE.com:443')).toBe('https://example.com/'); + expect(redactUrl('http://Example.COM:80/p')).toBe('http://example.com/p'); + }); + test('property: never throws for any string', () => { fc.assert( fc.property(fc.string(), value => { diff --git a/packages/core/src/observability/redaction.ts b/packages/core/src/observability/redaction.ts index 5d8a137..b398840 100644 --- a/packages/core/src/observability/redaction.ts +++ b/packages/core/src/observability/redaction.ts @@ -52,6 +52,16 @@ function hasHashDelimiter(input: URL | string): boolean { /** * Redacts sensitive components from a URL according to spec rules (OBS-11..15). * + * **The result is a re-rendered URL, not the caller's string with holes in it.** Every input goes + * through WHATWG `URL`, and the output is assembled from its parsed components, so the normalisations + * parsing performs come with it: the host is lower-cased, a default port for the scheme + * (`https://h:443/`) is dropped, a missing path becomes `/`, and percent-encoding is canonicalised. + * A log line therefore need not match the request line byte for byte. That is inherent to parsing and + * is left as is deliberately (audit #67 / #80): re-rendering the original authority by hand would mean + * a second URL renderer in this package, maintained against WHATWG, for no gain in what OBS-11..15 + * actually asks for — that userinfo, non-allow-listed query values and fragment values do not reach a + * log. Compare identity elsewhere; this is for humans and log pipelines. + * * @param input - the URL or string to redact. * @param queryAllowList - set of allowed query parameter names (default: \{api-version\}). * @returns the redacted URL string, or '[malformed url]' if parsing fails. diff --git a/packages/core/src/observability/tracing.ts b/packages/core/src/observability/tracing.ts index c0d9bcb..c98d692 100644 --- a/packages/core/src/observability/tracing.ts +++ b/packages/core/src/observability/tracing.ts @@ -84,17 +84,42 @@ export function getActiveSpan(): Span { * @public */ export function activateSpan(span: Span): Scope { + requireSpan(span, 'activateSpan'); + + const restore = spanStorage.enter(span); + return {close: restore}; +} + +function requireSpan(span: Span, caller: string): void { invariant( (span as unknown) !== null && (span as unknown) !== undefined, - 'activateSpan: span is required', + `${caller}: span is required`, ); invariant( typeof span.end === 'function', - 'activateSpan: span must implement end()', + `${caller}: span must implement end()`, ); +} - const restore = spanStorage.enter(span); - return {close: restore}; +/** + * The callback form of {@link activateSpan}, for a scope that can be written as one function: `span` is + * active for the whole of `fn`, and whatever was active before is active again the moment `fn` returns. + * + * `activateSpan`'s handle cannot make that promise across an `await`. Its `close()` is an `enterWith` on + * whichever async resource happens to run it, so a scope opened before an `await` and closed after one + * leaves the span installed on the resource that opened it -- the caller's, when the opener is + * `Runtime.send`. This form is `AsyncLocalStorage.run`, which unwinds structurally instead. The handle + * stays because OBS-22 specifies one; this is what the runtime uses. + * + * @param span - the span to activate for the extent of `fn`. + * @param fn - the work to run with `span` active. Its result is passed through untouched. + * @returns whatever `fn` returned. + * + * @internal + */ +export function runWithActiveSpan(span: Span, fn: () => T): T { + requireSpan(span, 'runWithActiveSpan'); + return spanStorage.run(span, fn); } /** Extracts trace.id and span.id from OpenTelemetry-compatible spanContext() if present. */ diff --git a/packages/core/src/pipeline/builder.test.ts b/packages/core/src/pipeline/builder.test.ts index ad22b1a..9e5b306 100644 --- a/packages/core/src/pipeline/builder.test.ts +++ b/packages/core/src/pipeline/builder.test.ts @@ -8,13 +8,20 @@ // scratch), PIPE-23 (a colliding reload leaves prior content untouched, and a same-type pillar repeat inside // one batch seats only one step), PIPE-25 (flatten order), PIPE-38 (appendAll preserves batch order; // prependAll reverses it), PIPE-1/PIPE-2 (a built pipeline, driven: entry in STAGE_ORDER, exit reversed), -// PIPE-35 (seedFrom's explicit, non-defaulted flatten-vs-nest modes) +// PIPE-35 (seedFrom's explicit, non-defaulted flatten-vs-nest modes), OBS-29 + CTX-16 (the public +// instrumentation options bag: the supplied bundle opens the operation span, the operation name reaches +// the request context, and flatten seeding carries both) import {describe, expect, test} from 'bun:test'; import fc from 'fast-check'; import {Protocol} from '../http/protocol.js'; import {Request} from '../http/request.js'; import {Response} from '../http/response.js'; import {Status} from '../http/status.js'; +import { + createInstrumentationBundle, + type Span, + type Tracer, +} from '../observability/tracing.js'; import type {Transport} from '../seams/transport.js'; import {PipelineBuilder} from './builder.js'; import { @@ -545,3 +552,98 @@ describe('PipelineBuilder.seedFrom nest mode (PIPE-35)', () => { expect(runtime.transport).toBe(seeded); }); }); + +/** Records the name of every span it is asked to open, so a test can count operations. */ +function countingTracer(): {tracer: Tracer; names: string[]} { + const names: string[] = []; + const span: Span = { + isRecording: true, + setAttribute: (): Span => span, + recordException: (): Span => span, + end: (): void => undefined, + }; + return { + names, + tracer: { + startSpan(name: string): Span { + names.push(name); + return span; + }, + }, + }; +} + +/** Captures what the drive's `RequestContext` says, from inside the pipeline. */ +function contextProbe(seen: { + operationName?: string | undefined; +}): StepDescriptor { + return { + type: Symbol('context-probe'), + stage: 'PRE_SERDE', + fn: async (request, ctx) => { + seen.operationName = + 'operationName' in ctx.context ? ctx.context.operationName : undefined; + return ctx.next(request); + }, + }; +} + +describe('PipelineBuilder instrumentation options (OBS-29, CTX-16)', () => { + test('the supplied bundle is what opens the per-operation span', async () => { + const {tracer, names} = countingTracer(); + const runtime = new PipelineBuilder(new RecordingTransport(), { + instrumentation: createInstrumentationBundle(() => tracer), + }) + .append(descriptor('probe', 'PRE_SERDE')) + .build(); + + await runtime.send(aRequest('https://example.com')); + await runtime.send(aRequest('https://example.com')); + + expect(names).toEqual(['http.client.operation', 'http.client.operation']); + }); + + test('operationName reaches the request context every step reads (CTX-16)', async () => { + const seen: {operationName?: string | undefined} = {}; + const runtime = new PipelineBuilder(new RecordingTransport(), { + operationName: 'GetUser', + }) + .append(contextProbe(seen)) + .build(); + + await runtime.send(aRequest('https://example.com')); + + expect(seen.operationName).toBe('GetUser'); + }); + + test('no options bag means the no-op bundle and no operation name', async () => { + const seen: {operationName?: string | undefined} = {}; + const runtime = new PipelineBuilder(new RecordingTransport()) + .append(contextProbe(seen)) + .build(); + + await runtime.send(aRequest('https://example.com')); + + expect(seen.operationName).toBeUndefined(); + }); + + test('flatten seeding carries the seed runtime’s options (PIPE-35)', async () => { + const {tracer, names} = countingTracer(); + const seen: {operationName?: string | undefined} = {}; + const seeded = new PipelineBuilder(new RecordingTransport(), { + instrumentation: createInstrumentationBundle(() => tracer), + operationName: 'GetUser', + }) + .append(descriptor('seeded', 'LOGGING')) + .build(); + + const runtime = PipelineBuilder.seedFrom(seeded, 'flatten') + .append(contextProbe(seen)) + .build(); + + await runtime.send(aRequest('https://example.com')); + + expect(names).toEqual(['http.client.operation']); + expect(seen.operationName).toBe('GetUser'); + }); +}); diff --git a/packages/core/src/pipeline/builder.ts b/packages/core/src/pipeline/builder.ts index 43d0573..83b383e 100644 --- a/packages/core/src/pipeline/builder.ts +++ b/packages/core/src/pipeline/builder.ts @@ -1,5 +1,6 @@ // SPDX-License-Identifier: MIT // packages/core/src/pipeline/builder.ts +import type {InstrumentationBundle} from '../context/instrumentation.js'; import {invariant} from '../invariant.js'; import type {Transport} from '../seams/transport.js'; import { @@ -8,7 +9,7 @@ import { PillarCollisionError, ReservedStageError, } from './errors.js'; -import {createRuntime, type Runtime} from './runtime.js'; +import {createRuntime, pipelineOptionsOf, type Runtime} from './runtime.js'; import {PILLAR_STAGES, STAGE_ORDER, type Stage} from './stage.js'; import type {StepDescriptor} from './step.js'; @@ -17,6 +18,37 @@ interface AnchorLocation { readonly index: number; } +/** + * What a pipeline carries into every call it drives, as opposed to what a single call carries + * (`RequestOptions`) or what one step is configured with (a pillar's own settings). + * + * Both fields are per-pipeline by construction: `CTX-4` gives every `send()` its own context key, and + * the bundle is shared by reference across that call's three promotions (`CTX-2`/`CTX-3`), so a client + * that needs two operation names builds two pipelines — cheap, since `seedFrom(runtime, 'flatten')` + * derives the second from the first and carries these options with it. + * + * @public + */ +export interface PipelineOptions { + /** + * The correlation bundle every context of every call carries (`CTX-14`), and — through its + * `tracerFactory` — the source of the one `http.client.operation` span `Runtime.send()` opens per + * logical operation (`OBS-29`). Build one with `createInstrumentationBundle(tracerFactory)`. + * + * @defaultValue the disabled-tracing no-op bundle (`CTX-15`), which opens no span at all + */ + readonly instrumentation?: InstrumentationBundle | undefined; + /** + * The advisory operation label (`CTX-16`) — a schema-defined operation id such as `'GetUser'`. + * Carried unchanged from the request context through every promotion, exposed to the tracing seam + * (the LOGGING pillar step names its per-attempt span with it), and never an input to the request, + * the dispatch decision or the store key. + * + * @defaultValue `undefined` — a raw request that belongs to no named operation + */ + readonly operationName?: string | undefined; +} + /** * Assembles a stage-based pipeline via surgical edits (PIPE-7, PIPE-18..PIPE-24), flattening into an * immutable Runtime at build() time (PIPE-25). Mutable while being built; the produced Runtime is frozen. @@ -26,9 +58,19 @@ interface AnchorLocation { export class PipelineBuilder { readonly #buckets = new Map(); readonly #transport: Transport; + readonly #options: PipelineOptions; - constructor(transport: Transport) { + /** + * @param transport - the terminal transport the built pipeline dispatches to. Never closed by the + * pipeline (PIPE-27). + * @param options - what the built pipeline carries into every call: the instrumentation bundle and + * the advisory operation name. Optional, and optional in the second position deliberately — this + * is the only public way to reach `OBS-29`'s per-operation span and `CTX-16`'s operation name, + * and adding it must not break the one-argument construction every existing caller writes. + */ + constructor(transport: Transport, options: PipelineOptions = {}) { this.#transport = transport; + this.#options = options; } /** @@ -225,7 +267,15 @@ export class PipelineBuilder { */ static seedFrom(runtime: Runtime, mode: 'flatten' | 'nest'): PipelineBuilder { if (mode === 'flatten') { - return new PipelineBuilder(runtime.transport).appendAll(runtime.steps); + // Flatten produces the pipeline that REPLACES `runtime`, so it inherits `runtime`'s + // `PipelineOptions` along with its steps: dropping them would silently un-trace a client that + // seeded from a traced preset, and there is no other way for the derived builder to recover + // them. `nest` needs no such carry -- `runtime` is still there, as the terminal transport, + // driving its own contexts with its own bundle. + return new PipelineBuilder( + runtime.transport, + pipelineOptionsOf(runtime), + ).appendAll(runtime.steps); } return new PipelineBuilder(runtime); } @@ -238,7 +288,9 @@ export class PipelineBuilder { const bucket = this.#buckets.get(stage); if (bucket !== undefined) flattened.push(...bucket); } - return createRuntime(flattened, this.#transport); // Runtime copies and freezes -- PIPE-10/PIPE-25. + // Runtime copies and freezes -- PIPE-10/PIPE-25. `PipelineOptions` is structurally the public + // half of `ContextInit`; the `key` half stays in-package, because CTX-4 wants one key per call. + return createRuntime(flattened, this.#transport, this.#options); } #rejectReservedStage(stage: Stage, operation: string): void { diff --git a/packages/core/src/pipeline/runtime.test.ts b/packages/core/src/pipeline/runtime.test.ts index 3db8ef9..6844ab4 100644 --- a/packages/core/src/pipeline/runtime.test.ts +++ b/packages/core/src/pipeline/runtime.test.ts @@ -8,7 +8,10 @@ // with one send() method, and nests inside another pipeline with the caller's options intact), PIPE-27 // (close() never touches the wrapped transport), CTX-17's positive half (the first store entry is installed // by the first promotion), CTX-1/2/3/6 (exchangeSource pins the call key and instrumentation when it -// rebuilds) +// rebuilds), OBS-22/OBS-23 (the caller's active span and diagnostic fields are what they were once +// send() settles, either way), OBS-29 (one operation span per send, ended exactly once even when end() +// throws, and a second send gets its own), CTX-11 (a throwing tracerFactory leaks no store entry), +// CTX-16 (the pipeline's operation name reaches the request context) import {describe, expect, test} from 'bun:test'; import { createRequestContext, @@ -22,7 +25,13 @@ import {Response} from '../http/response.js'; import {Status} from '../http/status.js'; import {invariant} from '../invariant.js'; import { + getDiagnosticContext, + pushDiagnosticFields, +} from '../observability/diagnostic-context.js'; +import { + NOOP_SPAN, createInstrumentationBundle, + getActiveSpan, type Span, type Tracer, } from '../observability/tracing.js'; @@ -460,3 +469,124 @@ describe('the per-operation span: 1:1 with a logical operation (OBS-29)', () => expect(response.status.code).toBe(200); }); }); + +describe('async-context hygiene across send() (OBS-22, OBS-23, OBS-29)', () => { + test('the caller observes no active span after `await send()` resolves', async () => { + const {tracer} = recordingTracer(); + expect(getActiveSpan()).toBe(NOOP_SPAN); + + await runtimeWith(tracer, new RecordingTransport(aResponse(200))).send( + aRequest('https://example.com'), + ); + + expect(getActiveSpan()).toBe(NOOP_SPAN); + }); + + test('the caller observes no active span after `await send()` rejects', async () => { + const {tracer} = recordingTracer(); + const failing: StepDescriptor = { + type: Symbol('failing'), + stage: 'PRE_REDIRECT', + fn: () => Promise.reject(new Error('boom')), + }; + + await runtimeWith(tracer, new RecordingTransport(aResponse(200)), [failing]) + .send(aRequest('https://example.com')) + .then( + () => undefined, + () => undefined, + ); + + expect(getActiveSpan()).toBe(NOOP_SPAN); + }); + + test('diagnostic fields a step pushed do not outlive the call (OBS-23)', async () => { + const pushing: StepDescriptor = { + type: Symbol('pushing'), + stage: 'PRE_REDIRECT', + fn: (request, ctx) => { + // What `activateSpanForCorrelation` does inside the LOGGING pillar step: a handle-based push + // whose restore runs in a later continuation and therefore never reaches this caller. + pushDiagnosticFields({'trace.id': 't-leaked', 'span.id': 's-leaked'}); + return ctx.next(request); + }, + }; + + await runtimeWith( + recordingTracer().tracer, + new RecordingTransport(aResponse(200)), + [pushing], + ).send(aRequest('https://example.com')); + + expect(getDiagnosticContext(null)).toEqual({}); + }); + + test('a second send() on the same runtime opens its own operation span (OBS-29)', async () => { + const {tracer, spans} = recordingTracer(); + const runtime = runtimeWith(tracer, new RecordingTransport(aResponse(200))); + + await runtime.send(aRequest('https://example.com/one')); + await runtime.send(aRequest('https://example.com/two')); + + expect(spans.length).toBe(2); + expect(spans.map(span => span.ended)).toEqual([1, 1]); + }); +}); + +describe('store and span hygiene on a failing tracer (CTX-11, OBS-29)', () => { + test('a throwing tracerFactory leaves the context store the size it found it', async () => { + const boom = new Error('tracer down'); + const runtime = createRuntime( + [passthroughStep()], + new RecordingTransport(aResponse(200)), + { + instrumentation: createInstrumentationBundle(() => { + throw boom; + }), + }, + ); + + const before = contextStore.size; + const thrown = await runtime.send(aRequest('https://example.com')).then( + () => undefined, + (error: unknown) => error, + ); + + expect(thrown).toBe(boom); + expect(contextStore.size).toBe(before); + }); + + test('an end() that throws on the success path is not called a second time', async () => { + let ends = 0; + const endFailed = new Error('end failed'); + const exceptions: unknown[] = []; + const span: Span = { + isRecording: true, + setAttribute(): Span { + return span; + }, + recordException(error: unknown): Span { + exceptions.push(error); + return span; + }, + end(): void { + ends += 1; + throw endFailed; + }, + }; + + const thrown = await runtimeWith( + {startSpan: () => span}, + new RecordingTransport(aResponse(200)), + ) + .send(aRequest('https://example.com')) + .then( + () => undefined, + (error: unknown) => error, + ); + + expect(thrown).toBe(endFailed); + expect(ends).toBe(1); + expect(exceptions).toEqual([endFailed]); + }); +}); diff --git a/packages/core/src/pipeline/runtime.ts b/packages/core/src/pipeline/runtime.ts index 03c3ad6..fb87486 100644 --- a/packages/core/src/pipeline/runtime.ts +++ b/packages/core/src/pipeline/runtime.ts @@ -11,9 +11,13 @@ import { } from '../context/context.js'; import {contextStore} from '../context/store.js'; import { - activateSpan, + captureDiagnosticSnapshot, + runWithSnapshot, +} from '../observability/diagnostic-context.js'; +import { getActiveSpan, NOOP_TRACER, + runWithActiveSpan, type Span, type Tracer, } from '../observability/tracing.js'; @@ -24,8 +28,12 @@ import type {Transport} from '../seams/transport.js'; import {Cursor} from './cursor.js'; import type {StepDescriptor} from './step.js'; -/** What `Runtime.send()` passes to `createDispatchContext`; `operationName` is not a dispatch-stage concept. */ -type RuntimeContextInit = Omit; +/** + * What a built pipeline carries into every drive. `createDispatchContext` takes the `instrumentation` + * and `key` halves -- `operationName` is not a dispatch-stage concept (CTX-16 introduces it at the + * request stage) -- and `send()` hands the name to `promoteToRequest` itself, one promotion later. + */ +type RuntimeContextInit = ContextInit; /** The advisory span name, matching what the LOGGING pillar step uses for its per-attempt spans. */ const OPERATION_SPAN_NAME = 'http.client.operation'; @@ -58,6 +66,36 @@ function startOperationSpan(context: RequestContext): Span | undefined { return span.isRecording ? span : undefined; } +/** + * Runs `drive` as the body of `span` and ends that span EXACTLY once, whichever way it finishes + * (OBS-29: `operationSucceeded` and `operationFailed` are mutually exclusive and happen once each). + * + * The `ended` latch is not belt-and-braces. `end()` is caller-supplied through `tracerFactory`, and + * OBS-20 deliberately does not wrap tracer calls -- so a throwing `end()` on the success path lands + * in the `catch` below, which is obliged to `recordException` the failure it now has to surface. + * Without the latch that path called `end()` a second time on a span the tracer already closed. + */ +async function driveWithSpan( + span: Span, + drive: () => Promise, +): Promise { + let ended = false; + const endOnce = (): void => { + if (ended) return; + ended = true; + span.end(); + }; + try { + const response = await drive(); + endOnce(); + return response; + } catch (error: unknown) { + span.recordException(error); + endOnce(); + throw error; + } +} + /** * The request context to promote from once the drive finishes: the original, unless a step substituted the * outbound request (PIPE-14), in which case an off-chain rebuild around the request that was actually sent, @@ -98,6 +136,14 @@ let create: ( contextInit: RuntimeContextInit, ) => Runtime; +/** + * The read half of the same friend-class hook: `PipelineBuilder.seedFrom(runtime, 'flatten')` builds + * the pipeline that replaces `runtime`, so it has to recover the options `runtime` was built with, + * and `#contextInit` is private. Surfaced as {@link pipelineOptionsOf} rather than as a getter, + * because a getter on this `@public` class would publish `ContextInit`'s in-package `key` slot. + */ +let readContextInit: (runtime: Runtime) => RuntimeContextInit; + /** * The built, immutable pipeline (PIPE-10, PIPE-25). Implements `Transport` itself (PIPE-26) -- Phase 2's * `Transport` SPI has one method (`send`), so there is no second `sendAsync` entry point to delegate through. @@ -134,6 +180,7 @@ export class Runtime implements Transport { static { create = (steps, transport, contextInit) => new Runtime(steps, transport, contextInit); + readContextInit = runtime => runtime.#contextInit; } /** @@ -155,6 +202,12 @@ export class Runtime implements Transport { * tracer and no span is already active — `OBS-29`'s "one tracer instance per logical operation". * It is the parent of whatever per-attempt spans the LOGGING pillar step opens inside the RETRY * and REDIRECT pipelines, which `PIPE-2` fixes there and which are therefore per *transmission*. + * Supply the tracer through `PipelineOptions.instrumentation`. + * + * @remarks The caller's async context is restored when this settles, resolved or rejected: the + * active span and the diagnostic fields (`trace.id`, `span.id`) are what they were before the + * call, so an application log emitted after `await send()` carries nothing from it. Both stores + * are scoped with `AsyncLocalStorage.run`, which also unwinds a scope a step left open. */ async send( request: Request, @@ -165,15 +218,45 @@ export class Runtime implements Transport { // PIPE-9: an empty pipeline dispatches directly to the terminal transport, no cursor allocated. return this.#transport.send(request, options, signal); } + // Every async-scoped store this call touches is RE-RUN around the drive rather than entered in + // place. `runWithSnapshot(captureDiagnosticSnapshot())` re-enters the caller's OWN diagnostic + // store under `AsyncLocalStorage.run`, which changes nothing a step can observe and everything + // about what survives the call: a `pushDiagnosticFields` below -- the LOGGING pillar's OBS-23 + // correlation scope is the shipped one -- now unwinds when `send()` returns. `#drive` does the + // same for the span slot with `runWithActiveSpan`. + // + // Until 2026-09-05 both slots were `enterWith` plus a restore closure called from a `finally`. + // `enterWith` installs on the async resource running it, and that resource is the CALLER's -- + // `send`'s synchronous prefix runs there -- while the `finally` runs on a resource created by + // the first `await` inside. So the restore reached nothing the caller could see: after + // `await send()` the ended operation span was still "active", suppressing the next call's span + // (OBS-29's 1:1 binding), and this call's `trace.id`/`span.id` rode into every subsequent + // application log through any core `Logger` (audit #67 / #80). + return runWithSnapshot(captureDiagnosticSnapshot(), () => + this.#drive(request, options, signal), + ); + } + + /** + * One drive, inside the re-entered stores `send()` established. Split out so `send()` is the + * scoping statement and nothing else: the whole body has to sit inside the `run` callback for the + * unwind to cover it, and a body that long inline reads as if the callback were optional. + */ + async #drive( + request: Request, + options: RequestOptions | undefined, + signal: AbortSignal | undefined, + ): Promise { const dispatchContext = createDispatchContext(this.#contextInit); - const requestContext = promoteToRequest(dispatchContext, request); - contextStore.install(requestContext); // CTX-17's positive half: the first store entry, at the first promotion. + // CTX-16: the operation name this pipeline was built with enters at the request stage and is + // carried unchanged by every promotion after it. + const requestContext = promoteToRequest( + dispatchContext, + request, + this.#contextInit.operationName, + ); let currentContext: ExecutionContext = requestContext; // tracks the latest install for the finally below. - // OBS-29's 1:1 binding. Started before the drive and outside every pillar, so a retry's second - // attempt and a redirect's second hop are the same operation as the first. - const span = startOperationSpan(requestContext); - const scope = span === undefined ? undefined : activateSpan(span); - try { + const drive = async (): Promise => { const cursor = new Cursor({ steps: this.#steps, transport: this.#transport, @@ -190,16 +273,20 @@ export class Runtime implements Transport { ); contextStore.install(exchangeContext); // install-or-replace under the same key (CTX-8). currentContext = exchangeContext; - span?.end(); return response; - } catch (error: unknown) { - // OBS-29: `operationFailed` and `operationSucceeded` are mutually exclusive and happen once - // each. `end()` is reached from exactly one of these two paths, never both. - span?.recordException(error); - span?.end(); - throw error; + }; + // CTX-11/CTX-17: the install and everything that can throw after it are inside ONE try, so the + // `finally` evicts on every path. `startOperationSpan` calls a caller-supplied `tracerFactory`, + // which OBS-30 says must not throw and nothing enforces; installed outside the try, one throwing + // factory left an entry in the process-wide store per failed send. + try { + contextStore.install(requestContext); // CTX-17's positive half: the first store entry, at the first promotion. + // OBS-29's 1:1 binding. Started before the drive and outside every pillar, so a retry's second + // attempt and a redirect's second hop are the same operation as the first. + const span = startOperationSpan(requestContext); + if (span === undefined) return await drive(); + return await runWithActiveSpan(span, () => driveWithSpan(span, drive)); } finally { - scope?.close(); contextStore.close(currentContext); // always the most recently installed context for this call. } } @@ -253,9 +340,11 @@ export class Runtime implements Transport { * * @param steps - the flattened, stage-ordered step array. Copied and frozen. * @param transport - the terminal transport. Never closed by the pipeline (PIPE-27). - * @param contextInit - what each drive's dispatch context is built from: the `instrumentation` - * bundle whose `tracerFactory` supplies `OBS-29`'s per-operation span, and an optional `key` - * pinning two contexts to one store slot (CTX-5). Defaults to the no-op bundle and a fresh key. + * @param contextInit - what each drive's context chain is built from: the `instrumentation` bundle + * whose `tracerFactory` supplies `OBS-29`'s per-operation span, the advisory `operationName` + * every promotion carries (CTX-16), and an optional `key` pinning two contexts to one store slot + * (CTX-5). Defaults to the no-op bundle, no operation name, and a fresh key. `PipelineBuilder`'s + * second constructor argument is the public way to supply the first two. * @returns the built, immutable runtime. * * @internal @@ -267,3 +356,18 @@ export function createRuntime( ): Runtime { return create(steps, transport, contextInit); } + +/** + * What `runtime` was built to carry into every call — the instrumentation bundle and the advisory + * operation name. The `key` slot of `ContextInit` rides along in the returned object when the + * in-package caller pinned one; `PipelineBuilder` never does. + * + * @param runtime - the built pipeline to read. + * @returns its context init, by reference. Not a copy: `createDispatchContext` and + * `promoteToRequest` only read it, and the object came from a caller that already owns it. + * + * @internal + */ +export function pipelineOptionsOf(runtime: Runtime): RuntimeContextInit { + return readContextInit(runtime); +} diff --git a/tests/node-conformance/observability.test.mjs b/tests/node-conformance/observability.test.mjs index 27300a1..dcac9d3 100644 --- a/tests/node-conformance/observability.test.mjs +++ b/tests/node-conformance/observability.test.mjs @@ -5,15 +5,25 @@ // * AsyncLocalStorage store propagation across native Node promises, microtasks, and macrotask timers (OBS-10, OBS-24). // * activateSpan / activateSpanForCorrelation scope restoration and MDC push on Node (OBS-22, OBS-23). // * W3C trace/span identifier randomness via globalThis.crypto.getRandomValues on Node (OBS-26, OBS-27). +// * What a caller's async context holds AFTER `await runtime.send()` resolves (OBS-22, OBS-23, OBS-29, +// audit #67 / #80). Node's AsyncLocalStorage is the mechanism under test, not merely the host: the +// leak this pins was `enterWith` installing on the caller's async resource with the restore closure +// running on a later one, and Bun's suite passed over it for nine phases. import assert from 'node:assert/strict'; import {describe, it} from 'node:test'; import { NOOP_SPAN, + PipelineBuilder, + Protocol, + Request, + Response, + Status, activateSpan, activateSpanForCorrelation, createInstrumentationBundle, createLogger, getActiveSpan, + loggingStep, } from '@dexpace/core'; describe('observability on Node.js native runtime floor', () => { @@ -109,3 +119,88 @@ describe('observability on Node.js native runtime floor', () => { assert.equal(emitted[0]['span.id'], spanId); }); }); + +/** A transport literal: two methods, no socket. */ +const okTransport = { + send: async request => + Response.newBuilder() + .request(request) + .status(Status.of(200)) + .protocol(Protocol.HTTP_1_1) + .body(null) + .build(), + close: async () => undefined, +}; + +/** A recording tracer whose spans carry a spanContext, so OBS-23's correlation push actually fires. */ +function recordingTracer() { + const started = []; + return { + started, + tracer: { + startSpan(name) { + const record = {name, ended: 0}; + started.push(record); + const span = { + isRecording: true, + setAttribute: () => span, + recordException: () => span, + end: () => { + record.ended += 1; + }, + spanContext: () => ({ + traceId: '4bf92f3577b34da6a3ce929d0e0e4736', + spanId: '00f067aa0ba902b7', + }), + }; + return span; + }, + }, + }; +} + +describe('async context after Runtime.send on Node.js (OBS-22, OBS-23, OBS-29)', () => { + it('leaves the caller the active span and diagnostic fields it had before the call', async () => { + const {tracer, started} = recordingTracer(); + const emitted = []; + // A pipeline built the public way, with the LOGGING pillar inside it: that step is what pushes + // OBS-23's trace.id/span.id, and before 2026-09-05 the push outlived the call. + const runtime = new PipelineBuilder(okTransport, { + instrumentation: createInstrumentationBundle(() => tracer), + }) + .append( + loggingStep({ + granularity: 'headers', + logger: createLogger(() => undefined), + }), + ) + .build(); + const request = Request.newBuilder().url('https://example.com/one').build(); + + assert.equal(getActiveSpan(), NOOP_SPAN); + const response = await runtime.send(request); + assert.equal(response.status.code, 200); + + assert.equal(getActiveSpan(), NOOP_SPAN); + createLogger((level, fields) => { + emitted.push(Object.fromEntries(fields)); + }) + .atLevel('info') + .event('application.event.after.send') + .emit(); + assert.equal(emitted.length, 1); + assert.equal(emitted[0]['trace.id'], undefined); + assert.equal(emitted[0]['span.id'], undefined); + + // OBS-29's 1:1 binding, which the leak also broke: the second call opens its own operation span. + await runtime.send(request); + const operationSpans = started.filter( + span => span.name === 'http.client.operation', + ); + assert.equal(operationSpans.length, 2); + assert.deepEqual( + operationSpans.map(span => span.ended), + [1, 1], + ); + }); +});