Merge pull request #3271 from golemfactory/improve-logs-readability

Improve logs

core/payment/Cargo.toml

@@ -58,6 +58,7 @@ structopt = "0.3"
 strum = { workspace = true }
 thiserror = "1.0"
 tokio = { version = "1", features = ["fs", "signal", "macros"] }
+tracing = { version = "0.1.40", features = ["log"] }
 uint = "0.7"
 uuid = { version = "0.8", features = ["v4"] }
 

core/payment/src/service.rs

@@ -52,6 +52,7 @@ mod local {
     use std::sync::atomic::{AtomicUsize, Ordering};
     use std::time::Instant;
     use std::{collections::BTreeMap, convert::TryInto};
+    use tracing::{debug, trace};
     use ya_client_model::{
         payment::{
             Account, DebitNoteEventType, DocumentStatus, DriverDetails, DriverStatusProperty,
@@ -138,9 +139,20 @@ mod local {
         sender: String,
         msg: SchedulePayment,
     ) -> Result<(), GenericError> {
-        log::debug!("Schedule payment processor started");
+        let id = msg.document_id();
+        debug!(
+            entity = "payment",
+            action = "schedule",
+            id,
+            "Schedule payment started"
+        );
         let res = processor.schedule_payment(msg).await;
-        log::debug!("Schedule payment processor finished");
+        trace!(
+            entity = "payment",
+            action = "schedule",
+            id,
+            "Schedule payment finished"
+        );
         Ok(res?)
     }
 
@@ -150,9 +162,20 @@ mod local {
         sender: String,
         msg: RegisterDriver,
     ) -> Result<(), RegisterDriverError> {
-        log::debug!("Register driver processor started");
+        let driver = msg.driver_name.clone();
+        debug!(
+            entity = "driver",
+            action = "register",
+            driver,
+            "Register driver started"
+        );
         let res = processor.register_driver(msg).await;
-        log::debug!("Register driver processor finished");
+        trace!(
+            entity = "driver",
+            action = "register",
+            driver,
+            "Register driver finished"
+        );
         res
     }
 
@@ -162,10 +185,20 @@ mod local {
         sender: String,
         msg: UnregisterDriver,
     ) -> Result<(), UnregisterDriverError> {
-        log::debug!("Unregister driver processor started");
+        let driver = msg.0.clone();
+        debug!(
+            entity = "driver",
+            action = "unregister",
+            driver,
+            "Unregister driver started"
+        );
         let res = processor.unregister_driver(msg).await;
-        log::debug!("Unregister driver processor finished");
-
+        trace!(
+            entity = "driver",
+            action = "unregister",
+            driver,
+            "Unregister driver finished"
+        );
         res
     }
 
@@ -175,9 +208,23 @@ mod local {
         sender: String,
         msg: RegisterAccount,
     ) -> Result<(), RegisterAccountError> {
-        log::debug!("Register account processor started");
+        let platform = format!("{}-{}-{}", &msg.driver, &msg.network, &msg.token);
+        let account = msg.address.clone();
+        debug!(
+            entity = "account",
+            action = "register",
+            account,
+            platform,
+            "Register account started"
+        );
         let res = processor.register_account(msg).await;
-        log::debug!("Register account processor finished");
+        trace!(
+            entity = "account",
+            action = "register",
+            account,
+            platform,
+            "Register account finished"
+        );
         res
     }
 
@@ -187,9 +234,20 @@ mod local {
         sender: String,
         msg: UnregisterAccount,
     ) -> Result<(), UnregisterAccountError> {
-        log::debug!("Unregister account processor started");
+        let account = msg.address.clone();
+        debug!(
+            entity = "account",
+            action = "unregister",
+            account,
+            "Unregister account started"
+        );
         processor.unregister_account(msg).await?;
-        log::debug!("Unregister account processor finished");
+        trace!(
+            entity = "account",
+            action = "unregister",
+            account,
+            "Unregister account finished"
+        );
         Ok(())
     }
 
@@ -199,9 +257,9 @@ mod local {
         sender: String,
         msg: GetAccounts,
     ) -> Result<Vec<Account>, GetAccountsError> {
-        log::debug!("Get accounts processor started");
+        trace!(entity = "accounts", action = "get", "Get accounts started");
         let res = processor.get_accounts().await;
-        log::debug!("Get accounts processor finished");
+        trace!(entity = "accounts", action = "get", "Get accounts finished");
         res
     }
 
@@ -215,12 +273,26 @@ mod local {
         let i = NOTIFY_COUNTER.fetch_add(1, Ordering::Relaxed);
         let start = Instant::now();
 
-        log::debug!("Notify payment no. {i} processor started");
-        let res = processor.notify_payment(msg).await;
-        log::debug!(
-            "Notify payment no. {} processor finished after {:.2}s",
-            i,
-            start.elapsed().as_secs_f32()
+        debug!(
+            entity = "payment",
+            action = "notify",
+            sender = msg.sender,
+            recipient = msg.recipient,
+            no = i,
+            "Notify payment started"
+        );
+        let res = processor.notify_payment(msg.clone()).await;
+
+        debug!(
+            entity = "payment",
+            action = "notify",
+            sender = msg.sender,
+            recipient = msg.recipient,
+            no = i,
+            duration = format!(
+                "Notify payment finished after {:.2}s",
+                start.elapsed().as_secs_f32()
+            )
         );
 
         Ok(res?)

utils/actix_utils/Cargo.toml

@@ -14,6 +14,8 @@ chrono = "^0.4"
 futures = "^0.3"
 log = "0.4"
 
+ya-std-utils = { path = "../std-utils" }
+
 [dev-dependencies]
 actix-rt = "2.7"
 tokio = { version = "1", features = ["process", "signal"] }

utils/actix_utils/src/deadline_checker.rs

@@ -5,6 +5,8 @@ use futures::Future;
 use std::collections::HashMap;
 use std::pin::Pin;
 
+use ya_std_utils::LogErr;
+
 use crate::{
     actix_signal::{SignalSlot, Subscribe},
     actix_signal_handler,
@@ -104,7 +106,7 @@ impl DeadlineChecker {
         }
 
         self.handle.take();
-        self.update_deadline(ctx).ok();
+        self.update_deadline(ctx).log_err().ok();
     }
 
     fn drain_elapsed(&mut self, timestamp: DateTime<Utc>) -> Vec<DeadlineElapsed> {
@@ -155,10 +157,7 @@ impl DeadlineChecker {
             })
             .min();
 
-        match nearest {
-            Some(deadline) => deadline,
-            None => Utc::now() + Duration::weeks(50),
-        }
+        nearest.unwrap_or_else(|| Utc::now() + Duration::weeks(50))
     }
 }
 
@@ -187,7 +186,7 @@ impl Handler<TrackDeadline> for DeadlineChecker {
             },
         );
 
-        self.update_deadline(ctx).unwrap();
+        self.update_deadline(ctx).log_err().ok();
     }
 }
 
@@ -207,7 +206,7 @@ impl Handler<StopTracking> for DeadlineChecker {
         }
 
         if any {
-            self.update_deadline(ctx).unwrap();
+            self.update_deadline(ctx).log_err().ok();
         }
     }
 }
@@ -217,7 +216,7 @@ impl Handler<StopTrackingCategory> for DeadlineChecker {
 
     fn handle(&mut self, msg: StopTrackingCategory, ctx: &mut Context<Self>) -> Self::Result {
         if self.deadlines.remove(&msg.category).is_some() {
-            self.update_deadline(ctx).unwrap()
+            self.update_deadline(ctx).log_err().ok();
         }
     }
 }