Logging in Rust mit log und tracing

Wenn in einem Programm etwas schiefgeht, willst du wissen, was es kurz vorher gemacht hat. Genau dafür gibt es Logging (Protokollierung). Ein Log ist wie ein Logbuch auf einem Schiff: kurze Notizen, jede mit Uhrzeit und einer Wichtigkeitsstufe, die du später liest, um zu verstehen, was passiert ist.

Du könntest überall println! verteilen, aber da stößt du schnell an Grenzen. Du kannst es nicht abschalten, ohne den Code zu ändern. Du kannst nicht sagen „zeig mir nur die Warnungen“. Und es vermischt deine Debug-Notizen mit der eigentlichen Ausgabe des Programms. Die Logging-Crates von Rust lösen alle drei Probleme. Auf dieser Seite lernst du die zwei beliebtesten kennen: log (mit env_logger) und tracing.

Warum nicht einfach println!?

Hier ist der Unterschied auf einen Blick:

	println!	ein Logging-Crate
An- und abschalten ohne neu zu kompilieren	Nein	Ja, mit der Variable RUST_LOG
Stufen (error, warn, info, …)	Nein	Ja
Zeigt, woher die Meldung kommt	Nein	Ja (den Modulnamen)
Wohin die Ausgabe geht	stdout	standardmäßig stderr (env_logger)

Die letzte Zeile ist wichtiger, als sie aussieht. stdout ist das eigentliche Ergebnis deines Programms – das, was jemand vielleicht in eine Datei oder ein anderes Programm umleitet. stderr ist der Nebenkanal für Meldungen über den Lauf. Logs gehören nach stderr. Dann speichert my_app > result.txt nur das Ergebnis, und die Logs erscheinen trotzdem im Terminal.

Die Fassade log und env_logger

Das Crate log gibt dir fünf Makros, eines pro Stufe, vom ernstesten zum unwichtigsten: error!, warn!, info!, debug! und trace!. Sie funktionieren genau wie println! – mit derselben {}-Formatierung.

Aber log allein gibt gar nichts aus. Es ist eine Fassade: ein Standardsatz von Makros, den jede Bibliothek benutzen kann, ohne festzulegen, wie die Meldungen angezeigt werden. Deine Anwendung wählt einen Logger, der sie tatsächlich ausgibt. Der einfachste ist env_logger. Füge beide zu deinem Projekt hinzu:

cargo add log env_logger

[dependencies]
log = "0.4"
env_logger = "0.11"

Jetzt rufst du einmal am Anfang von main env_logger::init() auf und kannst loslegen:

use log::{debug, error, info, warn};

fn divide(a: f64, b: f64) -> Option<f64> {
    debug!("divide aufgerufen mit a={a}, b={b}");
    if b == 0.0 {
        warn!("weigere mich, {a} durch null zu teilen");
        return None;
    }
    Some(a / b)
}

fn main() {
    env_logger::init();
    info!("Rechner startet");

    println!("10 / 4 = {:?}", divide(10.0, 4.0));
    println!("1 / 0 = {:?}", divide(1.0, 0.0));

    error!("so sieht eine Fehlerzeile aus");
}

Ausgabe:

10 / 4 = Some(2.5)
1 / 0 = None

▶ Selbst ausprobieren

Die Ausgabe oben ist nur stdout – das eigentliche Ergebnis des Programms. Die Log-Zeilen gehen nach stderr. Im Playground erscheinen sie im separaten Bereich „Standard Error“.

Fällt dir etwas auf? Standardmäßig zeigt env_logger nur Fehler. Wenn du mehr sehen willst, setzt du beim Start des Programms die Umgebungsvariable RUST_LOG. So sahen stderr und stdout zusammen aus, als wir das Programm im Terminal mit RUST_LOG=debug cargo run ausgeführt haben (jeden Zeitstempel haben wir durch … ersetzt – bei dir stehen dort das aktuelle Datum und die Uhrzeit):

[… INFO  my_app] Rechner startet
[… DEBUG my_app] divide aufgerufen mit a=10, b=4
10 / 4 = Some(2.5)
[… DEBUG my_app] divide aufgerufen mit a=1, b=0
[… WARN  my_app] weigere mich, 1 durch null zu teilen
1 / 0 = None
[… ERROR my_app] so sieht eine Fehlerzeile aus

Jede Log-Zeile zeigt die Stufe und das Modul, aus dem sie stammt (my_app, der Name des Crates). Die einfachen Zeilen ohne eckige Klammern sind die Ausgabe von println!.

Mit RUST_LOG auswählen, was du siehst

Eine Stufe zeigt diese Stufe und alles Ernstere. RUST_LOG=warn zeigt also Warnungen und Fehler, RUST_LOG=trace zeigt alles.

RUST_LOG=debug cargo run     # debug, info, warn, error
RUST_LOG=warn cargo run      # nur warn und error
RUST_LOG=off cargo run       # gar keine Logs

In der Windows PowerShell setzt du die Variable zuerst: $env:RUST_LOG="debug"; cargo run.

Du kannst auch nach Modul filtern. Das ist super, wenn eine Bibliothek zu gesprächig ist oder dich nur ein Teil deines Codes interessiert. Hier ist ein Programm mit einem Modul db:

use log::{debug, info};

mod db {
    use log::{debug, trace};

    pub fn find_user(id: u32) -> Option<&'static str> {
        trace!("suche Benutzer {id}");
        let name = match id {
            1 => Some("Ada"),
            2 => Some("Linus"),
            _ => None,
        };
        debug!("Ergebnis der Suche: {name:?}");
        name
    }
}

fn main() {
    env_logger::init();
    info!("Server startet");

    for id in [1, 3] {
        match db::find_user(id) {
            Some(name) => println!("Benutzer {id}: {name}"),
            None => println!("Benutzer {id}: nicht gefunden"),
        }
    }

    debug!("alle Suchen erledigt");
}

Ausgabe:

Benutzer 1: Ada
Benutzer 3: nicht gefunden

▶ Selbst ausprobieren

Ein paar Filter, die wir ausprobiert haben, und was sie nach stderr geschrieben haben (Zeitstempel durch … ersetzt):

$ RUST_LOG=my_app=trace cargo run       # alles aus unserem Crate
[… INFO  my_app] Server startet
[… TRACE my_app::db] suche Benutzer 1
[… DEBUG my_app::db] Ergebnis der Suche: Some("Ada")
Benutzer 1: Ada
[… TRACE my_app::db] suche Benutzer 3
[… DEBUG my_app::db] Ergebnis der Suche: None
Benutzer 3: nicht gefunden
[… DEBUG my_app] alle Suchen erledigt

$ RUST_LOG=my_app::db=debug cargo run   # nur das Modul db, ab debug
[… DEBUG my_app::db] Ergebnis der Suche: Some("Ada")
Benutzer 1: Ada
[… DEBUG my_app::db] Ergebnis der Suche: None
Benutzer 3: nicht gefunden

Du kannst Regeln mit Kommas kombinieren: RUST_LOG=info,my_app::db=trace bedeutet „info für alles, aber trace für das Modul db“. Eine kleine Falle: Der Filter benutzt den Crate-Namen mit Unterstrichen. Ein Paket namens my-app loggt als my_app.

Eine Standardstufe im Code festlegen

Oft willst du, dass info auch dann erscheint, wenn RUST_LOG nicht gesetzt ist. Dafür nimmst du statt init() den env_logger::Builder. Du kannst auch den Zeitstempel abschalten, was bei kleinen Werkzeugen praktisch ist:

use env_logger::Env;
use log::{debug, info};

fn main() {
    // `info` und höher anzeigen, außer RUST_LOG sagt etwas anderes.
    env_logger::Builder::from_env(Env::default().default_filter_or("info"))
        .format_timestamp(None)
        .init();

    info!("App gestartet");
    debug!("das siehst du nur mit RUST_LOG=debug");

    let total: u32 = (1..=10).sum();
    println!("Summe = {total}");
}

Ausgabe:

Summe = 55

▶ Selbst ausprobieren

Ohne Zeitstempel ist das echte stderr von cargo run kurz und übersichtlich:

[INFO  my_app] App gestartet

Strukturiertes Logging mit tracing

log liefert dir Textzeilen. tracing liefert dir Ereignisse mit Daten, gruppiert in Spans. Es wurde vom Tokio-Team gebaut, und asynchrone Web-Frameworks wie axum benutzen es. Du fügst es so hinzu:

cargo add tracing tracing-subscriber

Drei Ideen musst du kennen:

• Events (Ereignisse) sind wie Log-Zeilen: info!, warn! und Co., mit denselben Namen wie in log.
• Felder hängen Daten als key = value an: info!(user_id = 42, "angemeldet"). Werkzeuge können nach diesen Feldern suchen und filtern, statt Text zu zerlegen.
• Spans beschreiben einen Zeitraum, in dem gearbeitet wird, zum Beispiel „Bestellung 7 bearbeiten“. Jedes Event innerhalb eines Spans wird mit ihm markiert.

Wie log braucht auch tracing einen Subscriber, damit überhaupt etwas angezeigt wird. tracing_subscriber::fmt() ist der Standard-Subscriber. Eine Überraschung: Er schreibt standardmäßig nach stdout, deshalb leiten wir ihn mit .with_writer(std::io::stderr) nach stderr um:

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

fn main() {
    tracing_subscriber::fmt()
        .with_writer(std::io::stderr)
        .init();

    info!(user_id = 42, "angemeldet");

    let span = info_span!("checkout", order_id = 7);
    let _guard = span.enter();

    let items = [1200, 350, 999];
    let total: u32 = items.iter().sum();
    info!(items = items.len(), total, "Warenkorb summiert");

    if total > 2000 {
        warn!(total, limit = 2000, "Bestellung muss von Hand geprüft werden");
    }

    println!("Bestellsumme: {total}");
}

Ausgabe:

Bestellsumme: 2549

▶ Selbst ausprobieren

Hier ist stderr aus unserem Lauf (Zeitstempel durch … ersetzt, Farben entfernt):

…  INFO my_app: angemeldet user_id=42
…  INFO checkout{order_id=7}: my_app: Warenkorb summiert items=3 total=2549
…  WARN checkout{order_id=7}: my_app: Bestellung muss von Hand geprüft werden total=2549 limit=2000

Siehst du, dass die letzten beiden Zeilen mit checkout{order_id=7} beginnen? Das ist der Span. Solange _guard lebt, findet jedes Event „innerhalb“ des Checkouts statt. Nur total zu schreiben ist eine Kurzform für total = total.

#[instrument]: ein Span für jeden Aufruf

Spans von Hand anzulegen wird schnell mühsam. Setz #[instrument] auf eine Funktion, und tracing legt für jeden Aufruf einen Span an. Die Argumente werden dabei als Felder aufgezeichnet (sie müssen Debug implementieren):

use tracing::{debug, info, instrument};

#[instrument]
fn apply_discount(price: u32, percent: u32) -> u32 {
    let off = price * percent / 100;
    debug!(off, "Rabatt berechnet");
    price - off
}

fn main() {
    tracing_subscriber::fmt()
        .with_max_level(tracing::Level::DEBUG)
        .with_writer(std::io::stderr)
        .init();

    let final_price = apply_discount(2500, 10);
    info!(final_price, "fertig");
    println!("Endpreis: {final_price}");
}

Ausgabe:

Endpreis: 2250

▶ Selbst ausprobieren

stderr aus unserem Lauf:

… DEBUG apply_discount{price=2500 percent=10}: my_app: Rabatt berechnet off=250
…  INFO my_app: fertig final_price=2250

Der Subscriber fmt() zeigt info und höher, solange du ihm nichts anderes sagst – deshalb haben wir .with_max_level(tracing::Level::DEBUG) gesetzt. Wenn RUST_LOG so funktionieren soll wie bei env_logger, schalte das Feature env-filter ein und benutze EnvFilter:

[dependencies]
tracing = "0.1"
tracing-subscriber = { version = "0.3", features = ["env-filter"] }

use tracing_subscriber::EnvFilter;

tracing_subscriber::fmt()
    .with_env_filter(EnvFilter::from_default_env())
    .with_writer(std::io::stderr)
    .init();

Welches solltest du nehmen?

• Kleines Kommandozeilenwerkzeug oder Skript? log + env_logger. Winziges Setup, einfacher Text, fertig.
• Webserver, asynchroner Code oder viele Aufgaben gleichzeitig? tracing. Spans merken sich, zu welcher Anfrage eine Meldung gehört, selbst wenn Hunderte gleichzeitig laufen.
• Du schreibst eine Bibliothek? Benutze nur die Makros (log oder tracing) und rufe niemals init() auf. Die Anwendung entscheidet, wie Logs angezeigt werden.

Du musst dich nicht für immer festlegen. Das Standard-Setup von tracing-subscriber sammelt auch Meldungen aus dem Crate log ein, sodass Bibliotheken mit dem einen oder dem anderen gemeinsam erscheinen.

Häufige Fehler

Vergessen, einen Logger einzurichten. Wenn du nie env_logger::init() (oder das init() eines tracing-Subscribers) aufrufst, kompilieren die Makros problemlos und geben … nichts aus. Kein Fehler, keine Warnung. Wenn deine Logs verschwinden, prüf das zuerst – und danach RUST_LOG.

init() zweimal aufrufen. Es kann nur einen globalen Logger geben. Der zweite Aufruf löst eine Panic aus. Das ist die echte Meldung:

thread 'main' (12345) panicked at …/env_logger-0.11.11/src/logger.rs:901:16:
env_logger::init should not be called after logger initialized: SetLoggerError(())

Sie bedeutet: env_logger::init darf nicht aufgerufen werden, nachdem schon ein Logger initialisiert wurde. Ruf es einmal auf, ganz oben in main. In Tests benutzt du let _ = env_logger::builder().is_test(true).try_init();. Das gibt einen Fehler zurück, statt eine Panic auszulösen.

Den Span-Guard sofort wegwerfen. let _ = span.enter(); sieht harmlos aus, aber _ ist kein Variablenname – der Guard wird noch in derselben Zeile verworfen, und der Span endet sofort. Unser Lauf hat INFO my_app: bearbeite Anfrage ganz ohne Span ausgegeben. Gib dem Guard einen Namen, etwa let _guard = span.enter();, damit er bis zum Ende des Gültigkeitsbereichs (Scope) lebt.

Zusammenfassung

• Nimm ein Logging-Crate statt println!. Dann kannst du nach Stufe filtern und hältst Logs auf stderr, getrennt von deiner eigentlichen Ausgabe.
• log gibt dir error!, warn!, info!, debug! und trace!; env_logger::init() gibt sie aus.
• RUST_LOG steuert, was du siehst: RUST_LOG=debug, RUST_LOG=my_app=trace, RUST_LOG=info,my_app::db=trace.
• tracing bringt strukturierte Felder (info!(user_id = 42, "angemeldet")) und Spans mit; #[instrument] legt für jeden Funktionsaufruf einen Span an.
• Bibliotheken benutzen nur die Makros; die Anwendung richtet den Logger einmal ein.

Kurzer Check

Kurzer Check

1. Du startest ein Programm mit env_logger, ohne RUST_LOG zu setzen. Welche Log-Zeilen siehst du?

Alle Nur info! und höher Nur error! Gar keine

2. Wohin schreibt env_logger Log-Meldungen standardmäßig?

stdout stderr In eine Datei namens log.txt

3. Was zeigt RUST_LOG=warn?

Nur Warnungen Warnungen und alles Unwichtigere Warnungen und Fehler

4. Was bewirkt #[instrument] an einer Funktion?

Es stoppt die Funktion und gibt die Dauer aus Es legt für jeden Aufruf einen Span an, mit den Argumenten als Felder Es macht die Funktion schneller Es schaltet Logging für das ganze Programm ein

5. Du schreibst ein Bibliotheks-Crate. Wie sollte es mit Logging umgehen?

Die Logging-Makros benutzen, aber den Logger von der Anwendung einrichten lassen env_logger::init() aufrufen, wenn die Bibliothek geladen wird println! benutzen, damit es immer erscheint

Punkte: 0 / 5

Weiterlesen

• Doku des Crates log (auf Englisch): die fünf Makros und wie die Fassade funktioniert, inklusive Tipps für Autorinnen und Autoren von Bibliotheken.
• Doku von env_logger (auf Englisch): die vollständige Syntax von RUST_LOG und jede Option des Builder.
• Doku von tracing (auf Englisch): Spans, Events, Felder und #[instrument] im Detail.
• Doku von tracing-subscriber (auf Englisch): Formatierungsoptionen, EnvFilter und JSON-Ausgabe.
• Getting started with Tracing – Tokio (auf Englisch): eine freundliche Einführung vom Team, das tracing pflegt.