How to log structured fields

Short answer: Put the data in fields, not in the message text: info!(user_id = 42, "user logged in") prints user_id=42 after the message, where grep can count it and jq can aggregate it. Log errors through the sigils — ?value records the Debug form, %value records the Display form — and fmt().json() turns the output into one JSON object per event. Every example here also passes .with_ansi(false): the plain formatter writes color codes even when the output goes to a file, and the codes land between the field name and its value, breaking every query this page is about to run.

The previous article moved the log level out of the binary with RUST_LOG. This one is about what survives the filter. A line that says user 42 logged in can be read by a human, but counting logins per user from a file of sentences means a new regex every time the wording changes. A field is a named value first, prose second — and a named value can be counted, filtered, and averaged without ever parsing a sentence.

The message is not the place for data

Cargo.toml

[dependencies]
tracing = "0.1.44"
tracing-subscriber = { version = "0.3.23", features = ["env-filter", "json"] }

The env-filter feature is the previous article’s; json is the new one, and the JSON section at the bottom needs it. The examples assume a project created with cargo new structured-fields — the outputs name it, and a project with a different name prints that name instead.

Both calls in the loop below put the same fact in the log. One puts it in a field; the other formats it into the sentence:

src/main.rs

use tracing::info;
use tracing_subscriber::fmt;

fn main() {
    fmt().with_ansi(false).with_max_level(tracing::Level::INFO).init();
    for user_id in [7, 42, 42, 99] {
        info!(user_id, "user logged in");
        info!("user {user_id} logged in");
    }
}

2026-10-29T20:56:04.547949Z  INFO structured_fields: user logged in user_id=7
2026-10-29T20:56:04.548179Z  INFO structured_fields: user 7 logged in
2026-10-29T20:56:04.548191Z  INFO structured_fields: user logged in user_id=42
2026-10-29T20:56:04.548200Z  INFO structured_fields: user 42 logged in
2026-10-29T20:56:04.548208Z  INFO structured_fields: user logged in user_id=42
2026-10-29T20:56:04.548216Z  INFO structured_fields: user 42 logged in
2026-10-29T20:56:04.548222Z  INFO structured_fields: user logged in user_id=99
2026-10-29T20:56:04.548230Z  INFO structured_fields: user 99 logged in

(The timestamp differs on every run; the rest is what you will see.)

The second call is an ordinary format string — tracing macros accept the same {user_id} capture syntax println! does. The two lines carry the same information, and on a screen they read the same. In a file they are not equal. The first line’s data has a name that never changes with the wording; the second is a sentence that happens to contain a number. Rewrite the sentence as “login for user 42 accepted” and every query written against the old wording dies, while user_id= keeps working.

The color codes that break grep

.with_ansi(false) is in every example on this page, and it is not a styling preference. The plain formatter emits ANSI color codes whether stdout is a terminal or a redirected file — nothing in tracing-subscriber checks which one it is. In a terminal the codes are the colors. In a file they are bytes, and one of them sits between the field name and its value: user_id, then an escape sequence, then =, then another, then 7. Run the program without the flag, redirect to a file, and grep -o 'user_id=[0-9]*' app.log — the pattern every query below uses — matches nothing at all. No error, just zero matches, with the log full of the data you asked for.

With the flag set, the file is plain text and the queries work:

cargo run > app.log
grep -o 'user_id=[0-9]*' app.log | sort | uniq -c

   2 user_id=42
   1 user_id=7
   1 user_id=99

Four events, one command, logins per user. The same question against the sentence lines is a regex written for one particular wording — and it still cannot tell “user 42 logged in” from “login for user 42 accepted” if both wordings are ever in the file at once.

Errors: Debug or Display

Fields natively hold integers, floats, bools, and strings. An error type is none of those, so it goes through one of the two sigils:

src/main.rs

use std::io;
use tracing::info;
use tracing_subscriber::fmt;

fn main() {
    fmt().with_ansi(false).with_max_level(tracing::Level::INFO).init();
    let err = io::Error::other("disk full");
    info!(error = ?err, "read failed");
    info!(?err, "read failed");
    info!(error = %err, "read failed");
    info!(retries = 3u32, fast = true, ratio = 0.5, name = "grace", "diagnostics");
}

▶Run this in the Rust Playground

2026-10-29T20:55:15.724729Z  INFO structured_fields: read failed error=Custom { kind: Other, error: "disk full" }
2026-10-29T20:55:15.724741Z  INFO structured_fields: read failed err=Custom { kind: Other, error: "disk full" }
2026-10-29T20:55:15.724757Z  INFO structured_fields: read failed error=disk full
2026-10-29T20:55:15.724767Z  INFO structured_fields: diagnostics retries=3 fast=true ratio=0.5 name="grace"

?err records the Debug form, %err records the Display form — the same distinction as println!("{err:?}") versus println!("{err}"). The bare ?err is the shorthand the first article’s bare user_id follows: no field name given, so the variable’s own name — err — becomes it.

Which one to reach for: Debug exists for every type, which makes it the fallback that always compiles — but for an error, what it records is the wrapper (Custom { kind: Other, error: "disk full" }), not the message. Display records what a human would have seen from println!. The convention worth copying is error = %err for the message an operator reads, ? only when the type has no useful Display.

The native types go bare, and each keeps its shape — the diagnostics line at the end of the output above shows all of them in one event. retries=3 is a number, not "3"; name="grace" is a string, and gets the quotes; ratio=0.5 survives as a float that jq can average. Anything that is not one of these types goes through ? or % — there is no third option, and silently formatting a struct into the message string is the mistake this page started with.

JSON, when grep is not enough

key=value text carried the counting queries, but it stops there: “user 42’s average latency” out of flat text means grep, cut, and awk stacked on one fragile column layout. With the json feature already in Cargo.toml, the subscriber has a machine-readable mode, and the change is one builder call:

src/main.rs

use tracing::info;
use tracing_subscriber::fmt;

fn main() {
    fmt().json().with_max_level(tracing::Level::INFO).init();
    for (user_id, latency_ms) in [(7, 3), (42, 11), (42, 5), (99, 2)] {
        info!(user_id, latency_ms, "user logged in");
    }
}

{"timestamp":"2026-10-29T20:55:16.396510Z","level":"INFO","fields":{"message":"user logged in","user_id":7,"latency_ms":3},"target":"structured_fields"}
{"timestamp":"2026-10-29T20:55:16.397030Z","level":"INFO","fields":{"message":"user logged in","user_id":42,"latency_ms":11},"target":"structured_fields"}
{"timestamp":"2026-10-29T20:55:16.397110Z","level":"INFO","fields":{"message":"user logged in","user_id":42,"latency_ms":5},"target":"structured_fields"}
{"timestamp":"2026-10-29T20:55:16.397154Z","level":"INFO","fields":{"message":"user logged in","user_id":99,"latency_ms":2},"target":"structured_fields"}

One JSON object per event, one line each, the fields nested under "fields" next to the message. No .with_ansi(false) this time — the JSON formatter has no colors to turn off. The macros did not change: the same info! calls from the first section feed either formatter, because the format was always the subscriber’s decision, not the call site’s.

Now the file is a dataset:

cargo run > app.json
jq 'select(.fields.user_id == 42)' app.json

{
  "timestamp": "2026-10-29T20:55:16.397030Z",
  "level": "INFO",
  "fields": {
    "message": "user logged in",
    "user_id": 42,
    "latency_ms": 11
  },
  "target": "structured_fields"
}
{
  "timestamp": "2026-10-29T20:55:16.397110Z",
  "level": "INFO",
  "fields": {
    "message": "user logged in",
    "user_id": 42,
    "latency_ms": 5
  },
  "target": "structured_fields"
}

jq pretty-prints by default; the two events for user 42 are the whole answer. And the question grep could not ask:

jq -s '[.[] | select(.fields.user_id == 42) | .fields.latency_ms] | add / length' app.json

8

Eight milliseconds, the average of 11 and 5, computed over the log file with no regex and no column positions. That is the difference between a log you read and a log you query — and it was all set up by the field name in the macro call, not by anything the formatter did.

The level is now a runtime setting, and the fields are named, typed, and machine-readable. The next article leaves the log for a moment to build one of the things a program like this eventually needs: a global value, created once, on first use.