Add #[test_log(default_log_filter = "___")]

Users can now specify a default_log_filter via #[test_log(default_log_filter = "foo")]
which will be used when RUST_LOG is not specified.

Please note that because env_logger / tracing is initialized globally,
it is possible that this value will be ignored if they have already been
initialized by a different test.

Fixes: #25

CHANGELOG.md

@@ -1,5 +1,7 @@
 Unreleased
 ----------
+- Introduced `default_log_filter` attribute for setting the default log
+  filter on a per-test basis
 - Improved compile error output on wrong usage
 
 

Cargo.toml

@@ -30,6 +30,10 @@ include = ["src/lib.rs", "LICENSE-*", "README.md", "CHANGELOG.md"]
 [lib]
 proc-macro = true
 
+[[test]]
+name = "default_log_filter"
+required-features = ["log"]
+
 [features]
 default = ["log"]
 trace = []
@@ -47,4 +51,4 @@ test-case = {version = "3.1"}
 tokio = {version = "1.0", default-features = false, features = ["rt-multi-thread", "macros"]}
 tracing = {version = "0.1.20"}
 tracing-futures = {version = "0.2", default-features = false, features = ["std-future"]}
-tracing-subscriber = {version = "0.3", default-features = false, features = ["env-filter", "fmt"]}
+tracing-subscriber = {version = "0.3.10", default-features = false, features = ["env-filter", "fmt", "std"]}

README.md

@@ -120,7 +120,7 @@ enabling the `log` or `trace` feature, respectively). E.g.,
 ```toml
 [dev-dependencies]
 env_logger = "*"
-tracing-subscriber = {version = "0.3", default-features = false, features = ["env-filter", "fmt"]}
+tracing-subscriber = {version = "0.3.10", default-features = false, features = ["env-filter", "fmt", "std"]}
 ```
 
 

src/lib.rs

@@ -14,8 +14,13 @@ use proc_macro2::TokenStream as Tokens;
 
 use quote::quote;
 
+use syn::parse::Parse;
 use syn::parse_macro_input;
+use syn::Attribute;
+use syn::Expr;
 use syn::ItemFn;
+use syn::Lit;
+use syn::Meta;
 
 
 /// A procedural macro for the `test` attribute.
@@ -78,6 +83,19 @@ pub fn test(attr: TokenStream, item: TokenStream) -> TokenStream {
     .into()
 }
 
+fn parse_attrs(attrs: Vec<Attribute>) -> syn::Result<(AttributeArgs, Vec<Attribute>)> {
+  let mut attribute_args = AttributeArgs::default();
+  let mut ignored_attrs = vec![];
+  for attr in attrs {
+    let matched = attribute_args.try_parse_attr_single(&attr)?;
+    // Keep only attrs that didn't match the #[test_log(_)] syntax.
+    if !matched {
+      ignored_attrs.push(attr);
+    }
+  }
+
+  Ok((attribute_args, ignored_attrs))
+}
 
 fn try_test(attr: TokenStream, input: ItemFn) -> syn::Result<Tokens> {
   let inner_test = if attr.is_empty() {
@@ -93,12 +111,13 @@ fn try_test(attr: TokenStream, input: ItemFn) -> syn::Result<Tokens> {
     block,
   } = input;
 
-  let logging_init = expand_logging_init();
-  let tracing_init = expand_tracing_init();
+  let (attribute_args, ignored_attrs) = parse_attrs(attrs)?;
+  let logging_init = expand_logging_init(&attribute_args);
+  let tracing_init = expand_tracing_init(&attribute_args);
 
   let result = quote! {
     #[#inner_test]
-    #(#attrs)*
+    #(#ignored_attrs)*
     #vis #sig {
       // We put all initialization code into a separate module here in
       // order to prevent potential ambiguities that could result in
@@ -126,22 +145,110 @@ fn try_test(attr: TokenStream, input: ItemFn) -> syn::Result<Tokens> {
 }
 
 
+#[derive(Debug, Default)]
+struct AttributeArgs {
+  default_log_filter: Option<String>,
+}
+
+impl AttributeArgs {
+  fn try_parse_attr_single(&mut self, attr: &Attribute) -> syn::Result<bool> {
+    if !attr.path().is_ident("test_log") {
+      return Ok(false)
+    }
+
+    let nested_meta = attr.parse_args_with(Meta::parse)?;
+    let name_value = if let Meta::NameValue(name_value) = nested_meta {
+      name_value
+    } else {
+      return Err(syn::Error::new_spanned(
+        &nested_meta,
+        "Expected NameValue syntax, e.g. 'default_log_filter = \"debug\"'.",
+      ))
+    };
+
+    let ident = if let Some(ident) = name_value.path.get_ident() {
+      ident
+    } else {
+      return Err(syn::Error::new_spanned(
+        &name_value.path,
+        "Expected NameValue syntax, e.g. 'default_log_filter = \"debug\"'.",
+      ))
+    };
+
+    let arg_ref = if ident == "default_log_filter" {
+      &mut self.default_log_filter
+    } else {
+      return Err(syn::Error::new_spanned(
+        &name_value.path,
+        "Unrecognized attribute, see documentation for details.",
+      ))
+    };
+
+    if let Expr::Lit(lit) = &name_value.value {
+      if let Lit::Str(lit_str) = &lit.lit {
+        *arg_ref = Some(lit_str.value());
+      }
+    }
+
+    // If we couldn't parse the value on the right-hand side because it was some
+    // unexpected type, e.g. #[test_log::log(default_log_filter=10)], return an error.
+    if arg_ref.is_none() {
+      return Err(syn::Error::new_spanned(
+        &name_value.value,
+        "Failed to parse value, expected a string",
+      ))
+    }
+
+    Ok(true)
+  }
+}
+
+
 /// Expand the initialization code for the `log` crate.
-fn expand_logging_init() -> Tokens {
-  #[cfg(feature = "log")]
+#[cfg(feature = "log")]
+fn expand_logging_init(attribute_args: &AttributeArgs) -> Tokens {
+  let add_default_log_filter = if let Some(default_log_filter) = &attribute_args.default_log_filter
+  {
+    quote! {
+      let env_logger_builder = env_logger_builder
+        .parse_env(::env_logger::Env::default().default_filter_or(#default_log_filter));
+    }
+  } else {
+    quote! {}
+  };
+
   quote! {
     {
-      let _ = ::env_logger::builder().is_test(true).try_init();
+      let mut env_logger_builder = ::env_logger::builder();
+      #add_default_log_filter
+      let _ = env_logger_builder.is_test(true).try_init();
     }
   }
-  #[cfg(not(feature = "log"))]
+}
+
+#[cfg(not(feature = "log"))]
+fn expand_logging_init(_attribute_args: &AttributeArgs) -> Tokens {
   quote! {}
 }
 
 
 /// Expand the initialization code for the `tracing` crate.
-fn expand_tracing_init() -> Tokens {
-  #[cfg(feature = "trace")]
+#[cfg(feature = "trace")]
+fn expand_tracing_init(attribute_args: &AttributeArgs) -> Tokens {
+  let env_filter = if let Some(default_log_filter) = &attribute_args.default_log_filter {
+    quote! {
+      ::tracing_subscriber::EnvFilter::builder()
+        .with_default_directive(
+          #default_log_filter
+            .parse()
+            .expect("test-log: default_log_filter must be valid")
+        )
+        .from_env_lossy()
+    }
+  } else {
+    quote! { ::tracing_subscriber::EnvFilter::from_default_env() }
+  };
+
   quote! {
     {
       let __internal_event_filter = {
@@ -172,12 +279,15 @@ fn expand_tracing_init() -> Tokens {
       };
 
       let _ = ::tracing_subscriber::FmtSubscriber::builder()
-        .with_env_filter(::tracing_subscriber::EnvFilter::from_default_env())
+        .with_env_filter(#env_filter)
         .with_span_events(__internal_event_filter)
         .with_test_writer()
         .try_init();
     }
   }
-  #[cfg(not(feature = "trace"))]
+}
+
+#[cfg(not(feature = "trace"))]
+fn expand_tracing_init(_attribute_args: &AttributeArgs) -> Tokens {
   quote! {}
 }

tests/default_log_filter.rs

@@ -0,0 +1,21 @@
+//! This test needs to be defined in a separate file because it depends
+//! on global state (logger) and can't be run in parallel/the same
+//! process with other tests to avoid flakiness (other tests
+//! initializing `env_logger` first).
+
+use std::env;
+
+use logging::log_enabled;
+use logging::Level;
+
+
+#[ignore = "interferes with RUST_LOG; disabled by default"]
+#[test_log::test(tokio::test)]
+#[test_log(default_log_filter = "debug")]
+async fn with_inner_test_attribute_and_default_log_filter_defined() {
+  // Check that RUST_LOG isn't set, because that could affect the
+  // outcome of this test since we're checking that we fallback to
+  // "debug" if no RUST_LOG is set.
+  assert!(env::var(env_logger::DEFAULT_FILTER_ENV).is_err());
+  assert!(log_enabled!(Level::Debug));
+}

tests/mod.rs

@@ -68,6 +68,19 @@ async fn instrumented(input: usize) -> usize {
   result
 }
 
+/// To run the tracing tests and manually verify the output, run with
+/// the `trace` feature:
+/// ```sh
+/// cargo test --features trace trace_with_custom_runtime -- --nocapture
+/// ```
+///
+/// Log level can be configured via the `RUST_LOG` env variable and span
+/// events for `#[instrumented]` can be configured via the
+/// `RUST_LOG_SPAN_EVENTS` env variable:
+/// ```sh
+/// RUST_LOG=debug RUST_LOG_SPAN_EVENTS=full \
+///   cargo test --features trace trace_with_custom_runtime -- --nocapture
+/// ```
 #[test_log::test]
 fn trace_with_custom_runtime() {
   let rt = Builder::new_current_thread().build().unwrap();
@@ -86,6 +99,14 @@ async fn trace_with_tokio_attribute() {
   debug!("done");
 }
 
+#[test_log::test(tokio::test)]
+#[test_log(default_log_filter = "info")]
+async fn trace_with_default_log_filter() {
+  instrumented(6).await;
+  instrumented(4).await;
+  debug!("done");
+}
+
 #[test_log::test(tokio::test(flavor = "multi_thread", worker_threads = 1))]
 async fn trace_with_tokio_attribute_with_arguments() {
   instrumented(6).await;

tests/prototype.rs

@@ -0,0 +1,13 @@
+//! Use this file for iterating on the derive code. You can view the
+//! expanded code for any given configuration by updating this file and
+//! running:
+//!
+//! ```sh
+//! cargo expand --test=prototype
+//! ```
+
+
+#[test_log::test]
+fn it_works() {
+  assert_eq!(2 + 2, 4);
+}