Add support for initializing tracing

There is a second kind of infrastructure in addition to logging that
requires initialization: tracing. In a nutshell, in order to collect
traces we need to register a subscriber. In our case, we want this
subscriber to log events and spans as it would do for regular log based
messages.
This change adds the infrastructure for doing so. In binaries we would
typically just set a global subscriber and be done. However, we want to
preserve per-test configurability and so we just set the subscriber for
the context of the test.
Because conceptually logging and tracing are two separate concerns and
applications are free to mix and match, we introduce two features, log
and trace, that enable one or the other or both.

CHANGELOG.md

@@ -1,5 +1,8 @@
 Unreleased
 ----------
+- Added support for initializing `tracing` infrastructure
+  - Introduced `log` (enabled by default) and `trace` features (disabled
+    by default)
 - Dropped `env_logger` dependency
 
 

Cargo.toml

@@ -18,11 +18,11 @@ keywords = [
   "log",
   "logging",
   "testing",
-  "tests",
+  "tracing",
 ]
 description = """
-A replacement of the #[test] attribute that initializes the env_logger
-before running tests.
+A replacement of the #[test] attribute that initializes logging and/or
+tracing infrastructure before running tests.
 """
 
 [badges]
@@ -31,12 +31,20 @@ gitlab = { repository = "d-e-s-o/test-env-log", branch = "master" }
 [lib]
 proc-macro = true
 
+[features]
+default = ["log"]
+trace = []
+log = []
+
 [dependencies]
 proc-macro2 = "1.0"
 quote = {version = "1.0"}
 syn = {version = "1.0", features = ["full"]}
 
 [dev-dependencies]
 env_logger = {version = "0.7", default-features = false}
-log = "0.4"
+logging = {version = "0.4", package = "log"}
 tokio = {version = "0.2", default-features = false, features = ["rt-core", "macros"]}
+tracing = {version = "0.1", default-features = false}
+tracing-futures = {version = "0.2", default-features = false, features = ["std-future"]}
+tracing-subscriber = {version = "0.1.6", default-features = false, features = ["env-filter", "fmt"]}

README.md

@@ -10,22 +10,28 @@ test-env-log
 - [Changelog](CHANGELOG.md)
 
 **test-env-log** is a crate that takes care of automatically
-initializing `env_logger` for Rust tests.
+initializing logging and/or tracing for Rust tests.
 
 When running Rust tests it can often be helpful to have easy access to
-the verbose log messages emitted by the code under test. Assuming said
-code uses the [`log`](https://crates.io/crates/log) backend for its
-logging purposes that may not be straight forward, however. The problem
-is that all crates making use of `log` require some form of
-initialization to be usable.
-
-The commonly used [`env_logger`](https://crates.io/crates/env_logger),
-for example, needs to be initialized like this:
+the verbose log messages emitted by the code under test. Commonly, these
+log messages may be coming from the [`log`][log] crate or being emitted
+through the [`tracing`][tracing] infrastructure.
+
+The problem with either -- in the context of testing -- is that some
+form of initialization is required in order to make these crate's
+messages appear on a standard output stream.
+
+The commonly used [`env_logger`](https://crates.io/crates/env_logger)
+(which provides an easy way to configure `log` based logging), for
+example, needs to be initialized like this:
 ```rust
 let _ = env_logger::builder().is_test(true).try_init();
 ```
 in **each and every** test.
 
+Similarly, `tracing` based solutions require a subscriber to be
+registered that writes events/spans to the console.
+
 This crate takes care of this per-test initialization in an intuitive
 way.
 
@@ -34,8 +40,11 @@ Usage
 -----
 
 The crate provides a custom `#[test]` attribute that, when used for
-running a particular test, takes care of initializing `env_logger`
-beforehand.
+running a particular test, takes care of initializing `log` and/or
+`tracing` beforehand.
+
+#### Example
+
 As such, usage is as simple as importing and using said attribute:
 ```rust
 use test_env_log::test;
@@ -57,17 +66,46 @@ fn it_still_works() {
 }
 ```
 
+
+#### Logging Configuration
+
 As usual when running `cargo test`, the output is captured by the
 framework by default and only shown on test failure. The `--nocapture`
 argument can be supplied in order to overwrite this setting. E.g.,
 ```bash
 $ cargo test -- --nocapture
 ```
 
-Furthermore, by virtue of using `env_logger`, the `RUST_LOG` environment
-variable is honored and can be used to influence the log level to work
-with. Please refer to the [`env_logger` docs][env-docs-rs] for more
+Furthermore, the `RUST_LOG` environment variable is honored and can be
+used to influence the log level to work with (among other things).
+Please refer to the [`env_logger` docs][env-docs-rs] for more
 information.
 
+
+#### Features
+
+The crate comes with two features:
+- `log`, enabled by default, controls initialization for the `log`
+  crate.
+- `trace`, disabled by default, controls initialization for the
+  `tracing` crate.
+
+Depending on what backend the crate-under-test (and its dependencies)
+use, the respective feature should be enabled to make messages that are
+emitted by the test manifest on the console.
+
+Note that as a user you are required to explicitly add `env_logger` or
+`tracing-subscriber` as a dependency to your project-under-test (when
+enabling the `log` or `trace` feature, respectively). E.g.,
+
+```toml
+[dependencies]
+env_logger = "*"
+tracing-subscriber = {version = "0.1.6", features = ["chrono", "env-filter", "fmt"]}
+```
+
+
 [docs-rs]: https://docs.rs/crate/test-env-log
 [env-docs-rs]: https://docs.rs/env_logger/0.7.0/env_logger
+[log]: https://crates.io/crates/log
+[tracing]: https://crates.io/crates/tracing

src/lib.rs

@@ -6,6 +6,7 @@ extern crate proc_macro;
 use proc_macro::TokenStream;
 use proc_macro2::Ident;
 use proc_macro2::Span;
+use proc_macro2::TokenStream as Tokens;
 
 use quote::quote;
 
@@ -32,8 +33,9 @@ use syn::ReturnType;
 /// # // doctests seemingly run in a slightly different environment where
 /// # // `super`, which is what our macro makes use of, is not available.
 /// # // By having a fake module here we work around that problem.
+/// # #[cfg(feature = "log")]
 /// # mod fordoctest {
-/// # use log::info;
+/// # use logging::info;
 /// # // Note that no test would actually run, regardless of `no_run`,
 /// # // because we do not invoke the function.
 /// #[test_env_log::test]
@@ -72,6 +74,35 @@ pub fn test(attr: TokenStream, item: TokenStream) -> TokenStream {
 }
 
 
+/// Expand the initialization code for the `log` crate.
+fn expand_logging_init() -> Tokens {
+  #[cfg(feature = "log")]
+  quote! {
+    {
+      let _ = ::env_logger::builder().is_test(true).try_init();
+    }
+  }
+  #[cfg(not(feature = "log"))]
+  quote! {}
+}
+
+
+/// Expand the initialization code for the `tracing` crate.
+fn expand_tracing_init() -> Tokens {
+  #[cfg(feature = "trace")]
+  quote! {
+    let _guard = {
+      let subscriber = ::tracing_subscriber::FmtSubscriber::builder()
+        .with_env_filter(::tracing_subscriber::EnvFilter::from_default_env())
+        .finish();
+      ::tracing::subscriber::set_default(subscriber)
+    };
+  }
+  #[cfg(not(feature = "trace"))]
+  quote! {}
+}
+
+
 /// Emit code for a wrapper function around a test function.
 // We have to jump through a lot of hoops here to allow for the case
 // where the user imports test_env_log::test as test. In such a case
@@ -127,6 +158,9 @@ fn expand_wrapper(inner_test: &Path, wrappee: &ItemFn) -> TokenStream {
     ),
   };
 
+  let logging_init = expand_logging_init();
+  let tracing_init = expand_tracing_init();
+
   let result = quote! {
     #async_ fn #test_name() -> #ret_type {
       #body
@@ -140,7 +174,9 @@ fn expand_wrapper(inner_test: &Path, wrappee: &ItemFn) -> TokenStream {
       #[#inner_test]
       #(#attrs)*
       #async_ fn f() -> #alias_ref {
-        let _ = ::env_logger::builder().is_test(true).try_init();
+        #logging_init
+        #tracing_init
+
         super::#test_name()#await_
       }
     }

tests/mod.rs

@@ -1,6 +1,14 @@
 // Copyright (C) 2019-2020 Daniel Mueller <[email protected]>
 // SPDX-License-Identifier: (Apache-2.0 OR MIT)
 
+use tokio::runtime::Builder;
+
+use tracing::debug;
+use tracing::error;
+use tracing::info;
+use tracing::instrument;
+
+
 mod something {
   pub type Error = String;
 }
@@ -29,6 +37,36 @@ async fn with_inner_test_attribute_and_async() {
   assert_eq!(async { 42 }.await, 42)
 }
 
+#[instrument]
+async fn instrumented(input: usize) -> usize {
+  info!("input = {}", input);
+  if input == 0 || input == 4 {
+    error!("here we go");
+  }
+  let result = input + 1;
+  info!("result = {}", result);
+  result
+}
+
+#[test_env_log::test]
+fn trace_with_custom_runtime() {
+  let mut rt = Builder::new().basic_scheduler().build().unwrap();
+
+  rt.block_on(async {
+    instrumented(0).await;
+    instrumented(1).await;
+    debug!("done");
+  })
+}
+
+#[test_env_log::test(tokio::test)]
+async fn trace_with_tokio_attribute() {
+  instrumented(6).await;
+  instrumented(4).await;
+  debug!("done");
+}
+
+
 mod local {
   use super::Error;