Look, we've all been there. You're staring at a production log file with ten thousand lines of text, trying to figure out why a specific order failed. You're running a grep command for a specific order ID, but because the logs are just a stream of strings, you're missing the bigger picture. You can see that an error happened, but you can't easily see the sequence of events that led up to it across different functions without manually stitching together timestamps.

The Grep Nightmare

The naive way to handle logging is to treat your logs like a diary. You use the log crate or just println! and interpolate your variables directly into a string. It looks something like this:

fn process_order(order_id: u64, user_id: u64) {
    info!("Processing order {} for user {}", order_id, user_id);
    if let Err(e) = validate_payment(order_id) {
        error!("Payment failed for order {}: {}", order_id, e);
    }
}

On the surface, this is fine. But as a software engineer, you have to think about the person who has to query these logs six months from now. If you decide to change the log message from "Processing order" to "Handling order", you've just broken every single regex and dashboard alert based on that string. More importantly, if validate_payment calls five other functions, and you want the order_id in those logs too, you're forced to pass that ID as an argument through every single function call just so you can log it. It's tedious, it pollutes your API, and it's fragile.

Adding Context Without the Plumbing

This is where tracing changes the game. Instead of thinking about "log lines," we start thinking about "spans" and "fields." A span represents a period of time—like the duration of an HTTP request—and you can attach data to that span. Any log emitted inside that span automatically carries that data with it.

Here is how I would rewrite that same logic using tracing:

use tracing::{info, error, info_span};

fn process_order(order_id: u64, user_id: u64) {
    // We create a span and "enter" it. 
    // Everything inside this block inherits these fields.
    let span = info_span!("process_order", %order_id, %user_id);
    let _enter = span.enter();

    info!("Starting order processing"); 
    if let Err(e) = validate_payment(order_id) {
        error!(error = %e, "Payment failed");
    }
}

fn validate_payment(order_id: u64) -> Result<(), String> {
    // I don't need to manually log the order_id here; 
    // the span from the caller already has it.
    info!("Checking credit card validity");
    Err("Insufficient funds".to_string())
}

Notice the syntax %order_id. That's a shorthand in tracing that tells the library to use the Display trait to record the value. The magic here is that the log "Starting order processing" isn't just a string; it's a structured event. When this hits a collector like Jaeger or an ELK stack, it's stored as JSON: {"message": "Starting order processing", "order_id": 123, "user_id": 456}. You can now filter by order_id == 123 without caring what the actual text of the message is.

The Cost of Observability

You might be wondering if this is overkill or if it tanks performance. The trade-off is that tracing does slightly more work upfront to track the current span context. However, it's designed to be extremely efficient. Because tracing separates the recording of the event from the formatting of the event (which is handled by a "Subscriber"), you can change how your logs look—or even turn off specific fields—without changing a single line of your business logic.

I've found that the mental shift from "writing messages" to "emitting events with context" is the single biggest jump in maturity a developer can make when moving from a small CLI tool to a distributed system. You stop guessing what happened and start querying the facts.

📋 Practical Task

Implementing Order Processing Spans for a Payment Gateway

You are tasked with improving the observability of a payment gateway module. Currently, the code uses basic info! logs that make it impossible to track a single transaction across multiple function calls.

Your Goal: Refactor the following code to use a tracing::info_span!. Ensure that the transaction_id and amount are attached to the span so that they are automatically included in all logs within the process_transaction and authorize_funds functions, without having to explicitly pass them into the info! macros inside authorize_funds.

use tracing::{info, info_span};

fn authorize_funds() {
    // TODO: This log should automatically include transaction_id and amount via a span
    info!("Contacting banking API for authorization...");
}

fn process_transaction(transaction_id: &str, amount: f64) {
    // TODO: Wrap the following logic in a span named "payment_gateway"
    info!("Beginning transaction processing");
    authorize_funds();
    info!("Transaction completed successfully");
}

fn main() {
    // Assume a tracing subscriber is already initialized
    process_transaction("tx-999", 49.99);
}

Requirements:

• Create a span named "payment_gateway".
• Attach transaction_id and amount as fields to that span.
• Use .enter() to ensure authorize_funds() is executed within the context of that span.
• Remove any manual variable interpolation from the info! calls if they are now provided by the span.