feat(evm): logger integration via napi-rs callback (#808)

* add evm dispose function

* introduce evm logger

* add test

* pass logger to db

* reduce verbosity

* properly cleanup tests

* style: resolve style guide violations

---------

Co-authored-by: oXtxNt9U <[email protected]>

packages/configuration-generator/source/generators/genesis-block.test.ts

@@ -5,14 +5,22 @@ import { makeApplication } from "../application-factory";
 import { Identifiers } from "../identifiers";
 import { GenesisBlockGenerator } from "./genesis-block";
 import { MnemonicGenerator } from "./mnemonic";
+import { Application } from "@mainsail/kernel";
 
 describe<{
+	app: Application;
 	generator: GenesisBlockGenerator;
 	mnemonicGenerator: MnemonicGenerator;
-}>("GenesisBlockGenerator", ({ it, assert, beforeEach }) => {
+}>("GenesisBlockGenerator", ({ it, assert, afterEach, beforeEach }) => {
+	afterEach(async (context) => {
+		await context.app.getTagged<Contracts.Evm.Instance>(AppIdentifiers.Evm.Instance, "instance", "evm").dispose();
+	});
+
 	beforeEach(async (context) => {
 		const app = await makeApplication();
 
+		context.app = app;
+
 		// @ts-ignore
 		app.get<Contracts.Crypto.Configuration>(AppIdentifiers.Cryptography.Configuration).setConfig({
 			milestones: [

packages/contracts/source/contracts/evm/evm.ts

@@ -29,6 +29,7 @@ export interface Instance extends CommitHandler {
 	codeAt(address: string): Promise<string>;
 	storageAt(address: string, slot: bigint): Promise<string>;
 	mode(): EvmMode;
+	dispose(): Promise<void>;
 }
 
 export interface ProcessResult {

packages/evm-service/source/index.ts

@@ -22,6 +22,7 @@ export class ServiceProvider extends Providers.ServiceProvider {
 	public async boot(): Promise<void> {}
 
 	public async dispose(): Promise<void> {
-		// TODO
+		await this.app.getTagged<EvmInstance>(Identifiers.Evm.Instance, "instance", "ephemeral").dispose();
+		await this.app.getTagged<EvmInstance>(Identifiers.Evm.Instance, "instance", "evm").dispose();
 	}
 }

packages/evm-service/source/instances/evm.test.ts

@@ -1,4 +1,5 @@
 import { Contracts } from "@mainsail/contracts";
+import { Evm } from "@mainsail/evm";
 import { BigNumberish, ethers, randomBytes } from "ethers";
 
 import { describe, Sandbox } from "../../../test-framework/distribution";
@@ -12,9 +13,14 @@ import { setGracefulCleanup } from "tmp";
 describe<{
 	sandbox: Sandbox;
 	instance: Contracts.Evm.Instance;
-}>("Instance", ({ it, assert, afterAll, beforeEach }) => {
+}>("Instance", ({ it, assert, afterAll, afterEach, beforeEach }) => {
 	afterAll(() => setGracefulCleanup());
 
+	afterEach(async (context) => {
+		await context.sandbox.dispose();
+		await context.instance.dispose();
+	});
+
 	beforeEach(async (context) => {
 		await prepareSandbox(context);
 
@@ -56,6 +62,29 @@ describe<{
 		assert.equal(receipt.deployedContractAddress, "0x0c2485e7d05894BC4f4413c52B080b6D1eca122a");
 	});
 
+	it("should call log hook", async ({ sandbox, instance }) => {
+		let hookCalled = 0;
+
+		const evm = new Evm(sandbox.app.dataPath("loghook"), (level, message) => {
+			//console.log("CALLED HOOK", { level, message, hookCalled });
+			hookCalled++;
+		});
+
+		assert.equal(hookCalled, 0);
+
+		const commitKey = { commitKey: { height: 1n, round: 1n } };
+		await evm.prepareNextCommit(commitKey);
+		assert.equal(hookCalled, 0);
+
+		for (let i = 0; i < 100; i++) {
+			await evm.prepareNextCommit(commitKey);
+		}
+
+		await new Promise((resolve) => setTimeout(resolve, 1000)).then(() => evm.dispose());
+
+		assert.equal(hookCalled, 100);
+	});
+
 	// Also see
 	// https://docs.soliditylang.org/en/latest/units-and-global-variables.html#block-and-transaction-properties
 	it("should correctly set global variables", async ({ instance }) => {

packages/evm-service/source/instances/evm.ts

@@ -1,17 +1,57 @@
 import { inject, injectable, postConstruct } from "@mainsail/container";
 import { Contracts, Identifiers } from "@mainsail/contracts";
-import { Evm } from "@mainsail/evm";
+import { Evm, LogLevel } from "@mainsail/evm";
 
 @injectable()
 export class EvmInstance implements Contracts.Evm.Instance {
 	@inject(Identifiers.Application.Instance)
 	protected readonly app!: Contracts.Kernel.Application;
 
+	@inject(Identifiers.Services.Log.Service)
+	protected readonly logger!: Contracts.Kernel.Logger;
+
 	#evm!: Evm;
 
 	@postConstruct()
 	public initialize() {
-		this.#evm = new Evm(this.app.dataPath());
+		this.#evm = new Evm(this.app.dataPath(), (level: LogLevel, message: string) => {
+			try {
+				switch (level) {
+					case LogLevel.Info: {
+						this.logger.info(message);
+						break;
+					}
+					case LogLevel.Debug: {
+						this.logger.debug(message);
+						break;
+					}
+					case LogLevel.Notice: {
+						this.logger.notice(message);
+						break;
+					}
+					case LogLevel.Emergency: {
+						this.logger.emergency(message);
+						break;
+					}
+					case LogLevel.Alert: {
+						this.logger.alert(message);
+						break;
+					}
+					case LogLevel.Critical: {
+						this.logger.critical(message);
+						break;
+					}
+					case LogLevel.Warning: {
+						this.logger.warning(message);
+						break;
+					}
+				}
+			} catch {}
+		});
+	}
+
+	public async dispose(): Promise<void> {
+		await this.#evm.dispose();
 	}
 
 	public async prepareNextCommit(context: Contracts.Evm.PrepareNextCommitContext): Promise<void> {

packages/evm/bindings/src/lib.rs

@@ -6,9 +6,11 @@ use ctx::{
     JsTransactionContext, JsTransactionViewContext, JsUpdateRewardsAndVotesContext,
     PrepareNextCommitContext, TxContext, TxViewContext, UpdateRewardsAndVotesContext,
 };
+use logger::JsLogger;
 use mainsail_evm_core::{
     account::AccountInfoExtended,
     db::{CommitKey, GenesisInfo, PendingCommit, PersistentDB},
+    logger::LogLevel,
     receipt::{map_execution_result, TxReceipt},
     state_changes::AccountUpdate,
     state_commit, state_hash,
@@ -26,6 +28,7 @@ use revm::{
 };
 
 mod ctx;
+mod logger;
 mod result;
 mod utils;
 
@@ -35,18 +38,22 @@ pub struct EvmInner {
 
     // A pending commit consists of one or more transactions.
     pending_commit: Option<PendingCommit>,
+
+    logger: JsLogger,
 }
 
 // NOTE: we guarantee that this can be sent between threads, since it only is accessed through a mutex
 unsafe impl Send for EvmInner {}
 
 impl EvmInner {
-    pub fn new(path: PathBuf) -> Self {
-        let persistent_db = PersistentDB::new(path).expect("path ok");
+    pub fn new(path: PathBuf, logger_callback: Option<JsFunction>) -> Self {
+        let logger = JsLogger::new(logger_callback).expect("logger ok");
+        let persistent_db = PersistentDB::new(path, Some(logger.inner())).expect("path ok");
 
         EvmInner {
             persistent_db,
             pending_commit: Default::default(),
+            logger,
         }
     }
 
@@ -57,9 +64,12 @@ impl EvmInner {
                 return Ok(());
             }
 
-            println!(
-                "discarding existing pending commit {:?} for {:?}",
-                pending.key, ctx.commit_key
+            self.logger.log(
+                LogLevel::Debug,
+                format!(
+                    "discarding existing pending commit {:?} for {:?}",
+                    pending.key, ctx.commit_key
+                ),
             );
         }
 
@@ -77,7 +87,8 @@ impl EvmInner {
         Ok(match result {
             Ok(r) => {
                 if !r.is_success() {
-                    println!("view call failed: {:?}", r);
+                    self.logger
+                        .log(LogLevel::Warning, format!("view call failed: {:?}", r));
                 }
 
                 TxViewResult {
@@ -198,10 +209,14 @@ impl EvmInner {
             tx_hash: None,
         }) {
             Ok(receipt) => {
-                println!(
-                    "calculate_active_validators {:?} {:?}",
-                    ctx.commit_key, receipt
+                self.logger.log(
+                    LogLevel::Info,
+                    format!(
+                        "calculate_active_validators {:?} {:?}",
+                        ctx.commit_key, receipt
+                    ),
                 );
+
                 assert!(
                     receipt.is_success(),
                     "calculate_active_validators unsuccessful"
@@ -285,12 +300,16 @@ impl EvmInner {
                     tx_hash: None,
                 }) {
                     Ok(receipt) => {
-                        println!(
-                            "vote_update {:?} {:?} {:?}",
-                            ctx.commit_key,
-                            receipt,
-                            voters.len()
+                        self.logger.log(
+                            LogLevel::Info,
+                            format!(
+                                "vote_update {:?} {:?} {:?}",
+                                ctx.commit_key,
+                                receipt,
+                                voters.len()
+                            ),
                         );
+
                         assert!(receipt.is_success(), "vote_update unsuccessful");
                         Ok(())
                     }
@@ -502,11 +521,15 @@ impl EvmInner {
 
         let outcome = match self.take_pending_commit() {
             Some(pending_commit) => {
-                // println!(
-                //     "committing {:?} with {} transactions",
-                //     commit_key,
-                //     pending_commit.diff.len(),
+                // self.logger.log(
+                //     LogLevel::Info,
+                //     format!(
+                //         "committing {:?} with {} transitions",
+                //         commit_key,
+                //         pending_commit.transitions.transitions.len(),
+                //     ),
                 // );
+
                 state_commit::commit_to_db(&mut self.persistent_db, pending_commit)
             }
             None => Ok(Default::default()),
@@ -549,6 +572,14 @@ impl EvmInner {
         }
     }
 
+    pub fn dispose(&mut self) -> std::result::Result<(), EVMError<String>> {
+        // replace to drop any reference to logging hook
+        self.logger = JsLogger::new(None)
+            .map_err(|err| EVMError::Custom(format!("close logger err={err}")))?;
+
+        Ok(())
+    }
+
     fn transact_evm(
         &mut self,
         ctx: ExecutionContext,
@@ -676,10 +707,13 @@ pub struct JsEvmWrapper {
 #[napi]
 impl JsEvmWrapper {
     #[napi(constructor)]
-    pub fn new(path: JsString) -> Result<Self> {
+    pub fn new(path: JsString, logger_callback: Option<JsFunction>) -> Result<Self> {
         let path = path.into_utf8()?.into_owned()?;
         Ok(JsEvmWrapper {
-            evm: Arc::new(tokio::sync::Mutex::new(EvmInner::new(path.into()))),
+            evm: Arc::new(tokio::sync::Mutex::new(EvmInner::new(
+                path.into(),
+                logger_callback,
+            ))),
         })
     }
 
@@ -869,6 +903,11 @@ impl JsEvmWrapper {
         )
     }
 
+    #[napi(ts_return_type = "Promise<void>")]
+    pub fn dispose(&mut self, node_env: Env) -> Result<JsObject> {
+        node_env.execute_tokio_future(Self::dispose_async(self.evm.clone()), |_, _| Ok(()))
+    }
+
     async fn view_async(
         evm: Arc<tokio::sync::Mutex<EvmInner>>,
         view_ctx: TxViewContext,
@@ -1066,4 +1105,14 @@ impl JsEvmWrapper {
             Err(err) => Result::Err(serde::de::Error::custom(err)),
         }
     }
+
+    async fn dispose_async(evm: Arc<tokio::sync::Mutex<EvmInner>>) -> Result<()> {
+        let mut lock = evm.lock().await;
+        let result = lock.dispose();
+
+        match result {
+            Ok(result) => Result::Ok(result),
+            Err(err) => Result::Err(serde::de::Error::custom(err)),
+        }
+    }
 }