From 0187d9ef4fd81239524e7e235dfbe4a2021a7727 Mon Sep 17 00:00:00 2001 From: Daniel Karzel Date: Thu, 20 May 2021 16:36:01 +1000 Subject: [PATCH 1/2] Introduce `--json` flag for the CLI When `--json` is used the CLI does not log to file, but only on the command line in json output. --- swap/src/bin/swap.rs | 9 ++-- swap/src/cli/command.rs | 92 +++++++++++++++++++++++++++++++++++++++++ swap/src/cli/tracing.rs | 52 +++++++++++++++-------- 3 files changed, 132 insertions(+), 21 deletions(-) diff --git a/swap/src/bin/swap.rs b/swap/src/bin/swap.rs index 28f91ba4..d5e52d84 100644 --- a/swap/src/bin/swap.rs +++ b/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()) @@ -167,7 +168,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()) @@ -232,7 +233,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 +265,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()) diff --git a/swap/src/cli/command.rs b/swap/src/cli/command.rs index 3f8a8850..d3ec4313 100644 --- a/swap/src/cli/command.rs +++ b/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 { diff --git a/swap/src/cli/tracing.rs b/swap/src/cli/tracing.rs index 82ee2594..733b263e 100644 --- a/swap/src/cli/tracing.rs +++ b/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, swap_id: Uuid) -> Result<()> { - let level_filter = EnvFilter::try_new("swap=debug")?; +pub fn init(debug: bool, json: bool, dir: impl AsRef, 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); - - 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()))?; + Ok(()) } else { - set_global_default(registry.with(file_logger).with(info_terminal_printer()))?; + let level_filter = EnvFilter::try_new("swap=debug")?; + + let registry = Registry::default().with(level_filter); + + 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 { From fb9fb21c2b158e43444d46050237b4dc25ed7d14 Mon Sep 17 00:00:00 2001 From: Daniel Karzel Date: Fri, 21 May 2021 09:53:06 +1000 Subject: [PATCH 2/2] CLI log statements to be more JSON friendly Values to be logged as fields. Upon starting a swap we print the swap-id as well. --- swap/src/bin/swap.rs | 16 +++++++++------- swap/src/protocol/bob/swap.rs | 19 +++++++++---------- 2 files changed, 18 insertions(+), 17 deletions(-) diff --git a/swap/src/bin/swap.rs b/swap/src/bin/swap.rs index d5e52d84..eb7523a3 100644 --- a/swap/src/bin/swap.rs +++ b/swap/src/bin/swap.rs @@ -100,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, @@ -110,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(), @@ -119,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?; @@ -131,7 +133,7 @@ async fn main() -> Result<()> { env_config, event_loop_handle, monero_receive_address, - send_bitcoin, + amount, ); tokio::select! { @@ -193,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); @@ -353,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?; diff --git a/swap/src/protocol/bob/swap.rs b/swap/src/protocol/bob/swap.rs index 07425f53..5cdf7165 100644 --- a/swap/src/protocol/bob/swap.rs +++ b/swap/src/protocol/bob/swap.rs @@ -61,7 +61,7 @@ async fn next_state( env_config: &Config, receive_monero_address: monero::Address, ) -> Result { - 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 { 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,