diff --git a/swap/src/bin/swap.rs b/swap/src/bin/swap.rs index d8f25304..881aa749 100644 --- a/swap/src/bin/swap.rs +++ b/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 tracing_subscriber::fmt::MakeWriter; + use swap::tracing_ext::capture_logs; + 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>>>, - } - - impl io::Write for CapturingWriter { - fn write(&mut self, buf: &[u8]) -> io::Result { - self.captured.lock().unwrap().write(buf) - } - - fn flush(&mut self) -> io::Result<()> { - Ok(()) - } - } - struct MaxGiveable { amounts: Vec, call_counter: usize, diff --git a/swap/src/bitcoin/wallet.rs b/swap/src/bitcoin/wallet.rs index 7eb63794..a45e1a84 100644 --- a/swap/src/bitcoin/wallet.rs +++ b/swap/src/bitcoin/wallet.rs @@ -149,16 +149,7 @@ impl Wallet { } }; - match (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); + last_status = Some(print_status_change(txid, last_status, 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, 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) + } } diff --git a/swap/src/lib.rs b/swap/src/lib.rs index 9308b571..64c8ffe9 100644 --- a/swap/src/lib.rs +++ b/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; diff --git a/swap/src/tracing_ext.rs b/swap/src/tracing_ext.rs new file mode 100644 index 00000000..912187fd --- /dev/null +++ b/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>>>, +} + +impl io::Write for CapturingWriter { + fn write(&mut self, buf: &[u8]) -> io::Result { + self.captured.lock().unwrap().write(buf) + } + + fn flush(&mut self) -> io::Result<()> { + Ok(()) + } +}