From 4967d38220baa089eac4fc2783c909a94122632b Mon Sep 17 00:00:00 2001 From: Nazar Hussain Date: Mon, 14 Aug 2023 16:34:58 +0200 Subject: [PATCH] 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 --- .../test/unit/util}/logger.test.ts | 3 +- packages/logger/.mocharc.yml | 2 + packages/logger/karma.config.cjs | 9 + packages/logger/package.json | 7 +- packages/logger/src/browser.ts | 36 +++- packages/logger/src/env.ts | 9 +- packages/logger/src/interface.ts | 17 +- packages/logger/src/utils/consoleTransport.ts | 20 +- .../logger/test/fixtures/loggerFormats.ts | 48 +++++ packages/logger/test/unit/browser.test.ts | 25 +++ packages/logger/test/unit/env.node.test.ts | 28 +++ .../logger/test/unit/logger/winston.test.ts | 115 ----------- .../logger/test/unit/loggerTransport.test.ts | 194 ------------------ packages/logger/test/unit/node.node.test.ts | 28 +++ .../test/unit/{logger => utils}/json.test.ts | 0 .../unit/{logger => utils}/timeFormat.test.ts | 0 .../logger/test/unit/winston.node.test.ts | 99 +++++++++ packages/logger/test/utils/files.ts | 23 +++ packages/logger/webpack.test.config.cjs | 5 + packages/test-utils/src/mocha.ts | 74 +++++++ 20 files changed, 404 insertions(+), 338 deletions(-) rename packages/{logger/test/unit => cli/test/unit/util}/logger.test.ts (92%) create mode 100644 packages/logger/karma.config.cjs create mode 100644 packages/logger/test/fixtures/loggerFormats.ts create mode 100644 packages/logger/test/unit/browser.test.ts create mode 100644 packages/logger/test/unit/env.node.test.ts delete mode 100644 packages/logger/test/unit/logger/winston.test.ts delete mode 100644 packages/logger/test/unit/loggerTransport.test.ts create mode 100644 packages/logger/test/unit/node.node.test.ts rename packages/logger/test/unit/{logger => utils}/json.test.ts (100%) rename packages/logger/test/unit/{logger => utils}/timeFormat.test.ts (100%) create mode 100644 packages/logger/test/unit/winston.node.test.ts create mode 100644 packages/logger/test/utils/files.ts create mode 100644 packages/logger/webpack.test.config.cjs diff --git a/packages/logger/test/unit/logger.test.ts b/packages/cli/test/unit/util/logger.test.ts similarity index 92% rename from packages/logger/test/unit/logger.test.ts rename to packages/cli/test/unit/util/logger.test.ts index 6cf77fe6a440..5e792e9750d4 100644 --- a/packages/logger/test/unit/logger.test.ts +++ b/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"; diff --git a/packages/logger/.mocharc.yml b/packages/logger/.mocharc.yml index 8b4eb53ed37a..a70609535d4f 100644 --- a/packages/logger/.mocharc.yml +++ b/packages/logger/.mocharc.yml @@ -1,3 +1,5 @@ colors: true node-option: - "loader=ts-node/esm" +require: + - ./test/setup.ts \ No newline at end of file diff --git a/packages/logger/karma.config.cjs b/packages/logger/karma.config.cjs new file mode 100644 index 000000000000..a3ebb967e2ce --- /dev/null +++ b/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, + }); +}; diff --git a/packages/logger/package.json b/packages/logger/package.json index a4c918a15ed5..c43cdf18b51c 100644 --- a/packages/logger/package.json +++ b/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", diff --git a/packages/logger/src/browser.ts b/packages/logger/src/browser.ts index b63664dcba90..fc91fcfcd2a3 100644 --- a/packages/logger/src/browser.ts +++ b/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,13 +60,14 @@ 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 @@ -51,5 +75,7 @@ class BrowserConsole extends Transport { // eslint-disable-next-line @typescript-eslint/no-unsafe-call, no-console console[mappedMethod](message); } + + callback(); } } diff --git a/packages/logger/src/env.ts b/packages/logger/src/env.ts index 3a0408b319ae..201d91c69069 100644 --- a/packages/logger/src/env.ts +++ b/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): 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(); diff --git a/packages/logger/src/interface.ts b/packages/logger/src/interface.ts index 05e74a54b3d9..9b413accd0ad 100644 --- a/packages/logger/src/interface.ts +++ b/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; +} diff --git a/packages/logger/src/utils/consoleTransport.ts b/packages/logger/src/utils/consoleTransport.ts index 45a1664bbbd8..41a1084b4b83 100644 --- a/packages/logger/src/utils/consoleTransport.ts +++ b/packages/logger/src/utils/consoleTransport.ts @@ -1,17 +1,7 @@ -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(); private readonly defaultLevel: LogLevel; @@ -19,7 +9,7 @@ export class ConsoleDynamicLevel extends winston.transports.Console { private readonly levels!: Record; 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 diff --git a/packages/logger/test/fixtures/loggerFormats.ts b/packages/logger/test/fixtures/loggerFormats.ts new file mode 100644 index 000000000000..b9e0caf7bfa8 --- /dev/null +++ b/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":""}', + }, + }; + }, +]; diff --git a/packages/logger/test/unit/browser.test.ts b/packages/logger/test/unit/browser.test.ts new file mode 100644 index 000000000000..c6924404bd97 --- /dev/null +++ b/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]]); + }); + } + } + }); +}); diff --git a/packages/logger/test/unit/env.node.test.ts b/packages/logger/test/unit/env.node.test.ts new file mode 100644 index 000000000000..f03567d04bf3 --- /dev/null +++ b/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]]); + }); + } + } + }); +}); diff --git a/packages/logger/test/unit/logger/winston.test.ts b/packages/logger/test/unit/logger/winston.test.ts deleted file mode 100644 index ee9307c5c9b1..000000000000 --- a/packages/logger/test/unit/logger/winston.test.ts +++ /dev/null @@ -1,115 +0,0 @@ -import "../../setup.js"; -import {expect} from "chai"; -import {MESSAGE} from "triple-beam"; -import Transport from "winston-transport"; -import {LodestarError, LogLevel} from "@lodestar/utils"; -import {LogData, LogFormat, logFormats, TimestampFormatCode} from "../../../src/index.js"; -import {WinstonLoggerNode} from "../../../src/node.js"; - -type WinstonLog = {[MESSAGE]: string}; - -class MemoryTransport extends Transport { - private readonly logs: WinstonLog[] = []; - - log(info: WinstonLog, next: () => void): void { - this.logs.push(info); - next(); - } - - getLogs(): string[] { - return this.logs.map((log) => log[MESSAGE]); - } -} - -// describe("winston logger log level logic", () => { -// it("Should not run format function for not used log level", () => { -// const logger = createWinstonLogger({format, hideTimestamp: true}, [new MemoryTransport()]); -// }); -// }); - -describe("winston logger", () => { - describe("winston logger format and options", () => { - type TestCase = { - id: string; - message: string; - context?: LogData; - error?: Error; - output: {[P in LogFormat]: string}; - }; - /* eslint-disable quotes */ - const testCases: (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":""}`, - }, - }; - }, - ]; - - for (const testCase of testCases) { - const {id, message, context, error, output} = typeof testCase === "function" ? testCase() : testCase; - for (const format of logFormats) { - it(`${id} ${format} output`, async () => { - const memoryTransport = new MemoryTransport(); - const logger = WinstonLoggerNode.fromOpts( - {level: LogLevel.info, format, timestampFormat: {format: TimestampFormatCode.Hidden}}, - [memoryTransport] - ); - logger.warn(message, context, error); - - expect(memoryTransport.getLogs()).deep.equals([output[format]]); - }); - } - } - }); - - describe("child logger", () => { - it("Should parse child module", async () => { - const memoryTransport = new MemoryTransport(); - const loggerA = WinstonLoggerNode.fromOpts( - {level: LogLevel.info, timestampFormat: {format: TimestampFormatCode.Hidden}, module: "a"}, - [memoryTransport] - ); - const loggerAB = loggerA.child({module: "b"}); - const loggerABC = loggerAB.child({module: "c"}); - - loggerA.warn("test a"); - loggerAB.warn("test a/b"); - loggerABC.warn("test a/b/c"); - - expect(memoryTransport.getLogs()).deep.equals([ - "[a] \u001b[33mwarn\u001b[39m: test a", - "[a/b] \u001b[33mwarn\u001b[39m: test a/b", - "[a/b/c] \u001b[33mwarn\u001b[39m: test a/b/c", - ]); - }); - }); -}); diff --git a/packages/logger/test/unit/loggerTransport.test.ts b/packages/logger/test/unit/loggerTransport.test.ts deleted file mode 100644 index d7d1120d9235..000000000000 --- a/packages/logger/test/unit/loggerTransport.test.ts +++ /dev/null @@ -1,194 +0,0 @@ -import fs from "node:fs"; -import path from "node:path"; -import {expect} from "chai"; -import {LodestarError, LogData, LogLevel} from "@lodestar/utils"; -import {LogFormat, TimestampFormatCode, logFormats} from "../../src/index.js"; -import {LoggerNode, LoggerNodeOpts, getNodeLogger} from "../../src/node.js"; - -describe("winston logger format and options", () => { - type TestCase = { - id: string; - message: string; - context?: LogData; - error?: Error; - output: {[P in LogFormat]: string}; - }; - /* eslint-disable quotes */ - const testCases: (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":""}`, - }, - }; - }, - ]; - - let stdoutHook: ReturnType | null = null; - afterEach(() => stdoutHook?.restore()); - - for (const testCase of testCases) { - const {id, message, context, error, output} = typeof testCase === "function" ? testCase() : testCase; - for (const format of logFormats) { - it(`${id} ${format} output`, async () => { - stdoutHook = hookProcessStdout(); - - const logger = getNodeLogger({ - level: LogLevel.info, - format, - timestampFormat: {format: TimestampFormatCode.Hidden}, - }); - - logger.warn(message, context, error); - - expect(stdoutHook.chunks.join("").trim()).to.deep.equal(output[format]); - - stdoutHook.restore(); - }); - } - } -}); - -describe("winston dynamic level by module", () => { - // Tested manually that if an error is thrown in the body after hooking to stdout, the error is visible - // in the status render of the mocha it() block - let stdoutHook: ReturnType | null = null; - afterEach(() => stdoutHook?.restore()); - - it("Should log to child at a lower logLevel", async () => { - const loggerA = getNodeLoggerTest({ - module: "a", - levelModule: { - "a/b": LogLevel.debug, - }, - }); - - stdoutHook = hookProcessStdout(); - - const loggerAB = loggerA.child({module: "b"}); - - loggerA.info("test a info"); // show - loggerA.debug("test a debug"); // skip - loggerAB.info("test a/b info"); // show - loggerAB.debug("test a/b debug"); // show - - await new Promise((r) => setTimeout(r, 1)); - - expect(stdoutHook.chunks).deep.equals([ - "[a] \u001b[32minfo\u001b[39m: test a info\n", - "[a/b] \u001b[32minfo\u001b[39m: test a/b info\n", - "[a/b] \u001b[34mdebug\u001b[39m: test a/b debug\n", - ]); - - // Call at the end on success to print the result - stdoutHook.restore(); - }); -}); - -describe("winston transport log to file", () => { - let tmpDir: string; - let stdoutHook: ReturnType | null = null; - afterEach(() => stdoutHook?.restore()); - - before(() => { - tmpDir = fs.mkdtempSync("test-lodestar-winston-test"); - }); - - it("Should log to file", async () => { - const filename = "child-logger-test.log"; - // filename is mutated to include the data before the extension - const filenameRx = /^child-logger-test/; - const filepath = path.join(tmpDir, filename); - - const logger = getNodeLoggerTest({module: "a", file: {filepath, level: LogLevel.info, dailyRotate: 5}}); - - stdoutHook = hookProcessStdout(); - - logger.warn("test"); - - const expectedOut = "[a] \u001b[33mwarn\u001b[39m: test"; - - expect(await readFileWhenExists(tmpDir, filenameRx)).to.equal(expectedOut); - - expect(stdoutHook.chunks).deep.equals([expectedOut + "\n"]); - stdoutHook.restore(); - }); - - after(() => { - fs.rmSync(tmpDir, {recursive: true}); - }); -}); - -function getNodeLoggerTest(opts: Partial): LoggerNode { - return getNodeLogger({ - level: LogLevel.info, - timestampFormat: {format: TimestampFormatCode.Hidden}, - ...opts, - }); -} - -/** Wait for file to exist have some content, then return its contents */ -async function readFileWhenExists(dirpath: string, filenameRx: RegExp): Promise { - for (let i = 0; i < 200; i++) { - try { - const files = fs.readdirSync(dirpath); - const filename = files.find((file) => filenameRx.test(file)); - if (filename !== undefined) { - const data = fs.readFileSync(path.join(dirpath, filename), "utf8").trim(); - // Winston will first create the file then write to it - if (data) return data; - } - } catch (e) { - if ((e as IoError).code !== "ENOENT") throw e; - } - await new Promise((r) => setTimeout(r, 10)); - } - throw Error("Timeout"); -} - -type IoError = {code: string}; - -// eslint-disable-next-line @typescript-eslint/explicit-function-return-type -function hookProcessStdout() { - const processStdoutWrite = process.stdout.write; - const chunks: string[] = []; - - process.stdout.write = (chunk) => { - chunks.push(chunk.toString()); - return true; - }; - - return { - chunks, - restore() { - process.stdout.write = processStdoutWrite; - }, - }; -} diff --git a/packages/logger/test/unit/node.node.test.ts b/packages/logger/test/unit/node.node.test.ts new file mode 100644 index 000000000000..41c6f8f8f620 --- /dev/null +++ b/packages/logger/test/unit/node.node.test.ts @@ -0,0 +1,28 @@ +import {expect} from "chai"; +import {LogLevel} from "@lodestar/utils"; +import {stubLoggerForProcessStd} from "@lodestar/test-utils/mocha"; +import {TimestampFormatCode, logFormats} from "../../src/index.js"; +import {getNodeLogger} from "../../src/node.js"; +import {formatsTestCases} from "../fixtures/loggerFormats.js"; + +describe("node 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 = stubLoggerForProcessStd( + getNodeLogger({ + level: LogLevel.info, + format, + timestampFormat: {format: TimestampFormatCode.Hidden}, + }) + ); + logger.warn(message, context, error); + logger.restoreStubs(); + expect(logger.getLogs()).deep.equals([output[format]]); + }); + } + } + }); +}); diff --git a/packages/logger/test/unit/logger/json.test.ts b/packages/logger/test/unit/utils/json.test.ts similarity index 100% rename from packages/logger/test/unit/logger/json.test.ts rename to packages/logger/test/unit/utils/json.test.ts diff --git a/packages/logger/test/unit/logger/timeFormat.test.ts b/packages/logger/test/unit/utils/timeFormat.test.ts similarity index 100% rename from packages/logger/test/unit/logger/timeFormat.test.ts rename to packages/logger/test/unit/utils/timeFormat.test.ts diff --git a/packages/logger/test/unit/winston.node.test.ts b/packages/logger/test/unit/winston.node.test.ts new file mode 100644 index 000000000000..cdf7e17ddeb1 --- /dev/null +++ b/packages/logger/test/unit/winston.node.test.ts @@ -0,0 +1,99 @@ +import fs from "node:fs"; +import path from "node:path"; +import {expect} from "chai"; +import {LogLevel} from "@lodestar/utils"; +import {stubLoggerForProcessStd} from "@lodestar/test-utils/mocha"; +import {TimestampFormatCode} from "../../src/index.js"; +import {getNodeLogger} from "../../src/node.js"; +import {readFileWhenExists} from "../utils/files.js"; + +describe("winston logger", () => { + describe("winston dynamic level by module", () => { + it("should log to child at a lower log level", async () => { + const loggerA = stubLoggerForProcessStd( + getNodeLogger({ + level: LogLevel.info, + module: "a", + format: "human", + levelModule: { + "a/b": LogLevel.debug, + }, + timestampFormat: {format: TimestampFormatCode.Hidden}, + }) + ); + + const loggerAB = loggerA.child({module: "b"}); + + loggerA.info("test a info"); // show + loggerA.debug("test a debug"); // skip + loggerAB.info("test a/b info"); // show + loggerAB.debug("test a/b debug"); // show + + loggerA.restoreStubs(); + + expect(loggerA.getLogs()).deep.equals([ + "[a] \u001b[32minfo\u001b[39m: test a info", + "[a/b] \u001b[32minfo\u001b[39m: test a/b info", + "[a/b] \u001b[34mdebug\u001b[39m: test a/b debug", + ]); + }); + }); + + describe("winston transport log to file", () => { + let tmpDir: string; + + before(() => { + tmpDir = fs.mkdtempSync("test-lodestar-winston-test"); + }); + + after(() => { + fs.rmSync(tmpDir, {recursive: true}); + }); + + it("Should log to file", async () => { + const filename = "child-logger-test.log"; + // filename is mutated to include the data before the extension + const filenameRx = /^child-logger-test/; + const filepath = path.join(tmpDir, filename); + + const logger = getNodeLogger({ + module: "a", + level: LogLevel.info, + timestampFormat: {format: TimestampFormatCode.Hidden}, + file: { + filepath, + level: LogLevel.info, + dailyRotate: 5, + }, + }); + + logger.warn("test"); + + const expectedOut = "[a] \u001b[33mwarn\u001b[39m: test"; + + expect(await readFileWhenExists(tmpDir, filenameRx)).to.equal(expectedOut); + }); + }); + + describe("child logger", () => { + it("should parse child module", async () => { + const loggerA = stubLoggerForProcessStd( + getNodeLogger({level: LogLevel.info, timestampFormat: {format: TimestampFormatCode.Hidden}, module: "a"}) + ); + const loggerAB = loggerA.child({module: "b"}); + const loggerABC = loggerAB.child({module: "c"}); + + loggerA.warn("test a"); + loggerAB.warn("test a/b"); + loggerABC.warn("test a/b/c"); + + loggerA.restoreStubs(); + + expect(loggerA.getLogs()).deep.equals([ + "[a] \u001b[33mwarn\u001b[39m: test a", + "[a/b] \u001b[33mwarn\u001b[39m: test a/b", + "[a/b/c] \u001b[33mwarn\u001b[39m: test a/b/c", + ]); + }); + }); +}); diff --git a/packages/logger/test/utils/files.ts b/packages/logger/test/utils/files.ts new file mode 100644 index 000000000000..3eeeb64c0238 --- /dev/null +++ b/packages/logger/test/utils/files.ts @@ -0,0 +1,23 @@ +import fs from "node:fs"; +import path from "node:path"; + +type IoError = {code: string}; + +/** Wait for file to exist have some content, then return its contents */ +export async function readFileWhenExists(dirpath: string, filenameRx: RegExp): Promise { + for (let i = 0; i < 200; i++) { + try { + const files = fs.readdirSync(dirpath); + const filename = files.find((file) => filenameRx.test(file)); + if (filename !== undefined) { + const data = fs.readFileSync(path.join(dirpath, filename), "utf8").trim(); + // Winston will first create the file then write to it + if (data) return data; + } + } catch (e) { + if ((e as IoError).code !== "ENOENT") throw e; + } + await new Promise((r) => setTimeout(r, 10)); + } + throw Error("Timeout"); +} diff --git a/packages/logger/webpack.test.config.cjs b/packages/logger/webpack.test.config.cjs new file mode 100644 index 000000000000..711c6ac891a7 --- /dev/null +++ b/packages/logger/webpack.test.config.cjs @@ -0,0 +1,5 @@ +const webpackConfig = require("../../webpack.test.config.js"); + +module.exports = { + ...webpackConfig, +}; diff --git a/packages/test-utils/src/mocha.ts b/packages/test-utils/src/mocha.ts index 12c2741f67b9..a469cd373afa 100644 --- a/packages/test-utils/src/mocha.ts +++ b/packages/test-utils/src/mocha.ts @@ -1,4 +1,5 @@ import type {Suite} from "mocha"; +import {Logger} from "@lodestar/utils"; import {TestContext} from "./interfaces.js"; export {TestContext} from "./interfaces.js"; @@ -43,3 +44,76 @@ export function getMochaContext(suite: Suite): TestContext { return context; } + +// Typescript does not support array of generics so have to use this flexible workaround +function wrapLogWriter(...writers: [writer: object, ...keys: string[]][]): { + flush: () => string[]; + restore: () => void; +} { + const cache = [] as string[]; + const originals: Record> = {}; + + for (const [index, [writer, ...keys]] of writers.entries()) { + originals[index] = {}; + + for (const key of keys) { + originals[index][key] = writer[key as keyof typeof writer]; + + // eslint-disable-next-line @typescript-eslint/ban-ts-comment + // @ts-expect-error + writer[key as keyof typeof writer] = function mockedWriter(data: string) { + // Our fixtures does not include the new line character + cache.push(data.endsWith("\n") ? data.slice(0, -1) : data); + }; + } + } + + return { + flush: () => cache, + restore: () => { + for (const [index, [writer, ...keys]] of writers.entries()) { + for (const key of keys) { + // eslint-disable-next-line @typescript-eslint/ban-ts-comment + // @ts-expect-error + writer[key as keyof typeof writer] = originals[index][key]; + } + } + }, + }; +} + +export function stubLoggerForProcessStd( + logger: T +): T & {getLogs: () => string[]; restoreStubs: () => void} { + const {flush: flushStdout, restore: restoreStdout} = wrapLogWriter( + [process.stdout, "write"], + [process.stderr, "write"] + ); + + return Object.assign(logger, { + getLogs: () => flushStdout(), + restoreStubs: () => { + restoreStdout(); + }, + }); +} + +export function stubLoggerForConsole( + logger: T +): T & {getLogs: () => string[]; restoreStubs: () => void} { + const {flush: flushConsole, restore: restoreConsole} = wrapLogWriter([ + console, + "info", + "warn", + "error", + "debug", + "trace", + ]); + + return Object.assign(logger, { + getLogs: () => flushConsole(), + restoreStubs: () => { + restoreConsole(); + }, + }); +}