From 658ca2223e2a53d3cecfac489e856b9b00ca974c Mon Sep 17 00:00:00 2001 From: Santiago Palladino Date: Tue, 3 Dec 2024 19:29:25 -0300 Subject: [PATCH] Set up log correlation manually --- .../foundation/src/log/pino-logger.ts | 20 ++++++- yarn-project/telemetry-client/src/otel.ts | 53 +++++++++++-------- .../telemetry-client/src/otel_resource.ts | 1 + .../src/vendor/otel-pino-stream.ts | 10 ++-- 4 files changed, 56 insertions(+), 28 deletions(-) diff --git a/yarn-project/foundation/src/log/pino-logger.ts b/yarn-project/foundation/src/log/pino-logger.ts index ccdcfd9a5d48..d3d95e241228 100644 --- a/yarn-project/foundation/src/log/pino-logger.ts +++ b/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', diff --git a/yarn-project/telemetry-client/src/otel.ts b/yarn-project/telemetry-client/src/otel.ts index d1f084af050d..46b0b8d0ff8e 100644 --- a/yarn-project/telemetry-client/src/otel.ts +++ b/yarn-project/telemetry-client/src/otel.ts @@ -1,4 +1,4 @@ -import { type DebugLogger } from '@aztec/foundation/log'; +import { type DebugLogger, type LogData, addLogDataHandler } from '@aztec/foundation/log'; import { DiagConsoleLogger, @@ -6,26 +6,20 @@ import { 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 { 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(); diff --git a/yarn-project/telemetry-client/src/otel_resource.ts b/yarn-project/telemetry-client/src/otel_resource.ts index 9e724207f974..3810d3e73be6 100644 --- a/yarn-project/telemetry-client/src/otel_resource.ts +++ b/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 { + // TODO(palla/log): Do we really need *all* this info? const resource = detectResourcesSync({ detectors: [ osDetectorSync, diff --git a/yarn-project/telemetry-client/src/vendor/otel-pino-stream.ts b/yarn-project/telemetry-client/src/vendor/otel-pino-stream.ts index 69b585403636..5d2c053551a1 100644 --- a/yarn-project/telemetry-client/src/vendor/otel-pino-stream.ts +++ b/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;