From 78480547d5c900c8f7b398c8c799bbd4a7781bb0 Mon Sep 17 00:00:00 2001 From: Thomas Eizinger Date: Tue, 6 Jul 2021 16:08:43 +1000 Subject: [PATCH 1/3] Don't import tracing's macros Log statements end up getting changed constantly and having to clean up imports after that is annoying, for example, if the last `info!` in a file disappears, you end up with an unused import warning. Fully qualifying tracing's macros prevents that and also communicates clearly that we are using tracing and not log. --- swap/src/asb/config.rs | 5 ++--- swap/src/bin/asb.rs | 13 ++++++------- swap/src/bin/swap.rs | 13 ++++++------- swap/src/protocol/alice/swap.rs | 15 +++++++-------- 4 files changed, 21 insertions(+), 25 deletions(-) diff --git a/swap/src/asb/config.rs b/swap/src/asb/config.rs index 1ecbebe0..52cc0bee 100644 --- a/swap/src/asb/config.rs +++ b/swap/src/asb/config.rs @@ -14,7 +14,6 @@ use std::ffi::OsStr; use std::fs; use std::path::{Path, PathBuf}; use std::str::FromStr; -use tracing::info; use url::Url; pub trait GetDefaults { @@ -178,7 +177,7 @@ pub struct ConfigNotInitialized {} pub fn read_config(config_path: PathBuf) -> Result> { if config_path.exists() { - info!( + tracing::info!( path = %config_path.display(), "Using config file at", ); @@ -198,7 +197,7 @@ pub fn initial_setup(config_path: PathBuf, config: Config) -> Result<()> { ensure_directory_exists(config_path.as_path())?; fs::write(&config_path, toml)?; - info!( + tracing::info!( path = %config_path.as_path().display(), "Initial setup complete, config file created", ); diff --git a/swap/src/bin/asb.rs b/swap/src/bin/asb.rs index 35a7e436..46fba70b 100644 --- a/swap/src/bin/asb.rs +++ b/swap/src/bin/asb.rs @@ -36,7 +36,6 @@ use swap::protocol::alice::run; use swap::seed::Seed; use swap::tor::AuthenticatedClient; use swap::{asb, bitcoin, kraken, monero, tor}; -use tracing::{debug, info, warn}; use tracing_subscriber::filter::LevelFilter; const DEFAULT_WALLET_NAME: &str = "asb-wallet"; @@ -90,7 +89,7 @@ async fn main() -> Result<()> { )); } - info!( + tracing::info!( db_folder = %config.data.dir.display(), "Database and Seed will be stored in", ); @@ -110,17 +109,17 @@ async fn main() -> Result<()> { let monero_wallet = init_monero_wallet(&config, env_config).await?; let bitcoin_balance = bitcoin_wallet.balance().await?; - info!(%bitcoin_balance, "Initialized Bitcoin wallet"); + tracing::info!(%bitcoin_balance, "Initialized Bitcoin wallet"); let monero_balance = monero_wallet.get_balance().await?; if monero_balance == Amount::ZERO { let monero_address = monero_wallet.get_main_address(); - warn!( + tracing::warn!( %monero_address, "The Monero balance is 0, make sure to deposit funds at", ) } else { - info!(%monero_balance, "Initialized Monero wallet"); + tracing::info!(%monero_balance, "Initialized Monero wallet"); } let kraken_price_updates = kraken::connect(config.maker.price_ticker_ws_url.clone())?; @@ -314,7 +313,7 @@ async fn init_bitcoin_wallet( seed: &Seed, env_config: swap::env::Config, ) -> Result { - debug!("Opening Bitcoin wallet"); + tracing::debug!("Opening Bitcoin wallet"); let wallet_dir = config.data.dir.join("wallet"); let wallet = bitcoin::Wallet::new( @@ -336,7 +335,7 @@ async fn init_monero_wallet( config: &Config, env_config: swap::env::Config, ) -> Result { - debug!("Opening Monero wallet"); + tracing::debug!("Opening Monero wallet"); let wallet = monero::Wallet::open_or_create( config.monero.wallet_rpc_url.clone(), DEFAULT_WALLET_NAME.to_string(), diff --git a/swap/src/bin/swap.rs b/swap/src/bin/swap.rs index 7018d43a..5d23f3ff 100644 --- a/swap/src/bin/swap.rs +++ b/swap/src/bin/swap.rs @@ -34,7 +34,6 @@ use swap::protocol::bob; use swap::protocol::bob::Swap; use swap::seed::Seed; use swap::{bitcoin, cli, monero}; -use tracing::{debug, error, info, warn}; use url::Url; use uuid::Uuid; @@ -111,7 +110,7 @@ async fn main() -> Result<()> { ) .await?; - info!(%amount, %fees, %swap_id, "Swapping"); + tracing::info!(%amount, %fees, %swap_id, "Swapping"); db.insert_peer_id(swap_id, seller_peer_id).await?; db.insert_monero_address(swap_id, monero_receive_address) @@ -242,9 +241,9 @@ async fn main() -> Result<()> { match cancel { Ok((txid, _)) => { - debug!("Cancel transaction successfully published with id {}", txid) + tracing::debug!("Cancel transaction successfully published with id {}", txid) } - Err(cli::cancel::Error::CancelTimelockNotExpiredYet) => error!( + Err(cli::cancel::Error::CancelTimelockNotExpiredYet) => tracing::error!( "The Cancel Transaction cannot be published yet, because the timelock has not expired. Please try again later" ), } @@ -395,9 +394,9 @@ where TS: Future>, FS: Fn() -> TS, { - debug!("Requesting quote"); + tracing::debug!("Requesting quote"); let bid_quote = bid_quote.await?; - info!( + tracing::info!( price = %bid_quote.price, minimum_amount = %bid_quote.min_quantity, maximum_amount = %bid_quote.max_quantity, @@ -415,7 +414,7 @@ where eprintln!("{}", qr_code(&deposit_address)?); } - info!( + tracing::info!( %deposit_address, %max_giveable, %minimum_amount, diff --git a/swap/src/protocol/alice/swap.rs b/swap/src/protocol/alice/swap.rs index c15892a1..da7cc099 100644 --- a/swap/src/protocol/alice/swap.rs +++ b/swap/src/protocol/alice/swap.rs @@ -8,7 +8,6 @@ use crate::{bitcoin, database, monero}; use anyhow::{bail, Context, Result}; use tokio::select; use tokio::time::timeout; -use tracing::{error, info, warn}; use uuid::Uuid; pub async fn run(swap: Swap, rate_service: LR) -> Result @@ -66,7 +65,7 @@ where .latest_rate() .map_or("NaN".to_string(), |rate| format!("{}", rate)); - info!(%state, %rate, "Advancing state"); + tracing::info!(%state, %rate, "Advancing state"); Ok(match state { AliceState::Started { state3 } => { @@ -78,7 +77,7 @@ where .await { Err(_) => { - info!( + tracing::info!( minutes = %env_config.bitcoin_lock_mempool_timeout.as_secs_f64() / 60.0, "TxLock lock was not seen in mempool in time", ); @@ -99,7 +98,7 @@ where .await { Err(_) => { - info!( + tracing::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", @@ -204,7 +203,7 @@ where } } enc_sig = event_loop_handle.recv_encrypted_signature() => { - info!("Received encrypted signature"); + tracing::info!("Received encrypted signature"); AliceState::EncSigLearned { monero_wallet_restore_blockheight, @@ -232,7 +231,7 @@ where } }, Err(error) => { - error!( + tracing::error!( "Publishing the redeem transaction failed. Error {:#}", error ); @@ -248,7 +247,7 @@ where } }, Err(error) => { - error!( + tracing::error!( "Constructing the redeem transaction failed. Attempting to wait for cancellation now. Error {:#}", error); tx_lock_status .wait_until_confirmed_with(state3.cancel_timelock) @@ -361,7 +360,7 @@ where match punish { Ok(_) => AliceState::BtcPunished, Err(error) => { - warn!( + tracing::warn!( "Falling back to refund because punish transaction failed. Error {:#}", error ); From 9119ce5cc4cc9cd8b918e23b24d901a2b8aa7e7b Mon Sep 17 00:00:00 2001 From: Thomas Eizinger Date: Tue, 6 Jul 2021 16:42:05 +1000 Subject: [PATCH 2/3] Tidy up log messages across the codebase 1. Clearly separate the log messages from any fields that are captured. The log message itself should be meaningful because it depends on the underlying formatter, how/if the fields are displayed. 2. Some log messages had very little context, expand that. 3. Wording of errors was inconsistent, hopefully all errors should now start with `Failed to ...`. 4. Some log messages were duplicated across multiple layers (like opening the database). 5. Some log messages were split into two where one part is now an `error!` and the 2nd part is an `info!` on what is happening next. 6. Where appropriate, punctuation has been removed to not interrupt the reader's flow. --- swap/src/asb/config.rs | 2 +- swap/src/asb/event_loop.rs | 18 +++++++++--------- swap/src/bin/asb.rs | 13 ++++--------- swap/src/bin/swap.rs | 30 +++++++++++++----------------- swap/src/bitcoin/cancel.rs | 7 +++++++ swap/src/bitcoin/lock.rs | 8 ++++---- swap/src/bitcoin/wallet.rs | 27 ++++++++++++++++----------- swap/src/monero/wallet.rs | 10 +++++----- swap/src/monero/wallet_rpc.rs | 2 +- swap/src/network/tor_transport.rs | 2 +- swap/src/protocol/alice/swap.rs | 20 ++++++++++---------- swap/src/protocol/bob/swap.rs | 12 +++++++----- swap/src/seed.rs | 2 +- 13 files changed, 79 insertions(+), 74 deletions(-) diff --git a/swap/src/asb/config.rs b/swap/src/asb/config.rs index 52cc0bee..1cd3ab2f 100644 --- a/swap/src/asb/config.rs +++ b/swap/src/asb/config.rs @@ -179,7 +179,7 @@ pub fn read_config(config_path: PathBuf) -> Result { - tracing::warn!(%peer, "Ignoring spot price request because: {}", error); + tracing::warn!(%peer, "Ignoring spot price request: {}", error); } SwarmEvent::Behaviour(OutEvent::QuoteRequested { channel, peer }) => { let quote = match self.make_quote(self.min_buy, self.max_buy).await { Ok(quote) => quote, Err(error) => { - tracing::warn!(%peer, "Failed to make quote. Error {:#}", error); + tracing::warn!(%peer, "Failed to make quote: {:#}", error); continue; } }; @@ -253,7 +253,7 @@ where SwarmEvent::Behaviour(OutEvent::Failure {peer, error}) => { tracing::error!( %peer, - "Communication error. Error {:#}", error); + "Communication error: {:#}", error); } SwarmEvent::ConnectionEstablished { peer_id: peer, endpoint, .. } => { tracing::debug!(%peer, address = %endpoint.get_remote_address(), "New connection established"); @@ -268,16 +268,16 @@ where } } SwarmEvent::IncomingConnectionError { send_back_addr: address, error, .. } => { - tracing::warn!(%address, "Failed to set up connection with peer. Error {:#}", error); + tracing::warn!(%address, "Failed to set up connection with peer: {:#}", error); } SwarmEvent::ConnectionClosed { peer_id: peer, num_established, endpoint, cause: Some(error) } if num_established == 0 => { - tracing::warn!(%peer, address = %endpoint.get_remote_address(), "Lost connection. Error {:#}", error); + tracing::warn!(%peer, address = %endpoint.get_remote_address(), "Lost connection to peer: {:#}", error); } SwarmEvent::ConnectionClosed { peer_id: peer, num_established, endpoint, cause: None } if num_established == 0 => { tracing::info!(%peer, address = %endpoint.get_remote_address(), "Successfully closed connection"); } SwarmEvent::NewListenAddr(address) => { - tracing::info!(%address, "New listen address detected"); + tracing::info!(%address, "New listen address reported"); } _ => {} } @@ -295,7 +295,7 @@ where self.inflight_transfer_proofs.insert(id, responder); }, Some(Err(error)) => { - tracing::debug!("A swap stopped without sending a transfer proof. Error {:#}", error); + tracing::debug!("A swap stopped without sending a transfer proof: {:#}", error); } None => { unreachable!("stream of transfer proof receivers must never terminate") @@ -354,11 +354,11 @@ where match self.db.insert_peer_id(swap_id, bob_peer_id).await { Ok(_) => { if let Err(error) = self.swap_sender.send(swap).await { - tracing::warn!(%swap_id, "Swap cannot be spawned: {}", error); + tracing::warn!(%swap_id, "Failed to start swap: {}", error); } } Err(error) => { - tracing::warn!(%swap_id, "Unable to save peer-id, swap cannot be spawned: {}", error); + tracing::warn!(%swap_id, "Unable to save peer-id in database: {}", error); } } } diff --git a/swap/src/bin/asb.rs b/swap/src/bin/asb.rs index 46fba70b..08c81310 100644 --- a/swap/src/bin/asb.rs +++ b/swap/src/bin/asb.rs @@ -89,11 +89,6 @@ async fn main() -> Result<()> { )); } - tracing::info!( - db_folder = %config.data.dir.display(), - "Database and Seed will be stored in", - ); - let db_path = config.data.dir.join("database"); let db = Database::open(config.data.dir.join(db_path).as_path()) @@ -129,7 +124,7 @@ 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!("Setting up Tor hidden service"); let ac = register_tor_services(config.network.clone().listen, tor_client, &seed) .await?; @@ -195,10 +190,10 @@ async fn main() -> Result<()> { let swap_id = swap.swap_id; match run(swap, rate).await { Ok(state) => { - tracing::debug!(%swap_id, %state, "Swap finished with state") + tracing::debug!(%swap_id, final_state=%state, "Swap completed") } Err(error) => { - tracing::error!(%swap_id, "Swap failed. Error {:#}", error) + tracing::error!(%swap_id, "Swap failed: {:#}", error) } } }); @@ -383,7 +378,7 @@ async fn register_tor_services( hidden_services_details.iter().for_each(|(port, _)| { let onion_address = format!("/onion3/{}:{}", onion_address, port); - tracing::info!(%onion_address); + tracing::info!(%onion_address, "Successfully created hidden service"); }); Ok(ac) diff --git a/swap/src/bin/swap.rs b/swap/src/bin/swap.rs index 5d23f3ff..70f41082 100644 --- a/swap/src/bin/swap.rs +++ b/swap/src/bin/swap.rs @@ -110,7 +110,7 @@ async fn main() -> Result<()> { ) .await?; - tracing::info!(%amount, %fees, %swap_id, "Swapping"); + tracing::info!(%amount, %fees, %swap_id, "Starting new swap"); db.insert_peer_id(swap_id, seller_peer_id).await?; db.insert_monero_address(swap_id, monero_receive_address) @@ -184,7 +184,7 @@ async fn main() -> Result<()> { let mut swarm = swarm::cli(seed.derive_libp2p_identity(), tor_socks5_port, behaviour).await?; let our_peer_id = swarm.local_peer_id(); - tracing::debug!(peer_id = %our_peer_id, "Initializing network module"); + tracing::debug!(peer_id = %our_peer_id, "Network layer initialized"); for seller_address in seller_addresses { swarm @@ -244,7 +244,7 @@ async fn main() -> Result<()> { tracing::debug!("Cancel transaction successfully published with id {}", txid) } Err(cli::cancel::Error::CancelTimelockNotExpiredYet) => tracing::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" ), } } @@ -414,15 +414,15 @@ where eprintln!("{}", qr_code(&deposit_address)?); } - tracing::info!( - %deposit_address, - %max_giveable, - %minimum_amount, - %maximum_amount, - "Please deposit BTC you want to swap to", - ); - loop { + tracing::info!( + %deposit_address, + %max_giveable, + %minimum_amount, + %maximum_amount, + "Waiting for Bitcoin deposit", + ); + sync().await?; let new_max_givable = max_giveable_fn().await?; @@ -434,17 +434,13 @@ where tracing::info!( %new_balance, %max_giveable, - "Received BTC", + "Received Bitcoin", ); if max_giveable >= bid_quote.min_quantity { break; } else { - tracing::info!( - %minimum_amount, - %deposit_address, - "Please deposit more, not enough BTC to trigger swap with", - ); + tracing::info!("Deposited amount is less than `min_quantity`",); } } diff --git a/swap/src/bitcoin/cancel.rs b/swap/src/bitcoin/cancel.rs index 85cc233a..177d7e00 100644 --- a/swap/src/bitcoin/cancel.rs +++ b/swap/src/bitcoin/cancel.rs @@ -11,6 +11,7 @@ use miniscript::{Descriptor, DescriptorTrait}; use serde::{Deserialize, Serialize}; use std::cmp::Ordering; use std::collections::HashMap; +use std::fmt; use std::ops::Add; /// Represent a timelock, expressed in relative block height as defined in @@ -47,6 +48,12 @@ impl PartialEq for u32 { } } +impl fmt::Display for CancelTimelock { + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { + write!(f, "{} blocks", self.0) + } +} + /// Represent a timelock, expressed in relative block height as defined in /// [BIP68](https://github.com/bitcoin/bips/blob/master/bip-0068.mediawiki). /// E.g. The timelock expires 10 blocks after the reference transaction is diff --git a/swap/src/bitcoin/lock.rs b/swap/src/bitcoin/lock.rs index 8bb6ab29..b1b2be0e 100644 --- a/swap/src/bitcoin/lock.rs +++ b/swap/src/bitcoin/lock.rs @@ -151,14 +151,14 @@ impl TxLock { witness: Vec::new(), }; - let spending_fee = spending_fee.as_sat(); - tracing::debug!(%spending_fee, "Redeem tx fee"); + let fee = spending_fee.as_sat(); let tx_out = TxOut { - value: self.inner.clone().extract_tx().output[self.lock_output_vout()].value - - spending_fee, + value: self.inner.clone().extract_tx().output[self.lock_output_vout()].value - fee, script_pubkey: spend_address.script_pubkey(), }; + tracing::debug!(%fee, "Constructed Bitcoin spending transaction"); + Transaction { version: 2, lock_time: 0, diff --git a/swap/src/bitcoin/wallet.rs b/swap/src/bitcoin/wallet.rs index 18c72329..7eb63794 100644 --- a/swap/src/bitcoin/wallet.rs +++ b/swap/src/bitcoin/wallet.rs @@ -144,13 +144,18 @@ impl Wallet { let new_status = match client.lock().await.status_of_script(&tx) { Ok(new_status) => new_status, Err(error) => { - tracing::warn!(%txid, "Failed to get status of script. Error {:#}", error); + tracing::warn!(%txid, "Failed to get status of script: {:#}", error); return; } }; - if Some(new_status) != last_status { - tracing::debug!(%txid, status = %new_status, "Transaction"); + 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); @@ -409,9 +414,7 @@ where ) -> Result { let client = self.client.lock().await; let fee_rate = client.estimate_feerate(self.target_block)?; - let min_relay_fee = client.min_relay_fee()?; - tracing::debug!("Min relay fee: {}", min_relay_fee); estimate_fee(weight, transfer_amount, fee_rate, min_relay_fee) } @@ -443,20 +446,21 @@ fn estimate_fee( let weight = Decimal::from(weight); let weight_factor = dec!(4.0); - let fee_rate = Decimal::from_f32(fee_rate_svb).context("Could not parse fee_rate.")?; + let fee_rate = Decimal::from_f32(fee_rate_svb).context("Failed to parse fee rate")?; let sats_per_vbyte = weight / weight_factor * fee_rate; + tracing::debug!( - "Estimated fee for weight: {} for fee_rate: {:?} is in total: {}", - weight, - fee_rate, - sats_per_vbyte + %weight, + %fee_rate, + %sats_per_vbyte, + "Estimated fee for transaction", ); let transfer_amount = Decimal::from(transfer_amount.as_sat()); let max_allowed_fee = transfer_amount * MAX_RELATIVE_TX_FEE; - let min_relay_fee = Decimal::from(min_relay_fee.as_sat()); + let recommended_fee = if sats_per_vbyte < min_relay_fee { tracing::warn!( "Estimated fee of {} is smaller than the min relay fee, defaulting to min relay fee {}", @@ -482,6 +486,7 @@ fn estimate_fee( let amount = recommended_fee .map(bitcoin::Amount::from_sat) .context("Could not estimate tranasction fee.")?; + Ok(amount) } diff --git a/swap/src/monero/wallet.rs b/swap/src/monero/wallet.rs index a63ae4ff..955a12b1 100644 --- a/swap/src/monero/wallet.rs +++ b/swap/src/monero/wallet.rs @@ -157,12 +157,12 @@ impl Wallet { Err(error) => { tracing::warn!( address = %self.main_address, - "Transferring Monero back to default wallet failed. Error {:#}", error + "Failed to transfer Monero to default wallet: {:#}", error ); } }, Err(error) => { - tracing::warn!("Refreshing the generated wallet failed. Error {:#}", error); + tracing::warn!("Failed to refresh generated wallet: {:#}", error); } } @@ -192,7 +192,7 @@ impl Wallet { %amount, to = %public_spend_key, tx_id = %res.tx_hash, - "Sent transfer" + "Successfully initiated Monero transfer" ); Ok(TransferProof::new( @@ -202,7 +202,7 @@ impl Wallet { )) } - pub async fn watch_for_transfer(&self, request: WatchRequest) -> Result<()> { + pub async fn watch_for_transfer(&self, request: WatchRequest) -> Result<(), InsufficientFunds> { let WatchRequest { conf_target, public_view_key, @@ -314,7 +314,7 @@ where Err(error) => { tracing::debug!( %txid, - "Failed to retrieve tx from blockchain. Error {:#}", error + "Failed to retrieve tx from blockchain: {:#}", error ); continue; // treating every error as transient and retrying // is obviously wrong but the jsonrpc client is diff --git a/swap/src/monero/wallet_rpc.rs b/swap/src/monero/wallet_rpc.rs index 853ffdab..18d66064 100644 --- a/swap/src/monero/wallet_rpc.rs +++ b/swap/src/monero/wallet_rpc.rs @@ -128,7 +128,7 @@ impl WalletRpc { tracing::debug!( %port, - "Starting monero-wallet-rpc on" + "Starting monero-wallet-rpc" ); let network_flag = match network { diff --git a/swap/src/network/tor_transport.rs b/swap/src/network/tor_transport.rs index 9c1ad8d1..786056d8 100644 --- a/swap/src/network/tor_transport.rs +++ b/swap/src/network/tor_transport.rs @@ -42,7 +42,7 @@ impl Transport for TorDialOnlyTransport { } let dial_future = async move { - tracing::trace!("Connecting through Tor proxy to address: {}", addr); + tracing::trace!("Connecting through Tor proxy to address {}", addr); let stream = Socks5Stream::connect((Ipv4Addr::LOCALHOST, self.socks_port), address.to_string()) diff --git a/swap/src/protocol/alice/swap.rs b/swap/src/protocol/alice/swap.rs index da7cc099..b7765a38 100644 --- a/swap/src/protocol/alice/swap.rs +++ b/swap/src/protocol/alice/swap.rs @@ -231,10 +231,7 @@ where } }, Err(error) => { - tracing::error!( - "Publishing the redeem transaction failed. Error {:#}", - error - ); + tracing::error!("Failed to publish redeem transaction: {:#}", error); tx_lock_status .wait_until_confirmed_with(state3.cancel_timelock) .await?; @@ -247,8 +244,12 @@ where } }, Err(error) => { - tracing::error!( - "Constructing the redeem transaction failed. Attempting to wait for cancellation now. Error {:#}", error); + tracing::error!("Failed to construct redeem transaction: {:#}", error); + tracing::info!( + "Waiting for cancellation timelock ({}) to expire", + state3.cancel_timelock + ); + tx_lock_status .wait_until_confirmed_with(state3.cancel_timelock) .await?; @@ -360,10 +361,7 @@ where match punish { Ok(_) => AliceState::BtcPunished, Err(error) => { - tracing::warn!( - "Falling back to refund because punish transaction failed. Error {:#}", - error - ); + tracing::warn!("Failed to publish punish transaction: {:#}", error); // Upon punish failure we assume that the refund tx was included but we // missed seeing it. In case we fail to fetch the refund tx we fail @@ -372,6 +370,8 @@ where // because a punish tx failure is not recoverable (besides re-trying) if the // refund tx was not included. + tracing::info!("Falling back to refund"); + let published_refund_tx = bitcoin_wallet .get_raw_transaction(state3.tx_refund().txid()) .await?; diff --git a/swap/src/protocol/bob/swap.rs b/swap/src/protocol/bob/swap.rs index 9083b56e..cbff1c71 100644 --- a/swap/src/protocol/bob/swap.rs +++ b/swap/src/protocol/bob/swap.rs @@ -149,11 +149,13 @@ async fn next_state( received_xmr = monero_wallet.watch_for_transfer(watch_request) => { match received_xmr { Ok(()) => BobState::XmrLocked(state.xmr_locked(monero_wallet_restore_blockheight)), - Err(e) => { - tracing::warn!("Waiting for refund because insufficient Monero have been locked! {:#}", e); - tx_lock_status.wait_until_confirmed_with(state.cancel_timelock).await?; + Err(monero::InsufficientFunds { expected, actual }) => { + tracing::warn!("Insufficient Monero have been locked! Expected {} but got {}", expected, actual); + tracing::info!("Waiting for cancel timelock ({}) to expire", state.cancel_timelock); - BobState::CancelTimelockExpired(state.cancel()) + tx_lock_status.wait_until_confirmed_with(state.cancel_timelock).await?; + + BobState::CancelTimelockExpired(state.cancel()) }, } } @@ -229,7 +231,7 @@ async fn next_state( let tx_hashes = monero_wallet.sweep_all(monero_receive_address).await?; for tx_hash in tx_hashes { - tracing::info!(%monero_receive_address, txid=%tx_hash.0, "Sent XMR to"); + tracing::info!(%monero_receive_address, txid=%tx_hash.0, "Successfully transferred XMR to wallet"); } BobState::XmrRedeemed { diff --git a/swap/src/seed.rs b/swap/src/seed.rs index f5a65777..9e34c2db 100644 --- a/swap/src/seed.rs +++ b/swap/src/seed.rs @@ -64,7 +64,7 @@ impl Seed { return Self::from_file(&file_path); } - tracing::debug!("No seed file found, creating at: {}", file_path.display()); + tracing::debug!("No seed file found, creating at {}", file_path.display()); let random_seed = Seed::random()?; random_seed.write_to(file_path.to_path_buf())?; From 8f50eb2f3498c0457b84e636af75efba7ae1075c Mon Sep 17 00:00:00 2001 From: Thomas Eizinger Date: Wed, 7 Jul 2021 14:31:10 +1000 Subject: [PATCH 3/3] Utilize tracing's fields more --- swap/src/network/tor_transport.rs | 2 +- swap/src/protocol/alice/swap.rs | 4 ++-- swap/src/protocol/bob/swap.rs | 4 ++-- 3 files changed, 5 insertions(+), 5 deletions(-) diff --git a/swap/src/network/tor_transport.rs b/swap/src/network/tor_transport.rs index 786056d8..04484cd3 100644 --- a/swap/src/network/tor_transport.rs +++ b/swap/src/network/tor_transport.rs @@ -42,7 +42,7 @@ impl Transport for TorDialOnlyTransport { } let dial_future = async move { - tracing::trace!("Connecting through Tor proxy to address {}", addr); + tracing::trace!(address = %addr, "Establishing connection through Tor proxy"); let stream = Socks5Stream::connect((Ipv4Addr::LOCALHOST, self.socks_port), address.to_string()) diff --git a/swap/src/protocol/alice/swap.rs b/swap/src/protocol/alice/swap.rs index b7765a38..b09658f0 100644 --- a/swap/src/protocol/alice/swap.rs +++ b/swap/src/protocol/alice/swap.rs @@ -246,8 +246,8 @@ where Err(error) => { tracing::error!("Failed to construct redeem transaction: {:#}", error); tracing::info!( - "Waiting for cancellation timelock ({}) to expire", - state3.cancel_timelock + timelock = %state3.cancel_timelock, + "Waiting for cancellation timelock to expire", ); tx_lock_status diff --git a/swap/src/protocol/bob/swap.rs b/swap/src/protocol/bob/swap.rs index cbff1c71..0ebab92b 100644 --- a/swap/src/protocol/bob/swap.rs +++ b/swap/src/protocol/bob/swap.rs @@ -150,8 +150,8 @@ async fn next_state( match received_xmr { Ok(()) => BobState::XmrLocked(state.xmr_locked(monero_wallet_restore_blockheight)), Err(monero::InsufficientFunds { expected, actual }) => { - tracing::warn!("Insufficient Monero have been locked! Expected {} but got {}", expected, actual); - tracing::info!("Waiting for cancel timelock ({}) to expire", state.cancel_timelock); + tracing::warn!(%expected, %actual, "Insufficient Monero have been locked!"); + tracing::info!(timelock = %state.cancel_timelock, "Waiting for cancel timelock to expire"); tx_lock_status.wait_until_confirmed_with(state.cancel_timelock).await?;