chore: Sync logging with jest (#10459)

Jest would overwrite pino logs when logging via a worker thread. This
changes logging so that we only use pino-pretty if running in jest, and
we only use it as a stream in the main loop. See
https://github.com/pinojs/pino-pretty?tab=readme-ov-file#usage-with-jest
for more info.

This PR also restores OTLP exports via `getEndToEndTestTelemetryClient`,
which had been broken in a previous PR. Export now works by using a
multistream destination (again, main loop) to send logs to OTEL. Note
that there was an error in how we created the telemetry clients: since
starting a new OTEL telemetry client involved registering
metrics/traces/logs in the global OTEL variables, there were multiple
errors in the lines of `Attempted duplicate registration of API: trace`.
This is now fixed by having a single test telemetry client instance.
This requires _not_ setting the service name, which is unfortunate.


![image](https://github.com/user-attachments/assets/5208178c-7765-444f-b0f9-e3f4b7532e43)

As a last change here, the jest reporter for end-to-end tests is now set
to `summary`. This means that jest will no longer write to the console
`RUNS my-test-suite` every second or so, overwriting the actual logs we
are trying to read.

yarn-project/end-to-end/package.json

@@ -145,9 +145,9 @@
     },
     "reporters": [
       [
-        "default",
+        "summary",
         {
-          "summaryThreshold": 9999
+          "summaryThreshold": 0
         }
       ]
     ],

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
+        }
+      ]
+    ]
   }
 }

yarn-project/end-to-end/src/e2e_p2p/p2p_network.ts

@@ -121,7 +121,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();
 

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,

yarn-project/end-to-end/src/fixtures/snapshot_manager.ts

@@ -351,7 +351,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 });

yarn-project/end-to-end/src/fixtures/with_telemetry_utils.ts

@@ -1,23 +1,36 @@
+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<TelemetryClient> {
-  return !metricsPort
-    ? Promise.resolve(new NoopTelemetryClient())
-    : createAndStartTelemetryClient(getEndToEndTestTelemetryConfig(metricsPort, serviceName));
+let telemetryClient: Promise<TelemetryClient> | undefined;
+export function getEndToEndTestTelemetryClient(metricsPort?: number): Promise<TelemetryClient> {
+  if (!metricsPort) {
+    return Promise.resolve(new NoopTelemetryClient());
+  }
+  if (!telemetryClient) {
+    telemetryClient = createEndToEndTestOtelClient(metricsPort);
+  }
+  return telemetryClient;
+}
+
+function createEndToEndTestOtelClient(metricsPort: number): Promise<TelemetryClient> {
+  const otelStream = new OTelPinoStream({ levels });
+  registerLoggingStream(otelStream);
+  return createAndStartTelemetryClient(getEndToEndTestTelemetryConfig(metricsPort));
 }
 
 /**
  * Utility functions for setting up end-to-end tests with telemetry.
  *
  * 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;
 }

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,32 +69,35 @@ 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 },
 };
 
 // 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;
 

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