fmt layer is append-only causing to to grow forever while Span::record replaces values

[Fuuzetsu]

Bug Report

Version

[nix-develop]$ cargo tree
infinite-tracing-fmt v0.1.0 (/home/shana/programming/infinite-tracing-fmt)
├── tracing v0.1.36
│   ├── cfg-if v1.0.0
│   ├── pin-project-lite v0.2.9
│   └── tracing-core v0.1.29
│       └── once_cell v1.15.0
└── tracing-subscriber v0.3.15
    ├── sharded-slab v0.1.4
    │   └── lazy_static v1.4.0
    ├── thread_local v1.1.4
    │   └── once_cell v1.15.0
    └── tracing-core v0.1.29 (*)

Platform

Linux aya 5.15.67 #1-NixOS SMP Thu Sep 8 10:32:54 UTC 2022 x86_64 GNU/Linux

Crates

tracing-subscriber

Description

We have some code where we have a long-running tracing::Span with a bunch of fields. Over the course of its life, we update the values of those fields: this seems to be explicitly allowed and documented.

However, we also use the tracing_subscriber::fmt::Layer in the same program and every time we record a replacement of a field in the Span, the new value is appended to the formatted fields instead of replaced as we were expecting. This is unexpected: I don't care to see old values, I'm trying to explicitly replace them. I proved small code sample below that hopefully makes it obvious what I mean:

fn main() {
    tracing_subscriber::fmt::init();

    let mut loop_ix = 0usize;
    let span = tracing::span!(tracing::Level::INFO, "eternal_span", loop_ix);
    let _guard = span.enter();

    while loop_ix < 5 {
        loop_ix += 1;
        // Update loop index in the span.
        span.record("loop_ix", loop_ix);
        tracing::info!("Something.");
    }
}

[nix-develop]$ cargo run
    Blocking waiting for file lock on build directory
   Compiling tracing-core v0.1.29
   Compiling tracing-subscriber v0.3.15
   Compiling tracing v0.1.36
   Compiling infinite-tracing-fmt v0.1.0 (/home/shana/programming/infinite-tracing-fmt)
    Finished dev [unoptimized + debuginfo] target(s) in 2.14s
     Running `target/debug/infinite-tracing-fmt`
2022-10-03T03:07:05.470025Z  INFO eternal_span{loop_ix=0 loop_ix=1}: infinite_tracing_fmt: Something.
2022-10-03T03:07:05.470049Z  INFO eternal_span{loop_ix=0 loop_ix=1 loop_ix=2}: infinite_tracing_fmt: Something.
2022-10-03T03:07:05.470061Z  INFO eternal_span{loop_ix=0 loop_ix=1 loop_ix=2 loop_ix=3}: infinite_tracing_fmt: Something.
2022-10-03T03:07:05.470072Z  INFO eternal_span{loop_ix=0 loop_ix=1 loop_ix=2 loop_ix=3 loop_ix=4}: infinite_tracing_fmt: Something.
2022-10-03T03:07:05.470084Z  INFO eternal_span{loop_ix=0 loop_ix=1 loop_ix=2 loop_ix=3 loop_ix=4 loop_ix=5}: infinite_tracing_fmt: Something.

[package]
name = "infinite-tracing-fmt"
version = "0.1.0"
edition = "2021"

# See more keys and their definitions at https://doc.rust-lang.org/cargo/reference/manifest.html

[dependencies]
tracing = { version = "0.1", default-features = false }
tracing-subscriber = { version = "0.3", default-features = false, features = ["fmt"] }

I would like to only see a single loop_ix in the output but I see each one.

I have chased down the code inside tracing and I think I understand roughly what happens on Span::record. The default fmt layer is backed by DefaultFields and stores the formatted data inside FormattedFields<DefaultFields> which is just some String storage. On recording a value, it ends up calling add_fields with the storage from inside the span which just adds an space to the back then invokes format_fields. format_fields makes DefaultVisitor and invokes a record method on that which eventually goes through various record_* methods and ends up in record_debug. record_debug then actually handles the formatting of the value and appends it to the writer, which is the original mutable String.

It does not track what fields it has already formatted – fine. But in that case it seems like it's incompatible outside the box with replacing values in spans.

Is this expected behaviour? I suspect yes: in which case, what's the right thing to do here?

[Fuuzetsu]

I suspect yes: in which case, what's the right thing to do here?

I suspect that the suggested thing to do is something like JsonFields which is store a mapping of field to (formatted) value and overwrite on record. I'll try.

Still, unsure if this shouldn't just be the default behaviour of original layer.

[Fuuzetsu]

I suspect yes: in which case, what's the right thing to do here?

I suspect that the suggested thing to do is something like JsonFields which is store a mapping of field to (formatted) value and overwrite on record. I'll try.

Still, unsure if this shouldn't just be the default behaviour of original layer.

OK, I did some digging and tried to mimic the JSON implementation. I've come to realise that building on top of fmt was a mistake because your storage is always FormattedFields<N> where you can specify N: but FormattedFields is just a String-backed storage. This means you basically have to "smuggle" state inside and when trying to modify it, parse it, modify and reserialise it. Very inefficient. There are TODOs about it in the JSON formatter.

So I guess this means a real solution will implement a new layer instead and use whatever state it requires in ExtensionsMut rather than being stuck with FormattedFields<N>?

[Fuuzetsu]

I have today discovered that tracing-journald has exactly the same problem: it stores things in serialised Vec<u8> and repeated invocations to Span::record will append to this vector indefinitely whereas it probably should be replacing the old fields.

[davidbarsky]

Is this expected behaviour? I suspect yes: in which case, what's the right thing to do here?

Yes, this is intended behavior. Unfortunately, rewriting values requires maintaining state to index, mutate and reformat the log entry. A better way would be to make your own Layer and update these values as you need to. Alternatively, I'd emit an event for each loop iteration, but I can see how it's nice to update a span value.

[Fuuzetsu]

OK. I guess we can close the ticket?

I suppose json formatter should be own layer to performance reasons and tracing-journald should also be updated to only emit one field but we can open separate tickets for those if needed...

[Sushisource]

I've just run into this - and the built-in JSON (or compact, or full, whatever) formatter would be great to be able to use in situations like these. They look nice, they're flexible, they work well. Having to go implement your own layer just to avoid this duplication is a pretty big lift for something that seems like it ought to work by default.

So just throwing my 2c out there to keep this open and hopefully get a fix in for it

[davidbarsky]

I'm going to close this issue in favor of #2123 in order to make things a little more managable.