feat(logs)!: reduce logs (#1534)

* feat(log): log particle_id in service calls, set different log level by service name

* feat(log): disable some log namespaces

* feat(log): enable some log namespaces back, disable others

It's better to manage that through ENV vars

* chore: log levels

* chore: set error loglevel for tracing, avm_server

---------

Co-authored-by: Aleksey Proshutisnkiy <justprosh@users.noreply.github.com>

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,

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;

aquamarine/src/log.rs

@@ -0,0 +1,10 @@
+/// 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" | "run-console" => {
+            log::Level::Debug
+        }
+        "peer" | "script" | "stat" | "sig" | "srv" | "dist" | "kad" => log::Level::Info,
+        _ => log::Level::Info,
+    }
+}

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<F: ParticleFunctionStatic> Functions<F> {
     }
 
     /// 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<F: ParticleFunctionStatic> Functions<F> {
     //       maybe it's a good option.
     fn call(
         &self,
+        particle_id: String,
         call_id: u32,
         call: CallRequestParams,
         waker: Waker,
@@ -142,6 +147,7 @@ impl<F: ParticleFunctionStatic> Functions<F> {
         };
 
         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<F: ParticleFunctionStatic> Functions<F> {
             };
 
             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 {

particle-node/src/main.rs

@@ -67,7 +67,21 @@ 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("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)
+        .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("tracing", LevelFilter::Error)
+        .filter_module("avm_server::runner", LevelFilter::Error)
         .init();
 
     let version = format!("{}; AIR version {}", VERSION, air_interpreter_wasm::VERSION);