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

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

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

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

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!(
+                    tracing::info!("Deposited amount is less than `min_quantity`",);
-                        %minimum_amount,
-                        %deposit_address,
-                        "Please deposit more, not enough BTC to trigger swap with",
-                    );
                 }
             }
 

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();
+        let fee = spending_fee.as_sat();
-        tracing::debug!(%spending_fee, "Redeem tx fee");
         let tx_out = TxOut {
-            value: self.inner.clone().extract_tx().output[self.lock_output_vout()].value
+            value: self.inner.clone().extract_tx().output[self.lock_output_vout()].value - fee,
-                - spending_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 {
+                        match (last_status, new_status) {
-                            tracing::debug!(%txid, status = %new_status, "Transaction");
+                            (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,
-        weight,
+        %fee_rate,
-        fee_rate,
+        %sats_per_vbyte,
-        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!("Connecting through Tor proxy to address {}", addr);
 
             let stream =
                 Socks5Stream::connect((Ipv4Addr::LOCALHOST, self.socks_port), address.to_string())

swap/src/protocol/alice/swap.rs

@@ -231,10 +231,7 @@ where
                             }
                         },
                         Err(error) => {
-                            tracing::error!(
+                            tracing::error!("Failed to publish redeem transaction: {:#}", error);
-                                "Publishing the redeem transaction failed. Error {:#}",
-                                error
-                            );
                             tx_lock_status
                                 .wait_until_confirmed_with(state3.cancel_timelock)
                                 .await?;
@@ -247,8 +244,12 @@ where
                         }
                     },
                     Err(error) => {
-                        tracing::error!(
+                        tracing::error!("Failed to construct redeem transaction: {:#}", error);
-                            "Constructing the redeem transaction failed. Attempting to wait for cancellation now. Error {:#}", 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!(
+                    tracing::warn!("Failed to publish punish transaction: {:#}", error);
-                        "Falling back to refund because punish transaction failed. Error {:#}",
-                        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?;

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) => {
+                            Err(monero::InsufficientFunds { expected, actual }) => {
-                                 tracing::warn!("Waiting for refund because insufficient Monero have been locked! {:#}", e);
+                                tracing::warn!("Insufficient Monero have been locked! Expected {} but got {}", expected, actual);
-                                 tx_lock_status.wait_until_confirmed_with(state.cancel_timelock).await?;
+                                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 {

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