Guidelines regarding structured logging usage

WGH- commented

2026-01-07 14:34:21 -06:00

(Migrated from github.com)

What data should be put into structured logging attributes? Everything? Or only unimportant meta-information? If everything, should text message duplicate data already included in KV attributes?

// 1. only minor meta-information
log::error!(target: "pusher", "Push for client {uuid} failed: {err}");
// 2. everything, text message duplicates data
log::error!(target: "pusher", uuid:?, err:%; "Push for client {uuid} failed: {err}");
// 3. everything, text message doesn't include data logged into kv attributes
log::error!(target: "pusher", uuid:?, err:%; "Push for client failed");

This option seems inferior to me, as you can't effectively filter log entries by error or client.
Some loggers, notably, env_logger in its default configuration, will print both message and KVs to the console, which is redundant and ugly. However, it works fine for systemd-journal-logger: journalctl prints only the text message by default (+ timestamp). And you can also filter by KV attributes, as they're stored as custom journal fields.
Some loggers, notably, systemd-journal-logger, will store only the text message into MESSAGE journal field, and store the KVs as custom journal fields. journalctl will only show the text, and important error details can only be retrieved with journalctl -o verbose, and its output is too noisy to use for typical log-reading activities. In contrast, this record is rendered perfectly by env_logger: message key1=value1 key2=value2 ...

I think log is missing concrete guidelines regarding stuctured logging usage. Although output format is configurable in many loggers, it isn't in systemd-journal-logger, and you're still out of luck if combine different libraries that log using different conventions.

/cc @swsnr

What data should be put into structured logging attributes? Everything? Or only unimportant meta-information? If everything, should text message duplicate data already included in KV attributes? ```rust // 1. only minor meta-information log::error!(target: "pusher", "Push for client {uuid} failed: {err}"); // 2. everything, text message duplicates data log::error!(target: "pusher", uuid:?, err:%; "Push for client {uuid} failed: {err}"); // 3. everything, text message doesn't include data logged into kv attributes log::error!(target: "pusher", uuid:?, err:%; "Push for client failed"); ``` 1. This option seems inferior to me, as you can't effectively filter log entries by error or client. 2. Some loggers, notably, [`env_logger`](https://docs.rs/env_logger/) in its default configuration, will print both message and KVs to the console, which is redundant and ugly. However, it works fine for [`systemd-journal-logger`](https://docs.rs/systemd-journal-logger/): `journalctl` prints only the text message by default (+ timestamp). And you can also filter by KV attributes, as they're stored as custom journal fields. 3. Some loggers, notably, [`systemd-journal-logger`](https://docs.rs/systemd-journal-logger/), will store only the text message into `MESSAGE` journal field, and store the KVs as custom journal fields. `journalctl` will only show the text, and important error details can only be retrieved with `journalctl -o verbose`, and its output is too noisy to use for typical log-reading activities. In contrast, this record is rendered perfectly by [`env_logger`](https://docs.rs/env_logger/): `message key1=value1 key2=value2 ...` I think `log` is missing concrete guidelines regarding stuctured logging usage. Although output format is configurable in many loggers, [it isn't in `systemd-journal-logger`](https://codeberg.org/swsnr/systemd-journal-logger.rs/pulls/69), and you're still out of luck if combine different libraries that log using different conventions. /cc @swsnr

Thomasdezeeuw commented

2026-01-08 04:15:34 -06:00

(Migrated from github.com)

I agree that some guidelines on how to use key-values would be useful. I'll write down some of my thoughts to get started. Feedback is welcome!

From my point of view the most important thing for this (or pretty much anything related to logging) is what are you interested in doing once the logs are written? For example, do you want to be able to quickly filter the logs on a given value? Then it makes sense to log that as a separate key-value pair. If the value don't have a know set of values, i.e. it's not a number or a (kind of) enum, then I think it makes more sense to put it in the log message.

To give a concrete example let's start with errors. The error's text message you'll likely want to include in the log message, i.e. log::error!("some error happened: {err}"), and not as separate key-value pair. If your error also contains something like an error code (e.g. Rustc error codes) that should probably be logged as a separate key-value pair so that you can use that as a filter when querying the logs.

Another thing to consider is if the data logged in a single record can be logically separated. For example when logging HTTP requests you might want to add the HTTP method, path, version, etc. as key-value pairs as they can be seen as separate data (about the same thing). And again it makes for easier filtering/querying of logs.

Finally, I would also suggest to think about any processing you want to do with the logs. Keeping with the HTTP requests logging example, you might want to calculate the min/max/avg/etc. response times. Logging the response times as a key-value pair would make this much easier than having to extract that from a text message, i.e. log::info!(response_time; "request"); over log::info!("request, response_time={}").

I agree that some guidelines on how to use key-values would be useful. I'll write down some of my thoughts to get started. Feedback is welcome! From my point of view the most important thing for this (or pretty much anything related to logging) is what are you interested in doing once the logs are written? For example, do you want to be able to quickly filter the logs on a given value? Then it makes sense to log that as a separate key-value pair. If the value don't have a know set of values, i.e. it's not a number or a (kind of) enum, then I think it makes more sense to put it in the log message. To give a concrete example let's start with errors. The error's text message you'll likely want to include in the log message, i.e. `log::error!("some error happened: {err}")`, and not as separate key-value pair. If your error also contains something like an error code (e.g. [Rustc error codes](https://doc.rust-lang.org/error_codes/error-index.html)) that should probably be logged as a separate key-value pair so that you can use that as a filter when querying the logs. Another thing to consider is if the data logged in a single record can be logically separated. For example when logging HTTP requests you might want to add the HTTP method, path, version, etc. as key-value pairs as they can be seen as separate data (about the same thing). And again it makes for easier filtering/querying of logs. Finally, I would also suggest to think about any processing you want to do with the logs. Keeping with the HTTP requests logging example, you might want to calculate the min/max/avg/etc. response times. Logging the response times as a key-value pair would make this much easier than having to extract that from a text message, i.e. `log::info!(response_time; "request");` over `log::info!("request, response_time={}")`.

👍 1

WGH- commented

2026-01-08 06:20:24 -06:00

(Migrated from github.com)

For example, do you want to be able to quickly filter the logs on a given value? Then it makes sense to log that as a separate key-value pair. If the value don't have a know set of values, i.e. it's not a number or a (kind of) enum, then I think it makes more sense to put it in the log message.

I'd still put errors into structured attributes, even in cases they're not really simple enums (e.g. plain OS error enriched with dynamic anyhow context). Even if you have to resort to text grep, it's still better to grep a single attribute rather than grepping entire completely unstructured message.

> For example, do you want to be able to quickly filter the logs on a given value? Then it makes sense to log that as a separate key-value pair. If the value don't have a know set of values, i.e. it's not a number or a (kind of) enum, then I think it makes more sense to put it in the log message. I'd still put errors into structured attributes, even in cases they're not really simple enums (e.g. plain OS error enriched with dynamic `anyhow` context). Even if you have to resort to text grep, it's still better to grep a single attribute rather than grepping entire completely unstructured message.

KodrAus commented

2026-01-09 16:25:40 -06:00

(Migrated from github.com)

Great question @WGH- 👍

Personally, I'd advocate for 2: duplicate any relevant properties interpolated into your text message as structured fields too. This is probably something we'd do in the macros for you, were it not for macro_rules giving us no way to introspect the format string. They're in that privileged text message because they're the most important pieces of information for understanding the log event, so chances are they're also useful as structured data too.

For errors, you can capture them as an instance of the Error trait using the :err capturing modifier:

log::error!(target: "pusher", uuid:?, err:err; "Push for client {uuid} failed: {err}")

Targets can then specialize their handling of that err property to print a full cause chain for example based on its Error implementation instead of just having to work with whatever its Debug or Display implementation had.

As for what to include as structured properties, I think @Thomasdezeeuw summed it up nicely; capturing anything that will assist analysis on the logs later, without having to try parse relevant pieces of information out of raw text logs. Contextual information that correlates multiple logs together is especially useful.

I think we could also benefit from some recommend conventions on naming for various well-known properties too, like errors, trace/span/correlation ids etc.

Great question @WGH- :+1: Personally, I'd advocate for 2: duplicate any relevant properties interpolated into your text message as structured fields too. This is probably something we'd do in the macros for you, were it not for `macro_rules` giving us no way to introspect the format string. They're in that privileged text message because they're the most important pieces of information for understanding the log event, so chances are they're also useful as structured data too. For errors, you can capture them as an instance of the `Error` trait using the `:err` capturing modifier: ```rust log::error!(target: "pusher", uuid:?, err:err; "Push for client {uuid} failed: {err}") ``` Targets can then specialize their handling of that `err` property to print a full cause chain for example based on its `Error` implementation instead of just having to work with whatever its `Debug` or `Display` implementation had. As for what to include as structured properties, I think @Thomasdezeeuw summed it up nicely; capturing anything that will assist analysis on the logs later, without having to try parse relevant pieces of information out of raw text logs. Contextual information that correlates multiple logs together is especially useful. I think we could also benefit from some recommend conventions on naming for various well-known properties too, like errors, trace/span/correlation ids etc.

Thomasdezeeuw commented

2026-01-10 03:02:28 -06:00

(Migrated from github.com)

I think we could also benefit from some recommend conventions on naming for various well-known properties too, like errors, trace/span/correlation ids etc.

Talking about naming we should also add some basics, like what kind of casing should be used. I've always used snake casing (i.e. some_field) to match the naming of variables.

> I think we could also benefit from some recommend conventions on naming for various well-known properties too, like errors, trace/span/correlation ids etc. Talking about naming we should also add some basics, like what kind of casing should be used. I've always used snake casing (i.e. `some_field`) to match the naming of variables.

tisonkun commented

2026-06-05 21:46:14 -05:00

(Migrated from github.com)

Hi @WGH-!

I'd share a data point from logforth where we use it to report our database's (ScopeDB's) logs to multiple destinations (stdout, files, opentelemetry endpoints).

Typically, our log statements looks like:

// error in message
log::warn!("failed to cancel execution task: {err:?}");

// full parameterized
log::info!(
    target: "ingest",
    method:% = request.method(),
    uri:% = request.uri(),
    tenant_id:% = identity.tenant_id.as_str(),
    format:% = format,
    size:% = humansize::format_size(data_size, humansize::BINARY);
    "{:?}", req.statement
);

// mixed
log::error!(
    target: "statement",
    statement_id:% = statement_id,
    tenant_id:% = statement_context.tenant_id.as_str();
    "statement failed locally in {:.3}s: {}\nexecution error: {err:?}\nexplain analyze: \n{}",
    Timestamp::now().duration_since(started).as_secs_f64(),
    prepared.statement,
    report,
);

We previously tried to put err in the kvs but noticed that when developing applications that finally related to multiple languages, whether the field is called err/e/error is too hard to unified. And typically the err is a message to search. So putting the error message into the message part works well.

Besides, we leverage logforth's diagnostic to inject common kvs (as diags):

let static_diagnostic = {
    let mut static_diagnostic = StaticDiagnostic::default();
    static_diagnostic.insert("node_id", node_id);
    static_diagnostic.insert("nodegroup", nodegroup);
    static_diagnostic
};

builder = builder.dispatch(|b| {
    b.filter(filter)
        .diagnostic(FastraceDiagnostic::default())
        .diagnostic(static_diagnostic.clone())
        .append(appender)
});

The StaticDiagnostic is similar to Go's slog Handle.WithAttrs and FastraceDiagnostic integrated with fastrace to connect logs and traces.

A sample final view looks like (some internal spans redacted):

Logs

Log Details

Integrated with Traces

Refs:

Hi @WGH-! I'd share a data point from [`logforth`](https://github.com/fast/logforth) where we use it to report our database's (ScopeDB's) logs to multiple destinations (stdout, files, opentelemetry endpoints). Typically, our log statements looks like: ```rust // error in message log::warn!("failed to cancel execution task: {err:?}"); // full parameterized log::info!( target: "ingest", method:% = request.method(), uri:% = request.uri(), tenant_id:% = identity.tenant_id.as_str(), format:% = format, size:% = humansize::format_size(data_size, humansize::BINARY); "{:?}", req.statement ); // mixed log::error!( target: "statement", statement_id:% = statement_id, tenant_id:% = statement_context.tenant_id.as_str(); "statement failed locally in {:.3}s: {}\nexecution error: {err:?}\nexplain analyze: \n{}", Timestamp::now().duration_since(started).as_secs_f64(), prepared.statement, report, ); ``` We previously tried to put `err` in the kvs but noticed that when developing applications that finally related to multiple languages, whether the field is called `err`/`e`/`error` is too hard to unified. And typically the `err` is a message to search. So putting the error message into the message part works well. Besides, we leverage `logforth`'s diagnostic to inject common kvs (as diags): ```rust let static_diagnostic = { let mut static_diagnostic = StaticDiagnostic::default(); static_diagnostic.insert("node_id", node_id); static_diagnostic.insert("nodegroup", nodegroup); static_diagnostic }; builder = builder.dispatch(|b| { b.filter(filter) .diagnostic(FastraceDiagnostic::default()) .diagnostic(static_diagnostic.clone()) .append(appender) }); ``` The `StaticDiagnostic` is similar to Go's slog `Handle.WithAttrs` and `FastraceDiagnostic` integrated with [`fastrace`](https://github.com/fast/fastrace) to connect logs and traces. A sample final view looks like (some internal spans redacted): <details><summary>Logs</summary> <img width="3033" height="2102" alt="Image" src="https://github.com/user-attachments/assets/7c55c0a4-60f1-4577-bb1b-298023b90dac" /> </details> <details><summary>Log Details</summary> <img width="2424" height="2096" alt="Image" src="https://github.com/user-attachments/assets/1d9212d1-e3b3-415f-beb2-7b0e3f771183" /> </details> <details><summary>Integrated with Traces</summary> <img width="3400" height="2091" alt="Image" src="https://github.com/user-attachments/assets/3c7483db-95d0-4454-9814-9ff4d81cb4cc" /> </details> Refs: * https://github.com/fast/fastrace * https://github.com/fast/logforth * https://fast.github.io/blog/fastrace-a-modern-approach-to-distributed-tracing-in-rust/

👍 1

KodrAus commented

2026-06-06 01:57:06 -05:00

(Migrated from github.com)

We previously tried to put err in the kvs but noticed that when developing applications that finally related to multiple languages, whether the field is called err/e/error is too hard to unified.

This is the sort of thing we should at least standardise naming for in log so integration libraries can confidently map it to other schemas, like OpenTelemetry.

The fields that come to mind for me that we don’t handle explicitly in log are:

Timestamps
Errors
Span context
Any others?

> We previously tried to put err in the kvs but noticed that when developing applications that finally related to multiple languages, whether the field is called err/e/error is too hard to unified. This is the sort of thing we should at least standardise naming for in `log` so integration libraries can confidently map it to other schemas, like OpenTelemetry. The fields that come to mind for me that we don’t handle explicitly in `log` are: - Timestamps - Errors - Span context - Any others?

Thomasdezeeuw commented

2026-06-09 07:58:37 -05:00

(Migrated from github.com)

One more came to mind:

backtrace frames

Something that is more logging infrastructure specific but maybe worth considering:

log or event id (unique per generated log to make log storage idempotent)

One more came to mind: * backtrace frames Something that is more logging infrastructure specific but maybe worth considering: * log or event id (unique per generated log to make log storage idempotent)

Rows
Columns

Guidelines regarding structured logging usage #722