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..650e5e84 100644 --- a/package.json +++ b/package.json @@ -137,6 +137,8 @@ }, "dependencies": { "@aws-sdk/client-sqs": "^3.504.0", + "@opentelemetry/api": "^1.9.0", + "@opentelemetry/api-logs": "^0.55.0", "browser-dtector": "^4.1.0", "dayjs": "^1.11.13", "esbuild-plugin-alias": "^0.2.1", @@ -153,6 +155,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", diff --git a/pnpm-lock.yaml b/pnpm-lock.yaml index bc547b6f..ce507ff6 100644 --- a/pnpm-lock.yaml +++ b/pnpm-lock.yaml @@ -12,6 +12,12 @@ importers: '@aws-sdk/client-sqs': specifier: ^3.504.0 version: 3.758.0 + '@opentelemetry/api': + specifier: ^1.9.0 + version: 1.9.1 + '@opentelemetry/api-logs': + specifier: ^0.55.0 + version: 0.55.0 browser-dtector: specifier: ^4.1.0 version: 4.1.0 @@ -55,6 +61,15 @@ importers: '@oclif/core': specifier: ^4.2.9 version: 4.2.9 + '@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..403be509 --- /dev/null +++ b/src/Logger.otel.spec.ts @@ -0,0 +1,84 @@ +/* eslint-disable @typescript-eslint/no-explicit-any */ +import { 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(); + }); +}); diff --git a/src/Logger.ts b/src/Logger.ts index ce9fb172..e9f5775a 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 { 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,22 @@ 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(); + if (!spanContext) return; + object[ContextKey.TraceId] = spanContext.traceId; + object[ContextKey.SpanId] = spanContext.spanId; } private prettyStringify(object: any): string { @@ -886,7 +900,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; + } } /**