diff --git a/.changeset/otel-trace-correlation.md b/.changeset/otel-trace-correlation.md new file mode 100644 index 00000000..512ac634 --- /dev/null +++ b/.changeset/otel-trace-correlation.md @@ -0,0 +1,14 @@ +--- +'@smooai/logger': minor +--- + +Correlate logs with OpenTelemetry traces. When a span is active, log records +now carry the span's real W3C `traceId` + `spanId` instead of a fabricated +uuid (falling back to the prior uuid correlation id only when no span is +active). Each log line is also bridged into the standard +`@opentelemetry/api-logs` facade, so it becomes an OTLP log record — correlated +to the active span — whenever an observability LoggerProvider is registered +(e.g. `@smooai/observability`'s logs signal). With no provider registered the +bridge is a no-op and stdout output is unchanged. Depends only on the +`@opentelemetry/api` + `@opentelemetry/api-logs` facades (no SDK, no circular +dep on `@smooai/observability`). diff --git a/package.json b/package.json index 069ab2cf..9ce88941 100644 --- a/package.json +++ b/package.json @@ -153,6 +153,9 @@ "devDependencies": { "@changesets/cli": "^2.28.1", "@oclif/core": "^4.2.9", + "@opentelemetry/context-async-hooks": "^1.30.0", + "@opentelemetry/sdk-logs": "^0.55.0", + "@opentelemetry/sdk-trace-base": "^1.30.0", "@rollup/plugin-alias": "latest", "@smooai/config-typescript": "^1.0.16", "@smooai/utils": "^1.3.0", @@ -169,7 +172,9 @@ "vite": "^6.2.4", "vite-node": "^3.1.1", "vite-tsconfig-paths": "^5.1.4", - "vitest": "^3.1.1" + "vitest": "^3.1.1", + "@opentelemetry/api": "^1.9.0", + "@opentelemetry/api-logs": "^0.55.0" }, "engines": { "node": ">=20.0.0" @@ -183,5 +188,9 @@ "@smooai/config-typescript", "esbuild" ] + }, + "peerDependencies": { + "@opentelemetry/api": "^1.9.0", + "@opentelemetry/api-logs": "^0.55.0" } } diff --git a/pnpm-lock.yaml b/pnpm-lock.yaml index bc547b6f..d8b25cd5 100644 --- a/pnpm-lock.yaml +++ b/pnpm-lock.yaml @@ -55,6 +55,21 @@ importers: '@oclif/core': specifier: ^4.2.9 version: 4.2.9 + '@opentelemetry/api': + specifier: ^1.9.0 + version: 1.9.1 + '@opentelemetry/api-logs': + specifier: ^0.55.0 + version: 0.55.0 + '@opentelemetry/context-async-hooks': + specifier: ^1.30.0 + version: 1.30.1(@opentelemetry/api@1.9.1) + '@opentelemetry/sdk-logs': + specifier: ^0.55.0 + version: 0.55.0(@opentelemetry/api@1.9.1) + '@opentelemetry/sdk-trace-base': + specifier: ^1.30.0 + version: 1.30.1(@opentelemetry/api@1.9.1) '@rollup/plugin-alias': specifier: latest version: 6.0.0(rollup@4.38.0) @@ -533,6 +548,64 @@ packages: resolution: {integrity: sha512-VSk+SwKDkGShuRGC5f5WNF/U6Y8JvLfzIaWjLxMe4GlBmln0mKhHqvcfJc2gZOiyJp1QYK638H1w/peSkoZHag==} engines: {node: '>=18.0.0'} + '@opentelemetry/api-logs@0.55.0': + resolution: {integrity: sha512-3cpa+qI45VHYcA5c0bHM6VHo9gicv3p5mlLHNG3rLyjQU8b7e0st1rWtrUn3JbZ3DwwCfhKop4eQ9UuYlC6Pkg==} + engines: {node: '>=14'} + + '@opentelemetry/api@1.9.1': + resolution: {integrity: sha512-gLyJlPHPZYdAk1JENA9LeHejZe1Ti77/pTeFm/nMXmQH/HFZlcS/O2XJB+L8fkbrNSqhdtlvjBVjxwUYanNH5Q==} + engines: {node: '>=8.0.0'} + + '@opentelemetry/context-async-hooks@1.30.1': + resolution: {integrity: sha512-s5vvxXPVdjqS3kTLKMeBMvop9hbWkwzBpu+mUO2M7sZtlkyDJGwFe33wRKnbaYDo8ExRVBIIdwIGrqpxHuKttA==} + engines: {node: '>=14'} + peerDependencies: + '@opentelemetry/api': '>=1.0.0 <1.10.0' + + '@opentelemetry/core@1.28.0': + resolution: {integrity: sha512-ZLwRMV+fNDpVmF2WYUdBHlq0eOWtEaUJSusrzjGnBt7iSRvfjFE3RXYUZJrqou/wIDWV0DwQ5KIfYe9WXg9Xqw==} + engines: {node: '>=14'} + peerDependencies: + '@opentelemetry/api': '>=1.0.0 <1.10.0' + + '@opentelemetry/core@1.30.1': + resolution: {integrity: sha512-OOCM2C/QIURhJMuKaekP3TRBxBKxG/TWWA0TL2J6nXUtDnuCtccy49LUJF8xPFXMX+0LMcxFpCo8M9cGY1W6rQ==} + engines: {node: '>=14'} + peerDependencies: + '@opentelemetry/api': '>=1.0.0 <1.10.0' + + '@opentelemetry/resources@1.28.0': + resolution: {integrity: sha512-cIyXSVJjGeTICENN40YSvLDAq4Y2502hGK3iN7tfdynQLKWb3XWZQEkPc+eSx47kiy11YeFAlYkEfXwR1w8kfw==} + engines: {node: '>=14'} + peerDependencies: + '@opentelemetry/api': '>=1.0.0 <1.10.0' + + '@opentelemetry/resources@1.30.1': + resolution: {integrity: sha512-5UxZqiAgLYGFjS4s9qm5mBVo433u+dSPUFWVWXmLAD4wB65oMCoXaJP1KJa9DIYYMeHu3z4BZcStG3LC593cWA==} + engines: {node: '>=14'} + peerDependencies: + '@opentelemetry/api': '>=1.0.0 <1.10.0' + + '@opentelemetry/sdk-logs@0.55.0': + resolution: {integrity: sha512-TSx+Yg/d48uWW6HtjS1AD5x6WPfLhDWLl/WxC7I2fMevaiBuKCuraxTB8MDXieCNnBI24bw9ytyXrDCswFfWgA==} + engines: {node: '>=14'} + peerDependencies: + '@opentelemetry/api': '>=1.4.0 <1.10.0' + + '@opentelemetry/sdk-trace-base@1.30.1': + resolution: {integrity: sha512-jVPgBbH1gCy2Lb7X0AVQ8XAfgg0pJ4nvl8/IiQA6nxOsPvS+0zMJaFSs2ltXe0J6C8dqjcnpyqINDJmU30+uOg==} + engines: {node: '>=14'} + peerDependencies: + '@opentelemetry/api': '>=1.0.0 <1.10.0' + + '@opentelemetry/semantic-conventions@1.27.0': + resolution: {integrity: sha512-sAay1RrB+ONOem0OZanAR1ZI/k7yDpnOQSQmTMuGImUQb2y8EbSaCJ94FQluM74xoU03vlb2d2U90hZluL6nQg==} + engines: {node: '>=14'} + + '@opentelemetry/semantic-conventions@1.28.0': + resolution: {integrity: sha512-lp4qAiMTD4sNWW4DbKLBkfiMZ4jbAboJIGOQr5DvciMRI494OapieI9qiODpOt0XBr1LjIDy1xAGAnVs5supTA==} + engines: {node: '>=14'} + '@oxc-project/types@0.130.0': resolution: {integrity: sha512-ibD2usx9JRu7f5pu2tMKMI4cpA4NgXJQoYRP4pQ7Pxmn1l6k/53qWtQWZayhYy3X4QZkt90Ot+mJEaeXouio6Q==} @@ -3164,6 +3237,56 @@ snapshots: transitivePeerDependencies: - supports-color + '@opentelemetry/api-logs@0.55.0': + dependencies: + '@opentelemetry/api': 1.9.1 + + '@opentelemetry/api@1.9.1': {} + + '@opentelemetry/context-async-hooks@1.30.1(@opentelemetry/api@1.9.1)': + dependencies: + '@opentelemetry/api': 1.9.1 + + '@opentelemetry/core@1.28.0(@opentelemetry/api@1.9.1)': + dependencies: + '@opentelemetry/api': 1.9.1 + '@opentelemetry/semantic-conventions': 1.27.0 + + '@opentelemetry/core@1.30.1(@opentelemetry/api@1.9.1)': + dependencies: + '@opentelemetry/api': 1.9.1 + '@opentelemetry/semantic-conventions': 1.28.0 + + '@opentelemetry/resources@1.28.0(@opentelemetry/api@1.9.1)': + dependencies: + '@opentelemetry/api': 1.9.1 + '@opentelemetry/core': 1.28.0(@opentelemetry/api@1.9.1) + '@opentelemetry/semantic-conventions': 1.27.0 + + '@opentelemetry/resources@1.30.1(@opentelemetry/api@1.9.1)': + dependencies: + '@opentelemetry/api': 1.9.1 + '@opentelemetry/core': 1.30.1(@opentelemetry/api@1.9.1) + '@opentelemetry/semantic-conventions': 1.28.0 + + '@opentelemetry/sdk-logs@0.55.0(@opentelemetry/api@1.9.1)': + dependencies: + '@opentelemetry/api': 1.9.1 + '@opentelemetry/api-logs': 0.55.0 + '@opentelemetry/core': 1.28.0(@opentelemetry/api@1.9.1) + '@opentelemetry/resources': 1.28.0(@opentelemetry/api@1.9.1) + + '@opentelemetry/sdk-trace-base@1.30.1(@opentelemetry/api@1.9.1)': + dependencies: + '@opentelemetry/api': 1.9.1 + '@opentelemetry/core': 1.30.1(@opentelemetry/api@1.9.1) + '@opentelemetry/resources': 1.30.1(@opentelemetry/api@1.9.1) + '@opentelemetry/semantic-conventions': 1.28.0 + + '@opentelemetry/semantic-conventions@1.27.0': {} + + '@opentelemetry/semantic-conventions@1.28.0': {} + '@oxc-project/types@0.130.0': {} '@oxfmt/darwin-arm64@0.28.0': diff --git a/src/Logger.otel.spec.ts b/src/Logger.otel.spec.ts new file mode 100644 index 00000000..709cea69 --- /dev/null +++ b/src/Logger.otel.spec.ts @@ -0,0 +1,122 @@ +/* eslint-disable @typescript-eslint/no-explicit-any */ +import { INVALID_SPAN_CONTEXT, context, trace } from "@opentelemetry/api"; +import { logs } from "@opentelemetry/api-logs"; +import { AsyncHooksContextManager } from "@opentelemetry/context-async-hooks"; +import { + InMemoryLogRecordExporter, + LoggerProvider, + SimpleLogRecordProcessor, +} from "@opentelemetry/sdk-logs"; +import { BasicTracerProvider } from "@opentelemetry/sdk-trace-base"; +import { afterAll, afterEach, beforeAll, describe, expect, test, vi } from "vitest"; +import Logger, { ContextKey, Level } from "./Logger"; + +// Real-SDK proof of the correlation fix (th-de3805): a log emitted inside an +// active span must carry that span's real W3C trace_id/span_id — both in the +// stdout JSON object AND in the OTLP log record bridged through +// @opentelemetry/api-logs. No stubbing of getActiveSpan / getLogger: a real +// tracer, a real active context, and a real LoggerProvider. +describe("Logger OTel correlation", () => { + const memoryExporter = new InMemoryLogRecordExporter(); + const loggerProvider = new LoggerProvider(); + const tracerProvider = new BasicTracerProvider(); + const contextManager = new AsyncHooksContextManager(); + + beforeAll(() => { + loggerProvider.addLogRecordProcessor(new SimpleLogRecordProcessor(memoryExporter)); + logs.setGlobalLoggerProvider(loggerProvider); + context.setGlobalContextManager(contextManager.enable()); + }); + + afterEach(() => { + memoryExporter.getFinishedLogRecords().length = 0; + vi.resetAllMocks(); + }); + + afterAll(() => { + contextManager.disable(); + }); + + test("stamps the active span trace_id + span_id and bridges an OTLP record", () => { + const logger = new Logger({ context: {}, level: Level.Info }); + const logSpy = vi.spyOn(logger as any, "logFunc") as any; + + const span = tracerProvider.getTracer("test").startSpan("work"); + const expected = span.spanContext(); + + context.with(trace.setSpan(context.active(), span), () => { + logger.info("hello from a span"); + }); + span.end(); + + // stdout JSON object carries the real span ids, not the uuid fallback. + const built = logSpy.mock.calls[0][0][0] as any; + expect(built[ContextKey.TraceId]).toBe(expected.traceId); + expect(built[ContextKey.SpanId]).toBe(expected.spanId); + expect(built[ContextKey.TraceId]).toMatch(/^[0-9a-f]{32}$/); + + // The bridged OTLP log record carries body + the same correlation. + const records = memoryExporter.getFinishedLogRecords(); + expect(records).toHaveLength(1); + expect(records[0]!.body).toBe("hello from a span"); + expect(records[0]!.spanContext?.traceId).toBe(expected.traceId); + expect(records[0]!.spanContext?.spanId).toBe(expected.spanId); + expect(records[0]!.severityText).toBe(Level.Info); + }); + + test("falls back to the uuid traceId and no spanId when no span is active", () => { + const logger = new Logger({ context: {}, level: Level.Info }); + const logSpy = vi.spyOn(logger as any, "logFunc") as any; + + logger.info("no span here"); + + const built = logSpy.mock.calls[0][0][0] as any; + // Prior behavior: traceId is the context correlation uuid, no spanId. + expect(built[ContextKey.TraceId]).toBe(logger.correlationId()); + expect(built[ContextKey.TraceId]).not.toMatch(/^[0-9a-f]{32}$/); + expect(built[ContextKey.SpanId]).toBeUndefined(); + + // A record is still bridged (uncorrelated) so obs sees the line. + const records = memoryExporter.getFinishedLogRecords(); + expect(records).toHaveLength(1); + expect(records[0]!.spanContext).toBeUndefined(); + }); + + // The regression the guard exists for. An app that imports the OTel API but + // registers no TracerProvider gets a NonRecordingSpan carrying + // INVALID_SPAN_CONTEXT (all-zero ids) — as does a context propagated from a + // sampled-out parent. Stamping those would not merely fail to correlate, it + // would OVERWRITE the correlation uuid with zeroes and silently break the + // existing correlationId join. Remove `isSpanContextValid` from + // `applyOtelCorrelation` and this test fails. + test("an invalid span context leaves the correlation uuid intact", () => { + const logger = new Logger(); + logger.setCorrelationId("11111111-2222-3333-4444-555555555555"); + + const built = context.with( + trace.setSpanContext(context.active(), INVALID_SPAN_CONTEXT), + () => (logger as any).buildLogObject(Level.Info, ["hello"])[0], + ); + + expect(built[ContextKey.TraceId]).toBe("11111111-2222-3333-4444-555555555555"); + expect(built[ContextKey.TraceId]).not.toBe("00000000000000000000000000000000"); + expect(built[ContextKey.SpanId]).toBeUndefined(); + }); + + // Negative control: proves the assertion above is not vacuous. The SAME call + // shape with a VALID context must stamp — otherwise the test would pass even + // if correlation were removed entirely. + test("...but a valid span context still stamps", () => { + const logger = new Logger(); + logger.setCorrelationId("11111111-2222-3333-4444-555555555555"); + const span = tracerProvider.getTracer("test").startSpan("valid"); + + const built = context.with(trace.setSpan(context.active(), span), () => + (logger as any).buildLogObject(Level.Info, ["hello"])[0], + ); + span.end(); + + expect(built[ContextKey.TraceId]).toBe(span.spanContext().traceId); + expect(built[ContextKey.SpanId]).toBe(span.spanContext().spanId); + }); +}); diff --git a/src/Logger.ts b/src/Logger.ts index ce9fb172..222d82f2 100644 --- a/src/Logger.ts +++ b/src/Logger.ts @@ -1,5 +1,7 @@ /* eslint-disable @typescript-eslint/no-unused-vars */ /* eslint-disable @typescript-eslint/no-explicit-any */ +import { isSpanContextValid, trace } from "@opentelemetry/api"; +import { logs, SeverityNumber } from "@opentelemetry/api-logs"; import dayjs from "dayjs"; import stableStringify from "json-stable-stringify"; import { merge } from "merge-anything"; @@ -105,6 +107,7 @@ export enum ContextKey { RequestId = "requestId", Duration = "duration", TraceId = "traceId", + SpanId = "spanId", Error = "error", Namespace = "namespace", Service = "service", @@ -820,11 +823,32 @@ export default class Logger { object[ContextKey.LogLevel] = level; object[ContextKey.Time] = dayjs().toISOString(); object[ContextKey.Name] = this.name; - return [ - this.redactSensitiveValues( - this.removeUndefinedValuesRecursively(this.applyContextConfig(object)), - ), - ]; + const processed = this.redactSensitiveValues( + this.removeUndefinedValuesRecursively(this.applyContextConfig(object)), + ); + // Stamp the ACTIVE OTel span's real W3C trace_id/span_id so logs correlate + // with traces. Falls back to the context traceId (a uuid) only when no + // span is active. Stamped after the config/redact transforms so it always + // survives regardless of the context-key config. th-de3805. + this.applyOtelCorrelation(processed); + return [processed]; + } + + private applyOtelCorrelation(object: any): void { + const spanContext = trace.getActiveSpan()?.spanContext(); + // `isSpanContextValid` is load-bearing, not defensive politeness. An app + // that imports the OTel API but registers no TracerProvider gets a + // NonRecordingSpan carrying INVALID_SPAN_CONTEXT — all-zero ids — and so + // does a context propagated from a sampled-out parent. Without this guard + // every line is stamped traceId '000…0', which is worse than no correlation + // at all: it destroys the uuid fallback that `setCorrelationId` maintains, + // so the existing correlationId join silently stops working with no error. + // Go (`sc.IsValid()`), Rust (`span_context.is_valid()`) and Python + // (`if not ctx.is_valid`) all guard here; TypeScript was the only one that + // did not. + if (!spanContext || !isSpanContextValid(spanContext)) return; + object[ContextKey.TraceId] = spanContext.traceId; + object[ContextKey.SpanId] = spanContext.spanId; } private prettyStringify(object: any): string { @@ -886,7 +910,54 @@ export default class Logger { }; private doLog(level: Level, args: any[]): void { - this.logFunc(this.buildLogObject(level, args)); + const built = this.buildLogObject(level, args); + this.logFunc(built); + this.emitToOtel(level, built); + } + + /** + * Bridge each built log record into the standard `@opentelemetry/api-logs` + * facade so it becomes an OTLP log record when an observability + * LoggerProvider is registered (e.g. @smooai/observability's logs signal). + * When none is registered `logs.getLogger(...)` returns the api-logs no-op + * logger, so this is a cheap no-op and stdout output is unchanged. The logs + * SDK stamps the active span's trace_id/span_id onto the record from context + * at emit time, so records stay correlated with traces. th-de3805. + */ + private emitToOtel(level: Level, built: any[]): void { + try { + const logger = logs.getLogger("@smooai/logger"); + for (const object of built) { + const decycled = JSON.decycle(object); + logger.emit({ + severityNumber: this.levelToSeverityNumber(level), + severityText: level, + body: object[ContextKey.Message] ?? object[ContextKey.Error] ?? level, + attributes: decycled, + }); + } + } catch { + // Never let telemetry bridging break application logging. + } + } + + private levelToSeverityNumber(level: Level): SeverityNumber { + switch (level) { + case Level.Trace: + return SeverityNumber.TRACE; + case Level.Debug: + return SeverityNumber.DEBUG; + case Level.Info: + return SeverityNumber.INFO; + case Level.Warn: + return SeverityNumber.WARN; + case Level.Error: + return SeverityNumber.ERROR; + case Level.Fatal: + return SeverityNumber.FATAL; + default: + return SeverityNumber.UNSPECIFIED; + } } /**