Attribute Macro logfn 

#[logfn]

Provide an proc_macro #[logfn] which log the information:

• function call begin, argument list

• function return value, duration time.

Supports async fn and async-trait >=0.1.44.

Examples

use captains_log::{recipe, logfn};
use log::*;

let builder = recipe::raw_file_logger("/tmp", "log_test", log::Level::Debug).test();
builder.build().expect("setup_log");

// default log level to be info
#[logfn]
fn foo() {
    info!("foo");
    bar(1, "bar arg");
}

// you can change log level to warn
#[logfn(warn)]
fn bar(a: i32, s: &str) {
    info!("bar");
}
foo();

/tmp/log_test.log will have this content:

[2025-07-13 18:22:39.151481][INFO][test_logfn.rs:19] <<< foo () enter <<<
[2025-07-13 18:22:39.151774][INFO][test_logfn.rs:21] foo
[2025-07-13 18:22:39.151840][WARN][test_logfn.rs:25] <<< bar (a = 1, s = "bar arg") enter <<<
[2025-07-13 18:22:39.151886][INFO][test_logfn.rs:27] bar
[2025-07-13 18:22:39.151925][WARN][test_logfn.rs:25] >>> bar return () in 39.183µs >>>
[2025-07-13 18:22:39.151969][INFO][test_logfn.rs:19] >>> foo return () in 197.381µs >>>

Best practice with test suit

You can have #[logfn] used with retest.

• When you have large test suit, you want to know which logs belong to which test case.

• Sometimes your test crashes, you want to find the responsible test case.

• The time spend in each test

use rstest::*;
use log::*;
use captains_log::*;

// A show case that setup() fixture will be called twice, before each test.
// In order make logs available.
#[fixture]
fn setup() {
    let builder = recipe::raw_file_logger("/tmp", "log_rstest", log::Level::Debug).test();
    builder.build().expect("setup_log");
}

#[logfn]
#[rstest(file_size, case(0), case(1))]
fn test_rstest_foo(setup: (), file_size: usize) {
    info!("do something111");
}

#[logfn]
#[rstest]
fn test_rstest_bar(setup: ()) {
    info!("do something222");
}

#[tokio::test]
#[logfn]
#[rstest]
async fn test_rstest_async(setup: ()) {
    info!("something333")
}

Notice: the order when combine tokio::test with rstest, #[rstest] attribute must be at the bottom to make setup fixture effective.

After running the test with: cargo test -- --test-threads=1

/tmp/log_rstest.log will have this content:

[2025-07-13 18:22:39.159642][INFO][test_rstest.rs:33] <<< test_rstest_async (setup = ()) enter <<<
[2025-07-13 18:22:39.160255][INFO][test_rstest.rs:37] something333
[2025-07-13 18:22:39.160567][INFO][test_rstest.rs:33] >>> test_rstest_async return () in 564.047µs >>>
[2025-07-13 18:22:39.161299][INFO][test_rstest.rs:26] <<< test_rstest_bar (setup = ()) enter <<<
[2025-07-13 18:22:39.161643][INFO][test_rstest.rs:29] do something222
[2025-07-13 18:22:39.161703][INFO][test_rstest.rs:26] >>> test_rstest_bar return () in 62.681µs >>>
[2025-07-13 18:22:39.162169][INFO][test_rstest.rs:20] <<< test_rstest_foo (setup = (), file_size = 0) enter <<<
[2025-07-13 18:22:39.162525][INFO][test_rstest.rs:23] do something111
[2025-07-13 18:22:39.162600][INFO][test_rstest.rs:20] >>> test_rstest_foo return () in 78.457µs >>>
[2025-07-13 18:22:39.163050][INFO][test_rstest.rs:20] <<< test_rstest_foo (setup = (), file_size = 1) enter <<<
[2025-07-13 18:22:39.163320][INFO][test_rstest.rs:23] do something111
[2025-07-13 18:22:39.163377][INFO][test_rstest.rs:20] >>> test_rstest_foo return () in 58.747µs >>>