feat!: worker friendly logger instances (#5490)

* Add tests for logging in workers * Add logger package * Implement multiple independent loggers * Fix tests * Fix tests * Use separate exports in logger * Add typesVersion support for exports * Fix exports, add getEnvLogger * Fix logger usage and tests * Fix logger exports * Fix linter error * Fix logger unit test * Fix beacon node test logger * Fix more tests * Fix more tests * Fix more tests * Fix browser tests * Move env logger to separate subpath export --------- Co-authored-by: Nazar Hussain <[email protected]> Co-authored-by: Cayman <[email protected]>
ChainSafe · May 15, 2023 · c2e96c8 · c2e96c8
1 parent 375d660
commit c2e96c8
Show file tree

Hide file tree

Showing 85 changed files with 1,063 additions and 499 deletions.
diff --git a/packages/beacon-node/package.json b/packages/beacon-node/package.json
@@ -124,6 +124,7 @@
     "@lodestar/db": "^1.8.0",
     "@lodestar/fork-choice": "^1.8.0",
     "@lodestar/light-client": "^1.8.0",
+    "@lodestar/logger": "^1.8.0",
     "@lodestar/params": "^1.8.0",
     "@lodestar/reqresp": "^1.8.0",
     "@lodestar/state-transition": "^1.8.0",

diff --git a/packages/beacon-node/src/network/discv5/index.ts b/packages/beacon-node/src/network/discv5/index.ts
@@ -5,14 +5,14 @@ import {exportToProtobuf} from "@libp2p/peer-id-factory";
 import {createKeypairFromPeerId, ENR, ENRData, IKeypair, SignableENR} from "@chainsafe/discv5";
 import {spawn, Thread, Worker} from "@chainsafe/threads";
 import {chainConfigFromJson, chainConfigToJson, BeaconConfig} from "@lodestar/config";
-import {Logger} from "@lodestar/utils";
+import {LoggerNode} from "@lodestar/logger/node";
 import {NetworkCoreMetrics} from "../core/metrics.js";
 import {Discv5WorkerApi, Discv5WorkerData, LodestarDiscv5Opts} from "./types.js";
 
 export type Discv5Opts = {
   peerId: PeerId;
   discv5: LodestarDiscv5Opts;
-  logger: Logger;
+  logger: LoggerNode;
   config: BeaconConfig;
   metrics?: NetworkCoreMetrics;
 };
@@ -29,7 +29,7 @@ type Discv5WorkerStatus =
  * Wrapper class abstracting the details of discv5 worker instantiation and message-passing
  */
 export class Discv5Worker extends (EventEmitter as {new (): StrictEventEmitter<EventEmitter, Discv5Events>}) {
-  private logger: Logger;
+  private logger: LoggerNode;
   private status: Discv5WorkerStatus;
   private keypair: IKeypair;
 
@@ -53,6 +53,7 @@ export class Discv5Worker extends (EventEmitter as {new (): StrictEventEmitter<E
       metrics: Boolean(this.opts.metrics),
       chainConfig: chainConfigFromJson(chainConfigToJson(this.opts.config)),
       genesisValidatorsRoot: this.opts.config.genesisValidatorsRoot,
+      loggerOpts: this.opts.logger.toOpts(),
     };
     const worker = new Worker("./worker.js", {workerData} as ConstructorParameters<typeof Worker>[1]);
 

diff --git a/packages/beacon-node/src/network/discv5/types.ts b/packages/beacon-node/src/network/discv5/types.ts
@@ -1,6 +1,7 @@
 import {Discv5, ENRData, SignableENRData} from "@chainsafe/discv5";
 import {Observable} from "@chainsafe/threads/observable";
 import {ChainConfig} from "@lodestar/config";
+import {LoggerNodeOpts} from "@lodestar/logger/node";
 
 // TODO export IDiscv5Config so we don't need this convoluted type
 type Discv5Config = Parameters<(typeof Discv5)["create"]>[0]["config"];
@@ -22,6 +23,7 @@ export interface Discv5WorkerData {
   metrics: boolean;
   chainConfig: ChainConfig;
   genesisValidatorsRoot: Uint8Array;
+  loggerOpts: LoggerNodeOpts;
 }
 
 /**

diff --git a/packages/beacon-node/src/network/discv5/worker.ts b/packages/beacon-node/src/network/discv5/worker.ts
@@ -6,6 +6,7 @@ import {expose} from "@chainsafe/threads/worker";
 import {Observable, Subject} from "@chainsafe/threads/observable";
 import {createKeypairFromPeerId, Discv5, ENR, ENRData, SignableENR, SignableENRData} from "@chainsafe/discv5";
 import {createBeaconConfig, BeaconConfig} from "@lodestar/config";
+import {getNodeLogger} from "@lodestar/logger/node";
 import {RegistryMetricCreator} from "../../metrics/index.js";
 import {collectNodeJSMetrics} from "../../metrics/nodeJsMetrics.js";
 import {ENRKey} from "../metadata.js";
@@ -55,6 +56,8 @@ const workerData = worker.workerData as Discv5WorkerData;
 // eslint-disable-next-line @typescript-eslint/strict-boolean-expressions
 if (!workerData) throw Error("workerData must be defined");
 
+const logger = getNodeLogger(workerData.loggerOpts);
+
 // Set up metrics, nodejs and discv5-specific
 let metricsRegistry: RegistryMetricCreator | undefined;
 let enrRelevanceMetric: Gauge<"status"> | undefined;
@@ -134,3 +137,9 @@ const module: Discv5WorkerApi = {
 };
 
 expose(module);
+
+logger.info("discv5 worker started", {
+  peerId: peerId.toString(),
+  listenAddr: workerData.bindAddr,
+  initialENR: workerData.enr,
+});
diff --git a/packages/beacon-node/src/network/network.ts b/packages/beacon-node/src/network/network.ts
@@ -2,8 +2,9 @@ import {Connection} from "@libp2p/interface-connection";
 import {PeerId} from "@libp2p/interface-peer-id";
 import {Multiaddr} from "@multiformats/multiaddr";
 import {BeaconConfig} from "@lodestar/config";
-import {Logger, sleep, toHex} from "@lodestar/utils";
+import {sleep, toHex} from "@lodestar/utils";
 import {ForkName} from "@lodestar/params";
+import {LoggerNode} from "@lodestar/logger/node";
 import {computeEpochAtSlot, computeTimeAtSlot} from "@lodestar/state-transition";
 import {Epoch, phase0, allForks} from "@lodestar/types";
 import {routes} from "@lodestar/api";
@@ -42,7 +43,7 @@ type NetworkModules = {
   opts: NetworkOptions;
   config: BeaconConfig;
   libp2p: Libp2p;
-  logger: Logger;
+  logger: LoggerNode;
   chain: IBeaconChain;
   signal: AbortSignal;
   peersData: PeersData;
@@ -63,7 +64,7 @@ export type NetworkInitModules = {
   config: BeaconConfig;
   peerId: PeerId;
   peerStoreDir?: string;
-  logger: Logger;
+  logger: LoggerNode;
   metrics: Metrics | null;
   chain: IBeaconChain;
   reqRespHandlers: ReqRespHandlers;
@@ -88,7 +89,7 @@ export class Network implements INetwork {
   private readonly statusCache: LocalStatusCache;
   private readonly libp2p: Libp2p;
   private readonly gossipsub: Eth2Gossipsub;
-  private readonly logger: Logger;
+  private readonly logger: LoggerNode;
   private readonly config: BeaconConfig;
   private readonly clock: IClock;
   private readonly chain: IBeaconChain;

diff --git a/packages/beacon-node/src/network/peers/discover.ts b/packages/beacon-node/src/network/peers/discover.ts
@@ -2,9 +2,10 @@ import {PeerId} from "@libp2p/interface-peer-id";
 import {Multiaddr} from "@multiformats/multiaddr";
 import {PeerInfo} from "@libp2p/interface-peer-info";
 import {BeaconConfig} from "@lodestar/config";
-import {Logger, pruneSetToMax, sleep} from "@lodestar/utils";
+import {pruneSetToMax, sleep} from "@lodestar/utils";
 import {ENR} from "@chainsafe/discv5";
 import {ATTESTATION_SUBNET_COUNT, SYNC_COMMITTEE_SUBNET_COUNT} from "@lodestar/params";
+import {LoggerNode} from "@lodestar/logger/node";
 import {NetworkCoreMetrics} from "../core/metrics.js";
 import {Libp2p} from "../interface.js";
 import {ENRKey, SubnetType} from "../metadata.js";
@@ -30,7 +31,7 @@ export type PeerDiscoveryModules = {
   libp2p: Libp2p;
   peerRpcScores: IPeerRpcScoreStore;
   metrics: NetworkCoreMetrics | null;
-  logger: Logger;
+  logger: LoggerNode;
   config: BeaconConfig;
 };
 
@@ -76,7 +77,7 @@ export class PeerDiscovery {
   private libp2p: Libp2p;
   private peerRpcScores: IPeerRpcScoreStore;
   private metrics: NetworkCoreMetrics | null;
-  private logger: Logger;
+  private logger: LoggerNode;
   private config: BeaconConfig;
   private cachedENRs = new Map<PeerIdStr, CachedENR>();
   private randomNodeQuery: QueryStatus = {code: QueryStatusCode.NotActive};

diff --git a/packages/beacon-node/src/network/peers/peerManager.ts b/packages/beacon-node/src/network/peers/peerManager.ts
@@ -4,7 +4,7 @@ import {BitArray} from "@chainsafe/ssz";
 import {SYNC_COMMITTEE_SUBNET_COUNT} from "@lodestar/params";
 import {BeaconConfig} from "@lodestar/config";
 import {allForks, altair, phase0} from "@lodestar/types";
-import {Logger} from "@lodestar/utils";
+import {LoggerNode} from "@lodestar/logger/node";
 import {GoodByeReasonCode, GOODBYE_KNOWN_CODES, Libp2pEvent} from "../../constants/index.js";
 import {NetworkCoreMetrics} from "../core/metrics.js";
 import {NetworkEvent, INetworkEventBus} from "../events.js";
@@ -83,7 +83,7 @@ export type PeerManagerOpts = {
 
 export type PeerManagerModules = {
   libp2p: Libp2p;
-  logger: Logger;
+  logger: LoggerNode;
   metrics: NetworkCoreMetrics | null;
   reqResp: IReqRespBeaconNode;
   gossip: Eth2Gossipsub;
@@ -115,7 +115,7 @@ enum RelevantPeerStatus {
  */
 export class PeerManager {
   private libp2p: Libp2p;
-  private logger: Logger;
+  private logger: LoggerNode;
   private metrics: NetworkCoreMetrics | null;
   private reqResp: IReqRespBeaconNode;
   private gossipsub: Eth2Gossipsub;

diff --git a/packages/beacon-node/src/node/nodejs.ts b/packages/beacon-node/src/node/nodejs.ts
@@ -4,7 +4,7 @@ import {Registry} from "prom-client";
 import {PeerId} from "@libp2p/interface-peer-id";
 import {BeaconConfig} from "@lodestar/config";
 import {phase0} from "@lodestar/types";
-import {Logger} from "@lodestar/utils";
+import {LoggerNode} from "@lodestar/logger/node";
 import {Api, ServerApi} from "@lodestar/api";
 import {BeaconStateAllForks} from "@lodestar/state-transition";
 import {ProcessShutdownCallback} from "@lodestar/validator";
@@ -45,7 +45,7 @@ export type BeaconNodeInitModules = {
   opts: IBeaconNodeOptions;
   config: BeaconConfig;
   db: IBeaconDb;
-  logger: Logger;
+  logger: LoggerNode;
   processShutdownCallback: ProcessShutdownCallback;
   peerId: PeerId;
   peerStoreDir?: string;

diff --git a/packages/beacon-node/test/e2e/api/impl/lightclient/endpoint.test.ts b/packages/beacon-node/test/e2e/api/impl/lightclient/endpoint.test.ts
@@ -23,7 +23,7 @@ describe("lightclient api", function () {
   const chainConfig: ChainConfig = {...chainConfigDef, SECONDS_PER_SLOT, ALTAIR_FORK_EPOCH};
   const genesisValidatorsRoot = Buffer.alloc(32, 0xaa);
   const config = createBeaconConfig(chainConfig, genesisValidatorsRoot);
-  const testLoggerOpts: TestLoggerOpts = {logLevel: LogLevel.info};
+  const testLoggerOpts: TestLoggerOpts = {level: LogLevel.info};
   const loggerNodeA = testLogger("Node-A", testLoggerOpts);
   const validatorCount = 2;
 

diff --git a/packages/beacon-node/test/e2e/api/lodestar/lodestar.test.ts b/packages/beacon-node/test/e2e/api/lodestar/lodestar.test.ts
@@ -38,7 +38,7 @@ describe("api / impl / validator", function () {
       const genesisValidatorsRoot = Buffer.alloc(32, 0xaa);
       const config = createBeaconConfig(chainConfig, genesisValidatorsRoot);
 
-      const testLoggerOpts: TestLoggerOpts = {logLevel: LogLevel.info};
+      const testLoggerOpts: TestLoggerOpts = {level: LogLevel.info};
       const loggerNodeA = testLogger("Node-A", testLoggerOpts);
 
       const bn = await getDevBeaconNode({
@@ -90,7 +90,7 @@ describe("api / impl / validator", function () {
       const genesisValidatorsRoot = Buffer.alloc(32, 0xaa);
       const config = createBeaconConfig(chainConfig, genesisValidatorsRoot);
 
-      const testLoggerOpts: TestLoggerOpts = {logLevel: LogLevel.info};
+      const testLoggerOpts: TestLoggerOpts = {level: LogLevel.info};
       const loggerNodeA = testLogger("Node-A", testLoggerOpts);
 
       const bn = await getDevBeaconNode({

diff --git a/packages/beacon-node/test/e2e/chain/lightclient.test.ts b/packages/beacon-node/test/e2e/chain/lightclient.test.ts
@@ -3,7 +3,7 @@ import {ChainConfig} from "@lodestar/config";
 import {ssz, altair} from "@lodestar/types";
 import {JsonPath, toHexString, fromHexString} from "@chainsafe/ssz";
 import {computeDescriptor, TreeOffsetProof} from "@chainsafe/persistent-merkle-tree";
-import {TimestampFormatCode} from "@lodestar/utils";
+import {TimestampFormatCode} from "@lodestar/logger";
 import {EPOCHS_PER_SYNC_COMMITTEE_PERIOD, SLOTS_PER_EPOCH} from "@lodestar/params";
 import {Lightclient} from "@lodestar/light-client";
 import {computeStartSlotAtEpoch} from "@lodestar/state-transition";
@@ -57,7 +57,7 @@ describe("chain / lightclient", function () {
     const genesisTime = Math.floor(Date.now() / 1000) + genesisSlotsDelay * testParams.SECONDS_PER_SLOT;
 
     const testLoggerOpts: TestLoggerOpts = {
-      logLevel: LogLevel.info,
+      level: LogLevel.info,
       timestampFormat: {
         format: TimestampFormatCode.EpochSlot,
         genesisTime,
@@ -67,7 +67,7 @@ describe("chain / lightclient", function () {
     };
 
     const loggerNodeA = testLogger("Node", testLoggerOpts);
-    const loggerLC = testLogger("LC", {...testLoggerOpts, logLevel: LogLevel.debug});
+    const loggerLC = testLogger("LC", {...testLoggerOpts, level: LogLevel.debug});
 
     const bn = await getDevBeaconNode({
       params: testParams,
@@ -92,7 +92,7 @@ describe("chain / lightclient", function () {
       validatorClientCount,
       startIndex: 0,
       useRestApi: false,
-      testLoggerOpts: {...testLoggerOpts, logLevel: LogLevel.error},
+      testLoggerOpts: {...testLoggerOpts, level: LogLevel.error},
     });
 
     afterEachCallbacks.push(async () => {

diff --git a/packages/beacon-node/test/e2e/doppelganger/doppelganger.test.ts b/packages/beacon-node/test/e2e/doppelganger/doppelganger.test.ts
@@ -46,7 +46,7 @@ describe.skip("doppelganger / doppelganger test", function () {
   };
 
   async function createBNAndVC(config?: TestConfig): Promise<{beaconNode: BeaconNode; validators: Validator[]}> {
-    const testLoggerOpts: TestLoggerOpts = {logLevel: LogLevel.info};
+    const testLoggerOpts: TestLoggerOpts = {level: LogLevel.info};
     const loggerNodeA = testLogger("Node-A", testLoggerOpts);
 
     const bn = await getDevBeaconNode({
@@ -150,7 +150,7 @@ describe.skip("doppelganger / doppelganger test", function () {
     this.timeout("10 min");
 
     const doppelgangerProtectionEnabled = true;
-    const testLoggerOpts: TestLoggerOpts = {logLevel: LogLevel.info};
+    const testLoggerOpts: TestLoggerOpts = {level: LogLevel.info};
 
     // set genesis time to allow at least an epoch
     const genesisTime = Math.floor(Date.now() / 1000) - SLOTS_PER_EPOCH * beaconParams.SECONDS_PER_SLOT;

diff --git a/packages/beacon-node/test/sim/merge-interop.test.ts b/packages/beacon-node/test/sim/merge-interop.test.ts
@@ -2,7 +2,8 @@ import fs from "node:fs";
 import {Context} from "mocha";
 import {fromHexString} from "@chainsafe/ssz";
 import {isExecutionStateType, isMergeTransitionComplete} from "@lodestar/state-transition";
-import {LogLevel, sleep, TimestampFormatCode} from "@lodestar/utils";
+import {LogLevel, sleep} from "@lodestar/utils";
+import {TimestampFormatCode} from "@lodestar/logger";
 import {ForkName, SLOTS_PER_EPOCH} from "@lodestar/params";
 import {ChainConfig} from "@lodestar/config";
 import {routes} from "@lodestar/api";
@@ -265,8 +266,11 @@ describe("executionEngine / ExecutionEngineHttp", function () {
     const genesisTime = Math.floor(Date.now() / 1000) + genesisSlotsDelay * testParams.SECONDS_PER_SLOT;
 
     const testLoggerOpts: TestLoggerOpts = {
-      logLevel: LogLevel.info,
-      logFile: `${logFilesDir}/merge-interop-${testName}.log`,
+      level: LogLevel.info,
+      file: {
+        filepath: `${logFilesDir}/merge-interop-${testName}.log`,
+        level: LogLevel.debug,
+      },
       timestampFormat: {
         format: TimestampFormatCode.EpochSlot,
         genesisTime,

diff --git a/packages/beacon-node/test/sim/mergemock.test.ts b/packages/beacon-node/test/sim/mergemock.test.ts
@@ -1,7 +1,8 @@
 import fs from "node:fs";
 import {Context} from "mocha";
 import {fromHexString, toHexString} from "@chainsafe/ssz";
-import {LogLevel, sleep, TimestampFormatCode} from "@lodestar/utils";
+import {LogLevel, sleep} from "@lodestar/utils";
+import {TimestampFormatCode} from "@lodestar/logger";
 import {SLOTS_PER_EPOCH} from "@lodestar/params";
 import {ChainConfig} from "@lodestar/config";
 import {Epoch, bellatrix} from "@lodestar/types";
@@ -123,8 +124,11 @@ describe("executionEngine / ExecutionEngineHttp", function () {
     const genesisTime = Math.floor(Date.now() / 1000) + genesisSlotsDelay * testParams.SECONDS_PER_SLOT;
 
     const testLoggerOpts: TestLoggerOpts = {
-      logLevel: LogLevel.info,
-      logFile: `${logFilesDir}/mergemock-${testName}.log`,
+      level: LogLevel.info,
+      file: {
+        filepath: `${logFilesDir}/mergemock-${testName}.log`,
+        level: LogLevel.debug,
+      },
       timestampFormat: {
         format: TimestampFormatCode.EpochSlot,
         genesisTime,

diff --git a/packages/beacon-node/test/sim/withdrawal-interop.test.ts b/packages/beacon-node/test/sim/withdrawal-interop.test.ts
@@ -1,7 +1,8 @@
 import fs from "node:fs";
 import {Context} from "mocha";
 import {fromHexString, toHexString} from "@chainsafe/ssz";
-import {LogLevel, sleep, TimestampFormatCode} from "@lodestar/utils";
+import {LogLevel, sleep} from "@lodestar/utils";
+import {TimestampFormatCode} from "@lodestar/logger";
 import {SLOTS_PER_EPOCH, ForkName} from "@lodestar/params";
 import {ChainConfig} from "@lodestar/config";
 import {computeStartSlotAtEpoch} from "@lodestar/state-transition";
@@ -233,8 +234,11 @@ describe("executionEngine / ExecutionEngineHttp", function () {
     const genesisTime = Math.floor(Date.now() / 1000) + genesisSlotsDelay * testParams.SECONDS_PER_SLOT;
 
     const testLoggerOpts: TestLoggerOpts = {
-      logLevel: LogLevel.info,
-      logFile: `${logFilesDir}/mergemock-${testName}.log`,
+      level: LogLevel.info,
+      file: {
+        filepath: `${logFilesDir}/mergemock-${testName}.log`,
+        level: LogLevel.debug,
+      },
       timestampFormat: {
         format: TimestampFormatCode.EpochSlot,
         genesisTime,

diff --git a/packages/beacon-node/test/unit/chain/prepareNextSlot.test.ts b/packages/beacon-node/test/unit/chain/prepareNextSlot.test.ts
@@ -2,10 +2,10 @@ import {expect} from "chai";
 import sinon, {SinonStubbedInstance} from "sinon";
 import {config} from "@lodestar/config/default";
 import {ForkChoice, ProtoBlock} from "@lodestar/fork-choice";
-import {WinstonLogger} from "@lodestar/utils";
 import {ForkName, SLOTS_PER_EPOCH} from "@lodestar/params";
 import {ChainForkConfig} from "@lodestar/config";
 import {routes} from "@lodestar/api";
+import {LoggerNode} from "@lodestar/logger/node";
 import {BeaconChain, ChainEventEmitter} from "../../../src/chain/index.js";
 import {IBeaconChain} from "../../../src/chain/interface.js";
 import {IChainOptions} from "../../../src/chain/options.js";
@@ -20,6 +20,7 @@ import {ExecutionEngineHttp} from "../../../src/execution/engine/http.js";
 import {IExecutionEngine} from "../../../src/execution/engine/interface.js";
 import {StubbedChainMutable} from "../../utils/stub/index.js";
 import {zeroProtoBlock} from "../../utils/mocks/chain/chain.js";
+import {createStubbedLogger} from "../../utils/mocks/logger.js";
 
 type StubbedChain = StubbedChainMutable<"clock" | "forkChoice" | "emitter" | "regen" | "opts">;
 
@@ -31,7 +32,7 @@ describe("PrepareNextSlot scheduler", () => {
   let scheduler: PrepareNextSlotScheduler;
   let forkChoiceStub: SinonStubbedInstance<ForkChoice> & ForkChoice;
   let regenStub: SinonStubbedInstance<StateRegenerator> & StateRegenerator;
-  let loggerStub: SinonStubbedInstance<WinstonLogger> & WinstonLogger;
+  let loggerStub: SinonStubbedInstance<LoggerNode> & LoggerNode;
   let beaconProposerCacheStub: SinonStubbedInstance<BeaconProposerCache> & BeaconProposerCache;
   let getForkStub: SinonStubFn<(typeof config)["getForkName"]>;
   let updateBuilderStatus: SinonStubFn<IBeaconChain["updateBuilderStatus"]>;
@@ -51,7 +52,7 @@ describe("PrepareNextSlot scheduler", () => {
     regenStub = sandbox.createStubInstance(StateRegenerator) as SinonStubbedInstance<StateRegenerator> &
       StateRegenerator;
     chainStub.regen = regenStub;
-    loggerStub = sandbox.createStubInstance(WinstonLogger) as SinonStubbedInstance<WinstonLogger> & WinstonLogger;
+    loggerStub = createStubbedLogger(sandbox);
     beaconProposerCacheStub = sandbox.createStubInstance(
       BeaconProposerCache
     ) as SinonStubbedInstance<BeaconProposerCache> & BeaconProposerCache;