diff --git a/CHANGELOG.md b/CHANGELOG.md index b1cc856..6653026 100644 --- a/CHANGELOG.md +++ b/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 diff --git a/Cargo.toml b/Cargo.toml index 7d56937..0f28249 100644 --- a/Cargo.toml +++ b/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"]} diff --git a/README.md b/README.md index a714b36..4352e8c 100644 --- a/README.md +++ b/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"]} ``` diff --git a/src/lib.rs b/src/lib.rs index 0a0d8fd..b46c29d 100644 --- a/src/lib.rs +++ b/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) -> syn::Result<(AttributeArgs, Vec)> { + 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 { let inner_test = if attr.is_empty() { @@ -93,12 +111,13 @@ fn try_test(attr: TokenStream, input: ItemFn) -> syn::Result { 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 { } +#[derive(Debug, Default)] +struct AttributeArgs { + default_log_filter: Option, +} + +impl AttributeArgs { + fn try_parse_attr_single(&mut self, attr: &Attribute) -> syn::Result { + 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! {} } diff --git a/tests/default_log_filter.rs b/tests/default_log_filter.rs new file mode 100644 index 0000000..00f59c6 --- /dev/null +++ b/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)); +} diff --git a/tests/mod.rs b/tests/mod.rs index c52fea5..e38aa67 100644 --- a/tests/mod.rs +++ b/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; diff --git a/tests/prototype.rs b/tests/prototype.rs new file mode 100644 index 0000000..afc4aa4 --- /dev/null +++ b/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); +}