From fbf72a1c8c8d1d64f62bd4e424ebc3b8af5006b7 Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Tue, 7 Apr 2020 11:48:20 -0700 Subject: [PATCH 01/13] attributes: add test for expression fields Signed-off-by: Eliza Weisman --- tracing-attributes/tests/fields.rs | 37 ++++++++++++++++++++++++++++++ 1 file changed, 37 insertions(+) diff --git a/tracing-attributes/tests/fields.rs b/tracing-attributes/tests/fields.rs index 98b63f6f9a..e048d1aae8 100644 --- a/tracing-attributes/tests/fields.rs +++ b/tracing-attributes/tests/fields.rs @@ -15,6 +15,19 @@ fn fn_param(param: u32) {} #[instrument(fields(foo = "bar", empty))] fn fn_empty_field() {} +#[instrument(fields(len = s.len()))] +fn fn_expr_field(s: &str) {} + +#[derive(Debug)] +struct HasField { + my_field: &'static str, +} + +impl HasField { + #[instrument(fields(my_field = self.my_field), skip(self))] + fn self_expr_field(&self) {} +} + #[test] fn fields() { let span = span::mock().with_field( @@ -29,6 +42,30 @@ fn fields() { }); } +#[test] +fn expr_field() { + let span = span::mock().with_field( + mock("s") + .with_value(&tracing::field::debug("hello world")) + .and(mock("len").with_value(&"hello world".len())) + .only(), + ); + run_test(span, || { + fn_expr_field(&"hello world"); + }); +} + +#[test] +fn self_expr_field() { + let span = span::mock().with_field(mock("my_field").with_value(&"hello world").only()); + run_test(span, || { + let has_field = HasField { + my_field: "hello world", + }; + has_field.self_expr_field(); + }); +} + #[test] fn parameters_with_fields() { let span = span::mock().with_field( From 8a565e3a5f5a1bbe81eca6602da45dc08d11116c Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Tue, 7 Apr 2020 15:06:16 -0700 Subject: [PATCH 02/13] attributes: add support for arbitrary field values Signed-off-by: Eliza Weisman --- tracing-attributes/Cargo.toml | 1 + tracing-attributes/src/lib.rs | 403 ++++++++++++++++++++++++++-------- 2 files changed, 311 insertions(+), 93 deletions(-) diff --git a/tracing-attributes/Cargo.toml b/tracing-attributes/Cargo.toml index 0939e6d12a..f3cfb1efa6 100644 --- a/tracing-attributes/Cargo.toml +++ b/tracing-attributes/Cargo.toml @@ -38,6 +38,7 @@ proc-macro = true async-await = [] [dependencies] +proc-macro2 = "1" syn = { version = "1", features = ["full", "extra-traits"] } quote = "1" diff --git a/tracing-attributes/src/lib.rs b/tracing-attributes/src/lib.rs index 01404cadc0..957d0f7d6b 100644 --- a/tracing-attributes/src/lib.rs +++ b/tracing-attributes/src/lib.rs @@ -65,14 +65,15 @@ extern crate proc_macro; use std::collections::{HashMap, HashSet}; use std::iter; -use proc_macro::TokenStream; -use quote::{quote, quote_spanned, ToTokens}; +use proc_macro2::TokenStream; +use quote::{quote, quote_spanned, ToTokens, TokenStreamExt as _}; +use syn::parse::{Parse, ParseStream}; use syn::{ - spanned::Spanned, AttributeArgs, FieldPat, FnArg, Ident, ItemFn, Lit, LitInt, Meta, MetaList, - MetaNameValue, NestedMeta, Pat, PatIdent, PatReference, PatStruct, PatTuple, PatTupleStruct, - PatType, Path, Signature, + punctuated::Punctuated, spanned::Spanned, AttributeArgs, Expr, FieldPat, FnArg, Ident, ItemFn, + Lit, LitInt, LitStr, Meta, MetaList, MetaNameValue, NestedMeta, Pat, PatIdent, PatReference, + PatStruct, PatTuple, PatTupleStruct, PatType, Path, Signature, Token, }; - +use syn::ext::IdentExt as _; /// Instruments a function to create and enter a `tracing` [span] every time /// the function is called. /// @@ -173,9 +174,9 @@ use syn::{ /// [`tracing`]: https://github.com/tokio-rs/tracing /// [`fmt::Debug`]: https://doc.rust-lang.org/std/fmt/trait.Debug.html #[proc_macro_attribute] -pub fn instrument(args: TokenStream, item: TokenStream) -> TokenStream { +pub fn instrument(args: proc_macro::TokenStream, item: proc_macro::TokenStream) -> proc_macro::TokenStream { let input: ItemFn = syn::parse_macro_input!(item as ItemFn); - let args = syn::parse_macro_input!(args as AttributeArgs); + let args = syn::parse_macro_input!(args as InstrumentArgs); // these are needed ahead of time, as ItemFn contains the function body _and_ // isn't representable inside a quote!/quote_spanned! macro @@ -204,18 +205,9 @@ pub fn instrument(args: TokenStream, item: TokenStream) -> TokenStream { }, .. } = sig; - - // function name - let ident_str = ident.to_string(); - + let err = args.err; // generate this inside a closure, so we can return early on errors. let span = (|| { - // Pull out the arguments-to-be-skipped first, so we can filter results below. - let skips = match skips(&args) { - Ok(skips) => skips, - Err(err) => return quote!(#err), - }; - let param_names: Vec = params .clone() .into_iter() @@ -225,7 +217,7 @@ pub fn instrument(args: TokenStream, item: TokenStream) -> TokenStream { }) .collect(); - for skip in &skips { + for skip in args.skips.iter() { if !param_names.contains(skip) { return quote_spanned! {skip.span()=> compile_error!("attempting to skip non-existent parameter") @@ -235,37 +227,37 @@ pub fn instrument(args: TokenStream, item: TokenStream) -> TokenStream { let param_names: Vec = param_names .into_iter() - .filter(|ident| !skips.contains(ident)) + .filter(|ident| !args.skips.contains(ident)) .collect(); - let fields = match fields(&args, ¶m_names) { - Ok(fields) => fields, - Err(err) => return quote!(#err), - }; - let param_names_clone = param_names.clone(); - let level = level(&args); - let target = target(&args); - let span_name = name(&args, ident_str); + let level = args.level(); + let target = args.target(); + let span_name = args.name.as_ref() + .map(|name| { quote!(#name) }) + .unwrap_or_else(|| { + let ident_str = ident.to_string(); + quote!(#ident_str) + }); let mut quoted_fields: Vec<_> = param_names .into_iter() .map(|i| quote!(#i = tracing::field::debug(&#i))) .collect(); - quoted_fields.extend(fields.into_iter().map(|(key, value)| { - let value = match value { - Some(value) => quote!(#value), - None => quote!(tracing::field::Empty), - }; - - quote!(#key = #value) - })); + let custom_fields = &args.fields; + let custom_fields = if quoted_fields.is_empty() { + quote! { #custom_fields } + } else { + quote! {, #custom_fields } + }; quote!(tracing::span!( target: #target, #level, #span_name, - #(#quoted_fields),* + #(#quoted_fields),* + #custom_fields + )) })(); @@ -275,7 +267,7 @@ pub fn instrument(args: TokenStream, item: TokenStream) -> TokenStream { // enter the span and then perform the rest of the body. // If `err` is in args, instrument any resulting `Err`s. let body = if asyncness.is_some() { - if instrument_err(&args) { + if err { quote_spanned! {block.span()=> tracing_futures::Instrument::instrument(async move { match async move { #block }.await { @@ -296,7 +288,7 @@ pub fn instrument(args: TokenStream, item: TokenStream) -> TokenStream { .await } } - } else if instrument_err(&args) { + } else if err { quote_spanned!(block.span()=> let __tracing_attr_guard = __tracing_attr_span.enter(); match { #block } { @@ -326,6 +318,276 @@ pub fn instrument(args: TokenStream, item: TokenStream) -> TokenStream { .into() } +#[derive(Default, Debug)] +struct InstrumentArgs { + level: Option, + name: Option, + target: Option, + skips: HashSet, + fields: Option, + err: bool, +} + +impl InstrumentArgs { + 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(lit) => 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), + } + } + + fn target(&self) -> impl ToTokens { + if let Some(ref target) = self.target { + quote!(#target) + } else { + quote!(module_path!()) + } + } +} + +impl Parse for InstrumentArgs { + fn parse(input: ParseStream<'_>) -> syn::Result { + let mut args = Self::default(); + while !input.is_empty() { + let lookahead = input.lookahead1(); + if lookahead.peek(kw::name) { + if args.name.is_some() { + return Err(input.error("expected only a single `name` argument")); + } + let name = input.parse::>()?.value; + args.name = Some(name); + } else if lookahead.peek(kw::target) { + if args.target.is_some() { + return Err(input.error("expected only a single `target` argument")); + } + let target = input.parse::>()?.value; + args.target = Some(target); + } else if lookahead.peek(kw::level) { + if args.level.is_some() { + return Err(input.error("expected only a single `level` argument")); + } + args.level = Some(input.parse()?); + } else if lookahead.peek(kw::skip) { + if !args.skips.is_empty() { + return Err(input.error("expected only a single `skip` argument")); + } + let Skips(skips) = input.parse()?; + args.skips = skips; + } else if lookahead.peek(kw::fields) { + if args.fields.is_some() { + return Err(input.error("expected only a single `fields` argument")); + } + args.fields = Some(input.parse()?); + } else if lookahead.peek(kw::err) { + let _ = input.parse::()?; + args.err = true; + } else if lookahead.peek(Token![,]) { + let _ = input.parse::()?; + } else { + return Err(lookahead.error()); + } + } + Ok(args) + } +} + +struct StrArg { + value: LitStr, + _p: std::marker::PhantomData, +} + +impl Parse for StrArg { + fn parse(input: ParseStream<'_>) -> syn::Result { + let _ = input.parse::()?; + let _ = input.parse::()?; + let value = input.parse()?; + Ok(Self { + value, + _p: std::marker::PhantomData, + }) + } +} + +struct Skips(HashSet); + +impl Parse for Skips { + fn parse(input: ParseStream<'_>) -> syn::Result { + let _ = input.parse::(); + let content; + let _ = syn::parenthesized!(content in input); + let names: Punctuated = content.parse_terminated(Ident::parse_any)?; + let mut skips = HashSet::new(); + for name in names { + if skips.contains(&name) { + return Err(syn::Error::new( + name.span(), + "tried to skip the same field twice", + )); + } else { + skips.insert(name); + } + } + Ok(Self(skips)) + } +} + +#[derive(Debug)] +struct Fields(Punctuated); + +#[derive(Debug)] +struct Field { + name: Punctuated, + value: Option, + kind: FieldKind, +} + +#[derive(Debug, Eq, PartialEq)] +enum FieldKind { + Debug, + Display, + Value, +} + +impl Parse for Fields { + fn parse(input: ParseStream<'_>) -> syn::Result { + let _ = input.parse::(); + let content; + let _ = syn::parenthesized!(content in input); + let fields: Punctuated<_, Token![,]> = content.parse_terminated(Field::parse)?; + Ok(Self(fields)) + } +} + +impl ToTokens for Fields { + fn to_tokens(&self, tokens: &mut TokenStream) { + self.0.to_tokens(tokens) + } +} + +impl Parse for Field { + fn parse(input: ParseStream<'_>) -> syn::Result { + let mut kind = FieldKind::Value; + if input.peek(Token![%]) { + input.parse::()?; + kind = FieldKind::Display; + } else if input.peek(Token![?]) { + input.parse::()?; + kind = FieldKind::Debug; + }; + let name = Punctuated::parse_separated_nonempty_with(input, Ident::parse_any)?; + let value = if input.peek(Token![=]) { + input.parse::()?; + if input.peek(Token![%]) { + input.parse::()?; + kind = FieldKind::Display; + } else if input.peek(Token![?]) { + input.parse::()?; + kind = FieldKind::Debug; + }; + Some(input.parse()?) + } else { + None + }; + Ok(Self { + name, + kind, + value, + }) + } +} + +impl ToTokens for Field { + fn to_tokens(&self, tokens: &mut TokenStream) { + if let Some(ref value) = self.value { + let name = &self.name; + let kind = &self.kind; + tokens.extend(quote! { + #name = #kind#value + }) + } else { + if self.kind == FieldKind::Value { + // XXX(eliza): I don't like that fields without values produce + // empty fields rather than local variable shorthand...but, + // we've released a version where field names without values in + // `instrument` produce empty field values, so changing it now + // is a breaking change. agh. + let name = &self.name; + tokens.extend(quote!(#name = tracing::field::Empty)) + } else { + self.kind.to_tokens(tokens); + self.name.to_tokens(tokens); + } + } + } +} + +impl ToTokens for FieldKind { + fn to_tokens(&self, tokens: &mut TokenStream) { + match self { + FieldKind::Debug => tokens.extend(quote!{ ? }), + FieldKind::Display => tokens.extend(quote!{ % }), + _ => {}, + } + } +} + +#[derive(Debug)] +enum Level { + Str(LitStr), + Int(LitInt), + Path(Path), +} + +impl Parse for Level { + fn parse(input: ParseStream<'_>) -> syn::Result { + let _ = input.parse::()?; + let _ = input.parse::()?; + let lookahead = input.lookahead1(); + if lookahead.peek(LitStr) { + Ok(Self::Str(input.parse()?)) + } else if lookahead.peek(LitInt) { + Ok(Self::Int(input.parse()?)) + } else if lookahead.peek(Ident) { + Ok(Self::Path(input.parse()?)) + } else { + Err(lookahead.error()) + } + } +} + fn param_names(pat: Pat) -> Box> { match pat { Pat::Ident(PatIdent { ident, .. }) => Box::new(iter::once(ident)), @@ -379,60 +641,6 @@ fn skips(args: &[NestedMeta]) -> Result, impl ToTokens> { .collect()) } -fn level(args: &[NestedMeta]) -> impl ToTokens { - let mut levels = args.iter().filter_map(|arg| match arg { - NestedMeta::Meta(Meta::NameValue(MetaNameValue { - ref path, ref lit, .. - })) if path.is_ident("level") => Some(lit.clone()), - _ => None, - }); - let level = levels.next(); - - // If we found more than one arg named "level", that's a syntax error... - if let Some(lit) = levels.next() { - return quote_spanned! {lit.span()=> - compile_error!("expected only a single `level` argument!") - }; - } - - fn is_level(lit: &LitInt, expected: u64) -> bool { - match lit.base10_parse::() { - Ok(value) => value == expected, - Err(_) => false, - } - } - - match level { - Some(Lit::Str(ref lit)) if lit.value().eq_ignore_ascii_case("trace") => { - quote!(tracing::Level::TRACE) - } - Some(Lit::Str(ref lit)) if lit.value().eq_ignore_ascii_case("debug") => { - quote!(tracing::Level::DEBUG) - } - Some(Lit::Str(ref lit)) if lit.value().eq_ignore_ascii_case("info") => { - quote!(tracing::Level::INFO) - } - Some(Lit::Str(ref lit)) if lit.value().eq_ignore_ascii_case("warn") => { - quote!(tracing::Level::WARN) - } - Some(Lit::Str(ref lit)) if lit.value().eq_ignore_ascii_case("error") => { - quote!(tracing::Level::ERROR) - } - Some(Lit::Int(ref lit)) if is_level(lit, 1) => quote!(tracing::Level::TRACE), - Some(Lit::Int(ref lit)) if is_level(lit, 2) => quote!(tracing::Level::DEBUG), - Some(Lit::Int(ref lit)) if is_level(lit, 3) => quote!(tracing::Level::INFO), - Some(Lit::Int(ref lit)) if is_level(lit, 4) => quote!(tracing::Level::WARN), - Some(Lit::Int(ref lit)) if is_level(lit, 5) => quote!(tracing::Level::ERROR), - Some(lit) => quote_spanned! {lit.span()=> - compile_error!( - "unknown verbosity level, expected one of \"trace\", \ - \"debug\", \"info\", \"warn\", or \"error\", or a number 1-5" - ) - }, - None => quote!(tracing::Level::INFO), - } -} - fn target(args: &[NestedMeta]) -> impl ToTokens { let mut targets = args.iter().filter_map(|arg| match arg { NestedMeta::Meta(Meta::NameValue(MetaNameValue { @@ -579,3 +787,12 @@ fn instrument_err(args: &[NestedMeta]) -> bool { _ => false, }) } + +mod kw { + syn::custom_keyword!(fields); + syn::custom_keyword!(skip); + syn::custom_keyword!(level); + syn::custom_keyword!(target); + syn::custom_keyword!(name); + syn::custom_keyword!(err); +} From c2e2e857357aed47185e1ce4965bf83de626b5e5 Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Tue, 7 Apr 2020 16:10:59 -0700 Subject: [PATCH 03/13] remove unused code Signed-off-by: Eliza Weisman --- tracing-attributes/src/lib.rs | 177 ---------------------------------- 1 file changed, 177 deletions(-) diff --git a/tracing-attributes/src/lib.rs b/tracing-attributes/src/lib.rs index 957d0f7d6b..2417d490ca 100644 --- a/tracing-attributes/src/lib.rs +++ b/tracing-attributes/src/lib.rs @@ -611,183 +611,6 @@ fn param_names(pat: Pat) -> Box> { } } -fn skips(args: &[NestedMeta]) -> Result, impl ToTokens> { - let mut skips = args.iter().filter_map(|arg| match arg { - NestedMeta::Meta(Meta::List(MetaList { - ref path, - ref nested, - .. - })) if path.is_ident("skip") => Some(nested), - _ => None, - }); - let skip = skips.next(); - - // Ensure there's only one skip directive. - if let Some(list) = skips.next() { - return Err(quote_spanned! { - list.span() => compile_error!("expected only a single `skip` argument!") - }); - } - - // Collect the Idents inside the `skip(...)`, if it exists - Ok(skip - .iter() - .map(|list| list.iter()) - .flatten() - .filter_map(|meta| match meta { - NestedMeta::Meta(Meta::Path(p)) => p.get_ident().map(Clone::clone), - _ => None, - }) - .collect()) -} - -fn target(args: &[NestedMeta]) -> impl ToTokens { - let mut targets = args.iter().filter_map(|arg| match arg { - NestedMeta::Meta(Meta::NameValue(MetaNameValue { - ref path, ref lit, .. - })) if path.is_ident("target") => Some(lit.clone()), - _ => None, - }); - let target = targets.next(); - - // If we found more than one arg named "target", that's a syntax error... - if let Some(lit) = targets.next() { - return quote_spanned! {lit.span()=> - compile_error!("expected only a single `target` argument!") - }; - } - - match target { - Some(Lit::Str(ref lit)) => quote!(#lit), - Some(lit) => quote_spanned! {lit.span()=> - compile_error!( - "expected target to be a string literal" - ) - }, - None => quote!(module_path!()), - } -} - -fn fields( - args: &[NestedMeta], - param_names: &[Ident], -) -> Result<(Vec<(Ident, Option)>), impl ToTokens> { - let mut fields = args.iter().filter_map(|arg| match arg { - NestedMeta::Meta(Meta::List(MetaList { - ref path, - ref nested, - .. - })) if path.is_ident("fields") => Some(nested.clone()), - _ => None, - }); - let field_holder = fields.next(); - - // If we found more than one arg named "fields", that's a syntax error... - if let Some(lit) = fields.next() { - return Err(quote_spanned! {lit.span()=> - compile_error!("expected only a single `fields` argument!") - }); - } - - match field_holder { - Some(fields) => { - let mut parsed = Vec::default(); - let mut visited_keys: HashSet = Default::default(); - let param_set: HashSet = param_names.iter().map(|i| i.to_string()).collect(); - for field in fields.into_iter() { - let (key, value) = match field { - NestedMeta::Meta(meta) => match meta { - Meta::NameValue(kv) => (kv.path, Some(kv.lit)), - Meta::Path(path) => (path, None), - _ => { - return Err(quote_spanned! {meta.span()=> - compile_error!("each field must be a key with an optional value. Keys must be valid Rust identifiers (nested keys with dots are not supported).") - }) - } - }, - _ => { - return Err(quote_spanned! {field.span()=> - compile_error!("`fields` argument should be a list of key-value fields") - }) - } - }; - - let key = match key.get_ident() { - Some(key) => key, - None => { - return Err(quote_spanned! {key.span()=> - compile_error!("field keys must be valid Rust identifiers (nested keys with dots are not supported).") - }) - } - }; - - let key_str = key.to_string(); - if param_set.contains(&key_str) { - return Err(quote_spanned! {key.span()=> - compile_error!("field overlaps with (non-skipped) parameter name") - }); - } - - if visited_keys.contains(&key_str) { - return Err(quote_spanned! {key.span()=> - compile_error!("each field key must appear at most once") - }); - } else { - visited_keys.insert(key_str); - } - - if let Some(literal) = &value { - match literal { - Lit::Bool(_) | Lit::Str(_) | Lit::Int(_) => {} - _ => { - return Err(quote_spanned! {literal.span()=> - compile_error!("values can be only strings, integers or booleans") - }) - } - } - } - - parsed.push((key.clone(), value)); - } - Ok(parsed) - } - None => Ok(Default::default()), - } -} - -fn name(args: &[NestedMeta], default_name: String) -> impl ToTokens { - let mut names = args.iter().filter_map(|arg| match arg { - NestedMeta::Meta(Meta::NameValue(MetaNameValue { - ref path, ref lit, .. - })) if path.is_ident("name") => Some(lit.clone()), - _ => None, - }); - - let name = names.next(); - - // If we found more than one arg named "name", that's a syntax error. - if let Some(lit) = names.next() { - return quote_spanned! {lit.span() => - compile_error!("expected only a single `name` argument!") - }; - } - - match name { - Some(Lit::Str(ref lit)) => quote!(#lit), - Some(lit) => { - quote_spanned! { lit.span() => compile_error!("expected name to be a string literal") } - } - None => quote!(#default_name), - } -} - -fn instrument_err(args: &[NestedMeta]) -> bool { - args.iter().any(|arg| match arg { - NestedMeta::Meta(Meta::Path(path)) => path.is_ident("err"), - _ => false, - }) -} - mod kw { syn::custom_keyword!(fields); syn::custom_keyword!(skip); From 06c39c0cb70ff66ccdc4df90f3547f7cee77cdfa Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Tue, 7 Apr 2020 16:15:06 -0700 Subject: [PATCH 04/13] add a few more tests Signed-off-by: Eliza Weisman --- tracing-attributes/tests/fields.rs | 35 ++++++++++++++++++++++++++++++ 1 file changed, 35 insertions(+) diff --git a/tracing-attributes/tests/fields.rs b/tracing-attributes/tests/fields.rs index e048d1aae8..e28aabcf23 100644 --- a/tracing-attributes/tests/fields.rs +++ b/tracing-attributes/tests/fields.rs @@ -18,6 +18,12 @@ fn fn_empty_field() {} #[instrument(fields(len = s.len()))] fn fn_expr_field(s: &str) {} +#[instrument(fields(s.len = s.len(), s.is_empty = s.is_empty()))] +fn fn_two_expr_fields(s: &str) {} + +#[instrument(fields(%s, s.len = s.len()))] +fn fn_clashy_expr_field(s: &str) {} + #[derive(Debug)] struct HasField { my_field: &'static str, @@ -55,6 +61,35 @@ fn expr_field() { }); } +#[test] +fn two_expr_fields() { + let span = span::mock().with_field( + mock("s") + .with_value(&tracing::field::debug("hello world")) + .and(mock("s.len").with_value(&"hello world".len())) + .and(mock("s.is_empty").with_value(&false)) + .only(), + ); + run_test(span, || { + fn_two_expr_fields(&"hello world"); + }); +} + +#[test] +fn clashy_expr_field() { + let span = span::mock().with_field( + // Overriding the `s` field should record `s` as a `Display` value, + // rather than as a `Debug` value. + mock("s") + .with_value(&tracing::field::display("hello world")) + .and(mock("s.len").with_value(&"hello world".len())) + .only(), + ); + run_test(span, || { + fn_clashy_expr_field(&"hello world"); + }); +} + #[test] fn self_expr_field() { let span = span::mock().with_field(mock("my_field").with_value(&"hello world").only()); From 2f4804284c01a398383444786a8d1bbbbec46687 Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Tue, 7 Apr 2020 16:25:10 -0700 Subject: [PATCH 05/13] fix handling of clashy field names Signed-off-by: Eliza Weisman --- tracing-attributes/src/lib.rs | 12 ++++++++++++ 1 file changed, 12 insertions(+) diff --git a/tracing-attributes/src/lib.rs b/tracing-attributes/src/lib.rs index 2417d490ca..403c56435a 100644 --- a/tracing-attributes/src/lib.rs +++ b/tracing-attributes/src/lib.rs @@ -243,6 +243,18 @@ pub fn instrument(args: proc_macro::TokenStream, item: proc_macro::TokenStream) let mut quoted_fields: Vec<_> = param_names .into_iter() + .filter(|param| { + // If any parameters have the same name as a custom field, skip + // and allow them to be formatted by the custom field. + if let Some(ref fields) = args.fields { + fields.0.iter().all(|Field { ref name, .. }| { + let first = name.first(); + first != name.last() || !first.iter().any(|name| name == ¶m) + }) + } else { + true + } + }) .map(|i| quote!(#i = tracing::field::debug(&#i))) .collect(); let custom_fields = &args.fields; From ff50fae603a4697383d52e7692c09f3d644ea279 Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Wed, 8 Apr 2020 10:00:34 -0700 Subject: [PATCH 06/13] more clashy fields Signed-off-by: Eliza Weisman --- tracing-attributes/tests/fields.rs | 14 ++++++++++++++ 1 file changed, 14 insertions(+) diff --git a/tracing-attributes/tests/fields.rs b/tracing-attributes/tests/fields.rs index e28aabcf23..5af8f97e50 100644 --- a/tracing-attributes/tests/fields.rs +++ b/tracing-attributes/tests/fields.rs @@ -24,6 +24,11 @@ fn fn_two_expr_fields(s: &str) {} #[instrument(fields(%s, s.len = s.len()))] fn fn_clashy_expr_field(s: &str) {} + +#[instrument(fields(s = "s"))] +fn fn_clashy_expr_field2(s: &str) {} + + #[derive(Debug)] struct HasField { my_field: &'static str, @@ -88,6 +93,15 @@ fn clashy_expr_field() { run_test(span, || { fn_clashy_expr_field(&"hello world"); }); + + let span = span::mock().with_field( + mock("s") + .with_value(&"s") + .only(), + ); + run_test(span, || { + fn_clashy_expr_field2(&"hello world"); + }); } #[test] From 1e857927568651e328c68ffc1782cfa20340d632 Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Wed, 8 Apr 2020 10:09:23 -0700 Subject: [PATCH 07/13] fix accidentally breaking change Signed-off-by: Eliza Weisman --- tracing-attributes/src/lib.rs | 8 ++++++++ tracing-attributes/tests/names.rs | 22 ++++++++++++++++++++++ 2 files changed, 30 insertions(+) diff --git a/tracing-attributes/src/lib.rs b/tracing-attributes/src/lib.rs index 403c56435a..9139941bb8 100644 --- a/tracing-attributes/src/lib.rs +++ b/tracing-attributes/src/lib.rs @@ -401,6 +401,14 @@ impl Parse for InstrumentArgs { } let name = input.parse::>()?.value; args.name = Some(name); + } else if lookahead.peek(LitStr) { + // XXX: apparently we support names as either named args with an + // sign, _or_ as unnamed string literals. That's weird, but + // changing it is apparently breaking. + if args.name.is_some() { + return Err(input.error("expected only a single `name` argument")); + } + args.name = Some(input.parse()?); } else if lookahead.peek(kw::target) { if args.target.is_some() { return Err(input.error("expected only a single `target` argument")); diff --git a/tracing-attributes/tests/names.rs b/tracing-attributes/tests/names.rs index f5ccee457f..15497784ca 100644 --- a/tracing-attributes/tests/names.rs +++ b/tracing-attributes/tests/names.rs @@ -10,6 +10,12 @@ fn default_name() {} #[instrument(name = "my_name")] fn custom_name() {} +// XXX: it's weird that we support both of these forms, but apparently we +// managed to release a version that accepts both syntax, so now we have to +// support it! yay! +#[instrument("my_other_name")] +fn custom_name_no_equals() {} + #[test] fn default_name_test() { let (subscriber, handle) = subscriber::mock() @@ -41,3 +47,19 @@ fn custom_name_test() { handle.assert_finished(); } + +#[test] +fn custom_name_no_equals_test() { + let (subscriber, handle) = subscriber::mock() + .new_span(span::mock().named("my_other_name")) + .enter(span::mock().named("my_other_name")) + .exit(span::mock().named("my_other_name")) + .done() + .run_with_handle(); + + with_default(subscriber, || { + custom_name_no_equals(); + }); + + handle.assert_finished(); +} From b0aff00760fae3cbd7eb1c7ce329ae3c85900240 Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Wed, 8 Apr 2020 10:44:04 -0700 Subject: [PATCH 08/13] placate clippy Signed-off-by: Eliza Weisman --- tracing-attributes/src/lib.rs | 22 ++++++++++------------ 1 file changed, 10 insertions(+), 12 deletions(-) diff --git a/tracing-attributes/src/lib.rs b/tracing-attributes/src/lib.rs index 9139941bb8..2b132a55d0 100644 --- a/tracing-attributes/src/lib.rs +++ b/tracing-attributes/src/lib.rs @@ -557,19 +557,17 @@ impl ToTokens for Field { tokens.extend(quote! { #name = #kind#value }) + } if self.kind == FieldKind::Value { + // XXX(eliza): I don't like that fields without values produce + // empty fields rather than local variable shorthand...but, + // we've released a version where field names without values in + // `instrument` produce empty field values, so changing it now + // is a breaking change. agh. + let name = &self.name; + tokens.extend(quote!(#name = tracing::field::Empty)) } else { - if self.kind == FieldKind::Value { - // XXX(eliza): I don't like that fields without values produce - // empty fields rather than local variable shorthand...but, - // we've released a version where field names without values in - // `instrument` produce empty field values, so changing it now - // is a breaking change. agh. - let name = &self.name; - tokens.extend(quote!(#name = tracing::field::Empty)) - } else { - self.kind.to_tokens(tokens); - self.name.to_tokens(tokens); - } + self.kind.to_tokens(tokens); + self.name.to_tokens(tokens); } } } From c796b042c85a40e97520f6175bd0316772400712 Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Wed, 8 Apr 2020 10:45:27 -0700 Subject: [PATCH 09/13] rustfmt Signed-off-by: Eliza Weisman --- tracing-attributes/src/lib.rs | 40 ++++++++++++++++-------------- tracing-attributes/tests/fields.rs | 8 +----- 2 files changed, 22 insertions(+), 26 deletions(-) diff --git a/tracing-attributes/src/lib.rs b/tracing-attributes/src/lib.rs index 2b132a55d0..7fcbd025c5 100644 --- a/tracing-attributes/src/lib.rs +++ b/tracing-attributes/src/lib.rs @@ -67,13 +67,13 @@ use std::iter; use proc_macro2::TokenStream; use quote::{quote, quote_spanned, ToTokens, TokenStreamExt as _}; +use syn::ext::IdentExt as _; use syn::parse::{Parse, ParseStream}; use syn::{ punctuated::Punctuated, spanned::Spanned, AttributeArgs, Expr, FieldPat, FnArg, Ident, ItemFn, Lit, LitInt, LitStr, Meta, MetaList, MetaNameValue, NestedMeta, Pat, PatIdent, PatReference, PatStruct, PatTuple, PatTupleStruct, PatType, Path, Signature, Token, }; -use syn::ext::IdentExt as _; /// Instruments a function to create and enter a `tracing` [span] every time /// the function is called. /// @@ -174,7 +174,10 @@ use syn::ext::IdentExt as _; /// [`tracing`]: https://github.com/tokio-rs/tracing /// [`fmt::Debug`]: https://doc.rust-lang.org/std/fmt/trait.Debug.html #[proc_macro_attribute] -pub fn instrument(args: proc_macro::TokenStream, item: proc_macro::TokenStream) -> proc_macro::TokenStream { +pub fn instrument( + args: proc_macro::TokenStream, + item: proc_macro::TokenStream, +) -> proc_macro::TokenStream { let input: ItemFn = syn::parse_macro_input!(item as ItemFn); let args = syn::parse_macro_input!(args as InstrumentArgs); @@ -234,11 +237,13 @@ pub fn instrument(args: proc_macro::TokenStream, item: proc_macro::TokenStream) let level = args.level(); let target = args.target(); - let span_name = args.name.as_ref() - .map(|name| { quote!(#name) }) - .unwrap_or_else(|| { + let span_name = args + .name + .as_ref() + .map(|name| quote!(#name)) + .unwrap_or_else(|| { let ident_str = ident.to_string(); - quote!(#ident_str) + quote!(#ident_str) }); let mut quoted_fields: Vec<_> = param_names @@ -267,7 +272,7 @@ pub fn instrument(args: proc_macro::TokenStream, item: proc_macro::TokenStream) target: #target, #level, #span_name, - #(#quoted_fields),* + #(#quoted_fields),* #custom_fields )) @@ -348,7 +353,7 @@ impl InstrumentArgs { Err(_) => false, } } - + match &self.level { Some(Level::Str(ref lit)) if lit.value().eq_ignore_ascii_case("trace") => { quote!(tracing::Level::TRACE) @@ -371,7 +376,7 @@ impl InstrumentArgs { 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(lit) => quote!{ + Some(lit) => quote! { compile_error!( "unknown verbosity level, expected one of \"trace\", \ \"debug\", \"info\", \"warn\", or \"error\", or a number 1-5" @@ -541,11 +546,7 @@ impl Parse for Field { } else { None }; - Ok(Self { - name, - kind, - value, - }) + Ok(Self { name, kind, value }) } } @@ -557,7 +558,8 @@ impl ToTokens for Field { tokens.extend(quote! { #name = #kind#value }) - } if self.kind == FieldKind::Value { + } + if self.kind == FieldKind::Value { // XXX(eliza): I don't like that fields without values produce // empty fields rather than local variable shorthand...but, // we've released a version where field names without values in @@ -575,9 +577,9 @@ impl ToTokens for Field { impl ToTokens for FieldKind { fn to_tokens(&self, tokens: &mut TokenStream) { match self { - FieldKind::Debug => tokens.extend(quote!{ ? }), - FieldKind::Display => tokens.extend(quote!{ % }), - _ => {}, + FieldKind::Debug => tokens.extend(quote! { ? }), + FieldKind::Display => tokens.extend(quote! { % }), + _ => {} } } } @@ -595,7 +597,7 @@ impl Parse for Level { let _ = input.parse::()?; let lookahead = input.lookahead1(); if lookahead.peek(LitStr) { - Ok(Self::Str(input.parse()?)) + Ok(Self::Str(input.parse()?)) } else if lookahead.peek(LitInt) { Ok(Self::Int(input.parse()?)) } else if lookahead.peek(Ident) { diff --git a/tracing-attributes/tests/fields.rs b/tracing-attributes/tests/fields.rs index 5af8f97e50..ed69628b2a 100644 --- a/tracing-attributes/tests/fields.rs +++ b/tracing-attributes/tests/fields.rs @@ -24,11 +24,9 @@ fn fn_two_expr_fields(s: &str) {} #[instrument(fields(%s, s.len = s.len()))] fn fn_clashy_expr_field(s: &str) {} - #[instrument(fields(s = "s"))] fn fn_clashy_expr_field2(s: &str) {} - #[derive(Debug)] struct HasField { my_field: &'static str, @@ -94,11 +92,7 @@ fn clashy_expr_field() { fn_clashy_expr_field(&"hello world"); }); - let span = span::mock().with_field( - mock("s") - .with_value(&"s") - .only(), - ); + let span = span::mock().with_field(mock("s").with_value(&"s").only()); run_test(span, || { fn_clashy_expr_field2(&"hello world"); }); From 9f764f9ba695a9db8ca602188e8642519c431c4c Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Wed, 8 Apr 2020 14:47:04 -0700 Subject: [PATCH 10/13] fix instrument generating "bonus" empty fields Signed-off-by: Eliza Weisman --- tracing-attributes/src/lib.rs | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/tracing-attributes/src/lib.rs b/tracing-attributes/src/lib.rs index 7fcbd025c5..899e40af84 100644 --- a/tracing-attributes/src/lib.rs +++ b/tracing-attributes/src/lib.rs @@ -268,6 +268,7 @@ pub fn instrument( } else { quote! {, #custom_fields } }; + quote!(tracing::span!( target: #target, #level, @@ -558,8 +559,7 @@ impl ToTokens for Field { tokens.extend(quote! { #name = #kind#value }) - } - if self.kind == FieldKind::Value { + } else if self.kind == FieldKind::Value { // XXX(eliza): I don't like that fields without values produce // empty fields rather than local variable shorthand...but, // we've released a version where field names without values in From 1cc5581dcdfe93bb40ab8103fd9a9eeb89ad21a8 Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Wed, 8 Apr 2020 14:47:53 -0700 Subject: [PATCH 11/13] fix unused field warnings Signed-off-by: Eliza Weisman --- tracing-attributes/tests/fields.rs | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/tracing-attributes/tests/fields.rs b/tracing-attributes/tests/fields.rs index ed69628b2a..cc88cfec53 100644 --- a/tracing-attributes/tests/fields.rs +++ b/tracing-attributes/tests/fields.rs @@ -19,13 +19,13 @@ fn fn_empty_field() {} fn fn_expr_field(s: &str) {} #[instrument(fields(s.len = s.len(), s.is_empty = s.is_empty()))] -fn fn_two_expr_fields(s: &str) {} +fn fn_two_expr_fields(s: &str) { let _ = s; } #[instrument(fields(%s, s.len = s.len()))] -fn fn_clashy_expr_field(s: &str) {} +fn fn_clashy_expr_field(s: &str) { let _ = s; } #[instrument(fields(s = "s"))] -fn fn_clashy_expr_field2(s: &str) {} +fn fn_clashy_expr_field2(s: &str) { let _ = s; } #[derive(Debug)] struct HasField { From 0f7f4b0557e3dc6c8ba9aac7271d74e7e30eec4a Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Wed, 8 Apr 2020 15:38:17 -0700 Subject: [PATCH 12/13] AAAHHHHHH RUSTFMT Signed-off-by: Eliza Weisman --- tracing-attributes/tests/fields.rs | 12 +++++++++--- 1 file changed, 9 insertions(+), 3 deletions(-) diff --git a/tracing-attributes/tests/fields.rs b/tracing-attributes/tests/fields.rs index cc88cfec53..de038ca7b1 100644 --- a/tracing-attributes/tests/fields.rs +++ b/tracing-attributes/tests/fields.rs @@ -19,13 +19,19 @@ fn fn_empty_field() {} fn fn_expr_field(s: &str) {} #[instrument(fields(s.len = s.len(), s.is_empty = s.is_empty()))] -fn fn_two_expr_fields(s: &str) { let _ = s; } +fn fn_two_expr_fields(s: &str) { + let _ = s; +} #[instrument(fields(%s, s.len = s.len()))] -fn fn_clashy_expr_field(s: &str) { let _ = s; } +fn fn_clashy_expr_field(s: &str) { + let _ = s; +} #[instrument(fields(s = "s"))] -fn fn_clashy_expr_field2(s: &str) { let _ = s; } +fn fn_clashy_expr_field2(s: &str) { + let _ = s; +} #[derive(Debug)] struct HasField { From fd5824685d613d361d9cd27fe3e1697fab04ad5a Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Sat, 23 May 2020 13:16:36 -0700 Subject: [PATCH 13/13] post-merge fixup Signed-off-by: Eliza Weisman --- tracing-attributes/src/lib.rs | 60 ++++++++++++++++------------------- 1 file changed, 27 insertions(+), 33 deletions(-) diff --git a/tracing-attributes/src/lib.rs b/tracing-attributes/src/lib.rs index afc8b98c88..60dfe20fc3 100644 --- a/tracing-attributes/src/lib.rs +++ b/tracing-attributes/src/lib.rs @@ -70,9 +70,10 @@ use quote::{quote, quote_spanned, ToTokens, TokenStreamExt as _}; use syn::ext::IdentExt as _; use syn::parse::{Parse, ParseStream}; use syn::{ - punctuated::Punctuated, spanned::Spanned, AttributeArgs, Expr, FieldPat, FnArg, Ident, ItemFn, - Lit, LitInt, LitStr, Meta, MetaList, MetaNameValue, NestedMeta, Pat, PatIdent, PatReference, - PatStruct, PatTuple, PatTupleStruct, PatType, Path, Signature, Stmt, Token, + punctuated::Punctuated, spanned::Spanned, AttributeArgs, Block, Expr, ExprCall, FieldPat, + FnArg, Ident, Item, ItemFn, Lit, LitInt, LitStr, Meta, MetaList, MetaNameValue, NestedMeta, + Pat, PatIdent, PatReference, PatStruct, PatTuple, PatTupleStruct, PatType, Path, Signature, + Stmt, Token, }; /// Instruments a function to create and enter a `tracing` [span] every time /// the function is called. @@ -241,7 +242,7 @@ pub fn instrument( fn gen_body( input: &ItemFn, - args: AttributeArgs, + args: InstrumentArgs, fun_name: Option, ) -> proc_macro2::TokenStream { // these are needed ahead of time, as ItemFn contains the function body _and_ @@ -274,21 +275,25 @@ fn gen_body( let err = args.err; - // function name - let ident_str = if let Some(x) = &fun_name { - x.clone() - } else { - ident.to_string() - }; + // generate the span's name + let span_name = args + // did the user override the span's name? + .name + .as_ref() + .map(|name| quote!(#name)) + // are we overriding the name because the span is inside a function + // generated by `async-trait`? + .or_else(|| fun_name.as_ref().map(|name| quote!(#name))) + // if neither override is present, use the parsed function's name. + .unwrap_or_else(|| { + let name = ident.to_string(); + quote!(#name) + }); // generate this inside a closure, so we can return early on errors. let span = (|| { - // Pull out the arguments-to-be-skipped first, so we can filter results below. - let skips = match skips(&args) { - Ok(skips) => skips, - Err(err) => return quote!(#err), - }; - + // Pull out the arguments-to-be-skipped first, so we can filter results + // below. let param_names: Vec<(Ident, Ident)> = params .clone() .into_iter() @@ -322,7 +327,7 @@ fn gen_body( // } // ``` - for skip in &skips { + for skip in &args.skips { if !param_names.iter().map(|(user, _)| user).any(|y| y == skip) { return quote_spanned! {skip.span()=> compile_error!("attempting to skip non-existent parameter") @@ -330,28 +335,17 @@ fn gen_body( } } - // filter out skipped fields - let param_names: Vec<(Ident, Ident)> = param_names - .into_iter() - .filter(|ident| !args.skips.contains(ident)) - .collect(); - - let param_names_clone = param_names.clone(); - let level = args.level(); let target = args.target(); - let span_name = args - .name - .as_ref() - .map(|name| quote!(#name)) - .unwrap_or_else(|| { - let ident_str = ident.to_string(); - quote!(#ident_str) - }); + // filter out skipped fields let mut quoted_fields: Vec<_> = param_names .into_iter() .filter(|(param, _)| { + if args.skips.contains(param) { + return false; + } + // If any parameters have the same name as a custom field, skip // and allow them to be formatted by the custom field. if let Some(ref fields) = args.fields {