martosaur

martosaur

Should Logger.Translator persist original report to metadata?

TL;DR

Logger.Translator acts as a global filter and swallows structure of some OTP reports, which some logger handlers could benefit from. Would it be a good idea to save a copy of raw report in the metadata?

Context

Two main categories of log messages logger handlers deal with are reports and strings. Reports can be either maps or keyword lists. The most likely source of reports in an Elixir app is OTP reports. Think of Genserver crashes or Task process exits. Those reports often originate from Erlang and thus looks foreign Elixir output. This is where Logger.Translator comes in.

Logger.Translator is attached as a primary logger filter by Logger app and it translates a large variety of Erlang reports to… well, a combination of 2 things:

  1. String message
  2. crash_reason metadata entry

This behaviour can be customized in multiple ways:
1. handle_otp_reports and handle_sasl_reports logger configuration options allow to drop otp reports entirely.
2. Translator can be fully removed by calling Logger.remove_translator({Logger.Translator, :translate}) at runtime, and potentially replaced with custom implementation.
3. Translator can be even more fully removed by manually update primary logger config, e.g. via calling :logger.remove_primary_filter(:logger_translator)

All of the above will affect events for ALL attached logger handlers.

Problem

The translation from a structured report to a string message isn’t lossless and some logger handlers would benefit from having access to reports.

Consider this example of a log event coming from an exiting task:

Single File Example
inspect_filter = fn event, label -> IO.inspect(event, label: label) end

filters =
  [before: {inspect_filter, "before translator"}] ++
    :logger.get_primary_config().filters ++ [after: {inspect_filter, "after translator"}]

:logger.update_primary_config(%{filters: filters})

Task.start(fn ->
  Process.set_label(:foo)
  exit("Exit")
end)

Process.sleep(1_000)

Output:

before translator: %{
  meta: %{
    error_logger: %{tag: :error_msg},
    pid: #PID<0.97.0>,
    time: 1742685332014493,
    gl: #PID<0.69.0>,
    domain: [:otp, :elixir],
    report_cb: &Task.Supervised.format_report/1,
    callers: [#PID<0.94.0>]
  },
  msg: {:report,
   %{
     label: {Task.Supervisor, :terminating},
     report: %{
       args: [],
       function: #Function<1.46817823 in file:logger.exs>,
       name: #PID<0.97.0>,
       reason: {"Exit",
        [
          {:elixir_compiler_0, :"-__FILE__/1-fun-1-", 0,
           [file: ~c"logger.exs", line: 11]},
          {Task.Supervised, :invoke_mfa, 2,
           [file: ~c"lib/task/supervised.ex", line: 101]}
        ]},
       process_label: :foo,
       starter: #PID<0.94.0>
     }
   }},
  level: :error
}
after translator: %{
  meta: %{
    error_logger: %{tag: :error_msg},
    pid: #PID<0.97.0>,
    time: 1742685332014493,
    gl: #PID<0.69.0>,
    domain: [:otp, :elixir],
    report_cb: &Task.Supervised.format_report/1,
    callers: [#PID<0.94.0>],
    crash_reason: {"Exit",
     [
       {:elixir_compiler_0, :"-__FILE__/1-fun-1-", 0,
        [file: ~c"logger.exs", line: 11]},
       {Task.Supervised, :invoke_mfa, 2,
        [file: ~c"lib/task/supervised.ex", line: 101]}
     ]}
  },
  msg: {:string,
   [
     "Task #PID<0.97.0> started from #PID<0.94.0> terminating",
     [
       ["\n** (stop) " | "\"Exit\""],
       ["\n    " |
        "logger.exs:11: anonymous fn/0 in :elixir_compiler_0.__FILE__/1"],
       ["\n    " |
        "(elixir 1.18.3) lib/task/supervised.ex:101: Task.Supervised.invoke_mfa/2"]
     ],
     "\nProcess Label: :foo",
     "\nFunction: #Function<1.46817823 in file:logger.exs>",
     "\n    Args: []"
   ]},
  level: :error
}

16:15:32.014 [error] Task #PID<0.97.0> started from #PID<0.94.0> terminating
** (stop) "Exit"
    logger.exs:11: anonymous fn/0 in :elixir_compiler_0.__FILE__/1
    (elixir 1.18.3) lib/task/supervised.ex:101: Task.Supervised.invoke_mfa/2
Process Label: :foo
Function: #Function<1.46817823 in file:logger.exs>
    Args: []

The information is arguably there, but the only way for logger handler to access process label, for example, is by parsing iodata. And we actually can find an example of this in Sentry client library.

Workaround

The only way I can think of this can be addressed is introducing another logger filter, that would save reports to metadata. This isn’t ideal, as it requires handler developers to ask users to do changes to their primary logging configuration.

Proposed Solution

The best solution I can think of is for translator to save raw report in metadata alongside with crash_reason. This way handlers will have a chance to access raw reports, given the configuration is otherwise the default one. As for the drawbacks, I can see a couple:

  1. Having both crash_reason and original_report in metadata might be confusing
  2. There might be some memory cost to keeping report in metadata. Handlers and filters should share memory fairly well, since they’re called in the same process, but sophisticated handlers often send events to other processes.
  3. Some people export all their metadata to logging services and the change will directly impact their log volume.

Most Liked

martosaur

martosaur

For anybody stumbling upon this post, the translation behaviour will change in Elixir 1.19. Reports will no longer be replaced with a translation. Instead, the translation will be inserted into the report under the elixir_translation key and report_cb callback will be wrapped with Logger.Utils.translated_cb which will return translation.

Where Next?

Popular in Proposals: Ideas Top

martosaur
TL;DR Logger.Translator acts as a global filter and swallows structure of some OTP reports, which some logger handlers could benefit from...
New
cevado
Being able to build nested relations in a schemaless changeset would be helpful to deal with complex forms on Phoenix without the need to...
New
manhvu
In a large repo, working with module need to add alias too much is quite annoyed and not good for organizing code. I think better add su...
New
winsalva
Hello all. First of all i’m running this using termux on an android phone. Running mix assets.setup shows this message 06:54:08.450 [de...
New
cheerfulstoic
I feel like Elixir is getting big enough and old enough that I’m starting to experience problems with conflicting dependencies. An examp...
New
bartblast
This could resolve to {[a: 1, b: 2]}. Was it ever considered to allow such syntax? Notice this: {:abc, a: 1, b: 2} and this: my_fun(:abc,...
New
nhpip
So the other day I was rearranging the supervisor hierarchy of our product and I had a thought. In addition to creating a child spec with...
New
7rans
I implemented Access behavior for a struct today. Pseudo-code… defmodule MyStruct do defstruct data: %{} @behaviour Access # ... ...
New
sezaru
When writing my code, I always find __MODULE__ very useful to use as alias of that module “inner dependencies”, ex: alias __MODULE__.{Im...
New
dkuku
This is a proposal to make the map key mismatch errors a bit better: Every time I have a typo It’s very challenging for me even when I u...
New

Other popular topics Top

peerreynders
Manning 2016 Halloween weekend sale via Deal of the Day Friday, October 28 - Half off all MEAPs - code WM102816LT Saturday, October 29 ...
326 29600 154
New
jononomo
I am trying to figure out how Mix knows whether the environment is test, dev, or prod -- where is this set? Thanks.
New
gshaw
What is the idiomatic way of matching for not nil in Elixir? E.g., First way: defp halt_if_not_signed_in(conn, signed_in_account) when...
New
New
Harrisonl
We have an ECS cluster with 4 services, where each task joins a single cluster, via discovery ECS discovery service. Currently when I de...
New
chrismccord
As promised, the first release candidate of Phoenix 1.3.0 is out! This release focuses on code generators with improved project structure...
New
mgjohns61585
Could someone help me? I'm making my first elixir program, number guessing game. I can't figure out how to convert the user's guess from ...
New
WestKeys
Currently suffering from paralysis by [HTTP client] analysis. This is rather unusual in Elixirland as there tends to be consensus on the ...
New
josevalim
Hi everyone, One of the features added to Elixir early on to help integration with Erlang code was the idea of overridable function defi...
New
siddhant3030
Hi, I have to write a raw query for one of my project. But till now I have used ecto queries and don’t have much experience writing raw ...
New

We're in Beta

About us Mission Statement