From 58a1e45f066884438ac8b1d8d8bac26b2b53c046 Mon Sep 17 00:00:00 2001 From: Andy Lok Date: Sun, 16 Jun 2024 20:43:21 +0800 Subject: [PATCH] feat: log the function inputs --- Cargo.toml | 7 +- README.md | 109 ++++++++-- examples/main.rs | 48 +++-- src/lib.rs | 220 +++++++++++++-------- tests/ui/err/error-passthrough.rs | 7 + tests/ui/err/error-passthrough.stderr | 10 + tests/ui/err/has-no-argument.stderr | 7 - tests/ui/err/has-too-many-arguments.stderr | 8 +- tests/ui/{err => ok}/has-no-argument.rs | 0 9 files changed, 291 insertions(+), 125 deletions(-) create mode 100644 tests/ui/err/error-passthrough.rs create mode 100644 tests/ui/err/error-passthrough.stderr delete mode 100644 tests/ui/err/has-no-argument.stderr rename tests/ui/{err => ok}/has-no-argument.rs (100%) diff --git a/Cargo.toml b/Cargo.toml index b524312..c108073 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -1,11 +1,11 @@ [package] name = "logcall" -version = "0.1.5" +version = "0.1.6" edition = "2021" authors = ["andylokandy "] description = "An attribute macro that logs the function return value." -repository = "https://github.com/andylokandy/logfn" -documentation = "https://docs.rs/logfn" +repository = "https://github.com/andylokandy/logcall" +documentation = "https://docs.rs/logcall" categories = ["development-tools::debugging"] readme = "README.md" keywords = ["log", "macro", "derive", "logging", "function"] @@ -18,7 +18,6 @@ proc-macro = true proc-macro-error = "1" proc-macro2 = "1" quote = "1" -# The macro `quote_spanned!` is added to syn in 1.0.84 syn = { version = "1.0.84", features = [ "full", "parsing", diff --git a/README.md b/README.md index 65d783a..05a18e8 100644 --- a/README.md +++ b/README.md @@ -1,38 +1,113 @@ # logcall -An attribute macro that logs the function return value. +`logcall` is a Rust procedural macro crate designed to automatically log function calls, their inputs, and their outputs. This macro facilitates debugging and monitoring by providing detailed logs of function executions with minimal boilerplate code. -This is a reimplementation of the [`log-derive`](https://crates.io/crates/log-derive) crate with [`async-trait`](https://crates.io/crates/async-trait) compatibility. +This is a re-implementation of the [`log-derive`](https://crates.io/crates/log-derive) crate with [`async-trait`](https://crates.io/crates/async-trait) compatibility. + +## Installation + +Add `logcall` to your `Cargo.toml`: + +```toml +[dependencies] +logcall = "0.1" +``` ## Usage +Import the `logcall` crate and use the macro to annotate your functions: + ```rust use logcall::logcall; +/// Logs the function call at the default `debug` level. +#[logcall] +fn add(a: i32, b: i32) -> i32 { + a + b +} + +/// Logs the function call at the `info` level. #[logcall("info")] -fn foo(a: usize) -> usize { - a + 1 +fn multiply(a: i32, b: i32) -> i32 { + a * b } +/// Logs `Ok` results at the `info` level and `Err` results at the `error` level. +#[logcall(ok = "info", err = "error")] +fn divide(a: i32, b: i32) -> Result { + if b == 0 { + Err("Division by zero".to_string()) + } else { + Ok(a / b) + } +} + +/// Logs errors at the `error` level. No log output for `Ok` variant. #[logcall(err = "error")] -fn bar(a: usize) -> Result { - Err(a + 1) +fn divide2(a: usize, b: usize) -> Result { + if b == 0 { + Err("Division by zero".to_string()) + } else { + Ok(a / b) + } } -#[logcall(ok = "info", err = "error")] -fn baz(a: usize) -> Result { - Ok(a + 1) +/// Logs the function call with custom input logging format. +#[logcall(input = "a = {a:?}, ..")] +fn subtract(a: i32, b: i32) -> i32 { + a - b } fn main() { - env_logger::builder().filter_level(log::LevelFilter::Info).init(); - foo(1); - bar(1).ok(); - baz(1).ok(); + env_logger::builder() + .filter_level(log::LevelFilter::Trace) + .init(); + + add(2, 3); + multiply(2, 3); + divide(2, 0).ok(); + divide2(2, 0).ok(); + subtract(2, 3); } +``` + +### Log Output -// prints: -// [2023-07-22T06:55:10Z INFO main] foo() => 2 -// [2023-07-22T06:55:10Z ERROR main] bar() => Err(2) -// [2023-07-22T06:55:10Z INFO main] baz() => Ok(2) +When the `main` function runs, it initializes the logger and logs each function call as specified: + +``` +[2024-06-16T12:41:04Z DEBUG main] add(a = 2, b = 3) => 5 +[2024-06-16T12:41:04Z INFO main] multiply(a = 2, b = 3) => 6 +[2024-06-16T12:41:04Z ERROR main] divide(a = 2, b = 0) => Err("Division by zero") +[2024-06-16T12:41:04Z ERROR main] divide2(a = 2, b = 0) => Err("Division by zero") +[2024-06-16T12:41:04Z DEBUG main] subtract(a = 2, ..) => -1 ``` + +## Customization + +- **Default Log Level**: If no log level is specified, `logcall` logs at the `debug` level: + ```rust + #[logcall] + ``` +- **Specify Log Level**: Use the macro parameters to specify log level: + ```rust + #[logcall("info")] +- **Specify Log Levels for `Result`**: Use the `ok` and `err` parameters to specify log levels for `Ok` and `Err` variants: + ```rust + #[logcall(err = "error")] + #[logcall(ok = "info", err = "error")] + ``` +- **Customize Input Logging**: Use the `input` parameter to customize the input log format: + ```rust + #[logcall(input = "a = {a:?}, ..")] + #[logcall("info", input = "a = {a:?}, ..")] + #[logcall(ok = "info", err = "error", input = "a = {a:?}, ..")] + ``` + +## Contributing + +Contributions are welcome! Please submit pull requests or open issues to improve the crate. + +## License + +This project is licensed under the MIT License. diff --git a/examples/main.rs b/examples/main.rs index b979a5d..d76e699 100644 --- a/examples/main.rs +++ b/examples/main.rs @@ -1,25 +1,51 @@ use logcall::logcall; +/// Logs the function call at the default `debug` level. +#[logcall] +fn add(a: i32, b: i32) -> i32 { + a + b +} + +/// Logs the function call at the `info` level. #[logcall("info")] -fn foo(a: usize) -> usize { - a + 1 +fn multiply(a: i32, b: i32) -> i32 { + a * b } +/// Logs `Ok` results at the `info` level and `Err` results at the `error` level. +#[logcall(ok = "info", err = "error")] +fn divide(a: i32, b: i32) -> Result { + if b == 0 { + Err("Division by zero".to_string()) + } else { + Ok(a / b) + } +} + +/// Logs errors at the `error` level. No log output for `Ok` variant. #[logcall(err = "error")] -fn bar(a: usize) -> Result { - Err(format!("{}", a + 1)) +fn divide2(a: usize, b: usize) -> Result { + if b == 0 { + Err("Division by zero".to_string()) + } else { + Ok(a / b) + } } -#[logcall(ok = "info", err = "error")] -fn baz(a: usize) -> Result { - Ok(a + 1) +/// Logs the function call with custom input logging format. +#[logcall(input = "a = {a:?}, ..")] +fn subtract(a: i32, b: i32) -> i32 { + a - b } fn main() { env_logger::builder() - .filter_level(log::LevelFilter::Info) + .filter_level(log::LevelFilter::Trace) .init(); - foo(1); - bar(1).ok(); - baz(1).ok(); + + add(2, 3); + multiply(2, 3); + divide(2, 0).ok(); + divide2(2, 0).ok(); + subtract(2, 3); } diff --git a/src/lib.rs b/src/lib.rs index 4ee042a..a3384b3 100644 --- a/src/lib.rs +++ b/src/lib.rs @@ -1,7 +1,5 @@ -// Copyright 2020 TiKV Project Authors. Licensed under Apache-2.0. - #![doc = include_str!("../README.md")] -#![recursion_limit = "256"] + // Instrumenting the async fn is not as straight forward as expected because `async_trait` rewrites `async fn` // into a normal fn which returns `Box`, and this stops the macro from distinguishing `async fn` from `fn`. // The following code reused the `async_trait` probes from [tokio-tracing](https://github.com/tokio-rs/tracing/blob/6a61897a5e834988ad9ac709e28c93c4dbf29116/tracing-attributes/src/expand.rs). @@ -12,7 +10,6 @@ extern crate proc_macro; extern crate proc_macro_error; use proc_macro2::Span; -use quote::quote_spanned; use syn::spanned::Spanned; use syn::Ident; use syn::*; @@ -20,61 +17,77 @@ use syn::*; enum Args { Simple { level: String, + input_format: Option, }, Result { ok_level: Option, err_level: Option, + input_format: Option, }, } impl Args { fn parse(input: AttributeArgs) -> Args { - match input.as_slice() { - [NestedMeta::Lit(Lit::Str(s))] => Args::Simple { level: s.value() }, - [NestedMeta::Meta(Meta::NameValue(MetaNameValue { - path, - lit: Lit::Str(s), - .. - }))] if path.is_ident("ok") => Args::Result { - ok_level: Some(s.value()), - err_level: None, - }, - [NestedMeta::Meta(Meta::NameValue(MetaNameValue { - path, - lit: Lit::Str(s), - .. - }))] if path.is_ident("err") => Args::Result { - ok_level: None, - err_level: Some(s.value()), - }, - [NestedMeta::Meta(Meta::NameValue(MetaNameValue { - path, - lit: Lit::Str(s), - .. - })), NestedMeta::Meta(Meta::NameValue(MetaNameValue { - path: path2, - lit: Lit::Str(s2), - .. - }))] - | [NestedMeta::Meta(Meta::NameValue(MetaNameValue { - path: path2, - lit: Lit::Str(s2), - .. - })), NestedMeta::Meta(Meta::NameValue(MetaNameValue { - path, - lit: Lit::Str(s), - .. - }))] if path.is_ident("ok") && path2.is_ident("err") => Args::Result { - ok_level: Some(s.value()), - err_level: Some(s2.value()), - }, - [] => abort_call_site!("missing arguments"), - _ => abort_call_site!("invalid arguments"), + let mut simple_level = None; + let mut ok_level = None; + let mut err_level = None; + let mut input_format = None; + + for arg in input { + match arg { + NestedMeta::Meta(Meta::NameValue(MetaNameValue { + path, + lit: Lit::Str(lit_str), + .. + })) => { + let ident = path.get_ident().unwrap().to_string(); + match ident.as_str() { + "ok" => { + ok_level = Some(lit_str.value()); + } + "err" => { + err_level = Some(lit_str.value()); + } + "input" => { + input_format = Some(lit_str.value()); + } + _ => { + abort!(ident.span(), "unexpected argument"); + } + } + } + NestedMeta::Lit(Lit::Str(lit_str)) => { + if simple_level.is_some() { + abort!(lit_str.span(), "level has already been specified"); + } + simple_level = Some(lit_str.value()); + } + _ => { + abort!(arg.span(), "unexpected argument"); + } + } + } + + if ok_level.is_some() || err_level.is_some() { + if simple_level.is_some() { + abort_call_site!("plain level cannot be specified with `ok` or `err` levels"); + } + + Args::Result { + ok_level, + err_level, + input_format, + } + } else { + Args::Simple { + level: simple_level.unwrap_or_else(|| "debug".to_string()), + input_format, + } } } } -/// An attribute macro that logs the function return value. +/// `logcall` attribute macro that logs the function inputs and return values. #[proc_macro_attribute] #[proc_macro_error] pub fn logcall( @@ -92,7 +105,7 @@ pub fn logcall( // let's rewrite some statements! match internal_fun.kind { // async-trait <= 0.1.43 - AsyncTraitKind::Function(_) => { + AsyncTraitKind::Function => { unimplemented!( "Please upgrade the crate `async-trait` to a version higher than 0.1.44" ) @@ -101,15 +114,10 @@ pub fn logcall( AsyncTraitKind::Async(async_expr) => { // fallback if we couldn't find the '__async_trait' binding, might be // useful for crates exhibiting the same behaviors as async-trait - let instrumented_block = gen_block( - &async_expr.block, - true, - false, - &input.sig.ident.to_string(), - args, - ); + let instrumented_block = + gen_block(&async_expr.block, true, false, &input.sig, args); let async_attrs = &async_expr.attrs; - quote! { + quote::quote_spanned! {async_expr.span()=> Box::pin(#(#async_attrs) * #instrumented_block ) } } @@ -119,14 +127,14 @@ pub fn logcall( &input.block, input.sig.asyncness.is_some(), input.sig.asyncness.is_some(), - &input.sig.ident.to_string(), + &input.sig, args, ) }; let ItemFn { attrs, vis, sig, .. - } = input; + } = input.clone(); let Signature { output: return_type, @@ -145,7 +153,7 @@ pub fn logcall( .. } = sig; - quote::quote!( + quote::quote_spanned!(input.span()=> #(#attrs) * #vis #constness #unsafety #asyncness #abi fn #ident<#gen_params>(#params) #return_type #where_clause @@ -161,17 +169,26 @@ fn gen_block( block: &Block, async_context: bool, async_keyword: bool, - fn_name: &str, + sig: &Signature, args: Args, ) -> proc_macro2::TokenStream { + let fn_name = sig.ident.to_string(); + match args { - Args::Simple { level } => { + Args::Simple { + level, + input_format, + } => { // Generate the instrumented function body. // If the function is an `async fn`, this will wrap it in an async block. if async_context { - let log = gen_log(&level, fn_name, "__ret_value"); - let block = quote_spanned!(block.span()=> + let input_format = input_format.unwrap_or_else(|| gen_input_format(sig)); + let log = gen_log(&level, &fn_name, "__input_string", "__ret_value"); + let block = quote::quote_spanned!(block.span()=> async move { + #[allow(unknown_lints)] + #[allow(clippy::useless_format)] + let __input_string = format!(#input_format); let __ret_value = async move { #block }.await; #log; __ret_value @@ -179,15 +196,19 @@ fn gen_block( ); if async_keyword { - quote_spanned!(block.span()=> + quote::quote_spanned!(block.span()=> #block.await ) } else { block } } else { - let log = gen_log(&level, fn_name, "__ret_value"); - quote_spanned!(block.span()=> + let input_format = input_format.unwrap_or_else(|| gen_input_format(sig)); + let log = gen_log(&level, &fn_name, "__input_string", "__ret_value"); + quote::quote_spanned!(block.span()=> + #[allow(unknown_lints)] + #[allow(clippy::useless_format)] + let __input_string = format!(#input_format); #[allow(unknown_lints)] #[allow(clippy::redundant_closure_call)] let __ret_value = (move || #block)(); @@ -199,30 +220,31 @@ fn gen_block( Args::Result { ok_level, err_level, + input_format, } => { let ok_arm = if let Some(ok_level) = ok_level { - let log_ok = gen_log(&ok_level, fn_name, "__ret_value"); - quote_spanned!(block.span()=> + let log_ok = gen_log(&ok_level, &fn_name, "__input_string", "__ret_value"); + quote::quote_spanned!(block.span()=> __ret_value@Ok(_) => { #log_ok; __ret_value } ) } else { - quote_spanned!(block.span()=> + quote::quote_spanned!(block.span()=> Ok(__ret_value) => Ok(__ret_value), ) }; let err_arm = if let Some(err_level) = err_level { - let log_err = gen_log(&err_level, fn_name, "__ret_value"); - quote_spanned!(block.span()=> + let log_err = gen_log(&err_level, &fn_name, "__input_string", "__ret_value"); + quote::quote_spanned!(block.span()=> __ret_value@Err(_) => { #log_err; __ret_value } ) } else { - quote_spanned!(block.span()=> + quote::quote_spanned!(block.span()=> Err(__ret_value) => Err(__ret_value), ) }; @@ -230,8 +252,12 @@ fn gen_block( // Generate the instrumented function body. // If the function is an `async fn`, this will wrap it in an async block. if async_context { - let block = quote_spanned!(block.span()=> - async move { + let input_format = input_format.unwrap_or_else(|| gen_input_format(sig)); + let block = quote::quote_spanned!(block.span()=> + async move { + #[allow(unknown_lints)] + #[allow(clippy::useless_format)] + let __input_string = format!(#input_format); let __ret_value = async move { #block }.await; match __ret_value { #ok_arm @@ -241,14 +267,18 @@ fn gen_block( ); if async_keyword { - quote_spanned!(block.span()=> + quote::quote_spanned!(block.span()=> #block.await ) } else { block } } else { - quote_spanned!(block.span()=> + let input_format = input_format.unwrap_or_else(|| gen_input_format(sig)); + quote::quote_spanned!(block.span()=> + #[allow(unknown_lints)] + #[allow(clippy::useless_format)] + let __input_string = format!(#input_format); #[allow(unknown_lints)] #[allow(clippy::redundant_closure_call)] let __ret_value = (move || #block)(); @@ -262,21 +292,49 @@ fn gen_block( } } -fn gen_log(level: &str, fn_name: &str, return_value: &str) -> proc_macro2::TokenStream { +fn gen_log( + level: &str, + fn_name: &str, + input_string: &str, + return_value: &str, +) -> proc_macro2::TokenStream { let level = level.to_lowercase(); if !["error", "warn", "info", "debug", "trace"].contains(&level.as_str()) { abort_call_site!("unknown log level"); } let level: Ident = Ident::new(&level, Span::call_site()); + let input_string: Ident = Ident::new(input_string, Span::call_site()); let return_value: Ident = Ident::new(return_value, Span::call_site()); - quote!( - log::#level! ("{}() => {:?}", #fn_name, &#return_value) + quote::quote!( + log::#level! ("{}({}) => {:?}", #fn_name, #input_string, &#return_value) ) } +// fn(a: usize, b: usize) => "a = {a:?}, b = {b:?}" +fn gen_input_format(sig: &Signature) -> String { + let mut input_format = String::new(); + for (i, input) in sig.inputs.iter().enumerate() { + if i > 0 { + input_format.push_str(", "); + } + match input { + FnArg::Typed(PatType { pat, .. }) => { + if let Pat::Ident(pat_ident) = &**pat { + let ident = &pat_ident.ident; + input_format.push_str(&format!("{ident} = {{{ident}:?}}")); + } + } + FnArg::Receiver(_) => { + input_format.push_str("self"); + } + } + } + input_format +} + enum AsyncTraitKind<'a> { // old construction. Contains the function - Function(&'a ItemFn), + Function, // new construction. Contains a reference to the async block Async(&'a ExprAsync), } @@ -380,13 +438,13 @@ fn get_async_trait_info(block: &Block, block_is_async: bool) -> Option tests/ui/err/error-passthrough.rs:5:1 + | +2 | fn f() {} + | ------ previous definition of the value `f` here +... +5 | fn f() {} + | ^^^^^^ `f` redefined here + | + = note: `f` must be defined only once in the value namespace of this module diff --git a/tests/ui/err/has-no-argument.stderr b/tests/ui/err/has-no-argument.stderr deleted file mode 100644 index 42ab18c..0000000 --- a/tests/ui/err/has-no-argument.stderr +++ /dev/null @@ -1,7 +0,0 @@ -error: missing arguments - --> tests/ui/err/has-no-argument.rs:1:1 - | -1 | #[logcall::logcall] - | ^^^^^^^^^^^^^^^^^^^ - | - = note: this error originates in the attribute macro `logcall::logcall` (in Nightly builds, run with -Z macro-backtrace for more info) diff --git a/tests/ui/err/has-too-many-arguments.stderr b/tests/ui/err/has-too-many-arguments.stderr index 2b71480..40375eb 100644 --- a/tests/ui/err/has-too-many-arguments.stderr +++ b/tests/ui/err/has-too-many-arguments.stderr @@ -1,7 +1,5 @@ -error: invalid arguments - --> tests/ui/err/has-too-many-arguments.rs:1:1 +error: level has already been specified + --> tests/ui/err/has-too-many-arguments.rs:1:28 | 1 | #[logcall::logcall("info", "error")] - | ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ - | - = note: this error originates in the attribute macro `logcall::logcall` (in Nightly builds, run with -Z macro-backtrace for more info) + | ^^^^^^^ diff --git a/tests/ui/err/has-no-argument.rs b/tests/ui/ok/has-no-argument.rs similarity index 100% rename from tests/ui/err/has-no-argument.rs rename to tests/ui/ok/has-no-argument.rs