From 528e6331ada6ce5e41e66436fc27fb0acde4ddfe 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 ``` ```rust ``` 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 ; Conflicts: ; tracing-attributes/src/lib.rs --- tracing-attributes/src/attr.rs | 184 +++++++++++++++++++------------ tracing-attributes/src/expand.rs | 39 ++++--- tracing-attributes/src/lib.rs | 20 ++++ tracing-attributes/tests/err.rs | 69 ++++++++++++ tracing-attributes/tests/ret.rs | 50 +++++++++ 5 files changed, 279 insertions(+), 83 deletions(-) diff --git a/tracing-attributes/src/attr.rs b/tracing-attributes/src/attr.rs index ff875e1797..0ad68ef756 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, @@ -16,51 +24,15 @@ pub(crate) struct InstrumentArgs { pub(crate) skips: HashSet, pub(crate) skip_all: bool, 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 { @@ -167,12 +139,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 { @@ -190,6 +162,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, @@ -260,27 +281,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); @@ -376,9 +376,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), } @@ -388,9 +391,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 { @@ -399,6 +430,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 cb12ad87e4..0339dcb1f3 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 cc0b8e5198..00e24d0163 100644 --- a/tracing-attributes/src/lib.rs +++ b/tracing-attributes/src/lib.rs @@ -422,6 +422,16 @@ mod expand; /// By default, this will be [`INFO`], but if the 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`]. /// @@ -448,6 +458,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 9e6d6b78c3..a030138407 100644 --- a/tracing-attributes/tests/err.rs +++ b/tracing-attributes/tests/err.rs @@ -231,3 +231,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 cfd2de10d3..c29c87ea8a 100644 --- a/tracing-attributes/tests/ret.rs +++ b/tracing-attributes/tests/ret.rs @@ -253,3 +253,53 @@ fn test_ret_and_ok() { with_default(subscriber, || 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(); +}