Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Open
kbleeke opened this issue Oct 13, 2020 · 3 comments
Labels
crate/subscriber Related to the `tracing-subscriber` crate kind/bug Something isn't working

Comments

@kbleeke
Copy link

kbleeke commented Oct 13, 2020

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
Copy link
Member

hawkw commented Oct 13, 2020

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.

@davidbarsky davidbarsky added this to the tracing-subscriber 0.3 milestone Oct 13, 2020
@davidbarsky davidbarsky added the crate/subscriber Related to the `tracing-subscriber` crate label Oct 13, 2020
@kbleeke
Copy link
Author

kbleeke commented Oct 14, 2020

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
Copy link
Member

hawkw commented Oct 14, 2020

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

@hawkw hawkw added the kind/bug Something isn't working label Oct 14, 2020
akinnane added a commit to akinnane/tracing that referenced this issue Mar 28, 2021
New, exit and close span events are generated while the current
context is set to either `None` or the parent span of the span the
event relates to. This causes spans data to be absent from the JSON
output in the case of the `None`, or causes the span data to reference
the parent's span data. Changing the way the current span is
determined allows the correct span to be identified for these
events. Trying to access the events `.parent()` allows access of the
correct span for the `on_event` actions, while using `.current_span()`
works for normal events.

Ref: tokio-rs#1032
hawkw added a commit that referenced this issue Apr 7, 2021
* subscriber: fix span data for new, exit, and close events

New, exit and close span events are generated while the current
context is set to either `None` or the parent span of the span the
event relates to. This causes spans data to be absent from the JSON
output in the case of the `None`, or causes the span data to reference
the parent's span data. Changing the way the current span is
determined allows the correct span to be identified for these
events. Trying to access the events `.parent()` allows access of the
correct span for the `on_event` actions, while using `.current_span()`
works for normal events.

Ref: #1032

* Fix style

* subscriber: improve test for #1333

Based on feedback by @hawkw, I've improved the test for #1333 to parse
the json output. This is more specifc for the bug and allows easier
testing of the different span `on_events`.

Ref: #1333 (review)

* subscriber: improve #1334 tests covering all span states

Use the `on_records` test method check all events have the correct
context as described in the PR.

* Apply suggestions from code review

Co-authored-by: Eliza Weisman <eliza@buoyant.io>
hawkw added a commit that referenced this issue Apr 16, 2021
* subscriber: fix span data for new, exit, and close events

New, exit and close span events are generated while the current
context is set to either `None` or the parent span of the span the
event relates to. This causes spans data to be absent from the JSON
output in the case of the `None`, or causes the span data to reference
the parent's span data. Changing the way the current span is
determined allows the correct span to be identified for these
events. Trying to access the events `.parent()` allows access of the
correct span for the `on_event` actions, while using `.current_span()`
works for normal events.

Ref: #1032

* Fix style

* subscriber: improve test for #1333

Based on feedback by @hawkw, I've improved the test for #1333 to parse
the json output. This is more specifc for the bug and allows easier
testing of the different span `on_events`.

Ref: #1333 (review)

* subscriber: improve #1334 tests covering all span states

Use the `on_records` test method check all events have the correct
context as described in the PR.

* Apply suggestions from code review

Co-authored-by: Eliza Weisman <eliza@buoyant.io>
hawkw added a commit that referenced this issue Apr 17, 2021
* subscriber: fix span data for new, exit, and close events

New, exit and close span events are generated while the current
context is set to either `None` or the parent span of the span the
event relates to. This causes spans data to be absent from the JSON
output in the case of the `None`, or causes the span data to reference
the parent's span data. Changing the way the current span is
determined allows the correct span to be identified for these
events. Trying to access the events `.parent()` allows access of the
correct span for the `on_event` actions, while using `.current_span()`
works for normal events.

Ref: #1032

* Fix style

* subscriber: improve test for #1333

Based on feedback by @hawkw, I've improved the test for #1333 to parse
the json output. This is more specifc for the bug and allows easier
testing of the different span `on_events`.

Ref: #1333 (review)

* subscriber: improve #1334 tests covering all span states

Use the `on_records` test method check all events have the correct
context as described in the PR.

* Apply suggestions from code review

Co-authored-by: Eliza Weisman <eliza@buoyant.io>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
crate/subscriber Related to the `tracing-subscriber` crate kind/bug Something isn't working
Projects
None yet
Development

No branches or pull requests

3 participants