tracing-subscriber: span events don't include span fields with json formatter

[kbleeke]

Bug Report

Version

tracing = "0.1.21"
tracing-subscriber = "0.2.13"

Platform

Linux saren 5.8.14-arch1-1 #1 SMP PREEMPT Wed, 07 Oct 2020 23:59:46 +0000 x86_64 GNU/Linux

Crates

tracing-subscriber

Description

Span events that are enabled by SubscriberBuilder::with_span_events include the span's fields when the default formatter (that prints human-friendly logs) is used. I also expected this to be the case when the json formatter is used (SubscriberBuilder::json) but no span fields are included in the json.

Without json:

❯ RUST_LOG="info" cargo r
   Compiling tracingtest v0.1.0 (/home/pluth/rust/tracingbug)
    Finished dev [unoptimized + debuginfo] target(s) in 0.33s
     Running `target/debug/tracingtest`
Oct 13 12:56:15.904  INFO testspan{data="somedata"}: tracingtest: new
Oct 13 12:56:15.905  INFO testspan{data="somedata"}: tracingtest: close time.busy=0.00ns time.idle=234µs

Field data is shown here.

With json:

❯ RUST_LOG="info" cargo r
   Compiling tracingtest v0.1.0 (/home/pluth/rust/tracingbug)
    Finished dev [unoptimized + debuginfo] target(s) in 0.43s
     Running `target/debug/tracingtest`
{"timestamp":"Oct 13 12:56:40.641","level":"INFO","fields":{"message":"new"},"target":"tracingtest"}
{"timestamp":"Oct 13 12:56:40.641","level":"INFO","fields":{"message":"close","time.busy":"0.00ns","time.idle":"140µs"},"target":"tracingtest"}

Field data is not shown here.

Code:

use tracing_subscriber::fmt::format::FmtSpan;

fn main() {
    tracing_subscriber::fmt::fmt()
    .json()
    .with_span_events(FmtSpan::FULL)
    .init();

    tracing::info_span!("testspan", data="somedata");
}

[hawkw]

The behavior here is actually the same: in both cases, the span events are treated as children of the span that generated them. When using the human-readable formatter, the parent span context (including the span's fields) is displayed first. With the JSON formatter, displaying span contexts on events needs to be enabled by calling either with_current_span to emit the current span as a JSON field, or with_span_list to emit an ordered list of the current span followed by all its parents.

I believe

use tracing_subscriber::fmt::format::FmtSpan;

fn main() {
    tracing_subscriber::fmt::fmt()
        .json()
        .with_span_events(FmtSpan::FULL)
        .with_span_list(true)
        .init();

    tracing::info_span!("testspan", data="somedata");
}

should get you analogous behavior to the human-readable formatter.

In tracing-subscriber 0.3, we should probably make the default include the span list --- there aren't a lot of cases where people using the JSON format don't want the current span context. However, we've held off on that so far since it's technically a breaking change to the default output format.

[kbleeke]

Thanks for the quick reply. I don't think this works quite as expected. I created a more complex example to demonstrate:

use tracing_subscriber::fmt::format::FmtSpan;

fn main() {
    tracing_subscriber::fmt()
        .json()
        .with_current_span(true)
        .with_span_list(true)
        .with_span_events(FmtSpan::FULL)
        .init();

    tracing::info_span!("testspan", data="testdata").in_scope(|| {
        tracing::info!("testevent")
    });
}here

❯ RUST_LOG="info" cargo r
   Compiling stuff v0.1.0 (/home/pluth/rust/stuff)
    Finished dev [unoptimized + debuginfo] target(s) in 0.31s
     Running `target/debug/stuff`
{"timestamp":"Oct 14 11:00:19.865","level":"INFO","fields":{"message":"new"},"target":"stuff"}
{"timestamp":"Oct 14 11:00:19.865","level":"INFO","fields":{"message":"enter"},"target":"stuff","span":{"data":"testdata","name":"testspan"},"spans":[{"data":"testdata","name":"testspan"}]}
{"timestamp":"Oct 14 11:00:19.866","level":"INFO","fields":{"message":"testevent"},"target":"stuff","span":{"data":"testdata","name":"testspan"},"spans":[{"data":"testdata","name":"testspan"}]}
{"timestamp":"Oct 14 11:00:19.866","level":"INFO","fields":{"message":"exit"},"target":"stuff"}
{"timestamp":"Oct 14 11:00:19.866","level":"INFO","fields":{"message":"close","time.busy":"174µs","time.idle":"167µs"},"target":"stuff"}

The testevent includes the the current span and the span list. The entered span event also included this. However, the new, exit and close span events don't. I am specifically interested in the close event because of the timings.

[hawkw]

Hmm, that does indeed look like a bug. I'll take a look to see why those fields are missing.