diff --git a/package-lock.json b/package-lock.json index 3e6f217..e6fd3bb 100644 --- a/package-lock.json +++ b/package-lock.json @@ -1,12 +1,12 @@ { - "name": "@scope3data/observability-js", - "version": "2.0.0", + "name": "@scope3/observability-js", + "version": "2.1.1", "lockfileVersion": 3, "requires": true, "packages": { "": { - "name": "@scope3data/observability-js", - "version": "2.0.0", + "name": "@scope3/observability-js", + "version": "2.1.1", "license": "MIT", "dependencies": { "@opentelemetry/api": "^1.9.0", @@ -22,6 +22,7 @@ }, "devDependencies": { "@biomejs/biome": "^2.0.0", + "@opentelemetry/context-async-hooks": "^2.6.1", "@types/node": "^22.0.0", "husky": "^9.1.7", "lint-staged": "^16.3.3", @@ -744,7 +745,6 @@ "resolved": "https://registry.npmjs.org/@opentelemetry/api/-/api-1.9.0.tgz", "integrity": "sha512-3giAOQvZiH5F9bMlMiv8+GSPMeqg0dbaeo58/0SlA9sxSqZhnUtxzX9/2FzyhS9sWQf5S0GJE0AKBrFqjpeYcg==", "license": "Apache-2.0", - "peer": true, "engines": { "node": ">=8.0.0" } @@ -766,7 +766,6 @@ "resolved": "https://registry.npmjs.org/@opentelemetry/context-async-hooks/-/context-async-hooks-2.6.1.tgz", "integrity": "sha512-XHzhwRNkBpeP8Fs/qjGrAf9r9PRv67wkJQ/7ZPaBQQ68DYlTBBx5MF9LvPx7mhuXcDessKK2b+DcxqwpgkcivQ==", "license": "Apache-2.0", - "peer": true, "engines": { "node": "^18.19.0 || >=20.6.0" }, @@ -779,7 +778,6 @@ "resolved": "https://registry.npmjs.org/@opentelemetry/core/-/core-2.6.1.tgz", "integrity": "sha512-8xHSGWpJP9wBxgBpnqGL0R3PbdWQndL1Qp50qrg71+B28zK5OQmUgcDKLJgzyAAV38t4tOyLMGDD60LneR5W8g==", "license": "Apache-2.0", - "peer": true, "dependencies": { "@opentelemetry/semantic-conventions": "^1.29.0" }, @@ -1265,7 +1263,6 @@ "resolved": "https://registry.npmjs.org/@opentelemetry/resources/-/resources-2.6.1.tgz", "integrity": "sha512-lID/vxSuKWXM55XhAKNoYXu9Cutoq5hFdkbTdI/zDKQktXzcWBVhNsOkiZFTMU9UtEWuGRNe0HUgmsFldIdxVA==", "license": "Apache-2.0", - "peer": true, "dependencies": { "@opentelemetry/core": "2.6.1", "@opentelemetry/semantic-conventions": "^1.29.0" @@ -1316,7 +1313,6 @@ "resolved": "https://registry.npmjs.org/@opentelemetry/sdk-trace-base/-/sdk-trace-base-2.6.1.tgz", "integrity": "sha512-r86ut4T1e8vNwB35CqCcKd45yzqH6/6Wzvpk2/cZB8PsPLlZFTvrh8yfOS3CYZYcUmAx4hHTZJ8AO8Dj8nrdhw==", "license": "Apache-2.0", - "peer": true, "dependencies": { "@opentelemetry/core": "2.6.1", "@opentelemetry/resources": "2.6.1", @@ -1351,7 +1347,6 @@ "resolved": "https://registry.npmjs.org/@opentelemetry/semantic-conventions/-/semantic-conventions-1.40.0.tgz", "integrity": "sha512-cifvXDhcqMwwTlTK04GBNeIe7yyo28Mfby85QXFe1Yk8nmi36Ab/5UQwptOx84SsoGNRg+EVSjwzfSZMy6pmlw==", "license": "Apache-2.0", - "peer": true, "engines": { "node": ">=14" } @@ -2158,7 +2153,6 @@ "resolved": "https://registry.npmjs.org/acorn/-/acorn-8.16.0.tgz", "integrity": "sha512-UVJyE9MttOsBQIDKw1skb9nAwQuR5wuGD3+82K6JgJlm/Y+KI92oNsMNGZCYdDsVtRHSak0pcV5Dno5+4jh9sw==", "license": "MIT", - "peer": true, "bin": { "acorn": "bin/acorn" }, @@ -2459,7 +2453,6 @@ "dev": true, "hasInstallScript": true, "license": "MIT", - "peer": true, "bin": { "esbuild": "bin/esbuild" }, @@ -3054,7 +3047,6 @@ "integrity": "sha512-5gTmgEY/sqK6gFXLIsQNH19lWb4ebPDLA4SdLP7dsWkIXHWlG66oPuVvXSGFPppYZz8ZDZq0dYYrbHfBCVUb1Q==", "dev": true, "license": "MIT", - "peer": true, "engines": { "node": ">=12" }, @@ -3104,7 +3096,6 @@ } ], "license": "MIT", - "peer": true, "dependencies": { "nanoid": "^3.3.11", "picocolors": "^1.1.1", @@ -3639,7 +3630,6 @@ "integrity": "sha512-jl1vZzPDinLr9eUt3J/t7V6FgNEw9QjvBPdysz9KfQDD41fQrC2Y4vKQdiaUpFT4bXlb1RHhLpp8wtm6M5TgSw==", "dev": true, "license": "Apache-2.0", - "peer": true, "bin": { "tsc": "bin/tsc", "tsserver": "bin/tsserver" @@ -3667,7 +3657,6 @@ "integrity": "sha512-w+N7Hifpc3gRjZ63vYBXA56dvvRlNWRczTdmCBBa+CotUzAPf5b7YMdMR/8CQoeYE5LX3W4wj6RYTgonm1b9DA==", "dev": true, "license": "MIT", - "peer": true, "dependencies": { "esbuild": "^0.27.0", "fdir": "^6.5.0", diff --git a/package.json b/package.json index ac272b2..cb79033 100644 --- a/package.json +++ b/package.json @@ -1,6 +1,6 @@ { "name": "@scope3/observability-js", - "version": "2.1.0", + "version": "2.1.1", "description": "Unified observability (Sentry, OpenTelemetry, Pyroscope) for Node.js services", "keywords": [ "observability", @@ -61,6 +61,7 @@ }, "devDependencies": { "@biomejs/biome": "^2.0.0", + "@opentelemetry/context-async-hooks": "^2.6.1", "@types/node": "^22.0.0", "husky": "^9.1.7", "lint-staged": "^16.3.3", diff --git a/src/__tests__/otel-setup.test.ts b/src/__tests__/otel-setup.test.ts new file mode 100644 index 0000000..e6adb8d --- /dev/null +++ b/src/__tests__/otel-setup.test.ts @@ -0,0 +1,174 @@ +import { context, propagation, trace } from '@opentelemetry/api' +import { AsyncLocalStorageContextManager } from '@opentelemetry/context-async-hooks' +import * as Sentry from '@sentry/node' +import { afterEach, beforeEach, describe, expect, it, vi } from 'vitest' + +import { init, resetForTesting } from '../provider' + +const SENTRY_DSN = 'https://examplePublicKey@o0.ingest.sentry.io/0' + +/** + * `init()` registers OpenTelemetry globals on `globalThis`, and + * `context.setGlobalContextManager()` silently refuses to replace an existing + * registration. Vitest can reuse a worker thread across test files, and + * `globalThis` outlives the module graph, so the registry is cleared on both + * sides of every test rather than trusting file-level isolation. + */ +function clearOtelGlobals(): void { + context.disable() + trace.disable() + propagation.disable() +} + +function initWithOtel(otlpEndpoint?: string): void { + init({ + serviceName: 'otel-setup-test', + otlp: otlpEndpoint ? { endpoint: otlpEndpoint } : undefined, + // Must be neither 'test' nor a deployed environment. `resolveConfig` derives + // `isTest` from it and `init()` returns before touching any instrumentation + // when that is set, and it also derives `pyroscope.enabled`, which would + // otherwise start the profiler as a side effect of every test. + environment: 'development', + enableOtel: true, + sentry: { dsn: SENTRY_DSN, enabled: false }, + }) +} + +beforeEach(() => { + clearOtelGlobals() +}) + +afterEach(() => { + resetForTesting() + clearOtelGlobals() +}) + +describe('Sentry scope isolation with OpenTelemetry enabled', () => { + it('hands withIsolationScope a forked scope, not the ambient one', () => { + initWithOtel() + + const ambient = Sentry.getIsolationScope() + const forked = Sentry.withIsolationScope((scope) => scope) + + expect(forked).not.toBe(ambient) + }) + + it('does not leak tags between sibling isolation scopes', () => { + initWithOtel() + + Sentry.withIsolationScope((scope) => { + scope.setTag('background_job.name', 'first-job') + }) + + let secondJobSaw: Record = {} + Sentry.withIsolationScope((scope) => { + secondJobSaw = { ...scope.getScopeData().tags } + }) + + expect(secondJobSaw['background_job.name']).toBeUndefined() + }) + + it('leaves the process-global isolation scope unmutated', () => { + initWithOtel() + + Sentry.withIsolationScope((scope) => { + scope.setTag('area', 'some-sweep-job') + scope.setExtra('transcriptId', 'abc123') + }) + + const globalScopeData = Sentry.getIsolationScope().getScopeData() + + expect(globalScopeData.tags.area).toBeUndefined() + expect(globalScopeData.extra.transcriptId).toBeUndefined() + }) + + it('keeps concurrent isolation scopes independent across awaits', async () => { + initWithOtel() + + // Two callers interleaving is a different mechanism from two sequential + // ones: sequential leakage only needs the global scope mutated, whereas this + // needs AsyncLocalStorage to hold two forks apart while their continuations + // interleave. The delays are staggered so the second caller finishes while + // the first is still suspended. + async function runJob(name: string, delayMs: number): Promise { + return Sentry.withIsolationScope(async (scope) => { + scope.setTag('background_job.name', name) + await new Promise((tick) => setTimeout(tick, delayMs)) + return Sentry.getIsolationScope().getScopeData().tags[ + 'background_job.name' + ] + }) + } + + const [slowJobSaw, fastJobSaw] = await Promise.all([ + runJob('slow-job', 20), + runJob('fast-job', 1), + ]) + + expect(slowJobSaw).toBe('slow-job') + expect(fastJobSaw).toBe('fast-job') + }) + + it('reports when another context manager holds the registration', () => { + const consoleError = vi.spyOn(console, 'error').mockImplementation(() => {}) + // The context manager `SentryContextManager` wraps, so it maintains the OTel + // context but carries no Sentry scopes. `setGlobalContextManager()` refuses + // to replace an existing manager, so claiming the registration first is what + // makes the library's own registration a no-op. + context.setGlobalContextManager(new AsyncLocalStorageContextManager()) + + try { + initWithOtel() + + expect(Sentry.withIsolationScope((scope) => scope)).toBe( + Sentry.getIsolationScope(), + ) + expect(consoleError).toHaveBeenCalledWith( + expect.stringContaining('Sentry scope isolation is NOT active'), + ) + } finally { + consoleError.mockRestore() + } + }) +}) + +describe('trace provider registration on the Sentry client', () => { + it('gives the client a trace provider to flush on shutdown', () => { + initWithOtel() + + // `NodeClient.flush()` and `.close()` are the only things that force-flush + // the batched span processors, and they reach them through this reference. + // Without it a graceful shutdown drops whatever the batch is still holding. + expect(Sentry.getClient()?.traceProvider).toBeDefined() + }) + + it('flushes the trace provider when the client flushes', async () => { + initWithOtel() + + const provider = Sentry.getClient()?.traceProvider + if (!provider) throw new Error('expected a registered trace provider') + const forceFlush = vi.spyOn(provider, 'forceFlush') + + await Sentry.flush() + + expect(forceFlush).toHaveBeenCalled() + }) + + it('settles the client close when span export fails', async () => { + const consoleError = vi.spyOn(console, 'error').mockImplementation(() => {}) + // A port that refuses connections stands in for a collector that is draining + // at the same time as the pod. `NodeClient.close()` flushes first and then + // shuts down the provider, so both stages must respect the shutdown budget. + initWithOtel('http://127.0.0.1:1') + + try { + Sentry.getClient() + ?.tracer.startSpan('export-failure-probe') + .end() + + await expect(Sentry.close(2000)).resolves.not.toThrow() + } finally { + consoleError.mockRestore() + } + }, 2000) +}) diff --git a/src/provider.ts b/src/provider.ts index 89da549..050ad37 100644 --- a/src/provider.ts +++ b/src/provider.ts @@ -25,6 +25,13 @@ import type { ObservabilityConfig, ResolvedConfig } from './types' let initialized = false +/** + * Per-span-processor budget for the flush that `Sentry.flush()` and + * `Sentry.close()` trigger, kept well inside a Kubernetes termination grace + * period so shutdown cannot stall on an unreachable OTLP collector. + */ +const SHUTDOWN_FLUSH_TIMEOUT_MS = 500 + /** * Initialize Sentry, Pyroscope, and (optionally) the OpenTelemetry SDK. * @@ -192,7 +199,7 @@ function initializeOtelProvider(config: ResolvedConfig): void { [ATTR_SERVICE_VERSION]: config.release, }) - const sentryClient = Sentry.getClient() + const sentryClient = Sentry.getClient() const spanProcessors: SpanProcessor[] = [ new SentrySpanProcessor() as unknown as SpanProcessor, ] @@ -201,6 +208,7 @@ function initializeOtelProvider(config: ResolvedConfig): void { const otlpExporter = new OTLPTraceExporter({ url: `${config.otlp.endpoint}/v1/traces`, headers: config.otlp.headers, + timeoutMillis: SHUTDOWN_FLUSH_TIMEOUT_MS, }) spanProcessors.push( @@ -216,11 +224,91 @@ function initializeOtelProvider(config: ResolvedConfig): void { resource, sampler: sentryClient ? new SentrySampler(sentryClient) : undefined, spanProcessors, + // Bounds each span processor during a shutdown flush. The OTel default is + // 30s, which matches `exportTimeoutMillis` below and so can outlast a + // typical Kubernetes termination grace period. + forceFlushTimeoutMillis: SHUTDOWN_FLUSH_TIMEOUT_MS, }) provider.register({ propagator: new SentryPropagator(), + // Writes Sentry's scopes onto the OpenTelemetry context, which is what backs + // `withIsolationScope` and `getCurrentScope` once Sentry's async context + // strategy is in place. A plain context manager keeps the OTel context but + // carries no scopes, so those calls all resolve to the process-global scope. + contextManager: new Sentry.SentryContextManager(), }) + + attachTraceProviderForShutdownFlush(sentryClient, provider) + warnIfScopeIsolationInactive() +} + +/** + * Gives the Sentry client the handle its `flush()` and `close()` use to drain + * the span processors, so a graceful shutdown exports what the batch is still + * holding instead of discarding it. + * + * Skipped when the client already has a provider, which means something else + * completed an OpenTelemetry setup and owns the registered globals; replacing + * its provider would point shutdown at one that never receives spans. + * + * `NodeClient.flush()` awaits `forceFlush()` without a catch, and + * `BasicTracerProvider.forceFlush()` rejects with an array of errors if any + * processor fails or times out. Left to propagate, a failing span export would + * abort the client's own event flush and discard buffered errors, so span + * export failures are contained here. + */ +function attachTraceProviderForShutdownFlush( + client: Sentry.NodeClient | undefined, + provider: NodeTracerProvider, +): void { + if (!client || client.traceProvider) { + return + } + + const forceFlush = provider.forceFlush.bind(provider) + provider.forceFlush = () => + forceFlush().catch((error) => { + console.error('OpenTelemetry span flush failed during shutdown', error) + }) + + client.traceProvider = provider +} + +/** + * Reports when Sentry scope isolation is not actually active after provider + * registration. + * + * `provider.register()` delegates to `context.setGlobalContextManager()`, which + * refuses to replace an already-registered manager and reports the refusal only + * through OpenTelemetry's diag channel. Neither SDK validator catches that: + * `Sentry.validateOpenTelemetrySetup()` early-returns in non-debug builds and + * routes its output through Sentry's debug logger, while + * `openTelemetrySetupCheck()` records elements when they are *constructed* + * rather than when they are successfully registered, and tracks them per module + * instance, so it misreads installs that cross a duplicated + * @sentry/opentelemetry copy. + * + * An active context manager hands `withIsolationScope` a freshly forked scope; a + * missing one hands back the ambient process-global scope. Comparing identity is + * an exact check and leaves no tags behind in either case. + */ +function warnIfScopeIsolationInactive(): void { + const ambient = Sentry.getIsolationScope() + const forksIsolationScope = Sentry.withIsolationScope( + (forked) => forked !== ambient, + ) + + if (!forksIsolationScope) { + console.error( + 'Sentry scope isolation is NOT active. Tags, user identity and ' + + 'transaction names will leak between concurrent requests and ' + + 'background jobs. Either an OpenTelemetry context manager was already ' + + 'registered before init() ran, or a duplicated @sentry/core resolves ' + + 'to a different version than @sentry/node and never received the ' + + 'OpenTelemetry async context strategy.', + ) + } } function initializePyroscope(config: ResolvedConfig): void {