Trace an async request handler with fibre_tracing

For Rust developers who already use `tracing` and want to read their spans back

You will instrument a small async request handler, collect each request as a trace with fibre_tracing and print it as a waterfall of timed spans. A failing request then shows its own trace on an error page.

Before you start

You need Rust with Cargo. fibre_tracing comes from crates.io:

fibre_tracing = "0"

Set up the project#

Start a new binary crate.

cargo new traced_handler
cd traced_handler

Add fibre_tracing, the tracing crates it plugs into and tokio for the async runtime. Your [dependencies] section should look like this:

Cargo.toml

[dependencies]
fibre_tracing = "0"
tracing = "0.1"
tracing-subscriber = "0.3"
tokio = { version = "1", features = ["macros", "rt", "time"] }

fibre_tracing is a tracing_subscriber layer. It never installs itself as the global subscriber, so you put it on a registry yourself at the top of main.

Collect your first trace#

A trace starts at a span that carries the field fibre.root = true. Every span opened inside it joins the trace. Replace src/main.rs with this:

src/main.rs

use tracing_subscriber::layer::SubscriberExt;
use tracing_subscriber::util::SubscriberInitExt;

#[tokio::main(flavor = "current_thread")]
async fn main() {
    let (layer, traces) = fibre_tracing::layer();
    tracing_subscriber::registry().with(layer).init();

    handle("/users/7").await;

    for trace in traces.recent(10) {
        let root = trace.root().unwrap();
        println!("trace {} {} took {:?}", trace.id, root.name, trace.duration);
    }
}

#[tracing::instrument(fields(fibre.root = true))]
async fn handle(path: &str) {
    tokio::time::sleep(std::time::Duration::from_millis(5)).await;
}

fibre_tracing::layer() returns two things: the layer you install and a Traces handle you read through. When the root span closes, the finished trace goes into a ring of recent traces (256 by default). recent(n) hands back the last n of them, newest last.

$ cargo run
trace 1 handle took 7.592083ms

Your timings will differ from the ones shown in this tutorial. Trace ids start at 1 and count up in the order roots open.

Add child spans and print a waterfall#

A real handler does several things. This one authenticates, loads a user from a pretend database and renders a page. Each step gets its own span. The database call records how many rows it returned once it knows.

The root is now an explicit info_span! rather than an attribute, because the next section records a field on it after the handler body has finished. Replace src/main.rs with the whole program:

src/main.rs

use std::time::Duration;

use fibre_tracing::Trace;
use tokio::time::sleep;
use tracing::Instrument;
use tracing::field::Empty;
use tracing_subscriber::layer::SubscriberExt;
use tracing_subscriber::util::SubscriberInitExt;

#[tokio::main(flavor = "current_thread")]
async fn main() {
    let (layer, traces) = fibre_tracing::layer();
    tracing_subscriber::registry().with(layer).init();

    let response = handle("/users/7").await;
    println!("/users/7 -> {response:?}");

    println!();
    for trace in traces.recent(10) {
        print_waterfall(&trace);
    }
}

async fn handle(path: &str) -> Result<String, String> {
    let root = tracing::info_span!("request", fibre.root = true, path);
    route(path).instrument(root).await
}

async fn route(path: &str) -> Result<String, String> {
    authenticate().await;
    let id: u64 = path.trim_start_matches("/users/").parse().map_err(|_| "bad id".to_string())?;
    let name = load_user(id).await?;
    Ok(render(&name).await)
}

#[tracing::instrument]
async fn authenticate() {
    sleep(Duration::from_millis(2)).await;
}

#[tracing::instrument]
async fn load_user(id: u64) -> Result<String, String> {
    match query("select name from users where id = ?", id).await {
        Some(name) => Ok(name),
        None => Err(format!("no user {id}")),
    }
}

async fn query(sql: &'static str, id: u64) -> Option<String> {
    let span = tracing::info_span!("db.query", sql, rows = Empty);
    async {
        sleep(Duration::from_millis(8)).await;
        let row = (id == 7).then(|| "Ada".to_string());
        tracing::Span::current().record("rows", row.is_some() as u64);
        row
    }
    .instrument(span)
    .await
}

#[tracing::instrument(skip(name))]
async fn render(name: &str) -> String {
    sleep(Duration::from_millis(3)).await;
    format!("<h1>{name}</h1>")
}

fn print_waterfall(trace: &Trace) {
    println!("trace {} ({:.1}ms)", trace.id, trace.duration.as_secs_f64() * 1000.0);
    for span in &trace.spans {
        println!(
            "{:>6.1}ms {:<18} {:>5.1}ms {}",
            span.at.as_secs_f64() * 1000.0,
            format!("{}{}", "  ".repeat(span.depth), span.name),
            span.duration.as_secs_f64() * 1000.0,
            span.outcome().unwrap_or(""),
        );
    }
}

trace.spans lists the spans in the order they opened, root first. Each Span already knows its depth, when it opened relative to the root (at) and how long it stayed open (duration), so print_waterfall is a plain loop with no tree to walk.

$ cargo run
/users/7 -> Ok("<h1>Ada</h1>")

trace 1 (20.2ms)
   0.0ms request             20.2ms
   0.0ms   authenticate       3.8ms
   3.8ms   load_user         11.3ms
   3.8ms     db.query        11.3ms
  15.2ms   render             5.0ms

The db.query span sits one level under load_user because it opened inside it. The right-hand column is empty for now; it prints each span's outcome, which you add next.

Record outcomes and add an error path#

fibre_tracing reads a field called fibre.outcome as the result of a span. Span::outcome() returns it. Declare the field as Empty when the span opens and record it once you know the answer.

Change handle to hold on to the root span and record the outcome after the body returns:

src/main.rs

async fn handle(path: &str) -> Result<String, String> {
    let root = tracing::info_span!("request", fibre.root = true, path, fibre.outcome = Empty);
    let result = route(path).instrument(root.clone()).await;
    root.record("fibre.outcome", if result.is_ok() { "ok" } else { "failed" });
    result
}

The root is still open at that point because handle holds root. It closes when root drops at the end of the function. That close is what finishes the trace.

Give load_user its own outcome so a missing row shows up as not_found on the span that caused it:

src/main.rs

#[tracing::instrument(fields(fibre.outcome = Empty))]
async fn load_user(id: u64) -> Result<String, String> {
    let span = tracing::Span::current();
    match query("select name from users where id = ?", id).await {
        Some(name) => {
            span.record("fibre.outcome", "ok");
            Ok(name)
        }
        None => {
            span.record("fibre.outcome", "not_found");
            Err(format!("no user {id}"))
        }
    }
}

Then send two requests from main, one for a user that exists and one for a user that does not:

src/main.rs

#[tokio::main(flavor = "current_thread")]
async fn main() {
    let (layer, traces) = fibre_tracing::layer();
    tracing_subscriber::registry().with(layer).init();

    for path in ["/users/7", "/users/404"] {
        let response = handle(path).await;
        println!("{path} -> {response:?}");
    }

    println!();
    for trace in traces.recent(10) {
        print_waterfall(&trace);
        println!();
    }
}

$ cargo run
/users/7 -> Ok("<h1>Ada</h1>")
/users/404 -> Err("no user 404")

trace 1 (20.2ms)
   0.0ms request             20.2ms ok
   0.0ms   authenticate       3.8ms
   3.8ms   load_user         11.3ms ok
   3.9ms     db.query        11.3ms
  15.2ms   render             5.0ms

trace 2 (15.2ms)
   0.0ms request             15.2ms failed
   0.0ms   authenticate       3.8ms
   3.9ms   load_user         11.4ms not_found
   3.9ms     db.query        11.3ms

The failed request has no render span because route returned early with ?. You can see where it stopped and which step reported the problem.

Read a span's fields#

Every field a span recorded is kept in span.fields, a map from field name to fibre_tracing::Value. That includes fields recorded after the span opened, such as rows. Trace::named finds every span of a given name.

Add this to the end of main:

src/main.rs

    for trace in traces.recent(10) {
        let path = &trace.root().unwrap().fields["path"];
        for span in trace.named("db.query") {
            println!("{path}: rows={} sql={}", span.fields["rows"], span.fields["sql"]);
        }
    }

cargo run

The waterfalls print as before, followed by:

/users/7: rows=1 sql=select name from users where id = ?
/users/404: rows=0 sql=select name from users where id = ?

Value implements Display, so string fields print without quotes and numbers print as numbers. This is also how a test can assert on what a handler actually did: run it, take the trace and check the spans and fields it recorded.

Show the trace on an error page#

Everything so far read finished traces from the ring. Traces::current() returns the trace the current span belongs to while it is still running, with the spans that have opened so far. That is what an error page in development wants: the steps this request took before it failed.

Import Traces alongside Trace:

src/main.rs

use fibre_tracing::{Trace, Traces};

Make handle take the Traces handle and return a response body. On failure it builds the error page while still inside the root span:

src/main.rs

async fn handle(traces: &Traces, path: &str) -> String {
    let root = tracing::info_span!("request", fibre.root = true, path, fibre.outcome = Empty);
    match route(path).instrument(root.clone()).await {
        Ok(body) => {
            root.record("fibre.outcome", "ok");
            body
        }
        Err(err) => {
            root.record("fibre.outcome", "failed");
            root.in_scope(|| error_page(traces, &err))
        }
    }
}

fn error_page(traces: &Traces, err: &str) -> String {
    let mut page = format!("error: {err}\n");
    if let Some(trace) = traces.current() {
        for span in &trace.spans {
            let took = if span.duration.is_zero() {
                "still open".to_string()
            } else {
                format!("{:.1}ms", span.duration.as_secs_f64() * 1000.0)
            };
            page.push_str(&format!("  {}{} {took}\n", "  ".repeat(span.depth), span.name));
        }
    }
    page
}

current() looks at the span you are in, which is why the call sits inside root.in_scope. Outside any root it returns None. A span that has not closed yet has a duration of zero. Here that is the root itself.

In main, pass the handle and print the body as a string:

src/main.rs

    for path in ["/users/7", "/users/404"] {
        let response = handle(&traces, path).await;
        println!("{path} -> {response}");
    }

$ cargo run
/users/7 -> <h1>Ada</h1>
/users/404 -> error: no user 404
  request still open
    authenticate 3.8ms
    load_user 11.4ms
      db.query 11.3ms

The waterfalls and field lines follow as before.

Export failed traces with a listener#

A listener registered with on_finish is called with each trace as its root closes, before the trace goes into the ring. At that point the whole request is known, so you can decide what to send to an exporter based on how it went. Here the "exporter" is a println! that fires only for requests that failed or took longer than 50ms.

src/main.rs

    traces.on_finish(|trace| {
        let root = trace.root().unwrap();
        let failed = root.outcome() != Some("ok");
        let slow = trace.duration > Duration::from_millis(50);
        if failed || slow {
            println!(
                "[export] trace {} {} {} in {:.1}ms",
                trace.id,
                root.fields["path"],
                root.outcome().unwrap_or("no outcome"),
                trace.duration.as_secs_f64() * 1000.0,
            );
        }
    });

$ cargo run
/users/7 -> <h1>Ada</h1>
[export] trace 2 /users/404 failed in 15.3ms
/users/404 -> error: no user 404
  request still open
    authenticate 3.8ms
    load_user 11.4ms
      db.query 11.4ms


trace 1 (19.8ms)
   0.0ms request             19.8ms ok
   0.0ms   authenticate       3.8ms
   3.9ms   load_user         10.8ms ok
   3.9ms     db.query        10.8ms
  14.7ms   render             5.1ms

trace 2 (15.3ms)
   0.0ms request             15.3ms failed
   0.0ms   authenticate       3.8ms
   3.9ms   load_user         11.4ms not_found
   3.9ms     db.query        11.4ms

/users/7: rows=1 sql=select name from users where id = ?
/users/404: rows=0 sql=select name from users where id = ?

The [export] line prints before the error page. The listener runs on the thread that closes the root. The root closes when handle returns, before main gets to print the response. Keep listeners quick for that reason: a slow one delays every request that finishes.

If a process only exports and never reads the ring, fibre_tracing::with_ring(0) keeps no finished traces and still calls listeners.

Where to go next#

The usage guide on GitHub covers sizing the ring, composing the layer beside a log sink such as fibre_logging and running it next to tracing-opentelemetry: https://github.com/excsn/fibre/tree/main/tracing

The full API, including of_span for reading a trace from a span id, is on docs.rs: https://docs.rs/fibre_tracing