Migrate from log to tracing

Finomnis · Apr 12, 2023 · e359baa · e359baa
1 parent d7a6183
commit e359baa
Show file tree

Hide file tree

Showing 31 changed files with 284 additions and 232 deletions.
diff --git a/Cargo.toml b/Cargo.toml
@@ -40,7 +40,8 @@ pin-project-lite = "0.2.9"
 async-trait = "0.1.57"
 
 # For logging
-log = "0.4.17"
+tracing = { version = "0.1.37", features = ["async-await"] }
+humantime = "2.1.0"
 
 [dev-dependencies]
 # Error propagation
@@ -49,7 +50,7 @@ eyre = "0.6.8"
 miette = { version = "5.3.0", features = ["fancy"] }
 
 # Logging
-env_logger = "0.10.0"
+tracing-subscriber = "0.3.16"
 
 # Tokio
 tokio = { version = "1.20.1", features = ["full"] }

diff --git a/README.md b/README.md
@@ -24,11 +24,12 @@ Specifically, it provides:
 ## Usage Example
 
 ```rust
+#[tracing::instrument(name = "Subsys1", skip_all)]
 async fn subsys1(subsys: SubsystemHandle) -> Result<()>
 {
-    log::info!("Subsystem1 started.");
+    tracing::info!("Subsystem1 started.");
     subsys.on_shutdown_requested().await;
-    log::info!("Subsystem1 stopped.");
+    tracing::info!("Subsystem1 stopped.");
     Ok(())
 }
 ```

diff --git a/examples/01_normal_shutdown.rs b/examples/01_normal_shutdown.rs
@@ -7,33 +7,37 @@
 //! If custom arguments for the subsystem coroutines are required,
 //! a struct has to be used instead, as seen in other examples.
 
-use env_logger::{Builder, Env};
 use miette::Result;
 use tokio::time::{sleep, Duration};
 use tokio_graceful_shutdown::{SubsystemHandle, Toplevel};
 
+#[tracing::instrument(name = "Subsys1", skip_all)]
 async fn subsys1(subsys: SubsystemHandle) -> Result<()> {
-    log::info!("Subsystem1 started.");
+    tracing::info!("Subsystem1 started.");
     subsys.on_shutdown_requested().await;
-    log::info!("Shutting down Subsystem1 ...");
+    tracing::info!("Shutting down Subsystem1 ...");
     sleep(Duration::from_millis(400)).await;
-    log::info!("Subsystem1 stopped.");
+    tracing::info!("Subsystem1 stopped.");
     Ok(())
 }
 
+#[tracing::instrument(name = "Subsys2", skip_all)]
 async fn subsys2(subsys: SubsystemHandle) -> Result<()> {
-    log::info!("Subsystem2 started.");
+    tracing::info!("Subsystem2 started.");
     subsys.on_shutdown_requested().await;
-    log::info!("Shutting down Subsystem2 ...");
+    tracing::info!("Shutting down Subsystem2 ...");
     sleep(Duration::from_millis(500)).await;
-    log::info!("Subsystem2 stopped.");
+    tracing::info!("Subsystem2 stopped.");
     Ok(())
 }
 
 #[tokio::main]
 async fn main() -> Result<()> {
     // Init logging
-    Builder::from_env(Env::default().default_filter_or("debug")).init();
+    tracing_subscriber::fmt()
+        .pretty()
+        .with_max_level(tracing::Level::TRACE)
+        .init();
 
     // Create toplevel
     Toplevel::new()

diff --git a/examples/02_structs.rs b/examples/02_structs.rs
@@ -7,7 +7,6 @@
 //! trait requires an additional dependency, `async-trait`.
 
 use async_trait::async_trait;
-use env_logger::{Builder, Env};
 use miette::Result;
 use tokio::time::{sleep, Duration};
 use tokio_graceful_shutdown::{IntoSubsystem, SubsystemHandle, Toplevel};
@@ -17,12 +16,13 @@ struct Subsystem1 {
 }
 
 impl Subsystem1 {
+    #[tracing::instrument(name = "Subsys1", skip_all, fields(arg = %self.arg))]
     async fn run(self, subsys: SubsystemHandle) -> Result<()> {
-        log::info!("Subsystem1 started. Extra argument: {}", self.arg);
+        tracing::info!("Subsystem1 started. Extra argument: {}", self.arg);
         subsys.on_shutdown_requested().await;
-        log::info!("Shutting down Subsystem1 ...");
+        tracing::info!("Shutting down Subsystem1 ...");
         sleep(Duration::from_millis(500)).await;
-        log::info!("Subsystem1 stopped.");
+        tracing::info!("Subsystem1 stopped.");
         Ok(())
     }
 }
@@ -33,20 +33,24 @@ struct Subsystem2 {
 
 #[async_trait]
 impl IntoSubsystem<miette::Report> for Subsystem2 {
+    #[tracing::instrument(name = "Subsys2", skip_all, fields(arg = %self.arg))]
     async fn run(self, subsys: SubsystemHandle) -> Result<()> {
-        log::info!("Subsystem2 started. Extra argument: {}", self.arg);
+        tracing::info!("Subsystem2 started. Extra argument: {}", self.arg);
         subsys.on_shutdown_requested().await;
-        log::info!("Shutting down Subsystem2 ...");
+        tracing::info!("Shutting down Subsystem2 ...");
         sleep(Duration::from_millis(500)).await;
-        log::info!("Subsystem2 stopped.");
+        tracing::info!("Subsystem2 stopped.");
         Ok(())
     }
 }
 
 #[tokio::main]
 async fn main() -> Result<()> {
     // Init logging
-    Builder::from_env(Env::default().default_filter_or("debug")).init();
+    tracing_subscriber::fmt()
+        .pretty()
+        .with_max_level(tracing::Level::TRACE)
+        .init();
 
     let subsys1 = Subsystem1 { arg: 42 };
     let subsys2 = Subsystem2 { arg: 69 };

diff --git a/examples/03_shutdown_timeout.rs b/examples/03_shutdown_timeout.rs
@@ -4,24 +4,27 @@
 //! so the subsystem gets cancelled and the program returns an appropriate
 //! error code.
 
-use env_logger::{Builder, Env};
 use miette::Result;
 use tokio::time::{sleep, Duration};
 use tokio_graceful_shutdown::{SubsystemHandle, Toplevel};
 
+#[tracing::instrument(name = "Subsys1", skip_all)]
 async fn subsys1(subsys: SubsystemHandle) -> Result<()> {
-    log::info!("Subsystem1 started.");
+    tracing::info!("Subsystem1 started.");
     subsys.on_shutdown_requested().await;
-    log::info!("Shutting down Subsystem1 ...");
+    tracing::info!("Shutting down Subsystem1 ...");
     sleep(Duration::from_millis(2000)).await;
-    log::info!("Subsystem1 stopped.");
+    tracing::info!("Subsystem1 stopped.");
     Ok(())
 }
 
 #[tokio::main]
 async fn main() -> Result<()> {
     // Init logging
-    Builder::from_env(Env::default().default_filter_or("debug")).init();
+    tracing_subscriber::fmt()
+        .pretty()
+        .with_max_level(tracing::Level::TRACE)
+        .init();
 
     // Create toplevel
     Toplevel::new()

diff --git a/examples/04_subsystem_finished.rs b/examples/04_subsystem_finished.rs
@@ -5,21 +5,22 @@
 //! stopped intentionally, and no further measures by the runtime are performed.
 //! (unless there are no more subsystems left, in that case TopLevel would shut down anyway)
 
-use env_logger::{Builder, Env};
 use miette::Result;
 use tokio::time::{sleep, Duration};
 use tokio_graceful_shutdown::{SubsystemHandle, Toplevel};
 
+#[tracing::instrument(name = "Subsys1", skip_all)]
 async fn subsys1(_subsys: SubsystemHandle) -> Result<()> {
-    log::info!("Subsystem1 started.");
+    tracing::info!("Subsystem1 started.");
     sleep(Duration::from_millis(500)).await;
-    log::info!("Subsystem1 stopped.");
+    tracing::info!("Subsystem1 stopped.");
 
     // Task ends without an error. This should not cause the main program to shutdown,
     // because Subsys2 is still running.
     Ok(())
 }
 
+#[tracing::instrument(name = "Subsys2", skip_all)]
 async fn subsys2(subsys: SubsystemHandle) -> Result<()> {
     subsys.on_shutdown_requested().await;
     Ok(())
@@ -28,7 +29,10 @@ async fn subsys2(subsys: SubsystemHandle) -> Result<()> {
 #[tokio::main]
 async fn main() -> Result<()> {
     // Init logging
-    Builder::from_env(Env::default().default_filter_or("debug")).init();
+    tracing_subscriber::fmt()
+        .pretty()
+        .with_max_level(tracing::Level::TRACE)
+        .init();
 
     // Create toplevel
     Toplevel::new()

diff --git a/examples/05_subsystem_finished_with_error.rs b/examples/05_subsystem_finished_with_error.rs
@@ -6,20 +6,21 @@
 //! As expected, this is a graceful shutdown, giving other subsystems
 //! the chance to also shut down gracefully.
 
-use env_logger::{Builder, Env};
 use miette::{miette, Result};
 use tokio::time::{sleep, Duration};
 use tokio_graceful_shutdown::{SubsystemHandle, Toplevel};
 
+#[tracing::instrument(name = "Subsys1", skip_all)]
 async fn subsys1(_subsys: SubsystemHandle) -> Result<()> {
-    log::info!("Subsystem1 started.");
+    tracing::info!("Subsystem1 started.");
     sleep(Duration::from_millis(500)).await;
-    log::info!("Subsystem1 stopped.");
+    tracing::info!("Subsystem1 stopped.");
 
     // Task ends with an error. This should cause the main program to shutdown.
     Err(miette!("Subsystem1 threw an error."))
 }
 
+#[tracing::instrument(name = "Subsys2", skip_all)]
 async fn subsys2(subsys: SubsystemHandle) -> Result<()> {
     subsys.on_shutdown_requested().await;
     Ok(())
@@ -28,7 +29,10 @@ async fn subsys2(subsys: SubsystemHandle) -> Result<()> {
 #[tokio::main]
 async fn main() -> Result<()> {
     // Init logging
-    Builder::from_env(Env::default().default_filter_or("debug")).init();
+    tracing_subscriber::fmt()
+        .pretty()
+        .with_max_level(tracing::Level::TRACE)
+        .init();
 
     // Create toplevel
     Toplevel::new()

diff --git a/examples/06_nested_subsystems.rs b/examples/06_nested_subsystems.rs
@@ -1,34 +1,38 @@
 //! This example demonstrates how one subsystem can launch another
 //! nested subsystem.
 
-use env_logger::{Builder, Env};
 use miette::Result;
 use tokio::time::{sleep, Duration};
 use tokio_graceful_shutdown::{SubsystemHandle, Toplevel};
 
+#[tracing::instrument(name = "Subsys1", skip_all)]
 async fn subsys1(subsys: SubsystemHandle) -> Result<()> {
     subsys.start("Subsys2", subsys2);
-    log::info!("Subsystem1 started.");
+    tracing::info!("Subsystem1 started.");
     subsys.on_shutdown_requested().await;
-    log::info!("Shutting down Subsystem1 ...");
+    tracing::info!("Shutting down Subsystem1 ...");
     sleep(Duration::from_millis(500)).await;
-    log::info!("Subsystem1 stopped.");
+    tracing::info!("Subsystem1 stopped.");
     Ok(())
 }
 
+#[tracing::instrument(name = "Subsys2", skip_all)]
 async fn subsys2(subsys: SubsystemHandle) -> Result<()> {
-    log::info!("Subsystem2 started.");
+    tracing::info!("Subsystem2 started.");
     subsys.on_shutdown_requested().await;
-    log::info!("Shutting down Subsystem2 ...");
+    tracing::info!("Shutting down Subsystem2 ...");
     sleep(Duration::from_millis(500)).await;
-    log::info!("Subsystem2 stopped.");
+    tracing::info!("Subsystem2 stopped.");
     Ok(())
 }
 
 #[tokio::main]
 async fn main() -> Result<()> {
     // Init logging
-    Builder::from_env(Env::default().default_filter_or("debug")).init();
+    tracing_subscriber::fmt()
+        .pretty()
+        .with_max_level(tracing::Level::TRACE)
+        .init();
 
     // Create toplevel
     Toplevel::new()

diff --git a/examples/07_nested_error.rs b/examples/07_nested_error.rs
@@ -2,23 +2,24 @@
 //! a graceful shutdown is performed and other subsystems get the chance
 //! to clean up.
 
-use env_logger::{Builder, Env};
 use miette::{miette, Result};
 use tokio::time::{sleep, Duration};
 use tokio_graceful_shutdown::{SubsystemHandle, Toplevel};
 
+#[tracing::instrument(name = "Subsys1", skip_all)]
 async fn subsys1(subsys: SubsystemHandle) -> Result<()> {
     subsys.start("Subsys2", subsys2);
-    log::info!("Subsystem1 started.");
+    tracing::info!("Subsystem1 started.");
     subsys.on_shutdown_requested().await;
-    log::info!("Shutting down Subsystem1 ...");
+    tracing::info!("Shutting down Subsystem1 ...");
     sleep(Duration::from_millis(500)).await;
-    log::info!("Subsystem1 stopped.");
+    tracing::info!("Subsystem1 stopped.");
     Ok(())
 }
 
+#[tracing::instrument(name = "Subsys2", skip_all)]
 async fn subsys2(_subsys: SubsystemHandle) -> Result<()> {
-    log::info!("Subsystem2 started.");
+    tracing::info!("Subsystem2 started.");
     sleep(Duration::from_millis(500)).await;
 
     Err(miette!("Subsystem2 threw an error."))
@@ -27,7 +28,10 @@ async fn subsys2(_subsys: SubsystemHandle) -> Result<()> {
 #[tokio::main]
 async fn main() -> Result<()> {
     // Init logging
-    Builder::from_env(Env::default().default_filter_or("debug")).init();
+    tracing_subscriber::fmt()
+        .pretty()
+        .with_max_level(tracing::Level::TRACE)
+        .init();
 
     // Create toplevel
     Toplevel::new()

diff --git a/examples/08_panic_handling.rs b/examples/08_panic_handling.rs
@@ -4,23 +4,24 @@
 //! A normal program shutdown is performed, and other subsystems get the
 //! chance to clean up their work.
 
-use env_logger::{Builder, Env};
 use miette::Result;
 use tokio::time::{sleep, Duration};
 use tokio_graceful_shutdown::{SubsystemHandle, Toplevel};
 
+#[tracing::instrument(name = "Subsys1", skip_all)]
 async fn subsys1(subsys: SubsystemHandle) -> Result<()> {
     subsys.start("Subsys2", subsys2);
-    log::info!("Subsystem1 started.");
+    tracing::info!("Subsystem1 started.");
     subsys.on_shutdown_requested().await;
-    log::info!("Shutting down Subsystem1 ...");
+    tracing::info!("Shutting down Subsystem1 ...");
     sleep(Duration::from_millis(500)).await;
-    log::info!("Subsystem1 stopped.");
+    tracing::info!("Subsystem1 stopped.");
     Ok(())
 }
 
+#[tracing::instrument(name = "Subsys2", skip_all)]
 async fn subsys2(_subsys: SubsystemHandle) -> Result<()> {
-    log::info!("Subsystem2 started.");
+    tracing::info!("Subsystem2 started.");
     sleep(Duration::from_millis(500)).await;
 
     panic!("Subsystem2 panicked!")
@@ -29,7 +30,10 @@ async fn subsys2(_subsys: SubsystemHandle) -> Result<()> {
 #[tokio::main]
 async fn main() -> Result<()> {
     // Init logging
-    Builder::from_env(Env::default().default_filter_or("debug")).init();
+    tracing_subscriber::fmt()
+        .pretty()
+        .with_max_level(tracing::Level::TRACE)
+        .init();
 
     // Create toplevel
     Toplevel::new()