From 1706b3680025f6c19043c8e1441cc6ed748190d5 Mon Sep 17 00:00:00 2001 From: Philipp Hoenisch Date: Wed, 5 May 2021 13:43:46 +1000 Subject: [PATCH 1/5] Log exchange rate at each state. --- swap/src/bin/asb.rs | 5 +-- swap/src/protocol/alice/swap.rs | 35 ++++++++++++++----- ..._refund_using_cancel_and_refund_command.rs | 7 +++- ...and_refund_command_timelock_not_expired.rs | 7 +++- ...fund_command_timelock_not_expired_force.rs | 7 +++- .../alice_manually_punishes_after_bob_dead.rs | 7 +++- ..._manually_redeems_after_enc_sig_learned.rs | 7 +++- .../alice_punishes_after_restart_bob_dead.rs | 9 +++-- ...lice_refunds_after_restart_bob_refunded.rs | 9 +++-- ...and_refund_command_timelock_not_expired.rs | 1 + ...fund_command_timelock_not_expired_force.rs | 1 + ...ncurrent_bobs_after_xmr_lock_proof_sent.rs | 5 +-- ...current_bobs_before_xmr_lock_proof_sent.rs | 5 +-- swap/tests/happy_path.rs | 3 +- ...ppy_path_restart_alice_after_xmr_locked.rs | 9 +++-- ...happy_path_restart_bob_after_xmr_locked.rs | 3 +- ...appy_path_restart_bob_before_xmr_locked.rs | 3 +- swap/tests/punish.rs | 3 +- 18 files changed, 97 insertions(+), 29 deletions(-) create mode 100644 swap/tests/bob_refunds_using_cancel_and_refund_command_timelock_not_expired.rs create mode 100644 swap/tests/bob_refunds_using_cancel_and_refund_command_timelock_not_expired_force.rs diff --git a/swap/src/bin/asb.rs b/swap/src/bin/asb.rs index 96359070..8593ee5a 100644 --- a/swap/src/bin/asb.rs +++ b/swap/src/bin/asb.rs @@ -140,7 +140,7 @@ async fn main() -> Result<()> { Arc::new(bitcoin_wallet), Arc::new(monero_wallet), Arc::new(db), - kraken_rate, + kraken_rate.clone(), config.maker.min_buy_btc, config.maker.max_buy_btc, ) @@ -148,9 +148,10 @@ async fn main() -> Result<()> { tokio::spawn(async move { while let Some(swap) = swap_receiver.recv().await { + let rate = kraken_rate.clone(); tokio::spawn(async move { let swap_id = swap.swap_id; - match run(swap).await { + match run(swap, rate).await { Ok(state) => { tracing::debug!(%swap_id, "Swap finished with state {}", state) } diff --git a/swap/src/protocol/alice/swap.rs b/swap/src/protocol/alice/swap.rs index 14002f60..41d62f07 100644 --- a/swap/src/protocol/alice/swap.rs +++ b/swap/src/protocol/alice/swap.rs @@ -2,7 +2,7 @@ //! Alice holds XMR and wishes receive BTC. use crate::bitcoin::ExpiredTimelocks; use crate::env::Config; -use crate::protocol::alice::event_loop::EventLoopHandle; +use crate::protocol::alice::event_loop::{EventLoopHandle, LatestRate}; use crate::protocol::alice::{AliceState, Swap}; use crate::{bitcoin, database, monero}; use anyhow::{bail, Context, Result}; @@ -11,12 +11,22 @@ use tokio::time::timeout; use tracing::{error, info}; use uuid::Uuid; -pub async fn run(swap: Swap) -> Result { - run_until(swap, |_| false).await +pub async fn run(swap: Swap, rate_service: LR) -> Result +where + LR: LatestRate + Clone, +{ + run_until(swap, |_| false, rate_service).await } -#[tracing::instrument(name = "swap", skip(swap,exit_early), fields(id = %swap.swap_id), err)] -pub async fn run_until(mut swap: Swap, exit_early: fn(&AliceState) -> bool) -> Result { +#[tracing::instrument(name = "swap", skip(swap,exit_early,rate_service), fields(id = %swap.swap_id), err)] +pub async fn run_until( + mut swap: Swap, + exit_early: fn(&AliceState) -> bool, + rate_service: LR, +) -> Result +where + LR: LatestRate + Clone, +{ let mut current_state = swap.state; while !is_complete(¤t_state) && !exit_early(¤t_state) { @@ -27,6 +37,7 @@ pub async fn run_until(mut swap: Swap, exit_early: fn(&AliceState) -> bool) -> R swap.bitcoin_wallet.as_ref(), swap.monero_wallet.as_ref(), &swap.env_config, + rate_service.clone(), ) .await?; @@ -39,15 +50,23 @@ pub async fn run_until(mut swap: Swap, exit_early: fn(&AliceState) -> bool) -> R Ok(current_state) } -async fn next_state( +async fn next_state( swap_id: Uuid, state: AliceState, event_loop_handle: &mut EventLoopHandle, bitcoin_wallet: &bitcoin::Wallet, monero_wallet: &monero::Wallet, env_config: &Config, -) -> Result { - info!("Current state: {}", state); + mut rate_service: LR, +) -> Result +where + LR: LatestRate, +{ + let rate = rate_service + .latest_rate() + .map_or("NaN".to_string(), |rate| format!("{}", rate)); + + info!(%state, %rate, "Update"); Ok(match state { AliceState::Started { state3 } => { diff --git a/swap/tests/alice_and_bob_refund_using_cancel_and_refund_command.rs b/swap/tests/alice_and_bob_refund_using_cancel_and_refund_command.rs index d342d8e7..557768a3 100644 --- a/swap/tests/alice_and_bob_refund_using_cancel_and_refund_command.rs +++ b/swap/tests/alice_and_bob_refund_using_cancel_and_refund_command.rs @@ -3,6 +3,7 @@ pub mod harness; use harness::alice_run_until::is_xmr_lock_transaction_sent; use harness::bob_run_until::is_btc_locked; use harness::FastCancelConfig; +use swap::protocol::alice::event_loop::FixedRate; use swap::protocol::alice::AliceState; use swap::protocol::bob::BobState; use swap::protocol::{alice, bob}; @@ -15,7 +16,11 @@ async fn given_alice_and_bob_manually_refund_after_funds_locked_both_refund() { let bob_swap = tokio::spawn(bob::run_until(bob_swap, is_btc_locked)); let alice_swap = ctx.alice_next_swap().await; - let alice_swap = tokio::spawn(alice::run_until(alice_swap, is_xmr_lock_transaction_sent)); + let alice_swap = tokio::spawn(alice::run_until( + alice_swap, + is_xmr_lock_transaction_sent, + FixedRate::default(), + )); let bob_state = bob_swap.await??; assert!(matches!(bob_state, BobState::BtcLocked { .. })); diff --git a/swap/tests/alice_and_bob_refund_using_cancel_and_refund_command_timelock_not_expired.rs b/swap/tests/alice_and_bob_refund_using_cancel_and_refund_command_timelock_not_expired.rs index bd0761e3..9a20127e 100644 --- a/swap/tests/alice_and_bob_refund_using_cancel_and_refund_command_timelock_not_expired.rs +++ b/swap/tests/alice_and_bob_refund_using_cancel_and_refund_command_timelock_not_expired.rs @@ -3,6 +3,7 @@ pub mod harness; use harness::alice_run_until::is_xmr_lock_transaction_sent; use harness::bob_run_until::is_btc_locked; use harness::SlowCancelConfig; +use swap::protocol::alice::event_loop::FixedRate; use swap::protocol::alice::AliceState; use swap::protocol::bob::BobState; use swap::protocol::{alice, bob}; @@ -15,7 +16,11 @@ async fn given_alice_and_bob_manually_cancel_when_timelock_not_expired_errors() let bob_swap = tokio::spawn(bob::run_until(bob_swap, is_btc_locked)); let alice_swap = ctx.alice_next_swap().await; - let alice_swap = tokio::spawn(alice::run_until(alice_swap, is_xmr_lock_transaction_sent)); + let alice_swap = tokio::spawn(alice::run_until( + alice_swap, + is_xmr_lock_transaction_sent, + FixedRate::default(), + )); let bob_state = bob_swap.await??; assert!(matches!(bob_state, BobState::BtcLocked { .. })); diff --git a/swap/tests/alice_and_bob_refund_using_cancel_and_refund_command_timelock_not_expired_force.rs b/swap/tests/alice_and_bob_refund_using_cancel_and_refund_command_timelock_not_expired_force.rs index 59f5141e..843d6a79 100644 --- a/swap/tests/alice_and_bob_refund_using_cancel_and_refund_command_timelock_not_expired_force.rs +++ b/swap/tests/alice_and_bob_refund_using_cancel_and_refund_command_timelock_not_expired_force.rs @@ -3,6 +3,7 @@ pub mod harness; use harness::alice_run_until::is_xmr_lock_transaction_sent; use harness::bob_run_until::is_btc_locked; use harness::SlowCancelConfig; +use swap::protocol::alice::event_loop::FixedRate; use swap::protocol::alice::AliceState; use swap::protocol::bob::BobState; use swap::protocol::{alice, bob}; @@ -15,7 +16,11 @@ async fn given_alice_and_bob_manually_force_cancel_when_timelock_not_expired_err let bob_swap = tokio::spawn(bob::run_until(bob_swap, is_btc_locked)); let alice_swap = ctx.alice_next_swap().await; - let alice_swap = tokio::spawn(alice::run_until(alice_swap, is_xmr_lock_transaction_sent)); + let alice_swap = tokio::spawn(alice::run_until( + alice_swap, + is_xmr_lock_transaction_sent, + FixedRate::default(), + )); let bob_state = bob_swap.await??; assert!(matches!(bob_state, BobState::BtcLocked { .. })); diff --git a/swap/tests/alice_manually_punishes_after_bob_dead.rs b/swap/tests/alice_manually_punishes_after_bob_dead.rs index 1bf71d62..2da13969 100644 --- a/swap/tests/alice_manually_punishes_after_bob_dead.rs +++ b/swap/tests/alice_manually_punishes_after_bob_dead.rs @@ -3,6 +3,7 @@ pub mod harness; use harness::alice_run_until::is_xmr_lock_transaction_sent; use harness::bob_run_until::is_btc_locked; use harness::FastPunishConfig; +use swap::protocol::alice::event_loop::FixedRate; use swap::protocol::alice::AliceState; use swap::protocol::bob::BobState; use swap::protocol::{alice, bob}; @@ -20,7 +21,11 @@ async fn alice_manually_punishes_after_bob_dead() { let alice_swap = ctx.alice_next_swap().await; let alice_bitcoin_wallet = alice_swap.bitcoin_wallet.clone(); - let alice_swap = tokio::spawn(alice::run_until(alice_swap, is_xmr_lock_transaction_sent)); + let alice_swap = tokio::spawn(alice::run_until( + alice_swap, + is_xmr_lock_transaction_sent, + FixedRate::default(), + )); let bob_state = bob_swap.await??; assert!(matches!(bob_state, BobState::BtcLocked { .. })); diff --git a/swap/tests/alice_manually_redeems_after_enc_sig_learned.rs b/swap/tests/alice_manually_redeems_after_enc_sig_learned.rs index 38a0da9b..720dad19 100644 --- a/swap/tests/alice_manually_redeems_after_enc_sig_learned.rs +++ b/swap/tests/alice_manually_redeems_after_enc_sig_learned.rs @@ -2,6 +2,7 @@ pub mod harness; use harness::alice_run_until::is_encsig_learned; use harness::SlowCancelConfig; +use swap::protocol::alice::event_loop::FixedRate; use swap::protocol::alice::redeem::Finality; use swap::protocol::alice::AliceState; use swap::protocol::{alice, bob}; @@ -15,7 +16,11 @@ async fn alice_manually_redeems_after_enc_sig_learned() { let bob_swap = tokio::spawn(bob::run(bob_swap)); let alice_swap = ctx.alice_next_swap().await; - let alice_swap = tokio::spawn(alice::run_until(alice_swap, is_encsig_learned)); + let alice_swap = tokio::spawn(alice::run_until( + alice_swap, + is_encsig_learned, + FixedRate::default(), + )); let alice_state = alice_swap.await??; assert!(matches!(alice_state, AliceState::EncSigLearned { .. })); diff --git a/swap/tests/alice_punishes_after_restart_bob_dead.rs b/swap/tests/alice_punishes_after_restart_bob_dead.rs index 377b7b47..a272dbf1 100644 --- a/swap/tests/alice_punishes_after_restart_bob_dead.rs +++ b/swap/tests/alice_punishes_after_restart_bob_dead.rs @@ -3,6 +3,7 @@ pub mod harness; use harness::alice_run_until::is_xmr_lock_transaction_sent; use harness::bob_run_until::is_btc_locked; use harness::FastPunishConfig; +use swap::protocol::alice::event_loop::FixedRate; use swap::protocol::alice::AliceState; use swap::protocol::bob::BobState; use swap::protocol::{alice, bob}; @@ -19,7 +20,11 @@ async fn alice_punishes_after_restart_if_bob_dead() { let alice_swap = ctx.alice_next_swap().await; let alice_bitcoin_wallet = alice_swap.bitcoin_wallet.clone(); - let alice_swap = tokio::spawn(alice::run_until(alice_swap, is_xmr_lock_transaction_sent)); + let alice_swap = tokio::spawn(alice::run_until( + alice_swap, + is_xmr_lock_transaction_sent, + FixedRate::default(), + )); let bob_state = bob_swap.await??; assert!(matches!(bob_state, BobState::BtcLocked { .. })); @@ -40,7 +45,7 @@ async fn alice_punishes_after_restart_if_bob_dead() { ctx.restart_alice().await; let alice_swap = ctx.alice_next_swap().await; - let alice_swap = tokio::spawn(alice::run(alice_swap)); + let alice_swap = tokio::spawn(alice::run(alice_swap, FixedRate::default())); let alice_state = alice_swap.await??; ctx.assert_alice_punished(alice_state).await; diff --git a/swap/tests/alice_refunds_after_restart_bob_refunded.rs b/swap/tests/alice_refunds_after_restart_bob_refunded.rs index 0c341b7d..2cf12605 100644 --- a/swap/tests/alice_refunds_after_restart_bob_refunded.rs +++ b/swap/tests/alice_refunds_after_restart_bob_refunded.rs @@ -2,6 +2,7 @@ pub mod harness; use harness::alice_run_until::is_xmr_lock_transaction_sent; use harness::FastCancelConfig; +use swap::protocol::alice::event_loop::FixedRate; use swap::protocol::alice::AliceState; use swap::protocol::{alice, bob}; @@ -14,7 +15,11 @@ async fn alice_refunds_after_restart_if_bob_already_refunded() { let bob_swap = tokio::spawn(bob::run(bob_swap)); let alice_swap = ctx.alice_next_swap().await; - let alice_swap = tokio::spawn(alice::run_until(alice_swap, is_xmr_lock_transaction_sent)); + let alice_swap = tokio::spawn(alice::run_until( + alice_swap, + is_xmr_lock_transaction_sent, + FixedRate::default(), + )); let bob_state = bob_swap.await??; ctx.assert_bob_refunded(bob_state).await; @@ -27,7 +32,7 @@ async fn alice_refunds_after_restart_if_bob_already_refunded() { ctx.restart_alice().await; let alice_swap = ctx.alice_next_swap().await; - let alice_swap = tokio::spawn(alice::run(alice_swap)); + let alice_swap = tokio::spawn(alice::run(alice_swap, FixedRate::default())); let alice_state = alice_swap.await??; ctx.assert_alice_refunded(alice_state).await; diff --git a/swap/tests/bob_refunds_using_cancel_and_refund_command_timelock_not_expired.rs b/swap/tests/bob_refunds_using_cancel_and_refund_command_timelock_not_expired.rs new file mode 100644 index 00000000..8b137891 --- /dev/null +++ b/swap/tests/bob_refunds_using_cancel_and_refund_command_timelock_not_expired.rs @@ -0,0 +1 @@ + diff --git a/swap/tests/bob_refunds_using_cancel_and_refund_command_timelock_not_expired_force.rs b/swap/tests/bob_refunds_using_cancel_and_refund_command_timelock_not_expired_force.rs new file mode 100644 index 00000000..8b137891 --- /dev/null +++ b/swap/tests/bob_refunds_using_cancel_and_refund_command_timelock_not_expired_force.rs @@ -0,0 +1 @@ + diff --git a/swap/tests/concurrent_bobs_after_xmr_lock_proof_sent.rs b/swap/tests/concurrent_bobs_after_xmr_lock_proof_sent.rs index a580a6be..e756fd9e 100644 --- a/swap/tests/concurrent_bobs_after_xmr_lock_proof_sent.rs +++ b/swap/tests/concurrent_bobs_after_xmr_lock_proof_sent.rs @@ -2,6 +2,7 @@ pub mod harness; use harness::bob_run_until::is_xmr_locked; use harness::SlowCancelConfig; +use swap::protocol::alice::event_loop::FixedRate; use swap::protocol::alice::AliceState; use swap::protocol::bob::BobState; use swap::protocol::{alice, bob}; @@ -16,7 +17,7 @@ async fn concurrent_bobs_after_xmr_lock_proof_sent() { let bob_swap_1 = tokio::spawn(bob::run_until(bob_swap_1, is_xmr_locked)); let alice_swap_1 = ctx.alice_next_swap().await; - let alice_swap_1 = tokio::spawn(alice::run(alice_swap_1)); + let alice_swap_1 = tokio::spawn(alice::run(alice_swap_1, FixedRate::default())); let bob_state_1 = bob_swap_1.await??; assert!(matches!(bob_state_1, BobState::XmrLocked { .. })); @@ -28,7 +29,7 @@ async fn concurrent_bobs_after_xmr_lock_proof_sent() { let bob_swap_2 = tokio::spawn(bob::run(bob_swap_2)); let alice_swap_2 = ctx.alice_next_swap().await; - let alice_swap_2 = tokio::spawn(alice::run(alice_swap_2)); + let alice_swap_2 = tokio::spawn(alice::run(alice_swap_2, FixedRate::default())); // The 2nd swap should ALWAYS finish successfully in this // scenario diff --git a/swap/tests/concurrent_bobs_before_xmr_lock_proof_sent.rs b/swap/tests/concurrent_bobs_before_xmr_lock_proof_sent.rs index a15d6cae..420d3cbe 100644 --- a/swap/tests/concurrent_bobs_before_xmr_lock_proof_sent.rs +++ b/swap/tests/concurrent_bobs_before_xmr_lock_proof_sent.rs @@ -2,6 +2,7 @@ pub mod harness; use harness::bob_run_until::is_btc_locked; use harness::SlowCancelConfig; +use swap::protocol::alice::event_loop::FixedRate; use swap::protocol::alice::AliceState; use swap::protocol::bob::BobState; use swap::protocol::{alice, bob}; @@ -16,7 +17,7 @@ async fn concurrent_bobs_before_xmr_lock_proof_sent() { let bob_swap_1 = tokio::spawn(bob::run_until(bob_swap_1, is_btc_locked)); let alice_swap_1 = ctx.alice_next_swap().await; - let alice_swap_1 = tokio::spawn(alice::run(alice_swap_1)); + let alice_swap_1 = tokio::spawn(alice::run(alice_swap_1, FixedRate::default())); let bob_state_1 = bob_swap_1.await??; assert!(matches!(bob_state_1, BobState::BtcLocked(_))); @@ -28,7 +29,7 @@ async fn concurrent_bobs_before_xmr_lock_proof_sent() { let bob_swap_2 = tokio::spawn(bob::run(bob_swap_2)); let alice_swap_2 = ctx.alice_next_swap().await; - let alice_swap_2 = tokio::spawn(alice::run(alice_swap_2)); + let alice_swap_2 = tokio::spawn(alice::run(alice_swap_2, FixedRate::default())); // The 2nd swap ALWAYS finish successfully in this // scenario, but will receive an "unwanted" transfer proof that is ignored in diff --git a/swap/tests/happy_path.rs b/swap/tests/happy_path.rs index 2f50ff14..51e132fa 100644 --- a/swap/tests/happy_path.rs +++ b/swap/tests/happy_path.rs @@ -1,6 +1,7 @@ pub mod harness; use harness::SlowCancelConfig; +use swap::protocol::alice::event_loop::FixedRate; use swap::protocol::{alice, bob}; use tokio::join; @@ -11,7 +12,7 @@ async fn happy_path() { let bob_swap = tokio::spawn(bob::run(bob_swap)); let alice_swap = ctx.alice_next_swap().await; - let alice_swap = tokio::spawn(alice::run(alice_swap)); + let alice_swap = tokio::spawn(alice::run(alice_swap, FixedRate::default())); let (bob_state, alice_state) = join!(bob_swap, alice_swap); diff --git a/swap/tests/happy_path_restart_alice_after_xmr_locked.rs b/swap/tests/happy_path_restart_alice_after_xmr_locked.rs index 97a6f04a..95a68861 100644 --- a/swap/tests/happy_path_restart_alice_after_xmr_locked.rs +++ b/swap/tests/happy_path_restart_alice_after_xmr_locked.rs @@ -2,6 +2,7 @@ pub mod harness; use harness::alice_run_until::is_xmr_lock_transaction_sent; use harness::SlowCancelConfig; +use swap::protocol::alice::event_loop::FixedRate; use swap::protocol::alice::AliceState; use swap::protocol::{alice, bob}; @@ -12,7 +13,11 @@ async fn given_alice_restarts_after_xmr_is_locked_resume_swap() { let bob_swap = tokio::spawn(bob::run(bob_swap)); let alice_swap = ctx.alice_next_swap().await; - let alice_swap = tokio::spawn(alice::run_until(alice_swap, is_xmr_lock_transaction_sent)); + let alice_swap = tokio::spawn(alice::run_until( + alice_swap, + is_xmr_lock_transaction_sent, + FixedRate::default(), + )); let alice_state = alice_swap.await??; @@ -28,7 +33,7 @@ async fn given_alice_restarts_after_xmr_is_locked_resume_swap() { AliceState::XmrLockTransactionSent { .. } )); - let alice_state = alice::run(alice_swap).await?; + let alice_state = alice::run(alice_swap, FixedRate::default()).await?; ctx.assert_alice_redeemed(alice_state).await; let bob_state = bob_swap.await??; diff --git a/swap/tests/happy_path_restart_bob_after_xmr_locked.rs b/swap/tests/happy_path_restart_bob_after_xmr_locked.rs index a07fb2f2..b3a3b1ed 100644 --- a/swap/tests/happy_path_restart_bob_after_xmr_locked.rs +++ b/swap/tests/happy_path_restart_bob_after_xmr_locked.rs @@ -2,6 +2,7 @@ pub mod harness; use harness::bob_run_until::is_xmr_locked; use harness::SlowCancelConfig; +use swap::protocol::alice::event_loop::FixedRate; use swap::protocol::bob::BobState; use swap::protocol::{alice, bob}; @@ -13,7 +14,7 @@ async fn given_bob_restarts_after_xmr_is_locked_resume_swap() { let bob_swap = tokio::spawn(bob::run_until(bob_swap, is_xmr_locked)); let alice_swap = ctx.alice_next_swap().await; - let alice_swap = tokio::spawn(alice::run(alice_swap)); + let alice_swap = tokio::spawn(alice::run(alice_swap, FixedRate::default())); let bob_state = bob_swap.await??; diff --git a/swap/tests/happy_path_restart_bob_before_xmr_locked.rs b/swap/tests/happy_path_restart_bob_before_xmr_locked.rs index a07fb2f2..b3a3b1ed 100644 --- a/swap/tests/happy_path_restart_bob_before_xmr_locked.rs +++ b/swap/tests/happy_path_restart_bob_before_xmr_locked.rs @@ -2,6 +2,7 @@ pub mod harness; use harness::bob_run_until::is_xmr_locked; use harness::SlowCancelConfig; +use swap::protocol::alice::event_loop::FixedRate; use swap::protocol::bob::BobState; use swap::protocol::{alice, bob}; @@ -13,7 +14,7 @@ async fn given_bob_restarts_after_xmr_is_locked_resume_swap() { let bob_swap = tokio::spawn(bob::run_until(bob_swap, is_xmr_locked)); let alice_swap = ctx.alice_next_swap().await; - let alice_swap = tokio::spawn(alice::run(alice_swap)); + let alice_swap = tokio::spawn(alice::run(alice_swap, FixedRate::default())); let bob_state = bob_swap.await??; diff --git a/swap/tests/punish.rs b/swap/tests/punish.rs index ef498d10..61af1f61 100644 --- a/swap/tests/punish.rs +++ b/swap/tests/punish.rs @@ -2,6 +2,7 @@ pub mod harness; use harness::bob_run_until::is_btc_locked; use harness::FastPunishConfig; +use swap::protocol::alice::event_loop::FixedRate; use swap::protocol::bob::BobState; use swap::protocol::{alice, bob}; @@ -15,7 +16,7 @@ async fn alice_punishes_if_bob_never_acts_after_fund() { let bob_swap = tokio::spawn(bob::run_until(bob_swap, is_btc_locked)); let alice_swap = ctx.alice_next_swap().await; - let alice_swap = tokio::spawn(alice::run(alice_swap)); + let alice_swap = tokio::spawn(alice::run(alice_swap, FixedRate::default())); let bob_state = bob_swap.await??; assert!(matches!(bob_state, BobState::BtcLocked { .. })); From c011e9506238fc7987310844f77d5ba72d2a6423 Mon Sep 17 00:00:00 2001 From: Philipp Hoenisch Date: Wed, 5 May 2021 13:49:11 +1000 Subject: [PATCH 2/5] Improve logging by adding details as fields instead of into the msg. --- swap/src/asb/config.rs | 8 ++-- swap/src/asb/tracing.rs | 2 +- swap/src/bin/asb.rs | 39 ++++++++++-------- swap/src/bin/swap.rs | 3 +- swap/src/bitcoin/wallet.rs | 26 ++++++------ swap/src/fs.rs | 4 +- swap/src/kraken.rs | 8 ++-- swap/src/monero/wallet.rs | 48 +++++++++++++++-------- swap/src/monero/wallet_rpc.rs | 5 ++- swap/src/network/cbor_request_response.rs | 18 ++++----- swap/src/network/json_pull_codec.rs | 12 ++---- swap/src/network/swarm.rs | 8 ++-- swap/src/network/tor_transport.rs | 8 ++-- swap/src/protocol/alice/event_loop.rs | 39 ++++++++++-------- swap/src/protocol/alice/swap.rs | 34 +++++++++------- swap/src/protocol/bob/event_loop.rs | 2 +- 16 files changed, 150 insertions(+), 114 deletions(-) diff --git a/swap/src/asb/config.rs b/swap/src/asb/config.rs index 24cecf2f..6e956f2d 100644 --- a/swap/src/asb/config.rs +++ b/swap/src/asb/config.rs @@ -105,8 +105,8 @@ pub struct ConfigNotInitialized {} pub fn read_config(config_path: PathBuf) -> Result> { if config_path.exists() { info!( - "Using config file at default path: {}", - config_path.display() + path = %config_path.display(), + "Using config file at path", ); } else { return Ok(Err(ConfigNotInitialized {})); @@ -148,8 +148,8 @@ where fs::write(&config_path, toml)?; info!( - "Initial setup complete, config file created at {} ", - config_path.as_path().display() + path = %config_path.as_path().display(), + "Initial setup complete, config file created", ); Ok(()) } diff --git a/swap/src/asb/tracing.rs b/swap/src/asb/tracing.rs index dd27194c..65a84970 100644 --- a/swap/src/asb/tracing.rs +++ b/swap/src/asb/tracing.rs @@ -21,7 +21,7 @@ pub fn init(level: LevelFilter) -> Result<()> { builder.init(); } - tracing::info!("Initialized tracing with level: {}", level); + tracing::info!(%level, "Initialized tracing"); Ok(()) } diff --git a/swap/src/bin/asb.rs b/swap/src/bin/asb.rs index 8593ee5a..f1e5d90f 100644 --- a/swap/src/bin/asb.rs +++ b/swap/src/bin/asb.rs @@ -35,7 +35,7 @@ use swap::protocol::alice::{redeem, run, EventLoop}; use swap::seed::Seed; use swap::tor::AuthenticatedClient; use swap::{asb, bitcoin, env, kraken, monero, tor}; -use tracing::{info, warn}; +use tracing::{debug, info, warn}; use tracing_subscriber::filter::LevelFilter; #[macro_use] @@ -64,8 +64,8 @@ async fn main() -> Result<()> { }; info!( - "Database and Seed will be stored in directory: {}", - config.data.dir.display() + db_folder = %config.data.dir.display(), + "Database and Seed will be stored in", ); let db_path = config.data.dir.join("database"); @@ -81,20 +81,21 @@ async fn main() -> Result<()> { match opt.cmd { Command::Start { resume_only } => { let bitcoin_wallet = init_bitcoin_wallet(&config, &seed, env_config).await?; + let monero_wallet = init_monero_wallet(&config, env_config).await?; let bitcoin_balance = bitcoin_wallet.balance().await?; - info!("Bitcoin balance: {}", bitcoin_balance); + info!(%bitcoin_balance, "Initialized Bitcoin wallet"); let monero_balance = monero_wallet.get_balance().await?; if monero_balance == Amount::ZERO { - let deposit_address = monero_wallet.get_main_address(); + let monero_address = monero_wallet.get_main_address(); warn!( - "The Monero balance is 0, make sure to deposit funds at: {}", - deposit_address + %monero_address, + "The Monero balance is 0, make sure to deposit funds", ) } else { - info!("Monero balance: {}", monero_balance); + info!(%monero_balance, "Initialized Monero wallet"); } let kraken_price_updates = kraken::connect()?; @@ -104,14 +105,14 @@ async fn main() -> Result<()> { tor::Client::new(config.tor.socks5_port).with_control_port(config.tor.control_port); let _ac = match tor_client.assert_tor_running().await { Ok(_) => { - tracing::info!("Tor found. Setting up hidden service. "); + tracing::info!("Tor found. Setting up hidden service"); let ac = register_tor_services(config.network.clone().listen, tor_client, &seed) .await?; Some(ac) } Err(_) => { - tracing::warn!("Tor not found. Running on clear net. "); + tracing::warn!("Tor not found. Running on clear net"); None } }; @@ -153,17 +154,17 @@ async fn main() -> Result<()> { let swap_id = swap.swap_id; match run(swap, rate).await { Ok(state) => { - tracing::debug!(%swap_id, "Swap finished with state {}", state) + tracing::debug!(%swap_id, %state, "Swap finished with state") } - Err(e) => { - tracing::error!(%swap_id, "Swap failed with {:#}", e) + Err(error) => { + tracing::error!(%swap_id, %error, "Swap failed") } } }); } }); - info!("Our peer id is {}", event_loop.peer_id()); + info!(perr_id = %event_loop.peer_id(), "Our peer id"); event_loop.run().await; } @@ -203,7 +204,10 @@ async fn main() -> Result<()> { let bitcoin_balance = bitcoin_wallet.balance().await?; let monero_balance = monero_wallet.get_balance().await?; - tracing::info!("Current balance: {}, {}", bitcoin_balance, monero_balance); + tracing::info!( + %bitcoin_balance, + %monero_balance, + "Current balance"); } Command::ManualRecovery(ManualRecovery::Cancel { cancel_params: RecoverCommandParams { swap_id, force }, @@ -274,6 +278,7 @@ async fn init_bitcoin_wallet( seed: &Seed, env_config: swap::env::Config, ) -> Result { + debug!("Opening Bitcoin wallet"); let wallet_dir = config.data.dir.join("wallet"); let wallet = bitcoin::Wallet::new( @@ -295,6 +300,7 @@ async fn init_monero_wallet( config: &Config, env_config: swap::env::Config, ) -> Result { + debug!("Opening Monero wallet"); let wallet = monero::Wallet::open_or_create( config.monero.wallet_rpc_url.clone(), DEFAULT_WALLET_NAME.to_string(), @@ -341,7 +347,8 @@ async fn register_tor_services( .get_address_without_dot_onion(); hidden_services_details.iter().for_each(|(port, _)| { - tracing::info!("/onion3/{}:{}", onion_address, port); + let onion_address = format!("/onion3/{}:{}", onion_address, port); + tracing::info!(%onion_address); }); Ok(ac) diff --git a/swap/src/bin/swap.rs b/swap/src/bin/swap.rs index 825b8955..3d431320 100644 --- a/swap/src/bin/swap.rs +++ b/swap/src/bin/swap.rs @@ -245,8 +245,7 @@ async fn main() -> Result<()> { debug!("Cancel transaction successfully published with id {}", txid) } Err(bob::cancel::Error::CancelTimelockNotExpiredYet) => error!( - "The Cancel Transaction cannot be published yet, \ - because the timelock has not expired. Please try again later." + "The Cancel Transaction cannot be published yet, because the timelock has not expired. Please try again later" ), } } diff --git a/swap/src/bitcoin/wallet.rs b/swap/src/bitcoin/wallet.rs index 534aded8..3f2c4152 100644 --- a/swap/src/bitcoin/wallet.rs +++ b/swap/src/bitcoin/wallet.rs @@ -102,7 +102,7 @@ impl Wallet { format!("Failed to broadcast Bitcoin {} transaction {}", kind, txid) })?; - tracing::info!(%txid, "Published Bitcoin {} transaction", kind); + tracing::info!(%txid, %kind, "Published Bitcoin transaction"); Ok((txid, subscription)) } @@ -154,15 +154,16 @@ impl Wallet { let new_status = match client.lock().await.status_of_script(&tx) { Ok(new_status) => new_status, - Err(e) => { - tracing::warn!(%txid, "Failed to get status of script: {:#}", e); + Err(error) => { + tracing::warn!(%txid, %error, "Failed to get status of script."); return; } }; if Some(new_status) != last_status { - tracing::debug!(%txid, "Transaction is {}", new_status); + tracing::debug!(%txid, status = %new_status, "Transaction status."); } + last_status = Some(new_status); let all_receivers_gone = sender.send(new_status).is_err(); @@ -200,7 +201,7 @@ impl Subscription { let conf_target = self.finality_confirmations; let txid = self.txid; - tracing::info!(%txid, "Waiting for {} confirmation{} of Bitcoin transaction", conf_target, if conf_target > 1 { "s" } else { "" }); + tracing::info!(%txid, required_confirmation=%conf_target, "Waiting for Bitcoin transaction finality."); let mut seen_confirmations = 0; @@ -209,15 +210,18 @@ impl Subscription { let confirmations = inner.confirmations(); if confirmations > seen_confirmations { - tracing::info!(%txid, "Bitcoin tx has {} out of {} confirmation{}", confirmations, conf_target, if conf_target > 1 { "s" } else { "" }); + tracing::info!(%txid, + seen_confirmations = %confirmations, + needed_confirmations = %conf_target, + "Waiting for Bitcoin transaction finality."); seen_confirmations = confirmations; } inner.meets_target(conf_target) - }, - _ => false + } + _ => false, }) - .await + .await } pub async fn wait_until_seen(&self) -> Result<()> { @@ -614,8 +618,8 @@ impl Client { if let Some(new_block) = latest_block { tracing::debug!( - "Got notification for new block at height {}", - new_block.height + block_height = new_block.height, + "Got notification for new block." ); self.latest_block = BlockHeight::try_from(new_block)?; } diff --git a/swap/src/fs.rs b/swap/src/fs.rs index 914b39dd..217d4bf1 100644 --- a/swap/src/fs.rs +++ b/swap/src/fs.rs @@ -24,8 +24,8 @@ pub fn ensure_directory_exists(file: &Path) -> Result<(), std::io::Error> { if let Some(path) = file.parent() { if !path.exists() { tracing::info!( - "Parent directory does not exist, creating recursively: {}", - file.display() + directory = %file.display(), + "Parent directory does not exist, creating recursively", ); return std::fs::create_dir_all(path); } diff --git a/swap/src/kraken.rs b/swap/src/kraken.rs index 57e2861c..8e42386b 100644 --- a/swap/src/kraken.rs +++ b/swap/src/kraken.rs @@ -50,7 +50,9 @@ pub fn connect() -> Result { match result { Err(e) => { - tracing::warn!("Rate updates incurred an unrecoverable error: {:#}", e); + tracing::warn!( + error = %e, + "Rate updates incurred an unrecoverable error."); // in case the retries fail permanently, let the subscribers know price_update.send(Err(Error::PermanentFailure)) @@ -183,8 +185,8 @@ mod connection { // if the message is not an event, it is a ticker update or an unknown event Err(_) => match serde_json::from_str::(&msg) { Ok(ticker) => ticker, - Err(e) => { - tracing::warn!(%e, "Failed to deserialize message '{}' as ticker update", msg); + Err(error) => { + tracing::warn!(%error, %msg, "Failed to deserialize message as ticker update."); return Ok(None); } diff --git a/swap/src/monero/wallet.rs b/swap/src/monero/wallet.rs index 93af277e..87b3df1d 100644 --- a/swap/src/monero/wallet.rs +++ b/swap/src/monero/wallet.rs @@ -33,9 +33,9 @@ impl Wallet { "Unable to create Monero wallet, please ensure that the monero-wallet-rpc is available", )?; - tracing::debug!("Created Monero wallet {}", name); + tracing::debug!(monero_wallet_name = %name, "Created Monero wallet"); } else { - tracing::debug!("Opened Monero wallet {}", name); + tracing::debug!(monero_wallet_name = %name, "Opened Monero wallet"); } Self::connect(client, name, env_config).await @@ -148,19 +148,22 @@ impl Wallet { Ok(_) => match wallet.sweep_all(self.main_address.to_string()).await { Ok(sweep_all) => { for tx in sweep_all.tx_hash_list { - tracing::info!(%tx, "Monero transferred back to default wallet {}", self.main_address); + tracing::info!( + %tx, + monero_address = %self.main_address, + "Monero transferred back to default wallet"); } } - Err(e) => { + Err(error) => { tracing::warn!( - "Transferring Monero back to default wallet {} failed with {:#}", - self.main_address, - e + address = %self.main_address, + %error, + "Transferring Monero back to default wallet failed", ); } }, - Err(e) => { - tracing::warn!("Refreshing the generated wallet failed with {:#}", e); + Err(error) => { + tracing::warn!(%error, "Refreshing the generated wallet failed"); } } @@ -187,10 +190,10 @@ impl Wallet { .await?; tracing::debug!( - "sent transfer of {} to {} in {}", - amount, - public_spend_key, - res.tx_hash + %amount, + to = %public_spend_key, + tx_id = %res.tx_hash, + "Sent transfer" ); Ok(TransferProof::new( @@ -211,7 +214,11 @@ impl Wallet { let txid = transfer_proof.tx_hash(); - tracing::info!(%txid, "Waiting for {} confirmation{} of Monero transaction", conf_target, if conf_target > 1 { "s" } else { "" }); + tracing::info!( + %txid, + target_confirmations = %conf_target, + "Waiting for Monero transaction finality" + ); let address = Address::standard(self.network, public_spend_key, public_view_key.into()); @@ -311,7 +318,11 @@ where let tx = match fetch_tx(txid.clone()).await { Ok(proof) => proof, Err(error) => { - tracing::debug!(%txid, "Failed to retrieve tx from blockchain: {:#}", error); + tracing::debug!( + %txid, + %error, + "Failed to retrieve tx from blockchain" + ); continue; // treating every error as transient and retrying // is obviously wrong but the jsonrpc client is // too primitive to differentiate between all the @@ -330,7 +341,12 @@ where if tx.confirmations > seen_confirmations { seen_confirmations = tx.confirmations; - tracing::info!(%txid, "Monero lock tx has {} out of {} confirmations", tx.confirmations, conf_target); + tracing::info!( + %txid, + %seen_confirmations, + needed_confirmations = %conf_target, + "Received new confirmation for Monero lock tx" + ); } } diff --git a/swap/src/monero/wallet_rpc.rs b/swap/src/monero/wallet_rpc.rs index 273337ef..216d1120 100644 --- a/swap/src/monero/wallet_rpc.rs +++ b/swap/src/monero/wallet_rpc.rs @@ -121,7 +121,10 @@ impl WalletRpc { .local_addr()? .port(); - tracing::debug!("Starting monero-wallet-rpc on port {}", port); + tracing::debug!( + monero_wallet_rpc_port = %port, + "Starting monero-wallet-rpc on port" + ); let mut child = Command::new(self.exec_path()) .env("LANG", "en_AU.UTF-8") diff --git a/swap/src/network/cbor_request_response.rs b/swap/src/network/cbor_request_response.rs index 055224c8..3101d07c 100644 --- a/swap/src/network/cbor_request_response.rs +++ b/swap/src/network/cbor_request_response.rs @@ -45,10 +45,8 @@ where e => io::Error::new(io::ErrorKind::Other, e), })?; let mut de = serde_cbor::Deserializer::from_slice(&message); - let msg = Req::deserialize(&mut de).map_err(|e| { - tracing::debug!("serde read_request error: {:?}", e); - io::Error::new(io::ErrorKind::Other, e) - })?; + let msg = Req::deserialize(&mut de) + .map_err(|error| io::Error::new(io::ErrorKind::Other, error))?; Ok(msg) } @@ -65,9 +63,9 @@ where .await .map_err(|e| io::Error::new(io::ErrorKind::InvalidData, e))?; let mut de = serde_cbor::Deserializer::from_slice(&message); - let msg = Res::deserialize(&mut de).map_err(|e| { - tracing::debug!("serde read_response error: {:?}", e); - io::Error::new(io::ErrorKind::InvalidData, e) + let msg = Res::deserialize(&mut de).map_err(|error| { + tracing::debug!(%error, "serde read_response error."); + io::Error::new(io::ErrorKind::InvalidData, error) })?; Ok(msg) @@ -99,9 +97,9 @@ where where T: AsyncWrite + Unpin + Send, { - let bytes = serde_cbor::to_vec(&res).map_err(|e| { - tracing::debug!("serde write_response error: {:?}", e); - io::Error::new(io::ErrorKind::InvalidData, e) + let bytes = serde_cbor::to_vec(&res).map_err(|error| { + tracing::debug!(%error,"serde write_response error"); + io::Error::new(io::ErrorKind::InvalidData, error) })?; upgrade::write_one(io, &bytes).await?; diff --git a/swap/src/network/json_pull_codec.rs b/swap/src/network/json_pull_codec.rs index 8d802c16..aab788ba 100644 --- a/swap/src/network/json_pull_codec.rs +++ b/swap/src/network/json_pull_codec.rs @@ -59,10 +59,8 @@ where .await .map_err(|e| io::Error::new(io::ErrorKind::InvalidData, e))?; let mut de = serde_json::Deserializer::from_slice(&message); - let msg = Res::deserialize(&mut de).map_err(|e| { - tracing::debug!("serde read_response error: {:?}", e); - io::Error::new(io::ErrorKind::InvalidData, e) - })?; + let msg = Res::deserialize(&mut de) + .map_err(|error| io::Error::new(io::ErrorKind::InvalidData, error))?; Ok(msg) } @@ -88,10 +86,8 @@ where where T: AsyncWrite + Unpin + Send, { - let bytes = serde_json::to_vec(&res).map_err(|e| { - tracing::debug!("serde write_response error: {:?}", e); - io::Error::new(io::ErrorKind::InvalidData, e) - })?; + let bytes = serde_json::to_vec(&res) + .map_err(|error| io::Error::new(io::ErrorKind::InvalidData, error))?; upgrade::write_one(io, &bytes).await?; Ok(()) diff --git a/swap/src/network/swarm.rs b/swap/src/network/swarm.rs index 8460e6ee..27171392 100644 --- a/swap/src/network/swarm.rs +++ b/swap/src/network/swarm.rs @@ -49,11 +49,11 @@ fn with_clear_net(seed: &Seed, behaviour: B) -> Result> where B: NetworkBehaviour, { - tracing::info!("All connections will go through clear net."); + tracing::info!("All connections will go through clear net"); let identity = seed.derive_libp2p_identity(); let transport = transport::build_clear_net(&identity)?; let peer_id = identity.public().into_peer_id(); - tracing::debug!("Our peer-id: {}", peer_id); + tracing::debug!(%peer_id, "Our peer-id"); let swarm = SwarmBuilder::new(transport, behaviour, peer_id) .executor(Box::new(|f| { @@ -68,11 +68,11 @@ async fn with_tor(seed: &Seed, behaviour: B, tor_socks5_port: u16) -> Result< where B: NetworkBehaviour, { - tracing::info!("All connections will go through Tor socks5 proxy."); + tracing::info!("All connections will go through Tor socks5 proxy"); let identity = seed.derive_libp2p_identity(); let transport = transport::build_tor(&identity, tor_socks5_port)?; let peer_id = identity.public().into_peer_id(); - tracing::debug!("Our peer-id: {}", peer_id); + tracing::debug!(%peer_id, "Our peer-id"); let swarm = SwarmBuilder::new(transport, behaviour, peer_id) .executor(Box::new(|f| { diff --git a/swap/src/network/tor_transport.rs b/swap/src/network/tor_transport.rs index 837a5556..03e865e0 100644 --- a/swap/src/network/tor_transport.rs +++ b/swap/src/network/tor_transport.rs @@ -58,11 +58,11 @@ impl Transport for TorTcpConfig { Ok(tor_address_string) => { Ok(Box::pin(do_tor_dial(self.socks_port, tor_address_string))) } - Err(e) => { + Err(error) => { tracing::warn!( - "Address {} could not be formatted. Dialling via clear net. Details: {}", - addr, - e + address = %addr, + %error, + "Address could not be formatted. Dialling via clear net.", ); self.inner.dial(addr) } diff --git a/swap/src/protocol/alice/event_loop.rs b/swap/src/protocol/alice/event_loop.rs index 36a2751c..de5e3f17 100644 --- a/swap/src/protocol/alice/event_loop.rs +++ b/swap/src/protocol/alice/event_loop.rs @@ -199,8 +199,8 @@ where &mut OsRng ) { Ok(state) => state, - Err(e) => { - tracing::warn!(%peer, "Failed to make State0 for execution setup: {:#}", e); + Err(error) => { + tracing::warn!(%peer, %error, "Failed to make State0 for execution setup."); continue; } }; @@ -235,8 +235,8 @@ where let quote = match self.make_quote(self.min_buy, self.max_buy).await { Ok(quote) => quote, - Err(e) => { - tracing::warn!(%peer, "Failed to make quote: {:#}", e); + Err(error) => { + tracing::warn!(%peer, %error, "Failed to make quote."); continue; } }; @@ -262,7 +262,10 @@ where let swap_peer = match swap_peer { Ok(swap_peer) => swap_peer, Err(_) => { - tracing::warn!("Ignoring encrypted signature for unknown swap {} from {}", swap_id, peer); + tracing::warn!( + unknown_swap_id = %swap_id, + from = %peer, + "Ignoring encrypted signature for unknown swap."); continue; } }; @@ -270,9 +273,10 @@ where if swap_peer != peer { tracing::warn!( %swap_id, - "Ignoring malicious encrypted signature from {}, expected to receive it from {}", - peer, - swap_peer); + received_from = %peer, + expected_from = %swap_peer, + "Ignoring malicious encrypted signature which was not expected from this peer.", + ); continue; } @@ -300,7 +304,10 @@ where }.boxed()); } SwarmEvent::Behaviour(OutEvent::Failure {peer, error}) => { - tracing::error!(%peer, "Communication error: {:#}", error); + tracing::error!( + %peer, + %error, + "Communication error"); } SwarmEvent::ConnectionEstablished { peer_id: peer, endpoint, .. } => { tracing::debug!(%peer, address = %endpoint.get_remote_address(), "New connection established"); @@ -315,20 +322,20 @@ where } } SwarmEvent::IncomingConnectionError { send_back_addr: address, error, .. } => { - tracing::warn!(%address, "Failed to set up connection with peer: {}", error); + tracing::warn!(%address, %error, "Failed to set up connection with peer. "); } SwarmEvent::ConnectionClosed { peer_id: peer, num_established, endpoint, cause } if num_established == 0 => { match cause { Some(error) => { - tracing::warn!(%peer, address = %endpoint.get_remote_address(), "Lost connection: {}", error); + tracing::warn!(%peer, address = %endpoint.get_remote_address(), %error, "Lost connection."); }, None => { - tracing::info!(%peer, address = %endpoint.get_remote_address(), "Successfully closed connection"); + tracing::info!(%peer, address = %endpoint.get_remote_address(), "Successfully closed connection."); } } } - SwarmEvent::NewListenAddr(addr) => { - tracing::info!("Listening on {}", addr); + SwarmEvent::NewListenAddr(address) => { + tracing::info!(%address, "Listening on"); } _ => {} } @@ -345,8 +352,8 @@ where let id = self.swarm.behaviour_mut().transfer_proof.send_request(&peer, transfer_proof); self.inflight_transfer_proofs.insert(id, responder); }, - Some(Err(e)) => { - tracing::debug!("A swap stopped without sending a transfer proof: {:#}", e); + Some(Err(error)) => { + tracing::debug!(%error, "A swap stopped without sending a transfer proof."); } None => { unreachable!("stream of transfer proof receivers must never terminate") diff --git a/swap/src/protocol/alice/swap.rs b/swap/src/protocol/alice/swap.rs index 41d62f07..22351519 100644 --- a/swap/src/protocol/alice/swap.rs +++ b/swap/src/protocol/alice/swap.rs @@ -8,7 +8,7 @@ use crate::{bitcoin, database, monero}; use anyhow::{bail, Context, Result}; use tokio::select; use tokio::time::timeout; -use tracing::{error, info}; +use tracing::{error, info, warn}; use uuid::Uuid; pub async fn run(swap: Swap, rate_service: LR) -> Result @@ -66,7 +66,7 @@ where .latest_rate() .map_or("NaN".to_string(), |rate| format!("{}", rate)); - info!(%state, %rate, "Update"); + info!(%state, %rate, "Advancing state"); Ok(match state { AliceState::Started { state3 } => { @@ -78,10 +78,10 @@ where .await { Err(_) => { - tracing::info!( - "TxLock lock did not get {} confirmations in {} minutes", - env_config.bitcoin_finality_confirmations, - env_config.bitcoin_lock_confirmed_timeout.as_secs_f64() / 60.0 + info!( + confirmations_needed = %env_config.bitcoin_finality_confirmations, + minutes = %env_config.bitcoin_lock_confirmed_timeout.as_secs_f64() / 60.0, + "TxLock lock did not get enough confirmations in time", ); AliceState::SafelyAborted } @@ -183,7 +183,7 @@ where } } enc_sig = event_loop_handle.recv_encrypted_signature() => { - tracing::info!("Received encrypted signature"); + info!("Received encrypted signature"); AliceState::EncSigLearned { monero_wallet_restore_blockheight, @@ -210,8 +210,10 @@ where bail!("Waiting for Bitcoin transaction finality failed with {}! The redeem transaction was published, but it is not ensured that the transaction was included! You're screwed.", e) } }, - Err(e) => { - error!("Publishing the redeem transaction failed with {}, attempting to wait for cancellation now. If you restart the application before the timelock is expired publishing the redeem transaction will be retried.", e); + Err(error) => { + error!( + %error, + "Publishing the redeem transaction failed"); tx_lock_status .wait_until_confirmed_with(state3.cancel_timelock) .await?; @@ -223,8 +225,10 @@ where } } }, - Err(e) => { - error!("Constructing the redeem transaction failed with {}, attempting to wait for cancellation now.", e); + Err(error) => { + error!( + %error, + "Constructing the redeem transaction failed. Attempting to wait for cancellation now"); tx_lock_status .wait_until_confirmed_with(state3.cancel_timelock) .await?; @@ -325,10 +329,10 @@ where match punish { Ok(_) => AliceState::BtcPunished, - Err(e) => { - tracing::warn!( - "Falling back to refund because punish transaction failed with {:#}", - e + Err(error) => { + warn!( + %error, + "Falling back to refund because punish transaction failed" ); // Upon punish failure we assume that the refund tx was included but we diff --git a/swap/src/protocol/bob/event_loop.rs b/swap/src/protocol/bob/event_loop.rs index e32fa7e0..d3aa2a29 100644 --- a/swap/src/protocol/bob/event_loop.rs +++ b/swap/src/protocol/bob/event_loop.rs @@ -134,7 +134,7 @@ impl EventLoop { if swap_id != self.swap_id { // TODO: Save unexpected transfer proofs in the database and check for messages in the database when handling swaps - tracing::warn!("Received unexpected transfer proof for swap {} while running swap {}. This transfer proof will be ignored.", swap_id, self.swap_id); + tracing::warn!("Received unexpected transfer proof for swap {} while running swap {}. This transfer proof will be ignored", swap_id, self.swap_id); // When receiving a transfer proof that is unexpected we still have to acknowledge that it was received let _ = self.swarm.behaviour_mut().transfer_proof.send_response(channel, ()); From 316f95c65ba0c67e13dbf607d56890d54227ddfd Mon Sep 17 00:00:00 2001 From: Philipp Hoenisch Date: Tue, 11 May 2021 11:08:33 +1000 Subject: [PATCH 3/5] Always log whole causality chain for errors. --- swap/src/bin/asb.rs | 2 +- swap/src/bitcoin/wallet.rs | 12 ++++++------ swap/src/kraken.rs | 15 ++++++++------- swap/src/monero/wallet.rs | 8 +++----- swap/src/network/cbor_request_response.rs | 12 ++++-------- swap/src/network/tor_transport.rs | 3 +-- swap/src/protocol/alice/event_loop.rs | 23 +++++++++++------------ swap/src/protocol/alice/swap.rs | 12 ++++++------ 8 files changed, 40 insertions(+), 47 deletions(-) diff --git a/swap/src/bin/asb.rs b/swap/src/bin/asb.rs index f1e5d90f..7a671802 100644 --- a/swap/src/bin/asb.rs +++ b/swap/src/bin/asb.rs @@ -157,7 +157,7 @@ async fn main() -> Result<()> { tracing::debug!(%swap_id, %state, "Swap finished with state") } Err(error) => { - tracing::error!(%swap_id, %error, "Swap failed") + tracing::error!(%swap_id, "Swap failed. Error {:#}", error) } } }); diff --git a/swap/src/bitcoin/wallet.rs b/swap/src/bitcoin/wallet.rs index 3f2c4152..8bf9db7c 100644 --- a/swap/src/bitcoin/wallet.rs +++ b/swap/src/bitcoin/wallet.rs @@ -155,13 +155,13 @@ impl Wallet { let new_status = match client.lock().await.status_of_script(&tx) { Ok(new_status) => new_status, Err(error) => { - tracing::warn!(%txid, %error, "Failed to get status of script."); + tracing::warn!(%txid, "Failed to get status of script. Error {:#}", error); return; } }; if Some(new_status) != last_status { - tracing::debug!(%txid, status = %new_status, "Transaction status."); + tracing::debug!(%txid, status = %new_status, "Transaction status"); } last_status = Some(new_status); @@ -201,7 +201,7 @@ impl Subscription { let conf_target = self.finality_confirmations; let txid = self.txid; - tracing::info!(%txid, required_confirmation=%conf_target, "Waiting for Bitcoin transaction finality."); + tracing::info!(%txid, required_confirmation=%conf_target, "Waiting for Bitcoin transaction finality"); let mut seen_confirmations = 0; @@ -213,7 +213,7 @@ impl Subscription { tracing::info!(%txid, seen_confirmations = %confirmations, needed_confirmations = %conf_target, - "Waiting for Bitcoin transaction finality."); + "Waiting for Bitcoin transaction finality"); seen_confirmations = confirmations; } @@ -593,7 +593,7 @@ impl Client { [] => Ok(ScriptStatus::Unseen), [remaining @ .., last] => { if !remaining.is_empty() { - tracing::warn!("Found more than a single history entry for script. This is highly unexpected and those history entries will be ignored.") + tracing::warn!("Found more than a single history entry for script. This is highly unexpected and those history entries will be ignored") } if last.height <= 0 { @@ -619,7 +619,7 @@ impl Client { if let Some(new_block) = latest_block { tracing::debug!( block_height = new_block.height, - "Got notification for new block." + "Got notification for new block" ); self.latest_block = BlockHeight::try_from(new_block)?; } diff --git a/swap/src/kraken.rs b/swap/src/kraken.rs index 8e42386b..001696ff 100644 --- a/swap/src/kraken.rs +++ b/swap/src/kraken.rs @@ -43,16 +43,18 @@ pub fn connect() -> Result { } }, |error, next: Duration| { - tracing::info!(%error, "Kraken websocket connection failed, retrying in {}ms", next.as_millis()); - } + tracing::info!( + "Kraken websocket connection failed, retrying in {}ms. Error {:#}", + next.as_millis(), + error + ); + }, ) .await; match result { Err(e) => { - tracing::warn!( - error = %e, - "Rate updates incurred an unrecoverable error."); + tracing::warn!("Rate updates incurred an unrecoverable error: {:#}", e); // in case the retries fail permanently, let the subscribers know price_update.send(Err(Error::PermanentFailure)) @@ -186,8 +188,7 @@ mod connection { Err(_) => match serde_json::from_str::(&msg) { Ok(ticker) => ticker, Err(error) => { - tracing::warn!(%error, %msg, "Failed to deserialize message as ticker update."); - + tracing::warn!(%msg, "Failed to deserialize message as ticker update. Error {:#}", error); return Ok(None); } }, diff --git a/swap/src/monero/wallet.rs b/swap/src/monero/wallet.rs index 87b3df1d..4732a632 100644 --- a/swap/src/monero/wallet.rs +++ b/swap/src/monero/wallet.rs @@ -157,13 +157,12 @@ impl Wallet { Err(error) => { tracing::warn!( address = %self.main_address, - %error, - "Transferring Monero back to default wallet failed", + "Transferring Monero back to default wallet failed. Error {:#}", error ); } }, Err(error) => { - tracing::warn!(%error, "Refreshing the generated wallet failed"); + tracing::warn!("Refreshing the generated wallet failed. Error {:#}", error); } } @@ -320,8 +319,7 @@ where Err(error) => { tracing::debug!( %txid, - %error, - "Failed to retrieve tx from blockchain" + "Failed to retrieve tx from blockchain. Error {:#}", error ); continue; // treating every error as transient and retrying // is obviously wrong but the jsonrpc client is diff --git a/swap/src/network/cbor_request_response.rs b/swap/src/network/cbor_request_response.rs index 3101d07c..abec6e07 100644 --- a/swap/src/network/cbor_request_response.rs +++ b/swap/src/network/cbor_request_response.rs @@ -63,10 +63,8 @@ where .await .map_err(|e| io::Error::new(io::ErrorKind::InvalidData, e))?; let mut de = serde_cbor::Deserializer::from_slice(&message); - let msg = Res::deserialize(&mut de).map_err(|error| { - tracing::debug!(%error, "serde read_response error."); - io::Error::new(io::ErrorKind::InvalidData, error) - })?; + let msg = Res::deserialize(&mut de) + .map_err(|error| io::Error::new(io::ErrorKind::InvalidData, error))?; Ok(msg) } @@ -97,10 +95,8 @@ where where T: AsyncWrite + Unpin + Send, { - let bytes = serde_cbor::to_vec(&res).map_err(|error| { - tracing::debug!(%error,"serde write_response error"); - io::Error::new(io::ErrorKind::InvalidData, error) - })?; + let bytes = serde_cbor::to_vec(&res) + .map_err(|error| io::Error::new(io::ErrorKind::InvalidData, error))?; upgrade::write_one(io, &bytes).await?; Ok(()) diff --git a/swap/src/network/tor_transport.rs b/swap/src/network/tor_transport.rs index 03e865e0..772470af 100644 --- a/swap/src/network/tor_transport.rs +++ b/swap/src/network/tor_transport.rs @@ -61,8 +61,7 @@ impl Transport for TorTcpConfig { Err(error) => { tracing::warn!( address = %addr, - %error, - "Address could not be formatted. Dialling via clear net.", + "Address could not be formatted. Dialling via clear net. Error {:#}", error, ); self.inner.dial(addr) } diff --git a/swap/src/protocol/alice/event_loop.rs b/swap/src/protocol/alice/event_loop.rs index de5e3f17..ae26d1f1 100644 --- a/swap/src/protocol/alice/event_loop.rs +++ b/swap/src/protocol/alice/event_loop.rs @@ -170,7 +170,7 @@ where (redeem_address, punish_address) } _ => { - tracing::error!(%peer, "Failed to get new address during execution setup."); + tracing::error!(%peer, "Failed to get new address during execution setup"); continue; } }; @@ -183,7 +183,7 @@ where (tx_redeem_fee, tx_punish_fee) } _ => { - tracing::error!(%peer, "Failed to calculate transaction fees during execution setup."); + tracing::error!(%peer, "Failed to calculate transaction fees during execution setup"); continue; } }; @@ -200,7 +200,7 @@ where ) { Ok(state) => state, Err(error) => { - tracing::warn!(%peer, %error, "Failed to make State0 for execution setup."); + tracing::warn!(%peer, "Failed to make State0 for execution setup. Error {:#}", error); continue; } }; @@ -236,7 +236,7 @@ where let quote = match self.make_quote(self.min_buy, self.max_buy).await { Ok(quote) => quote, Err(error) => { - tracing::warn!(%peer, %error, "Failed to make quote."); + tracing::warn!(%peer, "Failed to make quote. Error {:#}", error); continue; } }; @@ -265,7 +265,7 @@ where tracing::warn!( unknown_swap_id = %swap_id, from = %peer, - "Ignoring encrypted signature for unknown swap."); + "Ignoring encrypted signature for unknown swap"); continue; } }; @@ -275,7 +275,7 @@ where %swap_id, received_from = %peer, expected_from = %swap_peer, - "Ignoring malicious encrypted signature which was not expected from this peer.", + "Ignoring malicious encrypted signature which was not expected from this peer", ); continue; } @@ -306,8 +306,7 @@ where SwarmEvent::Behaviour(OutEvent::Failure {peer, error}) => { tracing::error!( %peer, - %error, - "Communication error"); + "Communication error. Error {:#}", error); } SwarmEvent::ConnectionEstablished { peer_id: peer, endpoint, .. } => { tracing::debug!(%peer, address = %endpoint.get_remote_address(), "New connection established"); @@ -322,15 +321,15 @@ where } } SwarmEvent::IncomingConnectionError { send_back_addr: address, error, .. } => { - tracing::warn!(%address, %error, "Failed to set up connection with peer. "); + tracing::warn!(%address, "Failed to set up connection with peer. Error {:#}", error); } SwarmEvent::ConnectionClosed { peer_id: peer, num_established, endpoint, cause } if num_established == 0 => { match cause { Some(error) => { - tracing::warn!(%peer, address = %endpoint.get_remote_address(), %error, "Lost connection."); + tracing::warn!(%peer, address = %endpoint.get_remote_address(), "Lost connection. Error {:#}", error); }, None => { - tracing::info!(%peer, address = %endpoint.get_remote_address(), "Successfully closed connection."); + tracing::info!(%peer, address = %endpoint.get_remote_address(), "Successfully closed connection"); } } } @@ -353,7 +352,7 @@ where self.inflight_transfer_proofs.insert(id, responder); }, Some(Err(error)) => { - tracing::debug!(%error, "A swap stopped without sending a transfer proof."); + tracing::debug!("A swap stopped without sending a transfer proof. Error {:#}", error); } None => { unreachable!("stream of transfer proof receivers must never terminate") diff --git a/swap/src/protocol/alice/swap.rs b/swap/src/protocol/alice/swap.rs index 22351519..28290a21 100644 --- a/swap/src/protocol/alice/swap.rs +++ b/swap/src/protocol/alice/swap.rs @@ -212,8 +212,9 @@ where }, Err(error) => { error!( - %error, - "Publishing the redeem transaction failed"); + "Publishing the redeem transaction failed. Error {:#}", + error + ); tx_lock_status .wait_until_confirmed_with(state3.cancel_timelock) .await?; @@ -227,8 +228,7 @@ where }, Err(error) => { error!( - %error, - "Constructing the redeem transaction failed. Attempting to wait for cancellation now"); + "Constructing the redeem transaction failed. Attempting to wait for cancellation now. Error {:#}", error); tx_lock_status .wait_until_confirmed_with(state3.cancel_timelock) .await?; @@ -331,8 +331,8 @@ where Ok(_) => AliceState::BtcPunished, Err(error) => { warn!( - %error, - "Falling back to refund because punish transaction failed" + "Falling back to refund because punish transaction failed. Error {:#}", + error ); // Upon punish failure we assume that the refund tx was included but we From fc0cceb1808eb65418f58a5a62eb6bd3e60b2720 Mon Sep 17 00:00:00 2001 From: Philipp Hoenisch Date: Mon, 10 May 2021 12:03:43 +1000 Subject: [PATCH 4/5] Toggle json logs using commandline flag. --- CHANGELOG.md | 1 + Cargo.lock | 13 +++++++++++++ swap/Cargo.toml | 2 +- swap/src/asb/command.rs | 7 +++++++ swap/src/asb/tracing.rs | 12 ++++++++---- swap/src/bin/asb.rs | 3 +-- 6 files changed, 31 insertions(+), 7 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index f499a386..5914aabe 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -27,6 +27,7 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 When started with `--resume-only` the ASB does not accept new, incoming swap requests but only finishes swaps that are resumed upon startup. - A minimum accepted Bitcoin amount for the ASB similar to the maximum amount already present. For the CLI the minimum amount is enforced by waiting until at least the minimum is available as max-giveable amount. +- Added a new argument to ASB: `--json` or `-j`. If set, log messages will be printed in JSON format. ### Fixed diff --git a/Cargo.lock b/Cargo.lock index 23f48cfa..b1e7b0d9 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -4289,6 +4289,16 @@ dependencies = [ "tracing-core", ] +[[package]] +name = "tracing-serde" +version = "0.1.2" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "fb65ea441fbb84f9f6748fd496cf7f63ec9af5bca94dd86456978d055e8eb28b" +dependencies = [ + "serde", + "tracing-core", +] + [[package]] name = "tracing-subscriber" version = "0.2.18" @@ -4300,11 +4310,14 @@ dependencies = [ "lazy_static", "matchers", "regex", + "serde", + "serde_json", "sharded-slab", "thread_local", "tracing", "tracing-core", "tracing-log", + "tracing-serde", ] [[package]] diff --git a/swap/Cargo.toml b/swap/Cargo.toml index b236c334..824eb31f 100644 --- a/swap/Cargo.toml +++ b/swap/Cargo.toml @@ -61,7 +61,7 @@ torut = { version = "0.1", default-features = false, features = [ "v3", "control tracing = { version = "0.1", features = [ "attributes" ] } tracing-appender = "0.1" tracing-futures = { version = "0.2", features = [ "std-future", "futures-03" ] } -tracing-subscriber = { version = "0.2", default-features = false, features = [ "fmt", "ansi", "env-filter", "chrono", "tracing-log" ] } +tracing-subscriber = { version = "0.2", default-features = false, features = [ "fmt", "ansi", "env-filter", "chrono", "tracing-log", "json" ] } url = { version = "2", features = [ "serde" ] } uuid = { version = "0.8", features = [ "serde", "v4" ] } void = "1" diff --git a/swap/src/asb/command.rs b/swap/src/asb/command.rs index 3f641653..b669e5fb 100644 --- a/swap/src/asb/command.rs +++ b/swap/src/asb/command.rs @@ -10,6 +10,13 @@ use uuid::Uuid; author )] pub struct Arguments { + #[structopt( + short, + long = "json", + help = "Changes the log messages to json vs plain-text. If you run ASB as a service, it is recommended to set this to true to simplify log analyses." + )] + pub json: bool, + #[structopt( long = "config", help = "Provide a custom path to the configuration file. The configuration file must be a toml file.", diff --git a/swap/src/asb/tracing.rs b/swap/src/asb/tracing.rs index 65a84970..bced94d4 100644 --- a/swap/src/asb/tracing.rs +++ b/swap/src/asb/tracing.rs @@ -1,8 +1,9 @@ use anyhow::Result; use tracing_subscriber::filter::LevelFilter; +use tracing_subscriber::fmt::time::ChronoLocal; use tracing_subscriber::FmtSubscriber; -pub fn init(level: LevelFilter) -> Result<()> { +pub fn init(level: LevelFilter, json_format: bool) -> Result<()> { if level == LevelFilter::OFF { return Ok(()); } @@ -13,12 +14,15 @@ pub fn init(level: LevelFilter) -> Result<()> { .with_env_filter(format!("asb={},swap={}", level, level)) .with_writer(std::io::stderr) .with_ansi(is_terminal) + .with_timer(ChronoLocal::with_format("%F %T".to_owned())) .with_target(false); - if !is_terminal { - builder.without_time().init(); - } else { + if json_format { + builder.json().init(); + } else if is_terminal { builder.init(); + } else { + builder.without_time().init(); } tracing::info!(%level, "Initialized tracing"); diff --git a/swap/src/bin/asb.rs b/swap/src/bin/asb.rs index 7a671802..e9284373 100644 --- a/swap/src/bin/asb.rs +++ b/swap/src/bin/asb.rs @@ -45,9 +45,8 @@ const DEFAULT_WALLET_NAME: &str = "asb-wallet"; #[tokio::main] async fn main() -> Result<()> { - asb::tracing::init(LevelFilter::DEBUG).expect("initialize tracing"); - let opt = Arguments::from_args(); + asb::tracing::init(LevelFilter::DEBUG, opt.json).expect("initialize tracing"); let config_path = if let Some(config_path) = opt.config { config_path From 26e0383e173f6c1d7fd364edf2c4cb9f1c82adc0 Mon Sep 17 00:00:00 2001 From: Philipp Hoenisch Date: Tue, 11 May 2021 16:06:44 +1000 Subject: [PATCH 5/5] Apply suggestions from code review Co-authored-by: Daniel Karzel --- swap/src/asb/config.rs | 2 +- swap/src/bin/asb.rs | 2 +- swap/src/bitcoin/wallet.rs | 2 +- swap/src/monero/wallet_rpc.rs | 4 ++-- 4 files changed, 5 insertions(+), 5 deletions(-) diff --git a/swap/src/asb/config.rs b/swap/src/asb/config.rs index 6e956f2d..f1709964 100644 --- a/swap/src/asb/config.rs +++ b/swap/src/asb/config.rs @@ -106,7 +106,7 @@ pub fn read_config(config_path: PathBuf) -> Result Result<()> { let monero_address = monero_wallet.get_main_address(); warn!( %monero_address, - "The Monero balance is 0, make sure to deposit funds", + "The Monero balance is 0, make sure to deposit funds at", ) } else { info!(%monero_balance, "Initialized Monero wallet"); diff --git a/swap/src/bitcoin/wallet.rs b/swap/src/bitcoin/wallet.rs index 8bf9db7c..f1cbce60 100644 --- a/swap/src/bitcoin/wallet.rs +++ b/swap/src/bitcoin/wallet.rs @@ -161,7 +161,7 @@ impl Wallet { }; if Some(new_status) != last_status { - tracing::debug!(%txid, status = %new_status, "Transaction status"); + tracing::debug!(%txid, status = %new_status, "Transaction"); } last_status = Some(new_status); diff --git a/swap/src/monero/wallet_rpc.rs b/swap/src/monero/wallet_rpc.rs index 216d1120..f84a943f 100644 --- a/swap/src/monero/wallet_rpc.rs +++ b/swap/src/monero/wallet_rpc.rs @@ -122,8 +122,8 @@ impl WalletRpc { .port(); tracing::debug!( - monero_wallet_rpc_port = %port, - "Starting monero-wallet-rpc on port" + %port, + "Starting monero-wallet-rpc on" ); let mut child = Command::new(self.exec_path())