Span has malformed fields with single field

[skyvine]

Bug Report

Version

tracing_bug_reproducer v0.1.0 (/home/user/repositories/tracing_bug_reproducer)
├── tracing v0.1.41
│   ├── tracing-attributes v0.1.30 (proc-macro)
│   └── tracing-core v0.1.34
├── tracing-subscriber v0.3.19
│   ├── tracing-core v0.1.34 (*)
│   ├── tracing-log v0.2.0
│   │   └── tracing-core v0.1.34 (*)
│   └── tracing-serde v0.2.0
│       └── tracing-core v0.1.34 (*)

Platform

Linux foreign-guix 6.14.4-1.qubes.fc37.x86_64 #1 SMP PREEMPT_DYNAMIC Sat Apr 26 05:37:41 GMT 2025 x86_64 GNU/Linux

Description

When logging an event with a stringified UUID as a field in a span, I get an error message stating that the span "had malformed fields! this is a bug."

This is complete code for reproducing the issue:

use tracing::{event, span, Level};
use tracing_subscriber::fmt;
use uuid::Uuid;

fn main() {
    fmt().event_format(fmt::format().json()).init();
    let request_id = Uuid::new_v4();
    let _entered_guard = span!(Level::ERROR, "UUT", %request_id).entered();
    event!(Level::ERROR, "Reproduce the bug.");
}

This is the full error message with RUST_BACKTRACE=1:

thread 'main' panicked at /home/user/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tracing-subscriber-0.3.19/src/fmt/format/json.rs:197:49:
span 'UUT' had malformed fields! this is a bug.
  error: expected value at line 1 column 1
  fields: FormattedFields { fields: "\u{1b}[3mrequest_id\u{1b}[0m\u{1b}[2m=\u{1b}[0md857f106-2623-40f1-a0a6-62d5bf7fea6c", formatter: tracing_subscriber::fmt::format::DefaultFields, was_ansi: true }
stack backtrace:
   0: __rustc::rust_begin_unwind
             at /rustc/17067e9ac6d7ecb70e50f92c1944e545188d2359/library/std/src/panicking.rs:697:5
   1: core::panicking::panic_fmt
             at /rustc/17067e9ac6d7ecb70e50f92c1944e545188d2359/library/core/src/panicking.rs:75:14
   2: <tracing_subscriber::fmt::format::json::SerializableSpan<Span,N> as serde::ser::Serialize>::serialize
             at /home/user/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tracing-subscriber-0.3.19/src/fmt/format/json.rs:197:49
   3: <serde_json::ser::Compound<W,F> as serde::ser::SerializeMap>::serialize_value
             at /home/user/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/serde_json-1.0.140/src/ser.rs:654:22
   4: serde::ser::SerializeMap::serialize_entry
             at /home/user/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/serde-1.0.219/src/ser/mod.rs:1816:9
   5: tracing_subscriber::fmt::format::json::<impl tracing_subscriber::fmt::format::FormatEvent<S,N> for tracing_subscriber::fmt::format::Format<tracing_subscriber::fmt::format::json::Json,T>>::format_event::{{closure}}
             at /home/user/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tracing-subscriber-0.3.19/src/fmt/format/json.rs:291:21
   6: tracing_subscriber::fmt::format::json::<impl tracing_subscriber::fmt::format::FormatEvent<S,N> for tracing_subscriber::fmt::format::Format<tracing_subscriber::fmt::format::json::Json,T>>::format_event
             at /home/user/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tracing-subscriber-0.3.19/src/fmt/format/json.rs:327:9
   7: <tracing_subscriber::fmt::fmt_layer::Layer<S,N,E,W> as tracing_subscriber::layer::Layer<S>>::on_event::{{closure}}
             at /home/user/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tracing-subscriber-0.3.19/src/fmt/fmt_layer.rs:986:16
   8: std::thread::local::LocalKey<T>::try_with
             at /home/user/.rustup/toolchains/stable-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/std/src/thread/local.rs:311:12
   9: std::thread::local::LocalKey<T>::with
             at /home/user/.rustup/toolchains/stable-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/std/src/thread/local.rs:275:15
  10: <tracing_subscriber::fmt::fmt_layer::Layer<S,N,E,W> as tracing_subscriber::layer::Layer<S>>::on_event
             at /home/user/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tracing-subscriber-0.3.19/src/fmt/fmt_layer.rs:970:9
  11: <tracing_subscriber::layer::layered::Layered<L,S> as tracing_core::subscriber::Subscriber>::event
             at /home/user/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tracing-subscriber-0.3.19/src/layer/layered.rs:153:9
  12: <tracing_subscriber::layer::layered::Layered<L,S> as tracing_core::subscriber::Subscriber>::event
             at /home/user/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tracing-subscriber-0.3.19/src/layer/layered.rs:152:9
  13: <tracing_subscriber::fmt::Subscriber<N,E,F,W> as tracing_core::subscriber::Subscriber>::event
             at /home/user/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tracing-subscriber-0.3.19/src/fmt/mod.rs:408:9
  14: tracing_core::dispatcher::Dispatch::event
             at /home/user/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tracing-core-0.1.34/src/dispatcher.rs:612:13
  15: tracing_core::event::Event::dispatch::{{closure}}
             at /home/user/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tracing-core-0.1.34/src/event.rs:35:13
  16: tracing_core::dispatcher::get_default
             at /home/user/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tracing-core-0.1.34/src/dispatcher.rs:388:16
  17: tracing_core::event::Event::dispatch
             at /home/user/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tracing-core-0.1.34/src/event.rs:34:9
  18: tracing_bug_reproducer::main::{{closure}}
             at /home/user/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tracing-0.1.41/src/macros.rs:875:17
  19: tracing_bug_reproducer::main
             at ./src/main.rs:9:5
  20: core::ops::function::FnOnce::call_once
             at /home/user/.rustup/toolchains/stable-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/core/src/ops/function.rs:250:5

[skyvine]

Note: this issue only occurs with the JSON formatter. Using full, pretty, or compact produces the expected output.

[jplatte]

One way to structure the description:

Please, for fucks sake, do not generate issue reports with an LLM. I'm not going to close this one since I'm not one of the regular maintainers of this crate, but if I was, I would delete this issue to prevent anybody from wasting time on it.

[skyvine]

I did not generate this with an LLM. That line was part of the issue template (you can double-check this by clicking on "new issue", then selecting the "Bug Report" option, and looking at the default text that appears under the "Description" heading) and I neglected to remove it. I discovered this issue while working on https://github.com/skyvine/rust-todo and created a minimal reproducer instead of throwing my whole project at you.

[jplatte]

Right. It did not seem like the usual AI slop but that line looked like a clear indicator. Sorry for the language. I will try to do better.

I'll get a PR up to turn that part of the issue template into a comment, so it doesn't end up in actual issue reports if one forgets to remove it. (turns out it's already in a comment)

[skyvine]

I haven't worked with GitHub much recently so I didn't realize those sections were comments. I imagine that the way some people use LLMs can be quite frustrating.

It turns out this isn't related to using a UUID, I have the same issue with:

use tracing::{event, span, Level};
use tracing_subscriber::fmt;

fn main() {
    fmt().event_format(fmt::format().json()).init();
    let _entered_guard = span!(Level::ERROR, "UUT", request_id = "suut").entered();
    event!(Level::ERROR, "Reproduce the bug.");
}