From a12455638b252cd3d8bb32b24dc5dac1bb7d3a4c Mon Sep 17 00:00:00 2001 From: folex <0xdxdy@gmail.com> Date: Mon, 27 Mar 2023 10:24:44 -0300 Subject: [PATCH 1/5] feat(log): log particle_id in service calls, set different log level by service name --- aquamarine/src/actor.rs | 6 +++++- aquamarine/src/lib.rs | 1 + aquamarine/src/log.rs | 8 +++++++ aquamarine/src/particle_functions.rs | 31 +++++++++++++++++++++------- particle-node/src/main.rs | 12 +++++++++++ 5 files changed, 50 insertions(+), 8 deletions(-) create mode 100644 aquamarine/src/log.rs diff --git a/aquamarine/src/actor.rs b/aquamarine/src/actor.rs index 7d937cbe45..c7eff50aba 100644 --- a/aquamarine/src/actor.rs +++ b/aquamarine/src/actor.rs @@ -123,7 +123,11 @@ where let waker = cx.waker().clone(); // Schedule execution of functions - self.functions.execute(r.effects.call_requests, waker); + self.functions.execute( + r.effects.particle.id.clone(), + r.effects.call_requests, + waker, + ); let effects = RoutingEffects { particle: r.effects.particle, diff --git a/aquamarine/src/lib.rs b/aquamarine/src/lib.rs index ea95a95662..dfd257b8ee 100644 --- a/aquamarine/src/lib.rs +++ b/aquamarine/src/lib.rs @@ -48,6 +48,7 @@ mod config; mod deadline; mod error; mod invoke; +mod log; mod particle_data_store; mod particle_effects; mod particle_executor; diff --git a/aquamarine/src/log.rs b/aquamarine/src/log.rs new file mode 100644 index 0000000000..125b5cb9d2 --- /dev/null +++ b/aquamarine/src/log.rs @@ -0,0 +1,8 @@ +/// Function that prescribes different log levels for different builtin namespaces +pub fn builtin_log_level(service: &str) -> log::Level { + match service { + "array" | "cmp" | "debug" | "math" | "op" | "getDataSrv" => log::Level::Debug, + "peer" | "script" | "stat" | "sig" | "srv" | "dist" | "kad" => log::Level::Info, + _ => log::Level::Info, + } +} diff --git a/aquamarine/src/particle_functions.rs b/aquamarine/src/particle_functions.rs index 1fbca0d711..2ba0bb2059 100644 --- a/aquamarine/src/particle_functions.rs +++ b/aquamarine/src/particle_functions.rs @@ -24,13 +24,16 @@ use futures::future::BoxFuture; use futures::stream::FuturesUnordered; use futures::{FutureExt, StreamExt}; use humantime::format_duration as pretty; +use serde_json::json; +use serde_json::Value as JValue; + use particle_args::{Args, JError}; use particle_execution::{ FunctionOutcome, ParticleFunctionStatic, ParticleParams, ServiceFunction, }; use peer_metrics::FunctionKind; -use serde_json::json; -use serde_json::Value as JValue; + +use crate::log::builtin_log_level; #[derive(Clone, Debug)] /// Performance statistics about executed function call @@ -44,6 +47,7 @@ pub struct SingleCallStat { #[derive(Clone, Debug)] pub struct SingleCallResult { + /// `call_id` comes from AVM's CallRequest call_id: u32, result: CallServiceResult, stat: SingleCallStat, @@ -85,10 +89,10 @@ impl Functions { } /// Add a bunch of call requests to execution - pub fn execute(&mut self, requests: CallRequests, waker: Waker) { + pub fn execute(&mut self, particle_id: String, requests: CallRequests, waker: Waker) { let futs: Vec<_> = requests .into_iter() - .map(|(id, call)| self.call(id, call, waker.clone())) + .map(|(id, call)| self.call(particle_id.clone(), id, call, waker.clone())) .collect(); self.function_calls.extend(futs); } @@ -114,6 +118,7 @@ impl Functions { // maybe it's a good option. fn call( &self, + particle_id: String, call_id: u32, call: CallRequestParams, waker: Waker, @@ -142,6 +147,7 @@ impl Functions { }; let log_args = format!("{:?} {:?}", args.service_id, args.function_name); + let log_level = builtin_log_level(&args.service_id); let start = Instant::now(); @@ -192,10 +198,21 @@ impl Functions { }; if let Err(err) = &result { - let elapsed = pretty(elapsed); - log::warn!("Failed host call {} ({}): {}", log_args, elapsed, err) + log::warn!( + "Failed host call {} ({}) [{}]: {}", + log_args, + pretty(elapsed), + particle_id, + err + ) } else { - log::info!("Executed host call {} ({})", log_args, pretty(elapsed)); + log::log!( + log_level, + "Executed host call {} ({}) [{}]", + log_args, + pretty(elapsed), + particle_id + ); }; let stats = SingleCallStat { diff --git a/particle-node/src/main.rs b/particle-node/src/main.rs index 54d70e173e..3ab25b9414 100644 --- a/particle-node/src/main.rs +++ b/particle-node/src/main.rs @@ -68,6 +68,18 @@ async fn main() -> eyre::Result<()> { // Disable most spamming modules .filter_module("cranelift_codegen", LevelFilter::Off) .filter_module("wasmer_wasi_fl", LevelFilter::Off) + .filter_module("aquamarine::particle_executor", LevelFilter::Off) + .filter_module("tracing::span", LevelFilter::Off) + .filter_module("network", LevelFilter::Off) + .filter_module("execution", LevelFilter::Off) + .filter_module( + "particle_protocol::libp2p_protocol::upgrade", + LevelFilter::Off, + ) + .filter_module("avm_server::runner", LevelFilter::Off) + .filter_module("", LevelFilter::Off) + .filter_module("", LevelFilter::Off) + .filter_module("", LevelFilter::Off) .init(); let version = format!("{}; AIR version {}", VERSION, air_interpreter_wasm::VERSION); From e7be58b4927f8172a7a8f84487bd2f35da1853fe Mon Sep 17 00:00:00 2001 From: folex <0xdxdy@gmail.com> Date: Mon, 27 Mar 2023 10:26:04 -0300 Subject: [PATCH 2/5] feat(log): disable some log namespaces --- particle-node/src/main.rs | 9 ++------- 1 file changed, 2 insertions(+), 7 deletions(-) diff --git a/particle-node/src/main.rs b/particle-node/src/main.rs index 3ab25b9414..49499c8d51 100644 --- a/particle-node/src/main.rs +++ b/particle-node/src/main.rs @@ -72,14 +72,9 @@ async fn main() -> eyre::Result<()> { .filter_module("tracing::span", LevelFilter::Off) .filter_module("network", LevelFilter::Off) .filter_module("execution", LevelFilter::Off) - .filter_module( - "particle_protocol::libp2p_protocol::upgrade", - LevelFilter::Off, - ) + .filter_module("particle_protocol", LevelFilter::Off) .filter_module("avm_server::runner", LevelFilter::Off) - .filter_module("", LevelFilter::Off) - .filter_module("", LevelFilter::Off) - .filter_module("", LevelFilter::Off) + .filter_module("ipfs_effector", LevelFilter::Off) .init(); let version = format!("{}; AIR version {}", VERSION, air_interpreter_wasm::VERSION); From af7c57b6b111ad9aa4fe1be1723a15cc0e5d6d36 Mon Sep 17 00:00:00 2001 From: folex <0xdxdy@gmail.com> Date: Mon, 27 Mar 2023 13:29:22 -0300 Subject: [PATCH 3/5] feat(log): enable some log namespaces back, disable others It's better to manage that through ENV vars --- aquamarine/src/log.rs | 4 +++- particle-node/src/main.rs | 20 +++++++++++++------- 2 files changed, 16 insertions(+), 8 deletions(-) diff --git a/aquamarine/src/log.rs b/aquamarine/src/log.rs index 125b5cb9d2..69e597f31c 100644 --- a/aquamarine/src/log.rs +++ b/aquamarine/src/log.rs @@ -1,7 +1,9 @@ /// Function that prescribes different log levels for different builtin namespaces pub fn builtin_log_level(service: &str) -> log::Level { match service { - "array" | "cmp" | "debug" | "math" | "op" | "getDataSrv" => log::Level::Debug, + "array" | "cmp" | "debug" | "math" | "op" | "getDataSrv" | "run-console" => { + log::Level::Debug + } "peer" | "script" | "stat" | "sig" | "srv" | "dist" | "kad" => log::Level::Info, _ => log::Level::Info, } diff --git a/particle-node/src/main.rs b/particle-node/src/main.rs index 49499c8d51..662ad2a50c 100644 --- a/particle-node/src/main.rs +++ b/particle-node/src/main.rs @@ -68,13 +68,19 @@ async fn main() -> eyre::Result<()> { // Disable most spamming modules .filter_module("cranelift_codegen", LevelFilter::Off) .filter_module("wasmer_wasi_fl", LevelFilter::Off) - .filter_module("aquamarine::particle_executor", LevelFilter::Off) - .filter_module("tracing::span", LevelFilter::Off) - .filter_module("network", LevelFilter::Off) - .filter_module("execution", LevelFilter::Off) - .filter_module("particle_protocol", LevelFilter::Off) - .filter_module("avm_server::runner", LevelFilter::Off) - .filter_module("ipfs_effector", LevelFilter::Off) + .filter_module("walrus", LevelFilter::Off) + .filter_module("wasmer_interface_types_fl", LevelFilter::Off) + .filter_module("polling", LevelFilter::Off) + .filter_module("tide", LevelFilter::Error) + .filter_module("tokio_threadpool", LevelFilter::Error) + .filter_module("tokio_reactor", LevelFilter::Error) + .filter_module("mio", LevelFilter::Error) + .filter_module("tokio_io", LevelFilter::Error) + .filter_module("soketto", LevelFilter::Error) + .filter_module("cranelift_codegen", LevelFilter::Error) + .filter_module("async_io", LevelFilter::Error) + .filter_module("wasmer_interface_types_fl", LevelFilter::Error) + .filter_module("wasmer_wasi", LevelFilter::Error) .init(); let version = format!("{}; AIR version {}", VERSION, air_interpreter_wasm::VERSION); From 9453cb9d80511b2baa81c77151ba08761481f9e7 Mon Sep 17 00:00:00 2001 From: folex <0xdxdy@gmail.com> Date: Mon, 27 Mar 2023 13:30:31 -0300 Subject: [PATCH 4/5] chore: log levels --- particle-node/src/main.rs | 7 +++---- 1 file changed, 3 insertions(+), 4 deletions(-) diff --git a/particle-node/src/main.rs b/particle-node/src/main.rs index 662ad2a50c..b4b568e3ae 100644 --- a/particle-node/src/main.rs +++ b/particle-node/src/main.rs @@ -67,10 +67,11 @@ async fn main() -> eyre::Result<()> { .format_timestamp_micros() // Disable most spamming modules .filter_module("cranelift_codegen", LevelFilter::Off) - .filter_module("wasmer_wasi_fl", LevelFilter::Off) .filter_module("walrus", LevelFilter::Off) - .filter_module("wasmer_interface_types_fl", LevelFilter::Off) .filter_module("polling", LevelFilter::Off) + .filter_module("wasmer_wasi_fl", LevelFilter::Error) + .filter_module("wasmer_interface_types_fl", LevelFilter::Error) + .filter_module("wasmer_wasi", LevelFilter::Error) .filter_module("tide", LevelFilter::Error) .filter_module("tokio_threadpool", LevelFilter::Error) .filter_module("tokio_reactor", LevelFilter::Error) @@ -79,8 +80,6 @@ async fn main() -> eyre::Result<()> { .filter_module("soketto", LevelFilter::Error) .filter_module("cranelift_codegen", LevelFilter::Error) .filter_module("async_io", LevelFilter::Error) - .filter_module("wasmer_interface_types_fl", LevelFilter::Error) - .filter_module("wasmer_wasi", LevelFilter::Error) .init(); let version = format!("{}; AIR version {}", VERSION, air_interpreter_wasm::VERSION); From 720c829317643fab6b9e3b538340c6c273eb5881 Mon Sep 17 00:00:00 2001 From: folex <0xdxdy@gmail.com> Date: Wed, 29 Mar 2023 10:28:26 -0300 Subject: [PATCH 5/5] chore: set error loglevel for tracing, avm_server --- particle-node/src/main.rs | 2 ++ 1 file changed, 2 insertions(+) diff --git a/particle-node/src/main.rs b/particle-node/src/main.rs index b4b568e3ae..6fe6bef8ba 100644 --- a/particle-node/src/main.rs +++ b/particle-node/src/main.rs @@ -80,6 +80,8 @@ async fn main() -> eyre::Result<()> { .filter_module("soketto", LevelFilter::Error) .filter_module("cranelift_codegen", LevelFilter::Error) .filter_module("async_io", LevelFilter::Error) + .filter_module("tracing", LevelFilter::Error) + .filter_module("avm_server::runner", LevelFilter::Error) .init(); let version = format!("{}; AIR version {}", VERSION, air_interpreter_wasm::VERSION);