Move winston NodeJS transports to cli package (#4509)

* Move winston NodeJS transports to cli package * Remove old profile test * Fix types in beacon-node test * Remove logger.important usage * Use function constructor * Enable customization of logLevel per module * Don't mutate module on print * Update logger options * Update logger cli tests * Remove dynamic log level test * Check-types * Remove legacy item * Use LoggerModule for vmon
ChainSafe · Sep 6, 2022 · 91a5a06 · 91a5a06
1 parent 8806ed2
commit 91a5a06
Show file tree

Hide file tree

Showing 35 changed files with 528 additions and 595 deletions.
diff --git a/packages/beacon-node/src/node/loggerOptions.ts b/packages/beacon-node/src/node/loggerOptions.ts
diff --git a/packages/beacon-node/src/node/nodejs.ts b/packages/beacon-node/src/node/nodejs.ts
@@ -56,6 +56,19 @@ export enum BeaconNodeStatus {
   closed = "closed",
 }
 
+enum LoggerModule {
+  api = "api",
+  backfill = "backfill",
+  chain = "chain",
+  eth1 = "eth1",
+  metrics = "metrics",
+  network = "network",
+  /** validator monitor */
+  vmon = "vmon",
+  rest = "rest",
+  sync = "sync",
+}
+
 /**
  * The main Beacon Node class.  Contains various components for getting and processing data from the
  * Ethereum Consensus ecosystem as well as systems for getting beacon node metadata.
@@ -132,7 +145,13 @@ export class BeaconNode {
 
     let metrics = null;
     if (opts.metrics.enabled) {
-      metrics = createMetrics(opts.metrics, config, anchorState, logger.child({module: "VMON"}), metricsRegistries);
+      metrics = createMetrics(
+        opts.metrics,
+        config,
+        anchorState,
+        logger.child({module: LoggerModule.vmon}),
+        metricsRegistries
+      );
       initBeaconMetrics(metrics, anchorState);
       // Since the db is instantiated before this, metrics must be injected manually afterwards
       db.setMetrics(metrics.db);
@@ -141,15 +160,15 @@ export class BeaconNode {
     const chain = new BeaconChain(opts.chain, {
       config,
       db,
-      logger: logger.child(opts.logger.chain),
+      logger: logger.child({module: LoggerModule.chain}),
       processShutdownCallback,
       metrics,
       anchorState,
       eth1: initializeEth1ForBlockProduction(opts.eth1, {
         config,
         db,
         metrics,
-        logger: logger.child(opts.logger.eth1),
+        logger: logger.child({module: LoggerModule.eth1}),
         signal,
       }),
       executionEngine: initializeExecutionEngine(opts.executionEngine, {metrics, signal}),
@@ -164,7 +183,7 @@ export class BeaconNode {
     const network = new Network(opts.network, {
       config,
       libp2p,
-      logger: logger.child(opts.logger.network),
+      logger: logger.child({module: LoggerModule.network}),
       metrics,
       chain,
       reqRespHandlers: getReqRespHandlers({db, chain}),
@@ -177,7 +196,7 @@ export class BeaconNode {
       metrics,
       network,
       wsCheckpoint,
-      logger: logger.child(opts.logger.sync),
+      logger: logger.child({module: LoggerModule.sync}),
     });
 
     const backfillSync =
@@ -190,14 +209,14 @@ export class BeaconNode {
             network,
             wsCheckpoint,
             anchorState,
-            logger: logger.child(opts.logger.backfill),
+            logger: logger.child({module: LoggerModule.backfill}),
             signal,
           })
         : null;
 
     const api = getApi(opts.api, {
       config,
-      logger: logger.child(opts.logger.api),
+      logger: logger.child({module: LoggerModule.api}),
       db,
       sync,
       network,
@@ -206,15 +225,18 @@ export class BeaconNode {
     });
 
     const metricsServer = metrics
-      ? new HttpMetricsServer(opts.metrics, {register: metrics.register, logger: logger.child(opts.logger.metrics)})
+      ? new HttpMetricsServer(opts.metrics, {
+          register: metrics.register,
+          logger: logger.child({module: LoggerModule.metrics}),
+        })
       : undefined;
     if (metricsServer) {
       await metricsServer.start();
     }
 
     const restApi = new BeaconRestApiServer(opts.api.rest, {
       config,
-      logger: logger.child(opts.logger.api),
+      logger: logger.child({module: LoggerModule.rest}),
       api,
       metrics: metrics ? metrics.apiRest : null,
     });

diff --git a/packages/beacon-node/src/node/options.ts b/packages/beacon-node/src/node/options.ts
@@ -11,7 +11,6 @@ import {
   ExecutionBuilderOpts,
   defaultExecutionBuilderOpts,
 } from "../execution/index.js";
-import {defaultLoggerOptions, IBeaconLoggerOptions} from "./loggerOptions.js";
 // Re-export so the CLI doesn't need to depend on lodestar-api
 export {allNamespaces} from "../api/rest/index.js";
 
@@ -22,7 +21,6 @@ export interface IBeaconNodeOptions {
   eth1: Eth1Options;
   executionEngine: ExecutionEngineOpts;
   executionBuilder: ExecutionBuilderOpts;
-  logger: IBeaconLoggerOptions;
   metrics: MetricsOptions;
   network: INetworkOptions;
   sync: SyncOptions;
@@ -35,7 +33,6 @@ export const defaultOptions: IBeaconNodeOptions = {
   eth1: defaultEth1Options,
   executionEngine: defaultExecutionEngineOpts,
   executionBuilder: defaultExecutionBuilderOpts,
-  logger: defaultLoggerOptions,
   metrics: defaultMetricsOptions,
   network: defaultNetworkOptions,
   sync: defaultSyncOptions,

diff --git a/packages/beacon-node/test/e2e/chain/lightclient.test.ts b/packages/beacon-node/test/e2e/chain/lightclient.test.ts
@@ -113,7 +113,7 @@ describe("chain / lightclient", function () {
       });
     }).then(async (head) => {
       // Initialize lightclient
-      loggerLC.important("Initializing lightclient", {slot: head.slot});
+      loggerLC.info("Initializing lightclient", {slot: head.slot});
 
       const lightclient = await Lightclient.initializeFromCheckpointRoot({
         config: bn.config,
@@ -130,7 +130,7 @@ describe("chain / lightclient", function () {
         lightclient.stop();
       });
 
-      loggerLC.important("Initialized lightclient", {headSlot: lightclient.getHead().slot});
+      loggerLC.info("Initialized lightclient", {headSlot: lightclient.getHead().slot});
       lightclient.start();
 
       return new Promise<void>((resolve, reject) => {
@@ -166,7 +166,7 @@ describe("chain / lightclient", function () {
 
     const promiseTillFinalization = new Promise<void>((resolve) => {
       bn.chain.emitter.on(ChainEvent.finalized, (checkpoint) => {
-        loggerNodeA.important("Node A emitted finalized checkpoint event", {epoch: checkpoint.epoch});
+        loggerNodeA.info("Node A emitted finalized checkpoint event", {epoch: checkpoint.epoch});
         if (checkpoint.epoch >= finalizedEpochToReach) {
           resolve();
         }

diff --git a/packages/beacon-node/test/e2e/db/api/beacon/repositories/blockArchive.test.ts b/packages/beacon-node/test/e2e/db/api/beacon/repositories/blockArchive.test.ts
@@ -1,11 +1,10 @@
 import {expect} from "chai";
 import {config} from "@lodestar/config/default";
 import {fromHexString} from "@chainsafe/ssz";
-import {allForks, phase0, ssz} from "@lodestar/types";
+import {ssz} from "@lodestar/types";
 import {BeaconDb} from "../../../../../../src/db/index.js";
 import {generateSignedBlock} from "../../../../../utils/block.js";
 import {testLogger} from "../../../../../utils/logger.js";
-import {BlockArchiveBatchPutBinaryItem} from "../../../../../../src/db/repositories/index.js";
 import {startTmpBeaconDb} from "../../../../../utils/db.js";
 
 describe("BlockArchiveRepository", function () {
@@ -70,49 +69,4 @@ describe("BlockArchiveRepository", function () {
     savedBlock2.message.slot = sampleBlock.message.slot;
     expect(ssz.phase0.SignedBeaconBlock.equals(savedBlock1, savedBlock2)).to.equal(true);
   });
-
-  it("batchPutBinary should be faster than batchPut", async () => {
-    // increase length to test performance
-    const signedBlocks = Array.from({length: 1000}, (_, i) => {
-      const signedBlock = sampleBlock;
-      signedBlock.message.slot = i;
-      return signedBlock;
-    });
-    // persist to block db
-    await Promise.all(signedBlocks.map((signedBlock: phase0.SignedBeaconBlock) => db.block.add(signedBlock)));
-    const blockSummaries = signedBlocks.map(toBatchPutBinaryItem);
-    // old way
-    logger.profile("batchPut");
-    const savedBlocks = notNull(
-      await Promise.all(blockSummaries.map((summary) => db.block.get(summary.blockRoot as Uint8Array)))
-    );
-    await db.blockArchive.batchPut(savedBlocks.map((block) => ({key: block.message.slot, value: block})));
-    logger.profile("batchPut");
-    logger.profile("batchPutBinary");
-    const blockBinaries = notNull(
-      await Promise.all(blockSummaries.map((summary) => db.block.getBinary(summary.blockRoot as Uint8Array)))
-    );
-    await db.blockArchive.batchPutBinary(
-      blockSummaries.map((summary, i) => ({
-        ...summary,
-        value: blockBinaries[i],
-      }))
-    );
-    logger.profile("batchPutBinary");
-  });
 });
-
-function notNull<T>(arr: (T | null)[]): T[] {
-  for (const item of arr) if (item === null) throw Error("null item");
-  return arr as T[];
-}
-
-function toBatchPutBinaryItem(signedBlock: allForks.SignedBeaconBlock): BlockArchiveBatchPutBinaryItem {
-  return {
-    key: signedBlock.message.slot,
-    value: ssz.phase0.SignedBeaconBlock.serialize(signedBlock) as Buffer,
-    slot: signedBlock.message.slot,
-    blockRoot: config.getForkTypes(signedBlock.message.slot).BeaconBlock.hashTreeRoot(signedBlock.message),
-    parentRoot: signedBlock.message.parentRoot,
-  };
-}
diff --git a/packages/beacon-node/test/e2e/sync/finalizedSync.test.ts b/packages/beacon-node/test/e2e/sync/finalizedSync.test.ts
@@ -65,7 +65,7 @@ describe("sync / finalized sync", function () {
     afterEachCallbacks.push(() => bn.close());
 
     await waitForEvent<phase0.Checkpoint>(bn.chain.emitter, ChainEvent.finalized, 240000);
-    loggerNodeA.important("Node A emitted finalized checkpoint event");
+    loggerNodeA.info("Node A emitted finalized checkpoint event");
 
     const bn2 = await getDevBeaconNode({
       params: beaconParams,

diff --git a/packages/beacon-node/test/e2e/sync/unknownBlockSync.test.ts b/packages/beacon-node/test/e2e/sync/unknownBlockSync.test.ts
@@ -74,7 +74,7 @@ describe("sync / unknown block sync", function () {
     afterEachCallbacks.push(() => bn.close());
 
     await waitForEvent<phase0.Checkpoint>(bn.chain.emitter, ChainEvent.checkpoint, 240000);
-    loggerNodeA.important("Node A emitted checkpoint event");
+    loggerNodeA.info("Node A emitted checkpoint event");
 
     const bn2 = await getDevBeaconNode({
       params: testParams,

diff --git a/packages/beacon-node/test/e2e/sync/wss.test.ts b/packages/beacon-node/test/e2e/sync/wss.test.ts
@@ -84,16 +84,16 @@ describe("Start from WSS", function () {
     try {
       await finalizedEventistener;
       await waitForEvent<phase0.Checkpoint>(bn.chain.emitter, ChainEvent.finalized, timeout);
-      loggerNodeA.important("\n\nNode A finalized\n\n");
+      loggerNodeA.info("\n\nNode A finalized\n\n");
     } catch (e) {
       (e as Error).message = `Node A failed to finalize: ${(e as Error).message}`;
       throw e;
     }
 
     const checkpointSyncUrl = "http://127.0.0.1:19596";
-    loggerNodeB.important("Fetching weak subjectivity state ", {checkpointSyncUrl});
+    loggerNodeB.info("Fetching weak subjectivity state ", {checkpointSyncUrl});
     const {wsState, wsCheckpoint} = await fetchWeakSubjectivityState(config, loggerNodeB, {checkpointSyncUrl});
-    loggerNodeB.important("Fetched wss state");
+    loggerNodeB.info("Fetched wss state");
 
     const bnStartingFromWSS = await getDevBeaconNode({
       params: {...testParams, ALTAIR_FORK_EPOCH: Infinity},

diff --git a/packages/beacon-node/test/unit/metrics/utils.ts b/packages/beacon-node/test/unit/metrics/utils.ts
@@ -1,10 +1,10 @@
 import {config} from "@lodestar/config/default";
 import {ssz} from "@lodestar/types";
-import {WinstonLogger} from "@lodestar/utils";
 import {createMetrics, IMetrics} from "../../../src/metrics/index.js";
+import {testLogger} from "../../utils/logger.js";
 
 export function createMetricsTest(): IMetrics {
   const state = ssz.phase0.BeaconState.defaultViewDU();
-  const logger = new WinstonLogger();
+  const logger = testLogger();
   return createMetrics({enabled: true, port: 0}, config, state, logger);
 }
diff --git a/packages/beacon-node/test/unit/network/reqresp/response/rateLimiter.test.ts b/packages/beacon-node/test/unit/network/reqresp/response/rateLimiter.test.ts
@@ -1,13 +1,14 @@
 import {expect} from "chai";
 import PeerId from "peer-id";
 import sinon, {SinonStubbedInstance} from "sinon";
-import {WinstonLogger} from "@lodestar/utils";
 import {IPeerRpcScoreStore, PeerAction, PeerRpcScoreStore} from "../../../../../src/network/index.js";
 import {defaultNetworkOptions} from "../../../../../src/network/options.js";
 import {InboundRateLimiter} from "../../../../../src/network/reqresp/response/rateLimiter.js";
 import {Method, RequestTypedContainer} from "../../../../../src/network/reqresp/types.js";
+import {testLogger} from "../../../../utils/logger.js";
 
 describe("ResponseRateLimiter", () => {
+  const logger = testLogger();
   let inboundRateLimiter: InboundRateLimiter;
   const sandbox = sinon.createSandbox();
   let peerRpcScoresStub: IPeerRpcScoreStore & SinonStubbedInstance<PeerRpcScoreStore>;
@@ -16,7 +17,7 @@ describe("ResponseRateLimiter", () => {
     peerRpcScoresStub = sandbox.createStubInstance(PeerRpcScoreStore) as IPeerRpcScoreStore &
       SinonStubbedInstance<PeerRpcScoreStore>;
     inboundRateLimiter = new InboundRateLimiter(defaultNetworkOptions, {
-      logger: new WinstonLogger(),
+      logger,
       peerRpcScores: peerRpcScoresStub,
       metrics: null,
     });
@@ -140,7 +141,7 @@ describe("ResponseRateLimiter", () => {
     const startMem = process.memoryUsage().heapUsed;
 
     const rateLimiter = new InboundRateLimiter(defaultNetworkOptions, {
-      logger: new WinstonLogger(),
+      logger,
       peerRpcScores: peerRpcScoresStub,
       metrics: null,
     });

diff --git a/packages/beacon-node/test/utils/logger.ts b/packages/beacon-node/test/utils/logger.ts
@@ -1,5 +1,6 @@
 /* eslint-disable @typescript-eslint/no-unsafe-member-access, @typescript-eslint/no-unsafe-assignment */
-import {WinstonLogger, LogLevel, TransportType, TransportOpts, TimestampFormat} from "@lodestar/utils";
+import winston from "winston";
+import {createWinstonLogger, ILogger, LogLevel, TimestampFormat} from "@lodestar/utils";
 export {LogLevel};
 
 export type TestLoggerOpts = {
@@ -16,15 +17,20 @@ export type TestLoggerOpts = {
  * VERBOSE=1 mocha .ts
  * ```
  */
-export function testLogger(module?: string, opts?: TestLoggerOpts): WinstonLogger {
-  const transports: TransportOpts[] = [
-    {type: TransportType.console, level: getLogLevelFromEnvs() || opts?.logLevel || LogLevel.error},
+export function testLogger(module?: string, opts?: TestLoggerOpts): ILogger {
+  const transports: winston.transport[] = [
+    new winston.transports.Console({level: getLogLevelFromEnvs() || opts?.logLevel || LogLevel.error}),
   ];
   if (opts?.logFile) {
-    transports.push({type: TransportType.file, filename: opts.logFile, level: LogLevel.debug});
+    transports.push(
+      new winston.transports.File({
+        level: LogLevel.debug,
+        filename: opts.logFile,
+      })
+    );
   }
 
-  return new WinstonLogger({module, ...opts}, transports);
+  return createWinstonLogger({module, ...opts}, transports);
 }
 
 function getLogLevelFromEnvs(): LogLevel | null {