test: add support to dump raw simulation data for debugging

packages/cli/test/utils/simulation/SimulationEnvironment.ts

@@ -9,6 +9,8 @@ import {ChainForkConfig} from "@lodestar/config";
 import {activePreset} from "@lodestar/params";
 import {BeaconStateAllForks, interopSecretKey} from "@lodestar/state-transition";
 import {prettyMsToTime} from "@lodestar/utils";
+import {LogLevel, TimestampFormatCode} from "@lodestar/logger";
+import {getNodeLogger, LoggerNode} from "@lodestar/logger/node";
 import {EpochClock, MS_IN_SEC} from "./EpochClock.js";
 import {ExternalSignerServer} from "./ExternalSignerServer.js";
 import {SimulationTracker} from "./SimulationTracker.js";
@@ -36,14 +38,13 @@ interface StartOpts {
   runTimeoutMs: number;
 }
 
-/* eslint-disable no-console */
-
 export class SimulationEnvironment {
   readonly nodes: NodePair[] = [];
   readonly clock: EpochClock;
   readonly tracker: SimulationTracker;
   readonly runner: IRunner;
   readonly externalSigner: ExternalSignerServer;
+  readonly logger: LoggerNode;
 
   readonly forkConfig: ChainForkConfig;
   readonly options: SimulationOptions;
@@ -57,6 +58,14 @@ export class SimulationEnvironment {
     this.forkConfig = forkConfig;
     this.options = options;
 
+    this.logger = getNodeLogger({
+      level: LogLevel.debug,
+      module: `sim-${this.options.id}`,
+      timestampFormat: {
+        format: TimestampFormatCode.DateRegular,
+      },
+      file: {level: LogLevel.debug, filepath: path.join(options.logsDir, `simulation-${this.options.id}.log`)},
+    });
     this.clock = new EpochClock({
       genesisTime: this.options.genesisTime + this.forkConfig.GENESIS_DELAY,
       secondsPerSlot: this.forkConfig.SECONDS_PER_SLOT,
@@ -65,8 +74,10 @@ export class SimulationEnvironment {
     });
 
     this.externalSigner = new ExternalSignerServer([]);
-    this.runner = new Runner({logsDir: this.options.logsDir});
+    this.runner = new Runner({logsDir: this.options.logsDir, logger: this.logger.child({module: "runner"})});
     this.tracker = SimulationTracker.initWithDefaultAssertions({
+      logsDir: options.logsDir,
+      logger: this.logger,
       nodes: [],
       config: this.forkConfig,
       clock: this.clock,
@@ -95,7 +106,7 @@ export class SimulationEnvironment {
 
   async start(opts: StartOpts): Promise<void> {
     const currentTime = Date.now();
-    console.log(
+    this.logger.info(
       `Starting simulation environment "${this.options.id}". currentTime=${new Date(
         currentTime
       ).toISOString()} simulationTimeout=${prettyMsToTime(opts.runTimeoutMs)}`
@@ -108,7 +119,7 @@ export class SimulationEnvironment {
         const slot = this.clock.getSlotIndexInEpoch(slots);
 
         this.stop(1, `Sim run timeout in ${opts.runTimeoutMs}ms (approx. ${epoch}/${slot}).`).catch((e) =>
-          console.error("Error on stop", e)
+          this.logger.error("Error on stop", e)
         );
       }, opts.runTimeoutMs);
     }
@@ -122,7 +133,7 @@ export class SimulationEnvironment {
       this.stop(
         1,
         `Start sequence not completed before genesis, in ${prettyMsToTime(msToGenesis)} (approx. ${epoch}/${slot}).`
-      ).catch((e) => console.error("Error on stop", e));
+      ).catch((e) => this.logger.error("Error on stop", e));
     }, msToGenesis);
 
     try {
@@ -131,26 +142,26 @@ export class SimulationEnvironment {
         await mkdir(this.options.rootDir);
       }
 
-      console.log("Starting the simulation runner");
+      this.logger.info("Starting the simulation runner");
       await this.runner.start();
 
-      console.log("Starting execution nodes");
+      this.logger.info("Starting execution nodes");
       await Promise.all(this.nodes.map((node) => node.execution.job.start()));
 
-      console.log("Initializing genesis state for beacon nodes");
+      this.logger.info("Initializing genesis state for beacon nodes");
       await this.initGenesisState();
       if (!this.genesisState) {
         throw new Error("The genesis state for CL clients is not defined.");
       }
 
-      console.log("Starting beacon nodes");
+      this.logger.info("Starting beacon nodes");
       await Promise.all(this.nodes.map((node) => node.beacon.job.start()));
 
-      console.log("Starting validators");
+      this.logger.info("Starting validators");
       await Promise.all(this.nodes.map((node) => node.validator?.job.start()));
 
       if (this.nodes.some((node) => node.validator?.keys.type === "remote")) {
-        console.log("Starting external signer");
+        this.logger.info("Starting external signer");
         await this.externalSigner.start();
 
         for (const node of this.nodes) {
@@ -162,12 +173,12 @@ export class SimulationEnvironment {
                 url: this.externalSigner.url,
               }))
             );
-            console.log(`Imported remote keys for node ${node.id}`);
+            this.logger.info(`Imported remote keys for node ${node.id}`);
           }
         }
       }
 
-      console.log("Starting the simulation tracker");
+      this.logger.info("Starting the simulation tracker");
       await this.tracker.start();
       await Promise.all(this.nodes.map((node) => this.tracker.track(node)));
     } catch (error) {
@@ -182,8 +193,8 @@ export class SimulationEnvironment {
     process.removeAllListeners("uncaughtException");
     process.removeAllListeners("SIGTERM");
     process.removeAllListeners("SIGINT");
-    console.log(`Simulation environment "${this.options.id}" is stopping: ${message}`);
-    await this.tracker.stop();
+    this.logger.info(`Simulation environment "${this.options.id}" is stopping: ${message}`);
+    await this.tracker.stop({dumpStores: true});
     await Promise.all(this.nodes.map((node) => node.validator?.job.stop()));
     await Promise.all(this.nodes.map((node) => node.beacon.job.stop()));
     await Promise.all(this.nodes.map((node) => node.execution.job.stop()));

packages/cli/test/utils/simulation/SimulationTracker.ts

@@ -1,8 +1,11 @@
 import EventEmitter from "node:events";
+import path from "node:path";
+import fs from "node:fs/promises";
 import createDebug from "debug";
 import {routes} from "@lodestar/api/beacon";
 import {ChainForkConfig} from "@lodestar/config";
 import {Epoch, Slot} from "@lodestar/types";
+import {LoggerNode} from "@lodestar/logger/node";
 import {isNullish} from "../../utils.js";
 import {EpochClock} from "./EpochClock.js";
 import {
@@ -27,6 +30,8 @@ interface SimulationTrackerInitOptions {
   config: ChainForkConfig;
   clock: EpochClock;
   signal: AbortSignal;
+  logger: LoggerNode;
+  logsDir: string;
 }
 
 export enum SimulationTrackerEvent {
@@ -62,32 +67,45 @@ export function getStoresForAssertions<D extends SimulationAssertion[]>(
   return filterStores as StoreTypes<D>;
 }
 
-/* eslint-disable no-console */
+async function pathExists(filePath: string): Promise<boolean> {
+  try {
+    await fs.access(filePath);
+    return true;
+  } catch {
+    return false;
+  }
+}
+
 export class SimulationTracker {
   readonly emitter = new EventEmitter();
   readonly reporter: SimulationReporter<typeof defaultAssertions & StoreType<string, unknown>>;
+  readonly logger: LoggerNode;
+  readonly logsDir: string;
 
   private lastSeenSlot: Map<NodeId, Slot> = new Map();
   private slotCapture: Map<Slot, NodeId[]> = new Map();
   private signal: AbortSignal;
   private nodes: NodePair[];
   private clock: EpochClock;
   private forkConfig: ChainForkConfig;
-  private running: boolean = false;
+  private running = false;
 
   private errors: SimulationAssertionError[] = [];
   private stores: Stores;
   private assertions: SimulationAssertion[];
   private assertionIdsMap: Record<string, boolean> = {};
-  private constructor({signal, nodes, clock, config}: SimulationTrackerInitOptions) {
+  private constructor({signal, nodes, clock, config, logger, logsDir}: SimulationTrackerInitOptions) {
     this.signal = signal;
     this.nodes = nodes;
     this.clock = clock;
     this.forkConfig = config;
+    this.logsDir = logsDir;
+    this.logger = logger.child({module: "tracker"});
 
     this.stores = {} as StoreTypes<typeof defaultAssertions> & StoreType<string, unknown>;
     this.assertions = [] as SimulationAssertion[];
     this.reporter = new TableReporter({
+      logger: this.logger.child({module: "reporter"}),
       clock: this.clock,
       forkConfig: this.forkConfig,
       nodes: this.nodes,
@@ -162,19 +180,42 @@ export class SimulationTracker {
 
     // Start clock loop on current slot or genesis
     this.clockLoop(Math.max(this.clock.currentSlot, 0)).catch((e) => {
-      console.error("error on clockLoop", e);
+      this.logger.error("error on clockLoop", e);
     });
   }
 
-  async stop(): Promise<void> {
+  async stop(opts: {dumpStores: boolean}): Promise<void> {
     this.running = false;
+
+    if (opts.dumpStores) {
+      if (!(await pathExists(path.join(this.logsDir, "data"))))
+        await fs.mkdir(path.join(this.logsDir, "data"), {recursive: true});
+
+      for (const assertion of this.assertions) {
+        if (!assertion.dump) continue;
+
+        const data = await assertion.dump({
+          fork: this.forkConfig.getForkName(this.clock.currentSlot),
+          forkConfig: this.forkConfig,
+          clock: this.clock,
+          epoch: this.clock.currentEpoch,
+          store: this.stores[assertion.id],
+          slot: this.clock.currentSlot,
+          nodes: this.nodes,
+        });
+
+        for (const filename of Object.keys(data)) {
+          await fs.writeFile(path.join(this.logsDir, "data", filename), data[filename]);
+        }
+      }
+    }
   }
 
   async clockLoop(slot: number): Promise<void> {
     while (this.running && !this.signal.aborted) {
       // Wait for 2/3 of the slot to consider it missed
       await this.clock.waitForStartOfSlot(slot + 2 / 3, slot > 0).catch((e) => {
-        console.error("error on waitForStartOfSlot", e);
+        this.logger.error("error on waitForStartOfSlot", e);
       });
       this.reporter.progress(slot);
       slot++;

packages/cli/test/utils/simulation/TableRenderer.ts

@@ -1,12 +1,19 @@
+import {Logger} from "@lodestar/logger";
 import {strFixedSize} from "./utils/index.js";
 
+const V_SEP_M = " │ ";
+const V_SEP_S = "│ ";
+const V_SEP_E = " │";
+
 export class TableRenderer<Columns extends string[number]> {
+  readonly logger: Logger;
   private columnsSizes: Record<Columns, number>;
   private columns: Columns[];
   private rows: Record<Columns, unknown>[];
   private totalWidth: number;
 
-  constructor(columnWithSizes: Record<Columns, number>) {
+  constructor(columnWithSizes: Record<Columns, number>, {logger}: {logger: Logger}) {
+    this.logger = logger;
     this.columnsSizes = columnWithSizes;
     this.columns = Object.keys(columnWithSizes) as Columns[];
     this.rows = [];
@@ -20,54 +27,42 @@ export class TableRenderer<Columns extends string[number]> {
   }
 
   addEmptyRow(text: string): void {
-    this.printHSeparator(true);
-    this.printVSeparator("start");
-    process.stdout.write(strFixedSize(text, this.totalWidth - 4));
-    this.printVSeparator("end");
-    this.printHSeparator(true);
+    this.printHSeparator();
+    this.logger.info(`${V_SEP_S}${strFixedSize(text, this.totalWidth - 4)}${V_SEP_E}`);
+    this.printHSeparator();
   }
 
   printHeader(): void {
-    this.printHSeparator(true);
-    this.printVSeparator("start");
+    this.printHSeparator();
+    const output = [V_SEP_S];
     for (const [index, column] of this.columns.entries()) {
-      process.stdout.write(strFixedSize(column, this.columnsSizes[column]));
+      output.push(strFixedSize(column, this.columnsSizes[column]));
       if (index === this.columns.length - 1) {
-        this.printVSeparator("end");
+        output.push(V_SEP_E);
       } else {
-        this.printVSeparator();
+        output.push(V_SEP_M);
       }
     }
-    this.printHSeparator(true);
+    this.logger.info(output.join(""));
+    this.printHSeparator();
   }
 
   printRow(rowIndex: number): void {
     const row = this.rows[rowIndex];
-
-    this.printVSeparator("start");
+    const output = [V_SEP_S];
     for (const [index, column] of this.columns.entries()) {
       const value = String(row[column]);
-      process.stdout.write(value.padEnd(this.columnsSizes[column]));
+      output.push(value.padEnd(this.columnsSizes[column]));
       if (index === this.columns.length - 1) {
-        this.printVSeparator("end");
+        output.push(V_SEP_E);
       } else {
-        this.printVSeparator();
+        output.push(V_SEP_M);
       }
     }
+    this.logger.info(output.join(""));
   }
 
-  private printHSeparator(lineBreak: boolean): void {
-    process.stdout.write(`┼${"─".repeat(this.totalWidth - 2)}┼`);
-    if (lineBreak) process.stdout.write("\n");
-  }
-
-  private printVSeparator(mode?: "start" | "end"): void {
-    if (!mode) {
-      process.stdout.write(" │ ");
-    } else if (mode === "start") {
-      process.stdout.write("│ ");
-    } else if (mode === "end") {
-      process.stdout.write(" │\n");
-    }
+  private printHSeparator(): void {
+    this.logger.info(`┼${"─".repeat(this.totalWidth - 2)}┼`);
   }
 }