proc-macros: Pass params to the function as fields (#10)

The parameters to the function are now passed as fields into `span!` so
that we can see what arguments a traced function is called with.

Before:
```
DEBUG 2019-02-08T22:51:06Z: args: fibonacci_seq: Pushing 0 fibonacci; traced_function="fibonacci_seq";
DEBUG 2019-02-08T22:51:06Z: args: nth_fibonacci: Base case; traced_function="nth_fibonacci";
DEBUG 2019-02-08T22:51:06Z: args: fibonacci_seq: Pushing 1 fibonacci; traced_function="fibonacci_seq";
DEBUG 2019-02-08T22:51:06Z: args: nth_fibonacci: Base case; traced_function="nth_fibonacci";
DEBUG 2019-02-08T22:51:06Z: args: fibonacci_seq: Pushing 2 fibonacci; traced_function="fibonacci_seq";
DEBUG 2019-02-08T22:51:06Z: args: nth_fibonacci: Recursing; traced_function="nth_fibonacci";
DEBUG 2019-02-08T22:51:06Z: args: nth_fibonacci: Base case; traced_function="nth_fibonacci";
DEBUG 2019-02-08T22:51:06Z: args: nth_fibonacci: Base case; traced_function="nth_fibonacci";
DEBUG 2019-02-08T22:51:06Z: args: fibonacci_seq: Pushing 3 fibonacci; traced_function="fibonacci_seq";
DEBUG 2019-02-08T22:51:06Z: args: nth_fibonacci: Recursing; traced_function="nth_fibonacci";
DEBUG 2019-02-08T22:51:06Z: args: nth_fibonacci: Recursing; traced_function="nth_fibonacci";
DEBUG 2019-02-08T22:51:06Z: args: nth_fibonacci: Base case; traced_function="nth_fibonacci";
DEBUG 2019-02-08T22:51:06Z: args: nth_fibonacci: Base case; traced_function="nth_fibonacci";
DEBUG 2019-02-08T22:51:06Z: args: nth_fibonacci: Base case; traced_function="nth_fibonacci";
```

After:
```
DEBUG 2019-02-08T22:53:03Z: args: fibonacci_seq: Pushing 0 fibonacci; traced_function="fibonacci_seq"; to=5;
DEBUG 2019-02-08T22:53:03Z: args: nth_fibonacci: Base case; traced_function="nth_fibonacci"; n=0;
DEBUG 2019-02-08T22:53:03Z: args: fibonacci_seq: Pushing 1 fibonacci; traced_function="fibonacci_seq"; to=5;
DEBUG 2019-02-08T22:53:03Z: args: nth_fibonacci: Base case; traced_function="nth_fibonacci"; n=1;
DEBUG 2019-02-08T22:53:03Z: args: fibonacci_seq: Pushing 2 fibonacci; traced_function="fibonacci_seq"; to=5;
DEBUG 2019-02-08T22:53:03Z: args: nth_fibonacci: Recursing; traced_function="nth_fibonacci"; n=2;
DEBUG 2019-02-08T22:53:03Z: args: nth_fibonacci: Base case; traced_function="nth_fibonacci"; n=1;
DEBUG 2019-02-08T22:53:03Z: args: nth_fibonacci: Base case; traced_function="nth_fibonacci"; n=0;
DEBUG 2019-02-08T22:53:03Z: args: fibonacci_seq: Pushing 3 fibonacci; traced_function="fibonacci_seq"; to=5;
DEBUG 2019-02-08T22:53:03Z: args: nth_fibonacci: Recursing; traced_function="nth_fibonacci"; n=3;
DEBUG 2019-02-08T22:53:03Z: args: nth_fibonacci: Recursing; traced_function="nth_fibonacci"; n=2;
DEBUG 2019-02-08T22:53:03Z: args: nth_fibonacci: Base case; traced_function="nth_fibonacci"; n=1;
DEBUG 2019-02-08T22:53:03Z: args: nth_fibonacci: Base case; traced_function="nth_fibonacci"; n=0;
DEBUG 2019-02-08T22:53:03Z: args: nth_fibonacci: Base case; traced_function="nth_fibonacci"; n=1;
```

Closes #5 

Signed-off-by: Kevin Leimkuhler <kevinl@buoyant.io>
Co-authored-by: Eliza Weisman <eliza@buoyantio>

tokio-trace-proc-macros/examples/args.rs

@@ -0,0 +1,44 @@
+#[macro_use]
+extern crate tokio_trace;
+#[macro_use]
+extern crate tokio_trace_proc_macros;
+extern crate env_logger;
+extern crate tokio_trace_log;
+
+use tokio_trace::field;
+
+#[trace]
+fn nth_fibonacci(n: u64) -> u64 {
+ if n == 0 || n == 1 {
+ debug!("Base case");
+ 1
+ } else {
+ debug!("Recursing");
+ nth_fibonacci(n - 1) + nth_fibonacci(n - 2)
+ }
+}
+
+#[trace]
+fn fibonacci_seq(to: u64) -> Vec<u64> {
+ let mut sequence = vec![];
+
+ for n in 0..=to {
+ debug!("Pushing {n} fibonacci", n = n);
+ sequence.push(nth_fibonacci(n));
+ }
+
+ sequence
+}
+
+fn main() {
+ env_logger::Builder::new().parse("trace").init();
+ let subscriber = tokio_trace_log::TraceLogger::builder()
+ .with_parent_fields(false)
+ .finish();
+
+ tokio_trace::subscriber::with_default(subscriber, || {
+ let n: u64 = 5;
+ let sequence = fibonacci_seq(n);
+ info!("The first {} fibonacci numbers are {:?}", n, sequence);
+ })
+}

tokio-trace-proc-macros/src/lib.rs

@@ -8,7 +8,7 @@ extern crate proc_macro2;
 use proc_macro::TokenStream;
 use proc_macro2::Span;
 use syn::token::{Async, Const, Unsafe};
-use syn::{Abi, Attribute, Block, Ident, ItemFn, Visibility};
+use syn::{Abi, ArgCaptured, Attribute, Block, FnArg, Ident, ItemFn, Pat, PatIdent, Visibility};
 
 #[proc_macro_attribute]
 pub fn trace(_args: TokenStream, item: TokenStream) -> TokenStream {
@@ -33,11 +33,30 @@ pub fn trace(_args: TokenStream, item: TokenStream) -> TokenStream {
 
  let return_type = input.clone().decl.output;
  let params = input.clone().decl.inputs;
+ let param_names: Vec<Ident> = input
+ .clone()
+ .decl
+ .inputs
+ .into_iter()
+ .filter_map(|param| match param {
+ FnArg::Captured(ArgCaptured {
+ pat: Pat::Ident(PatIdent { ident, .. }),
+ ..
+ }) => Some(ident),
+ _ => None,
+ })
+ .collect();
+ let param_names_clone = param_names.clone();
 
  quote_spanned!(call_site=>
  #(#attrs) *
  #vis #constness #unsafety #asyncness #abi fn #ident(#params) #return_type {
- span!(#ident_str, traced_function = &#ident_str).enter(move || {
+ span!(
+ #ident_str,
+ traced_function = &#ident_str
+ #(, #param_names = tokio_trace::field::debug(&#param_names_clone)),*
+ )
+ .enter(move || {
  #block
  })
  }