From 5272aa9a4ee8c66f850f46a6e336e9c474dc381c Mon Sep 17 00:00:00 2001 From: Bryan English Date: Mon, 2 Nov 2026 10:08:49 -0500 Subject: [PATCH] feat: share context with the OpenTelemetry SDK When the OpenTelemetry SDK runs in the same process, microtel now keeps the current span in the SDK's context store instead of its own, so spans from either side parent spans from the other. Server handlers attach a context holding a bridge span over microtel's span, and client handlers take their parent from whatever span the SDK's store holds. That also covers the SDK's HTTP instrumentation tracing inbound requests while microtel traces the outbound ones. A parent taken from the SDK's store is remote only when its span context says so, the way the SDK decides for its own spans. So a client span under an SDK span in the same process exports without the remote bit. The SDK is found through the global that the OpenTelemetry API registers its parts on, and its context keys are Symbol.for strings, so there is no dependency on @opentelemetry/api. Sharing needs a context manager with attach(), since the handlers run in diagnostics_channel subscribers that cannot wrap the code they trace in with(). Without one, microtel keeps its own context. The bridge span takes attributes, events, status, exceptions, and name changes from OTel code while the span is recording, ignores end(), and drops links. As in the SDK, a span whose trace isn't sampled is not recording. Status and exceptions follow the SDK's rules, so an ok status is final for microtel's own writes too. Events are capped at the SDK's default limit of 128, since OTel code can now add them. Requests the SDK suppresses tracing for, such as its own exports, are not traced. Each side keeps propagating trace context the way it normally does. microtel's span rides along in the SDK's context, so the baggage microtel received still reaches its client spans under an SDK span. The tests run the real SDK, pinned as devDependencies, in child processes. Signed-off-by: Bryan English --- README.md | 62 +++++++- lib/context.js | 264 ++++++++++++++++++++++++++++++++ lib/core.js | 8 - lib/instrumentations.js | 40 ++--- lib/span.js | 22 ++- package-lock.json | 252 ++++++++++++++++++++++++++++++ package.json | 7 + test/fixtures/otel-sdk-child.js | 156 +++++++++++++++++++ test/test-otel-sdk.js | 260 +++++++++++++++++++++++++++++++ 9 files changed, 1026 insertions(+), 45 deletions(-) create mode 100644 lib/context.js create mode 100644 test/fixtures/otel-sdk-child.js create mode 100644 test/test-otel-sdk.js diff --git a/README.md b/README.md index d12f6cd..3c14e02 100644 --- a/README.md +++ b/README.md @@ -289,6 +289,50 @@ OpenTelemetry SDKs export them, so a collector sees the threshold and flags too. The span flags also record whether each span's parent arrived from another process. +## Working with the OpenTelemetry SDK + +microtel can run next to the official OpenTelemetry SDK for Node.js. When the +SDK has registered a context manager that supports `attach()`, as +`@opentelemetry/context-async-hooks` 2.11.0 and later do, the two share one +context. Spans the SDK starts while microtel traces a request become children of +microtel's server span, and the client spans microtel creates become children +of whatever SDK span is current. The same holds when the SDK's HTTP +instrumentation traces inbound requests and microtel traces the outbound ones. +This needs no configuration and no dependency on `@opentelemetry/api`. Without +such a context manager, microtel keeps its own context, and the two trace +separately. + +While microtel traces a request, `trace.getActiveSpan()` returns its server +span. Attributes, events, status, exceptions, and name changes made through it +land on that span until the span ends, following the SDK's rules for status +and exceptions. As in the SDK, a span whose trace isn't sampled records none +of them, and its `isRecording()` returns false. A span keeps at most 128 events, +the SDK's default limit. +Calls to `end()` are ignored, since microtel ends its own spans, and links are +dropped. Requests made while the SDK suppresses tracing, such as its own +exports, are not traced. + +Each side propagates trace context the way it normally does. microtel forwards +the `baggage` of requests it received itself, so baggage that the SDK extracted +or set is not added to the requests microtel traces. + +Only one of them should trace each kind of request, or the request gets two +spans. Turn off the SDK's `http` and `undici` instrumentations, for example +through `getNodeAutoInstrumentations()`: + +```js +getNodeAutoInstrumentations({ + '@opentelemetry/instrumentation-http': { enabled: false }, + '@opentelemetry/instrumentation-undici': { enabled: false }, +}); +``` + +Or turn off microtel's with the `exclude` option. The two can also split the +work: the SDK's HTTP instrumentation can trace only inbound requests, with +`disableOutgoingRequestInstrumentation: true`, while microtel excludes +`node:http/server`. Each exports its own spans, so give both the same service +name. + ## Benchmarks The benchmarks use the experimental `node:bench` runner, which is also what @@ -310,14 +354,16 @@ batches of spans, with each flush awaited through the end of its export. ## Current limitations -The tracing subsystem is independent of the OpenTelemetry JavaScript packages. It -is not interoperable with `@opentelemetry/api`, and spans created by one are not -visible to the other. Running both in the same process produces duplicate trace -and span IDs. The built-in instrumentation also overwrites the `traceparent` -(and, when present, `tracestate`) header on outgoing HTTP requests, and -replaces the `baggage` header when the span carries one, discarding whatever a -userland propagator may have set. Users should run either this package or a -userland OpenTelemetry SDK, not both. +microtel does not implement the OpenTelemetry API itself. Spans created through +`@opentelemetry/api` are recorded only when the OpenTelemetry SDK is running +too, and then by the SDK. See +[Working with the OpenTelemetry SDK](#working-with-the-opentelemetry-sdk) for +how the two share context. The built-in instrumentation overwrites the +`traceparent` (and, when present, `tracestate`) header on outgoing HTTP +requests, and replaces the `baggage` header when the span carries one, +discarding whatever a userland propagator may have set. The SDK's framework +instrumentations, such as its Express instrumentation, do not yet add routes to +microtel's server spans. `init()` activates tracing in the thread that calls it. Worker threads (`node:worker_threads`) are not traced unless they call `init()` themselves. diff --git a/lib/context.js b/lib/context.js new file mode 100644 index 0000000..c0eb897 --- /dev/null +++ b/lib/context.js @@ -0,0 +1,264 @@ +'use strict'; + +// Tracks the current span. When the OpenTelemetry SDK runs in the same +// process, the current span lives in the SDK's context store instead of +// microtel's own, so spans from either side parent spans from the other. +// The OpenTelemetry API registers its parts on a global and names its +// context keys with Symbol.for, so this needs no dependency on it. + +const { AsyncLocalStorage } = require('node:async_hooks'); + +const { STATUS_ERROR, STATUS_UNSET } = require('./span'); + +const kOtelApi = Symbol.for('opentelemetry.js.api.1'); +const kSpanKey = Symbol.for('OpenTelemetry Context Key SPAN'); +const kSuppressTracingKey = Symbol.for( + 'OpenTelemetry SDK Context Key SUPPRESS_TRACING', +); + +const kTraceId = /^(?!0{32})[0-9a-f]{32}$/; +const kSpanId = /^(?!0{16})[0-9a-f]{16}$/; + +// Returned by activeParent() when the SDK has asked for no tracing, as its +// exporters do for their own requests. +const kSuppressed = Symbol('kSuppressed'); + +// microtel's span rides along in the context next to its bridge. The SDK's +// child contexts keep it, so a client span under an SDK span still inherits +// the baggage microtel received. +const kMicrotelSpan = Symbol('kMicrotelSpan'); + +const storage = new AsyncLocalStorage(); + +// The handlers run in diagnostics_channel subscribers, before the code they +// trace, so they cannot wrap it in the SDK's with(). Sharing needs a context +// manager that can also take a context imperatively, through attach(). +function sdkContextManager() { + const manager = globalThis[kOtelApi]?.context; + return typeof manager?.attach === 'function' ? manager : undefined; +} + +// The parent for a new client span: a microtel span, the span context of an +// SDK span, or undefined for none. +function activeParent() { + const manager = sdkContextManager(); + if (manager === undefined) return storage.getStore(); + + const context = manager.active(); + if (context.getValue(kSuppressTracingKey) === true) return kSuppressed; + + const span = context.getValue(kSpanKey); + if (span === undefined) return undefined; + if (span instanceof BridgeSpan) return span.span; + + const { traceId, spanId, traceFlags, traceState, isRemote } = + span.spanContext(); + if (!kTraceId.test(traceId) || !kSpanId.test(spanId)) return undefined; + return { + traceId, + spanId, + traceFlags, + isRemote: isRemote === true, + tracestate: traceState?.serialize() || undefined, + baggage: context.getValue(kMicrotelSpan)?.baggage, + }; +} + +// Makes a span current for the rest of the async chain it was created in, +// including the request handler that runs next. +function enterSpan(span) { + const manager = sdkContextManager(); + if (manager === undefined) { + storage.enterWith(span); + return; + } + // TODO(bengl): The SDK's framework instrumentations, such as Express, + // report the matched route through an RPC metadata object they look up in + // this context. Adding one here, and reading its route when the response + // finishes, would give server spans http.route and a route in their name. + manager.attach( + new Context( + new Map([ + [kSpanKey, new BridgeSpan(span)], + [kMicrotelSpan, span], + ]), + ), + ); +} + +// A minimal OpenTelemetry Context. Each server request starts from an empty +// one, as the SDK's own HTTP instrumentation does, so nothing from the code +// that started the server leaks into requests. +class Context { + #values; + + constructor(values) { + this.#values = values; + } + + getValue(key) { + return this.#values?.get(key); + } + + setValue(key, value) { + return new Context(new Map(this.#values).set(key, value)); + } + + deleteValue(key) { + const values = new Map(this.#values); + values.delete(key); + return new Context(values); + } +} + +// The OpenTelemetry Span interface over a microtel span, for the SDK and for +// code that calls trace.getActiveSpan(). Writes land on the microtel span +// while it is recording, the way the SDK's own spans take them. microtel ends +// its own spans, so end() does nothing, and links are dropped because +// microtel spans have none. +class BridgeSpan { + #spanContext; + + constructor(span) { + this.span = span; + } + + spanContext() { + const { span } = this; + this.#spanContext ??= { + traceId: span.traceId, + spanId: span.spanId, + traceFlags: span.traceFlags, + traceState: span.tracestate ? new TraceState(span.tracestate) : undefined, + isRemote: false, + }; + return this.#spanContext; + } + + // As in the SDK, a span whose trace is not sampled records nothing. + isRecording() { + return this.span.endTime === undefined && this.span.isSampled; + } + + setAttribute(key, value) { + if (this.isRecording()) this.span.setAttribute(key, value); + return this; + } + + setAttributes(attributes) { + if (this.isRecording()) { + for (const key of Object.keys(attributes)) + this.span.setAttribute(key, attributes[key]); + } + return this; + } + + // The second argument is either attributes or a time. microtel times + // events itself, so a time is ignored. + addEvent(name, attributesOrTime) { + if (!this.isRecording()) return this; + const isAttributes = + typeof attributesOrTime === 'object' && + attributesOrTime !== null && + !Array.isArray(attributesOrTime) && + !(attributesOrTime instanceof Date); + this.span.addEvent( + name, + isAttributes ? { __proto__: null, ...attributesOrTime } : undefined, + ); + return this; + } + + addLink() { + return this; + } + + addLinks() { + return this; + } + + // As the SDK does, an unset status is ignored, and only an error keeps a + // message. The span itself keeps an ok status final. + setStatus({ code, message }) { + if (this.isRecording() && code !== STATUS_UNSET) { + const isError = code === STATUS_ERROR && typeof message === 'string'; + this.span.setStatus(code, isError ? message : ''); + } + return this; + } + + updateName(name) { + if (this.isRecording()) this.span.name = name; + return this; + } + + // Maps an exception the way the SDK does. An error's code wins over its + // name as the type, and nothing is recorded without a type or a message. + recordException(exception) { + if (!this.isRecording()) return; + const attributes = { __proto__: null }; + if (typeof exception === 'string') { + attributes['exception.message'] = exception; + } else if (exception) { + const type = exception.code ? String(exception.code) : exception.name; + if (type) attributes['exception.type'] = type; + if (exception.message) + attributes['exception.message'] = exception.message; + if (exception.stack) attributes['exception.stacktrace'] = exception.stack; + } + if (attributes['exception.type'] || attributes['exception.message']) + this.span.addEvent('exception', attributes); + } + + end() {} +} + +// OpenTelemetry's TraceState interface over a tracestate header. It hands the +// header back unchanged, and a change makes a new one with the changed key +// first, as the W3C spec asks. +class TraceState { + #header; + + constructor(header) { + this.#header = header; + } + + #members() { + const members = []; + for (const member of this.#header.split(',')) { + const eq = member.indexOf('='); + if (eq > 0) + members.push([member.slice(0, eq).trim(), member.slice(eq + 1).trim()]); + } + return members; + } + + get(key) { + return this.#members().find(([k]) => k === key)?.[1]; + } + + set(key, value) { + const rest = this.#members().filter(([k]) => k !== key); + return TraceState.#of([[key, value], ...rest]); + } + + unset(key) { + return TraceState.#of(this.#members().filter(([k]) => k !== key)); + } + + serialize() { + return this.#header; + } + + static #of(members) { + return new TraceState(members.map(([k, v]) => `${k}=${v}`).join(',')); + } +} + +module.exports = { + BridgeSpan, + TraceState, + activeParent, + enterSpan, + kSuppressed, +}; diff --git a/lib/core.js b/lib/core.js index de1f576..ce1e4a9 100644 --- a/lib/core.js +++ b/lib/core.js @@ -1,7 +1,6 @@ 'use strict'; const { randomUUID } = require('node:crypto'); -const { AsyncLocalStorage } = require('node:async_hooks'); const { validateHeaderName, validateHeaderValue } = require('node:http'); const { configureSampler } = require('./sampler'); @@ -22,7 +21,6 @@ let endpoint = null; let active = false; let filter = null; // null = all modules enabled; Set = only listed modules. let exclude = null; // null = nothing excluded; Set = listed modules disabled. -let spanStorage = null; let collectorHost = null; // Normalized host (e.g. "localhost:4318") for self-trace suppression. let exportUrl = null; // The collector's full export URL, fixed after start. let serviceName = kDefaultServiceName; @@ -32,11 +30,6 @@ let exportHeaders = null; // Copied at init, sent with every export request. let resourceAttributes = null; // A copy of options.resourceAttributes, made at init. let instanceId = null; // Random per-process identity, made at init. -function getSpanStorage() { - spanStorage ??= new AsyncLocalStorage(); - return spanStorage; -} - // A filter or exclude entry matches the module itself; a broader entry // also matches its subscopes, so 'node:http' covers node:http/client and // node:http/server. @@ -259,7 +252,6 @@ module.exports = { start, isActive: () => active, getEndpoint: () => endpoint, - getSpanStorage, isModuleEnabled, getCollectorHost: () => collectorHost, getExportUrl: () => exportUrl, diff --git a/lib/instrumentations.js b/lib/instrumentations.js index c08bf9f..330b12e 100644 --- a/lib/instrumentations.js +++ b/lib/instrumentations.js @@ -12,16 +12,8 @@ const { kSpan, } = require('./span'); const { parseForwarded } = require('./forwarded'); -const { - isModuleEnabled, - getSpanStorage, - getCollectorHost, - getExportUrl, -} = require('./core'); - -// Cached at subscription time to avoid a per-event AsyncLocalStorage -// lookup. -let spanStorage; +const { activeParent, enterSpan, kSuppressed } = require('./context'); +const { isModuleEnabled, getCollectorHost, getExportUrl } = require('./core'); // Shared client-span response handling. The caller decides when the span // ends. @@ -251,13 +243,13 @@ function onHttpServerRequestStart({ request, response, socket }) { ); // The span is stashed on the response so the response handlers do not - // need a second AsyncLocalStorage lookup. + // need a second context lookup. response[kSpan] = span; - // The span deliberately stays in the AsyncLocalStorage after the request - // ends, so work started while handling it still links to the server - // span as its parent. - spanStorage.enterWith(span); + // The span deliberately stays current after the request ends, so work + // started while handling it still links to the server span as its + // parent. + enterSpan(span); // Response 'close' without 'finish' means the connection was terminated // before the response completed. Request 'close' cannot be used for @@ -343,7 +335,8 @@ function onHttpClientRequestCreated({ request }) { const exportUrl = getExportUrl(); if (authority === getCollectorHost() && path === exportUrl.pathname) return; - const parent = spanStorage.getStore(); + const parent = activeParent(); + if (parent === kSuppressed) return; const method = request.method || 'GET'; const span = new Span(method, SPAN_KIND_CLIENT, { parent }); @@ -469,7 +462,7 @@ function onHttp2ServerStreamStart({ stream, headers }) { ); // The span is stashed on the stream so the finish and close handlers do - // not need a second AsyncLocalStorage lookup. + // not need a second context lookup. stream[kSpan] = span; // A subscriber to the stream's created channel can destroy the stream @@ -483,10 +476,10 @@ function onHttp2ServerStreamStart({ stream, headers }) { return; } - // The span deliberately stays in the AsyncLocalStorage after the stream - // ends, so work started while handling it still links to the server - // span as its parent. - spanStorage.enterWith(span); + // The span deliberately stays current after the stream ends, so work + // started while handling it still links to the server span as its + // parent. + enterSpan(span); } // Fires when the response headers are submitted, so the status code is @@ -580,7 +573,8 @@ let lastOriginAddress; let lastOriginPort; function onUndiciRequestCreate({ request }) { - const parent = spanStorage.getStore(); + const parent = activeParent(); + if (parent === kSuppressed) return; const method = request.method || 'GET'; const span = new Span(method, SPAN_KIND_CLIENT, { parent }); @@ -634,8 +628,6 @@ function onUndiciRequestTrailers({ request }) { const subscribe = (name, handler) => dc.subscribe(name, guard(name, handler)); function enableInstrumentations() { - spanStorage = getSpanStorage(); - if (isModuleEnabled('node:http/server')) { subscribe('http.server.request.start', onHttpServerRequestStart); subscribe('http.server.response.finish', onHttpServerResponseFinish); diff --git a/lib/span.js b/lib/span.js index 49d9723..451eb33 100644 --- a/lib/span.js +++ b/lib/span.js @@ -14,6 +14,7 @@ const SPAN_KIND_CLIENT = 3; // (Status codes: 0 UNSET, 1 OK, 2 ERROR.) const STATUS_UNSET = 0; +const STATUS_OK = 1; const STATUS_ERROR = 2; const kSpan = Symbol('kOtelSpan'); @@ -86,6 +87,10 @@ class RemoteParent { const kNoEvents = Object.freeze([]); const kUnsetStatus = Object.freeze({ code: STATUS_UNSET, message: '' }); +// OpenTelemetry code can add events through the SDK bridge in context.js, so +// a span keeps at most this many, the OpenTelemetry SDK's default limit. +const kMaxEvents = 128; + class Span { traceId; spanId; @@ -137,8 +142,10 @@ class Span { this.traceId = parent.traceId; this.parentSpanId = parent.spanId; this.#traceFlags = parent.traceFlags; - // Any parent but a local span came from another process. - this.#remoteParent = !(parent instanceof Span); + // A parent parsed from a traceparent header came from another + // process. An OpenTelemetry SDK span context says whether it did. + this.#remoteParent = + parent instanceof RemoteParent || parent.isRemote === true; } else { this.#remoteParent = false; // A root span starts the trace, so it makes the sampling decision. @@ -165,6 +172,10 @@ class Span { return this.#traceFlags; } + get isSampled() { + return (this.#traceFlags & kTraceFlagSampled) !== 0; + } + get hasRemoteParent() { return this.#remoteParent; } @@ -217,9 +228,7 @@ class Span { } addEvent(name, attributes) { - // Only the internal exception producer uses events today; cap them - // once addEvent becomes part of a public API. - // TODO(bengl): cap the number of events per span then. + if (this.#events.length >= kMaxEvents) return this; if (this.#events === kNoEvents) this.#events = []; this.#events.push({ name, @@ -239,6 +248,8 @@ class Span { } setStatus(code, message) { + // An ok status is final, as the OpenTelemetry SDK treats it. + if (this.#status.code === STATUS_OK) return this; this.#status = { code, message: message || '' }; return this; } @@ -289,6 +300,7 @@ module.exports = { SPAN_KIND_SERVER, SPAN_KIND_CLIENT, STATUS_UNSET, + STATUS_OK, STATUS_ERROR, kSpan, }; diff --git a/package-lock.json b/package-lock.json index 59dbb61..1cc7901 100644 --- a/package-lock.json +++ b/package-lock.json @@ -9,6 +9,13 @@ "version": "0.0.0", "license": "MIT", "devDependencies": { + "@opentelemetry/api": "1.9.1", + "@opentelemetry/context-async-hooks": "2.12.0", + "@opentelemetry/core": "2.12.0", + "@opentelemetry/instrumentation": "0.223.0", + "@opentelemetry/instrumentation-http": "0.223.0", + "@opentelemetry/sdk-trace-base": "2.12.0", + "@opentelemetry/sdk-trace-node": "2.12.0", "@opentelemetry/semantic-conventions": "1.43.0", "esbuild": "0.28.2", "prettier": "3.9.10" @@ -459,6 +466,169 @@ "node": ">=18" } }, + "node_modules/@opentelemetry/api": { + "version": "1.9.1", + "resolved": "https://registry.npmjs.org/@opentelemetry/api/-/api-1.9.1.tgz", + "integrity": "sha512-gLyJlPHPZYdAk1JENA9LeHejZe1Ti77/pTeFm/nMXmQH/HFZlcS/O2XJB+L8fkbrNSqhdtlvjBVjxwUYanNH5Q==", + "dev": true, + "license": "Apache-2.0", + "engines": { + "node": ">=8.0.0" + } + }, + "node_modules/@opentelemetry/api-logs": { + "version": "0.223.0", + "resolved": "https://registry.npmjs.org/@opentelemetry/api-logs/-/api-logs-0.223.0.tgz", + "integrity": "sha512-Oepm6etVPFCn0VWB1t833iOTgz1eYBDUPxcrOR/XvwzD1+Ag9VzSPSrrKAFNJ/haatj+8CXbG47pZXvdNQKDJw==", + "dev": true, + "license": "Apache-2.0", + "dependencies": { + "@opentelemetry/api": "^1.3.0" + }, + "engines": { + "node": ">=8.0.0" + } + }, + "node_modules/@opentelemetry/context-async-hooks": { + "version": "2.12.0", + "resolved": "https://registry.npmjs.org/@opentelemetry/context-async-hooks/-/context-async-hooks-2.12.0.tgz", + "integrity": "sha512-iK/1nD7mmZVkuYjVjkdFBiCvzntJdFny1S3CYbUYyOq7V5enL6XX+gJ7eh965L1LnS11VA8mQ7Ej/ck04SB0MQ==", + "dev": true, + "license": "Apache-2.0", + "engines": { + "node": "^18.19.0 || >=20.6.0" + }, + "peerDependencies": { + "@opentelemetry/api": ">=1.0.0 <1.10.0" + } + }, + "node_modules/@opentelemetry/core": { + "version": "2.12.0", + "resolved": "https://registry.npmjs.org/@opentelemetry/core/-/core-2.12.0.tgz", + "integrity": "sha512-1HsSAuvT4/my0QrXWsyXFdWjKaPeCHsismKZgEEIb8NK13LP6DrMRlsUbvD/0F9mDWK3xDom9AMv3IscxgOnOQ==", + "dev": true, + "license": "Apache-2.0", + "dependencies": { + "@opentelemetry/semantic-conventions": "^1.29.0" + }, + "engines": { + "node": "^18.19.0 || >=20.6.0" + }, + "peerDependencies": { + "@opentelemetry/api": ">=1.0.0 <1.10.0" + } + }, + "node_modules/@opentelemetry/instrumentation": { + "version": "0.223.0", + "resolved": "https://registry.npmjs.org/@opentelemetry/instrumentation/-/instrumentation-0.223.0.tgz", + "integrity": "sha512-tttBo88TbwK1zpsH6VeJoxLQopxOjW3cnrP50fsQJRZftkSKDDwjolXXBvow2jy0LKXlNRkDQh0NT6yI/q+BEQ==", + "dev": true, + "license": "Apache-2.0", + "dependencies": { + "@opentelemetry/api-logs": "0.223.0", + "import-in-the-middle": "^3.0.0", + "require-in-the-middle": "^8.0.0" + }, + "engines": { + "node": "^18.19.0 || >=20.6.0" + }, + "peerDependencies": { + "@opentelemetry/api": "^1.3.0" + } + }, + "node_modules/@opentelemetry/instrumentation-http": { + "version": "0.223.0", + "resolved": "https://registry.npmjs.org/@opentelemetry/instrumentation-http/-/instrumentation-http-0.223.0.tgz", + "integrity": "sha512-lQkvLeRjEHwDjc2NEEAPUlk4x/0qfjhbZh0U5d2/5rPPRQ7TNvMmOtd/ForpVVPGUBfhtEDrWhqumr7vLMjBtA==", + "dev": true, + "license": "Apache-2.0", + "dependencies": { + "@opentelemetry/core": "2.12.0", + "@opentelemetry/instrumentation": "0.223.0", + "@opentelemetry/semantic-conventions": "^1.29.0", + "forwarded-parse": "2.1.2" + }, + "engines": { + "node": "^18.19.0 || >=20.6.0" + }, + "peerDependencies": { + "@opentelemetry/api": "^1.3.0" + } + }, + "node_modules/@opentelemetry/resources": { + "version": "2.12.0", + "resolved": "https://registry.npmjs.org/@opentelemetry/resources/-/resources-2.12.0.tgz", + "integrity": "sha512-+rSRoOdln6NhXTVcBdHSlZxJDNzwxadeweK2ltZO3tVtfp6aklABc06xclDk6ovRR+EiGgIcSbh/6NgjFhnb3A==", + "dev": true, + "license": "Apache-2.0", + "dependencies": { + "@opentelemetry/core": "2.12.0", + "@opentelemetry/semantic-conventions": "^1.29.0" + }, + "engines": { + "node": "^18.19.0 || >=20.6.0" + }, + "peerDependencies": { + "@opentelemetry/api": ">=1.3.0 <1.10.0" + } + }, + "node_modules/@opentelemetry/sdk-trace": { + "version": "2.12.0", + "resolved": "https://registry.npmjs.org/@opentelemetry/sdk-trace/-/sdk-trace-2.12.0.tgz", + "integrity": "sha512-ImVuRQ6faOsTi1Wna88s2avgrrf/iDgXPigIeynkUhjstMuoQUDOJXgkez2j1mlU4btjXcXBGa+q7qKFYR3GsA==", + "dev": true, + "license": "Apache-2.0", + "dependencies": { + "@opentelemetry/core": "2.12.0", + "@opentelemetry/resources": "2.12.0", + "@opentelemetry/semantic-conventions": "^1.29.0" + }, + "engines": { + "node": "^18.19.0 || >=20.6.0" + }, + "peerDependencies": { + "@opentelemetry/api": ">=1.3.0 <1.10.0" + } + }, + "node_modules/@opentelemetry/sdk-trace-base": { + "version": "2.12.0", + "resolved": "https://registry.npmjs.org/@opentelemetry/sdk-trace-base/-/sdk-trace-base-2.12.0.tgz", + "integrity": "sha512-JOERgZCxRM06FEJ5kEWxlSRChah6MmXDx3KwCruqEv/iEyLkTokCSemf2y1w8oIHtfrr8EVTpzebq/31vn2Cpg==", + "deprecated": "Use @opentelemetry/sdk-trace package", + "dev": true, + "license": "Apache-2.0", + "dependencies": { + "@opentelemetry/core": "2.12.0", + "@opentelemetry/resources": "2.12.0", + "@opentelemetry/sdk-trace": "2.12.0", + "@opentelemetry/semantic-conventions": "^1.29.0" + }, + "engines": { + "node": "^18.19.0 || >=20.6.0" + }, + "peerDependencies": { + "@opentelemetry/api": ">=1.3.0 <1.10.0" + } + }, + "node_modules/@opentelemetry/sdk-trace-node": { + "version": "2.12.0", + "resolved": "https://registry.npmjs.org/@opentelemetry/sdk-trace-node/-/sdk-trace-node-2.12.0.tgz", + "integrity": "sha512-9DufH1IlmQMoKAfot5y/FhTP1RnmhLb5K6eKmJO/bvzPjYwPAazoiAUbTZFdPbqxOXN0FEbhZx/e6SB1Og4jmg==", + "deprecated": "Use @opentelemetry/sdk-trace package", + "dev": true, + "license": "Apache-2.0", + "dependencies": { + "@opentelemetry/context-async-hooks": "2.12.0", + "@opentelemetry/core": "2.12.0", + "@opentelemetry/sdk-trace-base": "2.12.0" + }, + "engines": { + "node": "^18.19.0 || >=20.6.0" + }, + "peerDependencies": { + "@opentelemetry/api": ">=1.0.0 <1.10.0" + } + }, "node_modules/@opentelemetry/semantic-conventions": { "version": "1.43.0", "resolved": "https://registry.npmjs.org/@opentelemetry/semantic-conventions/-/semantic-conventions-1.43.0.tgz", @@ -469,6 +639,38 @@ "node": ">=14" } }, + "node_modules/cjs-module-lexer": { + "version": "2.3.0", + "resolved": "https://registry.npmjs.org/cjs-module-lexer/-/cjs-module-lexer-2.3.0.tgz", + "integrity": "sha512-lmNyBzi6iYiqyrExTctfmjd8tInx+dHu9PBomTfH5RXS53c27JMFJgzNv5TyAnm3PgGf+MLy0+Ws41/HlVxdKQ==", + "dev": true, + "license": "MIT" + }, + "node_modules/debug": { + "version": "4.4.3", + "resolved": "https://registry.npmjs.org/debug/-/debug-4.4.3.tgz", + "integrity": "sha512-RGwwWnwQvkVfavKVt22FGLw+xYSdzARwm0ru6DhTVA3umU5hZc28V3kO4stgYryrTlLpuvgI9GiijltAjNbcqA==", + "dev": true, + "license": "MIT", + "dependencies": { + "ms": "^2.1.3" + }, + "engines": { + "node": ">=6.0" + }, + "peerDependenciesMeta": { + "supports-color": { + "optional": true + } + } + }, + "node_modules/es-module-lexer": { + "version": "3.0.4", + "resolved": "https://registry.npmjs.org/es-module-lexer/-/es-module-lexer-3.0.4.tgz", + "integrity": "sha512-BldNY5mwkVu+cQ5Ymn3e6hB9Sx8XHx4ZevWbiUyZbfKxJxYO27Hf0wfzkxIaD5CAJMaGl3YspKELj0ff/7nCMA==", + "dev": true, + "license": "MIT" + }, "node_modules/esbuild": { "version": "0.28.2", "resolved": "https://registry.npmjs.org/esbuild/-/esbuild-0.28.2.tgz", @@ -511,6 +713,42 @@ "@esbuild/win32-x64": "0.28.2" } }, + "node_modules/forwarded-parse": { + "version": "2.1.2", + "resolved": "https://registry.npmjs.org/forwarded-parse/-/forwarded-parse-2.1.2.tgz", + "integrity": "sha512-alTFZZQDKMporBH77856pXgzhEzaUVmLCDk+egLgIgHst3Tpndzz8MnKe+GzRJRfvVdn69HhpW7cmXzvtLvJAw==", + "dev": true, + "license": "MIT" + }, + "node_modules/import-in-the-middle": { + "version": "3.5.3", + "resolved": "https://registry.npmjs.org/import-in-the-middle/-/import-in-the-middle-3.5.3.tgz", + "integrity": "sha512-usm/IiY63VtOyx/dm7uEoZV+EsanCDmwRUroQZIkFLGu1NVXZ8mZqIOhaN4QIJ7EsbMTuQbJXwCySCx+ozMA8g==", + "dev": true, + "license": "Apache-2.0", + "dependencies": { + "cjs-module-lexer": "^2.2.0", + "es-module-lexer": "^3.0.3", + "module-details-from-path": "^1.0.4" + }, + "engines": { + "node": ">=18" + } + }, + "node_modules/module-details-from-path": { + "version": "1.0.4", + "resolved": "https://registry.npmjs.org/module-details-from-path/-/module-details-from-path-1.0.4.tgz", + "integrity": "sha512-EGWKgxALGMgzvxYF1UyGTy0HXX/2vHLkw6+NvDKW2jypWbHpjQuj4UMcqQWXHERJhVGKikolT06G3bcKe4fi7w==", + "dev": true, + "license": "MIT" + }, + "node_modules/ms": { + "version": "2.1.3", + "resolved": "https://registry.npmjs.org/ms/-/ms-2.1.3.tgz", + "integrity": "sha512-6FlzubTLZG3J2a/NVCAleEhjzq5oxgHyaCU9yYXvcLsvoVaHJq/s5xXI6/XXP6tz7R9xAOtHnSO/tXtF3WRTlA==", + "dev": true, + "license": "MIT" + }, "node_modules/prettier": { "version": "3.9.10", "resolved": "https://registry.npmjs.org/prettier/-/prettier-3.9.10.tgz", @@ -526,6 +764,20 @@ "funding": { "url": "https://github.com/prettier/prettier?sponsor=1" } + }, + "node_modules/require-in-the-middle": { + "version": "8.0.1", + "resolved": "https://registry.npmjs.org/require-in-the-middle/-/require-in-the-middle-8.0.1.tgz", + "integrity": "sha512-QT7FVMXfWOYFbeRBF6nu+I6tr2Tf3u0q8RIEjNob/heKY/nh7drD/k7eeMFmSQgnTtCzLDcCu/XEnpW2wk4xCQ==", + "dev": true, + "license": "MIT", + "dependencies": { + "debug": "^4.3.5", + "module-details-from-path": "^1.0.3" + }, + "engines": { + "node": ">=9.3.0 || >=8.10.0 <9.0.0" + } } } } diff --git a/package.json b/package.json index ad5debd..a1ffe7a 100644 --- a/package.json +++ b/package.json @@ -32,6 +32,13 @@ "format:check": "prettier --check ." }, "devDependencies": { + "@opentelemetry/api": "1.9.1", + "@opentelemetry/context-async-hooks": "2.12.0", + "@opentelemetry/core": "2.12.0", + "@opentelemetry/instrumentation": "0.223.0", + "@opentelemetry/instrumentation-http": "0.223.0", + "@opentelemetry/sdk-trace-base": "2.12.0", + "@opentelemetry/sdk-trace-node": "2.12.0", "@opentelemetry/semantic-conventions": "1.43.0", "esbuild": "0.28.2", "prettier": "3.9.10" diff --git a/test/fixtures/otel-sdk-child.js b/test/fixtures/otel-sdk-child.js new file mode 100644 index 0000000..be16551 --- /dev/null +++ b/test/fixtures/otel-sdk-child.js @@ -0,0 +1,156 @@ +'use strict'; + +// Spawned with JSON on argv[2], { mode, init }: runs microtel next to the +// OpenTelemetry SDK, sends one request with a caller's trace context through +// a traced frontend, flushes microtel, and prints the SDK's finished spans +// and the headers the backend received as JSON. The modes: +// microtel-inbound: microtel traces every request, and OTel code in the +// handler writes to the current span. A second request runs under a +// remote span context the SDK holds, with no SDK span around it. +// sdk-inbound: the SDK's HTTP instrumentation traces inbound requests, and +// microtel traces outbound ones. +// no-attach: the SDK's context manager has no attach(), so microtel keeps +// its own context. + +const { init, flush } = require(process.env.MICROTEL_PATH); +const { mode, init: options } = JSON.parse(process.argv[2]); +init(options); + +const { context, trace } = require('@opentelemetry/api'); +const { + AsyncLocalStorageContextManager, +} = require('@opentelemetry/context-async-hooks'); +const { suppressTracing } = require('@opentelemetry/core'); +const { registerInstrumentations } = require('@opentelemetry/instrumentation'); +const { HttpInstrumentation } = require('@opentelemetry/instrumentation-http'); +const { + InMemorySpanExporter, + SimpleSpanProcessor, +} = require('@opentelemetry/sdk-trace-base'); +const { NodeTracerProvider } = require('@opentelemetry/sdk-trace-node'); + +const exporter = new InMemorySpanExporter(); +const provider = new NodeTracerProvider({ + spanProcessors: [new SimpleSpanProcessor(exporter)], +}); +if (mode === 'no-attach') { + const manager = new AsyncLocalStorageContextManager(); + provider.register({ + contextManager: { + active: () => manager.active(), + with: (...args) => manager.with(...args), + bind: (...args) => manager.bind(...args), + enable() { + manager.enable(); + return this; + }, + disable() { + manager.disable(); + return this; + }, + }, + }); +} else { + provider.register(); +} +if (mode === 'sdk-inbound') { + registerInstrumentations({ + instrumentations: [ + new HttpInstrumentation({ disableOutgoingRequestInstrumentation: true }), + ], + }); +} + +// Loaded after the instrumentation is registered, so it gets patched. +const http = require('node:http'); +const tracer = trace.getTracer('test'); + +const get = (url, headers, done) => + http.get(url, { headers }, (res) => { + res.resume(); + res.on('end', done); + }); + +const received = {}; +const backend = http.createServer((req, res) => { + received[req.url] = req.headers; + res.end('ok'); +}); +const frontend = http.createServer((req, res) => { + // Without a current span the writes are skipped, so a broken bridge + // fails the test's assertions instead of crashing this process. + const current = trace.getActiveSpan(); + if (mode === 'microtel-inbound' && current) { + current.setAttribute('app.tier', 'web'); + current.updateName('GET /users/:id'); + current.recordException(new Error('boom')); + current.setStatus({ code: 2, message: 'failed' }); + current.end(); + // microtel has ended the span by the time this runs, so it must not + // change. + res.on('finish', () => current.setAttribute('app.late', 'yes')); + } + tracer.startActiveSpan('work', (work) => { + get(`http://127.0.0.1:${backend.address().port}/down`, {}, () => { + work.end(); + res.end('ok'); + }); + }); +}); + +const listen = (server) => + new Promise((resolve) => server.listen(0, '127.0.0.1', resolve)); + +(async () => { + await listen(backend); + await listen(frontend); + + // This request stands in for an outside caller. Suppressing it keeps it + // out of the trace, the same way the SDK's exporters opt out. + await new Promise((resolve) => + context.with(suppressTracing(context.active()), () => + get( + `http://127.0.0.1:${frontend.address().port}/front`, + { + traceparent: + '00-0af7651916cd43dd8448eb211c80319c-b7ad6b7169203331-01', + tracestate: 'vendor=state', + baggage: 'user=alice', + }, + resolve, + ), + ), + ); + + // A span context the SDK took from a caller, as its propagator extracts + // one before any SDK span starts. + if (mode === 'microtel-inbound') { + const remote = trace.setSpanContext(context.active(), { + traceId: '4bf92f3577b34da6a3ce929d0e0e4736', + spanId: '00f067aa0ba902b7', + traceFlags: 1, + isRemote: true, + }); + await new Promise((resolve) => + context.with(remote, () => + get(`http://127.0.0.1:${backend.address().port}/remote`, {}, resolve), + ), + ); + } + + flush(); + frontend.close(); + backend.close(); + http.globalAgent.destroy(); + + const spans = exporter.getFinishedSpans().map((span) => ({ + name: span.name, + kind: span.kind, + traceId: span.spanContext().traceId, + spanId: span.spanContext().spanId, + parentSpanId: span.parentSpanContext?.spanId, + traceState: span.spanContext().traceState?.serialize(), + attributes: span.attributes, + })); + process.stdout.write(JSON.stringify({ spans, received })); +})(); diff --git a/test/test-otel-sdk.js b/test/test-otel-sdk.js new file mode 100644 index 0000000..5257fb7 --- /dev/null +++ b/test/test-otel-sdk.js @@ -0,0 +1,260 @@ +'use strict'; + +const assert = require('node:assert'); +const { before, describe, it } = require('node:test'); +const { + fixture, + getClientSpan, + getServerSpan, + getSpans, + spanAttrs, + spawnMicrotel, + startOTelCollector, +} = require('./common/otel'); +const { BridgeSpan, TraceState } = require('../lib/context'); +const { Span, SPAN_KIND_SERVER } = require('../lib/span'); + +const bridged = () => { + const span = new Span('GET', SPAN_KIND_SERVER); + return { span, bridge: new BridgeSpan(span) }; +}; + +const kCallerTraceId = '0af7651916cd43dd8448eb211c80319c'; +const kCallerSpanId = 'b7ad6b7169203331'; +const kRemoteTraceId = '4bf92f3577b34da6a3ce929d0e0e4736'; +const kRemoteSpanId = '00f067aa0ba902b7'; +// The SDK's own SpanKind values, which differ from the OTLP wire values. +const kSdkServer = 1; + +// Each setup runs in a child process, since the SDK registers itself +// globally and init() activates once per process. +async function run(mode, init = {}) { + const collector = await startOTelCollector(); + const { code, stdout, stderr } = await spawnMicrotel([ + fixture('otel-sdk-child.js'), + JSON.stringify({ + mode, + init: { endpoint: `http://127.0.0.1:${collector.port}`, ...init }, + }), + ]); + await collector.close(); + assert.strictEqual(code, 0, stderr); + + const { spans, received } = JSON.parse(stdout); + return { + sdk: spans, + microtel: collector.payloads.flatMap(getSpans), + received, + }; +} + +const sdkServerSpan = (spans, path) => + spans.find( + (s) => + s.kind === kSdkServer && + (s.attributes['http.target'] ?? s.attributes['url.path']) === path, + ); + +describe('otel sharing context with the OpenTelemetry SDK', () => { + describe('when microtel traces inbound requests', () => { + let result; + + before(async () => { + result = await run('microtel-inbound'); + }); + + it('chains spans from both sides into one trace', () => { + const { sdk, microtel, received } = result; + const server = getServerSpan(microtel, '/front'); + const work = sdk.find((s) => s.name === 'work'); + const client = getClientSpan(microtel, '/down'); + const backend = getServerSpan(microtel, '/down'); + + assert.partialDeepStrictEqual(server, { + traceId: kCallerTraceId, + parentSpanId: kCallerSpanId, + }); + assert.partialDeepStrictEqual(work, { + traceId: kCallerTraceId, + parentSpanId: server.spanId, + traceState: 'vendor=state', + }); + assert.partialDeepStrictEqual(client, { + traceId: kCallerTraceId, + parentSpanId: work.spanId, + }); + assert.strictEqual(backend.parentSpanId, client.spanId); + // The baggage microtel received still travels under the SDK's span. + assert.strictEqual(received['/down'].baggage, 'user=alice'); + }); + + it('marks a parent remote only when it came from another process', () => { + const { microtel } = result; + // The SDK span the handler started is in this process. The caller is + // not, and neither is a span context the SDK extracted from one. + assert.strictEqual(getClientSpan(microtel, '/down').flags, 0x101); + assert.strictEqual(getServerSpan(microtel, '/front').flags, 0x301); + assert.partialDeepStrictEqual(getClientSpan(microtel, '/remote'), { + traceId: kRemoteTraceId, + parentSpanId: kRemoteSpanId, + flags: 0x301, + }); + }); + + it('takes writes from OTel code on its spans, except end()', () => { + const { microtel } = result; + const server = getServerSpan(microtel, '/front'); + const backend = getServerSpan(microtel, '/down'); + + assert.strictEqual(server.name, 'GET /users/:id'); + assert.strictEqual(spanAttrs(server)['app.tier'], 'web'); + assert.deepStrictEqual(server.status, { code: 2, message: 'failed' }); + const exception = server.events.find((e) => e.name === 'exception'); + assert.partialDeepStrictEqual(spanAttrs(exception), { + 'exception.type': 'Error', + 'exception.message': 'boom', + }); + // end() was ignored: the span ended with its response, after the + // request the handler made. + assert.ok( + BigInt(server.endTimeUnixNano) >= BigInt(backend.endTimeUnixNano), + ); + // A write after the span ended was ignored. + assert.strictEqual(spanAttrs(server)['app.late'], undefined); + }); + }); + + describe('when the SDK traces inbound requests', () => { + let result; + + before(async () => { + result = await run('sdk-inbound', { exclude: 'node:http/server' }); + }); + + it('chains spans from both sides into one trace', () => { + const { sdk, microtel, received } = result; + const server = sdkServerSpan(sdk, '/front'); + const work = sdk.find((s) => s.name === 'work'); + const client = getClientSpan(microtel, '/down'); + const backend = sdkServerSpan(sdk, '/down'); + + assert.partialDeepStrictEqual(server, { + traceId: kCallerTraceId, + parentSpanId: kCallerSpanId, + }); + assert.strictEqual(work.parentSpanId, server.spanId); + assert.partialDeepStrictEqual(client, { + traceId: kCallerTraceId, + parentSpanId: work.spanId, + // The SDK's span is a parent in this process. + flags: 0x101, + }); + assert.strictEqual(backend.parentSpanId, client.spanId); + // microtel propagates the trace context it inherited from the SDK, but + // not the baggage the SDK extracted. + assert.strictEqual(received['/down'].tracestate, 'vendor=state'); + assert.strictEqual(received['/down'].baggage, undefined); + }); + + it('does not trace requests the SDK suppresses tracing for', () => { + const { microtel } = result; + assert.strictEqual(getClientSpan(microtel, '/front'), undefined); + assert.strictEqual(microtel.length, 1); + }); + }); + + it('keeps its own context when the SDK cannot attach one', async () => { + const { sdk, microtel } = await run('no-attach'); + const server = getServerSpan(microtel, '/front'); + const client = getClientSpan(microtel, '/down'); + const work = sdk.find((s) => s.name === 'work'); + + assert.strictEqual(client.parentSpanId, server.spanId); + assert.strictEqual(work.parentSpanId, undefined); + assert.notStrictEqual(work.traceId, server.traceId); + }); + + it('hands the SDK tracestate unchanged, and changes it like the spec', () => { + const traceState = new TraceState('a=1, b=2'); + assert.strictEqual(traceState.serialize(), 'a=1, b=2'); + assert.strictEqual(traceState.get('b'), '2'); + assert.strictEqual(traceState.set('b', '3').serialize(), 'b=3,a=1'); + assert.strictEqual(traceState.unset('a').serialize(), 'b=2'); + }); + + it('follows the SDK rules for status', () => { + for (const [writes, expected] of [ + [[1, 2], { code: 1, message: '' }], + [[2, 0], { code: 2, message: 'oops' }], + [[2, 1], { code: 1, message: '' }], + ]) { + const { span, bridge } = bridged(); + for (const code of writes) bridge.setStatus({ code, message: 'oops' }); + assert.deepStrictEqual({ ...span.status }, expected, `${writes}`); + } + const { span, bridge } = bridged(); + bridge.setStatus({ code: 2, message: 42 }); + assert.deepStrictEqual({ ...span.status }, { code: 2, message: '' }); + }); + + it('maps exceptions the way the SDK does', () => { + const { span, bridge } = bridged(); + bridge.recordException({ code: 'ECONNRESET', name: 'Error', message: 'x' }); + bridge.recordException('just a message'); + bridge.recordException({}); + + const events = span.getEvents().map((e) => ({ ...e.attributes })); + assert.deepStrictEqual(events, [ + { 'exception.type': 'ECONNRESET', 'exception.message': 'x' }, + { 'exception.message': 'just a message' }, + ]); + }); + + it('ignores writes once the span has ended', () => { + const { span, bridge } = bridged(); + span.end(); + bridge + .setAttribute('key', 'value') + .setAttributes({ other: 'value' }) + .addEvent('event') + .setStatus({ code: 2, message: 'late' }) + .updateName('late'); + bridge.recordException(new Error('late')); + + assert.strictEqual(bridge.isRecording(), false); + assert.strictEqual(span.name, 'GET'); + assert.strictEqual(span.getAttributes().key, undefined); + assert.strictEqual(span.getAttributes().other, undefined); + assert.strictEqual(span.getEvents().length, 0); + assert.strictEqual(span.status.code, 0); + }); + + it('records nothing on a span that is not sampled', () => { + const span = new Span('GET', SPAN_KIND_SERVER, { + parent: { traceId: kCallerTraceId, spanId: kCallerSpanId, traceFlags: 0 }, + }); + const bridge = new BridgeSpan(span); + bridge.setAttribute('key', 'value'); + + assert.strictEqual(bridge.isRecording(), false); + assert.strictEqual(span.getAttributes().key, undefined); + }); + + it('caps the events on a span', () => { + const { span, bridge } = bridged(); + for (let i = 0; i < 200; i++) bridge.addEvent(`event ${i}`); + assert.strictEqual(span.getEvents().length, 128); + }); + + it('tells event attributes apart from event times', () => { + const { span, bridge } = bridged(); + bridge.addEvent('with attributes', { key: 'value' }); + for (const time of [Date.now(), new Date(), [1, 2]]) + bridge.addEvent('with a time', time); + + const [first, ...rest] = span.getEvents(); + assert.strictEqual(first.attributes.key, 'value'); + for (const event of rest) + assert.deepStrictEqual(Object.keys(event.attributes), []); + }); +});