Merge #607

607: Tidy up tracing statements r=da-kami a=thomaseizinger



Co-authored-by: Thomas Eizinger <thomas@eizinger.io>

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,9 +177,9 @@ pub struct ConfigNotInitialized {}
 
 pub fn read_config(config_path: PathBuf) -> Result<Result<Config, ConfigNotInitialized>> {
     if config_path.exists() {
-        info!(
+        tracing::info!(
             path = %config_path.display(),
-            "Using config file at",
+            "Reading config file",
         );
     } else {
         return Ok(Err(ConfigNotInitialized {}));
@@ -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",
     );

swap/src/asb/event_loop.rs

@@ -174,13 +174,13 @@ where
                             let _ = self.handle_execution_setup_done(peer_id, swap_id, state3).await;
                         }
                         SwarmEvent::Behaviour(OutEvent::SwapDeclined { peer, error }) => {
-                            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);
             }
         }
     }

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,11 +89,6 @@ async fn main() -> Result<()> {
         ));
     }
 
-    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())
@@ -110,17 +104,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())?;
@@ -130,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?;
@@ -196,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)
                             }
                         }
                     });
@@ -314,7 +308,7 @@ async fn init_bitcoin_wallet(
     seed: &Seed,
     env_config: swap::env::Config,
 ) -> Result<bitcoin::Wallet> {
-    debug!("Opening Bitcoin wallet");
+    tracing::debug!("Opening Bitcoin wallet");
     let wallet_dir = config.data.dir.join("wallet");
 
     let wallet = bitcoin::Wallet::new(
@@ -336,7 +330,7 @@ async fn init_monero_wallet(
     config: &Config,
     env_config: swap::env::Config,
 ) -> Result<monero::Wallet> {
-    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(),
@@ -384,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)

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,  "Starting new swap");
 
             db.insert_peer_id(swap_id, seller_peer_id).await?;
             db.insert_monero_address(swap_id, monero_receive_address)
@@ -185,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
@@ -242,10 +241,10 @@ 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!(
-                    "The Cancel Transaction cannot be published yet, because the timelock has not expired. Please try again later"
+                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<Output = Result<()>>,
     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,15 +414,15 @@ where
             eprintln!("{}", qr_code(&deposit_address)?);
         }
 
-        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?;
@@ -435,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`",);
                 }
             }
 

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<CancelTimelock> 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

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,

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<bitcoin::Amount> {
         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)
 }
 

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

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 {

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

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<LR>(swap: Swap, rate_service: LR) -> Result<AliceState>
@@ -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,10 +231,7 @@ where
                             }
                         },
                         Err(error) => {
-                            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?;
@@ -248,8 +244,12 @@ where
                         }
                     },
                     Err(error) => {
-                        error!(
-                            "Constructing the redeem transaction failed. Attempting to wait for cancellation now. Error {:#}", error);
+                        tracing::error!("Failed to construct redeem transaction: {:#}", error);
+                        tracing::info!(
+                            timelock = %state3.cancel_timelock,
+                            "Waiting for cancellation timelock to expire",
+                        );
+
                         tx_lock_status
                             .wait_until_confirmed_with(state3.cancel_timelock)
                             .await?;
@@ -361,10 +361,7 @@ where
             match punish {
                 Ok(_) => AliceState::BtcPunished,
                 Err(error) => {
-                    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
@@ -373,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?;

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!(%expected, %actual, "Insufficient Monero have been locked!");
+                                tracing::info!(timelock = %state.cancel_timelock, "Waiting for cancel timelock to expire");
 
-                                 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 {

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