Structured Logging and Spans with `tracing`

24 min read

Quick Overview

tracing is Rust’s structured, context-aware diagnostics framework — the natural step up from the log facade once your program is asynchronous, concurrent, or producing logs that a machine has to read. Instead of flat lines of text, tracing records events (a point in time) that happen inside spans (a period of time, like “handling this request”), so every log line automatically carries the structured context of where it came from. For a TypeScript/JavaScript developer this is the Rust equivalent of moving from console.log strings to a structured logger like pino plus the request-scoped context you would otherwise thread through with AsyncLocalStorage.

Note: tracing and the log crate interoperate. Libraries can keep emitting log records and your application can capture them through tracing (shown later), so adopting tracing is never an all-or-nothing rewrite. If you only need simple level-filtered text logs, start with log + env_logger; reach for tracing when you need spans, async context, or JSON.

TypeScript/JavaScript Example

A realistic Node service wants two things flat console.log cannot easily give: structured fields (so a log aggregator can index orderId) and request-scoped context (so every line emitted while handling one order is tagged with that order’s id, even across await points). Teams reach for pino for the first and AsyncLocalStorage for the second:

1
// orders.ts — structured logging with pino + request context via AsyncLocalStorage
2
import pino from "pino";
3
import { AsyncLocalStorage } from "node:async_hooks";
4

5
const log = pino({ level: process.env.LOG_LEVEL ?? "info" });
6

7
// Holds per-request context that should appear on every log line.
8
const requestContext = new AsyncLocalStorage<{ orderId: number; userId: number }>();
9

10
function ctxLog() {
11
  // Merge the active request context into each log call.
12
  const store = requestContext.getStore();
13
  return store ? log.child(store) : log;
14
}
15

16
async function processOrder(orderId: number, userId: number, amountCents: number): Promise<void> {
17
  // Everything awaited inside this callback sees the same context.
18
  await requestContext.run({ orderId, userId }, async () => {
19
    ctxLog().info("processing order");
20

21
    if (amountCents === 0) {
22
      ctxLog().error("empty cart");
23
      return;
24
    }
25

26
    ctxLog().debug({ gateway: "stripe" }, "submitting charge");
27
    await new Promise((r) => setTimeout(r, 5)); // simulate async I/O
28

29
    if (amountCents > 1_000_000) {
30
      ctxLog().warn({ threshold: 1_000_000 }, "charge exceeds manual-review threshold");
31
    }
32

33
    ctxLog().info({ txnId: 0xabcd }, "charge confirmed");
34
  });
35
}
36

37
await processOrder(1001, 42, 4_999);

Two things stand out. First, pino emits structured JSON where fields like orderId are real keys, not interpolated into a string. Second, AsyncLocalStorage is the only way to make context “follow” the logic across await without manually passing it to every function. Rust’s tracing gives you both — structured fields and span context that survives .await — as first-class, compiler-checked features.

Rust Equivalent

Add the framework (tracing) and a subscriber that decides what to do with the data (tracing-subscriber). The env-filter feature gives you RUST_LOG-style filtering:

1
cargo add tracing
2
cargo add tracing-subscriber --features env-filter

1
use tracing::{debug, error, info, instrument, warn};
2
use tracing_subscriber::EnvFilter;
3

4
#[derive(Debug)]
5
struct Order {
6
    id: u64,
7
    amount_cents: u64,
8
}
9

10
#[derive(Debug)]
11
enum CheckoutError {
12
    EmptyCart,
13
}
14

15
// `#[instrument]` wraps the function body in a span. `skip(order)` keeps the
16
// whole struct out of the span; `fields(...)` records just the parts we want.
17
#[instrument(skip(order), fields(order_id = order.id, amount = order.amount_cents))]
18
fn process_order(order: &Order, user_id: u64) -> Result<u64, CheckoutError> {
19
    info!("processing order");
20

21
    if order.amount_cents == 0 {
22
        error!("empty cart");
23
        return Err(CheckoutError::EmptyCart);
24
    }
25

26
    debug!(gateway = "stripe", "submitting charge");
27

28
    if order.amount_cents > 1_000_000 {
29
        warn!(threshold = 1_000_000, "charge exceeds manual-review threshold");
30
    }
31

32
    let txn_id = 0xABCD;
33
    info!(txn_id, "charge confirmed");
34
    Ok(txn_id)
35
}
36

37
fn main() {
38
    // Install a subscriber: text output, RUST_LOG override, default "info".
39
    tracing_subscriber::fmt()
40
        .with_env_filter(
41
            EnvFilter::try_from_default_env().unwrap_or_else(|_| EnvFilter::new("info")),
42
        )
43
        .init();
44

45
    let orders = [
46
        (Order { id: 1001, amount_cents: 4_999 }, 42u64),
47
        (Order { id: 1002, amount_cents: 0 }, 43),
48
        (Order { id: 1003, amount_cents: 5_000_000 }, 44),
49
    ];
50

51
    for (order, user_id) in &orders {
52
        match process_order(order, *user_id) {
53
            Ok(txn) => info!(txn, "order completed"),
54
            Err(e) => warn!(error = ?e, "order rejected"),
55
        }
56
    }
57
}

Running it produces real, span-tagged output (the timestamps and the process_order{...} prefix are emitted automatically):

1
$ cargo run
2
2026-06-02T06:29:35.618823Z  INFO process_order{user_id=42 order_id=1001 amount=4999}: probe: processing order
3
2026-06-02T06:29:35.618840Z  INFO process_order{user_id=42 order_id=1001 amount=4999}: probe: charge confirmed txn_id=43981
4
2026-06-02T06:29:35.618863Z  INFO probe: order completed txn=43981
5
2026-06-02T06:29:35.619681Z  INFO process_order{user_id=43 order_id=1002 amount=0}: probe: processing order
6
2026-06-02T06:29:35.619699Z ERROR process_order{user_id=43 order_id=1002 amount=0}: probe: empty cart
7
2026-06-02T06:29:35.619710Z  WARN probe: order rejected error=EmptyCart
8
2026-06-02T06:29:35.619721Z  INFO process_order{user_id=44 order_id=1003 amount=5000000}: probe: processing order
9
2026-06-02T06:29:35.619727Z  WARN process_order{user_id=44 order_id=1003 amount=5000000}: probe: charge exceeds manual-review threshold threshold=1000000
10
2026-06-02T06:29:35.620940Z  INFO process_order{user_id=44 order_id=1003 amount=5000000}: probe: charge confirmed txn_id=43981
11
2026-06-02T06:29:35.621000Z  INFO probe: order completed txn=43981

Notice what came for free: every line emitted inside process_order is automatically prefixed with process_order{user_id=… order_id=… amount=…} — the span context — while the order completed / order rejected lines emitted from main are not, because they are outside the span. That is the Rust analogue of AsyncLocalStorage, but achieved by one attribute and checked at compile time. The default fmt subscriber colorizes this output in a terminal; piped to a file (as above) it is plain text.

Detailed Explanation

Events vs. spans: the core idea

tracing has two primitives, and grasping the distinction is the whole game:

An event is a single moment — the direct equivalent of one console.log/info! call. You emit events with the event! macro or the level shortcuts error!, warn!, info!, debug!, trace! (deliberately the same names as the log crate).
A span represents a period of time with a beginning and an end — “while we were handling request 7”, “while this DB query ran”. A span can have fields (structured key-values), and while a span is entered, every event recorded — and every child span opened — is associated with it.

In Node you simulate span context with AsyncLocalStorage; in tracing it is the foundational data model. A span is opened, entered (made the current context), exited, and eventually closed.

Structured fields, not string interpolation

Each macro accepts structured fields before the message:

1
use tracing::info;
2

3
fn main() {
4
    tracing_subscriber::fmt().init();
5
    let txn_id = 0xABCDu64;
6
    info!(txn_id, gateway = "stripe", "charge confirmed");
7
}

txn_id uses field shorthand: a bare identifier records a field named txn_id with that variable’s value (the same ergonomic capture you get in format!("{txn_id}")).
gateway = "stripe" records an explicit key-value pair.
The final string literal is the event’s message field.

Fields are captured by their Display representation by default. Two sigils change that:

?value captures via Debug (info!(order = ?order) records the #[derive(Debug)] form).
%value captures via Display explicitly (useful when the default would otherwise pick something else).

This is why the order example wrote warn!(error = ?e, ...): CheckoutError has a Debug impl but no Display, so ?e selects Debug.

`#[instrument]`: a span for a whole function

The #[instrument] attribute is the most ergonomic way to create spans. It wraps the function body in a span named after the function and records every argument as a field automatically. That convenience comes with a constraint and some knobs:

Because arguments become fields, each argument type must implement Debug — or you must exclude it. skip(order) drops an argument from the span entirely (essential for large structs, secrets, or non-Debug types).
fields(order_id = order.id) adds computed fields, letting you record order.id even though you skipped the whole order.
It works on async fn too — and there it does something .enter() alone cannot do correctly, covered next.

Spans and `async`: why `.enter()` is not enough

This is the single most important async subtlety. A naive approach uses a span guard:

1
use tracing::info_span;
2

3
fn sync_work() {
4
    let span = info_span!("work");
5
    let _guard = span.enter(); // guard exits the span when dropped
6
    // ... synchronous work; every event here is inside "work" ...
7
}

For synchronous code this is correct. For async code it is wrong: if the future yields at an .await while the guard is held, the span stays “entered” on that thread while a different task runs there — leaking context across tasks. The fix is to attach the span to the future so it is entered only while that future is actively polled:

1
use tracing::{info, info_span, Instrument};
2

3
async fn fetch(id: u64) -> String {
4
    // The `Instrument` trait adds `.instrument(span)` to any future.
5
    async {
6
        info!("fetching");
7
        format!("user-{id}")
8
    }
9
    .instrument(info_span!("fetch", id))
10
    .await
11
}

#[instrument] on an async fn does exactly this for you, which is why it is the recommended default for async functions. The takeaway: use #[instrument] (or .instrument(span)), not a bare span.enter(), inside async.

Recording fields after the fact

Sometimes a field’s value is unknown when the span opens. Declare it as empty and fill it in later:

1
use tracing::{field, info, info_span};
2

3
fn run() {
4
    let span = info_span!("db_query", table = "orders", rows = field::Empty);
5
    let _guard = span.enter();
6
    info!("executing query");
7
    let row_count = 17;
8
    span.record("rows", row_count); // now the span carries rows=17
9
    info!("query finished");
10
}

Real output:

1
2026-06-02T06:30:24.683965Z  INFO db_query{table="orders"}: probe: executing query
2
2026-06-02T06:30:24.684439Z  INFO db_query{table="orders" rows=17}: probe: query finished

field::Empty reserves the slot; record populates it. (A field never declared on the span cannot be recorded later.)

Subscriber, layers, and `init()`

Like log, tracing separates emitting data from consuming it. The consumer is a Subscriber; until one is installed as the default, every event and span is a cheap no-op. tracing_subscriber::fmt() builds the common case — a subscriber that formats events to stderr. The more composable form is a Registry with layers stacked on top:

1
use tracing_subscriber::{fmt, prelude::*, EnvFilter};
2

3
fn main() {
4
    tracing_subscriber::registry()
5
        .with(EnvFilter::new("info"))      // filtering layer
6
        .with(fmt::layer())                 // formatting layer
7
        .init();
8
}

A Layer is a composable piece of subscriber behavior — a formatter, a filter, an OpenTelemetry exporter, a metrics collector. You stack the ones you need. This layering is tracing’s superpower over log: you can send the same events to a human-readable console and a JSON file and a distributed-tracing backend simultaneously.

`EnvFilter` and `RUST_LOG`

EnvFilter understands the same RUST_LOG directive grammar as env_logger, including per-module targets:

1
$ RUST_LOG=info cargo run
2
2026-06-02T06:33:47.384482Z  INFO probe: app started
3
2026-06-02T06:33:47.384533Z  INFO probe::db: running query
4

5
$ RUST_LOG="warn,probe::db=debug" cargo run
6
2026-06-02T06:33:47.872126Z  INFO probe::db: running query
7
2026-06-02T06:33:47.872164Z DEBUG probe::db: connection pool: 3/10 in use

The second invocation sets a global floor of warn (silencing the top-level info!/debug!) while raising the probe::db module to debug — independent dials per subsystem, exactly as with env_logger. EnvFilter additionally supports span-aware filtering (e.g. [span_name]=level) that env_logger cannot express.

Key Differences

Concern	Node.js (`pino` + `AsyncLocalStorage`)	Rust (`tracing` + `tracing-subscriber`)
Primitive	Log calls; context via `AsyncLocalStorage`	Events (points) and spans (periods) as first-class data
Structured fields	`log.info({ key }, "msg")`	`info!(key = value, "msg")` — typed, compiler-checked
Request context across `await`	Manual `AsyncLocalStorage.run`	`#[instrument]` / `.instrument(span)` — automatic
Backend selection	Pick `pino`/`winston` at import	Install one `Subscriber`; stack composable `Layer`s
Output formats	JSON (pino) or pretty (`pino-pretty`)	Pretty, compact, or JSON via `fmt` layer; swap freely
Filtering	`level` option / transport config	`EnvFilter` with `RUST_LOG` grammar + span filters
Cost when disabled	You guard expensive work yourself	Disabled spans/events compile to near-nothing
Interop with other loggers	N/A	Captures `log`-crate records via `tracing-log`

The mental shift: in Node, “context that follows execution” is a bolt-on (AsyncLocalStorage) and structured logging is a library choice (pino). In Rust, both are the native data model — a span is the context, and fields are structured by construction.

Note: tracing is the foundation of Rust’s observability story, not just logging. The same spans you emit for logs can be exported to distributed-tracing systems (Jaeger, Tempo, any OpenTelemetry backend) by adding a layer — no code change to your info! calls. That is why async-heavy crates like tokio, hyper, and axum are instrumented with tracing out of the box.

Common Pitfalls

Forgetting to install a subscriber

The most common surprise mirrors the log facade: events compile fine but produce no output because no subscriber was installed.

1
use tracing::info;
2

3
fn main() {
4
    // No subscriber installed — every event is a silent no-op.
5
    info!("you will never see this");
6
    println!("program finished");
7
}

1
$ RUST_LOG=trace cargo run
2
program finished

This is by design (libraries must stay silent when no consumer is present). The fix is one line early in main: tracing_subscriber::fmt().init();.

Using `span.enter()` inside `async`

Holding a span guard across an .await is the classic tracing bug. It compiles and may even look right in single-task tests, but under real concurrency the span leaks onto whatever task happens to be polled next. Clippy will not catch this for you: unlike a std::sync::MutexGuard (which clippy::await_holding_lock flags), a tracing span’s Entered guard is not detected, so this stays a silent logic bug.

The rule is simple: never hold a span.enter() guard across .await. Use #[instrument] on the async fn, or attach the span to the future with .instrument(span). Both enter the span only while the future is actively polled.

Spawned tasks do not inherit the current span

tokio::spawn starts an independent task; the new future does not automatically inherit the span that was current at the spawn site. The result is a log line missing its request context:

1
use tracing::{info, info_span, Instrument};
2

3
#[tokio::main]
4
async fn main() {
5
    tracing_subscriber::fmt().with_max_level(tracing::Level::INFO).init();
6

7
    let span = info_span!("request", request_id = "req-001");
8
    let _enter = span.enter();
9

10
    // BUG: the spawned task does NOT inherit the current span.
11
    let bug = tokio::spawn(async {
12
        info!("work in spawned task (no span)");
13
    });
14

15
    // FIX: capture the current span and attach it to the future before spawning.
16
    let fixed = tokio::spawn(
17
        async {
18
            info!("work in spawned task (span attached)");
19
        }
20
        .in_current_span(),
21
    );
22

23
    bug.await.unwrap();
24
    fixed.await.unwrap();
25
}

1
2026-06-02T06:31:26.089010Z  INFO probe: work in spawned task (no span)
2
2026-06-02T06:31:26.089085Z  INFO request{request_id="req-001"}: probe: work in spawned task (span attached)

The first line lost its request_id; the second kept it. The fix is .in_current_span() (or .instrument(span)) on the future passed to tokio::spawn.

`#[instrument]` requires `Debug` on every captured argument

Because #[instrument] records arguments as fields, each argument type must implement Debug. Forgetting this produces a real compiler error:

1
use tracing::instrument;
2

3
struct Connection {
4
    _handle: u64,
5
}
6

7
#[instrument] // does not compile (error[E0277]: `Connection` doesn't implement `Debug`)
8
fn run_query(conn: &Connection, sql: &str) {
9
    println!("{sql}");
10
    let _ = conn;
11
}
12

13
fn main() {
14
    tracing_subscriber::fmt().init();
15
    run_query(&Connection { _handle: 1 }, "SELECT 1");
16
}

The real message:

1
error[E0277]: `Connection` doesn't implement `Debug`
2
  --> src/main.rs:7:1
3
   |
4
 7 | #[instrument]
5
   | ^^^^^^^^^^^^^ the trait `Debug` is not implemented for `Connection`
6
   |
7
   = note: add `#[derive(Debug)]` to `Connection` or manually `impl Debug for Connection`
8
   = note: required for `&Connection` to implement `Debug`

Two fixes: #[instrument(skip(conn))] to exclude the argument, or #[derive(Debug)] on Connection. Always skip large structs, secrets, and database connections.

Installing the subscriber after the first events

tracing_subscriber’s init() sets the global default. Any event emitted before that call is dropped silently. Initialize the subscriber at the very top of main, before anything else logs.

Calling `init()` twice

Like installing a global logger, the global default subscriber can be set only once. A second init() (or two components racing to install one) panics with SetGlobalDefaultError. Use try_init() and handle the Result when something else might also initialize.

Best Practices

Libraries depend only on tracing; the binary installs the subscriber. Exactly like the log facade convention — a reusable crate emits spans and events and never picks a subscriber. (See popular-crates.md for where tracing sits in the ecosystem.)
Initialize the subscriber once, at the top of main. Prefer tracing_subscriber::fmt().with_env_filter(...).init() for simple apps, or a layered registry() when you need multiple outputs.
Default to #[instrument] for functions worth tracing. Add skip(...) for big or sensitive arguments and fields(...) for the specific values you want. On async fn, it is the correct way to scope a span across .await.
Never hold a span.enter() guard across .await. Use #[instrument] or .instrument(span) instead.
Propagate context into spawned tasks with .in_current_span() or .instrument(span).
Pick the right level. error! for failures an operator must act on; warn! for recoverable anomalies; info! for lifecycle/request events; debug! for developer diagnostics; trace! for high-volume detail.
Use EnvFilter with a sensible default (e.g. EnvFilter::new("info") when RUST_LOG is unset) so a fresh checkout shows useful output.
Emit JSON in production, pretty text in development. Drive the choice from configuration; the rest of your instrumentation does not change.
Bridge the log crate with the tracing-log feature so records from dependencies that use log (and there are many) appear in your unified pipeline.

JSON Logs

Production log aggregators (Loki, Elasticsearch, Datadog, CloudWatch) want newline-delimited JSON, not pretty text — the same reason Node services run pino in JSON mode. tracing-subscriber produces it with the json feature:

1
cargo add tracing-subscriber --features env-filter,json

1
use tracing::{info, instrument, warn};
2
use tracing_subscriber::{fmt, prelude::*, EnvFilter};
3

4
#[derive(Debug)]
5
struct Job {
6
    id: u64,
7
    payload_bytes: usize,
8
}
9

10
#[instrument(skip(job), fields(job_id = job.id, bytes = job.payload_bytes))]
11
async fn process_job(job: &Job) -> bool {
12
    info!("job started");
13
    if job.payload_bytes > 1_000 {
14
        warn!(limit = 1_000, "payload exceeds size limit");
15
        return false;
16
    }
17
    info!("job completed");
18
    true
19
}
20

21
#[tokio::main]
22
async fn main() {
23
    let filter = EnvFilter::try_from_default_env().unwrap_or_else(|_| EnvFilter::new("info"));
24
    tracing_subscriber::registry()
25
        .with(filter)
26
        // The JSON layer emits one line of newline-delimited JSON per event.
27
        .with(fmt::layer().json().with_current_span(true).with_span_list(false))
28
        .init();
29

30
    for job in &[Job { id: 1, payload_bytes: 512 }, Job { id: 2, payload_bytes: 8_192 }] {
31
        process_job(job).await;
32
    }
33
}

Real output — one JSON object per line, with the active span’s fields nested under "span":

1
{"timestamp":"2026-06-02T06:32:35.279209Z","level":"INFO","fields":{"message":"job started"},"target":"probe","span":{"bytes":512,"job_id":1,"name":"process_job"}}
2
{"timestamp":"2026-06-02T06:32:35.279285Z","level":"INFO","fields":{"message":"job completed"},"target":"probe","span":{"bytes":512,"job_id":1,"name":"process_job"}}
3
{"timestamp":"2026-06-02T06:32:35.279310Z","level":"INFO","fields":{"message":"job started"},"target":"probe","span":{"bytes":8192,"job_id":2,"name":"process_job"}}
4
{"timestamp":"2026-06-02T06:32:35.279323Z","level":"WARN","fields":{"message":"payload exceeds size limit","limit":1000},"target":"probe","span":{"bytes":8192,"job_id":2,"name":"process_job"}}

Each line is valid JSON your aggregator can index by level, target, span.job_id, or any custom field. Useful knobs on the JSON formatter:

.with_current_span(true) — include the immediately-active span’s fields under "span".
.with_span_list(true) — include the full stack of open spans under "spans" (set false, as above, when you only want the leaf).
.flatten_event(true) — lift the event’s own fields to the top level instead of nesting them under "fields".

The decisive advantage over Node here is that you flip between human-readable and JSON output by swapping one layer — your info!/#[instrument] instrumentation is identical in both modes.

Real-World Example

A production-flavored batch worker: each job runs inside its own span (so a log search by job_id reconstructs that job’s entire lifecycle), spans nest to show causality, and the subscriber is a composable registry honoring RUST_LOG. The validate step is its own child span, demonstrating the nesting that flat logging cannot express.

1
cargo add tracing
2
cargo add tracing-subscriber --features env-filter
3
cargo add tokio --features rt-multi-thread,macros,time

1
use std::time::Duration;
2
use tracing::{error, info, instrument, warn};
3
use tracing_subscriber::{fmt, prelude::*, EnvFilter};
4

5
#[derive(Debug)]
6
struct Job {
7
    id: u64,
8
    payload_bytes: usize,
9
}
10

11
#[derive(Debug)]
12
enum JobError {
13
    TooLarge,
14
}
15

16
/// Process a single job. The span carries `job_id`; every event emitted while
17
/// this function (and anything it calls) runs is tagged with that context.
18
#[instrument(skip(job), fields(job_id = job.id, bytes = job.payload_bytes))]
19
async fn process_job(job: &Job) -> Result<(), JobError> {
20
    info!("job started");
21

22
    if job.payload_bytes > 1_000 {
23
        error!(limit = 1_000, "payload exceeds size limit");
24
        return Err(JobError::TooLarge);
25
    }
26

27
    validate(job).await;
28

29
    tokio::time::sleep(Duration::from_millis(2)).await; // simulate work
30
    info!("job completed");
31
    Ok(())
32
}
33

34
#[instrument(skip(job), fields(job_id = job.id))]
35
async fn validate(job: &Job) {
36
    if job.payload_bytes == 0 {
37
        warn!("empty payload, treating as no-op");
38
    }
39
    info!("validated");
40
}
41

42
#[tokio::main]
43
async fn main() {
44
    // Compose a layered subscriber: a filter layer + a text fmt layer.
45
    // RUST_LOG overrides the "info" default if set.
46
    let filter = EnvFilter::try_from_default_env().unwrap_or_else(|_| EnvFilter::new("info"));
47
    tracing_subscriber::registry()
48
        .with(filter)
49
        .with(fmt::layer().with_target(false))
50
        .init();
51

52
    info!(worker = "batch-1", "worker online");
53

54
    let jobs = [
55
        Job { id: 1, payload_bytes: 512 },
56
        Job { id: 2, payload_bytes: 0 },
57
        Job { id: 3, payload_bytes: 8_192 },
58
    ];
59

60
    let mut ok = 0u32;
61
    let mut failed = 0u32;
62
    for job in &jobs {
63
        match process_job(job).await {
64
            Ok(()) => ok += 1,
65
            Err(e) => {
66
                warn!(error = ?e, job_id = job.id, "job failed");
67
                failed += 1;
68
            }
69
        }
70
    }
71

72
    info!(ok, failed, "batch finished");
73
}

Real output (with_target(false) drops the probe: column to reduce noise):

1
2026-06-02T06:31:46.616151Z  INFO worker online worker="batch-1"
2
2026-06-02T06:31:46.616314Z  INFO process_job{job_id=1 bytes=512}: job started
3
2026-06-02T06:31:46.616328Z  INFO process_job{job_id=1 bytes=512}:validate{job_id=1}: validated
4
2026-06-02T06:31:46.620742Z  INFO process_job{job_id=1 bytes=512}: job completed
5
2026-06-02T06:31:46.620937Z  INFO process_job{job_id=2 bytes=0}: job started
6
2026-06-02T06:31:46.621000Z  WARN process_job{job_id=2 bytes=0}:validate{job_id=2}: empty payload, treating as no-op
7
2026-06-02T06:31:46.621055Z  INFO process_job{job_id=2 bytes=0}:validate{job_id=2}: validated
8
2026-06-02T06:31:46.623881Z  INFO process_job{job_id=2 bytes=0}: job completed
9
2026-06-02T06:31:46.623980Z  INFO process_job{job_id=3 bytes=8192}: job started
10
2026-06-02T06:31:46.624009Z ERROR process_job{job_id=3 bytes=8192}: payload exceeds size limit limit=1000
11
2026-06-02T06:31:46.624039Z  WARN job failed error=TooLarge job_id=3
12
2026-06-02T06:31:46.624055Z  INFO batch finished ok=2 failed=1

The nesting process_job{...}:validate{...}: is the payoff: a log line from deep inside validate still tells you which job it belongs to, with zero manual context-passing. Swap fmt::layer() for fmt::layer().json() and the very same instrumentation produces machine-readable logs for your aggregator — the instrumentation is the asset, the output format is a configuration choice.

Capturing the `log` crate into `tracing`

Many dependencies emit log-crate records rather than tracing events. Enable the tracing-log feature so tracing_subscriber’s init() installs the bridge automatically, and those records flow into the same pipeline:

1
cargo add tracing-subscriber --features env-filter,tracing-log
2
cargo add log

1
use tracing::info;
2
use tracing_subscriber::fmt::format::FmtSpan;
3

4
#[tracing::instrument]
5
fn unit_of_work(n: u64) {
6
    info!("doing work");
7
    std::thread::sleep(std::time::Duration::from_millis(3));
8
}
9

10
fn main() {
11
    // With the `tracing-log` feature on, `init()` also installs the
12
    // log -> tracing bridge, so plain `log` records flow into this pipeline.
13
    tracing_subscriber::fmt()
14
        .with_max_level(tracing::Level::INFO)
15
        // Emit a synthetic event when each span closes, including its busy time.
16
        .with_span_events(FmtSpan::CLOSE)
17
        .init();
18

19
    log::info!("hello from the log crate"); // a record via the plain `log` facade
20
    unit_of_work(7);
21
}

1
2026-06-02T06:32:22.591891Z  INFO probe: hello from the log crate
2
2026-06-02T06:32:22.591946Z  INFO unit_of_work{n=7}: probe: doing work
3
2026-06-02T06:32:22.595853Z  INFO unit_of_work{n=7}: probe: close time.busy=3.87ms time.idle=34.2µs

Two things to note: the log::info! record appears alongside native events, and FmtSpan::CLOSE adds a close line reporting how long the span was busy (actively on a thread) versus idle (suspended at an .await) — free, accurate timing for every instrumented function.

Warning: Do not also call tracing_log::LogTracer::init() yourself when the subscriber’s tracing-log feature is enabled — both try to install the global log logger, and the second one panics with SetLoggerError. Let init() handle the bridge.

Exercises

Exercise 1: Predict the span context

Difficulty: Beginner

Objective: Cement the events-inside-spans mental model and the no-subscriber-means-silence rule.

Instructions: Consider the program below. Without running it, answer: (a) what is printed if you remove the tracing_subscriber::fmt().init() line entirely? (b) With the subscriber present, which of the two info! lines will carry the outer{user="ada"} span context, and which will not? Then run it to confirm.

1
use tracing::{info, info_span};
2

3
fn main() {
4
    tracing_subscriber::fmt().init();
5

6
    info!("before span");
7
    let span = info_span!("outer", user = "ada");
8
    {
9
        let _guard = span.enter();
10
        info!("inside span");
11
    }
12
    info!("after span");
13
}

Solution

(a) With no subscriber installed, every event is a silent no-op: the program prints nothing at all (it does not even error).

(b) Only "inside span" is emitted while the span guard is held, so only it carries the outer{user="ada"} prefix. "before span" (guard not yet created) and "after span" (guard already dropped at the end of the inner block) are outside the span. Real output:

1
2026-06-02T06:58:04.991510Z  INFO probe: before span
2
2026-06-02T06:58:04.991558Z  INFO outer{user="ada"}: probe: inside span
3
2026-06-02T06:58:04.991567Z  INFO probe: after span

The lesson: a span is a period delimited by when it is entered and exited; only events within that period inherit its fields. (This span.enter() guard pattern is correct here precisely because the code is synchronous — never hold such a guard across .await.)

Exercise 2: Capture return values and errors automatically

Difficulty: Intermediate

Objective: Use #[instrument]’s ret and err arguments to record outcomes without writing explicit info!/error! calls, and learn the Display-vs-Debug requirement for err.

Instructions: Write a function parse_amount(input: &str) -> Result<u64, ParseError> that parses a u64, returning a custom ParseError enum (deriving Debug but not Display) on failure. Instrument it so the Ok value is logged on success and the error is logged at ERROR level on failure. First try #[instrument(ret, err)], observe the compiler error, then fix it. Call it once with "4999" and once with "oops".

Solution

#[instrument(ret, err)] fails to compile because err records the error via Display by default, and ParseError does not implement Display:

1
error[E0277]: `ParseError` doesn't implement `std::fmt::Display`
2
  --> src/main.rs:8:1
3
   |
4
 8 | #[instrument(ret, err)]
5
   | ^^^^^^^^^^^^^^^^^^^^^^^ the trait `std::fmt::Display` is not implemented for `ParseError`

The fix is err(Debug), which records the error via its Debug impl instead:

1
use tracing::instrument;
2

3
#[derive(Debug)]
4
enum ParseError {
5
    NotANumber,
6
}
7

8
// `ret` logs the Ok value at the span's level; `err(Debug)` logs the Err via
9
// Debug at ERROR level. Plain `err` would require a `Display` impl.
10
#[instrument(ret, err(Debug))]
11
fn parse_amount(input: &str) -> Result<u64, ParseError> {
12
    input.parse::<u64>().map_err(|_| ParseError::NotANumber)
13
}
14

15
fn main() {
16
    tracing_subscriber::fmt()
17
        .with_max_level(tracing::Level::INFO)
18
        .init();
19

20
    let _ = parse_amount("4999");
21
    let _ = parse_amount("oops");
22
}

Real output:

1
2026-06-02T06:33:03.883288Z  INFO parse_amount{input="4999"}: probe: return=4999
2
2026-06-02T06:33:03.883316Z ERROR parse_amount{input="oops"}: probe: error=NotANumber

ret produced the return=4999 event; err(Debug) produced the ERROR-level error=NotANumber event — both automatically, with no manual logging inside the function body.

Exercise 3: Propagate request context into a spawned task and emit JSON

Difficulty: Advanced

Objective: Combine #[instrument], async span propagation across tokio::spawn, and a JSON subscriber — the realistic shape of production request logging.

Instructions: Write an async handle(request_id: u64, path: &str) instrumented so its span records request_id. Inside it, log a “request received” event, then tokio::spawn a background subtask that logs “processing in background task” and must still carry the request_id context, then log “request complete”. Configure a JSON subscriber (layered registry() with an EnvFilter defaulting to info). Call handle(42, "/orders").await. Verify the background task’s JSON line includes request_id.

Solution

1
cargo add tracing
2
cargo add tracing-subscriber --features env-filter,json
3
cargo add tokio --features rt-multi-thread,macros

1
use tracing::{info, instrument, Instrument};
2
use tracing_subscriber::{fmt, prelude::*, EnvFilter};
3

4
#[instrument(fields(request_id = %request_id))]
5
async fn handle(request_id: u64, path: &str) {
6
    info!(path, "request received");
7

8
    // Offload a subtask to another tokio task, carrying the span with it
9
    // via `.in_current_span()` so it keeps the request_id context.
10
    let child = tokio::spawn(
11
        async {
12
            info!("processing in background task");
13
        }
14
        .in_current_span(),
15
    );
16
    child.await.unwrap();
17

18
    info!("request complete");
19
}
20

21
#[tokio::main]
22
async fn main() {
23
    let filter = EnvFilter::try_from_default_env().unwrap_or_else(|_| EnvFilter::new("info"));
24
    tracing_subscriber::registry()
25
        .with(filter)
26
        .with(fmt::layer().json().with_current_span(true).with_span_list(false))
27
        .init();
28

29
    handle(42, "/orders").await;
30
}

Real output (three JSON lines, all tagged with request_id):

1
{"timestamp":"2026-06-02T06:33:31.948971Z","level":"INFO","fields":{"message":"request received","path":"/orders"},"target":"probe","span":{"path":"/orders","request_id":"42","name":"handle"}}
2
{"timestamp":"2026-06-02T06:33:31.949095Z","level":"INFO","fields":{"message":"processing in background task"},"target":"probe","span":{"path":"/orders","request_id":"42","name":"handle"}}
3
{"timestamp":"2026-06-02T06:33:31.949160Z","level":"INFO","fields":{"message":"request complete"},"target":"probe","span":{"path":"/orders","request_id":"42","name":"handle"}}

The middle line — emitted from a different tokio task — still carries "request_id":"42" because .in_current_span() attached the span to the spawned future. Remove .in_current_span() and that line loses its context entirely, the exact bug from the Common Pitfalls section. This combination — #[instrument] for the request span, .in_current_span()/.instrument() for spawned work, and a JSON layer — is the backbone of production-grade request logging in Rust.

Structured Logging and Spans with tracing

Quick Overview

TypeScript/JavaScript Example

Rust Equivalent

Detailed Explanation

Events vs. spans: the core idea

Structured fields, not string interpolation

#[instrument]: a span for a whole function

Spans and async: why .enter() is not enough

Recording fields after the fact

Subscriber, layers, and init()

EnvFilter and RUST_LOG

Key Differences

Common Pitfalls

Forgetting to install a subscriber

Using span.enter() inside async

Spawned tasks do not inherit the current span

#[instrument] requires Debug on every captured argument

Installing the subscriber after the first events

Calling init() twice

Best Practices

JSON Logs

Real-World Example

Capturing the log crate into tracing

Further Reading

Exercises

Exercise 1: Predict the span context

Exercise 2: Capture return values and errors automatically

Exercise 3: Propagate request context into a spawned task and emit JSON

Structured Logging and Spans with `tracing`

`#[instrument]`: a span for a whole function

Spans and `async`: why `.enter()` is not enough

Subscriber, layers, and `init()`

`EnvFilter` and `RUST_LOG`

Using `span.enter()` inside `async`

`#[instrument]` requires `Debug` on every captured argument

Calling `init()` twice

Capturing the `log` crate into `tracing`