From 382e7095e84a1e70fe0ce216af052a7c7aebf293 Mon Sep 17 00:00:00 2001 From: Philipp Hoenisch Date: Tue, 21 Sep 2021 14:36:23 +1000 Subject: [PATCH 1/3] Add logging library and initialize by default --- Cargo.lock | 124 +++++++++++++++++++++++++++++++++++++++++++ daemon/Cargo.toml | 3 ++ daemon/README.md | 13 +++++ daemon/src/logger.rs | 33 ++++++++++++ daemon/src/maker.rs | 10 +++- daemon/src/taker.rs | 10 +++- 6 files changed, 191 insertions(+), 2 deletions(-) create mode 100644 daemon/src/logger.rs diff --git a/Cargo.lock b/Cargo.lock index 38d7366..edf713d 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -22,6 +22,15 @@ dependencies = [ "memchr", ] +[[package]] +name = "ansi_term" +version = "0.12.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "d52a9bb7ec0cf484c551830a7ce27bd20d67eac647e1befb56b0be4ee39a55d2" +dependencies = [ + "winapi 0.3.9", +] + [[package]] name = "anyhow" version = "1.0.44" @@ -269,6 +278,18 @@ version = "1.0.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "baf1de4339761588bc0619e3cbc0120ee582ebb74b53b4efbf79117bd2da40fd" +[[package]] +name = "chrono" +version = "0.4.19" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "670ad68c9088c2a963aaa298cb369688cf3f9465ce5e2d4ca10e6e0098a1ce73" +dependencies = [ + "libc", + "num-integer", + "num-traits", + "winapi 0.3.9", +] + [[package]] name = "clap" version = "3.0.0-beta.4" @@ -411,6 +432,7 @@ name = "daemon" version = "0.1.0" dependencies = [ "anyhow", + "atty", "bdk", "cfd_protocol", "clap", @@ -430,6 +452,8 @@ dependencies = [ "thiserror", "tokio", "tokio-util", + "tracing", + "tracing-subscriber", "uuid", ] @@ -1029,6 +1053,15 @@ version = "1.0.2" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "3e2e65a1a2e43cfcb47a895c4c8b10d1f4a61097f9f254f183aee60cad9c651d" +[[package]] +name = "matchers" +version = "0.0.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "f099785f7595cc4b4553a174ce30dd7589ef93391ff414dbb67f62392b9e0ce1" +dependencies = [ + "regex-automata", +] + [[package]] name = "matches" version = "0.1.9" @@ -1133,6 +1166,16 @@ dependencies = [ "winapi 0.3.9", ] +[[package]] +name = "num-integer" +version = "0.1.44" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "d2cc698a63b549a70bc047073d2949cce27cd1c7b0a4a862d08a8031bc2801db" +dependencies = [ + "autocfg 1.0.1", + "num-traits", +] + [[package]] name = "num-traits" version = "0.2.14" @@ -1551,6 +1594,15 @@ dependencies = [ "regex-syntax", ] +[[package]] +name = "regex-automata" +version = "0.1.10" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "6c230d73fb8d8c1b9c0b3135c5142a8acee3a0558fb8db5cf1cb65f8d7862132" +dependencies = [ + "regex-syntax", +] + [[package]] name = "regex-syntax" version = "0.6.25" @@ -1870,6 +1922,15 @@ dependencies = [ "opaque-debug", ] +[[package]] +name = "sharded-slab" +version = "0.1.3" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "740223c51853f3145fe7c90360d2d4232f2b62e3449489c207eccde818979982" +dependencies = [ + "lazy_static", +] + [[package]] name = "signal-hook-registry" version = "1.4.0" @@ -2146,6 +2207,15 @@ dependencies = [ "syn", ] +[[package]] +name = "thread_local" +version = "1.1.3" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "8018d24e04c95ac8790716a5987d0fec4f8b27249ffa0f7d33f1369bdfb88cbd" +dependencies = [ + "once_cell", +] + [[package]] name = "time" version = "0.3.2" @@ -2267,9 +2337,21 @@ checksum = "09adeb8c97449311ccd28a427f96fb563e7fd31aabf994189879d9da2394b89d" dependencies = [ "cfg-if", "pin-project-lite", + "tracing-attributes", "tracing-core", ] +[[package]] +name = "tracing-attributes" +version = "0.1.16" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "98863d0dd09fa59a1b79c6750ad80dbda6b75f4e71c437a6a1a8cb91a8bcbd77" +dependencies = [ + "proc-macro2", + "quote", + "syn", +] + [[package]] name = "tracing-core" version = "0.1.19" @@ -2279,6 +2361,48 @@ dependencies = [ "lazy_static", ] +[[package]] +name = "tracing-log" +version = "0.1.2" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "a6923477a48e41c1951f1999ef8bb5a3023eb723ceadafe78ffb65dc366761e3" +dependencies = [ + "lazy_static", + "log", + "tracing-core", +] + +[[package]] +name = "tracing-serde" +version = "0.1.2" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "fb65ea441fbb84f9f6748fd496cf7f63ec9af5bca94dd86456978d055e8eb28b" +dependencies = [ + "serde", + "tracing-core", +] + +[[package]] +name = "tracing-subscriber" +version = "0.2.20" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "b9cbe87a2fa7e35900ce5de20220a582a9483a7063811defce79d7cbd59d4cfe" +dependencies = [ + "ansi_term", + "chrono", + "lazy_static", + "matchers", + "regex", + "serde", + "serde_json", + "sharded-slab", + "thread_local", + "tracing", + "tracing-core", + "tracing-log", + "tracing-serde", +] + [[package]] name = "try-lock" version = "0.2.3" diff --git a/daemon/Cargo.toml b/daemon/Cargo.toml index 81023ed..9878c34 100644 --- a/daemon/Cargo.toml +++ b/daemon/Cargo.toml @@ -5,6 +5,7 @@ edition = "2018" [dependencies] anyhow = "1" +atty = "0.2" bdk = { git = "https://github.com/bitcoindevkit/bdk/" } cfd_protocol = { path = "../cfd_protocol" } clap = "3.0.0-beta.4" @@ -23,6 +24,8 @@ sqlx = { version = "0.5", features = ["offline"] } thiserror = "1" tokio = { version = "1", features = ["rt-multi-thread", "macros", "sync", "net"] } tokio-util = { version = "0.6", features = ["codec"] } +tracing = { version = "0.1" } +tracing-subscriber = { version = "0.2", default-features = false, features = ["fmt", "ansi", "env-filter", "chrono", "tracing-log", "json"] } uuid = { version = "0.8", features = ["serde", "v4"] } [[bin]] diff --git a/daemon/README.md b/daemon/README.md index 323e5c4..04e85bf 100644 --- a/daemon/README.md +++ b/daemon/README.md @@ -25,3 +25,16 @@ Currently the database for taker and maker is the same. The `taker` binary is used as an example to run the `prepare` command above, but it is irrelevant if you run it for taker or maker. The `tempdb` created can be deleted, it should not be checked into the repo. You can keep it around and just run the `prepare` statement multiple times when working on the database. + +## Logging + +`maker` and `taker` both make use of a log library which can be controlled using the environment variable `RUST_LOG`. +By default, logging is set to `debug` for application specific logs only. +If you want to see logs by third party libraries, you need to set `RUST_LOG=`. +For example, to enable logs for rocket, use: + +```bash +RUST_LOG=rocket=debug cargo run --bin taker +``` + +Additionally, logs can be formatted in json format by passing `--json` or `-j`. diff --git a/daemon/src/logger.rs b/daemon/src/logger.rs new file mode 100644 index 0000000..b58ebb3 --- /dev/null +++ b/daemon/src/logger.rs @@ -0,0 +1,33 @@ +use anyhow::Result; +use tracing_subscriber::filter::LevelFilter; +use tracing_subscriber::fmt::time::ChronoLocal; +use tracing_subscriber::{EnvFilter, FmtSubscriber}; + +pub fn init(level: LevelFilter, json_format: bool) -> Result<()> { + if level == LevelFilter::OFF { + return Ok(()); + } + + let is_terminal = atty::is(atty::Stream::Stderr); + + let filter = EnvFilter::from_default_env() + .add_directive(format!("taker={}", level).parse()?) + .add_directive(format!("maker={}", level).parse()?); + + let builder = FmtSubscriber::builder() + .with_env_filter(filter) + .with_writer(std::io::stderr) + .with_ansi(is_terminal) + .with_timer(ChronoLocal::with_format("%F %T".to_owned())) + .with_target(false); + + if json_format { + builder.json().init(); + } else { + builder.init(); + } + + tracing::info!("Initialized logger"); + + Ok(()) +} diff --git a/daemon/src/maker.rs b/daemon/src/maker.rs index 1293521..091d68a 100644 --- a/daemon/src/maker.rs +++ b/daemon/src/maker.rs @@ -1,7 +1,7 @@ use crate::maker_cfd_actor::Command; use crate::seed::Seed; use crate::wallet::Wallet; -use anyhow::Result; +use anyhow::{Context, Result}; use bdk::bitcoin::secp256k1::{schnorrsig, SECP256K1}; use bdk::bitcoin::Network; use clap::Clap; @@ -12,9 +12,11 @@ use rocket_db_pools::Database; use std::path::PathBuf; use std::time::Duration; use tokio::sync::{mpsc, watch}; +use tracing_subscriber::filter::LevelFilter; mod db; mod keypair; +mod logger; mod maker_cfd_actor; mod maker_inc_connections_actor; mod model; @@ -51,12 +53,18 @@ struct Opts { /// Generate a seed file within the data directory. #[clap(long)] generate_seed: bool, + + /// If enabled logs will be in json format + #[clap(short, long)] + json: bool, } #[rocket::main] async fn main() -> Result<()> { let opts = Opts::parse(); + logger::init(LevelFilter::DEBUG, opts.json).context("initialize logger")?; + let data_dir = opts .data_dir .unwrap_or_else(|| std::env::current_dir().expect("unable to get cwd")); diff --git a/daemon/src/taker.rs b/daemon/src/taker.rs index fefc54f..21f3e72 100644 --- a/daemon/src/taker.rs +++ b/daemon/src/taker.rs @@ -1,7 +1,7 @@ use crate::model::WalletInfo; use crate::taker_cfd_actor::Command; use crate::wallet::Wallet; -use anyhow::Result; +use anyhow::{Context, Result}; use bdk::bitcoin::secp256k1::{schnorrsig, SECP256K1}; use bdk::bitcoin::Network; use clap::Clap; @@ -14,9 +14,11 @@ use std::path::PathBuf; use std::thread::sleep; use std::time::Duration; use tokio::sync::watch; +use tracing_subscriber::filter::LevelFilter; mod db; mod keypair; +mod logger; mod model; mod routes_taker; mod seed; @@ -55,12 +57,18 @@ struct Opts { /// Generate a seed file within the data directory. #[clap(long)] generate_seed: bool, + + /// If enabled logs will be in json format + #[clap(short, long)] + json: bool, } #[rocket::main] async fn main() -> Result<()> { let opts = Opts::parse(); + logger::init(LevelFilter::DEBUG, opts.json).context("initialize logger")?; + let data_dir = opts .data_dir .unwrap_or_else(|| std::env::current_dir().expect("unable to get cwd")); From 1fd474531954ed52ded7e11199bff1a941dbe7e6 Mon Sep 17 00:00:00 2001 From: Philipp Hoenisch Date: Tue, 21 Sep 2021 14:46:01 +1000 Subject: [PATCH 2/3] Use logger instead of println --- daemon/src/maker.rs | 2 +- daemon/src/maker_cfd_actor.rs | 5 ++--- daemon/src/maker_inc_connections_actor.rs | 4 ++-- daemon/src/send_wire_message_actor.rs | 2 +- daemon/src/taker.rs | 2 +- daemon/src/taker_cfd_actor.rs | 2 +- daemon/src/taker_inc_message_actor.rs | 2 +- 7 files changed, 9 insertions(+), 10 deletions(-) diff --git a/daemon/src/maker.rs b/daemon/src/maker.rs index 091d68a..831bc17 100644 --- a/daemon/src/maker.rs +++ b/daemon/src/maker.rs @@ -98,7 +98,7 @@ async fn main() -> Result<()> { let listener = tokio::net::TcpListener::bind(&format!("0.0.0.0:{}", opts.p2p_port)).await?; let local_addr = listener.local_addr().unwrap(); - println!("Listening on {}", local_addr); + tracing::info!("Listening on {}", local_addr); rocket::custom(figment) .manage(cfd_feed_receiver) diff --git a/daemon/src/maker_cfd_actor.rs b/daemon/src/maker_cfd_actor.rs index 535673e..77a67b5 100644 --- a/daemon/src/maker_cfd_actor.rs +++ b/daemon/src/maker_cfd_actor.rs @@ -68,9 +68,8 @@ pub fn new( order_id, quantity, } => { - println!( - "Taker {} wants to take {} of order {}", - taker_id, quantity, order_id + tracing::debug!(%taker_id, %quantity, %order_id, + "Taker wants to take an order" ); let mut conn = db.acquire().await.unwrap(); diff --git a/daemon/src/maker_inc_connections_actor.rs b/daemon/src/maker_inc_connections_actor.rs index 8f5afec..2470284 100644 --- a/daemon/src/maker_inc_connections_actor.rs +++ b/daemon/src/maker_inc_connections_actor.rs @@ -43,7 +43,7 @@ pub fn new( loop { tokio::select! { Ok((socket, remote_addr)) = listener.accept() => { - println!("Connected to {}", remote_addr); + tracing::info!("Connected to {}", remote_addr); let taker_id = TakerId::default(); let (read, write) = socket.into_split(); @@ -114,7 +114,7 @@ fn in_taker_messages( .send(maker_cfd_actor::Command::IncProtocolMsg(msg)) .unwrap(), Err(error) => { - eprintln!("Error in reading message: {}", error); + tracing::error!(%error, "Error in reading message"); } } } diff --git a/daemon/src/send_wire_message_actor.rs b/daemon/src/send_wire_message_actor.rs index d60f022..b127c32 100644 --- a/daemon/src/send_wire_message_actor.rs +++ b/daemon/src/send_wire_message_actor.rs @@ -20,7 +20,7 @@ where { Ok(_) => {} Err(_) => { - eprintln!("TCP connection error"); + tracing::error!("TCP connection error"); break; } } diff --git a/daemon/src/taker.rs b/daemon/src/taker.rs index 21f3e72..be420c7 100644 --- a/daemon/src/taker.rs +++ b/daemon/src/taker.rs @@ -100,7 +100,7 @@ async fn main() -> Result<()> { if let Ok(connection) = socket.connect(opts.taker).await { break connection.into_split(); } else { - println!( + tracing::warn!( "Could not connect to the maker, retrying in {}s ...", CONNECTION_RETRY_INTERVAL.as_secs() ); diff --git a/daemon/src/taker_cfd_actor.rs b/daemon/src/taker_cfd_actor.rs index 563ed56..d973ab3 100644 --- a/daemon/src/taker_cfd_actor.rs +++ b/daemon/src/taker_cfd_actor.rs @@ -57,7 +57,7 @@ pub fn new( let current_order = load_order_by_id(order_id, &mut conn).await.unwrap(); - println!("Accepting current order: {:?}", ¤t_order); + tracing::info!("Accepting current order: {:?}", ¤t_order); let cfd = Cfd::new( current_order.clone(), diff --git a/daemon/src/taker_inc_message_actor.rs b/daemon/src/taker_inc_message_actor.rs index 0ad962d..e65f3da 100644 --- a/daemon/src/taker_inc_message_actor.rs +++ b/daemon/src/taker_inc_message_actor.rs @@ -43,7 +43,7 @@ pub fn new( .unwrap(); } Err(error) => { - eprintln!("Error in reading message: {}", error); + tracing::error!("Error in reading message: {}", error); } } } From 90ae8ef154ce2083086537ce17dee0a2d84e5100 Mon Sep 17 00:00:00 2001 From: Philipp Hoenisch Date: Tue, 21 Sep 2021 16:23:09 +1000 Subject: [PATCH 3/3] Enable rocket logs by default --- daemon/src/logger.rs | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/daemon/src/logger.rs b/daemon/src/logger.rs index b58ebb3..16f1329 100644 --- a/daemon/src/logger.rs +++ b/daemon/src/logger.rs @@ -12,7 +12,8 @@ pub fn init(level: LevelFilter, json_format: bool) -> Result<()> { let filter = EnvFilter::from_default_env() .add_directive(format!("taker={}", level).parse()?) - .add_directive(format!("maker={}", level).parse()?); + .add_directive(format!("maker={}", level).parse()?) + .add_directive(format!("rocket={}", level).parse()?); let builder = FmtSubscriber::builder() .with_env_filter(filter)