What do we do with logging in libraries?

Logging has been a major headache for library authors for a long time. Library code is dropped into highly opinionated application environments, and whatever choices you make as a maintainer, you simply cannot satisfy everybody. You use info logs? More like debug. Debug logs? Very noisy. No logs at all? Ugh, zero observability.

There is simply no universally accepted, recommended way to do logging in libraries. As a result, most libraries simply avoid logging if they can help it.

I think it's time we talk about this. Yes, I'll be talking about reports. But first, let me explain why logs are so hard to get right.

It's just a log, how hard can it be?

If you were to log an API request error, would you do it like this:

case Req.request!(req) do
  %{status: 200, body: body} ->
    ...

  response ->
    Logger.error("Error calling API: #{inspect(response)}")
end

or like this:

case Req.request!(req) do
  %{status: 200, body: body} ->
    ...

  response ->
    Logger.error("Error calling API", response: response)
end

or perhaps you're a seasoned veteran and go for both:

case Req.request!(req) do
  %{status: 200, body: body} ->
    ...

  response ->
    Logger.error(
      "Error calling API: #{inspect(response)}",
      response: response
    )
end

Unfortunately, none of these logs are ideal. By that I mean none of them meet all 3 basic conditions that I think make a good log.

Condition 1: Looking good in terminal

In dev, we see logs as they are printed in the terminal. By default, the Elixir log formatter, typically used in dev, will print only the log message:

iex> Logger.error("Hello", foo: "bar")
11:14:06.457 [error] Hello

Technically, you can also print metadata, but in reality it almost never happens. It's too annoying to configure, it's too annoying to format, and most real-life applications contain so much generic metadata that it instantly crowds precious terminal real estate.

I know, it's heartbreaking, but you must display all important information in the log message in order to make it look good in a terminal environment:

Logger.error("Error calling API: #{inspect(response)}")

Condition 2: Looking good in cloud

Logging in production is a completely different beast. Any serious application will use some kind of structured logging sink: Google Cloud Logging, AWS CloudWatch, OpenTelemetry, Datadog, etc. For this you will typically employ a JSON formatter.

Those services aren't limited by text-based terminal representation. They will happily ingest all of your metadata and let you slice and dice your logs in whatever way you want. They are all about metadata. For them, the log message is just another field in your log structure.

To meet this condition, your logs should put all dynamic information into the metadata. A dynamic log message isn't ideal, but we'll let it fly to accommodate the dev environment:

Logger.error(
  "Error calling API: #{inspect(response)}",
  response: response
)

Condition 3: Facilitating Issue Grouping

There is one more place where logs manifest: error tracking solutions, such as Sentry and PostHog. They keep track of what errors happened in your app, group identical issues together, and ping you on Slack whenever there is a new issue.

As you can imagine, grouping errors together is very important and it's consistently the hardest thing to get right. Usually, it is done through fingerprinting: each error is issued a unique ID based on a set of heuristics. For an unhandled exception, this can be the exception type and the last frame of the stack trace. For error logs, it is commonly a log message.

Now look at this example log:

Postgrex.Protocol (#PID<0.2021.0> ("db_conn_4")) failed to connect:
** (Postgrex.Error) FATAL 53300 (too_many_connections) remaining connection slots are reserved for roles with the SUPERUSER attribute

This is a real log message from Postgrex. Notice how it has a bunch of dynamic values such as pid and connection name mixed into the message. It will be pretty hard for error tracking to group two of those logs together, even though they clearly stem from the same underlying root cause.

So for error tracking, a good log is one that puts all dynamic values into metadata and leaves the log message completely static for easier fingerprinting:

Logger.error("Error calling API", response: response)

Consider reports

As we can see, metadata and log messages are in constant tension. There is no way to write a log in such a way that would satisfy all 3 conditions. And the reason for this is that the decision about how the message is formatted is made too early.

But we don't have to make this decision! Logger in Erlang (and Elixir!) provides great support for structured logging, and you can log structured data like this:

iex> Logger.error(%{response: %{status: 400, body: "bad_request"}})
12:18:12.006 [error] [response: %{status: 400, body: "bad_request"}]

Okay that's definitely structured, but how can we make it look good in terminal? As with everything, Erlang has a callback for this. You can put a special function under report_cb metadata key that will tell the formatter how the report should be rendered.

iex> Logger.error(
  %{response: %{status: 400, body: "bad_request"}},
  report_cb: fn report ->
    {"Error calling API: ~tw", [report.response]}
  end)

12:24:33.350 [error] Error calling API: %{status: 400, body: "bad_request"}

The drawback here is that report_cb must return an io format tuple, which uses fairly arcane Erlang syntax.

If it doesn't look like this log addressed all our problems, you're not wrong. But this structured log achieved one very important thing: it made all dynamic information programmatically accessible, while still providing a preferred text representation. This is huge.

Putting it to practice

Let's see how it will look in practice. Consider this Postgrex error:

defmodule Postgrex.Protocol do
  ...

  def handshake_shutdown(timeout, pid, sock) do
    if Process.alive?(pid) do
      Logger.error(fn ->
        [
          inspect(__MODULE__),
          " (",
          inspect(pid),
          ") timed out because it was handshaking for longer than ",
          to_string(timeout) | "ms"
        ]
      end)

      :gen_tcp.shutdown(sock, :read_write)
    end
  end
end

This is how we can rewrite it with a report:

defmodule Postgrex.Protocol do
  ...

  def handshake_shutdown(timeout, pid, sock) do
    if Process.alive?(pid) do
      Logger.error(
        %{
          log_id: {Postgrex, :handshake_shutdown},
          pid: pid,
          timeout: timeout
        },
        report_cb: &__MODULE__._format_handshake_shutdown/1
      )

      :gen_tcp.shutdown(sock, :read_write)
    end
  end

  def _format_handshake_shutdown(report) do
    {"~ts (~tw) timed out because it was handshaking for longer than ~twms",
      [inspect(__MODULE__), report.pid, report.timeout]}
  end
end

~ts interpolates a string. ~tw interpolates a term. Remote captures are preferred for the report_cb callback. That's all you need to know to write report logs!

You may also notice log_id. Since reports are just maps, there is no easy way to identify them. So I propose we use a log_id field as a convention. It is equally useful for users who want to customize or filter our events, and for third-party developers who want to provide better support for certain libraries.

When your library logs are structured like this, it's simple for me as a user to customize them. For example, I can create a simple production filter that will put all dynamic values into metadata and use a static log message:

defmodule ProductionFilter do
  def filter(
    %{msg: {:report, report}, meta: %{report_cb: report_cb}} = log_event,
    _opts)
  when is_function(report_cb, 1) do
    {static_msg, format_values} = report_cb.(report)

    log_event
    |> Map.put(:msg, {:string, static_msg})
    |> Map.update!(:meta, fn meta ->
      meta
      |> Map.put(:report, report)
      |> Map.put(:format_values, format_values)
    end)
  end
end

iex> :logger.add_primary_filter(
  :reshape_reports,
  {&ProductionFilter.filter/2, []}
)
iex> Logger.error(
  %{response: %{status: 400, body: "bad_request"}},
  report_cb: fn report ->
    {"Error calling API: ~tw", [report.response]}
  end)
12:48:16.928 [error] Error calling API: ~tw

~tw part might look a little awkward in the terminal, but it will look great in the cloud where you would be able to easily aggregate and filter by any metadata field.

Alternatively, the user can choose to write their own log message:

defmodule ProductionFilter do
  def filter(
    %{msg: {:report, %{log_id: {Postgrex, :handshake_shutdown}} = report}, meta: %{report_cb: report_cb}} = log_event,
    _opts)
  when is_function(report_cb, 1) do
    log_event
    |> Map.put(:msg, {:string, "Postgrex handshake time out"})
    |> Map.update!(:meta, fn meta ->
      Map.put(meta, :report, report)
    end)
  end

But wait, what about telemetry?

Right, telemetry. The closest we got to a standard approach is instrumenting a library with telemetry and providing a default handler that will log off of emitted telemetry events. This is what Oban does, for example.

This is a good approach, but unfortunately I don't expect it to be universally adopted for a number of reasons:

Instrumenting your code with telemetry, while valuable, is quite an undertaking, and most libraries just don't do it.
Not every log message can be cleanly mapped to a telemetry event. They are a bit different concepts.
telemetry is an external dependency, albeit an omnipresent one.
The mechanism for log customization is basically writing your own telemetry handler, which is an all-or-nothing approach. Even worse, logging libraries like Sentry or PostHog will have to create their own handlers if they want to play nice with your library.

And finally, logging off of telemetry doesn't directly address the fundamental problem outlined above. Somebody still has to write this Logger.error call, and it'd better be good.

Conclusion

Structured logging is a great way to add logging to libraries while still giving users control through built-in logging filters and handlers. It works with or without telemetry instrumentation. So next time you find yourself thinking about the best way to handle logs in your library, consider using reports with a formatting callback.

Alex Martsinovich