captains_log_helper/
lib.rs

1//! This is sub-crate of [captains-log](https://docs.rs/captains-log/latest/captains_log/)
2//!
3//! Provides a attribute macro [macro@logfn] to wrap function for convenience.
4
5#![recursion_limit = "128"]
6use proc_macro2::Span;
7use quote::quote;
8use syn::{
9    parse_macro_input, spanned::Spanned, Expr,
10    ItemFn, LitStr, Ident, Signature, FnArg, Pat, PatType,
11    Block, Stmt, ExprCall,ExprAsync, Generics, Path,
12};
13use syn::parse::{Parse, ParseStream};
14
15#[derive(Default, Debug)]
16struct Args {
17    level: Option<String>,
18}
19
20impl Parse for Args {
21    fn parse(input: ParseStream) -> syn::Result::<Self> {
22        let mut args = Self::default();
23        while !input.is_empty() {
24            if input.peek(LitStr) {
25                // [logfn("warn")]
26                let level = input.parse::<LitStr>()?;
27                args.level = Some(level.value());
28            } else if input.peek(Ident) {
29                // [logfn(warn)]
30                let ident = input.parse::<Ident>()?;
31                if args.level.is_none() {
32                    args.level = Some(ident.to_string());
33                }
34            } else {
35                return Err(input.error("unexpected token"));
36            }
37        }
38        if let Some(v) = args.level.as_ref() {
39            match v.as_str() {
40                "trace" | "debug" | "info" | "warn" | "error"=>{},
41                _=> {
42                    return Err(input.error(format!("unexpected level value: {:?}", v)));
43                }
44            }
45        }
46        Ok(args)
47    }
48}
49
50fn gen_arg_list(sig: &Signature) -> String {
51    let mut arg_list = String::new();
52    for (i, input) in sig.inputs.iter().enumerate() {
53        if i > 0 {
54            arg_list.push_str(", ");
55        }
56        match input {
57            FnArg::Typed(PatType { pat, .. }) => {
58                if let Pat::Ident(pat_ident) = &**pat {
59                    let ident = &pat_ident.ident;
60                    arg_list.push_str(&format!("{ident} = {{{ident}:?}}"));
61                }
62            }
63            FnArg::Receiver(_) => {
64                arg_list.push_str("self");
65            }
66        }
67    }
68    arg_list
69}
70
71// The following code reused the `async_trait` probes from tokio-tracing
72//
73// https://github.com/tokio-rs/tracing/blob/6a61897a/tracing-attributes/src/expand.rs
74// Copyright (c) 2019 Tokio Contributors, MIT license
75fn process_async_trait<'a>(block: &'a Block, is_async: bool) -> Option<&'a ExprAsync> {
76
77    fn path_to_string(path: &Path) -> String {
78        use std::fmt::Write;
79        let mut res = String::with_capacity(path.segments.len() * 5);
80        for i in 0..path.segments.len() {
81            write!(res, "{}", path.segments[i].ident).expect("write to string ok");
82            if i < path.segments.len() -1 {
83                res.push_str("::");
84            }
85        }
86        res
87    }
88
89    if is_async {
90        return None;
91    }
92    // last expression of the block (it determines the return value
93    // of the block, so that if we are working on a function whose
94    // `trait` or `impl` declaration is annotated by async_trait,
95    //  this is quite likely the point where the future is pinned)
96    let last_expr = block.stmts.iter().rev().find_map(|stmt| {
97        if let Stmt::Expr(expr, ..) = stmt {
98            Some(expr)
99        } else {
100            None
101        }
102    })?;
103    // is the last expression a function call?
104    let (outside_func, outside_args) = match last_expr {
105        Expr::Call(ExprCall { func, args, .. }) => (func, args),
106        _ => return None,
107    };
108    // is it a call to `Box::pin()`?
109    let path = match outside_func.as_ref() {
110        Expr::Path(path) => &path.path,
111        _ => return None,
112    };
113    if !path_to_string(path).ends_with("Box::pin") {
114        return None;
115    }
116    // Does the call take an argument? If it doesn't,
117    // it's not going to compile anyway, but that's no reason
118    // to (try to) perform an out-of-bounds access
119    if outside_args.is_empty() {
120        return None;
121    }
122    // Is the argument to Box::pin an async block that
123    // captures its arguments?
124    if let Expr::Async(async_expr) = &outside_args[0] {
125         // check that the move 'keyword' is present
126        async_expr.capture?;
127        return Some(async_expr);
128    }
129    unimplemented!("async-trait < 0.1.44 is not supported");
130}
131
132
133fn generate_function(args: Args, block: &Block,
134    async_context: bool, async_keyword: bool,
135    sig: &Signature) -> proc_macro2::TokenStream {
136    let fn_name = sig.ident.to_string();
137    let level = args.level.unwrap_or("info".to_string());
138    let level = Ident::new(&level, Span::call_site());
139    let arg_list = gen_arg_list(sig);
140    let fmt_begin = format!("<<< {} ({}) enter <<<", fn_name, arg_list);
141    let fmt_end = format!(">>> {} return {{__ret_value:?}} in {{__dur:?}} >>>", fn_name);
142    let begin_expr = quote! {
143        log::#level!(#fmt_begin);
144        let __start_ts = std::time::Instant::now();
145    };
146    let end_expr = quote! {
147        let __dur = std::time::Instant::now() - __start_ts;
148        log::#level!(#fmt_end);
149    };
150
151    if async_context {
152        let block = quote::quote_spanned!(block.span()=>
153            #begin_expr
154            let __ret_value = async { #block }.await;
155            #end_expr
156            __ret_value
157        );
158        if async_keyword { // normal async fn
159            return block.into();
160        } else { // async_trait
161            return quote::quote_spanned!(block.span()=>
162                async move {
163                    #block
164                }
165            ).into();
166        }
167    } else {
168        return quote::quote_spanned!(block.span()=>
169            #begin_expr
170            let __ret_value = (move ||#block)();
171            #end_expr
172            __ret_value
173        ).into();
174    }
175}
176
177fn output_stream(input: &ItemFn, func_body: proc_macro2::TokenStream) -> proc_macro::TokenStream {
178    let sig = &input.sig;
179    let attrs = &input.attrs;
180    let vis = &input.vis;
181    let Signature {
182        output,
183        inputs,
184        unsafety,
185        constness,
186        abi,
187        ident,
188        asyncness,
189        generics:
190            Generics {
191                params: gen_params,
192                where_clause,
193                ..
194            },
195        ..
196    } = sig;
197    quote::quote_spanned!(input.span()=>
198        #(#attrs) *
199        #vis #constness #unsafety #asyncness #abi fn #ident<#gen_params>(#inputs) #output
200        #where_clause
201        {
202            #func_body
203        }
204    ).into()
205}
206
207
208/// Provide an proc_macro `#[logfn]` which log the information:
209///
210/// - function call begin, argument list
211///
212/// - function return value, duration time.
213///
214/// Supports async fn and async-trait >=0.1.44.
215///
216/// # Examples
217///
218/// ``` rust
219///
220/// use captains_log::{recipe, logfn};
221/// use log::*;
222///
223/// let builder = recipe::raw_file_logger("/tmp", "log_test", log::Level::Debug).test();
224/// builder.build().expect("setup_log");
225///
226/// // default log level to be info
227/// #[logfn]
228/// fn foo() {
229///     info!("foo");
230///     bar(1, "bar arg");
231/// }
232///
233/// // you can change log level to warn
234/// #[logfn(warn)]
235/// fn bar(a: i32, s: &str) {
236///     info!("bar");
237/// }
238/// foo();
239/// ```
240///
241/// /tmp/log_test.log will have this content:
242///
243/// ``` text
244///[2025-07-13 18:22:39.151481][INFO][test_logfn.rs:19] <<< foo () enter <<<
245///[2025-07-13 18:22:39.151774][INFO][test_logfn.rs:21] foo
246///[2025-07-13 18:22:39.151840][WARN][test_logfn.rs:25] <<< bar (a = 1, s = "bar arg") enter <<<
247///[2025-07-13 18:22:39.151886][INFO][test_logfn.rs:27] bar
248///[2025-07-13 18:22:39.151925][WARN][test_logfn.rs:25] >>> bar return () in 39.183µs >>>
249///[2025-07-13 18:22:39.151969][INFO][test_logfn.rs:19] >>> foo return () in 197.381µs >>>
250/// ```
251///
252/// # Best practice with test suit
253///
254/// You can have `#[logfn]` used with retest.
255///
256/// * When you have large test suit, you want to know which logs belong to which test case.
257///
258/// * Sometimes your test crashes, you want to find the responsible test case.
259///
260/// * The time spend in each test
261///
262/// ``` rust
263/// use rstest::*;
264/// use log::*;
265/// use captains_log::*;
266///
267/// // A show case that setup() fixture will be called twice, before each test.
268/// // In order make logs available.
269/// #[fixture]
270/// fn setup() {
271///     let builder = recipe::raw_file_logger("/tmp", "log_rstest", log::Level::Debug).test();
272///     builder.build().expect("setup_log");
273/// }
274///
275/// #[logfn]
276/// #[rstest(file_size, case(0), case(1))]
277/// fn test_rstest_foo(setup: (), file_size: usize) {
278///     info!("do something111");
279/// }
280///
281/// #[logfn]
282/// #[rstest]
283/// fn test_rstest_bar(setup: ()) {
284///     info!("do something222");
285/// }
286///
287/// #[tokio::test]
288/// #[logfn]
289/// #[rstest]
290/// async fn test_rstest_async(setup: ()) {
291///     info!("something333")
292/// }
293///
294/// ```
295///
296/// **Notice:** the order when combine tokio::test with rstest,
297/// `#[rstest]` attribute must be at the bottom to make setup fixture effective.
298///
299/// After running the test with:
300/// `cargo test -- --test-threads=1`
301///
302/// /tmp/log_rstest.log will have this content:
303///
304/// ``` text
305///[2025-07-13 18:22:39.159642][INFO][test_rstest.rs:33] <<< test_rstest_async (setup = ()) enter <<<
306///[2025-07-13 18:22:39.160255][INFO][test_rstest.rs:37] something333
307///[2025-07-13 18:22:39.160567][INFO][test_rstest.rs:33] >>> test_rstest_async return () in 564.047µs >>>
308///[2025-07-13 18:22:39.161299][INFO][test_rstest.rs:26] <<< test_rstest_bar (setup = ()) enter <<<
309///[2025-07-13 18:22:39.161643][INFO][test_rstest.rs:29] do something222
310///[2025-07-13 18:22:39.161703][INFO][test_rstest.rs:26] >>> test_rstest_bar return () in 62.681µs >>>
311///[2025-07-13 18:22:39.162169][INFO][test_rstest.rs:20] <<< test_rstest_foo (setup = (), file_size = 0) enter <<<
312///[2025-07-13 18:22:39.162525][INFO][test_rstest.rs:23] do something111
313///[2025-07-13 18:22:39.162600][INFO][test_rstest.rs:20] >>> test_rstest_foo return () in 78.457µs >>>
314///[2025-07-13 18:22:39.163050][INFO][test_rstest.rs:20] <<< test_rstest_foo (setup = (), file_size = 1) enter <<<
315///[2025-07-13 18:22:39.163320][INFO][test_rstest.rs:23] do something111
316///[2025-07-13 18:22:39.163377][INFO][test_rstest.rs:20] >>> test_rstest_foo return () in 58.747µs >>>
317/// ```
318#[proc_macro_attribute]
319pub fn logfn(
320    attr: proc_macro::TokenStream, item: proc_macro::TokenStream,
321) -> proc_macro::TokenStream {
322    let original_fn: ItemFn = parse_macro_input!(item as ItemFn);
323    let args = parse_macro_input!(attr as Args);
324//    let closure = make_closure(&original_fn);
325    let is_async = original_fn.sig.asyncness.is_some();
326
327    let body = {
328        if let Some(async_expr) = process_async_trait(&original_fn.block, is_async) {
329            let inst_block = generate_function(args, &async_expr.block, true, false, &original_fn.sig);
330            let async_attrs = &async_expr.attrs;
331            quote::quote_spanned! {async_expr.span()=>
332                Box::pin(#(#async_attrs) * #inst_block)}
333        } else {
334            generate_function(
335                args, &original_fn.block, is_async, is_async, &original_fn.sig)
336        }
337    };
338    output_stream(&original_fn, body)
339}
captains_log_helper/lib.rs

captains_log_helper/
lib.rs
