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

subscriber: fix on_event serialization when no fields set on span #1333

Merged
merged 3 commits into from
Mar 31, 2021

Conversation

akinnane
Copy link
Contributor

Motivation

Serializing a spans on_ACTION events, when no fields are set on the span, results in invalid JSON. This is because serializier_map was getting a size hint for self.0.metadata().fields().len() then serializing self.0.fields.field_set() instead. This resulted in the fields key being set to an empty object, then Serde serializes the k/v pairs from field_set(). This was causing an erroneous closing brace } to be added after the serialized fields.

This is discussed here: #829 (comment)

[dependencies]
tracing = "=0.1.25"
tracing-serde = "=0.1.2"
tracing-subscriber = "=0.2.17"
use tracing_subscriber::fmt::format::FmtSpan;

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

    tracing::info_span!("broken_json").in_scope(|| {
    });

    tracing::info_span!("valid_json", "").in_scope(|| {
    });
}
{"timestamp":"Mar 28 19:08:44.323","level":"INFO","fields":{},"message":"new"},"target":"json_events"}
{"timestamp":"Mar 28 19:08:44.323","level":"INFO","fields":{},"message":"enter"},"target":"json_events","span":{"name":"broken_json"},"spans":[{"name":"broken_json"}]}
{"timestamp":"Mar 28 19:08:44.323","level":"INFO","fields":{},"message":"exit"},"target":"json_events"}
{"timestamp":"Mar 28 19:08:44.323","level":"INFO","fields":{},"message":"close","time.busy":"61.7µs","time.idle":"113µs"},"target":"json_events"}
{"timestamp":"Mar 28 19:08:44.323","level":"INFO","fields":{"message":"new"},"target":"json_events"}
{"timestamp":"Mar 28 19:08:44.323","level":"INFO","fields":{"message":"enter"},"target":"json_events","span":{"message":"","name":"valid_json"},"spans":[{"message":"","name":"valid_json"}]}
{"timestamp":"Mar 28 19:08:44.323","level":"INFO","fields":{"message":"exit"},"target":"json_events"}
{"timestamp":"Mar 28 19:08:44.323","level":"INFO","fields":{"message":"close","time.busy":"70.6µs","time.idle":"70.7µs"},"target":"json_events"}

Solution

This change aligns the size hint with the size of actual serialized data.

Serializing a spans `on_ACTION` events, when no fields are set on the
span, results in invalid JSON. This is because `serializier_map` was
getting a size hint for `self.0.metadata().fields().len()` then
serializing `self.0.fields.field_set()` instead. This resulted in the
fields key being set to an empty object, then Serde serializes the k/v
pairs from `field_set()`. This was causing an erroneous closing brace
`}` to be added after the serialized fields.

This change aligns the size hint with the actual serialized data.

Refs: tokio-rs#829 (comment)
@akinnane akinnane requested review from davidbarsky, hawkw and a team as code owners March 28, 2021 18:30
Copy link
Member

@hawkw hawkw left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

thanks for the fix, this looks good to me!

i had one minor suggestion about testing, but i'd be fine to merge this as it is currently if that change seems like a lot of unnecessary effort. up to you!

Comment on lines +656 to +672
#[test]
fn json_span_event() {
// Check span events serialize correctly.
// Discussion: https:/tokio-rs/tracing/issues/829#issuecomment-661984255
//
let expected = r#"{"timestamp":"fake time","level":"INFO","fields":{"message":"enter"},"target":"tracing_subscriber::fmt::format::json::test"}"#;
let collector = collector()
.flatten_event(false)
.with_current_span(false)
.with_span_list(false)
.with_span_events(FmtSpan::ENTER);

test_json(expected, collector, || {
tracing::info_span!("valid_json").in_scope(|| {});
});
}

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

take it or leave it, but since the issue here is that we were generating invalid JSON, it might be worth rewriting this test in the same style as the record_works test? this test actually attempts to parse the output as JSON and then makes assertions about its structure. this could be worth doing, since it would also implicitly assert that the output definitely does parse as JSON.

of course, since the hard-coded JSON string is valid JSON as well, this test is also fine as-is.

@hawkw hawkw merged commit d38f793 into tokio-rs:master Mar 31, 2021
hawkw added a commit that referenced this pull request Mar 31, 2021
…1333)

Serializing a spans `on_ACTION` events, when no fields are set on the
span, results in invalid JSON. This is because `serializier_map` was
getting a size hint for `self.0.metadata().fields().len()` then
serializing `self.0.fields.field_set()` instead. This resulted in the
fields key being set to an empty object, then Serde serializes the k/v
pairs from `field_set()`. This was causing an erroneous closing brace
`}` to be added after the serialized fields.

This change aligns the size hint with the actual serialized data.

Refs: #829 (comment)

Co-authored-by: Eliza Weisman <[email protected]>
hawkw added a commit that referenced this pull request Mar 31, 2021
…1333)

Serializing a spans `on_ACTION` events, when no fields are set on the
span, results in invalid JSON. This is because `serializier_map` was
getting a size hint for `self.0.metadata().fields().len()` then
serializing `self.0.fields.field_set()` instead. This resulted in the
fields key being set to an empty object, then Serde serializes the k/v
pairs from `field_set()`. This was causing an erroneous closing brace
`}` to be added after the serialized fields.

This change aligns the size hint with the actual serialized data.

Refs: #829 (comment)

Co-authored-by: Eliza Weisman <[email protected]>
hawkw added a commit that referenced this pull request Mar 31, 2021
…1333)

Serializing a spans `on_ACTION` events, when no fields are set on the
span, results in invalid JSON. This is because `serializier_map` was
getting a size hint for `self.0.metadata().fields().len()` then
serializing `self.0.fields.field_set()` instead. This resulted in the
fields key being set to an empty object, then Serde serializes the k/v
pairs from `field_set()`. This was causing an erroneous closing brace
`}` to be added after the serialized fields.

This change aligns the size hint with the actual serialized data.

Refs: #829 (comment)

Co-authored-by: Eliza Weisman <[email protected]>
@hawkw
Copy link
Member

hawkw commented Mar 31, 2021

@akinnane this fixes the issue described in #829, correct?

akinnane added a commit to akinnane/tracing that referenced this pull request Apr 6, 2021
Based on feedback by @hawkw, I've improved the test to parse the json
output. This is more specifc for the use bug and allows easier testing
of the different span state `on_events`.

Ref: tokio-rs#1333 (review)
akinnane added a commit to akinnane/tracing that referenced this pull request Apr 6, 2021
Based on feedback by @hawkw, I've improved the test for tokio-rs#1333 to parse
the json output. This is more specifc for the bug and allows easier
testing of the different span `on_events`.

Ref: tokio-rs#1333 (review)
hawkw added a commit that referenced this pull request 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 <[email protected]>
hawkw pushed a commit that referenced this pull request Apr 9, 2021
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)
hawkw added a commit that referenced this pull request 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 <[email protected]>
hawkw added a commit that referenced this pull request 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 <[email protected]>
hawkw added a commit that referenced this pull request Apr 30, 2021
# 0.2.18 (April 30, 2021)

### Deprecated

- Deprecated the `CurrentSpan` type, which is inefficient and largely
  superseded by the `registry` API ([#1321])

### Fixed

- **json**: Invalid JSON emitted for events in spans with no fields
  ([#1333])
- **json**: Missing span data for synthesized new span, exit, and close
  events ([#1334])
- **fmt**: Extra space before log lines when timestamps are disabled
  ([#1355])

### Added

- **env-filter**: Support for filters on spans whose names contain any
  characters other than `{` and `]` ([#1368])

Thanks to @Folyd, and new contributors @akinnane and @aym-v for
contributing to  this release!

[#1321]: #1321
[#1333]: #1333
[#1334]: #1334
[#1355]: #1355
[#1368]: #1368
hawkw added a commit that referenced this pull request May 1, 2021
# 0.2.18 (April 30, 2021)

### Deprecated

- Deprecated the `CurrentSpan` type, which is inefficient and largely
  superseded by the `registry` API ([#1321])

### Fixed

- **json**: Invalid JSON emitted for events in spans with no fields
  ([#1333])
- **json**: Missing span data for synthesized new span, exit, and close
  events ([#1334])
- **fmt**: Extra space before log lines when timestamps are disabled
  ([#1355])

### Added

- **env-filter**: Support for filters on spans whose names contain any
  characters other than `{` and `]` ([#1368])

Thanks to @Folyd, and new contributors @akinnane and @aym-v for
contributing to  this release!

[#1321]: #1321
[#1333]: #1333
[#1334]: #1334
[#1355]: #1355
[#1368]: #1368
hawkw added a commit that referenced this pull request Feb 4, 2022
# 0.1.3 (February 4, 2022)

This release adds *experimental* support for recording structured field
values using the [`valuable`] crate. See [this blog post][post] for
details on `valuable`.

Note that `valuable` support currently requires `--cfg
tracing_unstable`. See the documentation for details.

### Added

- **valuable**: Experimental support for serializing user-defined types
  using [`valuable`] and [`valuable-serde`] ([#1862])
- Support for serializing `f64` values ([#1507])

### Fixed

- Fixed incorrect size hint in `SerializeFieldSet` ([#1333])
- A number of documentation fixes

Thanks to @akinnane and @maxburke for contributing to this release!

[`valuable`]: https://crates.io/crates/valuable
[`valuable-serde`]: https://crates.io/crates/valuable-serde
[post]: https://tokio.rs/blog/2021-05-valuable
[#1862]: #1862
[#1507]: #1507
[#1333]: #1333

(I also noticed there was a missing changelog entry for v0.1.2, so I
fixed that while I was here)
hawkw added a commit that referenced this pull request Feb 4, 2022
# 0.1.3 (February 4, 2022)

This release adds *experimental* support for recording structured field
values using the [`valuable`] crate. See [this blog post][post] for
details on `valuable`.

Note that `valuable` support currently requires `--cfg
tracing_unstable`. See the documentation for details.

### Added

- **valuable**: Experimental support for serializing user-defined types
  using [`valuable`] and [`valuable-serde`] ([#1862])
- Support for serializing `f64` values ([#1507])

### Fixed

- Fixed incorrect size hint in `SerializeFieldSet` ([#1333])
- A number of documentation fixes

Thanks to @akinnane and @maxburke for contributing to this release!

[`valuable`]: https://crates.io/crates/valuable
[`valuable-serde`]: https://crates.io/crates/valuable-serde
[post]: https://tokio.rs/blog/2021-05-valuable
[#1862]: #1862
[#1507]: #1507
[#1333]: #1333

(I also noticed there was a missing changelog entry for v0.1.2, so I
fixed that while I was here)
kaffarell pushed a commit to kaffarell/tracing that referenced this pull request May 22, 2024
# 0.2.18 (April 30, 2021)

### Deprecated

- Deprecated the `CurrentSpan` type, which is inefficient and largely
  superseded by the `registry` API ([tokio-rs#1321])

### Fixed

- **json**: Invalid JSON emitted for events in spans with no fields
  ([tokio-rs#1333])
- **json**: Missing span data for synthesized new span, exit, and close
  events ([tokio-rs#1334])
- **fmt**: Extra space before log lines when timestamps are disabled
  ([tokio-rs#1355])

### Added

- **env-filter**: Support for filters on spans whose names contain any
  characters other than `{` and `]` ([tokio-rs#1368])

Thanks to @Folyd, and new contributors @akinnane and @aym-v for
contributing to  this release!

[tokio-rs#1321]: tokio-rs#1321
[tokio-rs#1333]: tokio-rs#1333
[tokio-rs#1334]: tokio-rs#1334
[tokio-rs#1355]: tokio-rs#1355
[tokio-rs#1368]: tokio-rs#1368
kaffarell pushed a commit to kaffarell/tracing that referenced this pull request May 22, 2024
# 0.1.3 (February 4, 2022)

This release adds *experimental* support for recording structured field
values using the [`valuable`] crate. See [this blog post][post] for
details on `valuable`.

Note that `valuable` support currently requires `--cfg
tracing_unstable`. See the documentation for details.

### Added

- **valuable**: Experimental support for serializing user-defined types
  using [`valuable`] and [`valuable-serde`] ([tokio-rs#1862])
- Support for serializing `f64` values ([tokio-rs#1507])

### Fixed

- Fixed incorrect size hint in `SerializeFieldSet` ([tokio-rs#1333])
- A number of documentation fixes

Thanks to @akinnane and @maxburke for contributing to this release!

[`valuable`]: https://crates.io/crates/valuable
[`valuable-serde`]: https://crates.io/crates/valuable-serde
[post]: https://tokio.rs/blog/2021-05-valuable
[tokio-rs#1862]: tokio-rs#1862
[tokio-rs#1507]: tokio-rs#1507
[tokio-rs#1333]: tokio-rs#1333

(I also noticed there was a missing changelog entry for v0.1.2, so I
fixed that while I was here)
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

2 participants