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), []); + }); +});