Set up log correlation manually

yarn-project/foundation/src/log/pino-logger.ts

@@ -15,7 +15,9 @@ export function createDebugLogger(module: string): DebugLogger {
     { level: getLogLevelFromFilters(logFilters, module) },
   );
 
-  const logFn = (level: LogLevel, msg: string, data?: LogData) => pinoLogger[level](data ?? {}, msg);
+  // We check manually for isLevelEnabled to avoid calling processLogData unnecessarily.
+  const logFn = (level: LogLevel, msg: string, data?: LogData) =>
+    pinoLogger.isLevelEnabled(level) && pinoLogger[level](processLogData(data ?? {}), msg);
 
   return {
     silent: () => {},
@@ -38,6 +40,20 @@ export function createDebugLogger(module: string): DebugLogger {
   };
 }
 
+// Allow global hooks for processing log data.
+// Used for injecting OTEL trace_id in telemetry client.
+type LogDataHandler = (data: LogData) => LogData;
+const logDataHandlers: LogDataHandler[] = [];
+
+export function addLogDataHandler(handler: LogDataHandler): void {
+  logDataHandlers.push(handler);
+}
+
+function processLogData(data: LogData): LogData {
+  return logDataHandlers.reduce((accum, handler) => handler(accum), data);
+}
+
+// Load log levels from environment variables.
 const defaultLogLevel = process.env.NODE_ENV === 'test' ? 'silent' : 'info';
 const [logLevel, logFilters] = parseEnv(process.env.LOG_LEVEL, defaultLogLevel);
 
@@ -46,7 +62,7 @@ const prettyTransport: LoggerOptions['transport'] = {
   target: 'pino-pretty',
   options: {
     sync: true,
-    ignore: 'module,pid,hostname',
+    ignore: 'module,pid,hostname,trace_id,span_id,trace_flags',
     messageFormat: `${bold('{module}')} ${reset('{msg}')}`,
     customLevels: 'fatal:60,error:50,warn:40,info:30,verbose:25,debug:20,trace:10',
     customColors: 'fatal:bgRed,error:red,warn:yellow,info:green,verbose:magenta,debug:blue,trace:gray',

yarn-project/telemetry-client/src/otel.ts

@@ -1,31 +1,25 @@
-import { type DebugLogger } from '@aztec/foundation/log';
+import { type DebugLogger, type LogData, addLogDataHandler } from '@aztec/foundation/log';
 
 import {
   DiagConsoleLogger,
   DiagLogLevel,
   type Meter,
   type Tracer,
   type TracerProvider,
+  context,
   diag,
+  isSpanContextValid,
+  trace,
 } from '@opentelemetry/api';
 import { OTLPMetricExporter } from '@opentelemetry/exporter-metrics-otlp-http';
 import { OTLPTraceExporter } from '@opentelemetry/exporter-trace-otlp-http';
 import { HostMetrics } from '@opentelemetry/host-metrics';
-import { awsEc2Detector, awsEcsDetector } from '@opentelemetry/resource-detector-aws';
-import {
-  type IResource,
-  detectResourcesSync,
-  envDetectorSync,
-  osDetectorSync,
-  processDetectorSync,
-  serviceInstanceIdDetectorSync,
-} from '@opentelemetry/resources';
+import { type IResource } from '@opentelemetry/resources';
 import { type LoggerProvider } from '@opentelemetry/sdk-logs';
 import { MeterProvider, PeriodicExportingMetricReader } from '@opentelemetry/sdk-metrics';
 import { BatchSpanProcessor, NodeTracerProvider } from '@opentelemetry/sdk-trace-node';
-import { SEMRESATTRS_SERVICE_NAME, SEMRESATTRS_SERVICE_VERSION } from '@opentelemetry/semantic-conventions';
+import { ATTR_SERVICE_NAME, ATTR_SERVICE_VERSION } from '@opentelemetry/semantic-conventions';
 
-import { aztecDetector } from './aztec_resource_detector.js';
 import { type TelemetryClientConfig } from './config.js';
 import { registerOtelLoggerProvider } from './otel_logger_provider.js';
 import { getOtelResource } from './otel_resource.js';
@@ -44,19 +38,33 @@ export class OpenTelemetryClient implements TelemetryClient {
   ) {}
 
   getMeter(name: string): Meter {
-    return this.meterProvider.getMeter(name, this.resource.attributes[SEMRESATTRS_SERVICE_VERSION] as string);
+    return this.meterProvider.getMeter(name, this.resource.attributes[ATTR_SERVICE_VERSION] as string);
   }
 
   getTracer(name: string): Tracer {
-    return this.traceProvider.getTracer(name, this.resource.attributes[SEMRESATTRS_SERVICE_VERSION] as string);
+    return this.traceProvider.getTracer(name, this.resource.attributes[ATTR_SERVICE_VERSION] as string);
   }
 
   public start() {
     this.log.info('Starting OpenTelemetry client');
     diag.setLogger(new DiagConsoleLogger(), DiagLogLevel.INFO);
 
+    // Add a callback to the logger to set context data from current trace
+    // Adapted from open-telemetry/opentelemetry-js-contrib PinoInstrumentation._getMixinFunction
+    addLogDataHandler((data: LogData) => {
+      const spanContext = trace.getSpan(context.active())?.spanContext();
+      return spanContext && isSpanContextValid(spanContext)
+        ? {
+            ...data,
+            ['trace_id']: spanContext.traceId,
+            ['span_id']: spanContext.spanId,
+            ['trace_flags']: `0${spanContext.traceFlags.toString(16)}`,
+          }
+        : data;
+    });
+
     this.hostMetrics = new HostMetrics({
-      name: this.resource.attributes[SEMRESATTRS_SERVICE_NAME] as string,
+      name: this.resource.attributes[ATTR_SERVICE_NAME] as string,
       meterProvider: this.meterProvider,
     });
 
@@ -91,14 +99,13 @@ export class OpenTelemetryClient implements TelemetryClient {
   public static async createAndStart(config: TelemetryClientConfig, log: DebugLogger): Promise<OpenTelemetryClient> {
     const resource = await getOtelResource();
 
-    const tracerProvider = new NodeTracerProvider({ resource });
-
-    // optionally push traces to an OTEL collector instance
-    if (config.tracesCollectorUrl) {
-      tracerProvider.addSpanProcessor(
-        new BatchSpanProcessor(new OTLPTraceExporter({ url: config.tracesCollectorUrl.href })),
-      );
-    }
+    // TODO(palla/log): Should we show traces as logs in stdout when otel collection is disabled?
+    const tracerProvider = new NodeTracerProvider({
+      resource,
+      spanProcessors: config.tracesCollectorUrl
+        ? [new BatchSpanProcessor(new OTLPTraceExporter({ url: config.tracesCollectorUrl.href }))]
+        : [],
+    });
 
     tracerProvider.register();
 

yarn-project/telemetry-client/src/otel_resource.ts

@@ -11,6 +11,7 @@ import {
 import { aztecDetector } from './aztec_resource_detector.js';
 
 export async function getOtelResource(): Promise<IResource> {
+  // TODO(palla/log): Do we really need *all* this info?
   const resource = detectResourcesSync({
     detectors: [
       osDetectorSync,

yarn-project/telemetry-client/src/vendor/otel-pino-stream.ts

@@ -215,9 +215,13 @@ export class OTelPinoStream extends Writable {
 
         // The `trace_id` et al fields that may have been added by the
         // "log correlation" feature are stripped, because they are redundant.
-        trace_id, // eslint-disable-line @typescript-eslint/no-unused-vars
-        span_id, // eslint-disable-line @typescript-eslint/no-unused-vars
-        trace_flags, // eslint-disable-line @typescript-eslint/no-unused-vars
+        // trace_id, // eslint-disable-line @typescript-eslint/no-unused-vars
+        // span_id, // eslint-disable-line @typescript-eslint/no-unused-vars
+        // trace_flags, // eslint-disable-line @typescript-eslint/no-unused-vars
+
+        // [aztec] They are not redundant, we depend on them for correlation.
+        // The instrumentation package seems to be adding these fields via a custom hook.
+        // We push them from the logger module in foundation, so we don't want to clear them here.
 
         ...attributes
       } = recObj;