From a347dd8b979b27e61988d9699773253166716ebc Mon Sep 17 00:00:00 2001 From: Thomas Eizinger Date: Thu, 8 Jul 2021 11:15:14 +1000 Subject: [PATCH 1/5] Move helper structs below tests --- swap/src/bin/swap.rs | 44 ++++++++++++++++++++++---------------------- 1 file changed, 22 insertions(+), 22 deletions(-) diff --git a/swap/src/bin/swap.rs b/swap/src/bin/swap.rs index 5c39af1d..f14c5ef9 100644 --- a/swap/src/bin/swap.rs +++ b/swap/src/bin/swap.rs @@ -492,28 +492,6 @@ mod tests { use super::*; - struct MaxGiveable { - amounts: Vec, - call_counter: usize, - } - - impl MaxGiveable { - fn new(amounts: Vec) -> Self { - Self { - amounts, - call_counter: 0, - } - } - fn give(&mut self) -> Result { - let amount = self - .amounts - .get(self.call_counter) - .ok_or_else(|| anyhow::anyhow!("No more balances available"))?; - self.call_counter += 1; - Ok(*amount) - } - } - #[tokio::test] async fn given_no_balance_and_transfers_less_than_max_swaps_max_giveable() { let _guard = subscriber::set_default(tracing_subscriber::fmt().with_test_writer().finish()); @@ -712,6 +690,28 @@ mod tests { assert!(matches!(error, tokio::time::error::Elapsed { .. })) } + struct MaxGiveable { + amounts: Vec, + call_counter: usize, + } + + impl MaxGiveable { + fn new(amounts: Vec) -> Self { + Self { + amounts, + call_counter: 0, + } + } + fn give(&mut self) -> Result { + let amount = self + .amounts + .get(self.call_counter) + .ok_or_else(|| anyhow::anyhow!("No more balances available"))?; + self.call_counter += 1; + Ok(*amount) + } + } + fn quote_with_max(btc: f64) -> BidQuote { BidQuote { price: Amount::from_btc(0.001).unwrap(), From 56ea23c2a369b54b2419054d0551a04c324d8b49 Mon Sep 17 00:00:00 2001 From: Thomas Eizinger Date: Thu, 8 Jul 2021 11:50:37 +1000 Subject: [PATCH 2/5] Assert log output for `determine_btc_to_swap` --- swap/src/bin/swap.rs | 144 +++++++++++++++++++++++++++++++++++++------ 1 file changed, 124 insertions(+), 20 deletions(-) diff --git a/swap/src/bin/swap.rs b/swap/src/bin/swap.rs index f14c5ef9..1ac76ea7 100644 --- a/swap/src/bin/swap.rs +++ b/swap/src/bin/swap.rs @@ -483,18 +483,17 @@ where #[cfg(test)] mod tests { - use std::sync::Mutex; - + use super::*; + use crate::determine_btc_to_swap; use ::bitcoin::Amount; + use std::io; + use std::sync::Mutex; use tracing::subscriber; - - use crate::determine_btc_to_swap; - - use super::*; + use tracing_subscriber::fmt::MakeWriter; #[tokio::test] async fn given_no_balance_and_transfers_less_than_max_swaps_max_giveable() { - let _guard = subscriber::set_default(tracing_subscriber::fmt().with_test_writer().finish()); + let writer = capture_logs(); let givable = Arc::new(Mutex::new(MaxGiveable::new(vec![ Amount::ZERO, Amount::from_btc(0.0009).unwrap(), @@ -517,11 +516,19 @@ mod tests { let expected_amount = Amount::from_btc(0.0009).unwrap(); let expected_fees = Amount::from_btc(0.0001).unwrap(); - assert_eq!((amount, fees), (expected_amount, expected_fees)) + assert_eq!((amount, fees), (expected_amount, expected_fees)); + assert_eq!( + writer.captured(), + r" INFO swap: Received quote: 1 XMR ~ price=0.00100000 BTC minimum_amount=0.00000000 BTC maximum_amount=0.01000000 BTC + INFO swap: Waiting for Bitcoin deposit deposit_address=1PdfytjS7C8wwd9Lq5o4x9aXA2YRqaCpH6 max_giveable=0.00000000 BTC minimum_amount=0.00000000 BTC maximum_amount=0.01000000 BTC + INFO swap: Received Bitcoin new_balance=0.00100000 BTC max_giveable=0.00090000 BTC +" + ); } + #[tokio::test] async fn given_no_balance_and_transfers_more_then_swaps_max_quantity_from_quote() { - let _guard = subscriber::set_default(tracing_subscriber::fmt().with_test_writer().finish()); + let writer = capture_logs(); let givable = Arc::new(Mutex::new(MaxGiveable::new(vec![ Amount::ZERO, Amount::from_btc(0.1).unwrap(), @@ -544,12 +551,19 @@ mod tests { let expected_amount = Amount::from_btc(0.01).unwrap(); let expected_fees = Amount::from_btc(0.0001).unwrap(); - assert_eq!((amount, fees), (expected_amount, expected_fees)) + assert_eq!((amount, fees), (expected_amount, expected_fees)); + assert_eq!( + writer.captured(), + r" INFO swap: Received quote: 1 XMR ~ price=0.00100000 BTC minimum_amount=0.00000000 BTC maximum_amount=0.01000000 BTC + INFO swap: Waiting for Bitcoin deposit deposit_address=1PdfytjS7C8wwd9Lq5o4x9aXA2YRqaCpH6 max_giveable=0.00000000 BTC minimum_amount=0.00000000 BTC maximum_amount=0.01000000 BTC + INFO swap: Received Bitcoin new_balance=0.10010000 BTC max_giveable=0.10000000 BTC +" + ); } #[tokio::test] async fn given_initial_balance_below_max_quantity_swaps_max_givable() { - let _guard = subscriber::set_default(tracing_subscriber::fmt().with_test_writer().finish()); + let writer = capture_logs(); let givable = Arc::new(Mutex::new(MaxGiveable::new(vec![ Amount::from_btc(0.0049).unwrap(), Amount::from_btc(99.9).unwrap(), @@ -572,12 +586,17 @@ mod tests { let expected_amount = Amount::from_btc(0.0049).unwrap(); let expected_fees = Amount::from_btc(0.0001).unwrap(); - assert_eq!((amount, fees), (expected_amount, expected_fees)) + assert_eq!((amount, fees), (expected_amount, expected_fees)); + assert_eq!( + writer.captured(), + r" INFO swap: Received quote: 1 XMR ~ price=0.00100000 BTC minimum_amount=0.00000000 BTC maximum_amount=0.01000000 BTC +" + ); } #[tokio::test] async fn given_initial_balance_above_max_quantity_swaps_max_quantity() { - let _guard = subscriber::set_default(tracing_subscriber::fmt().with_test_writer().finish()); + let writer = capture_logs(); let givable = Arc::new(Mutex::new(MaxGiveable::new(vec![ Amount::from_btc(0.1).unwrap(), Amount::from_btc(99.9).unwrap(), @@ -600,12 +619,17 @@ mod tests { let expected_amount = Amount::from_btc(0.01).unwrap(); let expected_fees = Amount::from_btc(0.0001).unwrap(); - assert_eq!((amount, fees), (expected_amount, expected_fees)) + assert_eq!((amount, fees), (expected_amount, expected_fees)); + assert_eq!( + writer.captured(), + r" INFO swap: Received quote: 1 XMR ~ price=0.00100000 BTC minimum_amount=0.00000000 BTC maximum_amount=0.01000000 BTC +" + ); } #[tokio::test] async fn given_no_initial_balance_then_min_wait_for_sufficient_deposit() { - let _guard = subscriber::set_default(tracing_subscriber::fmt().with_test_writer().finish()); + let writer = capture_logs(); let givable = Arc::new(Mutex::new(MaxGiveable::new(vec![ Amount::ZERO, Amount::from_btc(0.01).unwrap(), @@ -628,12 +652,19 @@ mod tests { let expected_amount = Amount::from_btc(0.01).unwrap(); let expected_fees = Amount::from_btc(0.0001).unwrap(); - assert_eq!((amount, fees), (expected_amount, expected_fees)) + assert_eq!((amount, fees), (expected_amount, expected_fees)); + assert_eq!( + writer.captured(), + r" INFO swap: Received quote: 1 XMR ~ price=0.00100000 BTC minimum_amount=0.01000000 BTC maximum_amount=184467440737.09551615 BTC + INFO swap: Waiting for Bitcoin deposit deposit_address=1PdfytjS7C8wwd9Lq5o4x9aXA2YRqaCpH6 max_giveable=0.00000000 BTC minimum_amount=0.01000000 BTC maximum_amount=184467440737.09551615 BTC + INFO swap: Received Bitcoin new_balance=0.01010000 BTC max_giveable=0.01000000 BTC +" + ); } #[tokio::test] async fn given_balance_less_then_min_wait_for_sufficient_deposit() { - let _guard = subscriber::set_default(tracing_subscriber::fmt().with_test_writer().finish()); + let writer = capture_logs(); let givable = Arc::new(Mutex::new(MaxGiveable::new(vec![ Amount::from_btc(0.0001).unwrap(), Amount::from_btc(0.01).unwrap(), @@ -656,12 +687,19 @@ mod tests { let expected_amount = Amount::from_btc(0.01).unwrap(); let expected_fees = Amount::from_btc(0.0001).unwrap(); - assert_eq!((amount, fees), (expected_amount, expected_fees)) + assert_eq!((amount, fees), (expected_amount, expected_fees)); + assert_eq!( + writer.captured(), + r" INFO swap: Received quote: 1 XMR ~ price=0.00100000 BTC minimum_amount=0.01000000 BTC maximum_amount=184467440737.09551615 BTC + INFO swap: Waiting for Bitcoin deposit deposit_address=1PdfytjS7C8wwd9Lq5o4x9aXA2YRqaCpH6 max_giveable=0.00010000 BTC minimum_amount=0.01000000 BTC maximum_amount=184467440737.09551615 BTC + INFO swap: Received Bitcoin new_balance=0.01010000 BTC max_giveable=0.01000000 BTC +" + ); } #[tokio::test] async fn given_no_initial_balance_and_transfers_less_than_min_keep_waiting() { - let _guard = subscriber::set_default(tracing_subscriber::fmt().with_test_writer().finish()); + let writer = capture_logs(); let givable = Arc::new(Mutex::new(MaxGiveable::new(vec![ Amount::ZERO, Amount::from_btc(0.01).unwrap(), @@ -687,7 +725,73 @@ mod tests { .await .unwrap_err(); - assert!(matches!(error, tokio::time::error::Elapsed { .. })) + assert!(matches!(error, tokio::time::error::Elapsed { .. })); + assert_eq!( + writer.captured(), + r" INFO swap: Received quote: 1 XMR ~ price=0.00100000 BTC minimum_amount=0.10000000 BTC maximum_amount=184467440737.09551615 BTC + INFO swap: Waiting for Bitcoin deposit deposit_address=1PdfytjS7C8wwd9Lq5o4x9aXA2YRqaCpH6 max_giveable=0.00000000 BTC minimum_amount=0.10000000 BTC maximum_amount=184467440737.09551615 BTC + INFO swap: Received Bitcoin new_balance=0.01010000 BTC max_giveable=0.01000000 BTC + INFO swap: Deposited amount is less than `min_quantity` + INFO swap: Waiting for Bitcoin deposit deposit_address=1PdfytjS7C8wwd9Lq5o4x9aXA2YRqaCpH6 max_giveable=0.01000000 BTC minimum_amount=0.10000000 BTC maximum_amount=184467440737.09551615 BTC +" + ); + } + + /// 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 { From 56a48e71ef88c74808f59565552e0f0993d856f0 Mon Sep 17 00:00:00 2001 From: Thomas Eizinger Date: Thu, 8 Jul 2021 12:12:55 +1000 Subject: [PATCH 3/5] Add failing test that shows spamming of output --- swap/src/bin/swap.rs | 44 ++++++++++++++++++++++++++++++++++++++++++++ 1 file changed, 44 insertions(+) diff --git a/swap/src/bin/swap.rs b/swap/src/bin/swap.rs index 1ac76ea7..d5036dc2 100644 --- a/swap/src/bin/swap.rs +++ b/swap/src/bin/swap.rs @@ -737,6 +737,50 @@ mod tests { ); } + #[tokio::test] + async fn given_longer_delay_until_deposit_should_not_spam_user() { + let writer = capture_logs(); + let givable = Arc::new(Mutex::new(MaxGiveable::new(vec![ + Amount::ZERO, + Amount::ZERO, + Amount::ZERO, + Amount::ZERO, + Amount::ZERO, + Amount::ZERO, + Amount::ZERO, + Amount::ZERO, + Amount::ZERO, + Amount::from_btc(0.2).unwrap(), + ]))); + + tokio::time::timeout( + Duration::from_secs(10), + determine_btc_to_swap( + true, + async { Ok(quote_with_min(0.1)) }, + get_dummy_address(), + || async { Ok(Amount::from_btc(0.21)?) }, + || async { + let mut result = givable.lock().unwrap(); + + result.give() + }, + || async { Ok(()) }, + ), + ) + .await + .unwrap() + .unwrap(); + + assert_eq!( + writer.captured(), + r" INFO swap: Received quote: 1 XMR ~ price=0.00100000 BTC minimum_amount=0.10000000 BTC maximum_amount=184467440737.09551615 BTC + INFO swap: Waiting for Bitcoin deposit deposit_address=1PdfytjS7C8wwd9Lq5o4x9aXA2YRqaCpH6 max_giveable=0.00000000 BTC minimum_amount=0.10000000 BTC maximum_amount=184467440737.09551615 BTC + INFO swap: Received Bitcoin new_balance=0.21000000 BTC max_giveable=0.20000000 BTC +" + ); + } + /// Setup tracing with a capturing writer, allowing assertions on the log /// messages. /// From cacfc50fb217aaee3e0f8e5e5ffc39246552773a Mon Sep 17 00:00:00 2001 From: Thomas Eizinger Date: Thu, 8 Jul 2021 12:14:30 +1000 Subject: [PATCH 4/5] Don't spam the user while waiting for BTC --- swap/src/bin/swap.rs | 30 ++++++++++++++---------------- 1 file changed, 14 insertions(+), 16 deletions(-) diff --git a/swap/src/bin/swap.rs b/swap/src/bin/swap.rs index d5036dc2..1e591f0d 100644 --- a/swap/src/bin/swap.rs +++ b/swap/src/bin/swap.rs @@ -446,28 +446,26 @@ where "Waiting for Bitcoin deposit", ); - sync().await?; + max_giveable = loop { + sync().await?; + let new_max_givable = max_giveable_fn().await?; - let new_max_givable = max_giveable_fn().await?; + if new_max_givable > max_giveable { + break new_max_givable; + } - if new_max_givable != max_giveable { - max_giveable = new_max_givable; + tokio::time::sleep(Duration::from_secs(1)).await; + }; - let new_balance = balance().await?; - tracing::info!( - %new_balance, - %max_giveable, - "Received Bitcoin", - ); + let new_balance = balance().await?; + tracing::info!(%new_balance, %max_giveable, "Received Bitcoin"); - if max_giveable >= bid_quote.min_quantity { - break; - } else { - tracing::info!("Deposited amount is less than `min_quantity`",); - } + if max_giveable < bid_quote.min_quantity { + tracing::info!("Deposited amount is less than `min_quantity`"); + continue; } - tokio::time::sleep(Duration::from_secs(1)).await; + break; } }; From 2c8bbe4913bc094bc973e080aeff5d3ef6d03200 Mon Sep 17 00:00:00 2001 From: Thomas Eizinger Date: Thu, 8 Jul 2021 13:40:11 +1000 Subject: [PATCH 5/5] Remove left-over "half" of log message With the move to using tracing's fields, this log message was not properly updated. --- swap/src/bin/swap.rs | 18 +++++++++--------- 1 file changed, 9 insertions(+), 9 deletions(-) diff --git a/swap/src/bin/swap.rs b/swap/src/bin/swap.rs index 1e591f0d..169b9563 100644 --- a/swap/src/bin/swap.rs +++ b/swap/src/bin/swap.rs @@ -423,7 +423,7 @@ where price = %bid_quote.price, minimum_amount = %bid_quote.min_quantity, maximum_amount = %bid_quote.max_quantity, - "Received quote: 1 XMR ~ ", + "Received quote", ); let mut max_giveable = max_giveable_fn().await?; @@ -517,7 +517,7 @@ mod tests { assert_eq!((amount, fees), (expected_amount, expected_fees)); assert_eq!( writer.captured(), - r" INFO swap: Received quote: 1 XMR ~ price=0.00100000 BTC minimum_amount=0.00000000 BTC maximum_amount=0.01000000 BTC + r" INFO swap: Received quote price=0.00100000 BTC minimum_amount=0.00000000 BTC maximum_amount=0.01000000 BTC INFO swap: Waiting for Bitcoin deposit deposit_address=1PdfytjS7C8wwd9Lq5o4x9aXA2YRqaCpH6 max_giveable=0.00000000 BTC minimum_amount=0.00000000 BTC maximum_amount=0.01000000 BTC INFO swap: Received Bitcoin new_balance=0.00100000 BTC max_giveable=0.00090000 BTC " @@ -552,7 +552,7 @@ mod tests { assert_eq!((amount, fees), (expected_amount, expected_fees)); assert_eq!( writer.captured(), - r" INFO swap: Received quote: 1 XMR ~ price=0.00100000 BTC minimum_amount=0.00000000 BTC maximum_amount=0.01000000 BTC + r" INFO swap: Received quote price=0.00100000 BTC minimum_amount=0.00000000 BTC maximum_amount=0.01000000 BTC INFO swap: Waiting for Bitcoin deposit deposit_address=1PdfytjS7C8wwd9Lq5o4x9aXA2YRqaCpH6 max_giveable=0.00000000 BTC minimum_amount=0.00000000 BTC maximum_amount=0.01000000 BTC INFO swap: Received Bitcoin new_balance=0.10010000 BTC max_giveable=0.10000000 BTC " @@ -587,7 +587,7 @@ mod tests { assert_eq!((amount, fees), (expected_amount, expected_fees)); assert_eq!( writer.captured(), - r" INFO swap: Received quote: 1 XMR ~ price=0.00100000 BTC minimum_amount=0.00000000 BTC maximum_amount=0.01000000 BTC + r" INFO swap: Received quote price=0.00100000 BTC minimum_amount=0.00000000 BTC maximum_amount=0.01000000 BTC " ); } @@ -620,7 +620,7 @@ mod tests { assert_eq!((amount, fees), (expected_amount, expected_fees)); assert_eq!( writer.captured(), - r" INFO swap: Received quote: 1 XMR ~ price=0.00100000 BTC minimum_amount=0.00000000 BTC maximum_amount=0.01000000 BTC + r" INFO swap: Received quote price=0.00100000 BTC minimum_amount=0.00000000 BTC maximum_amount=0.01000000 BTC " ); } @@ -653,7 +653,7 @@ mod tests { assert_eq!((amount, fees), (expected_amount, expected_fees)); assert_eq!( writer.captured(), - r" INFO swap: Received quote: 1 XMR ~ price=0.00100000 BTC minimum_amount=0.01000000 BTC maximum_amount=184467440737.09551615 BTC + r" INFO swap: Received quote price=0.00100000 BTC minimum_amount=0.01000000 BTC maximum_amount=184467440737.09551615 BTC INFO swap: Waiting for Bitcoin deposit deposit_address=1PdfytjS7C8wwd9Lq5o4x9aXA2YRqaCpH6 max_giveable=0.00000000 BTC minimum_amount=0.01000000 BTC maximum_amount=184467440737.09551615 BTC INFO swap: Received Bitcoin new_balance=0.01010000 BTC max_giveable=0.01000000 BTC " @@ -688,7 +688,7 @@ mod tests { assert_eq!((amount, fees), (expected_amount, expected_fees)); assert_eq!( writer.captured(), - r" INFO swap: Received quote: 1 XMR ~ price=0.00100000 BTC minimum_amount=0.01000000 BTC maximum_amount=184467440737.09551615 BTC + r" INFO swap: Received quote price=0.00100000 BTC minimum_amount=0.01000000 BTC maximum_amount=184467440737.09551615 BTC INFO swap: Waiting for Bitcoin deposit deposit_address=1PdfytjS7C8wwd9Lq5o4x9aXA2YRqaCpH6 max_giveable=0.00010000 BTC minimum_amount=0.01000000 BTC maximum_amount=184467440737.09551615 BTC INFO swap: Received Bitcoin new_balance=0.01010000 BTC max_giveable=0.01000000 BTC " @@ -726,7 +726,7 @@ mod tests { assert!(matches!(error, tokio::time::error::Elapsed { .. })); assert_eq!( writer.captured(), - r" INFO swap: Received quote: 1 XMR ~ price=0.00100000 BTC minimum_amount=0.10000000 BTC maximum_amount=184467440737.09551615 BTC + r" INFO swap: Received quote price=0.00100000 BTC minimum_amount=0.10000000 BTC maximum_amount=184467440737.09551615 BTC INFO swap: Waiting for Bitcoin deposit deposit_address=1PdfytjS7C8wwd9Lq5o4x9aXA2YRqaCpH6 max_giveable=0.00000000 BTC minimum_amount=0.10000000 BTC maximum_amount=184467440737.09551615 BTC INFO swap: Received Bitcoin new_balance=0.01010000 BTC max_giveable=0.01000000 BTC INFO swap: Deposited amount is less than `min_quantity` @@ -772,7 +772,7 @@ mod tests { assert_eq!( writer.captured(), - r" INFO swap: Received quote: 1 XMR ~ price=0.00100000 BTC minimum_amount=0.10000000 BTC maximum_amount=184467440737.09551615 BTC + r" INFO swap: Received quote price=0.00100000 BTC minimum_amount=0.10000000 BTC maximum_amount=184467440737.09551615 BTC INFO swap: Waiting for Bitcoin deposit deposit_address=1PdfytjS7C8wwd9Lq5o4x9aXA2YRqaCpH6 max_giveable=0.00000000 BTC minimum_amount=0.10000000 BTC maximum_amount=184467440737.09551615 BTC INFO swap: Received Bitcoin new_balance=0.21000000 BTC max_giveable=0.20000000 BTC "