Merge tezos/tezos!15269: EVM Node: Add logging to the WASM Runtime

Co-authored-by: Thomas Letan <[email protected]>

Approved-by: Alain Mebsout <[email protected]>
Approved-by: Sylvain R. <[email protected]>

See merge request https://gitlab.com/tezos/tezos/-/merge_requests/15269

Author: Marge Bot

etherlink/bin_node/lib_dev/wasm_runtime.ml

@@ -5,7 +5,11 @@
 (*                                                                           *)
 (*****************************************************************************)
 
-let static_context = Evm_node_wasm_runtime.wasm_runtime_new_context ()
+open Evm_node_wasm_runtime
+
+let () = wasm_runtime_logger_init ()
+
+let static_context = wasm_runtime_new_context ()
 
 module Shared_inbox : sig
   (** [wrap inbox] encapsulates [inbox] between [sol; ipl] and [eol]. These
@@ -41,7 +45,7 @@ let run ~preimages_dir ?preimages_endpoint ~entrypoint tree rollup_address inbox
     : Irmin_context.tree Lwt.t =
   Lwt_preemptive.detach
     (fun () ->
-      Evm_node_wasm_runtime.wasm_runtime_run
+      wasm_runtime_run
         ~preimages_dir
         ?preimages_endpoint:(Option.map Uri.to_string preimages_endpoint)
         ~entrypoint

src/lib_wasm_runtime/Cargo.lock

@@ -13,3 +13,5 @@ ocaml = { version = "1.*" }
 wasmer = { path = "../../src/rust_deps/wasmer-3.3.0/lib/api", default-features = false, features = ["cranelift", "jit"] }
 wasmer-compiler-cranelift = { path = "../../src/rust_deps/wasmer-3.3.0/lib/compiler-cranelift" }
 tezos_crypto_rs = { version = "0.6", default-features = false }
+log = "0.4"
+env_logger = "0.11"

src/lib_wasm_runtime/Cargo.toml

@@ -21,3 +21,5 @@ val wasm_runtime_run :
   Irmin_context.tree
 
 val wasm_runtime_preload_kernel : context -> Irmin_context.tree -> unit
+
+val wasm_runtime_logger_init : unit -> unit

src/lib_wasm_runtime/ocaml-api/evm_node_wasm_runtime.mli

@@ -5,6 +5,7 @@ open! Bigarray
 (* file: api.rs *)
 
 type context
+external wasm_runtime_logger_init: unit -> unit = "wasm_runtime_logger_init"
 external wasm_runtime_new_context: unit -> context = "wasm_runtime_new_context"
 external wasm_runtime_run: context -> string -> string option -> string -> Irmin_context.tree -> bytes -> int32 -> string list ->  Irmin_context.tree = "wasm_runtime_run_bytecode" "wasm_runtime_run"
 external wasm_runtime_preload_kernel: context -> Irmin_context.tree -> unit = "wasm_runtime_preload_kernel"

src/lib_wasm_runtime/ocaml-api/wasm_runtime_gen.ml

@@ -5,6 +5,7 @@ open! Bigarray
 (* file: api.rs *)
 
 type context
+external wasm_runtime_logger_init: unit -> unit = "wasm_runtime_logger_init"
 external wasm_runtime_new_context: unit -> context = "wasm_runtime_new_context"
 external wasm_runtime_run: context -> string -> string option -> string -> Irmin_context.tree -> bytes -> int32 -> string list ->  Irmin_context.tree = "wasm_runtime_run_bytecode" "wasm_runtime_run"
 external wasm_runtime_preload_kernel: context -> Irmin_context.tree -> unit = "wasm_runtime_preload_kernel"

src/lib_wasm_runtime/ocaml-api/wasm_runtime_gen.mli

@@ -8,6 +8,7 @@ use crate::{
     runtime::{self, InputsBuffer, RunStatus},
     types::{ContextHash, EvmTree, OCamlString, SmartRollupAddress},
 };
+use log::trace;
 use ocaml::{Error, List, Pointer, Value};
 use std::collections::BTreeMap;
 use wasmer::{Engine, Features, Module, NativeEngineExt, Store, Target};
@@ -50,6 +51,7 @@ impl KernelsCache {
         let hash = bindings::store_get_hash(evm_tree, &KERNEL_PATH)?;
 
         if self.miss(&hash) {
+            trace!("KernelsCache::load cache miss");
             let code = bindings::read_value(&evm_tree, KERNEL_PATH)?;
             let kernel = Kernel::new(engine, code.as_bytes())?;
             let _previous = self.insert(&hash, kernel);
@@ -91,6 +93,12 @@ impl Context {
     }
 }
 
+#[ocaml::func]
+#[ocaml::sig("unit -> unit")]
+pub fn wasm_runtime_logger_init() {
+    env_logger::init();
+}
+
 #[ocaml::func]
 #[ocaml::sig("unit -> context")]
 pub fn wasm_runtime_new_context() -> Pointer<Context> {

src/lib_wasm_runtime/src/api.rs

@@ -5,11 +5,13 @@
 
 use std::collections::VecDeque;
 
+use log::{debug, error, info, warn};
 use ocaml::Error;
 
 use crate::{
     bindings,
     types::{EvmTree, OCamlString, SmartRollupAddress},
+    write_debug::write_debug,
 };
 
 #[derive(Clone)]
@@ -106,7 +108,7 @@ impl Host {
     }
 
     pub fn write_debug(&self, msg: &[u8]) {
-        print!("{}", String::from_utf8_lossy(msg))
+        write_debug(msg)
     }
 
     pub fn next_input(&mut self) -> Option<Input> {

src/lib_wasm_runtime/src/host.rs

@@ -5,3 +5,4 @@ mod bindings;
 mod host;
 mod runtime;
 mod types;
+mod write_debug;

src/lib_wasm_runtime/src/lib.rs

@@ -5,9 +5,10 @@
 
 use std::{fs, path::PathBuf};
 
-use crate::bindings::{self, BindingsError};
+use crate::bindings::{self, BindingsError, Key};
 
 use super::env::Env;
+use log::trace;
 use tezos_crypto_rs::blake2b;
 use wasmer::{
     imports, AsStoreRef, Function, FunctionEnv, FunctionEnvMut, Imports, MemoryView, RuntimeError,
@@ -85,6 +86,7 @@ fn write_output(_env: FunctionEnvMut<Env>, _ptr: u32, length: u32) -> i32 {
 }
 
 fn read_input(mut env: FunctionEnvMut<Env>, info_addr: u32, dst: u32, max_bytes: u32) -> i32 {
+    trace!("read_input");
     let (runtime_env, store) = env.data_and_store_mut();
 
     match runtime_env.mut_host().next_input() {
@@ -117,6 +119,7 @@ fn store_exists(env: FunctionEnvMut<Env>, key_ptr: u32, key_len: u32) -> Result<
     let memory_view = memory.view(&store);
 
     let key = read_from_memory(&memory_view, key_ptr, key_len)?;
+    trace!("store_exists({})", key.as_str());
 
     match bindings::mem_tree(&runtime_env.host().tree(), key) {
         Ok(true) => Ok(1),
@@ -132,6 +135,7 @@ fn store_has(env: FunctionEnvMut<Env>, key_ptr: u32, key_len: u32) -> Result<i32
     let memory_view = memory.view(&store);
 
     let key = read_from_memory(&memory_view, key_ptr, key_len)?;
+    trace!("store_has({})", key.as_str());
 
     match bindings::store_has(&runtime_env.host().tree(), key) {
         Ok(i) => Ok(i as i32),
@@ -149,6 +153,7 @@ fn store_delete(
     let memory_view = memory.view(&store);
 
     let key = read_from_memory(&memory_view, key_ptr, key_len)?;
+    trace!("store_delete({})", key.as_str());
 
     match bindings::store_delete(&runtime_env.host().tree(), key, false) {
         Ok(evm_tree) => {
@@ -169,6 +174,7 @@ fn store_delete_value(
     let memory_view = memory.view(&store);
 
     let key = read_from_memory(&memory_view, key_ptr, key_len)?;
+    trace!("store_delete_value({})", key.as_str());
 
     match bindings::store_delete(&runtime_env.host().tree(), key, true) {
         Ok(evm_tree) => {
@@ -192,6 +198,7 @@ fn store_copy(
 
     let from = read_from_memory(&memory_view, from_ptr, from_len)?;
     let to = read_from_memory(&memory_view, to_ptr, to_len)?;
+    trace!("store_copy(from: {}, to: {})", from.as_str(), to.as_str());
 
     match bindings::store_copy(&runtime_env.host().tree(), from, to) {
         Ok(evm_tree) => {
@@ -215,6 +222,7 @@ fn store_move(
 
     let from = read_from_memory(&memory_view, from_ptr, from_len)?;
     let to = read_from_memory(&memory_view, to_ptr, to_len)?;
+    trace!("store_move(from: {}, to: {})", from.as_str(), to.as_str());
 
     match bindings::store_move(&runtime_env.host().tree(), from, to) {
         Ok(evm_tree) => {
@@ -238,6 +246,7 @@ fn store_get_hash(
     let memory_view = memory.view(&store);
 
     let key = read_from_memory(&memory_view, key_ptr, key_len)?;
+    trace!("store_get_hash({})", key.as_str());
 
     match bindings::store_get_hash(&runtime_env.host().tree(), &key) {
         Ok(hash) => {
@@ -261,6 +270,7 @@ fn store_list_size(
     let memory_view = memory.view(&store);
 
     let key = read_from_memory(&memory_view, key_ptr, key_len)?;
+    trace!("store_list_size({})", key.as_str());
 
     match bindings::store_list_size(&runtime_env.host().tree(), key) {
         Ok(res) => Ok(res as i64),
@@ -279,6 +289,7 @@ fn store_value_size(
     let memory_view = memory.view(&store);
 
     let key = read_from_memory(&memory_view, key_ptr, key_len)?;
+    trace!("store_value_size({})", key.as_str());
 
     match bindings::store_value_size(&runtime_env.host().tree(), key) {
         Ok(res) => Ok(res as i32),
@@ -299,6 +310,7 @@ fn store_read(
     let memory_view = memory.view(&store);
 
     let key = read_from_memory(&memory_view, key_ptr, key_len)?;
+    trace!("store_read({})", key.as_str());
 
     match bindings::store_read(
         runtime_env.host().tree(),
@@ -327,6 +339,7 @@ fn store_write(
     let memory_view = memory.view(&store);
 
     let key = read_from_memory(&memory_view, key_ptr, key_len)?;
+    trace!("store_write({})", key.as_str());
     let buffer = read_from_memory(&memory_view, src_ptr, src_len)?;
 
     match bindings::store_write(runtime_env.host().tree(), key, offset as usize, &buffer) {
@@ -343,6 +356,7 @@ fn reveal_metadata(
     dst_ptr: u32,
     max_bytes: u32,
 ) -> Result<i32, RuntimeError> {
+    trace!("reveal_metadata");
     let (runtime_env, store) = env.data_and_store_mut();
     let memory = runtime_env.memory();
     let memory_view = memory.view(&store);
@@ -382,6 +396,7 @@ fn reveal_preimage(
 
     let hash_bytes = read_from_memory(&memory_view, hash_ptr, hash_len)?;
     let hash_hex = hex::encode(&hash_bytes);
+    trace!("reveal_preimage({hash_hex})");
 
     if hash_bytes[0] != 0u8 {
         return Err(RuntimeError::new(format!(