Merge #618

618: Don't spam on transaction status change r=da-kami a=thomaseizinger



Co-authored-by: Thomas Eizinger <thomas@eizinger.io>

swap/src/bin/swap.rs

@@ -483,14 +483,13 @@ mod tests {
     use super::*;
     use crate::determine_btc_to_swap;
     use ::bitcoin::Amount;
-    use std::io;
     use std::sync::Mutex;
-    use tracing::subscriber;
+    use swap::tracing_ext::capture_logs;
-    use tracing_subscriber::fmt::MakeWriter;
+    use tracing::level_filters::LevelFilter;
 
     #[tokio::test]
     async fn given_no_balance_and_transfers_less_than_max_swaps_max_giveable() {
-        let writer = capture_logs();
+        let writer = capture_logs(LevelFilter::INFO);
         let givable = Arc::new(Mutex::new(MaxGiveable::new(vec![
             Amount::ZERO,
             Amount::from_btc(0.0009).unwrap(),
@@ -525,7 +524,7 @@ mod tests {
 
     #[tokio::test]
     async fn given_no_balance_and_transfers_more_then_swaps_max_quantity_from_quote() {
-        let writer = capture_logs();
+        let writer = capture_logs(LevelFilter::INFO);
         let givable = Arc::new(Mutex::new(MaxGiveable::new(vec![
             Amount::ZERO,
             Amount::from_btc(0.1).unwrap(),
@@ -560,7 +559,7 @@ mod tests {
 
     #[tokio::test]
     async fn given_initial_balance_below_max_quantity_swaps_max_givable() {
-        let writer = capture_logs();
+        let writer = capture_logs(LevelFilter::INFO);
         let givable = Arc::new(Mutex::new(MaxGiveable::new(vec![
             Amount::from_btc(0.0049).unwrap(),
             Amount::from_btc(99.9).unwrap(),
@@ -593,7 +592,7 @@ mod tests {
 
     #[tokio::test]
     async fn given_initial_balance_above_max_quantity_swaps_max_quantity() {
-        let writer = capture_logs();
+        let writer = capture_logs(LevelFilter::INFO);
         let givable = Arc::new(Mutex::new(MaxGiveable::new(vec![
             Amount::from_btc(0.1).unwrap(),
             Amount::from_btc(99.9).unwrap(),
@@ -626,7 +625,7 @@ mod tests {
 
     #[tokio::test]
     async fn given_no_initial_balance_then_min_wait_for_sufficient_deposit() {
-        let writer = capture_logs();
+        let writer = capture_logs(LevelFilter::INFO);
         let givable = Arc::new(Mutex::new(MaxGiveable::new(vec![
             Amount::ZERO,
             Amount::from_btc(0.01).unwrap(),
@@ -661,7 +660,7 @@ mod tests {
 
     #[tokio::test]
     async fn given_balance_less_then_min_wait_for_sufficient_deposit() {
-        let writer = capture_logs();
+        let writer = capture_logs(LevelFilter::INFO);
         let givable = Arc::new(Mutex::new(MaxGiveable::new(vec![
             Amount::from_btc(0.0001).unwrap(),
             Amount::from_btc(0.01).unwrap(),
@@ -696,7 +695,7 @@ mod tests {
 
     #[tokio::test]
     async fn given_no_initial_balance_and_transfers_less_than_min_keep_waiting() {
-        let writer = capture_logs();
+        let writer = capture_logs(LevelFilter::INFO);
         let givable = Arc::new(Mutex::new(MaxGiveable::new(vec![
             Amount::ZERO,
             Amount::from_btc(0.01).unwrap(),
@@ -736,7 +735,7 @@ mod tests {
 
     #[tokio::test]
     async fn given_longer_delay_until_deposit_should_not_spam_user() {
-        let writer = capture_logs();
+        let writer = capture_logs(LevelFilter::INFO);
         let givable = Arc::new(Mutex::new(MaxGiveable::new(vec![
             Amount::ZERO,
             Amount::ZERO,
@@ -778,63 +777,6 @@ mod tests {
         );
     }
 
-    /// Setup tracing with a capturing writer, allowing assertions on the log
-    /// messages.
-    ///
-    /// Time and ANSI are disabled to make the output more predictable and
-    /// readable.
-    fn capture_logs() -> MakeCapturingWriter {
-        let make_writer = MakeCapturingWriter::default();
-
-        let guard = subscriber::set_default(
-            tracing_subscriber::fmt()
-                .with_ansi(false)
-                .without_time()
-                .with_writer(make_writer.clone())
-                .finish(),
-        );
-        // don't clean up guard we stay initialized
-        std::mem::forget(guard);
-
-        make_writer
-    }
-
-    #[derive(Default, Clone)]
-    struct MakeCapturingWriter {
-        writer: CapturingWriter,
-    }
-
-    impl MakeCapturingWriter {
-        fn captured(&self) -> String {
-            let captured = &self.writer.captured;
-            let cursor = captured.lock().unwrap();
-            String::from_utf8(cursor.clone().into_inner()).unwrap()
-        }
-    }
-
-    impl MakeWriter for MakeCapturingWriter {
-        type Writer = CapturingWriter;
-
-        fn make_writer(&self) -> Self::Writer {
-            self.writer.clone()
-        }
-    }
-
-    #[derive(Default, Clone)]
-    struct CapturingWriter {
-        captured: Arc<Mutex<io::Cursor<Vec<u8>>>>,
-    }
-
-    impl io::Write for CapturingWriter {
-        fn write(&mut self, buf: &[u8]) -> io::Result<usize> {
-            self.captured.lock().unwrap().write(buf)
-        }
-
-        fn flush(&mut self) -> io::Result<()> {
-            Ok(())
-        }
-    }
-
     struct MaxGiveable {
         amounts: Vec<Amount>,
         call_counter: usize,

swap/src/bitcoin/wallet.rs

@@ -149,16 +149,7 @@ impl Wallet {
                             }
                         };
 
-                        match (last_status, new_status) {
+                        last_status = Some(print_status_change(txid, last_status, new_status));
-                            (None, new_status) => {
-                                tracing::debug!(%txid, status = %new_status, "Found relevant Bitcoin transaction");
-                            },
-                            (Some(old_status), new_status) => {
-                                tracing::debug!(%txid, %new_status, %old_status, "Bitcoin transaction status changed");
-                            }
-                        }
-
-                        last_status = Some(new_status);
 
                         let all_receivers_gone = sender.send(new_status).is_err();
 
@@ -182,6 +173,20 @@ impl Wallet {
     }
 }
 
+fn print_status_change(txid: Txid, old: Option<ScriptStatus>, new: ScriptStatus) -> ScriptStatus {
+    match (old, new) {
+        (None, new_status) => {
+            tracing::debug!(%txid, status = %new_status, "Found relevant Bitcoin transaction");
+        }
+        (Some(old_status), new_status) if old_status != new_status => {
+            tracing::debug!(%txid, %new_status, %old_status, "Bitcoin transaction status changed");
+        }
+        _ => {}
+    }
+
+    new
+}
+
 /// Represents a subscription to the status of a given transaction.
 #[derive(Debug, Clone)]
 pub struct Subscription {
@@ -850,7 +855,9 @@ impl fmt::Display for ScriptStatus {
 mod tests {
     use super::*;
     use crate::bitcoin::{PublicKey, TxLock};
+    use crate::tracing_ext::capture_logs;
     use proptest::prelude::*;
+    use tracing::level_filters::LevelFilter;
 
     #[test]
     fn given_depth_0_should_meet_confirmation_target_one() {
@@ -1124,4 +1131,38 @@ mod tests {
             _ => panic!("expected exactly two outputs"),
         }
     }
+
+    #[test]
+    fn printing_status_change_doesnt_spam_on_same_status() {
+        let writer = capture_logs(LevelFilter::DEBUG);
+
+        let tx = Txid::default();
+        let mut old = None;
+        old = Some(print_status_change(tx, old, ScriptStatus::Unseen));
+        old = Some(print_status_change(tx, old, ScriptStatus::InMempool));
+        old = Some(print_status_change(tx, old, ScriptStatus::InMempool));
+        old = Some(print_status_change(tx, old, ScriptStatus::InMempool));
+        old = Some(print_status_change(tx, old, ScriptStatus::InMempool));
+        old = Some(print_status_change(tx, old, ScriptStatus::InMempool));
+        old = Some(print_status_change(tx, old, ScriptStatus::InMempool));
+        old = Some(print_status_change(tx, old, confs(1)));
+        old = Some(print_status_change(tx, old, confs(2)));
+        old = Some(print_status_change(tx, old, confs(3)));
+        old = Some(print_status_change(tx, old, confs(3)));
+        print_status_change(tx, old, confs(3));
+
+        assert_eq!(
+            writer.captured(),
+            r"DEBUG swap::bitcoin::wallet: Found relevant Bitcoin transaction txid=0000000000000000000000000000000000000000000000000000000000000000 status=unseen
+DEBUG swap::bitcoin::wallet: Bitcoin transaction status changed txid=0000000000000000000000000000000000000000000000000000000000000000 new_status=in mempool old_status=unseen
+DEBUG swap::bitcoin::wallet: Bitcoin transaction status changed txid=0000000000000000000000000000000000000000000000000000000000000000 new_status=confirmed with 1 blocks old_status=in mempool
+DEBUG swap::bitcoin::wallet: Bitcoin transaction status changed txid=0000000000000000000000000000000000000000000000000000000000000000 new_status=confirmed with 2 blocks old_status=confirmed with 1 blocks
+DEBUG swap::bitcoin::wallet: Bitcoin transaction status changed txid=0000000000000000000000000000000000000000000000000000000000000000 new_status=confirmed with 3 blocks old_status=confirmed with 2 blocks
+"
+        )
+    }
+
+    fn confs(confirmations: u32) -> ScriptStatus {
+        ScriptStatus::from_confirmations(confirmations)
+    }
 }

swap/src/lib.rs

@@ -29,5 +29,6 @@ pub mod network;
 pub mod protocol;
 pub mod seed;
 pub mod tor;
+pub mod tracing_ext;
 
 mod monero_ext;

swap/src/tracing_ext.rs

@@ -0,0 +1,65 @@
+#![allow(clippy::unwrap_used)] // This is only meant to be used in tests.
+
+use std::io;
+use std::sync::{Arc, Mutex};
+use tracing::subscriber;
+use tracing_subscriber::filter::LevelFilter;
+use tracing_subscriber::fmt::MakeWriter;
+
+/// Setup tracing with a capturing writer, allowing assertions on the log
+/// messages.
+///
+/// Time and ANSI are disabled to make the output more predictable and
+/// readable.
+pub fn capture_logs(min_level: LevelFilter) -> MakeCapturingWriter {
+    let make_writer = MakeCapturingWriter::default();
+
+    let guard = subscriber::set_default(
+        tracing_subscriber::fmt()
+            .with_ansi(false)
+            .without_time()
+            .with_writer(make_writer.clone())
+            .with_env_filter(format!("{}", min_level))
+            .finish(),
+    );
+    // don't clean up guard we stay initialized
+    std::mem::forget(guard);
+
+    make_writer
+}
+
+#[derive(Default, Clone)]
+pub struct MakeCapturingWriter {
+    writer: CapturingWriter,
+}
+
+impl MakeCapturingWriter {
+    pub fn captured(&self) -> String {
+        let captured = &self.writer.captured;
+        let cursor = captured.lock().unwrap();
+        String::from_utf8(cursor.clone().into_inner()).unwrap()
+    }
+}
+
+impl MakeWriter for MakeCapturingWriter {
+    type Writer = CapturingWriter;
+
+    fn make_writer(&self) -> Self::Writer {
+        self.writer.clone()
+    }
+}
+
+#[derive(Default, Clone)]
+pub struct CapturingWriter {
+    captured: Arc<Mutex<io::Cursor<Vec<u8>>>>,
+}
+
+impl io::Write for CapturingWriter {
+    fn write(&mut self, buf: &[u8]) -> io::Result<usize> {
+        self.captured.lock().unwrap().write(buf)
+    }
+
+    fn flush(&mut self) -> io::Result<()> {
+        Ok(())
+    }
+}