Tracing: No span info output to appender

1

Not sure what I'm missing here but I don't get span information in events when using a RollingFileAppender.

Sample code:

#![allow(unused_variables)]

use tracing::{event, instrument, Level};
use tracing_appender::{
    non_blocking::WorkerGuard,
    rolling::{RollingFileAppender, Rotation},
};
use tracing_subscriber::fmt::format::FmtSpan;

#[instrument]
fn main() {
    // A ref to the Guard must be stored as its drop causes flushing of the appender
    let guard = init_tracing();
    event!(Level::INFO, "server started");
}

fn init_tracing() -> WorkerGuard {
    let appender = RollingFileAppender::builder()
        .rotation(Rotation::DAILY)
        .filename_prefix("server.log")
        .build("./log")
        .expect("failed to initialize rolling file appender");

    let (non_blocking, guard) = tracing_appender::non_blocking(appender);
    tracing_subscriber::fmt()
        .with_file(true)
        .with_span_events(FmtSpan::FULL)
        .with_line_number(true)
        .with_thread_ids(true)
        .with_target(false)
        .with_writer(non_blocking)
        .init();

    guard
}

Output:

2024-12-03T21:02:50.733492Z  INFO ThreadId(01) server/src/main.rs:14: server started

I've played with options to with_span_events and nothing does it.

Am I missing something fundamental or is there a bug here?

2

Actually it's not specific to the appender at all. Even this trivial example outputs no span information:

#[instrument]
fn main() {
    let stdout_subscriber = tracing_subscriber::fmt::init();
    event!(Level::INFO, "server started");
}

The docs state that, "The easiest way to emit spans is with the instrument proc-macro annotation provided by tracing, which re-writes the bodies of functions to emit spans each time they are invoked...If you run your application, you now will see events decorated with their span's context emitted for each incoming connection that it processes."

Constructing a span manually instead of using #instrument gave the same results.

I'm used to, say, NewRelic spans were each has start & end delimiters and some id attribute...

3

instrument on main has no effect, because you entered the span before the subscriber is setup. any instrumented function called after the subscriber is initialized will have the span correctly registered:

fn main() {
	let stdout_subscriber = tracing_subscriber::fmt::init();
	start();
}
#[instrument]
fn start() {
	event!(Level::INFO, "server started");
}

merely constructing a span is not enough, you need to "enter" a span. because spans can be entered and left multiple times, they are not used as RAII guard objects themselves.

// create span but not enter
let span = span!(Level::TRACE, "my_span");
info!("not entered yet");

// manually enter and left a span
let guard = span.enter();
info!("inside my_span");
drop(guard);
info!("left my_span");

// the alternative `entered()` api
let span = span.entered();
info!("entered again");
// it not "exit()" explicitly, will exit on drop
let span = span.exit();

// the scoped api
span.in_scope(|| {
    info!("inside scope of my_span");
});
info!("outside of my_span");
span.in_scope(|| {
    info!("inside scope again");
});

the difference between .enter() and .entered() is the former takes &self and can be entered concurrently, while the latter is linear and consumes self.

3 Likes