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())?;