feat: correlate logs with OTel traces + bridge to api-logs

.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`).

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",

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();
+  });
+});

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;
+    }
   }
 
   /**