fix: the browser logger and improve tests for logger package (#5883)

* Restructure the unit tests for logger

* Add browser tests support

* Move logger test utils to relevant package

packages/logger/test/unit/logger.test.ts → packages/cli/test/unit/util/logger.test.ts

@@ -1,7 +1,6 @@
 import {expect} from "chai";
 import sinon from "sinon";
-// eslint-disable-next-line import/no-relative-packages
-import {shouldDeleteLogFile} from "../../../cli/src/util/logger.js";
+import {shouldDeleteLogFile} from "../../../src/util/logger.js";
 
 describe("shouldDeleteLogFile", function () {
   const prefix = "beacon";

packages/logger/.mocharc.yml

@@ -1,3 +1,5 @@
 colors: true
 node-option:
   - "loader=ts-node/esm"
+require:
+  - ./test/setup.ts

packages/logger/karma.config.cjs

@@ -0,0 +1,9 @@
+const karmaConfig = require("../../karma.base.config.js");
+const webpackConfig = require("./webpack.test.config.cjs");
+
+module.exports = function karmaConfigurator(config) {
+  config.set({
+    ...karmaConfig,
+    webpack: webpackConfig,
+  });
+};

packages/logger/package.json

@@ -56,7 +56,9 @@
     "lint": "eslint --color --ext .ts src/ test/",
     "lint:fix": "yarn run lint --fix",
     "pretest": "yarn run check-types",
-    "test:unit": "mocha 'test/**/*.test.ts'",
+    "test:unit": "mocha 'test/unit/**/*.test.ts'",
+    "test:browsers": "yarn karma start karma.config.cjs",
+    "test:e2e": "mocha 'test/e2e/**/*.test.ts'",
     "check-readme": "typescript-docs-verifier"
   },
   "types": "lib/index.d.ts",
@@ -69,7 +71,8 @@
   "devDependencies": {
     "@types/triple-beam": "^1.3.2",
     "rimraf": "^4.4.1",
-    "triple-beam": "^1.3.0"
+    "triple-beam": "^1.3.0",
+    "@lodestar/test-utils": "^1.10.0"
   },
   "keywords": [
     "ethereum",

packages/logger/src/browser.ts

@@ -2,14 +2,37 @@ import winston from "winston";
 import Transport from "winston-transport";
 import {LogLevel, Logger} from "@lodestar/utils";
 import {createWinstonLogger} from "./winston.js";
+import {LEVEL, MESSAGE, TimestampFormat, WinstonLogInfo} from "./interface.js";
 
 export type BrowserLoggerOpts = {
+  /**
+   * Module prefix for all logs
+   */
   module?: string;
   level: LogLevel;
+  /**
+   * Rendering format for logs, defaults to "human"
+   */
+  format?: "human" | "json";
+  /**
+   * Enables relative to genesis timestamp format
+   * ```
+   * timestampFormat = {
+   *   format: TimestampFormatCode.EpochSlot,
+   *   genesisTime: args.logFormatGenesisTime,
+   *   secondsPerSlot: config.SECONDS_PER_SLOT,
+   *   slotsPerEpoch: SLOTS_PER_EPOCH,
+   * }
+   * ```
+   */
+  timestampFormat?: TimestampFormat;
 };
 
 export function getBrowserLogger(opts: BrowserLoggerOpts): Logger {
-  return createWinstonLogger({level: opts.level, module: opts.module ?? ""}, [new BrowserConsole({level: opts.level})]);
+  return createWinstonLogger(
+    {level: opts.level, module: opts.module ?? "", format: opts.format, timestampFormat: opts.timestampFormat},
+    [new BrowserConsole({level: opts.level})]
+  );
 }
 
 class BrowserConsole extends Transport {
@@ -37,19 +60,22 @@ class BrowserConsole extends Transport {
     this.level = opts?.level && this.levels.hasOwnProperty(opts.level) ? opts.level : "info";
   }
 
-  log(method: string | number, message: unknown): void {
+  log(info: WinstonLogInfo, callback: () => void): void {
     setTimeout(() => {
-      this.emit("logged", method);
+      this.emit("logged", info);
     }, 0);
 
-    const val = this.levels[method as LogLevel];
-    const mappedMethod = this.methods[method as LogLevel];
+    const val = this.levels[info[LEVEL]];
+    const mappedMethod = this.methods[info[LEVEL]];
+    const message = info[MESSAGE];
 
     if (val <= this.levels[this.level as LogLevel]) {
       // eslint-disable-next-line @typescript-eslint/ban-ts-comment
       // @ts-expect-error
       // eslint-disable-next-line @typescript-eslint/no-unsafe-call, no-console
       console[mappedMethod](message);
     }
+
+    callback();
   }
 }

packages/logger/src/env.ts

@@ -2,6 +2,7 @@ import {Logger} from "@lodestar/utils";
 import {LogLevel} from "@lodestar/utils";
 import {BrowserLoggerOpts, getBrowserLogger} from "./browser.js";
 import {getEmptyLogger} from "./empty.js";
+import {LogFormat, TimestampFormat} from "./interface.js";
 
 export function getEnvLogLevel(): LogLevel | null {
   if (process == null) return null;
@@ -13,9 +14,15 @@ export function getEnvLogLevel(): LogLevel | null {
 
 export function getEnvLogger(opts?: Partial<BrowserLoggerOpts>): Logger {
   const level = opts?.level ?? getEnvLogLevel();
+  const format = (opts?.format ?? process.env["LOG_FORMAT"]) as LogFormat;
+  const timestampFormat =
+    opts?.timestampFormat ??
+    ((process.env["LOG_TIMESTAMP_FORMAT"]
+      ? {format: process.env["LOG_TIMESTAMP_FORMAT"]}
+      : undefined) as TimestampFormat);
 
   if (level != null) {
-    return getBrowserLogger({...opts, level});
+    return getBrowserLogger({...opts, level, format, timestampFormat});
   }
 
   return getEmptyLogger();

packages/logger/src/interface.ts

@@ -1,5 +1,8 @@
+// eslint-disable-next-line import/no-extraneous-dependencies
+import {LEVEL, MESSAGE} from "triple-beam";
 import {LogLevel, Logger, LogHandler, LogData} from "@lodestar/utils";
-export {LogLevel, Logger, LogHandler, LogData};
+
+export {LogLevel, Logger, LogHandler, LogData, LEVEL, MESSAGE};
 
 export const logLevelNum: {[K in LogLevel]: number} = {
   [LogLevel.error]: 0,
@@ -23,9 +26,9 @@ export type EpochSlotOpts = {
   slotsPerEpoch: number;
 };
 export enum TimestampFormatCode {
-  DateRegular,
-  Hidden,
-  EpochSlot,
+  DateRegular = "regular",
+  Hidden = "hidden",
+  EpochSlot = "epoch",
 }
 export type TimestampFormat =
   | {format: TimestampFormatCode.DateRegular}
@@ -38,3 +41,9 @@ export interface LoggerOptions {
   format?: LogFormat;
   timestampFormat?: TimestampFormat;
 }
+
+export interface WinstonLogInfo {
+  module: string;
+  [LEVEL]: LogLevel;
+  [MESSAGE]: string;
+}

packages/logger/src/utils/consoleTransport.ts

@@ -1,25 +1,15 @@
-import winston, {Logger} from "winston";
-// eslint-disable-next-line import/no-extraneous-dependencies
-import {LEVEL} from "triple-beam";
-import {LogLevel} from "../interface.js";
+import {Logger, transports} from "winston";
+import {LEVEL, LogLevel, WinstonLogInfo} from "../interface.js";
 
-interface DefaultMeta {
-  module: string;
-}
-
-interface LogInfo extends DefaultMeta {
-  [LEVEL]: LogLevel;
-}
-
-export class ConsoleDynamicLevel extends winston.transports.Console {
+export class ConsoleDynamicLevel extends transports.Console {
   private readonly levelByModule = new Map<string, LogLevel>();
   private readonly defaultLevel: LogLevel;
 
   // Define property from TransportStream that's not in the types
   private readonly levels!: Record<LogLevel, number>;
   private parent?: Logger;
 
-  constructor(opts: {defaultLevel: LogLevel} & winston.transports.ConsoleTransportOptions) {
+  constructor(opts: {defaultLevel: LogLevel} & transports.ConsoleTransportOptions) {
     super(opts);
 
     this.defaultLevel = opts.defaultLevel;
@@ -36,7 +26,7 @@ export class ConsoleDynamicLevel extends winston.transports.Console {
     return this.levelByModule.delete(module);
   }
 
-  _write(info: LogInfo, enc: BufferEncoding, callback: (error?: Error | null | undefined) => void): void {
+  _write(info: WinstonLogInfo, enc: BufferEncoding, callback: (error?: Error | null | undefined) => void): void {
     const moduleLevel = this.levelByModule.get(info.module) ?? this.defaultLevel;
 
     // Min number is highest prio log level

packages/logger/test/fixtures/loggerFormats.ts

@@ -0,0 +1,48 @@
+import {LodestarError} from "@lodestar/utils";
+import {LogData, LogFormat} from "../../src/index.js";
+
+type TestCase = {
+  id: string;
+  message: string;
+  context?: LogData;
+  error?: Error;
+  output: {[P in LogFormat]: string};
+};
+
+/* eslint-disable quotes */
+export const formatsTestCases: (TestCase | (() => TestCase))[] = [
+  {
+    id: "regular log with metadata",
+    message: "foo bar",
+    context: {meta: "data"},
+    output: {
+      human: "[]                 \u001b[33mwarn\u001b[39m: foo bar meta=data",
+      json: '{"context":{"meta":"data"},"level":"warn","message":"foo bar","module":""}',
+    },
+  },
+
+  {
+    id: "regular log with big int metadata",
+    message: "big int",
+    context: {data: BigInt(1)},
+    output: {
+      human: "[]                 \u001b[33mwarn\u001b[39m: big int data=1",
+      json: '{"context":{"data":"1"},"level":"warn","message":"big int","module":""}',
+    },
+  },
+
+  () => {
+    const error = new LodestarError({code: "SAMPLE_ERROR", data: {foo: "bar"}});
+    error.stack = "$STACK";
+    return {
+      id: "error with metadata",
+      opts: {format: "human", module: "SAMPLE"},
+      message: "foo bar",
+      error: error,
+      output: {
+        human: `[]                 \u001b[33mwarn\u001b[39m: foo bar code=SAMPLE_ERROR, data=foo=bar\n${error.stack}`,
+        json: '{"error":{"code":"SAMPLE_ERROR","data":{"foo":"bar"},"stack":"$STACK"},"level":"warn","message":"foo bar","module":""}',
+      },
+    };
+  },
+];

packages/logger/test/unit/browser.test.ts

@@ -0,0 +1,25 @@
+import {expect} from "chai";
+import {LogLevel} from "@lodestar/utils";
+import {stubLoggerForConsole} from "@lodestar/test-utils/mocha";
+import {TimestampFormatCode, logFormats} from "../../src/index.js";
+import {formatsTestCases} from "../fixtures/loggerFormats.js";
+import {getBrowserLogger} from "../../src/browser.js";
+
+describe("browser logger", () => {
+  describe("format and options", () => {
+    for (const testCase of formatsTestCases) {
+      const {id, message, context, error, output} = typeof testCase === "function" ? testCase() : testCase;
+      for (const format of logFormats) {
+        it(`${id} ${format} output`, async () => {
+          const logger = stubLoggerForConsole(
+            getBrowserLogger({level: LogLevel.info, format, timestampFormat: {format: TimestampFormatCode.Hidden}})
+          );
+
+          logger.warn(message, context, error);
+          logger.restoreStubs();
+          expect(logger.getLogs()).deep.equals([output[format]]);
+        });
+      }
+    }
+  });
+});

packages/logger/test/unit/env.node.test.ts

@@ -0,0 +1,28 @@
+import {expect} from "chai";
+import {LogLevel} from "@lodestar/utils";
+import {stubLoggerForConsole} from "@lodestar/test-utils/mocha";
+import {TimestampFormatCode, logFormats} from "../../src/index.js";
+import {formatsTestCases} from "../fixtures/loggerFormats.js";
+import {getEnvLogger} from "../../src/env.js";
+
+describe("env logger", () => {
+  describe("format and options", () => {
+    for (const testCase of formatsTestCases) {
+      const {id, message, context, error, output} = typeof testCase === "function" ? testCase() : testCase;
+      for (const format of logFormats) {
+        it(`${id} ${format} output`, async () => {
+          // Set env variables
+          process.env.LOG_LEVEL = LogLevel.info;
+          process.env.LOG_FORMAT = format;
+          process.env.LOG_TIMESTAMP_FORMAT = TimestampFormatCode.Hidden;
+
+          const logger = stubLoggerForConsole(getEnvLogger());
+
+          logger.warn(message, context, error);
+          logger.restoreStubs();
+          expect(logger.getLogs()).deep.equals([output[format]]);
+        });
+      }
+    }
+  });
+});