The desire to produce structured logs is common. In this article, I will survey the major approaches one could take to achieve this goal using the built-in Elixir Logger.
As an example, I will use JSON as the "structured" format, as it seems to be the most common. The same points apply to any structured format you choose.
First, a quick recap of the important pieces of the Elixir Logger.
Log events are produced via the API functions such as Logger.info
and Logger.warn
. A log event is a "message", which is usually a string, paired with "metadata", which is a list of key-value pairs.
> Logger.info("200 OK", request_id: 42)
Log events are consumed by "backends".
import Config
config :logger,
backends: [:console, OtherBackend]
Each backend is independent, making its own decisions about which log events to filter out and how to format them.
Finally, there is the configuration for each backend, with format
and metadata
being the only relevant ones for this article.
import Config
config :logger, :console,
format: # describes the output format
level: # sets the minimum log level to output
metadata: # what metadata keys (if any) will be included in the output
Let's quickly see what kind of behaviour we get out-of-the-box.
With the following configuration:
import Config
config :logger, :console,
metadata: [:request_id]
this is the kind of output you can expect to see:
> Logger.info("200 OK", request_id: 42)
12:00 request_id=42 [info] 200 OK
The output is determined by the format
configuration parameter, which defaults to $time $metadata[$level] $message
.
You may be wondering what happens if we provide a map instead of a string for the message
argument. Here is what it looks like:
> Logger.info(%{status: 200, request_id: 42})
12:00 [info] [request_id: 42, status: 200]
I'll explain what is going on here at the end of the article, but, for now, I will ignore this because it won't turn out to be usable.
Now let's look at the different approaches to structured logging.
Serializing into $message
(the non-approach)
One approach that may occur to you is to forget about how the logging framework works and serialize messages into JSON yourself, like so:
> Logger.info(encode(%{status: 200, request_id: 42}))
12:00 [info] {"status": 200,"request_id":42}
Almost there, now you just need to get rid of the extra stuff in the way of your JSON formatted log.
import Config
config :logger, :console
format: "$message\n"
> Logger.info(encode(%{status: 200, request_id: 42}))
{"status": 200,"request_id":42}
There we go. We now have JSON logs. But we lost the timestamp and log level. So we add them back.
> Logger.info(encode(%{timestamp: "12:00", level: :info, status: 200, request_id: 42}))
{"timestamp": "12:00","level": "info","status": 200,"request_id":42}
And it seems we have accomplished our task.
Obviously, I think this is a bad approach. Here are some of the reasons why:
You have to remember to include "level" and "timestamp" fields every time you produce a log event.
Something the logger is designed to do for you. If you think that you can solve that problem by wrapping the Elixir logger, then you should know that that is also a bad idea.
But most importantly,
it does not play well with third-party libraries.
Any other library that produces log events in a sane way,
i.e. by calling Logger.info("some message", ... metadata ...)
will not participate in this scheme. So you will end up with a mixture of JSON formatted logs produced by your application and raw strings produced by other applications.
{"level":"info","timestamp":"12:00","message":"did something"}
Raw log from third-party library
{"level":"info","timestamp":"12:01","message":"did something else"}
Custom formatter - the most straightforward approach
In Elixir's logging framework there is a somewhat informal notion of a "custom formatter", this is a configuration parameter that lets the user of a logging backend customize the way log events are serialized. By convention, this piece of configuration is specified by the format
key.
The simplest form of this parameter is a string.
import Config
config :logger, :console,
format: "[$level] $message"
Which lets you specify simple formats, but this parameter can also be a {module, function}
tuple which lets you take complete control over formatting.
import Config
config :logger, :console
format: {MyApp.Logger.Formatter, :format}
Once you do that, it is just a matter of implementing this module and function.
defmodule MyApp.Logger.Formatter do
def format(level, message, timestamp, metadata) do
# encode the log event
end
end
Now we have complete control. We also have to provide the metadata
keys we wish to receive, as usual.
import Config
config :logger, :console
format: {MyApp.Logger.Formatter, :format},
metadata: [:request_id]
defmodule MyApp.Logger.Formatter do
def format(level, message, timestamp, metadata) do
log_event =
to_json(
%{
timestamp: format_timestamp(timestamp),
level: level,
message: :erlang.iolist_to_binary(message)
},
metadata
)
encode(log_event)
rescue
_ -> "could not format: #{inspect({level, message, metadata})}"
end
defp to_json(...) # not every Erlang term is valid json, convert here
defp format_timestamp(...)
end
We get the output we expect.
> Logger.info("nice stuff", request_id: 42)
{"timestamp":"12:00","level":"info","message":"nice stuff","request_id":42}
And with this, all third-party log events will also be formatted properly.
This approach will work for any backend which follows the convention of exposing a format
configuration parameter.
A new backend - is overkill
The third and final approach that we will consider is creating a new backend. As I will show, it is no better than the previous approach. First, let's see a simplified implementation of a backend based on the built-in :console
backend.
We tell the :logger
application to send logs to our new backend.
import Config
config :logger,
backends: [MyApp.Logger.Backends.Console]
And implement it as follows:
defmodule MyApp.Logger.Backends.Console do
@behaviour :gen_event
def init(_) do
level = :info
format = Logger.Formatter.compile("$time $metadata[$level] $message\n")
metadata = [:request_id]
device = Process.whereis(:user)
{:ok, %{level: level, format: format, metadata: metadata, device: device}}
end
def handle_event({level, _group_leader, {Logger, message, timestamp, metadata}}, state) do
%{level: min_level, format: format, metadata: keys, device: device} = state
cond do
# Filter out logs that are lower than the configured level
Logger.compare_levels(level, min_level) == :lt ->
{:ok, state}
true ->
:ok =
:io.put_chars(
device,
Logger.Formatter.format(
format,
level,
message,
timestamp,
Keyword.take(metadata, keys)
)
)
{:ok, state}
end
end
end
Let's go over that in detail.
A backend is a gen_event
, so we declare that we implement that behaviour.
We implement the callback init/1
, which returns {:ok, state}
, just like a GenServer
. Normally, we would fetch configuration for the backend here and do any setup work which is required for that particular backend. For example, a file based backend may open a file and store the file handle. In this example, I locate the :user
process and store its pid. The :user
process is a special device which is responsible for output to the standard I/O streams, i.e. the console. I also "compile" the format template for later use.
Finally, we implement the handle_event/2
callback, which is the heart of the backend. It receives a log event, drops it if it is lower than the configured minimum log level, otherwise, it formats and sends it to the output device. You can see that this particular backend delegates formatting completely to another module: Logger.Formatter
.
The Logger.Formatter
module, given a format string, works in the following way:
> fmt = Logger.Formatter.compile("[$level] $message\n")
["[", :level, "] ", :message, "\n"]
> output = Logger.Formatter.format(fmt, :info, "200 OK", :no_timestamp, :no_metadata)
["[", "info", "] ", "200 OK", "\n"]
> :io.put_chars(:user, output)
[info] 200 OK
:ok
but when given a {module, function}
tuple, it will simply delegate to that module.
> Logger.Formatter.compile({MyMod, :my_fun})
{MyMod, :my_fun}
> Logger.Formatter.format({MyMod, :my_fun}, level, message, timestamp, metadata)
# Just calls MyMod.my_fun(level, message, timestamp, metadata)
Seeing what a backend consists of you should be able to see that formatting happens entirely in Logger.Formatter.format/5
. Which gets us back to where we were in the second approach.
Which is why I conclude:
Creating a new backend just to format log events is overkill.
Because, as the above code shows, it is no more flexible than a formatting module.
So when should you create a new backend? I'll tentatively propose a rule and my reasoning for it.
A logger backend is tasked with receiving log events and sending them to an output device. Only the backend is responsible for sending output to the device, therefore this suggests it has the following responsibilities:
- managing the I/O device
- and efficient use of the I/O device (i.e. buffering output)
In particular, the backend is not responsible for formatting output, that is left up to the Logger.Formatter
module (or a custom formatter).
Which leads to the following rule:
Only create a new logger backend when you need to manage a new type of I/O device.
Each device may have particular needs in terms of setup and efficient use, and that can be encapsulated by the backend.
Examples of I/O devices that may warrant their own backends:
- the standard I/O streams, i.e. the console
- a file
- a set of files with log rotation
- a socket (for remote logging)
That's all I have to say about the different approaches to structured logging using the built-in Elixir logger.
Now I'd like to look at a potential future approach.
Reports - a future approach?
Earlier in the article we saw that the message
argument to the Logger API functions need not be a string.
> Logger.info(%{status: 200, request_id: 42})
12:00 [info] [request_id: 42, status: 200]
This may look promising until you realise that you have no control over how this message is formatted.[^1]
defmodule CustomFormatter do
def format(level, message, timestamp, metadata) do
# "message" is already formated into "[request_id: 42, status: 200]"
end
end
So what is going on?
To understand this we need to look at how Elixir's logger is implemented on top of the Erlang logger.
The Erlang logger has its own design which differs in significant ways from the Elixir logger. To keep this article short, I will not explain the Erlang logger in detail, but poke around its API enough to give you an idea of the pieces.
The Erlang logger is organised into "handlers". When Elixir starts up, it registers the Logger
module as a handler (replacing the default Erlang handler).
> :logger.get_handler_ids
[Logger]
You can take a look at the configuration:
> :logger.get_handler_config Logger
{:ok,
%{
... elided ...,
id: Logger,
module: Logger.Handler
}}
A "handler" configures a callback module to implement its behaviour, which is the Logger.Handler
module, in this case. The callback that handles a log event is log/2
and what it receives is a little different to what a "backend" receives.
An Erlang "log event" has the following type:
@type log_event :: %{level: level(),
msg: {:report, map()}
| {:string, :unicode.chardata()},
meta: metadata()}
For example, a log event could be:
%{level: :info,
msg: {:string, "200 OK"},
meta: %{request_id: 42}}
or
%{level: :info,
msg: {:report, %{status: 200, request_id: 42}},
meta: %{}}
The name Erlang gives a structured log message is a "report". A report is just a map. The line of code responsible for formatting this report is here.
It turns into the following call:
> Kernel.inspect(Map.to_list(%{status: 200, request_id: 42}))
"[request_id: 42, status: 200]"
The Elixir logger's handler implementation will always render a report to a string before passing it to a backend. It is this fact that makes reports unusable for structured logging today.
I assume this was done for backwards-compatibility, after all, the Elixir Logger predates the Erlang logger.
One could imagine a change to the Elixir logger to allow backends to receive Erlang-style log events and bring the two systems closer together.
[^1] There is the report_cb
callback, but it does not help.
Latest comments (4)
I wrote an Erlang logger formatter which correctly handles structured logs: hex.pm/packages/logger_formatter_json
Good to see people taking advantage of the new integration between the Erlang and Elixir logging systems.
The custom formatter here doesn't work for the message as a map. When formatter recieve the message, it's already got transformed to string.
That's right. That is why I wrote:
I explain in the last part of the article why this happens. I link to the code that is responsible for this behaviour. Here is the link again.
It is a bit confusing, which is why I felt compelled to write about it :).