Demo of the tracing crate to automatically trace function entry and exit (each function must have the `#[instrument]` attribute)

fbb.rs

#!/usr/bin/env rust-script
//! Automatic function call tracing with parameters
//!
//! ```cargo
//! [dependencies]
//! tracing = "0.1"
//! tracing-subscriber = { version = "0.3", features = ["fmt"] }
//! ```

use tracing::instrument;

// Use #[instrument(level = "info")] to ensure visibility
// and add ret to automatically log return values
#[instrument(level = "info", ret)]
fn baz(value: i32, name: &str) -> i32 {
    let result = value * 2;
    if name == "special" {
        result + 100
    } else {
        result
    }
}

#[instrument(level = "info", ret)]
fn bar(input: i32, multiplier: f64) -> i32 {
    let adjusted = (input as f64 * multiplier) as i32;
    let result1 = baz(adjusted, "normal");
    let result2 = baz(adjusted + 5, "special");
    result1 + result2
}

#[instrument(level = "info", ret)]
fn foo(start_value: i32) -> i32 {
    bar(start_value, 1.5)
}

fn main() {
    // Configure tracing to show entry/exit events
    tracing_subscriber::fmt()
        .with_max_level(tracing::Level::INFO)
        .with_target(false)
        .with_span_events(tracing_subscriber::fmt::format::FmtSpan::ENTER | tracing_subscriber::fmt::format::FmtSpan::EXIT)
        .init();

    println!("=== Starting traced execution ===");
    let result = foo(42);
    println!("Final result: {}\n", result);
    
    println!("=== Another call ===");
    let result2 = foo(10);
    println!("Second result: {}", result2);
}

=== Starting traced execution ===
2025-05-26T15:36:31.589517Z  INFO foo{start_value=42}: enter
2025-05-26T15:36:31.589524Z  INFO foo{start_value=42}:bar{input=42 multiplier=1.5}: enter
2025-05-26T15:36:31.589527Z  INFO foo{start_value=42}:bar{input=42 multiplier=1.5}:baz{value=63 name="normal"}: enter
2025-05-26T15:36:31.589529Z  INFO foo{start_value=42}:bar{input=42 multiplier=1.5}:baz{value=63 name="normal"}: return=126
2025-05-26T15:36:31.589531Z  INFO foo{start_value=42}:bar{input=42 multiplier=1.5}:baz{value=63 name="normal"}: exit
2025-05-26T15:36:31.589534Z  INFO foo{start_value=42}:bar{input=42 multiplier=1.5}:baz{value=68 name="special"}: enter
2025-05-26T15:36:31.589535Z  INFO foo{start_value=42}:bar{input=42 multiplier=1.5}:baz{value=68 name="special"}: return=236
2025-05-26T15:36:31.589540Z  INFO foo{start_value=42}:bar{input=42 multiplier=1.5}:baz{value=68 name="special"}: exit
2025-05-26T15:36:31.589542Z  INFO foo{start_value=42}:bar{input=42 multiplier=1.5}: return=362
2025-05-26T15:36:31.589543Z  INFO foo{start_value=42}:bar{input=42 multiplier=1.5}: exit
2025-05-26T15:36:31.589545Z  INFO foo{start_value=42}: return=362
2025-05-26T15:36:31.589546Z  INFO foo{start_value=42}: exit
Final result: 362

=== Another call ===
2025-05-26T15:36:31.589548Z  INFO foo{start_value=10}: enter
2025-05-26T15:36:31.589550Z  INFO foo{start_value=10}:bar{input=10 multiplier=1.5}: enter
2025-05-26T15:36:31.589551Z  INFO foo{start_value=10}:bar{input=10 multiplier=1.5}:baz{value=15 name="normal"}: enter
2025-05-26T15:36:31.589553Z  INFO foo{start_value=10}:bar{input=10 multiplier=1.5}:baz{value=15 name="normal"}: return=30
2025-05-26T15:36:31.589554Z  INFO foo{start_value=10}:bar{input=10 multiplier=1.5}:baz{value=15 name="normal"}: exit
2025-05-26T15:36:31.589556Z  INFO foo{start_value=10}:bar{input=10 multiplier=1.5}:baz{value=20 name="special"}: enter
2025-05-26T15:36:31.589558Z  INFO foo{start_value=10}:bar{input=10 multiplier=1.5}:baz{value=20 name="special"}: return=140
2025-05-26T15:36:31.589559Z  INFO foo{start_value=10}:bar{input=10 multiplier=1.5}:baz{value=20 name="special"}: exit
2025-05-26T15:36:31.589561Z  INFO foo{start_value=10}:bar{input=10 multiplier=1.5}: return=170
2025-05-26T15:36:31.589562Z  INFO foo{start_value=10}:bar{input=10 multiplier=1.5}: exit
2025-05-26T15:36:31.589563Z  INFO foo{start_value=10}: return=170
2025-05-26T15:36:31.589565Z  INFO foo{start_value=10}: exit
Second result: 170