Guidelines regarding structured logging usage

[WGH-]

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");

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 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.
3. 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

[Thomasdezeeuw]

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={}").

[WGH-]

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]

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.

[Thomasdezeeuw]

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.