From fbcc8efe139c9bbd20f347a244bdf960d03af73f Mon Sep 17 00:00:00 2001 From: Santiago Palladino Date: Thu, 16 Jan 2025 17:51:37 -0300 Subject: [PATCH] chore: Log correlation in traces in google cloud (#11276) Adds a google cloud logger config so that logs trace and span ids use the required naming for correlation. Replaces #11019 Fixes #10937 --- .../src/fixtures/get_acvm_config.ts | 3 +- yarn-project/foundation/src/config/index.ts | 9 ++- .../src/log/gcloud-logger-config.ts | 71 +++++++++++++++++++ .../foundation/src/log/pino-logger.ts | 55 ++++---------- yarn-project/pxe/src/config/index.ts | 3 +- yarn-project/telemetry-client/src/config.ts | 5 +- yarn-project/telemetry-client/src/otel.ts | 12 ++-- 7 files changed, 103 insertions(+), 55 deletions(-) create mode 100644 yarn-project/foundation/src/log/gcloud-logger-config.ts diff --git a/yarn-project/end-to-end/src/fixtures/get_acvm_config.ts b/yarn-project/end-to-end/src/fixtures/get_acvm_config.ts index ed34c79864a..b1169b9303a 100644 --- a/yarn-project/end-to-end/src/fixtures/get_acvm_config.ts +++ b/yarn-project/end-to-end/src/fixtures/get_acvm_config.ts @@ -1,4 +1,5 @@ import { type Logger } from '@aztec/aztec.js'; +import { parseBooleanEnv } from '@aztec/foundation/config'; import { randomBytes } from '@aztec/foundation/crypto'; import { promises as fs } from 'fs'; @@ -23,7 +24,7 @@ export async function getACVMConfig(logger: Logger): Promise< | undefined > { try { - if (['1', 'true'].includes(ACVM_FORCE_WASM)) { + if (parseBooleanEnv(ACVM_FORCE_WASM)) { return undefined; } const acvmBinaryPath = ACVM_BINARY_PATH ? ACVM_BINARY_PATH : `../../noir/${NOIR_RELEASE_DIR}/acvm`; diff --git a/yarn-project/foundation/src/config/index.ts b/yarn-project/foundation/src/config/index.ts index 4485aae5059..b49fbb776aa 100644 --- a/yarn-project/foundation/src/config/index.ts +++ b/yarn-project/foundation/src/config/index.ts @@ -1,6 +1,6 @@ import { type EnvVar } from './env_var.js'; -export { EnvVar } from './env_var.js'; +export { type EnvVar } from './env_var.js'; export interface ConfigMapping { env?: EnvVar; @@ -102,7 +102,7 @@ export function optionalNumberConfigHelper(): Pick { export function booleanConfigHelper( defaultVal = false, ): Required & { parseVal: (val: string) => boolean }> { - const parse = (val: string | boolean) => (typeof val === 'boolean' ? val : ['1', 'true', 'TRUE'].includes(val)); + const parse = (val: string | boolean) => (typeof val === 'boolean' ? val : parseBooleanEnv(val)); return { parseEnv: parse, parseVal: parse, @@ -111,6 +111,11 @@ export function booleanConfigHelper( }; } +/** Parses an env var as boolean. Returns true only if value is 1, true, or TRUE. */ +export function parseBooleanEnv(val: string | undefined): boolean { + return val !== undefined && ['1', 'true', 'TRUE'].includes(val); +} + /** * Safely parses a number from a string. * If the value is not a number or is not a safe integer, the default value is returned. diff --git a/yarn-project/foundation/src/log/gcloud-logger-config.ts b/yarn-project/foundation/src/log/gcloud-logger-config.ts new file mode 100644 index 00000000000..65aef7c5b55 --- /dev/null +++ b/yarn-project/foundation/src/log/gcloud-logger-config.ts @@ -0,0 +1,71 @@ +import { type pino } from 'pino'; + +/* eslint-disable camelcase */ + +const GOOGLE_CLOUD_TRACE_ID = 'logging.googleapis.com/trace'; +const GOOGLE_CLOUD_SPAN_ID = 'logging.googleapis.com/spanId'; +const GOOGLE_CLOUD_TRACE_SAMPLED = 'logging.googleapis.com/trace_sampled'; + +/** + * Pino configuration for google cloud observability. Tweaks message and timestamp, + * adds trace context attributes, and injects severity level. + * Adapted from https://cloud.google.com/trace/docs/setup/nodejs-ot#config-structured-logging. + */ +export const GoogleCloudLoggerConfig = { + messageKey: 'message', + // Same as pino.stdTimeFunctions.isoTime but uses "timestamp" key instead of "time" + timestamp(): string { + return `,"timestamp":"${new Date(Date.now()).toISOString()}"`; + }, + formatters: { + log(object: Record): Record { + // Add trace context attributes following Cloud Logging structured log format described + // in https://cloud.google.com/logging/docs/structured-logging#special-payload-fields + const { trace_id, span_id, trace_flags, ...rest } = object; + + if (trace_id && span_id) { + return { + [GOOGLE_CLOUD_TRACE_ID]: trace_id, + [GOOGLE_CLOUD_SPAN_ID]: span_id, + [GOOGLE_CLOUD_TRACE_SAMPLED]: trace_flags ? trace_flags === '01' : undefined, + trace_flags, // Keep the original trace_flags for otel-pino-stream + ...rest, + }; + } + return object; + }, + level(label: string, level: number): object { + // Inspired by https://github.com/pinojs/pino/issues/726#issuecomment-605814879 + // Severity labels https://cloud.google.com/logging/docs/reference/v2/rest/v2/LogEntry#LogSeverity + let severity: string; + + switch (label as pino.Level | keyof typeof customLevels) { + case 'trace': + case 'debug': + severity = 'DEBUG'; + break; + case 'verbose': + case 'info': + severity = 'INFO'; + break; + case 'warn': + severity = 'WARNING'; + break; + case 'error': + severity = 'ERROR'; + break; + case 'fatal': + severity = 'CRITICAL'; + break; + default: + severity = 'DEFAULT'; + break; + } + + return { severity, level }; + }, + }, +} satisfies pino.LoggerOptions; + +// Define custom logging levels for pino. Duplicate from pino-logger.ts. +const customLevels = { verbose: 25 }; diff --git a/yarn-project/foundation/src/log/pino-logger.ts b/yarn-project/foundation/src/log/pino-logger.ts index 40291006c9c..e64ebe5e345 100644 --- a/yarn-project/foundation/src/log/pino-logger.ts +++ b/yarn-project/foundation/src/log/pino-logger.ts @@ -5,6 +5,8 @@ import { type Writable } from 'stream'; import { inspect } from 'util'; import { compactArray } from '../collection/array.js'; +import { type EnvVar, parseBooleanEnv } from '../config/index.js'; +import { GoogleCloudLoggerConfig } from './gcloud-logger-config.js'; import { getLogLevelFromFilters, parseEnv } from './log-filters.js'; import { type LogLevel } from './log-levels.js'; import { type LogData, type LogFn } from './log_fn.js'; @@ -86,46 +88,14 @@ const [logLevel, logFilters] = parseEnv(process.env.LOG_LEVEL, defaultLogLevel); // Define custom logging levels for pino. const customLevels = { verbose: 25 }; -// inspired by https://github.com/pinojs/pino/issues/726#issuecomment-605814879 -const levelToSeverityFormatter = (label: string, level: number): object => { - // Severity labels https://cloud.google.com/logging/docs/reference/v2/rest/v2/LogEntry#LogSeverity - let severity: string; - - switch (label as pino.Level | keyof typeof customLevels) { - case 'trace': - case 'debug': - severity = 'DEBUG'; - break; - case 'verbose': - case 'info': - severity = 'INFO'; - break; - case 'warn': - severity = 'WARNING'; - break; - case 'error': - severity = 'ERROR'; - break; - case 'fatal': - severity = 'CRITICAL'; - break; - default: - severity = 'DEFAULT'; - break; - } - - return { severity, level }; -}; - -const useGcloudObservability = process.env.USE_GCLOUD_OBSERVABILITY === 'true'; +// Global pino options, tweaked for google cloud if running there. +const useGcloudObservability = parseBooleanEnv(process.env['USE_GCLOUD_OBSERVABILITY' satisfies EnvVar]); const pinoOpts: pino.LoggerOptions = { customLevels, - messageKey: useGcloudObservability ? 'message' : 'msg', + messageKey: 'msg', useOnlyCustomLevels: false, level: logLevel, - formatters: { - level: levelToSeverityFormatter, - }, + ...(useGcloudObservability ? GoogleCloudLoggerConfig : {}), }; export const levels = { @@ -145,7 +115,7 @@ export const pinoPrettyOpts = { 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', minimumLevel: 'trace' as const, - singleLine: !['1', 'true'].includes(process.env.LOG_MULTILINE ?? ''), + singleLine: !parseBooleanEnv(process.env['LOG_MULTILINE' satisfies EnvVar]), }; const prettyTransport: pino.TransportTargetOptions = { @@ -167,7 +137,8 @@ const stdioTransport: pino.TransportTargetOptions = { // would mean that all child loggers created before the telemetry-client is initialized would not have // this transport configured. Note that the target is defined as the export in the telemetry-client, // since pino will load this transport separately on a worker thread, to minimize disruption to the main loop. -const otlpEndpoint = process.env.OTEL_EXPORTER_OTLP_LOGS_ENDPOINT; +const otlpEndpoint = process.env['OTEL_EXPORTER_OTLP_LOGS_ENDPOINT' satisfies EnvVar]; +const otlpEnabled = !!otlpEndpoint && !useGcloudObservability; const otelOpts = { levels }; const otelTransport: pino.TransportTargetOptions = { target: '@aztec/telemetry-client/otel-pino-stream', @@ -185,10 +156,10 @@ function makeLogger() { return pino(pinoOpts, pino.destination(2)); } else { // Regular nodejs with transports on worker thread, using pino-pretty for console logging if LOG_JSON - // is not set, and an optional OTLP transport if the OTLP endpoint is provided. + // is not set, and an optional OTLP transport if the OTLP endpoint is set. const targets: pino.TransportSingleOptions[] = compactArray([ - ['1', 'true', 'TRUE'].includes(process.env.LOG_JSON ?? '') ? stdioTransport : prettyTransport, - otlpEndpoint ? otelTransport : undefined, + parseBooleanEnv(process.env.LOG_JSON) ? stdioTransport : prettyTransport, + otlpEnabled ? otelTransport : undefined, ]); return pino(pinoOpts, pino.transport({ targets, levels: levels.values })); } @@ -203,7 +174,7 @@ logger.verbose( ...logFilters.reduce((accum, [module, level]) => ({ ...accum, [`log.${module}`]: level }), {}), }, isNode - ? `Logger initialized with level ${logLevel}` + (otlpEndpoint ? ` with OTLP exporter to ${otlpEndpoint}` : '') + ? `Logger initialized with level ${logLevel}` + (otlpEnabled ? ` with OTLP exporter to ${otlpEndpoint}` : '') : `Browser console logger initialized with level ${logLevel}`, ); diff --git a/yarn-project/pxe/src/config/index.ts b/yarn-project/pxe/src/config/index.ts index 7eeb270453f..dc971a6f30a 100644 --- a/yarn-project/pxe/src/config/index.ts +++ b/yarn-project/pxe/src/config/index.ts @@ -4,6 +4,7 @@ import { booleanConfigHelper, getConfigFromMappings, numberConfigHelper, + parseBooleanEnv, } from '@aztec/foundation/config'; import { type DataStoreConfig, dataConfigMappings } from '@aztec/kv-store/config'; import { type Network } from '@aztec/types/network'; @@ -99,7 +100,7 @@ export const allPxeConfigMappings: ConfigMappingsType ['1', 'true', 'TRUE'].includes(val) || !!process.env.NETWORK, + parseEnv: (val: string) => parseBooleanEnv(val) || !!process.env.NETWORK, description: 'Enable real proofs', isBoolean: true, }, diff --git a/yarn-project/telemetry-client/src/config.ts b/yarn-project/telemetry-client/src/config.ts index e4613d27494..523c47cdff1 100644 --- a/yarn-project/telemetry-client/src/config.ts +++ b/yarn-project/telemetry-client/src/config.ts @@ -1,4 +1,4 @@ -import { type ConfigMappingsType, getConfigFromMappings } from '@aztec/foundation/config'; +import { type ConfigMappingsType, booleanConfigHelper, getConfigFromMappings } from '@aztec/foundation/config'; export interface TelemetryClientConfig { useGcloudObservability: boolean; @@ -18,8 +18,7 @@ export const telemetryClientConfigMappings: ConfigMappingsType val === 'true', + ...booleanConfigHelper(false), }, metricsCollectorUrl: { env: 'OTEL_EXPORTER_OTLP_METRICS_ENDPOINT', diff --git a/yarn-project/telemetry-client/src/otel.ts b/yarn-project/telemetry-client/src/otel.ts index b0a509239cd..66a54390e56 100644 --- a/yarn-project/telemetry-client/src/otel.ts +++ b/yarn-project/telemetry-client/src/otel.ts @@ -1,7 +1,7 @@ import { type LogData, type Logger, addLogDataHandler } from '@aztec/foundation/log'; -import { MetricExporter } from '@google-cloud/opentelemetry-cloud-monitoring-exporter'; -import { TraceExporter } from '@google-cloud/opentelemetry-cloud-trace-exporter'; +import { MetricExporter as GoogleCloudMetricExporter } from '@google-cloud/opentelemetry-cloud-monitoring-exporter'; +import { TraceExporter as GoogleCloudTraceExporter } from '@google-cloud/opentelemetry-cloud-trace-exporter'; import { DiagConsoleLogger, DiagLogLevel, @@ -237,17 +237,17 @@ export class OpenTelemetryClient implements TelemetryClient { }); } - public static getGcloudClientFactory(config: TelemetryClientConfig): OpenTelemetryClientFactory { + private static getGcloudClientFactory(config: TelemetryClientConfig): OpenTelemetryClientFactory { return (resource: IResource, log: Logger) => { const tracerProvider = new NodeTracerProvider({ resource, - spanProcessors: [new BatchSpanProcessor(new TraceExporter({ resourceFilter: /.*/ }))], + spanProcessors: [new BatchSpanProcessor(new GoogleCloudTraceExporter({ resourceFilter: /.*/ }))], }); tracerProvider.register(); const meterProvider = OpenTelemetryClient.createMeterProvider(resource, { - exporter: new MetricExporter(), + exporter: new GoogleCloudMetricExporter(), exportTimeoutMillis: config.otelExportTimeoutMs, exportIntervalMillis: config.otelCollectIntervalMs, }); @@ -256,7 +256,7 @@ export class OpenTelemetryClient implements TelemetryClient { }; } - public static getCustomClientFactory(config: TelemetryClientConfig): OpenTelemetryClientFactory { + private static getCustomClientFactory(config: TelemetryClientConfig): OpenTelemetryClientFactory { return (resource: IResource, log: Logger) => { const tracerProvider = new NodeTracerProvider({ resource,