improve logging & add fetch process indicator (#767)

* improve logging & add fetch process indicator * cleanup * add space * remove fetch status
AcalaNetwork · Jun 1, 2024 · 87458ac · 87458ac
1 parent 5c9f469
commit 87458ac
Show file tree

Hide file tree

Showing 6 changed files with 73 additions and 38 deletions.
diff --git a/executor/Cargo.lock b/executor/Cargo.lock
diff --git a/executor/Cargo.toml b/executor/Cargo.toml
@@ -22,9 +22,9 @@ wasm-bindgen = "0.2.87"
 serde-wasm-bindgen = "0.6.3"
 wasm-bindgen-futures = "0.4"
 js-sys = "0.3"
+web-sys = { version = "0.3", features = ["console"] }
 log = "0.4"
 console_error_panic_hook = "0.1"
-console_log = { version = "1.0" }
 
 smoldot = { path = '../vendor/smoldot/lib', default-features = false }
 

diff --git a/executor/src/lib.rs b/executor/src/lib.rs
@@ -1,19 +1,57 @@
 extern crate console_error_panic_hook;
 
+use log::{Level, Log, Metadata, Record};
 use smoldot::{
     json_rpc::methods::{HashHexString, HexString},
     trie::TrieEntryVersion,
 };
-use std::{collections::BTreeMap, str::FromStr};
+use std::collections::BTreeMap;
 use wasm_bindgen::prelude::*;
+use web_sys::console;
 
 mod proof;
 mod task;
 
-fn setup_console(level: Option<String>) {
+static LOGGER: WebConsoleLogger = WebConsoleLogger {};
+
+struct WebConsoleLogger {}
+
+impl Log for WebConsoleLogger {
+    #[inline]
+    fn enabled(&self, metadata: &Metadata) -> bool {
+        metadata.level() <= log::max_level()
+    }
+
+    fn log(&self, record: &Record) {
+        if !self.enabled(record.metadata()) {
+            return;
+        }
+
+        // pick the console.log() variant for the appropriate logging level
+        let console_log = match record.level() {
+            Level::Error => console::error_1,
+            Level::Warn => console::warn_1,
+            Level::Info => console::info_1,
+            Level::Debug => console::log_1,
+            Level::Trace => console::debug_1,
+        };
+
+        let msg = format!(
+            "{}: {}",
+            format!("{:>28} {:>6}", record.target(), record.level()),
+            record.args()
+        );
+
+        console_log(&msg.into());
+    }
+
+    fn flush(&self) {}
+}
+
+fn setup_console(level: Option<log::Level>) {
     console_error_panic_hook::set_once();
-    let level = level.map(|x| x.to_uppercase()).unwrap_or("INFO".into());
-    let _ = console_log::init_with_level(log::Level::from_str(level.as_str()).unwrap());
+    let _ = log::set_logger(&LOGGER);
+    log::set_max_level(level.unwrap_or(log::Level::Info).to_level_filter());
 }
 
 #[wasm_bindgen(typescript_custom_section)]
@@ -120,14 +158,10 @@ pub async fn create_proof(nodes: JsValue, updates: JsValue) -> Result<JsValue, J
 }
 
 #[wasm_bindgen]
-pub async fn run_task(
-    task: JsValue,
-    js: JsCallback,
-    log_level: Option<String>,
-) -> Result<JsValue, JsValue> {
-    setup_console(log_level);
-
+pub async fn run_task(task: JsValue, js: JsCallback) -> Result<JsValue, JsValue> {
     let task = serde_wasm_bindgen::from_value::<task::TaskCall>(task)?;
+    setup_console(task.log_level());
+
     let result = task::run_task(task, js).await?;
     let result = serde_wasm_bindgen::to_value(&result)?;
 

diff --git a/executor/src/task.rs b/executor/src/task.rs
@@ -18,6 +18,8 @@ use smoldot::{
 use std::collections::BTreeMap;
 use wasm_bindgen::prelude::*;
 
+const LOG_TARGET: &str = "chopsticks::executor";
+
 #[derive(Serialize, Deserialize)]
 #[serde(rename_all = "camelCase")]
 pub struct RuntimeVersion {
@@ -70,6 +72,19 @@ pub struct TaskCall {
     storage_proof_size: u64,
 }
 
+impl TaskCall {
+    pub fn log_level(&self) -> Option<log::Level> {
+        match self.runtime_log_level {
+            1 => Some(log::Level::Error),
+            2 => Some(log::Level::Warn),
+            3 => Some(log::Level::Info),
+            4 => Some(log::Level::Debug),
+            5 => Some(log::Level::Trace),
+            _ => None,
+        }
+    }
+}
+
 #[derive(Serialize, Deserialize, Debug)]
 #[serde(rename_all = "camelCase")]
 pub struct LogInfo {
@@ -134,7 +149,7 @@ pub async fn run_task(task: TaskCall, js: crate::JsCallback) -> Result<TaskRespo
     let mut runtime_logs: Vec<LogInfo> = vec![];
 
     for (call, params) in task.calls {
-        log::trace!("Calling {}", call);
+        log::trace!(target: LOG_TARGET, "Calling {call}");
 
         let vm = runtime_call::run(runtime_call::Config {
             virtual_machine: vm_proto.clone(),
@@ -332,18 +347,14 @@ pub async fn run_task(task: TaskCall, js: crate::JsCallback) -> Result<TaskRespo
                                 message,
                             } => {
                                 let level = match log_level {
-                                    0 => "ERROR".to_string(),
-                                    1 => "WARN".to_string(),
-                                    2 => "INFO".to_string(),
-                                    3 => "DEBUG".to_string(),
-                                    4 => "TRACE".to_string(),
-                                    l => format!("_{l}_"),
+                                    0 => log::Level::Error,
+                                    1 => log::Level::Warn,
+                                    2 => log::Level::Info,
+                                    3 => log::Level::Debug,
+                                    4 => log::Level::Trace,
+                                    l => unreachable!("unexpected log level {l}"),
                                 };
-                                log::info!(
-                                    "{}: {}",
-                                    format!("{:<28}{:>6}", target.to_string(), level),
-                                    message.to_string()
-                                );
+                                log::log!(target: target.as_ref(), level, "{}", message.to_string());
                                 runtime_logs.push(LogInfo {
                                     message: message.to_string(),
                                     level: Some(log_level),
@@ -357,7 +368,7 @@ pub async fn run_task(task: TaskCall, js: crate::JsCallback) -> Result<TaskRespo
             }
         };
 
-        log::trace!("Completed {}", call);
+        log::trace!(target: LOG_TARGET, "Completed {call}");
 
         match res {
             Ok(success) => {

diff --git a/packages/core/src/wasm-executor/browser-wasm-executor.js b/packages/core/src/wasm-executor/browser-wasm-executor.js
@@ -19,7 +19,7 @@ const createProof = async (nodes, updates) => {
 }
 
 const runTask = async (task, callback) => {
-  return pkg.run_task(task, callback, 'info')
+  return pkg.run_task(task, callback)
 }
 
 const testing = async (callback, key) => {

diff --git a/packages/core/src/wasm-executor/node-wasm-executor.js b/packages/core/src/wasm-executor/node-wasm-executor.js
@@ -22,7 +22,7 @@ const createProof = async (nodes, updates) => {
 }
 
 const runTask = async (task, callback) => {
-  return pkg.run_task(task, callback, process.env.RUST_LOG)
+  return pkg.run_task(task, callback)
 }
 
 const testing = async (callback, key) => {