Merge #474

474: Add more log details r=bonomat a=bonomat

Resolves #448 

1. The first commit adds an additional log statement of the exchange rate for each state-update. This is useful because it allows us to measure profitability easily, i.e. by knowing what was the exchange rate when the swap was started and what was it when it was finalized.
2. The second commit changes a bunch of log messages. 
3. The third commit is adds a new commandline flag to toggle json format.




Co-authored-by: Philipp Hoenisch <[email protected]>
Co-authored-by: Philipp Hoenisch <[email protected]>

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
 

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"

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.",

swap/src/asb/config.rs

@@ -105,8 +105,8 @@ pub struct ConfigNotInitialized {}
 pub fn read_config(config_path: PathBuf) -> Result<Result<Config, ConfigNotInitialized>> {
     if config_path.exists() {
         info!(
-            "Using config file at default path: {}",
-            config_path.display()
+            path = %config_path.display(),
+            "Using config file at",
         );
     } 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(())
 }

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,15 +14,18 @@ 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!("Initialized tracing with level: {}", level);
+    tracing::info!(%level, "Initialized tracing");
 
     Ok(())
 }

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]
@@ -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
@@ -64,8 +63,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 +80,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 at",
                 )
             } else {
-                info!("Monero balance: {}", monero_balance);
+                info!(%monero_balance, "Initialized Monero wallet");
             }
 
             let kraken_price_updates = kraken::connect()?;
@@ -104,14 +104,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
                 }
             };
@@ -140,29 +140,30 @@ 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,
             )
             .unwrap();
 
             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)
+                                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, "Swap failed. Error {:#}", error)
                             }
                         }
                     });
                 }
             });
 
-            info!("Our peer id is {}", event_loop.peer_id());
+            info!(perr_id = %event_loop.peer_id(), "Our peer id");
 
             event_loop.run().await;
         }
@@ -202,7 +203,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 },
@@ -273,6 +277,7 @@ async fn init_bitcoin_wallet(
     seed: &Seed,
     env_config: swap::env::Config,
 ) -> Result<bitcoin::Wallet> {
+    debug!("Opening Bitcoin wallet");
     let wallet_dir = config.data.dir.join("wallet");
 
     let wallet = bitcoin::Wallet::new(
@@ -294,6 +299,7 @@ async fn init_monero_wallet(
     config: &Config,
     env_config: swap::env::Config,
 ) -> Result<monero::Wallet> {
+    debug!("Opening Monero wallet");
     let wallet = monero::Wallet::open_or_create(
         config.monero.wallet_rpc_url.clone(),
         DEFAULT_WALLET_NAME.to_string(),
@@ -340,7 +346,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)

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"
                 ),
             }
         }

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, "Failed to get status of script. Error {:#}", error);
                                 return;
                             }
                         };
 
                         if Some(new_status) != last_status {
-                            tracing::debug!(%txid, "Transaction is {}", new_status);
+                            tracing::debug!(%txid, status = %new_status, "Transaction");
                         }
+
                         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<()> {
@@ -589,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 {
@@ -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)?;
         }

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);
         }

swap/src/kraken.rs

@@ -43,8 +43,12 @@ pub fn connect() -> Result<PriceUpdates> {
                 }
             },
             |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;
 
@@ -183,9 +187,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::<wire::PriceUpdate>(&msg) {
                 Ok(ticker) => ticker,
-                Err(e) => {
-                    tracing::warn!(%e, "Failed to deserialize message '{}' as ticker update", msg);
-
+                Err(error) => {
+                    tracing::warn!(%msg, "Failed to deserialize message as ticker update. Error {:#}", error);
                     return Ok(None);
                 }
             },