diff --git a/yarn-project/end-to-end/package.json b/yarn-project/end-to-end/package.json index 047609c4015..c3064e75b30 100644 --- a/yarn-project/end-to-end/package.json +++ b/yarn-project/end-to-end/package.json @@ -144,9 +144,9 @@ }, "reporters": [ [ - "default", + "summary", { - "summaryThreshold": 9999 + "summaryThreshold": 0 } ] ], diff --git a/yarn-project/end-to-end/package.local.json b/yarn-project/end-to-end/package.local.json index cbb0987a9dc..e30a30e4508 100644 --- a/yarn-project/end-to-end/package.local.json +++ b/yarn-project/end-to-end/package.local.json @@ -4,5 +4,15 @@ "formatting": "run -T prettier --check ./src \"!src/web/main.js\" && run -T eslint ./src", "test": "LOG_LEVEL=${LOG_LEVEL:-verbose} NODE_NO_WARNINGS=1 node --experimental-vm-modules ../node_modules/.bin/jest --testTimeout=300000 --forceExit", "test:unit": "NODE_NO_WARNINGS=1 node --experimental-vm-modules ../node_modules/.bin/jest src/fixtures" + }, + "jest": { + "reporters": [ + [ + "summary", + { + "summaryThreshold": 0 + } + ] + ] } } \ No newline at end of file diff --git a/yarn-project/end-to-end/src/e2e_p2p/p2p_network.ts b/yarn-project/end-to-end/src/e2e_p2p/p2p_network.ts index 0fb208a4932..f0012f4fbc5 100644 --- a/yarn-project/end-to-end/src/e2e_p2p/p2p_network.ts +++ b/yarn-project/end-to-end/src/e2e_p2p/p2p_network.ts @@ -90,7 +90,7 @@ export class P2PNetworkTest { }) { const port = basePort || (await getPort()); - const telemetry = await getEndToEndTestTelemetryClient(metricsPort, /*service name*/ `bootstrapnode`); + const telemetry = await getEndToEndTestTelemetryClient(metricsPort); const bootstrapNode = await createBootstrapNodeFromPrivateKey(BOOTSTRAP_NODE_PRIVATE_KEY, port, telemetry); const bootstrapNodeEnr = bootstrapNode.getENR().encodeTxt(); diff --git a/yarn-project/end-to-end/src/fixtures/setup_p2p_test.ts b/yarn-project/end-to-end/src/fixtures/setup_p2p_test.ts index 53c7a3dde62..7f70fd2c735 100644 --- a/yarn-project/end-to-end/src/fixtures/setup_p2p_test.ts +++ b/yarn-project/end-to-end/src/fixtures/setup_p2p_test.ts @@ -63,7 +63,7 @@ export async function createNode( ) { const validatorConfig = await createValidatorConfig(config, bootstrapNode, tcpPort, accountIndex, dataDirectory); - const telemetryClient = await getEndToEndTestTelemetryClient(metricsPort, /*serviceName*/ `node:${tcpPort}`); + const telemetryClient = await getEndToEndTestTelemetryClient(metricsPort); return await AztecNodeService.createAndSync(validatorConfig, { telemetry: telemetryClient, diff --git a/yarn-project/end-to-end/src/fixtures/snapshot_manager.ts b/yarn-project/end-to-end/src/fixtures/snapshot_manager.ts index 8aa2a934b33..01c1eb6c12b 100644 --- a/yarn-project/end-to-end/src/fixtures/snapshot_manager.ts +++ b/yarn-project/end-to-end/src/fixtures/snapshot_manager.ts @@ -345,7 +345,7 @@ async function setupFromFresh( aztecNodeConfig.bbWorkingDirectory = bbConfig.bbWorkingDirectory; } - const telemetry = await getEndToEndTestTelemetryClient(opts.metricsPort, /*serviceName*/ statePath); + const telemetry = await getEndToEndTestTelemetryClient(opts.metricsPort); logger.verbose('Creating and synching an aztec node...'); const aztecNode = await AztecNodeService.createAndSync(aztecNodeConfig, { telemetry }); diff --git a/yarn-project/end-to-end/src/fixtures/with_telemetry_utils.ts b/yarn-project/end-to-end/src/fixtures/with_telemetry_utils.ts index 4791fda9bca..aed13a14fde 100644 --- a/yarn-project/end-to-end/src/fixtures/with_telemetry_utils.ts +++ b/yarn-project/end-to-end/src/fixtures/with_telemetry_utils.ts @@ -1,15 +1,28 @@ +import { levels, registerLoggingStream } from '@aztec/foundation/log'; import { type TelemetryClient } from '@aztec/telemetry-client'; import { NoopTelemetryClient } from '@aztec/telemetry-client/noop'; +import { OTelPinoStream } from '@aztec/telemetry-client/otel-pino-stream'; import { type TelemetryClientConfig, createAndStartTelemetryClient, getConfigEnvVars as getTelemetryConfig, } from '@aztec/telemetry-client/start'; -export function getEndToEndTestTelemetryClient(metricsPort?: number, serviceName?: string): Promise { - return !metricsPort - ? Promise.resolve(new NoopTelemetryClient()) - : createAndStartTelemetryClient(getEndToEndTestTelemetryConfig(metricsPort, serviceName)); +let telemetryClient: Promise | undefined; +export function getEndToEndTestTelemetryClient(metricsPort?: number): Promise { + if (!metricsPort) { + return Promise.resolve(new NoopTelemetryClient()); + } + if (!telemetryClient) { + telemetryClient = createEndToEndTestOtelClient(metricsPort); + } + return telemetryClient; +} + +function createEndToEndTestOtelClient(metricsPort: number): Promise { + const otelStream = new OTelPinoStream({ levels }); + registerLoggingStream(otelStream); + return createAndStartTelemetryClient(getEndToEndTestTelemetryConfig(metricsPort)); } /** @@ -17,7 +30,7 @@ export function getEndToEndTestTelemetryClient(metricsPort?: number, serviceName * * Read from env vars, override if metricsPort is set */ -export function getEndToEndTestTelemetryConfig(metricsPort?: number, serviceName?: string) { +function getEndToEndTestTelemetryConfig(metricsPort?: number) { const telemetryConfig: TelemetryClientConfig = getTelemetryConfig(); if (metricsPort) { telemetryConfig.metricsCollectorUrl = new URL(`http://127.0.0.1:${metricsPort}/v1/metrics`); @@ -27,8 +40,5 @@ export function getEndToEndTestTelemetryConfig(metricsPort?: number, serviceName telemetryConfig.otelCollectIntervalMs = 5000; telemetryConfig.otelExportTimeoutMs = 2500; } - if (serviceName) { - telemetryConfig.serviceName = serviceName; - } return telemetryConfig; } diff --git a/yarn-project/foundation/src/log/pino-logger.ts b/yarn-project/foundation/src/log/pino-logger.ts index a4ed349522b..1eafd070c5a 100644 --- a/yarn-project/foundation/src/log/pino-logger.ts +++ b/yarn-project/foundation/src/log/pino-logger.ts @@ -1,6 +1,8 @@ import { createColors } from 'colorette'; import isNode from 'detect-node'; -import { type LoggerOptions, pino } from 'pino'; +import { pino, symbols } from 'pino'; +import pretty from 'pino-pretty'; +import { type Writable } from 'stream'; import { inspect } from 'util'; import { compactArray } from '../collection/array.js'; @@ -67,24 +69,26 @@ function isLevelEnabled(logger: pino.Logger<'verbose', boolean>, level: LogLevel const defaultLogLevel = process.env.NODE_ENV === 'test' ? 'silent' : 'info'; const [logLevel, logFilters] = parseEnv(process.env.LOG_LEVEL, defaultLogLevel); -// Transport options for pretty logging to stdout via pino-pretty. +// Transport options for pretty logging to stderr via pino-pretty. const useColor = true; const { bold, reset } = createColors({ useColor }); -const prettyTransport: LoggerOptions['transport'] = { +const pinoPrettyOpts = { + destination: 2, + sync: true, + colorize: useColor, + 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', + minimumLevel: 'trace' as const, +}; +const prettyTransport: pino.TransportSingleOptions = { target: 'pino-pretty', - options: { - destination: 2, - sync: true, - colorize: useColor, - 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', - }, + options: pinoPrettyOpts, }; // Transport for vanilla stdio logging as JSON. -const stdioTransport: LoggerOptions['transport'] = { +const stdioTransport: pino.TransportSingleOptions = { target: 'pino/file', options: { destination: 2 }, }; @@ -92,7 +96,8 @@ const stdioTransport: LoggerOptions['transport'] = { // Define custom logging levels for pino. const customLevels = { verbose: 25 }; const pinoOpts = { customLevels, useOnlyCustomLevels: false, level: logLevel }; -const levels = { + +export const levels = { labels: { ...pino.levels.labels, ...Object.fromEntries(Object.entries(customLevels).map(e => e.reverse())) }, values: { ...pino.levels.values, ...customLevels }, }; @@ -103,27 +108,32 @@ const levels = { // 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 otelTransport: LoggerOptions['transport'] = { +const otlpEndpoint = process.env.OTEL_EXPORTER_OTLP_LOGS_ENDPOINT; +const otelOpts = { levels }; +const otelTransport: pino.TransportSingleOptions = { target: '@aztec/telemetry-client/otel-pino-stream', - options: { levels, messageKey: 'msg' }, + options: otelOpts, }; -// In nodejs, create a new pino instance with an stdout transport (either vanilla or json), and optionally -// an OTLP transport if the OTLP endpoint is provided. Note that transports are initialized in a worker thread. -// On the browser, we just log to the console. -const otlpEndpoint = process.env.OTEL_EXPORTER_OTLP_LOGS_ENDPOINT; -const logger = isNode - ? pino( - pinoOpts, - pino.transport({ - targets: compactArray([ - ['1', 'true', 'TRUE'].includes(process.env.LOG_JSON ?? '') ? stdioTransport : prettyTransport, - process.env.OTEL_EXPORTER_OTLP_LOGS_ENDPOINT ? otelTransport : undefined, - ]), - }), - ) - : pino({ ...pinoOpts, browser: { asObject: false } }); +function makeLogger() { + if (!isNode) { + // We are on the browser + return pino({ ...pinoOpts, browser: { asObject: false } }); + } else if (process.env.JEST_WORKER_ID) { + // We are on jest, so we need sync logging. We stream to stderr with pretty. + return pino(pinoOpts, pretty(pinoPrettyOpts)); + } 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. + const targets: pino.TransportSingleOptions[] = compactArray([ + ['1', 'true', 'TRUE'].includes(process.env.LOG_JSON ?? '') ? stdioTransport : prettyTransport, + otlpEndpoint ? otelTransport : undefined, + ]); + return pino(pinoOpts, pino.transport({ targets })); + } +} + +const logger = makeLogger(); // Log the logger configuration. logger.verbose( @@ -136,6 +146,27 @@ logger.verbose( : `Browser console logger initialized with level ${logLevel}`, ); +/** + * Registers an additional destination to the pino logger. + * Use only when working with destinations, not worker transports. + */ +export function registerLoggingStream(stream: Writable): void { + logger.verbose({ module: 'logger' }, `Registering additional logging stream`); + const original = (logger as any)[symbols.streamSym]; + const destination = original + ? pino.multistream( + [ + // Set streams to lowest logging level, and control actual logging from the parent logger + // otherwise streams default to info and refuse to log anything below that. + { level: 'trace', stream: original }, + { level: 'trace', stream }, + ], + { levels: levels.values }, + ) + : stream; + (logger as any)[symbols.streamSym] = destination; +} + /** Log function that accepts an exception object */ type ErrorLogFn = (msg: string, err?: Error | unknown, data?: LogData) => void; 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 5d2c053551a..3f1361df7a7 100644 --- a/yarn-project/telemetry-client/src/vendor/otel-pino-stream.ts +++ b/yarn-project/telemetry-client/src/vendor/otel-pino-stream.ts @@ -129,9 +129,9 @@ export function getTimeConverter(pinoLogger: any, pinoMod: any) { } interface OTelPinoStreamOptions { - messageKey: string; + messageKey?: string; levels: any; // Pino.LevelMapping - otelTimestampFromTime: (time: any) => number; + otelTimestampFromTime?: (time: any) => number; } /** @@ -153,7 +153,7 @@ export class OTelPinoStream extends Writable { // to transports. Eventually OTelPinoStream might be able to use this // for auto-configuration in newer pino versions. The event currently does // not include the `timeSym` value that is needed here, however. - this._messageKey = options.messageKey; + this._messageKey = options.messageKey ?? 'msg'; this._levels = options.levels; // [aztec] The following will break if we set up a custom time function in our logger