From b61521c33cb664977b08b4664aeda8ebf547fc64 Mon Sep 17 00:00:00 2001 From: Yiannis Marangos Date: Mon, 11 Sep 2023 13:33:45 +0300 Subject: [PATCH] chore: Migrate from `log` to `tracing` (#55) * chore: Migrate from `log` to `tracing` * replace all println!() with debug!() --- Cargo.lock | 113 ++++++++++++++++++++++++++++++++++- celestia/Cargo.toml | 6 +- celestia/src/native.rs | 50 +++++++++++----- node/Cargo.toml | 2 +- node/src/p2p.rs | 20 +++---- rpc/Cargo.toml | 5 +- rpc/tests/utils/tiny_node.rs | 12 ++-- 7 files changed, 172 insertions(+), 36 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index da1e4d38..02bdde00 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -495,6 +495,9 @@ dependencies = [ "dotenvy", "libp2p", "tokio", + "tracing", + "tracing-appender", + "tracing-subscriber", ] [[package]] @@ -510,11 +513,11 @@ dependencies = [ "futures", "getrandom 0.2.10", "libp2p", - "log", "prost", "tendermint-proto", "thiserror", "tokio", + "tracing", "wasm-bindgen-futures", ] @@ -542,11 +545,11 @@ dependencies = [ "http", "jsonrpsee", "libp2p", - "log", "rand", "serde", "thiserror", "tokio", + "tracing", ] [[package]] @@ -695,6 +698,16 @@ dependencies = [ "libc", ] +[[package]] +name = "crossbeam-channel" +version = "0.5.8" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "a33c2bf77f2df06183c3aa30d1e96c0695a313d4f9c453cc3762a6db39f99200" +dependencies = [ + "cfg-if", + "crossbeam-utils", +] + [[package]] name = "crossbeam-utils" version = "0.8.16" @@ -2141,6 +2154,15 @@ version = "0.1.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "ffbee8634e0d45d258acb448e7eaab3fce7a0a467395d4d9f228e3c1f01fb2e4" +[[package]] +name = "matchers" +version = "0.1.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "8263075bb86c5a1b1427b5ae862e8889656f126e9f77c484496e8b47cf5c5558" +dependencies = [ + "regex-automata 0.1.10", +] + [[package]] name = "matches" version = "0.1.10" @@ -2366,6 +2388,16 @@ dependencies = [ "minimal-lexical", ] +[[package]] +name = "nu-ansi-term" +version = "0.46.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "77a8165726e8236064dbb45459242600304b42a5ea24ee2948e18e023bf7ba84" +dependencies = [ + "overload", + "winapi", +] + [[package]] name = "num-bigint" version = "0.4.4" @@ -2454,6 +2486,12 @@ version = "0.1.5" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "ff011a302c396a5197692431fc1948019154afc178baf7d8e37367442a4601cf" +[[package]] +name = "overload" +version = "0.1.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "b15813163c1d831bf4a13c3610c05c0d03b39feb07f7e09fa234dac9b15aaf39" + [[package]] name = "parity-scale-codec" version = "3.6.5" @@ -2981,10 +3019,19 @@ checksum = "697061221ea1b4a94a624f67d0ae2bfe4e22b8a17b6a192afb11046542cc8c47" dependencies = [ "aho-corasick", "memchr", - "regex-automata", + "regex-automata 0.3.8", "regex-syntax 0.7.5", ] +[[package]] +name = "regex-automata" +version = "0.1.10" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "6c230d73fb8d8c1b9c0b3135c5142a8acee3a0558fb8db5cf1cb65f8d7862132" +dependencies = [ + "regex-syntax 0.6.29", +] + [[package]] name = "regex-automata" version = "0.3.8" @@ -3379,6 +3426,15 @@ dependencies = [ "digest 0.10.7", ] +[[package]] +name = "sharded-slab" +version = "0.1.4" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "900fba806f70c630b0a382d0d825e17a0f19fcd059a2ade1ff237bcddf446b31" +dependencies = [ + "lazy_static", +] + [[package]] name = "signature" version = "2.1.0" @@ -3652,6 +3708,16 @@ dependencies = [ "syn 2.0.29", ] +[[package]] +name = "thread_local" +version = "1.1.7" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "3fdd6f064ccff2d6567adcb3873ca630700f00b5ad3f060c25b5dcfd9a4ce152" +dependencies = [ + "cfg-if", + "once_cell", +] + [[package]] name = "time" version = "0.3.28" @@ -3797,6 +3863,17 @@ dependencies = [ "tracing-core", ] +[[package]] +name = "tracing-appender" +version = "0.2.2" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "09d48f71a791638519505cefafe162606f706c25592e4bde4d97600c0195312e" +dependencies = [ + "crossbeam-channel", + "time", + "tracing-subscriber", +] + [[package]] name = "tracing-attributes" version = "0.1.26" @@ -3815,6 +3892,36 @@ source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "0955b8137a1df6f1a2e9a37d8a6656291ff0297c1a97c24e0d8425fe2312f79a" dependencies = [ "once_cell", + "valuable", +] + +[[package]] +name = "tracing-log" +version = "0.1.3" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "78ddad33d2d10b1ed7eb9d1f518a5674713876e97e5bb9b7345a7984fbb4f922" +dependencies = [ + "lazy_static", + "log", + "tracing-core", +] + +[[package]] +name = "tracing-subscriber" +version = "0.3.17" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "30a651bc37f915e81f087d86e62a18eec5f79550c7faff886f7090b4ea757c77" +dependencies = [ + "matchers", + "nu-ansi-term", + "once_cell", + "regex", + "sharded-slab", + "smallvec", + "thread_local", + "tracing", + "tracing-core", + "tracing-log", ] [[package]] diff --git a/celestia/Cargo.toml b/celestia/Cargo.toml index fd2a0899..2007bad9 100644 --- a/celestia/Cargo.toml +++ b/celestia/Cargo.toml @@ -8,10 +8,14 @@ license = "Apache-2.0" crate-type = ["rlib", "cdylib"] [dependencies] -anyhow = "1.0.71" celestia-node = { workspace = true } celestia-rpc = { workspace = true } +anyhow = "1.0.71" +tracing = "0.1.37" +tracing-appender = "0.2.2" +tracing-subscriber = { version = "0.3.17", features = ["env-filter"] } + [target.'cfg(not(target_arch = "wasm32"))'.dependencies] dotenvy = "0.15.7" libp2p = { version = "0.52.3", features = [ diff --git a/celestia/src/native.rs b/celestia/src/native.rs index ff8f35c5..edfa6ded 100644 --- a/celestia/src/native.rs +++ b/celestia/src/native.rs @@ -3,27 +3,17 @@ use std::env; use anyhow::{Context, Result}; use celestia_node::node::{Node, NodeConfig}; use celestia_rpc::prelude::*; -use libp2p::{core::upgrade::Version, identity, noise, tcp, yamux, Transport}; +use libp2p::{core::upgrade::Version, identity, noise, tcp, yamux, Multiaddr, Transport}; +use tracing::info; const WS_URL: &str = "ws://localhost:26658"; #[tokio::main] pub async fn run() -> Result<()> { let _ = dotenvy::dotenv(); + let _guard = init_tracing(); - // Get the address of the local bridge node - let auth_token = env::var("CELESTIA_NODE_AUTH_TOKEN_ADMIN")?; - let client = celestia_rpc::client::new_websocket(WS_URL, Some(&auth_token)).await?; - let bridge_info = client.p2p_info().await?; - println!("bridge id: {:?}", bridge_info.id); - println!("bridge listens on: {:?}", bridge_info.addrs); - - let bridge_ma = bridge_info - .addrs - .into_iter() - .find(|ma| ma.protocol_stack().any(|protocol| protocol == "tcp")) - .context("Bridge doesn't listen on tcp")?; - + let bridge_ma = fetch_bridge_multiaddr().await?; let p2p_local_keypair = identity::Keypair::generate_ed25519(); let p2p_transport = tcp::tokio::Transport::default() @@ -44,3 +34,35 @@ pub async fn run() -> Result<()> { Ok(()) } + +/// Get the address of the local bridge node +async fn fetch_bridge_multiaddr() -> Result { + let auth_token = env::var("CELESTIA_NODE_AUTH_TOKEN_ADMIN")?; + let client = celestia_rpc::client::new_websocket(WS_URL, Some(&auth_token)).await?; + let bridge_info = client.p2p_info().await?; + info!("bridge id: {:?}", bridge_info.id); + info!("bridge listens on: {:?}", bridge_info.addrs); + + let bridge_ma = bridge_info + .addrs + .into_iter() + .find(|ma| ma.protocol_stack().any(|protocol| protocol == "tcp")) + .context("Bridge doesn't listen on tcp")?; + + Ok(bridge_ma) +} + +fn init_tracing() -> tracing_appender::non_blocking::WorkerGuard { + let (non_blocking, guard) = tracing_appender::non_blocking(std::io::stdout()); + + let filter = tracing_subscriber::EnvFilter::builder() + .with_default_directive(tracing_subscriber::filter::LevelFilter::INFO.into()) + .from_env_lossy(); + + tracing_subscriber::fmt() + .with_env_filter(filter) + .with_writer(non_blocking) + .init(); + + guard +} diff --git a/node/Cargo.toml b/node/Cargo.toml index e95e155a..4723a451 100644 --- a/node/Cargo.toml +++ b/node/Cargo.toml @@ -18,10 +18,10 @@ libp2p = { version = "0.52.3", features = [ "macros", "request-response", ] } -log = "0.4.20" prost = "0.12.0" thiserror = "1.0.48" tokio = { version = "1.32.0", features = ["macros", "sync"] } +tracing = "0.1.37" [target.'cfg(not(target_arch = "wasm32"))'.dependencies] tokio = { version = "1.32.0", features = ["rt-multi-thread"] } diff --git a/node/src/p2p.rs b/node/src/p2p.rs index 8aa4246f..7e8cce5c 100644 --- a/node/src/p2p.rs +++ b/node/src/p2p.rs @@ -13,9 +13,9 @@ use libp2p::swarm::{ THandlerErr, }; use libp2p::{identify, request_response, Multiaddr, PeerId, TransportError}; -use log::{error, trace, warn}; use tendermint_proto::Protobuf; use tokio::select; +use tracing::{debug, instrument, warn}; use crate::executor::{spawn, Executor}; use crate::utils::gossipsub_ident_topic; @@ -187,12 +187,11 @@ impl Worker { } } + #[instrument(level = "trace", skip(self))] async fn on_swarm_event( &mut self, ev: &SwarmEvent>, ) -> Result<()> { - trace!("{ev:?}"); - #[allow(clippy::single_match)] match ev { SwarmEvent::Behaviour(ev) => match ev { @@ -207,9 +206,8 @@ impl Worker { Ok(()) } + #[instrument(level = "trace", skip(self))] async fn on_command(&mut self, cmd: P2pCmd) -> Result<()> { - trace!("{cmd:?}"); - match cmd { P2pCmd::NetworkInfo { respond_to } => { let _ = respond_to.send(self.swarm.network_info()); @@ -234,15 +232,15 @@ impl Worker { response, }, } => { - println!( + debug!( "Response for request: {request_id}, from peer: {peer}, status: {:?}", response.status_code() ); let header = ExtendedHeader::decode(&response.body[..]).unwrap(); // TODO: Forward response back with one shot channel - println!("Header: {header:?}"); + debug!("Header: {header:?}"); } - _ => println!("Unhandled header_ex event: {ev:?}"), + _ => debug!("Unhandled header_ex event: {ev:?}"), } Ok(()) @@ -259,12 +257,12 @@ impl Worker { let header = ExtendedHeader::decode(&message.data[..]).unwrap(); // TODO: produce event - println!("New header from header-sub: {header:?}"); + debug!("New header from header-sub: {header:?}"); } else { - println!("New gossipsub message, id: {message_id}, message: {message:?}"); + debug!("New gossipsub message, id: {message_id}, message: {message:?}"); } } - _ => println!("Unhandled gossipsub event: {ev:?}"), + _ => debug!("Unhandled gossipsub event: {ev:?}"), } Ok(()) diff --git a/rpc/Cargo.toml b/rpc/Cargo.toml index 93b5f0b9..a5314d4f 100644 --- a/rpc/Cargo.toml +++ b/rpc/Cargo.toml @@ -9,6 +9,7 @@ thiserror = "1.0.40" jsonrpsee = { version = "0.20", features = ["client-core", "macros"] } celestia-types = { workspace = true } serde = { version = "1.0.188", features = ["derive"] } +tracing = "0.1.37" [target.'cfg(not(target_arch = "wasm32"))'.dependencies] http = "0.2.9" @@ -18,10 +19,10 @@ jsonrpsee = { version = "0.20", features = ["http-client", "ws-client"] } anyhow = "1.0.71" dotenvy = "0.15.7" futures = "0.3.28" -libp2p = "0.52.3" -log = "0.4" +libp2p = { version = "0.52.3", features = ["tokio", "macros", "tcp", "noise", "yamux"] } rand = "0.8.5" tokio = { version = "1.32.0", features = ["rt", "macros"] } +tracing = "0.1.37" [features] default = ["p2p"] diff --git a/rpc/tests/utils/tiny_node.rs b/rpc/tests/utils/tiny_node.rs index e78e8eee..4e450933 100644 --- a/rpc/tests/utils/tiny_node.rs +++ b/rpc/tests/utils/tiny_node.rs @@ -13,6 +13,7 @@ use tokio::{ sync::mpsc, time::{sleep, Duration}, }; +use tracing::{debug, warn}; // how long to wait during startup for node to start listening on interfaces, before we return a // list of addresses @@ -36,7 +37,8 @@ pub async fn start_tiny_node() -> anyhow::Result { // Create identity let local_key = identity::Keypair::generate_ed25519(); let local_peer_id = PeerId::from(local_key.public()); - log::debug!("local peer id: {local_peer_id:?}"); + + debug!("local peer id: {local_peer_id:?}"); // Setup swarm let transport = tcp::tokio::Transport::default() @@ -55,9 +57,10 @@ pub async fn start_tiny_node() -> anyhow::Result { tokio::task::spawn(async move { loop { if let Some(SwarmEvent::NewListenAddr { address, .. }) = swarm.next().await { - dbg!(&address); + debug!("{address:?}"); + if addr_tx.send(address).await.is_err() { - log::warn!("received new addr after set startup time, unittests might not have all the node addresses"); + warn!("received new addr after set startup time, unittests might not have all the node addresses"); } } } @@ -76,7 +79,8 @@ pub async fn start_tiny_node() -> anyhow::Result { id: p2p::PeerId(local_peer_id), addrs, }; - log::debug!("Listening addresses: {addr:?}"); + + debug!("Listening addresses: {addr:?}"); Ok(addr) }