Skip to content
Learn Rust
Theme

Logging with tracing

tracing is a Rust framework for logging and diagnostics, developed in the tokio-rs organisation on GitHub. Like Go’s log/slog, Python’s structlog or C#’s Serilog, it records structured fields, not just text. It adds spans, which tag every log line inside a piece of work, such as one request.

RememberLog with info!(field = value, "message"). Wrap a piece of work in a span to tag everything inside it.

Project layout
logging/
├── src/
│   └── main.rs                 the program on this page
├── Cargo.lock                  created by Cargo
└── Cargo.toml                  dependencies go here
RustCargo.toml
[package]
name = "logging"
version = "0.1.0"
edition = "2024"


[dependencies]
tracing = "0.1.44"
tracing-subscriber = "0.3.23"
Rustsrc/main.rs
use tracing::{info, info_span, warn};


fn main() {
    // Print events to the terminal. without_time() keeps this page's output stable.
    tracing_subscriber::fmt()
        .without_time()
        .with_target(false)
        .init();


    info!(port = 3000, "server starting");


    let span = info_span!("request", method = "GET", path = "/notes");
    let _guard = span.enter(); // everything until _guard is dropped is inside the span
    info!(count = 2, "listed notes");
    warn!(user = "ana", "slow response");
}
$ cargo run
 INFO server starting port=3000
 INFO request{method="GET" path="/notes"}: listed notes count=2
 WARN request{method="GET" path="/notes"}: slow response user="ana"
Gomain.go
package main


import (
  "log/slog"
  "os"
)


func main() {
  // Drop the time so this page's output stays stable.
  logger := slog.New(slog.NewTextHandler(os.Stdout, &slog.HandlerOptions{
    ReplaceAttr: func(groups []string, a slog.Attr) slog.Attr {
      if a.Key == slog.TimeKey {
        return slog.Attr{}
      }
      return a
    },
  }))


  logger.Info("server starting", "port", 3000)


  req := logger.With("method", "GET", "path", "/notes")
  req.Info("listed notes", "count", 2)
  req.Warn("slow response", "user", "ana")
}
$ go run .
level=INFO msg="server starting" port=3000
level=INFO msg="listed notes" method=GET path=/notes count=2
level=WARN msg="slow response" method=GET path=/notes user=ana
  • Two crates: tracing is what your code and libraries call; tracing-subscriber decides where the output goes. The tracing docs say libraries should link only to tracing and leave the subscriber to the executable, and that a library should not install one itself, because that conflicts with the executable’s. So only your main sets one up.
  • Fields are name = value before the message. Use ?value to record a value with its Debug format and %value for its Display format (Printing and Formatting covers both traits). Numbers, booleans and strings need neither (id and title below).
  • Spans are like logger.With(...) in slog, since both attach fields to the lines logged through them (a span tags the lines logged while it is entered). A span also knows when the work starts and ends. Those moments are not logged unless you ask the subscriber to (see below), and a span entered with enter() exits when its guard is dropped.

By default the formatter puts a timestamp at the start of every line and writes to stdout. This page’s program calls without_time() so that its output is the same on every run (and with_target(false) to leave out the module path). Here is the default, with the timestamp swapped for a fixed word by sed (the command also has -q to hide Cargo’s own lines and 2>/dev/null, which shows the log lines are on stdout):

Rustsrc/main.rs
use tracing::info;


fn main() {
    // No without_time(): every line starts with the time it was logged.
    tracing_subscriber::fmt().with_target(false).init();


    info!(port = 3000, "server starting");
}
$ cargo run | sed ... # the timestamp replaced by <timestamp>
<timestamp>  INFO server starting port=3000

Fields, spans and #[instrument]

Section titled “Fields, spans and #[instrument]”

This program logs plain fields, ? and % fields, two spans inside each other, and a function with #[tracing::instrument], which makes a span named after the function, with its arguments as fields (the docs say types that do not implement Value are recorded using fmt::Debug). with_span_events adds a line each time a span is entered and exited:

Rustsrc/main.rs
use std::fmt;


use tracing::{info, info_span, instrument};
use tracing_subscriber::fmt::format::FmtSpan;


#[derive(Debug)]
struct Note {
    id: u32,
    title: &'static str,
}


struct Email(&'static str);


impl fmt::Display for Email {
    fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result {
        write!(f, "{}", self.0)
    }
}


// Every argument becomes a field on a span that lasts for the call.
#[instrument]
fn find_note(id: u32, owner: &str) -> Option<Note> {
    info!("looking up");
    if id == 1 { Some(Note { id, title: "milk" }) } else { None }
}


fn main() {
    tracing_subscriber::fmt()
        .without_time()
        .with_target(false)
        // also log a line each time a span is entered and exited
        .with_span_events(FmtSpan::ENTER | FmtSpan::EXIT)
        .init();


    let note = Note { id: 7, title: "call Ana" };
    info!(id = note.id, title = note.title, "plain values");
    info!(?note, email = %Email("[email protected]"), tags = ?["a", "b"], "Debug and Display");


    {
        let outer = info_span!("outer", user = "ana");
        let _outer = outer.enter();
        let inner = info_span!("inner", step = 2);
        let _inner = inner.enter();
        info!("inside both");
    }
    info!("outside");


    find_note(1, "ana");
    find_note(2, "bo");
}
$ cargo run
 INFO plain values id=7 title="call Ana"
 INFO Debug and Display note=Note { id: 7, title: "call Ana" } [email protected] tags=["a", "b"]
 INFO outer{user="ana"}: enter
 INFO outer{user="ana"}:inner{step=2}: enter
 INFO outer{user="ana"}:inner{step=2}: inside both
 INFO outer{user="ana"}:inner{step=2}: exit
 INFO outer{user="ana"}: exit
 INFO outside
 INFO find_note{id=1 owner="ana"}: enter
 INFO find_note{id=1 owner="ana"}: looking up
 INFO find_note{id=1 owner="ana"}: exit
 INFO find_note{id=2 owner="bo"}: enter
 INFO find_note{id=2 owner="bo"}: looking up
 INFO find_note{id=2 owner="bo"}: exit

The inner span exits first: guards are dropped in the reverse of the order they were made (Ownership covers drop order). Every line inside both spans carries both sets of fields, outer first.

In async code, do not hold the guard from span.enter() across an .await. The docs for Span say it gives an incorrect trace, because another task can then run while your span is still entered. They point to Span::in_scope for a synchronous section and the Instrument trait for a future, and the instrument docs say async fns can carry the attribute. No async example was run for this page; Async with Tokio covers the runtime.

Choosing levels at runtime

Section titled “Choosing levels at runtime”

The RUST_LOG variable picks which levels are shown, if you ask for it. Turn on tracing-subscriber’s env-filter feature (cargo add tracing-subscriber --features env-filter; see Finding and using crates) and pass an EnvFilter to the builder:

Rust
[package]
name = "logging"
version = "0.1.0"
edition = "2024"


[dependencies]
tracing = "0.1.44"
tracing-subscriber = { version = "0.3.23", features = ["env-filter"] }
terminal
$ cargo run
 INFO server starting port=3000
 WARN slow response user="ana"
$ RUST_LOG=debug cargo run
DEBUG cache miss key="notes"
 INFO server starting port=3000
 WARN slow response user="ana"
$ RUST_LOG=warn cargo run
 WARN slow response user="ana"

Two details came from running it. The feature alone is not enough: the builder in the first program does not read RUST_LOG (with the feature on, RUST_LOG=debug still hid a debug! line), hence with_env_filter. And an EnvFilter made with from_default_env from an unset RUST_LOG shows only errors (the docs say a default directive enabling the ERROR level is added; with the feature on, fmt::init() printed an ERROR event and no info, warn or debug line when I ran it). try_from_default_env, which this program uses, returns an error when the variable is unset instead, so the program falls back to info. The directive syntax can also filter by module.

The same job in your language

Section titled “The same job in your language”

The table lists libraries and where they come from, checked against each project’s own page. It is not a ranking.

Language Common choices Part of the language’s own libraries?
Go log/slog Yes. log/slog records a message, a level and key-value attributes; it is the Go program above.
Python logging, structlog logging is in the standard library; structlog is a separate package.
TypeScript pino, winston They are npm packages. Node has console built in.
Java SLF4J with Logback Both are separate libraries. The JDK has its own System.Logger.
Kotlin kotlin-logging A library. Its README says the JVM artifact depends on slf4j-api.
C# ILogger (.NET logging), Serilog Not the base library: the Microsoft Learn page has you add the Microsoft.Extensions.Logging package, which has ILogger. Serilog is a separate library.
C syslog A POSIX function that sends a message to the system logger.
C++ spdlog A third-party library.

Only the Go row was run as a logging program; the gotcha below runs a different example, ending a scope, in the other languages.

Try it yourself

Section titled “Try it yourself”

Nothing checks these for you. Each one was run in the image behind this page, and the output shown is what it printed.

  1. Change the level. Run the env program above with no variable, then as RUST_LOG=debug cargo run and as RUST_LOG=warn cargo run. With debug the cache miss line appears first; with warn only the slow response line is left.

  2. Read the exits. In the spans output above, find the exit lines for outer and inner. inner exits first, then outer.

  3. Break the span. In the first program, change let _guard to let _. It compiles, and the request{...} tags vanish from the last two lines. The gotcha below is the same mistake with a lock, where rustc refuses it:

    Rustsrc/main.rs
    use tracing::{info, info_span, warn};
    

    fn main() {
        // Print events to the terminal. without_time() keeps this page's output stable.
        tracing_subscriber::fmt()
            .without_time()
            .with_target(false)
            .init();
    

        info!(port = 3000, "server starting");
    

        let span = info_span!("request", method = "GET", path = "/notes");
        let _ = span.enter();
        info!(count = 2, "listed notes");
        warn!(user = "ana", "slow response");
    }
    $ cargo run
     INFO server starting port=3000
 INFO listed notes count=2
 WARN slow response user="ana"

Read more

Section titled “Read more”
Gotcha

let _ = instead of let _guard =

Looks fine: in Go, Python, TypeScript, Java, C# and C++ it runs but gives a wrong answer. Rust won't compile it.

Broken in Go. Rust catches it.No direct equivalent in Kotlin. Just a Rust rule.Broken in Python. Rust catches it.Broken in TypeScript. Rust catches it.Broken in Java. Rust catches it.Broken in C#. Rust catches it.No direct equivalent in C. Just a Rust rule.Broken in C++. Rust catches it.
Rustsrc/main.rs✗ won't compile
use std::sync::Mutex;


fn main() {
    let counter = Mutex::new(0);


    // Meant to hold the lock for the rest of main.
    let _ = counter.lock().unwrap();


    println!("lock is held: {}", counter.try_lock().is_err());
}
package main


import "fmt"


type Span struct{ name string }


func Start(name string) *Span {
  fmt.Println("enter", name)
  return &Span{name}
}


func (s *Span) End() { fmt.Println("exit", s.name) }


func handle() {
  span := Start("request")
  defer span.End() // runs when handle returns
  fmt.Println("listed notes")
}


func main() {
  handle()
  _ = Start("forgotten") // `_` throws the *Span away; nothing ever calls End
  fmt.Println("after")
}
$ go run main.go! runs · wrong answer
enter request
listed notes
exit request
enter forgotten
after
class Span(private val name: String) : AutoCloseable {
    init { println("enter $name") }
    override fun close() { println("exit $name") }
}


fun main() {
    Span("request").use { println("listed notes") } // close() runs when the block ends
    Span("forgotten") // nothing ever calls close()
    println("after")
}
$ kotlinc Main.kt -include-runtime -d main.jar && java -jar main.jarno equivalent
enter request
listed notes
exit request
enter forgotten
after
class Span:
    def __init__(self, name):
        self.name = name


    def __enter__(self):
        print("enter", self.name)
        return self


    def __exit__(self, *exc):
        print("exit", self.name)




with Span("request"):
    print("listed notes")  # __exit__ runs when the with block ends


_ = Span("forgotten").__enter__()  # nothing ever calls __exit__
print("after")
$ python3 main.py! runs · wrong answer
enter request
listed notes
exit request
enter forgotten
after
class Span implements Disposable {
  name: string;


  constructor(name: string) {
    this.name = name;
    console.log("enter", name);
  }


  [Symbol.dispose]() {
    console.log("exit", this.name);
  }
}


{
  using span = new Span("request");
  console.log("listed notes"); // [Symbol.dispose] runs when the block ends
}
new Span("forgotten"); // nothing ever calls [Symbol.dispose]
console.log("after");
$ tsc --strict --module nodenext --types node main.ts && node main.js! runs · wrong answer
enter request
listed notes
exit request
enter forgotten
after
public class Main {
    static class Span implements AutoCloseable {
        private final String name;


        Span(String name) {
            this.name = name;
            System.out.println("enter " + name);
        }


        @Override
        public void close() {
            System.out.println("exit " + name);
        }
    }


    public static void main(String[] args) {
        try (Span span = new Span("request")) {
            System.out.println("listed notes"); // close() runs when the block ends
        }
        new Span("forgotten"); // nothing ever calls close()
        System.out.println("after");
    }
}
$ javac Main.java && java Main! runs · wrong answer
enter request
listed notes
exit request
enter forgotten
after
using System;


class Span : IDisposable
{
    private readonly string name;


    public Span(string name)
    {
        this.name = name;
        Console.WriteLine("enter " + name);
    }


    public void Dispose() => Console.WriteLine("exit " + name);
}


class Program
{
    static void Main()
    {
        using (var span = new Span("request"))
        {
            Console.WriteLine("listed notes"); // Dispose() runs when the block ends
        }
        _ = new Span("forgotten"); // `_` discards it; nothing ever calls Dispose
        Console.WriteLine("after");
    }
}
$ dotnet run! runs · wrong answer
enter request
listed notes
exit request
enter forgotten
after
Cno equivalent

Not run here. Standard C has no destructors, so no value ends anything when it goes away: you call the cleanup function yourself.

#include <iostream>
#include <string>


struct Span {
    std::string name;
    explicit Span(std::string n) : name(std::move(n)) { std::cout << "enter " << name << "\n"; }
    ~Span() { std::cout << "exit " << name << "\n"; }
};


int main() {
    {
        Span span("request");  // a named object lives to the end of the block
        std::cout << "listed notes\n";
    }
    {
        Span("temporary");  // no name: destroyed at the end of this statement
        std::cout << "listed notes\n";
    }
}
$ g++ -std=c++20 -Wall -Wextra main.cpp -o main && ./main! runs · wrong answer
enter request
listed notes
exit request
enter temporary
exit temporary
listed notes
What does the compiler say? Guess first, then open.
$ cargo build
error: non-binding let on a synchronization lock
 --> src/main.rs:7:9
  |
7 |     let _ = counter.lock().unwrap();
  |         ^ this lock is not assigned to a binding and is immediately dropped
  |
  = note: `#[deny(let_underscore_lock)]` (part of `#[deny(let_underscore)]`) on by default
help: consider binding to an unused variable to avoid immediately dropping the value
  |
7 |     let _unused = counter.lock().unwrap();
  |          ++++++
help: consider immediately dropping the value
  |
7 -     let _ = counter.lock().unwrap();
7 +     drop(counter.lock().unwrap());
What happens in Go

_ = Start(...) throws the pointer away and nothing calls End. What closes a scope in Go is defer, which runs when the function returns, not when a value goes away.

What happens in Kotlin

There is no val _ = ... form to show: in the Kotlin version in the image it does not compile without an experimental flag. Kotlin closes a resource with use, at the end of its block. A value you just create, like Span("forgotten") in the program shown, is never closed.

What happens in Python

with calls __exit__ at the end of its block. Calling __enter__ yourself and keeping the result in _ never calls __exit__.

What happens in TypeScript

A using declaration calls [Symbol.dispose] at the end of its block. An object that is only created is never disposed. Node 24 ran this file directly; it was not type-checked.

What happens in Java

try with a resource calls close() at the end of its block. An object that is only created is never closed.

What happens in C#

using calls Dispose() at the end of its block. _ = new Span(...) discards the object and never disposes it.

What happens in C

Not run here. Standard C has no destructors, so no value ends anything when it goes away: you call the cleanup function yourself.

What happens in C++

C++ has the same trap. A named object lives to the end of its block. A temporary with no name is destroyed at the end of its statement, so exit temporary prints before listed notes.

What Rust sees

let _ = counter.lock().unwrap(); does not bind the guard to any name, so it is dropped at the end of that statement and the lock is released at once. rustc has a lint for exactly this, let_underscore_lock, which is deny by default, so Rust refuses to compile it. A name like _guard keeps the guard alive until the end of the block.

Why Rust says no

The lint exists for lock guards only. The same mistake with another guard is not caught: let _ = span.enter(); compiles, and only the output tells you, because the span exits before the next log line (Try it yourself, task 3, shows that output). The other languages below show the scope version of the trap with a span-like object.

The fix

Compiles and runs.

Rust, fixedsrc/main.rsRun ↗
use std::sync::Mutex;


fn main() {
    let counter = Mutex::new(0);


    // A name, even one starting with an underscore, keeps the guard alive to the end of main.
    let _guard = counter.lock().unwrap();


    println!("lock is held: {}", counter.try_lock().is_err());
}
$ cargo run
lock is held: true

Learn Rust is an independent project, not affiliated with the Rust Project or the Rust Foundation. Code and text are under the MIT licence.Source on GitHub.