I'm not a massive fan of the printf-style logging you get with the log
crate and prefer to use structured logging when I can. It really pays off for logging in production services because you can wire it up to something like Datadog or the Elastic stack to get rich dashboards.
I used to use slog
for this, but over the last year or so I've started moving towards the tracing
crate and the JSON output generated by the tracing_subscriber
logger.
For example, I have a Discord bot which logs every command that gets executed. This is the code I use to log the incoming message:
tracing::debug!(
command,
author.nick = author,
author.id = msg.author.id,
message,
link,
guild,
attachments = msg.attachments,
"Executing a command"
);
It will log this output (indented for readability) when you ask it to run the about
command:
{
"timestamp": "2022-02-11T02:49:34.485522Z",
"level": "DEBUG",
"fields": {
"message": "@Bot#3189 about",
"command": "about",
"author.nick": "Michael",
"author.id": "419204234060234766",
"link": "https://discord.com/channels/860564021496905788/860564021496905792/941526345861709824",
"guild": "Michael's Test Server",
"attachments": "[]"
},
"target": "halp::discord::hooks"
}
Besides the structured logging, tracing
has this concept of "spans" representing a section of code with a start and end. For example, you might enter a new span when you start handling a HTTP request and attach fields like the endpoint and request ID, you would then do the normal handling process, emitting logs or entering nested spans as you go, before you finally exit the span.
Depending on the logger implementation, you could log when spans are entered/exited or even use it to record timing metrics. The tokio console uses spans under the hood to help you debug async code and reason about futures as they are being executed.