feat: introduce tracing

We replace `log` with `tracing` across the codebase. Where possible, we make use of structured logging now instead of templating strings.

`tracing` offers the ability to also record "span"s. A span lasts until its dropped and describes the entire duration that it is active for. All logs (in `tracing` term "events") are hierarchically embedded in all parent-spans).

We introduce several spans:

- On debug level: One for `new_outgoing_connection`, `new_incoming_connection` and `new_established_connection`
- On debug level: `Connection::poll`, `Swarm::poll` and `Pool::poll`
- On trace level: `NetworkBehaviour::poll` for each implementation of `NetworkBehaviour`
- On trace level: `ConnectionHandler::poll` for each implementation of (protocol) `ConnectionHandler`s

The idea here is that logging on debug level gives you a decent overview of what the system is doing. You get spans for the duration of connections and how often each connection gets polled.

Dropping down to trace level gives you an extremely detailed view of how long each individual `ConnectionHandler` was executed as part of `poll` which could be used for detailed analysis on how busy certain handlers are.

Most importantly, simply logging on `info` does not give you any spans. We consider `info` to be a good default that should be reasonably quiet.

Resolves libp2p#1533.

Pull-Request: libp2p#4282.

core/Cargo.toml

@@ -17,7 +17,6 @@ futures = { version = "0.3.29", features = ["executor", "thread-pool"] }
 futures-timer = "3"
 instant = "0.1.12"
 libp2p-identity = { workspace = true, features = ["peerid", "ed25519"] }
-log = "0.4"
 multiaddr = { workspace = true }
 multihash = { workspace = true }
 multistream-select = { workspace = true }
@@ -30,6 +29,7 @@ rw-stream-sink = { workspace = true }
 serde = { version = "1", optional = true, features = ["derive"] }
 smallvec = "1.11.1"
 thiserror = "1.0"
+tracing = "0.1.37"
 unsigned-varint = "0.7"
 void = "1"
 

core/src/transport/choice.rs

@@ -22,7 +22,6 @@ use crate::either::EitherFuture;
 use crate::transport::{ListenerId, Transport, TransportError, TransportEvent};
 use either::Either;
 use futures::future;
-use log::{debug, trace};
 use multiaddr::Multiaddr;
 use std::{pin::Pin, task::Context, task::Poll};
 
@@ -52,33 +51,33 @@ where
         id: ListenerId,
         addr: Multiaddr,
     ) -> Result<(), TransportError<Self::Error>> {
-        trace!(
-            "Attempting to listen on {} using {}",
-            addr,
+        tracing::trace!(
+            address=%addr,
+            "Attempting to listen on address using {}",
             std::any::type_name::<A>()
         );
         let addr = match self.0.listen_on(id, addr) {
             Err(TransportError::MultiaddrNotSupported(addr)) => {
-                debug!(
-                    "Failed to listen on {} using {}",
-                    addr,
+                tracing::debug!(
+                    address=%addr,
+                    "Failed to listen on address using {}",
                     std::any::type_name::<A>()
                 );
                 addr
             }
             res => return res.map_err(|err| err.map(Either::Left)),
         };
 
-        trace!(
-            "Attempting to listen on {} using {}",
-            addr,
+        tracing::trace!(
+            address=%addr,
+            "Attempting to listen on address using {}",
             std::any::type_name::<B>()
         );
         let addr = match self.1.listen_on(id, addr) {
             Err(TransportError::MultiaddrNotSupported(addr)) => {
-                debug!(
-                    "Failed to listen on {} using {}",
-                    addr,
+                tracing::debug!(
+                    address=%addr,
+                    "Failed to listen on address using {}",
                     std::any::type_name::<B>()
                 );
                 addr
@@ -94,17 +93,17 @@ where
     }
 
     fn dial(&mut self, addr: Multiaddr) -> Result<Self::Dial, TransportError<Self::Error>> {
-        trace!(
-            "Attempting to dial {} using {}",
-            addr,
+        tracing::trace!(
+            address=%addr,
+            "Attempting to dial address using {}",
             std::any::type_name::<A>()
         );
         let addr = match self.0.dial(addr) {
             Ok(connec) => return Ok(EitherFuture::First(connec)),
             Err(TransportError::MultiaddrNotSupported(addr)) => {
-                debug!(
-                    "Failed to dial {} using {}",
-                    addr,
+                tracing::debug!(
+                    address=%addr,
+                    "Failed to dial address using {}",
                     std::any::type_name::<A>()
                 );
                 addr
@@ -114,17 +113,17 @@ where
             }
         };
 
-        trace!(
-            "Attempting to dial {} using {}",
-            addr,
+        tracing::trace!(
+            address=%addr,
+            "Attempting to dial address using {}",
             std::any::type_name::<A>()
         );
         let addr = match self.1.dial(addr) {
             Ok(connec) => return Ok(EitherFuture::Second(connec)),
             Err(TransportError::MultiaddrNotSupported(addr)) => {
-                debug!(
-                    "Failed to dial {} using {}",
-                    addr,
+                tracing::debug!(
+                    address=%addr,
+                    "Failed to dial address using {}",
                     std::any::type_name::<A>()
                 );
                 addr

core/src/transport/global_only.rs

@@ -22,7 +22,6 @@ use crate::{
     multiaddr::{Multiaddr, Protocol},
     transport::{ListenerId, TransportError, TransportEvent},
 };
-use log::debug;
 use std::{
     pin::Pin,
     task::{Context, Poll},
@@ -292,20 +291,20 @@ impl<T: crate::Transport + Unpin> crate::Transport for Transport<T> {
         match addr.iter().next() {
             Some(Protocol::Ip4(a)) => {
                 if !ipv4_global::is_global(a) {
-                    debug!("Not dialing non global IP address {:?}.", a);
+                    tracing::debug!(ip=%a, "Not dialing non global IP address");
                     return Err(TransportError::MultiaddrNotSupported(addr));
                 }
                 self.inner.dial(addr)
             }
             Some(Protocol::Ip6(a)) => {
                 if !ipv6_global::is_global(a) {
-                    debug!("Not dialing non global IP address {:?}.", a);
+                    tracing::debug!(ip=%a, "Not dialing non global IP address");
                     return Err(TransportError::MultiaddrNotSupported(addr));
                 }
                 self.inner.dial(addr)
             }
             _ => {
-                debug!("Not dialing unsupported Multiaddress {:?}.", addr);
+                tracing::debug!(address=%addr, "Not dialing unsupported Multiaddress");
                 Err(TransportError::MultiaddrNotSupported(addr))
             }
         }
@@ -318,20 +317,20 @@ impl<T: crate::Transport + Unpin> crate::Transport for Transport<T> {
         match addr.iter().next() {
             Some(Protocol::Ip4(a)) => {
                 if !ipv4_global::is_global(a) {
-                    debug!("Not dialing non global IP address {:?}.", a);
+                    tracing::debug!(ip=?a, "Not dialing non global IP address");
                     return Err(TransportError::MultiaddrNotSupported(addr));
                 }
                 self.inner.dial_as_listener(addr)
             }
             Some(Protocol::Ip6(a)) => {
                 if !ipv6_global::is_global(a) {
-                    debug!("Not dialing non global IP address {:?}.", a);
+                    tracing::debug!(ip=?a, "Not dialing non global IP address");
                     return Err(TransportError::MultiaddrNotSupported(addr));
                 }
                 self.inner.dial_as_listener(addr)
             }
             _ => {
-                debug!("Not dialing unsupported Multiaddress {:?}.", addr);
+                tracing::debug!(address=%addr, "Not dialing unsupported Multiaddress");
                 Err(TransportError::MultiaddrNotSupported(addr))
             }
         }

core/src/upgrade/apply.rs

@@ -21,7 +21,6 @@
 use crate::upgrade::{InboundConnectionUpgrade, OutboundConnectionUpgrade, UpgradeError};
 use crate::{connection::ConnectedPoint, Negotiated};
 use futures::{future::Either, prelude::*};
-use log::debug;
 use multistream_select::{self, DialerSelectFuture, ListenerSelectFuture};
 use std::{mem, pin::Pin, task::Context, task::Poll};
 
@@ -141,11 +140,11 @@ where
                             return Poll::Pending;
                         }
                         Poll::Ready(Ok(x)) => {
-                            log::trace!("Upgraded inbound stream to {name}");
+                            tracing::trace!(upgrade=%name, "Upgraded inbound stream");
                             return Poll::Ready(Ok(x));
                         }
                         Poll::Ready(Err(e)) => {
-                            debug!("Failed to upgrade inbound stream to {name}");
+                            tracing::debug!(upgrade=%name, "Failed to upgrade inbound stream");
                             return Poll::Ready(Err(UpgradeError::Apply(e)));
                         }
                     }
@@ -223,11 +222,11 @@ where
                             return Poll::Pending;
                         }
                         Poll::Ready(Ok(x)) => {
-                            log::trace!("Upgraded outbound stream to {name}",);
+                            tracing::trace!(upgrade=%name, "Upgraded outbound stream");
                             return Poll::Ready(Ok(x));
                         }
                         Poll::Ready(Err(e)) => {
-                            debug!("Failed to upgrade outbound stream to {name}",);
+                            tracing::debug!(upgrade=%name, "Failed to upgrade outbound stream",);
                             return Poll::Ready(Err(UpgradeError::Apply(e)));
                         }
                     }

examples/autonat/Cargo.toml

@@ -11,9 +11,10 @@ release = false
 [dependencies]
 tokio = { version = "1.33", features = ["full"] }
 clap = { version = "4.4.7", features = ["derive"] }
-env_logger = "0.10.0"
 futures = "0.3.29"
 libp2p = { path = "../../libp2p", features = ["tokio", "tcp", "noise", "yamux", "autonat", "identify", "macros"] }
+tracing = "0.1.37"
+tracing-subscriber = { version = "0.3", features = ["env-filter"] }
 
 [lints]
 workspace = true

examples/autonat/src/bin/autonat_client.rs

@@ -29,6 +29,7 @@ use libp2p::{autonat, identify, identity, noise, tcp, yamux, PeerId};
 use std::error::Error;
 use std::net::Ipv4Addr;
 use std::time::Duration;
+use tracing_subscriber::EnvFilter;
 
 #[derive(Debug, Parser)]
 #[clap(name = "libp2p autonat")]
@@ -45,7 +46,9 @@ struct Opt {
 
 #[tokio::main]
 async fn main() -> Result<(), Box<dyn Error>> {
-    env_logger::init();
+    let _ = tracing_subscriber::fmt()
+        .with_env_filter(EnvFilter::from_default_env())
+        .try_init();
 
     let opt = Opt::parse();
 

examples/autonat/src/bin/autonat_server.rs

@@ -27,6 +27,7 @@ use libp2p::swarm::{NetworkBehaviour, SwarmEvent};
 use libp2p::{autonat, identify, identity, noise, tcp, yamux};
 use std::error::Error;
 use std::net::Ipv4Addr;
+use tracing_subscriber::EnvFilter;
 
 #[derive(Debug, Parser)]
 #[clap(name = "libp2p autonat")]
@@ -37,7 +38,9 @@ struct Opt {
 
 #[tokio::main]
 async fn main() -> Result<(), Box<dyn Error>> {
-    env_logger::init();
+    let _ = tracing_subscriber::fmt()
+        .with_env_filter(EnvFilter::from_default_env())
+        .try_init();
 
     let opt = Opt::parse();
 

examples/browser-webrtc/Cargo.toml

@@ -17,10 +17,10 @@ crate-type = ["cdylib"]
 
 [dependencies]
 anyhow = "1.0.72"
-env_logger = "0.10"
 futures = "0.3.29"
-log = "0.4"
 rand = "0.8"
+tracing = "0.1.37"
+tracing-subscriber = { version = "0.3", features = ["env-filter"] }
 
 [target.'cfg(not(target_arch = "wasm32"))'.dependencies]
 axum = "0.6.19"

examples/browser-webrtc/src/lib.rs

@@ -28,13 +28,13 @@ pub async fn run(libp2p_endpoint: String) -> Result<(), JsError> {
         .build();
 
     let addr = libp2p_endpoint.parse::<Multiaddr>()?;
-    log::info!("Dialing {addr}");
+    tracing::info!("Dialing {addr}");
     swarm.dial(addr)?;
 
     loop {
         match swarm.next().await.unwrap() {
             SwarmEvent::Behaviour(ping::Event { result: Err(e), .. }) => {
-                log::error!("Ping failed: {:?}", e);
+                tracing::error!("Ping failed: {:?}", e);
 
                 break;
             }
@@ -43,10 +43,10 @@ pub async fn run(libp2p_endpoint: String) -> Result<(), JsError> {
                 result: Ok(rtt),
                 ..
             }) => {
-                log::info!("Ping successful: RTT: {rtt:?}, from {peer}");
+                tracing::info!("Ping successful: RTT: {rtt:?}, from {peer}");
                 body.append_p(&format!("RTT: {rtt:?} at {}", Date::new_0().to_string()))?;
             }
-            evt => log::info!("Swarm event: {:?}", evt),
+            evt => tracing::info!("Swarm event: {:?}", evt),
         }
     }
 

examples/browser-webrtc/src/main.rs

@@ -22,10 +22,9 @@ use tower_http::cors::{Any, CorsLayer};
 
 #[tokio::main]
 async fn main() -> anyhow::Result<()> {
-    env_logger::builder()
-        .parse_filters("browser_webrtc_example=debug,libp2p_webrtc=info,libp2p_ping=debug")
-        .parse_default_env()
-        .init();
+    let _ = tracing_subscriber::fmt()
+        .with_env_filter("browser_webrtc_example=debug,libp2p_webrtc=info,libp2p_ping=debug")
+        .try_init();
 
     let mut swarm = libp2p::SwarmBuilder::with_new_identity()
         .with_tokio()
@@ -56,11 +55,13 @@ async fn main() -> anyhow::Result<()> {
                 .iter()
                 .any(|e| e == Protocol::Ip4(Ipv4Addr::LOCALHOST))
             {
-                log::debug!("Ignoring localhost address to make sure the example works in Firefox");
+                tracing::debug!(
+                    "Ignoring localhost address to make sure the example works in Firefox"
+                );
                 continue;
             }
 
-            log::info!("Listening on: {address}");
+            tracing::info!(%address, "Listening");
 
             break address;
         }
@@ -74,7 +75,7 @@ async fn main() -> anyhow::Result<()> {
     loop {
         tokio::select! {
             swarm_event = swarm.next() => {
-                log::trace!("Swarm Event: {:?}", swarm_event)
+                tracing::trace!(?swarm_event)
             },
             _ = tokio::signal::ctrl_c() => {
                 break;
@@ -110,7 +111,7 @@ pub(crate) async fn serve(libp2p_transport: Multiaddr) {
 
     let addr = SocketAddr::new(listen_addr.into(), 8080);
 
-    log::info!("Serving client files at http://{addr}");
+    tracing::info!(url=%format!("http://{addr}"), "Serving client files at url");
 
     axum::Server::bind(&addr)
         .serve(server.into_make_service())
@@ -141,7 +142,7 @@ async fn get_index(
 
 /// Serves the static files generated by `wasm-pack`.
 async fn get_static_file(Path(path): Path<String>) -> Result<impl IntoResponse, StatusCode> {
-    log::debug!("Serving static file: {path}");
+    tracing::debug!(file_path=%path, "Serving static file");
 
     let content = StaticFiles::get(&path).ok_or(StatusCode::NOT_FOUND)?.data;
     let content_type = mime_guess::from_path(path)

examples/chat/Cargo.toml

@@ -11,9 +11,10 @@ release = false
 [dependencies]
 tokio = { version = "1.33", features = ["full"] }
 async-trait = "0.1"
-env_logger = "0.10.0"
 futures = "0.3.29"
 libp2p = { path = "../../libp2p", features = [ "tokio", "gossipsub", "mdns", "noise", "macros", "tcp", "yamux", "quic"] }
+tracing = "0.1.37"
+tracing-subscriber = { version = "0.3", features = ["env-filter"] }
 
 [lints]
 workspace = true

examples/chat/src/main.rs

@@ -27,6 +27,7 @@ use std::error::Error;
 use std::hash::{Hash, Hasher};
 use std::time::Duration;
 use tokio::{io, io::AsyncBufReadExt, select};
+use tracing_subscriber::EnvFilter;
 
 // We create a custom network behaviour that combines Gossipsub and Mdns.
 #[derive(NetworkBehaviour)]
@@ -37,6 +38,10 @@ struct MyBehaviour {
 
 #[tokio::main]
 async fn main() -> Result<(), Box<dyn Error>> {
+    let _ = tracing_subscriber::fmt()
+        .with_env_filter(EnvFilter::from_default_env())
+        .try_init();
+
     let mut swarm = libp2p::SwarmBuilder::with_new_identity()
         .with_tokio()
         .with_tcp(