Should Logger.Translator persist original report to metadata?

Chat & Discussions Proposals: Ideas
,
1

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.
1 Like
2

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.

2 Likes