From 196e83e1f3d6d55fa55a5b82e7d36104d56ab4fd Mon Sep 17 00:00:00 2001 From: nitnelave Date: Mon, 10 Oct 2022 23:51:59 +0200 Subject: [PATCH] attributes: support custom levels for `ret` and `err` (#2335) This branch adds the ability to override the level of the events generated by the `ret` and `err` arguments to `#[instrument]`. An overridden level can be specified with: ```rust #[instrument(ret(level = "info"))] ``` ```rust #[instrument(err(level = Level::Debug))] ``` and so on. This syntax is fully backwards compatible with existing uses of the attribute. In addition, some refactoring was done to how levels are parsed and how the tokens for a specified level is generated. Fixes #2330 --- tracing-attributes/src/attr.rs | 184 +++++++++++++++++++------------ tracing-attributes/src/expand.rs | 39 ++++--- tracing-attributes/src/lib.rs | 24 +++- tracing-attributes/tests/err.rs | 69 ++++++++++++ tracing-attributes/tests/ret.rs | 50 +++++++++ 5 files changed, 281 insertions(+), 85 deletions(-) diff --git a/tracing-attributes/src/attr.rs b/tracing-attributes/src/attr.rs index 2af0400f2b..6bb586ef40 100644 --- a/tracing-attributes/src/attr.rs +++ b/tracing-attributes/src/attr.rs @@ -6,6 +6,14 @@ use quote::{quote, quote_spanned, ToTokens}; use syn::ext::IdentExt as _; use syn::parse::{Parse, ParseStream}; +/// Arguments to `#[instrument(err(...))]` and `#[instrument(ret(...))]` which describe how the +/// return value event should be emitted. +#[derive(Clone, Default, Debug)] +pub(crate) struct EventArgs { + level: Option, + pub(crate) mode: FormatMode, +} + #[derive(Clone, Default, Debug)] pub(crate) struct InstrumentArgs { level: Option, @@ -15,51 +23,15 @@ pub(crate) struct InstrumentArgs { pub(crate) follows_from: Option, pub(crate) skips: HashSet, pub(crate) fields: Option, - pub(crate) err_mode: Option, - pub(crate) ret_mode: Option, + pub(crate) err_args: Option, + pub(crate) ret_args: Option, /// Errors describing any unrecognized parse inputs that we skipped. parse_warnings: Vec, } impl InstrumentArgs { - pub(crate) fn level(&self) -> impl ToTokens { - fn is_level(lit: &LitInt, expected: u64) -> bool { - match lit.base10_parse::() { - Ok(value) => value == expected, - Err(_) => false, - } - } - - match &self.level { - Some(Level::Str(ref lit)) if lit.value().eq_ignore_ascii_case("trace") => { - quote!(tracing::Level::TRACE) - } - Some(Level::Str(ref lit)) if lit.value().eq_ignore_ascii_case("debug") => { - quote!(tracing::Level::DEBUG) - } - Some(Level::Str(ref lit)) if lit.value().eq_ignore_ascii_case("info") => { - quote!(tracing::Level::INFO) - } - Some(Level::Str(ref lit)) if lit.value().eq_ignore_ascii_case("warn") => { - quote!(tracing::Level::WARN) - } - Some(Level::Str(ref lit)) if lit.value().eq_ignore_ascii_case("error") => { - quote!(tracing::Level::ERROR) - } - Some(Level::Int(ref lit)) if is_level(lit, 1) => quote!(tracing::Level::TRACE), - Some(Level::Int(ref lit)) if is_level(lit, 2) => quote!(tracing::Level::DEBUG), - Some(Level::Int(ref lit)) if is_level(lit, 3) => quote!(tracing::Level::INFO), - Some(Level::Int(ref lit)) if is_level(lit, 4) => quote!(tracing::Level::WARN), - Some(Level::Int(ref lit)) if is_level(lit, 5) => quote!(tracing::Level::ERROR), - Some(Level::Path(ref pat)) => quote!(#pat), - Some(_) => quote! { - compile_error!( - "unknown verbosity level, expected one of \"trace\", \ - \"debug\", \"info\", \"warn\", or \"error\", or a number 1-5" - ) - }, - None => quote!(tracing::Level::INFO), - } + pub(crate) fn level(&self) -> Level { + self.level.clone().unwrap_or(Level::Info) } pub(crate) fn target(&self) -> impl ToTokens { @@ -154,12 +126,12 @@ impl Parse for InstrumentArgs { args.fields = Some(input.parse()?); } else if lookahead.peek(kw::err) { let _ = input.parse::(); - let mode = FormatMode::parse(input)?; - args.err_mode = Some(mode); + let err_args = EventArgs::parse(input)?; + args.err_args = Some(err_args); } else if lookahead.peek(kw::ret) { let _ = input.parse::()?; - let mode = FormatMode::parse(input)?; - args.ret_mode = Some(mode); + let ret_args = EventArgs::parse(input)?; + args.ret_args = Some(ret_args); } else if lookahead.peek(Token![,]) { let _ = input.parse::()?; } else { @@ -177,6 +149,55 @@ impl Parse for InstrumentArgs { } } +impl EventArgs { + pub(crate) fn level(&self, default: Level) -> Level { + self.level.clone().unwrap_or(default) + } +} + +impl Parse for EventArgs { + fn parse(input: ParseStream<'_>) -> syn::Result { + if !input.peek(syn::token::Paren) { + return Ok(Self::default()); + } + let content; + let _ = syn::parenthesized!(content in input); + let mut result = Self::default(); + let mut parse_one_arg = + || { + let lookahead = content.lookahead1(); + if lookahead.peek(kw::level) { + if result.level.is_some() { + return Err(content.error("expected only a single `level` argument")); + } + result.level = Some(content.parse()?); + } else if result.mode != FormatMode::default() { + return Err(content.error("expected only a single format argument")); + } else if let Some(ident) = content.parse::>()? { + match ident.to_string().as_str() { + "Debug" => result.mode = FormatMode::Debug, + "Display" => result.mode = FormatMode::Display, + _ => return Err(syn::Error::new( + ident.span(), + "unknown event formatting mode, expected either `Debug` or `Display`", + )), + } + } + Ok(()) + }; + parse_one_arg()?; + if !content.is_empty() { + if content.lookahead1().peek(Token![,]) { + let _ = content.parse::()?; + parse_one_arg()?; + } else { + return Err(content.error("expected `,` or `)`")); + } + } + Ok(result) + } +} + struct StrArg { value: LitStr, _p: std::marker::PhantomData, @@ -247,27 +268,6 @@ impl Default for FormatMode { } } -impl Parse for FormatMode { - fn parse(input: ParseStream<'_>) -> syn::Result { - if !input.peek(syn::token::Paren) { - return Ok(FormatMode::default()); - } - let content; - let _ = syn::parenthesized!(content in input); - let maybe_mode: Option = content.parse()?; - maybe_mode.map_or(Ok(FormatMode::default()), |ident| { - match ident.to_string().as_str() { - "Debug" => Ok(FormatMode::Debug), - "Display" => Ok(FormatMode::Display), - _ => Err(syn::Error::new( - ident.span(), - "unknown error mode, must be Debug or Display", - )), - } - }) - } -} - #[derive(Clone, Debug)] pub(crate) struct Fields(pub(crate) Punctuated); @@ -363,9 +363,12 @@ impl ToTokens for FieldKind { } #[derive(Clone, Debug)] -enum Level { - Str(LitStr), - Int(LitInt), +pub(crate) enum Level { + Trace, + Debug, + Info, + Warn, + Error, Path(Path), } @@ -375,9 +378,37 @@ impl Parse for Level { let _ = input.parse::()?; let lookahead = input.lookahead1(); if lookahead.peek(LitStr) { - Ok(Self::Str(input.parse()?)) + let str: LitStr = input.parse()?; + match str.value() { + s if s.eq_ignore_ascii_case("trace") => Ok(Level::Trace), + s if s.eq_ignore_ascii_case("debug") => Ok(Level::Debug), + s if s.eq_ignore_ascii_case("info") => Ok(Level::Info), + s if s.eq_ignore_ascii_case("warn") => Ok(Level::Warn), + s if s.eq_ignore_ascii_case("error") => Ok(Level::Error), + _ => Err(input.error( + "unknown verbosity level, expected one of \"trace\", \ + \"debug\", \"info\", \"warn\", or \"error\", or a number 1-5", + )), + } } else if lookahead.peek(LitInt) { - Ok(Self::Int(input.parse()?)) + fn is_level(lit: &LitInt, expected: u64) -> bool { + match lit.base10_parse::() { + Ok(value) => value == expected, + Err(_) => false, + } + } + let int: LitInt = input.parse()?; + match &int { + i if is_level(i, 1) => Ok(Level::Trace), + i if is_level(i, 2) => Ok(Level::Debug), + i if is_level(i, 3) => Ok(Level::Info), + i if is_level(i, 4) => Ok(Level::Warn), + i if is_level(i, 5) => Ok(Level::Error), + _ => Err(input.error( + "unknown verbosity level, expected one of \"trace\", \ + \"debug\", \"info\", \"warn\", or \"error\", or a number 1-5", + )), + } } else if lookahead.peek(Ident) { Ok(Self::Path(input.parse()?)) } else { @@ -386,6 +417,19 @@ impl Parse for Level { } } +impl ToTokens for Level { + fn to_tokens(&self, tokens: &mut TokenStream) { + match self { + Level::Trace => tokens.extend(quote!(tracing::Level::TRACE)), + Level::Debug => tokens.extend(quote!(tracing::Level::DEBUG)), + Level::Info => tokens.extend(quote!(tracing::Level::INFO)), + Level::Warn => tokens.extend(quote!(tracing::Level::WARN)), + Level::Error => tokens.extend(quote!(tracing::Level::ERROR)), + Level::Path(ref pat) => tokens.extend(quote!(#pat)), + } + } +} + mod kw { syn::custom_keyword!(fields); syn::custom_keyword!(skip); diff --git a/tracing-attributes/src/expand.rs b/tracing-attributes/src/expand.rs index 0390a8c44e..d6b7855615 100644 --- a/tracing-attributes/src/expand.rs +++ b/tracing-attributes/src/expand.rs @@ -10,7 +10,7 @@ use syn::{ }; use crate::{ - attr::{Field, Fields, FormatMode, InstrumentArgs}, + attr::{Field, Fields, FormatMode, InstrumentArgs, Level}, MaybeItemFn, MaybeItemFnRef, }; @@ -116,7 +116,8 @@ fn gen_block( .map(|name| quote!(#name)) .unwrap_or_else(|| quote!(#instrumented_function_name)); - let level = args.level(); + let args_level = args.level(); + let level = args_level.clone(); let follows_from = args.follows_from.iter(); let follows_from = quote! { @@ -232,21 +233,33 @@ fn gen_block( let target = args.target(); - let err_event = match args.err_mode { - Some(FormatMode::Default) | Some(FormatMode::Display) => { - Some(quote!(tracing::error!(target: #target, error = %e))) + let err_event = match args.err_args { + Some(event_args) => { + let level_tokens = event_args.level(Level::Error); + match event_args.mode { + FormatMode::Default | FormatMode::Display => Some(quote!( + tracing::event!(target: #target, #level_tokens, error = %e) + )), + FormatMode::Debug => Some(quote!( + tracing::event!(target: #target, #level_tokens, error = ?e) + )), + } } - Some(FormatMode::Debug) => Some(quote!(tracing::error!(target: #target, error = ?e))), _ => None, }; - let ret_event = match args.ret_mode { - Some(FormatMode::Display) => Some(quote!( - tracing::event!(target: #target, #level, return = %x) - )), - Some(FormatMode::Default) | Some(FormatMode::Debug) => Some(quote!( - tracing::event!(target: #target, #level, return = ?x) - )), + let ret_event = match args.ret_args { + Some(event_args) => { + let level_tokens = event_args.level(args_level); + match event_args.mode { + FormatMode::Display => Some(quote!( + tracing::event!(target: #target, #level_tokens, return = %x) + )), + FormatMode::Default | FormatMode::Debug => Some(quote!( + tracing::event!(target: #target, #level_tokens, return = ?x) + )), + } + } _ => None, }; diff --git a/tracing-attributes/src/lib.rs b/tracing-attributes/src/lib.rs index 6165803695..269e32522c 100644 --- a/tracing-attributes/src/lib.rs +++ b/tracing-attributes/src/lib.rs @@ -227,10 +227,20 @@ mod expand; /// 42 /// } /// ``` -/// The return value event will have the same level as the span generated by `#[instrument]`. -/// By default, this will be `TRACE`, but if the level is overridden, the event will be at the same +/// The level of the return value event defaults to the same level as the span generated by `#[instrument]`. +/// By default, this will be `TRACE`, but if the span level is overridden, the event will be at the same /// level. /// +/// It's also possible to override the level for the `ret` event independently: +/// +/// ``` +/// # use tracing_attributes::instrument; +/// #[instrument(ret(level = "warn"))] +/// fn my_function() -> i32 { +/// 42 +/// } +/// ``` +/// /// **Note**: if the function returns a `Result`, `ret` will record returned values if and /// only if the function returns [`Result::Ok`]. /// @@ -257,6 +267,16 @@ mod expand; /// } /// ``` /// +/// Similarly, you can override the level of the `err` event: +/// +/// ``` +/// # use tracing_attributes::instrument; +/// #[instrument(err(level = "info"))] +/// fn my_function(arg: usize) -> Result<(), std::io::Error> { +/// Ok(()) +/// } +/// ``` +/// /// By default, error values will be recorded using their `std::fmt::Display` implementations. /// If an error implements `std::fmt::Debug`, it can be recorded using its `Debug` implementation /// instead, by writing `err(Debug)`: diff --git a/tracing-attributes/tests/err.rs b/tracing-attributes/tests/err.rs index d062a2b7c1..842a6e0e3a 100644 --- a/tracing-attributes/tests/err.rs +++ b/tracing-attributes/tests/err.rs @@ -252,3 +252,72 @@ fn test_err_custom_target() { }); handle.assert_finished(); } + +#[instrument(err(level = "info"))] +fn err_info() -> Result { + u8::try_from(1234) +} + +#[test] +fn test_err_info() { + let span = span::mock().named("err_info"); + let (collector, handle) = collector::mock() + .new_span(span.clone()) + .enter(span.clone()) + .event(event::mock().at_level(Level::INFO)) + .exit(span.clone()) + .drop_span(span) + .done() + .run_with_handle(); + with_default(collector, || err_info().ok()); + handle.assert_finished(); +} + +#[instrument(err(Debug, level = "info"))] +fn err_dbg_info() -> Result { + u8::try_from(1234) +} + +#[test] +fn test_err_dbg_info() { + let span = span::mock().named("err_dbg_info"); + let (collector, handle) = collector::mock() + .new_span(span.clone()) + .enter(span.clone()) + .event( + event::mock().at_level(Level::INFO).with_fields( + field::mock("error") + // use the actual error value that will be emitted, so + // that this test doesn't break if the standard library + // changes the `fmt::Debug` output from the error type + // in the future. + .with_value(&tracing::field::debug(u8::try_from(1234).unwrap_err())), + ), + ) + .exit(span.clone()) + .drop_span(span) + .done() + .run_with_handle(); + with_default(collector, || err_dbg_info().ok()); + handle.assert_finished(); +} + +#[instrument(level = "warn", err(level = "info"))] +fn err_warn_info() -> Result { + u8::try_from(1234) +} + +#[test] +fn test_err_warn_info() { + let span = span::mock().named("err_warn_info").at_level(Level::WARN); + let (collector, handle) = collector::mock() + .new_span(span.clone()) + .enter(span.clone()) + .event(event::mock().at_level(Level::INFO)) + .exit(span.clone()) + .drop_span(span) + .done() + .run_with_handle(); + with_default(collector, || err_warn_info().ok()); + handle.assert_finished(); +} diff --git a/tracing-attributes/tests/ret.rs b/tracing-attributes/tests/ret.rs index fce206e0f6..2511e0a520 100644 --- a/tracing-attributes/tests/ret.rs +++ b/tracing-attributes/tests/ret.rs @@ -253,3 +253,53 @@ fn test_ret_and_ok() { with_default(collector, || ret_and_ok().ok()); handle.assert_finished(); } + +#[instrument(level = "warn", ret(level = "info"))] +fn ret_warn_info() -> i32 { + 42 +} + +#[test] +fn test_warn_info() { + let span = span::mock().named("ret_warn_info").at_level(Level::WARN); + let (collector, handle) = collector::mock() + .new_span(span.clone()) + .enter(span.clone()) + .event( + event::mock() + .with_fields(field::mock("return").with_value(&tracing::field::debug(42))) + .at_level(Level::INFO), + ) + .exit(span.clone()) + .drop_span(span) + .done() + .run_with_handle(); + + with_default(collector, ret_warn_info); + handle.assert_finished(); +} + +#[instrument(ret(level = "warn", Debug))] +fn ret_dbg_warn() -> i32 { + 42 +} + +#[test] +fn test_dbg_warn() { + let span = span::mock().named("ret_dbg_warn").at_level(Level::INFO); + let (collector, handle) = collector::mock() + .new_span(span.clone()) + .enter(span.clone()) + .event( + event::mock() + .with_fields(field::mock("return").with_value(&tracing::field::debug(42))) + .at_level(Level::WARN), + ) + .exit(span.clone()) + .drop_span(span) + .done() + .run_with_handle(); + + with_default(collector, ret_dbg_warn); + handle.assert_finished(); +}