Added possibility of tracing db locks

There is some suspicious behavior during payment processing that needs to be resolved on production.

core/payment/src/timeout_lock.rs

@@ -1,18 +1,58 @@
 use std::time::Duration;
 
-use futures::Future;
+use futures::{Future, FutureExt};
+use tokio::time::error::Elapsed;
+use tokio::time::Instant;
 use tokio::{
     sync::{Mutex, MutexGuard, RwLock, RwLockReadGuard, RwLockWriteGuard},
     time::Timeout,
 };
 
 pub trait MutexTimeoutExt<T: ?Sized + 'static> {
-    fn timeout_lock(&self, duration: Duration) -> Timeout<impl Future<Output = MutexGuard<'_, T>>>;
+    fn timeout_lock(
+        &self,
+        duration: Duration,
+    ) -> impl Future<Output = Result<MutexGuard<'_, T>, Elapsed>>;
 }
-
+static ID: std::sync::atomic::AtomicUsize = std::sync::atomic::AtomicUsize::new(0);
 impl<T: ?Sized + 'static> MutexTimeoutExt<T> for Mutex<T> {
-    fn timeout_lock(&self, duration: Duration) -> Timeout<impl Future<Output = MutexGuard<'_, T>>> {
-        tokio::time::timeout(duration, self.lock())
+    #[track_caller]
+    fn timeout_lock(
+        &self,
+        duration: Duration,
+    ) -> impl Future<Output = Result<MutexGuard<'_, T>, Elapsed>> {
+        let caller_location = std::panic::Location::caller();
+        let caller_line_number = caller_location.line();
+        let caller_file = caller_location.file();
+
+        let next_id = ID.fetch_add(1, std::sync::atomic::Ordering::SeqCst);
+
+        let caller = format!("{}:{}", caller_file, caller_line_number);
+        log::trace!("Timeout lock {next_id} requested from {caller}");
+        let curr = Instant::now();
+        tokio::time::timeout(duration, self.lock()).then(move |result| {
+            let elapsed_ms = curr.elapsed().as_secs_f64() / 1000.0;
+            let duration_ms = duration.as_secs_f64() * 1000.0;
+            match &result {
+                Ok(guard) => {
+                    if elapsed_ms > duration_ms / 2.0 {
+                        log::warn!(
+                            "Timeout lock {next_id} acquired after {elapsed_ms:.0}ms by {caller}"
+                        );
+                    } else {
+                        log::trace!(
+                            "Timeout lock {next_id} acquired after {elapsed_ms:.2}ms by {caller}"
+                        );
+                    }
+                }
+                Err(_) => {
+                    log::error!(
+                        "Timeout lock {next_id} timed out after {elapsed_ms:.0}ms for {caller}"
+                    );
+                }
+            };
+            futures::future::ready(result)
+        })
     }
 }
 

core/serv/src/main.rs

@@ -503,6 +503,13 @@ impl ServiceCommand {
                         "info,actix_web::middleware::logger=warn,sqlx=warn".to_string()
                     }),
                 );
+                if env::var("YAGNA_TRACE_DB_LOCKS") == Ok("1".to_string()) {
+                    env::set_var(
+                        "RUST_LOG",
+                        env::var("RUST_LOG").unwrap_or("info".to_string())
+                            + ",ya_payment::timeout_lock=trace",
+                    );
+                }
 
                 //this force_debug flag sets default log level to debug
                 //if the --debug option is set