Rust tracing not generating span IDs or associating with parents

Question

I have a tracing subscriber like:

let subscriber = tracing_subscriber::registry().with(
        tracing_subscriber::fmt::layer()
            .compact()
            .with_file(true)
            .with_line_number(true)
            .with_span_events(FmtSpan::CLOSE)
            .with_target(false)
            // .json()
            .with_filter(level_filters::LevelFilter::from_level(Level::DEBUG))
    );

    tracing::subscriber::set_global_default(subscriber).unwrap();

But the logs and spans are not getting IDs generated (and thus not being associated with a parent/current span). What do I need to fix so that spans have IDs generated, are associated with parents, and logs have the current span id in them? I am tracing like #[tracing::instrument(level = "debug", skip(state))] and logging like

debug!(
                "Getting subslice of value for key {} with start={} end={}",
                key, start, end
            );

Generated logs look like:

2024-06-23T12:37:08.371471Z DEBUG get_or_list_prefix:get_item:root:outer_child: src/routes/get.rs:74: close time.busy=5.38µs time.idle=5.71µs key_prefix=Some("a") params=GetOrListParams { list: None, limit: None, with_vals: None, reverse: None, start: None, end: None } params=GetOrListParams { list: None, limit: None, with_vals: None, reverse: None, start: None, end: None } key="a"
2024-06-23T12:37:08.371534Z  INFO get_or_list_prefix:get_item:root: src/routes/get.rs:71: close time.busy=86.0µs time.idle=3.67µs key_prefix=Some("a") params=GetOrListParams { list: None, limit: None, with_vals: None, reverse: None, start: None, end: None } params=GetOrListParams { list: None, limit: None, with_vals: None, reverse: None, start: None, end: None } key="a"
2024-06-23T12:37:08.371606Z DEBUG get_or_list_prefix:get_item: src/routes/get.rs:65: close time.busy=163µs time.idle=7.37µs key_prefix=Some("a") params=GetOrListParams { list: None, limit: None, with_vals: None, reverse: None, start: None, end: None } params=GetOrListParams { list: None, limit: None, with_vals: None, reverse: None, start: None, end: None } key="a"
2024-06-23T12:37:08.371637Z DEBUG get_or_list_prefix: src/routes/get.rs:41: close time.busy=216µs time.idle=16.9µs key_prefix=Some("a") params=GetOrListParams { list: None, limit: None, with_vals: None, reverse: None, start: None, end: None }

My hope is to be able to have spans automtically generate IDs, automatically reference their parent span IDs if they have one, and logs would include the ID of the current span.

Answer 1

IDs are being generated for spans and their parents, but your subscriber just doesn't show them.

Span IDs aren't particularly useful in human readable logs. Either spans are naturally delimited for your use-case, in which case you don't need them; or they're often interleaved, in which case associating them by eye is tedious and cumbersome. More often you have a particular tool to view traces in an organized way and thus your output format is tied to it (e.g. a profiler like tracy or coz, or some opentelemetry tool).

But here is a demonstration how you could log the span ID with your message by creating your own FormatEvent implementation for use with an existing tracing-subscriber. This is adapted from the example here, so you may look there or at the source of other implementations for more ideas.

use tracing::{Event, Subscriber};
use tracing_subscriber::fmt::format::{self, FormatEvent, FormatFields};
use tracing_subscriber::fmt::time::{FormatTime, SystemTime};
use tracing_subscriber::fmt::FmtContext;
use tracing_subscriber::registry::LookupSpan;

struct MyFormatter;

impl<S, N> FormatEvent<S, N> for MyFormatter
where
    S: Subscriber + for<'a> LookupSpan<'a>,
    N: for<'a> FormatFields<'a> + 'static,
{
    fn format_event(
        &self,
        ctx: &FmtContext<'_, S, N>,
        mut writer: format::Writer<'_>,
        event: &Event<'_>,
    ) -> std::fmt::Result {
        let metadata = event.metadata();

        write!(&mut writer, "[")?;
        SystemTime.format_time(&mut writer)?;
        write!(&mut writer, "]")?;

        write!(&mut writer, " {} {}", metadata.level(), metadata.target())?;

        if let Some(span) = ctx.parent_span() {
            write!(&mut writer, " span={:?}", span.id())?;
        }

        write!(&mut writer, ": ")?;
        ctx.field_format().format_fields(writer.by_ref(), event)?;

        writeln!(writer)
    }
}

fn main() {
    tracing_subscriber::fmt().event_format(MyFormatter).init();

    tracing::info!("no span");

    let _span = tracing::info_span!("my_span", answer = 42).entered();
    tracing::info!(
        question = "life, the universe, and everything",
        "hello world"
    );
}

[2024-06-26T16:54:21.851457Z] INFO mycrate: no span
[2024-06-26T16:54:21.853566Z] INFO mycrate span=Id(1): hello world question="life, the universe, and everything"