Merge #397

397: Always log at debug level to file r=rishflab a=rishflab

WILL SQUASH DOWN TO 3 COMMITS WHEN APPROVED!

Log at debug level to file

EnvFilter is applied globally. This means you cannot log at INFO level 
to the terminal and at DEBUG level to log files. To get a around this 
limitation I had to implement the layer trait on a new type and filter 
in the on_event() trait method. Each swap has its own log file denoted 
by its swap_id. The logger appends to the existing file when resuming a 
swap.

Closes #278 


I think the `DebugTerminalPritner` and `InfoTerminalPrinter` could be consolidated with some effort with some generics wizardry. It works for now and I think it can be done later. I wish in general there was a cleaner way to do this.
 

Co-authored-by: rishflab <rishflab@hotmail.com>

Cargo.lock

@@ -620,6 +620,7 @@ dependencies = [
  "libc",
  "num-integer",
  "num-traits",
+ "time 0.1.43",
  "winapi 0.3.9",
 ]
 
@@ -722,6 +723,16 @@ dependencies = [
  "cfg-if 1.0.0",
 ]
 
+[[package]]
+name = "crossbeam-channel"
+version = "0.5.0"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "dca26ee1f8d361640700bde38b2c37d8c22b3ce2d360e1fc1c74ea4b0aa7d775"
+dependencies = [
+ "cfg-if 1.0.0",
+ "crossbeam-utils",
+]
+
 [[package]]
 name = "crossbeam-epoch"
 version = "0.9.3"
@@ -3614,6 +3625,7 @@ dependencies = [
  "tokio-util",
  "toml",
  "tracing",
+ "tracing-appender",
  "tracing-futures",
  "tracing-subscriber",
  "url 2.2.1",
@@ -3958,6 +3970,17 @@ dependencies = [
  "tracing-core",
 ]
 
+[[package]]
+name = "tracing-appender"
+version = "0.1.2"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "9965507e507f12c8901432a33e31131222abac31edd90cabbcf85cf544b7127a"
+dependencies = [
+ "chrono",
+ "crossbeam-channel",
+ "tracing-subscriber",
+]
+
 [[package]]
 name = "tracing-attributes"
 version = "0.1.15"

swap/Cargo.toml

@@ -53,6 +53,7 @@ tokio-tungstenite = { version = "0.14", features = [ "rustls-tls" ] }
 tokio-util = { version = "0.6", features = ["io"] }
 toml = "0.5"
 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"] }
 url = { version = "2", features = ["serde"] }

swap/src/asb.rs

@@ -1,5 +1,6 @@
 pub mod command;
 pub mod config;
 mod rate;
+pub mod tracing;
 
 pub use rate::Rate;

swap/src/asb/tracing.rs

@@ -2,7 +2,7 @@ use anyhow::Result;
 use tracing_subscriber::filter::LevelFilter;
 use tracing_subscriber::FmtSubscriber;
 
-pub fn init_tracing(level: LevelFilter) -> Result<()> {
+pub fn init(level: LevelFilter) -> Result<()> {
     if level == LevelFilter::OFF {
         return Ok(());
     }

swap/src/bin/asb.rs

@@ -29,8 +29,7 @@ use swap::network::swarm;
 use swap::protocol::alice::event_loop::KrakenRate;
 use swap::protocol::alice::{run, Behaviour, EventLoop};
 use swap::seed::Seed;
-use swap::trace::init_tracing;
-use swap::{bitcoin, env, kraken, monero};
+use swap::{asb, bitcoin, env, kraken, monero};
 use tracing::{info, warn};
 use tracing_subscriber::filter::LevelFilter;
 
@@ -41,7 +40,7 @@ const DEFAULT_WALLET_NAME: &str = "asb-wallet";
 
 #[tokio::main]
 async fn main() -> Result<()> {
-    init_tracing(LevelFilter::DEBUG).expect("initialize tracing");
+    asb::tracing::init(LevelFilter::DEBUG).expect("initialize tracing");
 
     let opt = Arguments::from_args();
 

swap/src/bin/swap.rs

@@ -21,7 +21,7 @@ use std::sync::Arc;
 use std::time::Duration;
 use structopt::StructOpt;
 use swap::bitcoin::{Amount, TxLock};
-use swap::cli::command::{Arguments, Command, Data, MoneroParams};
+use swap::cli::command::{Arguments, Command, MoneroParams};
 use swap::database::Database;
 use swap::env::{Config, GetConfig};
 use swap::network::quote::BidQuote;
@@ -29,9 +29,8 @@ use swap::network::swarm;
 use swap::protocol::bob;
 use swap::protocol::bob::{Behaviour, Builder, EventLoop};
 use swap::seed::Seed;
-use swap::{bitcoin, env, monero};
-use tracing::{debug, error, info, warn, Level};
-use tracing_subscriber::FmtSubscriber;
+use swap::{bitcoin, cli, env, monero};
+use tracing::{debug, error, info, warn};
 use url::Url;
 use uuid::Uuid;
 
@@ -40,46 +39,9 @@ extern crate prettytable;
 
 #[tokio::main]
 async fn main() -> Result<()> {
-    let args = Arguments::from_args();
-
-    let is_terminal = atty::is(atty::Stream::Stderr);
-    let base_subscriber = |level| {
-        FmtSubscriber::builder()
-            .with_writer(std::io::stderr)
-            .with_ansi(is_terminal)
-            .with_target(false)
-            .with_env_filter(format!("swap={}", level))
-    };
-
-    if args.debug {
-        let subscriber = base_subscriber(Level::DEBUG)
-            .with_timer(tracing_subscriber::fmt::time::ChronoLocal::with_format(
-                "%F %T".to_owned(),
-            ))
-            .finish();
-
-        tracing::subscriber::set_global_default(subscriber)?;
-    } else {
-        let subscriber = base_subscriber(Level::INFO)
-            .without_time()
-            .with_level(false)
-            .finish();
-
-        tracing::subscriber::set_global_default(subscriber)?;
-    }
-
-    let data: Data = args.data;
-    let data_dir = data.0;
-
-    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()).context("Failed to read in seed file")?;
-
-    let env_config = env::Testnet::get_config();
+    let Arguments { data, debug, cmd } = Arguments::from_args();
 
-    match args.cmd {
+    match cmd {
         Command::BuyXmr {
             alice_peer_id,
             alice_multiaddr,
@@ -90,6 +52,16 @@ async fn main() -> Result<()> {
                 },
             electrum_rpc_url,
         } => {
+            let swap_id = Uuid::new_v4();
+
+            let data_dir = data.0;
+            cli::tracing::init(debug, 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())
+                .context("Failed to read in seed file")?;
+            let env_config = env::Testnet::get_config();
+
             if receive_monero_address.network != env_config.monero_network {
                 bail!(
                     "Given monero address is on network {:?}, expected address on network {:?}",
@@ -128,7 +100,6 @@ async fn main() -> Result<()> {
             )
             .await?;
 
-            let swap_id = Uuid::new_v4();
             db.insert_peer_id(swap_id, alice_peer_id).await?;
 
             let swap = Builder::new(
@@ -154,6 +125,11 @@ async fn main() -> Result<()> {
             }
         }
         Command::History => {
+            let data_dir = data.0;
+
+            let db = Database::open(data_dir.join("database").as_path())
+                .context("Failed to open database")?;
+
             let mut table = Table::new();
 
             table.add_row(row!["SWAP ID", "STATE"]);
@@ -175,6 +151,14 @@ async fn main() -> Result<()> {
                 },
             electrum_rpc_url,
         } => {
+            let data_dir = data.0;
+            cli::tracing::init(debug, 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())
+                .context("Failed to read in seed file")?;
+            let env_config = env::Testnet::get_config();
+
             if receive_monero_address.network != env_config.monero_network {
                 bail!("The given monero address is on network {:?}, expected address of network {:?}.", receive_monero_address.network, env_config.monero_network)
             }
@@ -218,6 +202,14 @@ async fn main() -> Result<()> {
             force,
             electrum_rpc_url,
         } => {
+            let data_dir = data.0;
+            cli::tracing::init(debug, 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())
+                .context("Failed to read in seed file")?;
+            let env_config = env::Testnet::get_config();
+
             let bitcoin_wallet =
                 init_bitcoin_wallet(electrum_rpc_url, &seed, data_dir, env_config).await?;
 
@@ -240,6 +232,14 @@ async fn main() -> Result<()> {
             force,
             electrum_rpc_url,
         } => {
+            let data_dir = data.0;
+            cli::tracing::init(debug, 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())
+                .context("Failed to read in seed file")?;
+            let env_config = env::Testnet::get_config();
+
             let bitcoin_wallet =
                 init_bitcoin_wallet(electrum_rpc_url, &seed, data_dir, env_config).await?;
 

swap/src/cli.rs

@@ -1 +1,2 @@
 pub mod command;
+pub mod tracing;

swap/src/cli/tracing.rs

@@ -0,0 +1,81 @@
+use anyhow::Result;
+use std::path::Path;
+use tracing::subscriber::set_global_default;
+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 uuid::Uuid;
+
+pub fn init(debug: bool, dir: impl AsRef<Path>, swap_id: Uuid) -> Result<()> {
+    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(())
+}
+
+pub struct StdErrPrinter<L> {
+    inner: L,
+    level: Level,
+}
+
+type StdErrLayer<S, T> = tracing_subscriber::fmt::Layer<
+    S,
+    DefaultFields,
+    Format<tracing_subscriber::fmt::format::Full, T>,
+    fn() -> std::io::Stderr,
+>;
+
+fn debug_terminal_printer<S>() -> StdErrPrinter<StdErrLayer<S, ChronoLocal>> {
+    let is_terminal = atty::is(atty::Stream::Stderr);
+    StdErrPrinter {
+        inner: fmt::layer()
+            .with_ansi(is_terminal)
+            .with_target(false)
+            .with_timer(ChronoLocal::with_format("%F %T".to_owned()))
+            .with_writer(std::io::stderr),
+        level: Level::DEBUG,
+    }
+}
+
+fn info_terminal_printer<S>() -> StdErrPrinter<StdErrLayer<S, ()>> {
+    let is_terminal = atty::is(atty::Stream::Stderr);
+    StdErrPrinter {
+        inner: fmt::layer()
+            .with_ansi(is_terminal)
+            .with_target(false)
+            .with_level(false)
+            .without_time()
+            .with_writer(std::io::stderr),
+        level: Level::INFO,
+    }
+}
+
+impl<L, S> Layer<S> for StdErrPrinter<L>
+where
+    L: 'static + Layer<S>,
+    S: Subscriber + for<'a> tracing_subscriber::registry::LookupSpan<'a>,
+{
+    fn on_event(&self, event: &Event<'_>, ctx: Context<'_, S>) {
+        if self.level.ge(event.metadata().level()) {
+            self.inner.on_event(event, ctx);
+        }
+    }
+}

swap/src/lib.rs

@@ -27,6 +27,5 @@ pub mod monero;
 pub mod network;
 pub mod protocol;
 pub mod seed;
-pub mod trace;
 
 mod monero_ext;