Merge #520

520: Cli json logging r=da-kami a=da-kami

Combining `--json` with the debug file logger was a pita, so I stopped and went for a simpler approach:

If `--json` is given we just log to terminal - **no** logfiles will be created in `{data-dir}/logs`. 
The `--debug` flag applies to `--json` (i.e. if not given it will just print json on info level). We could change that to automatically fallback to debug - could add a `required_if` dependency via strucopt/clap but I did not want to invest more time into thinking about this.

Note on extending binary functionality:
As discussed with @thomaseizinger recently, we will have to think about multiple binaries soon, i.e. a binary that focuses to be used to building on top of it (that always logs json) and potientially keeping a simple CLI that is more user friendly. This also goes towards more clearly separating the application code from re-usable protocol / network code. 


Co-authored-by: Daniel Karzel <daniel@comit.network>

swap/src/bin/swap.rs

@@ -45,6 +45,7 @@ async fn main() -> Result<()> {
         env_config,
         data_dir,
         debug,
+        json,
         cmd,
     } = match parse_args_and_apply_defaults(env::args_os()) {
         Ok(args) => args,
@@ -76,7 +77,7 @@ async fn main() -> Result<()> {
         } => {
             let swap_id = Uuid::new_v4();
 
-            cli::tracing::init(debug, data_dir.join("logs"), swap_id)?;
+            cli::tracing::init(debug, json, data_dir.join("logs"), swap_id)?;
             let db = Database::open(data_dir.join("database").as_path())
                 .context("Failed to open database")?;
             let seed = Seed::from_file_or_generate(data_dir.as_path())
@@ -99,6 +100,8 @@ async fn main() -> Result<()> {
                 .behaviour_mut()
                 .add_address(seller_peer_id, seller_addr);
 
+            let our_peer_id = swarm.local_peer_id();
+            tracing::debug!(peer_id = %our_peer_id, "Initializing network module");
             let (event_loop, mut event_loop_handle) = EventLoop::new(
                 swap_id,
                 swarm,
@@ -109,7 +112,7 @@ async fn main() -> Result<()> {
             let event_loop = tokio::spawn(event_loop.run());
 
             let max_givable = || bitcoin_wallet.max_giveable(TxLock::script_size());
-            let (send_bitcoin, fees) = determine_btc_to_swap(
+            let (amount, fees) = determine_btc_to_swap(
                 event_loop_handle.request_quote(),
                 bitcoin_wallet.new_address(),
                 || bitcoin_wallet.balance(),
@@ -118,7 +121,7 @@ async fn main() -> Result<()> {
             )
             .await?;
 
-            info!("Swapping {} with {} fees", send_bitcoin, fees);
+            info!(%amount, %fees, %swap_id,  "Swapping");
 
             db.insert_peer_id(swap_id, seller_peer_id).await?;
 
@@ -130,7 +133,7 @@ async fn main() -> Result<()> {
                 env_config,
                 event_loop_handle,
                 monero_receive_address,
-                send_bitcoin,
+                amount,
             );
 
             tokio::select! {
@@ -167,7 +170,7 @@ async fn main() -> Result<()> {
             monero_daemon_address,
             tor_socks5_port,
         } => {
-            cli::tracing::init(debug, data_dir.join("logs"), swap_id)?;
+            cli::tracing::init(debug, json, data_dir.join("logs"), swap_id)?;
             let db = Database::open(data_dir.join("database").as_path())
                 .context("Failed to open database")?;
             let seed = Seed::from_file_or_generate(data_dir.as_path())
@@ -192,8 +195,8 @@ async fn main() -> Result<()> {
             let seller_peer_id = db.get_peer_id(swap_id)?;
 
             let mut swarm = swarm::bob(&seed, seller_peer_id, tor_socks5_port).await?;
-            let bob_peer_id = swarm.local_peer_id();
-            tracing::debug!("Our peer-id: {}", bob_peer_id);
+            let our_peer_id = swarm.local_peer_id();
+            tracing::debug!(peer_id = %our_peer_id, "Initializing network module");
             swarm
                 .behaviour_mut()
                 .add_address(seller_peer_id, seller_addr);
@@ -232,7 +235,7 @@ async fn main() -> Result<()> {
             bitcoin_electrum_rpc_url,
             bitcoin_target_block,
         } => {
-            cli::tracing::init(debug, data_dir.join("logs"), swap_id)?;
+            cli::tracing::init(debug, json, data_dir.join("logs"), swap_id)?;
             let db = Database::open(data_dir.join("database").as_path())
                 .context("Failed to open database")?;
             let seed = Seed::from_file_or_generate(data_dir.as_path())
@@ -264,7 +267,7 @@ async fn main() -> Result<()> {
             bitcoin_electrum_rpc_url,
             bitcoin_target_block,
         } => {
-            cli::tracing::init(debug, data_dir.join("logs"), swap_id)?;
+            cli::tracing::init(debug, json, data_dir.join("logs"), swap_id)?;
             let db = Database::open(data_dir.join("database").as_path())
                 .context("Failed to open database")?;
             let seed = Seed::from_file_or_generate(data_dir.as_path())
@@ -352,10 +355,10 @@ where
     debug!("Requesting quote");
     let bid_quote = bid_quote.await?;
     info!(
+        price = %bid_quote.price,
         minimum_amount = %bid_quote.min_quantity,
         maximum_amount = %bid_quote.max_quantity,
-        "Received quote: 1 XMR ~ {}",
-        bid_quote.price
+        "Received quote: 1 XMR ~ ",
     );
 
     let mut current_maximum_giveable = max_giveable().await?;

swap/src/cli/command.rs

@@ -29,6 +29,7 @@ const DEFAULT_TOR_SOCKS5_PORT: &str = "9050";
 pub struct Arguments {
     pub env_config: env::Config,
     pub debug: bool,
+    pub json: bool,
     pub data_dir: PathBuf,
     pub cmd: Command,
 }
@@ -42,6 +43,7 @@ where
     let args = RawArguments::from_clap(&matches);
 
     let debug = args.debug;
+    let json = args.json;
     let is_testnet = args.testnet;
     let data = args.data;
 
@@ -63,6 +65,7 @@ where
         } => Ok(Arguments {
             env_config: env_config_from(is_testnet),
             debug,
+            json,
             data_dir: data::data_dir_from(data, is_testnet)?,
             cmd: Command::BuyXmr {
                 seller_peer_id,
@@ -86,6 +89,7 @@ where
         RawCommand::History => Ok(Arguments {
             env_config: env_config_from(is_testnet),
             debug,
+            json,
             data_dir: data::data_dir_from(data, is_testnet)?,
             cmd: Command::History,
         }),
@@ -106,6 +110,7 @@ where
         } => Ok(Arguments {
             env_config: env_config_from(is_testnet),
             debug,
+            json,
             data_dir: data::data_dir_from(data, is_testnet)?,
             cmd: Command::Resume {
                 swap_id,
@@ -134,6 +139,7 @@ where
         } => Ok(Arguments {
             env_config: env_config_from(is_testnet),
             debug,
+            json,
             data_dir: data::data_dir_from(data, is_testnet)?,
             cmd: Command::Cancel {
                 swap_id,
@@ -156,6 +162,7 @@ where
         } => Ok(Arguments {
             env_config: env_config_from(is_testnet),
             debug,
+            json,
             data_dir: data::data_dir_from(data, is_testnet)?,
             cmd: Command::Refund {
                 swap_id,
@@ -225,6 +232,13 @@ pub struct RawArguments {
     #[structopt(long, help = "Activate debug logging.")]
     pub debug: bool,
 
+    #[structopt(
+        short,
+        long = "json",
+        help = "Changes the log messages to json vs plain-text. This can be helpful to simplify automated log analyses."
+    )]
+    pub json: bool,
+
     #[structopt(subcommand)]
     pub cmd: RawCommand,
 }
@@ -765,11 +779,77 @@ mod tests {
         assert_eq!(args, Arguments::resume_testnet_defaults().with_debug());
     }
 
+    #[test]
+    fn given_with_json_then_json_set() {
+        let raw_ars = vec![
+            BINARY_NAME,
+            "--json",
+            "buy-xmr",
+            "--receive-address",
+            MONERO_MAINNET_ADDRESS,
+            "--seller-addr",
+            MUTLI_ADDRESS,
+            "--seller-peer-id",
+            PEER_ID,
+        ];
+
+        let args = parse_args_and_apply_defaults(raw_ars).unwrap();
+        assert_eq!(args, Arguments::buy_xmr_mainnet_defaults().with_json());
+
+        let raw_ars = vec![
+            BINARY_NAME,
+            "--testnet",
+            "--json",
+            "buy-xmr",
+            "--receive-address",
+            MONERO_STAGENET_ADDRESS,
+            "--seller-addr",
+            MUTLI_ADDRESS,
+            "--seller-peer-id",
+            PEER_ID,
+        ];
+
+        let args = parse_args_and_apply_defaults(raw_ars).unwrap();
+        assert_eq!(args, Arguments::buy_xmr_testnet_defaults().with_json());
+
+        let raw_ars = vec![
+            BINARY_NAME,
+            "--json",
+            "resume",
+            "--swap-id",
+            SWAP_ID,
+            "--receive-address",
+            MONERO_MAINNET_ADDRESS,
+            "--seller-addr",
+            MUTLI_ADDRESS,
+        ];
+
+        let args = parse_args_and_apply_defaults(raw_ars).unwrap();
+        assert_eq!(args, Arguments::resume_mainnet_defaults().with_json());
+
+        let raw_ars = vec![
+            BINARY_NAME,
+            "--testnet",
+            "--json",
+            "resume",
+            "--swap-id",
+            SWAP_ID,
+            "--receive-address",
+            MONERO_STAGENET_ADDRESS,
+            "--seller-addr",
+            MUTLI_ADDRESS,
+        ];
+
+        let args = parse_args_and_apply_defaults(raw_ars).unwrap();
+        assert_eq!(args, Arguments::resume_testnet_defaults().with_json());
+    }
+
     impl Arguments {
         pub fn buy_xmr_testnet_defaults() -> Self {
             Self {
                 env_config: env::Testnet::get_config(),
                 debug: false,
+                json: false,
                 data_dir: data_dir_path_cli().join(TESTNET),
                 cmd: Command::BuyXmr {
                     seller_peer_id: PeerId::from_str(PEER_ID).unwrap(),
@@ -789,6 +869,7 @@ mod tests {
             Self {
                 env_config: env::Mainnet::get_config(),
                 debug: false,
+                json: false,
                 data_dir: data_dir_path_cli().join(MAINNET),
                 cmd: Command::BuyXmr {
                     seller_peer_id: PeerId::from_str(PEER_ID).unwrap(),
@@ -807,6 +888,7 @@ mod tests {
             Self {
                 env_config: env::Testnet::get_config(),
                 debug: false,
+                json: false,
                 data_dir: data_dir_path_cli().join(TESTNET),
                 cmd: Command::Resume {
                     swap_id: Uuid::from_str(SWAP_ID).unwrap(),
@@ -826,6 +908,7 @@ mod tests {
             Self {
                 env_config: env::Mainnet::get_config(),
                 debug: false,
+                json: false,
                 data_dir: data_dir_path_cli().join(MAINNET),
                 cmd: Command::Resume {
                     swap_id: Uuid::from_str(SWAP_ID).unwrap(),
@@ -844,6 +927,7 @@ mod tests {
             Self {
                 env_config: env::Testnet::get_config(),
                 debug: false,
+                json: false,
                 data_dir: data_dir_path_cli().join(TESTNET),
                 cmd: Command::Cancel {
                     swap_id: Uuid::from_str(SWAP_ID).unwrap(),
@@ -859,6 +943,7 @@ mod tests {
             Self {
                 env_config: env::Mainnet::get_config(),
                 debug: false,
+                json: false,
                 data_dir: data_dir_path_cli().join(MAINNET),
                 cmd: Command::Cancel {
                     swap_id: Uuid::from_str(SWAP_ID).unwrap(),
@@ -873,6 +958,7 @@ mod tests {
             Self {
                 env_config: env::Testnet::get_config(),
                 debug: false,
+                json: false,
                 data_dir: data_dir_path_cli().join(TESTNET),
                 cmd: Command::Refund {
                     swap_id: Uuid::from_str(SWAP_ID).unwrap(),
@@ -888,6 +974,7 @@ mod tests {
             Self {
                 env_config: env::Mainnet::get_config(),
                 debug: false,
+                json: false,
                 data_dir: data_dir_path_cli().join(MAINNET),
                 cmd: Command::Refund {
                     swap_id: Uuid::from_str(SWAP_ID).unwrap(),
@@ -907,6 +994,11 @@ mod tests {
             self.debug = true;
             self
         }
+
+        pub fn with_json(mut self) -> Self {
+            self.json = true;
+            self
+        }
     }
 
     fn data_dir_path_cli() -> PathBuf {

swap/src/cli/tracing.rs

@@ -5,30 +5,48 @@ use tracing::{Event, Level, Subscriber};
 use tracing_subscriber::fmt::format::{DefaultFields, Format};
 use tracing_subscriber::fmt::time::ChronoLocal;
 use tracing_subscriber::layer::{Context, SubscriberExt};
-use tracing_subscriber::{fmt, EnvFilter, Layer, Registry};
+use tracing_subscriber::{fmt, EnvFilter, FmtSubscriber, Layer, Registry};
 use uuid::Uuid;
 
-pub fn init(debug: bool, dir: impl AsRef<Path>, swap_id: Uuid) -> Result<()> {
-    let level_filter = EnvFilter::try_new("swap=debug")?;
+pub fn init(debug: bool, json: bool, dir: impl AsRef<Path>, swap_id: Uuid) -> Result<()> {
+    if json {
+        let level = if debug { Level::DEBUG } else { Level::INFO };
 
-    let registry = Registry::default().with(level_filter);
+        let is_terminal = atty::is(atty::Stream::Stderr);
 
-    let appender = tracing_appender::rolling::never(dir, format!("swap-{}.log", swap_id));
-    let (appender, guard) = tracing_appender::non_blocking(appender);
+        FmtSubscriber::builder()
+            .with_env_filter(format!("swap={}", level))
+            .with_writer(std::io::stderr)
+            .with_ansi(is_terminal)
+            .with_timer(ChronoLocal::with_format("%F %T".to_owned()))
+            .with_target(false)
+            .json()
+            .init();
 
-    std::mem::forget(guard);
+        Ok(())
+    } else {
+        let level_filter = EnvFilter::try_new("swap=debug")?;
 
-    let file_logger = fmt::layer()
-        .with_ansi(false)
-        .with_target(false)
-        .with_writer(appender);
+        let registry = Registry::default().with(level_filter);
 
-    if debug {
-        set_global_default(registry.with(file_logger).with(debug_terminal_printer()))?;
-    } else {
-        set_global_default(registry.with(file_logger).with(info_terminal_printer()))?;
+        let appender = tracing_appender::rolling::never(dir, format!("swap-{}.log", swap_id));
+        let (appender, guard) = tracing_appender::non_blocking(appender);
+
+        std::mem::forget(guard);
+
+        let file_logger = fmt::layer()
+            .with_ansi(false)
+            .with_target(false)
+            .with_writer(appender);
+
+        if debug {
+            set_global_default(registry.with(file_logger).with(debug_terminal_printer()))?;
+        } else {
+            set_global_default(registry.with(file_logger).with(info_terminal_printer()))?;
+        }
+
+        Ok(())
     }
-    Ok(())
 }
 
 pub struct StdErrPrinter<L> {

swap/src/protocol/bob/swap.rs

@@ -61,7 +61,7 @@ async fn next_state(
     env_config: &Config,
     receive_monero_address: monero::Address,
 ) -> Result<BobState> {
-    tracing::trace!("Current state: {}", state);
+    tracing::trace!(%state, "Advancing state");
 
     Ok(match state {
         BobState::Started { btc_amount } => {
@@ -152,7 +152,7 @@ async fn next_state(
                         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);
+                                 tracing::warn!("Waiting for refund because insufficient Monero have been locked! {:#}", e);
                                  tx_lock_status.wait_until_confirmed_with(state.cancel_timelock).await?;
 
                                  BobState::CancelTimelockExpired(state.cancel())
@@ -205,10 +205,10 @@ async fn next_state(
         BobState::BtcRedeemed(state) => {
             let (spend_key, view_key) = state.xmr_keys();
 
-            let generated_wallet_file_name = swap_id.to_string();
+            let wallet_file_name = swap_id.to_string();
             if let Err(e) = monero_wallet
                 .create_from_and_load(
-                    generated_wallet_file_name.clone(),
+                    wallet_file_name.clone(),
                     spend_key,
                     view_key,
                     state.monero_wallet_restore_blockheight,
@@ -219,11 +219,10 @@ async fn next_state(
                 // exist! This is a very unlikely scenario, but if we don't take care of it we
                 // might not be able to ever transfer the Monero.
                 tracing::warn!("Failed to generate monero wallet from keys: {:#}", e);
-                tracing::info!(
-                    "Falling back to trying to open the the wallet if it already exists: {}",
-                    swap_id
+                tracing::info!(%wallet_file_name,
+                    "Falling back to trying to open the the wallet if it already exists",
                 );
-                monero_wallet.open(generated_wallet_file_name).await?;
+                monero_wallet.open(wallet_file_name).await?;
             }
 
             // Ensure that the generated wallet is synced so we have a proper balance
@@ -232,7 +231,7 @@ async fn next_state(
             let tx_hashes = monero_wallet.sweep_all(receive_monero_address).await?;
 
             for tx_hash in tx_hashes {
-                tracing::info!("Sent XMR to {} in tx {}", receive_monero_address, tx_hash.0);
+                tracing::info!(%receive_monero_address, txid=%tx_hash.0, "Sent XMR to");
             }
 
             BobState::XmrRedeemed {
@@ -281,7 +280,7 @@ pub async fn request_price_and_setup(
 ) -> Result<bob::state::State2> {
     let xmr = event_loop_handle.request_spot_price(btc).await?;
 
-    tracing::info!("Spot price for {} is {}", btc, xmr);
+    tracing::info!(%btc, %xmr, "Spot price");
 
     let state0 = State0::new(
         swap_id,