chore: improve the sim tests logs (#6394)

* Improve the sim tests logs

* Update packages/utils/src/format.ts

---------

Co-authored-by: Nico Flaig <nflaig@protonmail.com>

packages/cli/test/sim/backup_eth_provider.test.ts

@@ -79,4 +79,7 @@ await waitForSlot(env.clock.getLastSlotOfEpoch(bellatrixForkEpoch) + activePrese
   env,
 });
 
+await node2.beacon.job.stop();
+await node3.beacon.job.stop();
+
 await env.stop();

packages/cli/test/sim/multi_fork.test.ts

@@ -259,4 +259,7 @@ await waitForHead(env, unknownBlockSync, {
   slot: headForUnknownBlockSync.response.data.message.slot,
 });
 
+await unknownBlockSync.beacon.job.stop();
+await unknownBlockSync.execution.job.stop();
+
 await env.stop();

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

@@ -1,5 +1,4 @@
 /* eslint-disable @typescript-eslint/naming-convention */
-import {EventEmitter} from "node:events";
 import fs from "node:fs";
 import {mkdir, writeFile} from "node:fs/promises";
 import path from "node:path";
@@ -9,6 +8,7 @@ import {nodeUtils} from "@lodestar/beacon-node";
 import {ChainForkConfig} from "@lodestar/config";
 import {activePreset} from "@lodestar/params";
 import {BeaconStateAllForks, interopSecretKey} from "@lodestar/state-transition";
+import {prettyMsToTime} from "@lodestar/utils";
 import {EpochClock, MS_IN_SEC} from "./EpochClock.js";
 import {ExternalSignerServer} from "./ExternalSignerServer.js";
 import {SimulationTracker} from "./SimulationTracker.js";
@@ -42,7 +42,6 @@ export class SimulationEnvironment {
   readonly nodes: NodePair[] = [];
   readonly clock: EpochClock;
   readonly tracker: SimulationTracker;
-  readonly emitter: EventEmitter;
   readonly runner: IRunner;
   readonly externalSigner: ExternalSignerServer;
 
@@ -52,6 +51,7 @@ export class SimulationEnvironment {
   private keysCount = 0;
   private nodePairCount = 0;
   private genesisState?: BeaconStateAllForks;
+  private runTimeout?: NodeJS.Timeout;
 
   private constructor(forkConfig: ChainForkConfig, options: SimulationOptions) {
     this.forkConfig = forkConfig;
@@ -64,7 +64,6 @@ export class SimulationEnvironment {
       signal: this.options.controller.signal,
     });
 
-    this.emitter = new EventEmitter();
     this.externalSigner = new ExternalSignerServer([]);
     this.runner = new Runner({logsDir: this.options.logsDir});
     this.tracker = SimulationTracker.initWithDefaultAssertions({
@@ -96,8 +95,14 @@ export class SimulationEnvironment {
 
   async start(opts: StartOpts): Promise<void> {
     const currentTime = Date.now();
+    console.log(
+      `Starting simulation environment "${this.options.id}". currentTime=${new Date(
+        currentTime
+      ).toISOString()} simulationTimeout=${prettyMsToTime(opts.runTimeoutMs)}`
+    );
+
     if (opts.runTimeoutMs > 0) {
-      setTimeout(() => {
+      this.runTimeout = setTimeout(() => {
         const slots = this.clock.getSlotFor((currentTime + opts.runTimeoutMs) / MS_IN_SEC);
         const epoch = this.clock.getEpochForSlot(slots);
         const slot = this.clock.getSlotIndexInEpoch(slots);
@@ -116,7 +121,7 @@ export class SimulationEnvironment {
 
       this.stop(
         1,
-        `Start sequence not completed before genesis, in ${msToGenesis}ms (approx. ${epoch}/${slot}).`
+        `Start sequence not completed before genesis, in ${prettyMsToTime(msToGenesis)} (approx. ${epoch}/${slot}).`
       ).catch((e) => console.error("Error on stop", e));
     }, msToGenesis);
 
@@ -126,21 +131,27 @@ export class SimulationEnvironment {
         await mkdir(this.options.rootDir);
       }
 
+      console.log("Starting the simulation runner");
       await this.runner.start();
+
+      console.log("Starting execution nodes");
       await Promise.all(this.nodes.map((node) => node.execution.job.start()));
 
+      console.log("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");
       await Promise.all(this.nodes.map((node) => node.beacon.job.start()));
+
+      console.log("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...");
+        console.log("Starting external signer");
         await this.externalSigner.start();
-        console.log("Started external signer");
 
         for (const node of this.nodes) {
           if (node.validator?.keys.type === "remote") {
@@ -156,6 +167,7 @@ export class SimulationEnvironment {
         }
       }
 
+      console.log("Starting the simulation tracker");
       await this.tracker.start();
       await Promise.all(this.nodes.map((node) => this.tracker.track(node)));
     } catch (error) {
@@ -179,6 +191,10 @@ export class SimulationEnvironment {
     await this.runner.stop();
     this.options.controller.abort();
 
+    if (this.runTimeout) {
+      clearTimeout(this.runTimeout);
+    }
+
     if (this.tracker.getErrorCount() > 0) {
       this.tracker.reporter.summary();
       process.exit(this.tracker.getErrorCount() > 0 ? 1 : code);

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

@@ -29,19 +29,19 @@ export type SimulationOptions = {
 };
 
 export enum BeaconClient {
-  Lodestar = "beacon_lodestar",
-  Lighthouse = "beacon_lighthouse",
+  Lodestar = "beacon-lodestar",
+  Lighthouse = "beacon-lighthouse",
 }
 
 export enum ValidatorClient {
-  Lodestar = "validator_lodestar",
-  Lighthouse = "validator_lighthouse",
+  Lodestar = "validator-lodestar",
+  Lighthouse = "validator-lighthouse",
 }
 
 export enum ExecutionClient {
-  Mock = "execution_mock",
-  Geth = "execution_geth",
-  Nethermind = "execution_nethermind",
+  Mock = "execution-mock",
+  Geth = "execution-geth",
+  Nethermind = "execution-nethermind",
 }
 
 export enum ExecutionStartMode {

packages/test-utils/src/childProcess.ts

@@ -3,7 +3,7 @@ import childProcess from "node:child_process";
 import stream from "node:stream";
 import fs from "node:fs";
 import path from "node:path";
-import {sleep} from "@lodestar/utils";
+import {prettyMsToTime, sleep} from "@lodestar/utils";
 import {TestContext} from "./interfaces.js";
 
 /**
@@ -328,13 +328,15 @@ export async function spawnChildProcess(
                 const timeSinceHealthCheckStart = Date.now() - startHealthCheckMs;
                 if (timeSinceHealthCheckStart > logHealthChecksAfterMs) {
                   console.log(
-                    `Health check unsuccessful. logPrefix=${logPrefix} pid=${proc.pid}  timeSinceHealthCheckStart=${timeSinceHealthCheckStart}`
+                    `Health check unsuccessful. logPrefix=${logPrefix} pid=${
+                      proc.pid
+                    } timeSinceHealthCheckStart=${prettyMsToTime(timeSinceHealthCheckStart)}`
                   );
                 }
               }
             })
             .catch((e) => {
-              console.error("error on health check, health functions must never throw", e);
+              console.error("Error on health check, health functions must never throw", e);
             });
         }, healthCheckIntervalMs);
 
@@ -344,7 +346,9 @@ export async function spawnChildProcess(
           if (intervalId !== undefined) {
             reject(
               new Error(
-                `Health check timeout. logPrefix=${logPrefix} pid=${proc.pid}  healthTimeoutMs=${healthTimeoutMs}`
+                `Health check timeout. logPrefix=${logPrefix} pid=${proc.pid} healthTimeout=${prettyMsToTime(
+                  healthTimeoutMs ?? 0
+                )}`
               )
             );
           }
@@ -358,9 +362,9 @@ export async function spawnChildProcess(
 
           reject(
             new Error(
-              `process exited before healthy. logPrefix=${logPrefix} pid=${
-                proc.pid
-              } healthTimeoutMs=${healthTimeoutMs} code=${code} command="${command} ${args.join(" ")}"`
+              `Process exited before healthy. logPrefix=${logPrefix} pid=${proc.pid} healthTimeout=${prettyMsToTime(
+                healthTimeoutMs ?? 0
+              )} code=${code} command="${command} ${args.join(" ")}"`
             )
           );
         });

packages/utils/src/format.ts

@@ -54,3 +54,11 @@ export function prettyWeiToEth(wei: bigint, suffix = false): string {
   if (suffix) eth += " ETH";
   return eth;
 }
+
+/**
+ * Format milliseconds to time format HH:MM:SS.ms
+ */
+export function prettyMsToTime(timeMs: number): string {
+  const date = new Date(0, 0, 0, 0, 0, 0, timeMs);
+  return `${date.getHours()}:${date.getMinutes()}:${date.getSeconds()}.${date.getMilliseconds()}`;
+}