Skip to content

Commit

Permalink
test: add support to dump raw simulation data for debugging (#6429)
Browse files Browse the repository at this point in the history 
* Add logs support for file dump

* Add logger to runner

* Add feature to dump raw data for debugging

* Add dump support to few assertions

* Update log level for errors

* Fix head assertion csv data

* Revert "Fix head assertion csv data"

This reverts commit 91abfc2.

* Fix head assertion csv data
  • Loading branch information
@nazarhussain
nazarhussain authored Feb 15, 2024
1 parent c52c7bd commit 83d7d70
Show file tree
Hide file tree
Showing 10 changed files with 198 additions and 77 deletions.
43 changes: 27 additions & 16 deletions packages/cli/test/utils/simulation/SimulationEnvironment.ts
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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";
Expand Down Expand Up @@ -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;
Expand All @@ -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,
Expand All @@ -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,
Expand Down Expand Up @@ -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)}`
Expand All @@ -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);
}
Expand All @@ -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 {
Expand All @@ -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) {
Expand All @@ -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) {
Expand All @@ -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()));
Expand Down
53 changes: 47 additions & 6 deletions packages/cli/test/utils/simulation/SimulationTracker.ts
View file
Original file line number Diff line number Diff line change
@@ -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 {
Expand All @@ -27,6 +30,8 @@ interface SimulationTrackerInitOptions {
config: ChainForkConfig;
clock: EpochClock;
signal: AbortSignal;
logger: LoggerNode;
logsDir: string;
}

export enum SimulationTrackerEvent {
Expand Down Expand Up @@ -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,
Expand Down Expand Up @@ -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++;
Expand Down
55 changes: 25 additions & 30 deletions packages/cli/test/utils/simulation/TableRenderer.ts
View file
Original file line number Diff line number Diff line change
@@ -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 = [];
Expand All @@ -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)}┼`);
}
}
Loading

0 comments on commit 83d7d70

Please sign in to comment.