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

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/bin/swap.rs

@@ -21,7 +21,8 @@ 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::cli::trace::init_tracing;
 use swap::database::Database;
 use swap::env::{Config, GetConfig};
 use swap::network::quote::BidQuote;
@@ -30,8 +31,7 @@ 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 tracing::{debug, error, info, warn};
 use url::Url;
 use uuid::Uuid;
 
@@ -40,46 +40,9 @@ extern crate prettytable;
 
 #[tokio::main]
 async fn main() -> Result<()> {
-    let args = Arguments::from_args();
+    let Arguments { data, debug, cmd } = 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();
-
-    match args.cmd {
+    match cmd {
         Command::BuyXmr {
             alice_peer_id,
             alice_multiaddr,
@@ -90,6 +53,16 @@ async fn main() -> Result<()> {
                 },
             electrum_rpc_url,
         } => {
+            let swap_id = Uuid::new_v4();
+
+            let data_dir = data.0;
+            init_tracing(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 +101,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 +126,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 +152,14 @@ async fn main() -> Result<()> {
                 },
             electrum_rpc_url,
         } => {
+            let data_dir = data.0;
+            init_tracing(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 +203,14 @@ async fn main() -> Result<()> {
             force,
             electrum_rpc_url,
         } => {
+            let data_dir = data.0;
+            init_tracing(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 +233,14 @@ async fn main() -> Result<()> {
             force,
             electrum_rpc_url,
         } => {
+            let data_dir = data.0;
+            init_tracing(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 trace;

swap/src/cli/trace.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_tracing(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);
+        }
+    }
+}