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

sevensidedmarble
Hello all, Apologies if this has been proposed before I guess, but I have a very simple one: With the increasing importance of LV, I th...
New
sevensidedmarble
All the pieces are there to execute arbitrary JS commands from the server. You can put them on a data property and call them from the cli...
New
PJUllrich
Hey folks, I have the unique problem that I need to ignore all “change” and “input” events for one specific input element in a LiveView F...
New
superchris
Currently there is no out of the box way to support DOM Custom Events in phoenix. I’ve created a separate library to do this, but I’d lov...
New
BartOtten
I’d like to propose that we refrain from using the term "DeadView" as the opposite of “LiveView” and instead choose an alternative. A new...
New
nunobernardes99
On 1.8+, when we generate an authentication system with mix phx.gen.auth we can make use of magic link login which is amazing and a great...
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

Other popular topics Top

Brian
What is the proper way to load a module from a file in to IEX? In the python world, doing something like this pretty standard: from ....
New
dokuzbir
I want to highlight html closing tags when i click a html tag. That works in .html files but doesnt work for html.eex templates. How can...
New
Darmani72
If I have a post route which an argument: post /my_post_route/:my_param1, MyController.my_post_handler How would get the post params ...
New
bsollish-terakeet
Credo is smart enough to check for (something like) this: assert length(the_list) == 0 with this response: Checking if an enum is empt...
New
shijith.k
I am trying to start a new phoenix project with elixir 1.9, but mix phx.new does not work. It says that ** (Mix) The task "phx.new" could...
New
sergio
Kind of like when jquery came out, it was super necessary. Existing drag and drop libraries have a bunch of baggage to support old browse...
New

We're in Beta

About us Mission Statement