Logging structs and vectors of structs via JSON subscriber (and Valuable) ... is broken?

[s-m-e]

Bug Report

Version

├── tracing v0.1.40
│   ├── tracing-attributes v0.1.27 (proc-macro)
│   └── tracing-core v0.1.32
├── tracing-subscriber v0.3.18
│   ├── tracing-core v0.1.32 (*)
│   ├── tracing-log v0.2.0
│   │   └── tracing-core v0.1.32 (*)
│   └── tracing-serde v0.1.3
│       └── tracing-core v0.1.32 (*)

Platform

Linux e2 5.15.0-124-generic #134-Ubuntu SMP Fri Sep 27 20:20:17 UTC 2024 x86_64 x86_64 x86_64 GNU/Linux

rustc 1.81.0 (eeb90cda1 2024-09-04)

Crates

[dependencies]
tracing = "0.1"
tracing-subscriber = { version = "0.3", features = ["json"] }
valuable = { version = "0.1.0", features = ["derive"] }

Description

I tried to make sense of this and this in the context of logging JSON, which I could not really make work. Minimal example:

use std::fmt;

use tracing::info;
use tracing_subscriber;
use valuable::Valuable;

#[derive(Clone, Debug, Valuable)]
struct Foo {
    bar: String,
}

impl fmt::Display for Foo {
    fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result {
        write!(f, "<Foo bar={}>", self.bar)
    }
}

fn vec2str<T: fmt::Display>(data: &Vec<T>) -> String {
    let mut buffer = String::new();
    for item in data {
        buffer.push_str(&format!("{}", item));
    };
    buffer
}

fn main() {
    tracing_subscriber::fmt()
        .json()
        .with_max_level(tracing::Level::DEBUG)
        .with_current_span(false)
        .init();

    // WORKS
    //   Actual output: {"timestamp":"2024-11-20T15:00:24.868450Z","level":"INFO","fields":{"msg":"Hello world!"},"target":"rusttest"}
    info!(msg = "Hello world!");

    let stuff = Foo {
        bar: "abc".to_string(),
    };
    let otherstuff: Vec<Foo> = vec![
        Foo {bar: "def".to_string()},
        Foo {bar: "ghi".to_string()},
    ];

    println!("{}", stuff);  // just debugging
    println!("{}", vec2str(&otherstuff));  // just debugging

    // DOES NOT WORK CORRECTLY:
    //   Expected: {"timestamp":"2024-11-20T15:00:24.868450Z","level":"INFO","fields":{"msg":{"bar": "abc"}},"target":"rusttest"}
    //   In reality: {"timestamp":"2024-11-20T15:00:24.868450Z","level":"INFO","fields":{"msg":"Foo { bar: \"abc\" }"},"target":"rusttest"}
    info!(msg = stuff.as_value());

    // DOES NOT WORK CORRECTLY:
    //   Expected: {"timestamp":"2024-11-20T15:00:24.868450Z","level":"INFO","fields":{"msg":[{"bar": "def"}, {"bar": "ghi"}]},"target":"rusttest"}
    //   In reality: {"timestamp":"2024-11-20T15:00:24.868450Z","level":"INFO","fields":{"msg":"[Foo { bar: \"def\" }, Foo { bar: \"ghi\" }]"},"target":"rusttest"}
   info!(msg = otherstuff.as_value());

}

The JSON output is not really valid JSON.

Am I assuming correctly that, after reading #1570 and this comment on it, what I am attempting to do is not fully supported (yet)? Or am I missing something?

[s-m-e]

Just in case someone else runs into this, workaround (for myself) for the time being:

use std::io::Error;

use serde::Serialize;
use serde_json::to_string;
use chrono;

#[derive(Serialize)]
struct Log<T> {
    timestamp: String,
    level: String,
    fields: T,
    target: String,
}

fn log<T: Serialize>(level: String, data: T) -> Result<(), Error> {
    let log: Log<T> = Log {
        timestamp: chrono::offset::Utc::now().to_rfc3339_opts(chrono::SecondsFormat::Micros, true),
        level: level,
        fields: data,
        target: "tool::log".to_string(),
    };
    println!("{}", to_string(&log)?); // JSON
    Ok(())
}

fn info_<T: Serialize>(data: T) -> Result<(), Error> {
    log("INFO".to_string(), data)?;
    Ok(())
}

#[derive(Serialize)]
struct Msg1<'a> {
    msg: &'a Foo,
}

#[derive(Serialize)]
struct Msg2<'a> {
    msg: &'a Vec<Foo>,
}

... which allows me to do ...

info_(Msg1 { msg: &stuff })?;
info_(Msg2 { msg: &otherstuff })?;

... resulting in the desired output and otherwise, well, generating output that fits nicely into what tracing is doing otherwise.

[nicolas-vivot]

What you tried to do in the first place is correct and was supported until recently.

I have just run a cargo update since it wasn't done for a while on one of my projects, and found out that the json logging is completely broken with the latest version. (same as you)

Based on the time of your message, it seems that it has been broken for at least the last two releases.

Thank you for the workaround, but for me going without Valuable and have to refactor this on an entire code base will be a no go.

[nicolas-vivot]

After digging a bit, it looks like in my case, i was also pulling tracing-serde in an older version somewhere else in my cargo workspace.
This resulted in having two versions and introducing probably this issue.

After updating everything to the same version to align with what's coming with tracing-subscriber, this issue is gone and logging as json for structure/Valuable works as expected.

Solution: verify your dependencies on tracing-serde and make sure they align with what you have for other tracing crates.

[s-m-e]

@nicolas-vivot Could you post the versions of all components as they are working for you?