Unveiling Observability: Tracing mit Spans, Events und Tower-HTTP in Rust

Einleitung

In der komplexen Welt der modernen Softwareentwicklung ist das Verständnis des Verhaltens Ihrer Anwendungen, insbesondere verteilter Systeme, von größter Bedeutung. Wenn Dinge schiefgehen, oder auch wenn sie prächtig funktionieren, wird das Gewinnen von Einblicken in den Ausführungsfluss, die benötigte Zeit für Operationen und den Kontext rund um Ereignisse für die Fehlerbehebung, die Leistungsoptimierung und die allgemeine Überwachung der Systemgesundheit entscheidend. Hier kommen robuste Observability-Tools ins Spiel. Das Rust-Ökosystem bietet tracing, ein leistungsstarkes und flexibles Framework für strukturiertes Logging und verteiltes Tracing. Es bietet eine Basisschicht, auf der hochentwickelte Diagnosewerkzeuge aufgebaut werden können. Dieser Artikel wird sich eingehend mit tracing befassen, seine grundlegenden Komponenten – Spans und Events – untersuchen und dann demonstrieren, wie es nahtlos mit tower-http, einer beliebten Sammlung von HTTP-Middleware, integriert werden kann, um umsetzbare Observability für Ihre Webservices zu bringen.

Verständnis des Kerns von Tracing

Bevor wir uns in praktische Beispiele stürzen, wollen wir ein solides Verständnis der beiden Eckpfeiler von tracing schaffen: Spans und Events.

Spans: Die Umschläge der Ausführung

Ein Span repräsentiert eine Ausführungszeitspanne innerhalb Ihrer Anwendung. Betrachten Sie ihn als eine logische Arbeitseinheit, einen begrenzten Kontext, der eine bestimmte Operation umschließt. Spans haben einen Anfang und ein Ende und bilden eine hierarchische Struktur. Zum Beispiel könnte ein einzelner HTTP-Request-Handler ein Span sein. Innerhalb dieses Handlers könnten eine Datenbankabfrage oder ein externer API-Aufruf verschachtelte Spans sein. Diese hierarchische Beziehung ist entscheidend für das Verständnis der kausalen Kette von Operationen und die Rekonstruktion des vollständigen Ablaufs von Anfragen durch Ihr System. Spans können zugehörige Daten, sogenannte Felder, tragen, die kontextbezogene Informationen für diese spezifische Operation liefern – wie z. B. Request-IDs, User-IDs oder Eingabeparameter.

Events: Zeitpunkte

Im Gegensatz zu Spans repräsentieren Events diskrete, augenblickliche Vorkommnisse zu einem bestimmten Zeitpunkt während der Ausführung Ihrer Anwendung. Es handelt sich um atomare Log-Nachrichten, die oft zur Meldung wichtiger Vorkommnisse verwendet werden, die nicht unbedingt eine Dauer umfassen, wie z. B. das Abfangen eines Fehlers, die Anmeldung eines Benutzers oder der Abschluss eines bestimmten Datentransformationsschritts. Wie Spans tragen auch Events Felder, um relevanten Kontext bereitzustellen.

Die Stärke von tracing liegt darin, wie Spans und Events zusammenarbeiten. Events treten oft im Kontext eines aktiven Spans auf und erben dessen kontextbezogene Felder und verstärken die Erzählung dessen, was innerhalb dieser spezifischen Arbeitseinheit geschieht.

Layers und Subscribers

tracing gibt die Ausgabe nicht direkt an die Konsole aus oder sendet Daten an ein Tracing-Backend. Stattdessen arbeitet es über ein System von Subscribers und Layers. Ein Subscriber ist ein Typ, der das tracing Subscriber-Trait implementiert und für die Verarbeitung von Tracing-Daten (Spans und Events) verantwortlich ist, sobald diese generiert werden. Layers sind komponierbare Einheiten, die sich zwischen der Trace-Datenquelle und dem Subscriber befinden und das Filtern, Formatieren und Anreichern der Daten ermöglichen, bevor sie den endgültigen Subscriber erreichen. Diese Architektur bietet immense Flexibilität und ermöglicht es Ihnen, Ihre Observability-Lösung an spezifische Bedürfnisse anzupassen, wie z. B. das Logging an verschiedene Ziele oder das Filtern bestimmter Arten von Events.

Praktisches Tracing mit Spans und Events

Lassen Sie uns diese Konzepte anhand einiger Rust-Codes veranschaulichen. Zuerst müssen Sie tracing und tracing-subscriber zu Ihrer Cargo.toml hinzufügen:

[dependencies]
tracing = "0.1"
tracing-subscriber = "0.3"

Betrachten wir nun eine einfache Funktion, die einige Arbeiten simuliert:

use tracing::{info, span, Level};

#[tracing::instrument] // Dieses Makro erstellt einen Span für die Funktion
async fn perform_complex_operation(input_value: u32) -> String {
    // Ein Event innerhalb des Spans
    info!("Starting complex operation with input_value={}", input_value);

    // Simulieren einiger Arbeiten
    tokio::time::sleep(std::time::Duration::from_millis(50)).await;

    let intermediate_result = input_value * 2;
    // Weiteres Event
    info!("Calculated intermediate_result={}", intermediate_result);

    // Einen neuen verschachtelten Span betreten
    let nested_span = span!(Level::INFO, "nested_processing", step = 1);
    let _guard = nested_span.enter(); // Den Span-Kontext betreten

    tokio::time::sleep(std::time::Duration::from_millis(30)).await;
    let final_result = format!("Processed: {}", intermediate_result + 10);
    info!("Finished nested processing");

    drop(_guard); // Den verschachtelten Span explizit verlassen

    info!("Complex operation completed, returning: {}", final_result);
    final_result
}

#[tokio::main]
async fn main() {
    // Einen einfachen Subscriber für die Konsolenausgabe initialisieren
    tracing_subscriber::fmt::init();

    let result = perform_complex_operation(42).await;
    info!("Application finished with result: {}", result);
}

In diesem Beispiel:

• #[tracing::instrument] auf perform_complex_operation erstellt automatisch einen Span, der die gesamte Ausführung der Funktion umschließt. Es werden auch automatisch Funktionsargumente als Felder in den Span aufgenommen.
• info! Makroaufrufe erzeugen Events. Beachten Sie, wie info!("Starting complex operation with input_value={}", input_value); automatisch input_value als Feld übernimmt, da es im Kontext des aktuellen Spans verfügbar ist (wegen #[tracing::instrument]).
• Wir erstellen manuell einen verschachtelten Span nested_processing mit span! und betreten seinen Kontext mit nested_span.enter(). Der _guard stellt sicher, dass der Span verlassen wird, wenn er den Gültigkeitsbereich verlässt (oder explizit mit drop). Dies zeigt die manuelle Span-Erstellung für eine präzise Kontrolle.
• tracing_subscriber::fmt::init() richtet einen einfachen Subscriber ein, der formatierte Tracedaten auf der Konsole ausgibt und uns die hierarchische Struktur sehen lässt.

Wenn Sie dies ausführen, werden Sie eine Ausgabe ähnlich der folgenden beobachten (vereinfacht zur Verdeutlichung):

INFO tokio_app: Starting complex operation with input_value=42 span=perform_complex_operation
INFO tokio_app: Calculated intermediate_result=84 span=perform_complex_operation
INFO tokio_app: Finished nested processing span=perform_complex_operation::nested_processing step=1
INFO tokio_app: Complex operation completed, returning: Processed: 94 span=perform_complex_operation
INFO tokio_app: Application finished with result: Processed: 94

Beachten Sie, wie span=... den aktiven Span für jedes Event angibt und span=perform_complex_operation::nested_processing den verschachtelten Span zeigt.

Integration mit Tower-HTTP

Lassen Sie uns nun unsere Observability durch die Integration von tracing mit tower-http erweitern, einer Sammlung von HTTP-Middleware für tower-Services. tower-http bietet eine Trace-Middleware, die speziell für diesen Zweck entwickelt wurde.

Fügen Sie zunächst die notwendigen Abhängigkeiten zu Ihrer Cargo.toml hinzu:

[dependencies]
tracing = "0.1"
tracing-subscriber = "0.3"
tokio = { version = "1", features = ["full"] }
axum = "0.6" # axum für einen einfachen Webserver verwenden
tower = "0.4"
tower-http = { version = "0.4", features = ["trace"] }

Erstellen Sie als Nächstes eine kleine axum-Anwendung (die intern tower verwendet) und wenden Sie die Trace-Middleware an.

use axum::{routing::get, Router};
use tower_http::trace::{TraceLayer, DefaultOnRequest, DefaultOnResponse};
use tracing::{info, Level};
use std::time::Duration;

// Ein einfacher Handler, der unsere getracede Funktion verwendet
async fn hello_handler() -> String {
    info!("Handler received request");
    let result = perform_complex_operation(100).await;
    format!("Hello, from handler! {}", result)
}

// Unsere vorherige getracete Funktion
#[tracing::instrument]
async fn perform_complex_operation(input_value: u32) -> String {
    info!("Starting complex operation with input_value={}", input_value);
    tokio::time::sleep(Duration::from_millis(50)).await;
    let intermediate_result = input_value * 2;
    info!("Calculated intermediate_result={}", intermediate_result);
    // ... (Rest der Funktion wie zuvor)
    let nested_span = tracing::span!(Level::INFO, "nested_processing", step = 1);
    let _guard = nested_span.enter();
    tokio::time::sleep(Duration::from_millis(30)).await;
    let final_result = format!("Processed: {}", intermediate_result + 10);
    info!("Finished nested processing");
    drop(_guard);
    info!("Complex operation completed, returning: {}", final_result);
    final_result
}


#[tokio::main]
async fn main() {
    tracing_subscriber::fmt::init();

    let app = Router::new()
        .route("/hello", get(hello_handler))
        .layer(
            TraceLayer::new_for_http() // Eine neue TraceLayer für HTTP-Dienste erstellen
                .on_request(DefaultOnRequest::new().level(Level::INFO)) // Request-Details loggen
                .on_response(DefaultOnResponse::new().level(Level::INFO)), // Response-Details loggen
        );

    let listener = tokio::net::TcpListener::bind("127.0.0.1:3000")
        .await
        .unwrap();
    info!("Listening on {}", listener.local_addr().unwrap());
    axum::serve(listener, app).await.unwrap();
}

In diesem erweiterten Beispiel:

• Wir haben einen axum Router mit dem Endpunkt /hello erstellt.
• Die Middleware TraceLayer::new_for_http() wird auf unsere Anwendung angewendet. Dies erstellt automatisch einen Root-Span für jede eingehende HTTP-Anfrage.
• .on_request(DefaultOnRequest::new().level(Level::INFO)) konfiguriert die Middleware so, dass ein Event auf INFO-Ebene ausgegeben wird, wenn eine Anfrage beginnt, einschließlich Details wie Methode und Pfad.
• .on_response(DefaultOnResponse::new().level(Level::INFO)) konfiguriert sie so, dass ein Event auf INFO-Ebene ausgegeben wird, wenn eine Antwort gesendet wird, einschließlich Statuscode und Antwortzeit.

Wenn Sie diese Anwendung ausführen und eine Anfrage an http://127.0.0.1:3000/hello senden (z. B. mit curl), sehen Sie detaillierte Tracing-Ausgaben:

INFO tower_http::trace::make_span: started processing request request.method=GET request.uri=/hello request.version=HTTP/1.1 remote_addr=127.0.0.1:49877 request_id=... span=http_request
INFO axum_app: Handler received request span=http_request
INFO axum_app: Starting complex operation with input_value=100 span=http_request::perform_complex_operation
INFO axum_app: Calculated intermediate_result=200 span=http_request::perform_complex_operation
INFO axum_app: Finished nested processing span=http_request::perform_complex_operation::nested_processing step=1
INFO axum_app: Complex operation completed, returning: Processed: 210 span=http_request::perform_complex_operation
INFO tower_http::trace::make_span: finished processing request status=200 response.time=100ms span=http_request

Beobachten Sie, wie tower-http einen Top-Level-Span http_request erstellt und alle nachfolgenden info!-Events und manuellen Spans in Ihrem Handler automatisch unter diesem Request-Span verschachtelt werden. Dies zeigt klar den gesamten Lebenszyklus einer HTTP-Anfrage, von ihrer Ankunft bis zur endgültigen Antwort, wobei alle internen Operationen detaillierten Kontext liefern. Diese strukturierte, hierarchische Ansicht ist von unschätzbarem Wert für die Identifizierung von Engpässen, das Verständnis von Request-Flüssen und die Fehlerbehebung bei Problemen in Ihren Webservices.

Fazit

Das tracing-Crate ist ein unverzichtbares Werkzeug im Observability-Toolkit von Rust und bietet ein robustes und flexibles Framework für das Verständnis des Anwendungsverhaltens. Durch die Beherrschung der Konzepte von Spans als umschließende Arbeitseinheiten und Events als augenblickliche Vorkommnisse erhalten Sie die Möglichkeit, ein detailliertes Bild der Ausführung Ihres Codes zu zeichnen. Die Integration von tracing mit tower-http bringt diese beispiellose Sichtbarkeit direkt in Ihre Webservices und verwandelt undurchsichtige HTTP-Anfragen in klare, nachvollziehbare Erzählungen. Die Übernahme von tracing befähigt Entwickler, widerstandsfähigere, performantere und verständlichere Rust-Anwendungen zu erstellen.