Tracing

Recipe	Crates	Categories
Log Trace Data to stdout
Change the Log Level
Log in JSON Format
Configure Tracing
Write Logs to Multiple Destinations Simultaneously
Configure Tracing at Runtime
Change the Tracing Configuration at Runtime
Customize the Formatting of Log Lines
Log Events with tracing
Create then Enter a Span
Create and Enter a Span in a One-liner Using entered
Use Spans to Instrument Synchronous and Asynchronous Code
Add Tracing Spans to Functions

Tracing refers to the process of capturing and recording information about the execution of a software program.

Log Trace Data to stdout

A one-liner allows recording of tracing's Events and Spans by formatting them as text and logging them to stdout.

//! - `tracing` is a framework for instrumenting Rust programs to collect
//!   scoped, structured, and async-aware diagnostics.
//! - Its `Subscriber` trait represents the functionality necessary to collect
//!   this trace data.
//! - The `tracing-subscriber` crate contains tools for composing subscribers
//!   out of smaller units of behaviour, and batteries-included implementations
//!   of common subscriber functionality.
//! - In particular, the `tracing_subscriber::fmt` module provides a default
//!   implementation of the `Subscriber` trait that records `Events` and `Spans`
//!   by formatting them as text and logging them to stdout.
//!   [(docs.rs)](https://docs.rs/tracing-subscriber/latest/tracing_subscriber/index.html)
//!
//! Add to your `Cargo.toml`:
//! ```toml
//! [dependencies]
//! tracing = "0.1.41" # Or latest version
//! tracing-subscriber = "0.3.19"
//! ```

fn main() {
    // In most cases, you will use the following to
    // initialize and install the global subscriber for your application:
    tracing_subscriber::fmt::init();

    // This is typicaly called early in the `main()` function of your
    // application. `init()` should not be called by libraries!
    // That will cause conflicts when executables try to set them later.

    // `fmt::init()` sets up a subscriber that logs to the console
    // and filters logs  at runtime based on the `RUST_LOG` environment
    // variable, for example, `RUST_LOG=debug,my_crate=trace`.
    //
    // If the environment variable is empty or not set, or if it contains only
    // invalid directives, the ERROR level is used.

    // Test it out.
    tracing::error!("tracing configured!");
}
// `tracing_subscriber::fmt::init()` is equivalent to:
// tracing_subscriber::fmt() // Returns `SubscriberBuilder::default()`.
//     .with_env_filter(EnvFilter::from_default_env()) // Reads RUST_LOG.
//     .init(); // Installs the global default subscriber.

Change the Log Level

/// Demonstrates how to configure the tracing subscriber
/// to change the logging level.
fn main() {
    // Change the default logging level:
    tracing_subscriber::fmt()
        // Sets the maximum verbosity level.
        .with_max_level(tracing::Level::DEBUG)
        // Sets this subscriber to be the global trace collector for this application.
        .init();
    // You may use `try_init()` instead.

    tracing::debug!("tracing configured!");
}

Log in JSON Format

use std::fs::File;

use tracing::instrument;
use tracing_subscriber::fmt::format::FmtSpan;

/// Demonstrates how to log in JSON format.
/// This is intended for production use with systems where structured logs are
/// consumed as JSON by analysis and viewing tools.
fn main() {
    let file = File::create("temp/my_log.json").unwrap();

    // Build a custom subscriber.
    let json_subscriber = tracing_subscriber::fmt()
        .json() // Log in JSON format.
        .with_writer(std::sync::Mutex::new(file)) // Log to the file.
        // Adjust the following configuration as needed.
        .with_max_level(tracing::Level::TRACE) // Log everything.
        .flatten_event(false) // Do not flatten event metadata.
        .with_current_span(true) // Include the current span in formatted events.
        .with_span_list(true) // Include a list (from root to leaf) of all currently entered spans in formatted events.
        .with_span_events(FmtSpan::FULL) // Events will be logged whenever a span is created, entered, exited, or closed.
        .with_thread_ids(true) // Include the thread ID of the current thread.
        .with_thread_names(true) // Include the thread name of the current thread.
        .with_ansi(false) // Disable ANSI terminal escape codes for colors and other text formatting.
        .finish();

    // Register it as the global default. Equivalent to
    // `json_subscriber.init()`.
    tracing::subscriber::set_global_default(json_subscriber)
        .expect("Setting tracing default failed.");

    tracing::debug!("Tracing configured!");

    // Calling this instrumented function will log span events, since
    // `with_span_events` is enabled above.
    a_function();
}

#[instrument]
fn a_function() {
    tracing::debug!("In a_function.");
}

Configure Tracing

use std::io;

// use tracing_subscriber::filter;
use tracing_subscriber::filter::EnvFilter;
use tracing_subscriber::filter::LevelFilter;
use tracing_subscriber::fmt;
use tracing_subscriber::layer::SubscriberExt;
// use tracing_subscriber::prelude::*;
use tracing_subscriber::util::SubscriberInitExt;

/// The most important component of the `tracing-subscriber` API is the
/// `Layer` trait. `Layer`s can be composed together to form a
/// `Subscriber`.
fn layers() {
    // Create a few layers.
    // `layer()` is shorthand for the equivalent `Layer::default()` function.
    let layer1 = fmt::layer().with_writer(io::stderr); // Logs to the console's standard error stream.
    let layer2 = fmt::layer().with_writer(io::stdout); // Logs to the console.

    // Initialize tracing.
    // `registry()` is equivalent to `Registry::default()`.
    // A Registry is a Subscriber around which multiple Layers implementing
    // various behaviors may be added.
    tracing_subscriber::registry()
        .with(layer1)
        .with(layer2)
        .init();

    // Test it.
    tracing::debug!("tracing configured!");
}

use std::error::Error;

// A Layer which filters spans and events based on a set of filter directives.
// EnvFilter implements both the Layer and Filter traits, so it may be used for
// both global filtering and per-layer filtering, respectively.
#[allow(dead_code)]
fn filter() -> Result<(), Box<dyn Error + Send + Sync + 'static>> {
    // 1. Returns a new EnvFilter from the value of the RUST_LOG environment
    //    variable, ignoring any invalid filter directives.
    let _filter_layer = EnvFilter::from_default_env();

    // 2. Returns a new EnvFilter from the value of the RUST_LOG environment
    //    variable, or "info" if the environment variable is unset or contains
    //    any invalid filter directives.
    let _filter_layer = EnvFilter::try_from_default_env()
        .or_else(|_| EnvFilter::try_new("info"))
        .unwrap();

    // "development_tools_debugging=debug,axum=debug,tower_http=debug,
    // mongodb=debug" "my_crate=info,my_crate::my_mod=debug,
    // [my_span]=trace"

    // 3. Custom environment variable
    let _filter_layer = EnvFilter::try_from_env("MY_CUSTOM_FILTER_ENV_VAR")?
        // Set the base level when not matched by other directives to DEBUG.
        .add_directive(LevelFilter::DEBUG.into())
        // Set the max level for `my_crate::my_mod` to TRACE, overriding
        // any directives parsed from the env variable.
        .add_directive("my_crate::my_mod=trace".parse()?);

    // FIXME fmt().with_env_filter(filter_layer).try_init()?;

    // Test it.
    tracing::debug!("tracing configured!");
    Ok(())
}

fn main() -> Result<(), Box<dyn Error + Send + Sync + 'static>> {
    layers();
    // FIXME filter()?;
    Ok(())
}

Write Logs to Multiple Destinations Simultaneously

use std::io;

use tracing_subscriber::filter::EnvFilter;
use tracing_subscriber::fmt;
use tracing_subscriber::layer::SubscriberExt;

/// Demonstrates how to write logs to multiple destinations (in this instance,
/// stdout and a file) simultaneously.
fn main() {
    let dir = tempfile::tempdir().expect("Failed to create tempdir");

    // Hourly rotating file appender that writes to
    // /{dir}/example.log.YYYY-MM-DD-HH:
    let file_appender = tracing_appender::rolling::hourly(dir, "example.log");

    // Non-Blocking rolling file appender:
    let (non_blocking, _guard) = tracing_appender::non_blocking(file_appender);

    let collector = tracing_subscriber::registry()
        .with(
            EnvFilter::from_default_env()
                .add_directive(tracing::Level::TRACE.into()),
        )
        .with(fmt::layer().with_writer(io::stdout))
        .with(fmt::layer().with_writer(non_blocking));
    tracing::subscriber::set_global_default(collector)
        .expect("Unable to set a global collector");

    // Test it.
    tracing::debug!("tracing configured!");
}

Configure Tracing at Runtime

//! This example demonstrates how to enable or
//! disable layers at runtime based on a configuration flag.
//!
//! It configures a `tracing` subscriber with multiple layers, including a
//! human-readable pretty-printed layer and an optional JSON-formatted layer
//! that logs to a file.

use std::fs::File;

use serde::Deserialize;
use tracing_subscriber::Registry;
use tracing_subscriber::fmt;
use tracing_subscriber::prelude::*;

/// Configuration struct.
#[derive(Debug, Deserialize)]
struct Config {
    is_prod: bool,
    path: String,
}

/// Demonstrates how to configure tracing at runtime.
fn main() -> anyhow::Result<()> {
    // Example configuration.
    // In production, this may be loaded from a configuration file or
    // environment variables.
    let cfg = Config {
        is_prod: true,
        path: "temp/log.json".into(),
    };

    // Setup a human-readable, multi-line logger.
    // `layer()` is a shorthand for the equivalent `Layer::default` function.
    let pretty_layer = fmt::layer().pretty();

    // If `cfg.is_prod` is true, also log JSON-formatted logs to a file.
    let json_optional_layer: Option<_> = if cfg.is_prod {
        let file = File::create(cfg.path)?;
        let json_layer = fmt::layer().json().with_writer(file);
        Some(json_layer)
    } else {
        None
    };

    let subscriber = Registry::default().with(pretty_layer);
    // A `Layer` wrapped in an `Option` also implements the `Layer` trait.
    // This allows individual layers to be enabled or disabled at runtime while
    // always producing a `Subscriber` of the same type.
    //
    // If `cfg.is_prod` is false, then `json_optional_layer` will be `None`, and
    // this layer will do nothing.
    let subscriber = subscriber.with(json_optional_layer);

    tracing::subscriber::set_global_default(subscriber)?;

    tracing::error!("tracing configured!");
    println!("Done.");

    Ok(())
}

Change the Tracing Configuration at Runtime

use std::fs::File;
use std::io;

use tracing_subscriber::Layer;
use tracing_subscriber::filter;
use tracing_subscriber::filter::LevelFilter;
use tracing_subscriber::fmt;
use tracing_subscriber::prelude::*;
use tracing_subscriber::reload;
use tracing_subscriber::reload::Handle;

struct Config {
    enable_log_file: bool,
    enable_stdout: bool,
    enable_stderr: bool,
}

/// Demonstrates how to configure tracing at runtime,
/// - dealing with a variable number of `Layer`s of different types.
/// - reloading the tracing configuration at runtime.
fn main() -> anyhow::Result<()> {
    let cfg = Config {
        enable_log_file: true,
        enable_stdout: true,
        enable_stderr: true,
    };

    // We create below any number of layers, based on our dynamically loaded
    // config file. We box the layers, which are of varied types, as
    // type-erased trait objects, so that they could be pushed to the `Vec`.
    let mut layers: Vec<Box<dyn Layer<_> + Send + Sync>> = Vec::new();

    if cfg.enable_log_file {
        let file = File::create("temp/myapp.log")?;
        let layer = fmt::layer()
        .json()
        .with_writer(file)
        // More layer configuration here...
        .with_thread_names(true)
        .boxed(); // Equivalent to `Box::new`.
        layers.push(layer);
    }

    let mut reload_handle: Option<Handle<_, _>> = None;
    if cfg.enable_stdout {
        let layer = fmt::layer().pretty().with_filter(LevelFilter::WARN);
        // We wrap this `layer` using the `reload` module to get a reload
        // handle.
        let (layer, handle) = reload::Layer::new(layer);
        layers.push(Box::new(layer));
        reload_handle = Some(handle);
    }

    if cfg.enable_stderr {
        let layer = fmt::layer()
            .with_writer(io::stderr)
            .with_filter(LevelFilter::DEBUG)
            .boxed();
        layers.push(layer);
    }

    // `Vec<L> where L: Layer` implements `Layer`.
    // `Box<dyn Layer<S> + Send + Sync>` also implements `Layer`.
    tracing_subscriber::registry().with(layers).init();

    tracing::info!("This will be ignored by the pretty logger to stdout.");

    // Upon receiving a reload signal...
    if let Some(hdl) = reload_handle {
        hdl.modify(|layer| *layer.filter_mut() = filter::LevelFilter::INFO)?;
    }
    tracing::info!("This will be logged by all layers.");
    Ok(())
}

Customize the Formatting of Log Lines

use tracing_subscriber::fmt;
use tracing_subscriber::fmt::format::Format;
use tracing_subscriber::fmt::time::UtcTime;

/// This example demonstrates customizing the formatting of log lines for spans
/// and events. See https://docs.rs/tracing-subscriber/latest/tracing_subscriber/fmt/index.html#customizing-formatters
fn main() {
    // Configure a custom event formatter.
    let format: Format<_, _> = fmt::format() // Returns the default configuration for an event formatter.
        .with_ansi(true)  // Enable ANSI terminal colors for formatted output.
        .with_file(true)  // Displays the event's source code file path.
        .with_line_number(true) // Displays the source code line number.
        // or: .with_source_location(true)
        .with_level(false) // Don't include event levels e.g. Error, Debug, etc.
        .with_target(false) // Don't include event targets.
        .with_thread_ids(true) // Include the thread ID of the current thread.
        .with_thread_names(true) // Include the name of the current thread.
        .without_time() // Do not emit timestamps with log messages.
        .with_timer(UtcTime::rfc_3339()) // Use the given timer for log message timestamps.
        .compact(); // Use the `Compact` formatting style.
    // Consider also: `.json()` or `.pretty()`

    // The default logging format, `Full`, includes all fields in each event and
    // its containing spans. The `Compact` logging format is intended to produce
    // shorter log lines; it displays each event's fields, along with fields
    // from the current span context, but other information is abbreviated.

    // Create a subscriber that uses our custom event format, and
    // set it as the default.
    // - `fmt()` is essentially shorthand for `SubscriberBuilder::default()`.
    // - `init()` installs this Subscriber as the global default.
    tracing_subscriber::fmt().event_format(format).init();

    // Test it out.
    tracing::error!("tracing configured!");
}

Log Events with tracing

An Event signifies something that happened at a moment in time. tracing's Events are comparable to the log records emitted by unstructured logging code.

//! This example demonstrates the basic usage of the `tracing` crate for logging
//! events.
//!
//! It showcases how to use different log levels (trace, debug, info, warn,
//! error) and how to add structured data to log messages.

use tracing::Level;
use tracing::debug;
use tracing::error;
use tracing::event;
use tracing::info;
use tracing::trace;
use tracing::warn;

fn main() {
    // Basic logging of a message at various severity levels.
    event!(Level::INFO, "something happened");
    error!("error!");
    warn!("warning!");
    info!("info!");
    debug!("debug info!");
    trace!("trace info!");

    // Set the level and modify the event's target.
    // A target is a string that categorizes part of the system where the span
    // or event occurred. The tracing macros default to using the module path
    // where the span or event originated as the target, but it may be
    // overridden.
    event!(target: "app_events", Level::TRACE, "something has happened!");

    // Structured fields on events (and spans) are specified using the syntax
    // `field_name = field_value`. Fields are separated by commas.
    // Here, we record an event with two fields:
    event!(
        Level::INFO,
        answer = 42,
        question = "life, the universe, and everything"
    );

    // Unlike other fields, `message`'s shorthand initialization is just
    // the string itself.
    debug!(excitement = "yay!", "hello!");

    // String formatting; shorthand for `user = user`:
    let user = "ferris";
    event!(Level::TRACE, "login: {}", user);

    // Records an event with a `struct` field using the `Debug` format.
    // Note the `?`: `my_struct` will be recorded
    // using its `fmt::Debug` implementation.
    let my_struct = S;
    event!(Level::TRACE, greeting = ?my_struct);
}

/// A simple struct for demonstration purposes.
#[derive(Debug)]
struct S;

Create then Enter a Span

use tracing::Level;
use tracing::span;

fn main() {
    // Create a new span named "my_span" with the TRACE level.
    // Spans are used to represent a period of time in the execution of a
    // program.
    let span = span!(Level::TRACE, "my_span");
    {
        // Current lexical scope.
        let _guard = span.enter();
        println!(
            "`enter` returns a RAII guard, which, when dropped, exits the span."
        );
        tracing::info!(
            "Any trace events that occur here will occur within the span."
        )
    }
    tracing::info!("Dropping the guard exits the span.");
}

Create and Enter a Span in a One-liner Using entered

use tracing::Level;
use tracing::span;

/// Demonstrates entering and exiting a span using `entered()` and `exit()`.
fn main() {
    // Create a span, entering it using `entered()`, thus consuming it and
    // returning a guard that will exit the span when dropped.
    {
        let _span = span!(Level::INFO, "Some span").entered();

        tracing::info!("Code here is within the span.");
    }

    tracing::info!("Code here is no longer within the span.");

    // Optionally, use `entered` and `exit` to get in and out of the span.
    {
        let span = span!(Level::TRACE, "Another span").entered();
        tracing::info!("Within the span.");

        // Explicitly exit the span, returning it.
        let span = span.exit();
        tracing::info!("No longer within the span.");

        // Re-enter the span.
        let _span = span.entered();
        tracing::info!("Within the span.");
    }
}

Use Spans to Instrument Synchronous and Asynchronous Code

Holding the drop guard returned by Span::enter across .await points will result in incorrect traces. Use tracing::span::Span::in_scope⮳ to make sure the span is exited before the await call. Alternatively, use instrument to make sure that the span is automatically exited and re-entered when a async function or block is awaited then resumed.

//! Demonstrates how to use tracing spans to instrument code,
//! including synchronous and asynchronous code.
//!
//! This example showcases:
//! - Creating spans using `info_span!` and `debug_span!`.
//! - Entering and exiting spans using `in_scope`.
//! - Instrumenting async blocks and functions using `instrument`.
//! - How spans are handled across `await` points.

// Extension trait allowing futures to be instrumented with a tracing span,
// via `instrument(...)`:
use tracing::Instrument;
use tracing::debug_span;
use tracing::info;
use tracing::info_span;

/// An example async function that demonstrates span usage.
async fn my_async_function() {
    // Constructs a span at the info level:
    let span = info_span!("my_async_function_scope");
    // The above is equivalent to:
    // span!(Level::INFO, "my_async_function");

    // Executes some synchronous code in the context of this span:
    let _some_value = span.in_scope(|| {
        info!("I'm in the span!");
        42
    });
    info!("I'm not in the span!");

    // The `await` keyword may yield, causing the runtime to switch to another
    // task. However, the span has already been exited.
    some_other_async_function().await;

    // When the execution resumes from the await point, renter the span if
    // needed:
    span.in_scope(|| {
        info!("I'm also in the span!");
    });

    // We can also instrument async code:
    async move {
        // If we yield here, the span will be exited,
        // and re-entered when we resume.
        some_other_async_function().await;
        info!("I'm still in the span!");
    }
    .instrument(span) // Instrument the async block with the span...
    .await; // ...and await it.

    // We can also instrument an async function call.
    // This will create a new span for the duration of the function call.
    let _some_value = some_other_async_function()
        .instrument(debug_span!("some_other_async_function_scope"))
        .await;
}

async fn some_other_async_function() {}

#[tokio::main]
async fn main() {
    // Initialize the tracing subscriber to output logs to the console.
    tracing_subscriber::fmt()
        .with_max_level(tracing::Level::DEBUG)
        .init();
    my_async_function().await;
}

Add Tracing Spans to Functions

use tracing::Level;
use tracing::event;
use tracing::instrument;
use tracing::trace;

/// This function will be instrumented with a span.
///
/// The span will be named `my_function` and will have a field `my_arg`
/// with the value of the argument passed to the function.
#[instrument]
fn my_function(my_arg: usize) {
    // This event will be recorded inside a span named `my_function`
    // with the field `my_arg`.
    event!(Level::INFO, "inside my_function!");
    // ...
}

/// This async function will be instrumented with a span.
///
/// The span will be named `my_async_span`.
///
/// The span will be exited when the function yields and re-entered when it
/// resumes.
#[instrument(name = "my_async_span")]
async fn my_async_function() {
    trace!("I'm in my_async_span.");

    // If we yield here, the span will be exited,
    // and re-entered when we resume.
    some_other_async_function().await;
}

async fn some_other_async_function() {
    trace!("I'm in some_other_async_function.");
}

#[tokio::main]
async fn main() {
    my_function(42);
    my_async_function().await;
}

See Also

tracing_journald⮳ provides support for logging tracing⮳ events natively to journald⮳, preserving any structured information.

References

• Next steps with Tracing⮳.