FORMATTER CRASH in Datadog formatter when GenServer crashes

[rohan-b99]

Related to #133

You can repro this with a single file application (e.g. test.exs):

Mix.install([:logger_json])

require Logger
formatter = {LoggerJSON.Formatters.Datadog, encoder_opts: [pretty: true]}
:logger.update_handler_config(:default, :formatter, formatter)

defmodule CrashingGenServer do
  use GenServer

  def start_link(_) do
    GenServer.start_link(__MODULE__, :ok, name: __MODULE__)
  end

  def init(state) do
    {:ok, state}
  end

  def handle_call(:boom, _, _) do
    raise "boom"
  end
end

{:ok, _} = Supervisor.start_link([{CrashingGenServer, :ok}], strategy: :one_for_one)

pid = self()
{:ok, _} =
  Task.start(fn ->
    try do
      GenServer.call(CrashingGenServer, :boom)
    catch
      _ -> nil
    after
      send(pid, :done)
    end
  end)

# Wait for task to finish
receive do
  :done -> nil
end

# Let logs flush
Process.sleep(100)

Running elixir test.exs results in:

2024-11-07 14:31:58.012297 {error,simple_handler_process_dead}
2024-11-07 14:31:58.012274 
    formatter_crashed: 'Elixir.LoggerJSON.Formatters.Datadog'
    config: [{encoder_opts,[{pretty,true}]}]
    log_event: #{meta=>#{line=>410,pid=><0.166.0>,time=>1730989918012119,file=>"logger_h_common.erl",gl=><0.69.0>,internal_log_event=>true,mfa=>{logger_h_common,try_format,3},report_cb=>fun logger:format_otp_report/1},msg=>{report,[{formatter_crashed,'Elixir.LoggerJSON.Formatters.Datadog'},{config,[{encoder_opts,[{pretty,true}]}]},{log_event,#{meta=>#{error_logger=>#{tag=>error_msg},pid=><0.166.0>,time=>1730989918009549,gl=><0.69.0>,domain=>[otp,elixir],report_cb=>fun 'Elixir.Task.Supervised':format_report/1,callers=>[<0.98.0>],crash_reason=>{{{#{message=><<"boom">>,'__struct__'=>'Elixir.RuntimeError','__exception__'=>true},[{'Elixir.CrashingGenServer',handle_call,3,[{file,"fail.exs"},{line,19},{error_info,#{module=>'Elixir.Exception'}}]},{gen_server,try_handle_call,4,[{file,"gen_server.erl"},{line,1131}]},{gen_server,handle_msg,6,[{file,"gen_server.erl"},{line,1160}]},{proc_lib,init_p_do_apply,3,[{file,"proc_lib.erl"},{line,241}]}]},{'Elixir.GenServer',call,['Elixir.CrashingGenServer',boom,5000]}},[{'Elixir.GenServer',call,3,[{file,"lib/gen_server.ex"},{line,1128}]},{elixir_compiler_0,'-__FILE__/1-fun-0-',1,[{file,"fail.exs"},{line,29}]},{'Elixir.Task.Supervised',invoke_mfa,2,[{file,"lib/task/supervised.ex"},{line,101}]}]}},msg=>{string,[<<"Task #PID<0.166.0> started from #PID<0.98.0> terminating">>,[[<<10,42,42,32,40,115,116,111,112,41,32>>|<<101,120,105,116,101,100,32,105,110,58,32,71,101,110,83,101,114,118,101,114,46,99,97,108,108,40,67,114,97,115,104,105,110,103,71,101,110,83,101,114,118,101,114,44,32,58,98,111,111,109,44,32,53,48,48,48,41,10,32,32,32,32,42,42,32,40,69,88,73,84,41,32,97,110,32,101,120,99,101,112,116,105,111,110,32,119,97,115,32,114,97,105,115,101,100,58,10,32,32,32,32,32,32,32,32,42,42,32,40,82,117,110,116,105,109,101,69,114,114,111,114,41,32,98,111,111,109,10,32,32,32,32,32,32,32,32,32,32,32,32,102,97,105,108,46,101,120,115,58,49,57,58,32,67,114,97,115,104,105,110,103,71,101,110,83,101,114,118,101,114,46,104,97,110,100,108,101,95,99,97,108,108,47,51,10,32,32,32,32,32,32,32,32,32,32,32,32,40,115,116,100,108,105,98,32,53,46,50,46,51,41,32,103,101,110,95,115,101,114,118,101,114,46,101,114,108,58,49,49,51,49,58,32,58,103,101,110,95,115,101,114,118,101,114,46,116,114,121,95,104,97,110,100,108,101,95,99,97,108,108,47,52,10,32,32,32,32,32,32,32,32,32,32,32,32,40,115,116,100,108,105,98,32,53,46,50,46,51,41,32,103,101,110,95,115,101,114,118,101,114,46,101,114,108,58,49,49,54,48,58,32,58,103,101,110,95,115,101,114,118,101,114,46,104,97,110,100,108,101,95,109,115,103,47,54,10,32,32,32,32,32,32,32,32,32,32,32,32,40,115,116,100,108,105,98,32,53,46,50,46,51,41,32,112,114,111,99,95,108,105,98,46,101,114,108,58,50,52,49,58,32,58,112,114,111,99,95,108,105,98,46,105,110,105,116,95,112,95,100,111,95,97,112,112,108,121,47,51>>],[<<10,32,32,32,32>>|<<"(elixir 1.17.2) lib/gen_server.ex:1128: GenServer.call/3">>],[<<10,32,32,32,32>>|<<"fail.exs:29: anonymous fn/1 in :elixir_compiler_0.__FILE__/1">>],[<<10,32,32,32,32>>|<<"(elixir 1.17.2) lib/task/supervised.ex:101: Task.Supervised.invoke_mfa/2">>]],<<10,70,117,110,99,116,105,111,110,58,32,35,70,117,110,99,116,105,111,110,60,48,46,50,55,49,56,57,54,48,50,32,105,110,32,102,105,108,101,58,102,97,105,108,46,101,120,115,62>>,<<10,32,32,32,32,65,114,103,115,58,32,91,93>>]},level=>error}},{reason,{error,function_clause,[{'Elixir.Enum','-map/2-lists^map/1-1-',[#Fun<Elixir.LoggerJSON.Formatter.RedactorEncoder.3.73320869>,<<101,120,105,116,101,100,32,105,110,58,32,71,101,110,83,101,114,118,101,114,46,99,97,108,108,40,67,114,97,115,104,105,110,103,71,101,110,83,101,114,118,101,114,44,32,58,98,111,111,109,44,32,53,48,48,48,41,10,32,32,32,32,42,42,32,40,69,88,73,84,41,32,97,110,32,101,120,99,101,112,116,105,111,110,32,119,97,115,32,114,97,105,115,101,100,58,10,32,32,32,32,32,32,32,32,42,42,32,40,82,117,110,116,105,109,101,69,114,114,111,114,41,32,98,111,111,109,10,32,32,32,32,32,32,32,32,32,32,32,32,102,97,105,108,46,101,120,115,58,49,57,58,32,67,114,97,115,104,105,110,103,71,101,110,83,101,114,118,101,114,46,104,97,110,100,108,101,95,99,97,108,108,47,51,10,32,32,32,32,32,32,32,32,32,32,32,32,40,115,116,100,108,105,98,32,53,46,50,46,51,41,32,103,101,110,95,115,101,114,118,101,114,46,101,114,108,58,49,49,51,49,58,32,58,103,101,110,95,115,101,114,118,101,114,46,116,114,121,95,104,97,110,100,108,101,95,99,97,108,108,47,52,10,32,32,32,32,32,32,32,32,32,32,32,32,40,115,116,100,108,105,98,32,53,46,50,46,51,41,32,103,101,110,95,115,101,114,118,101,114,46,101,114,108,58,49,49,54,48,58,32,58,103,101,110,95,115,101,114,118,101,114,46,104,97,110,100,108,101,95,109,115,103,47,54,10,32,32,32,32,32,32,32,32,32,32,32,32,40,115,116,100,108,105,98,32,53,46,50,46,51,41,32,112,114,111,99,95,108,105,98,46,101,114,108,58,50,52,49,58,32,58,112,114,111,99,95,108,105,98,46,105,110,105,116,95,112,95,100,111,95,97,112,112,108,121,47,51>>],[{file,"lib/enum.ex"},{line,1703}]},{'Elixir.Enum','-map/2-lists^map/1-1-',2,[{file,"lib/enum.ex"},{line,1703}]},{'Elixir.Enum','-map/2-lists^map/1-1-',2,[{file,"lib/enum.ex"},{line,1703}]},{'Elixir.Enum','-map/2-lists^map/1-1-',2,[{file,"lib/enum.ex"},{line,1703}]},{'Elixir.LoggerJSON.Formatter.RedactorEncoder',encode_key_value,2,[{file,"lib/logger_json/formatter/redactor_encoder.ex"},{line,69}]},{'Elixir.LoggerJSON.Formatter.RedactorEncoder','-encode/2-fun-0-',3,[{file,"lib/logger_json/formatter/redactor_encoder.ex"},{line,52}]},{maps,fold_1,4,[{file,"maps.erl"},{line,416}]},{'Elixir.LoggerJSON.Formatter.RedactorEncoder',encode,2,[{file,"lib/logger_json/formatter/redactor_encoder.ex"},{line,51}]}]}}]},level=>debug}
    reason: {error,function_clause,[{'Elixir.Enum','-map/2-lists^map/1-1-',[#Fun<Elixir.LoggerJSON.Formatter.RedactorEncoder.3.73320869>,<<101,120,105,116,101,100,32,105,110,58,32,71,101,110,83,101,114,118,101,114,46,99,97,108,108,40,67,114,97,115,104,105,110,103,71,101,110,83,101,114,118,101,114,44,32,58,98,111,111,109,44,32,53,48,48,48,41,10,32,32,32,32,42,42,32,40,69,88,73,84,41,32,97,110,32,101,120,99,101,112,116,105,111,110,32,119,97,115,32,114,97,105,115,101,100,58,10,32,32,32,32,32,32,32,32,42,42,32,40,82,117,110,116,105,109,101,69,114,114,111,114,41,32,98,111,111,109,10,32,32,32,32,32,32,32,32,32,32,32,32,102,97,105,108,46,101,120,115,58,49,57,58,32,67,114,97,115,104,105,110,103,71,101,110,83,101,114,118,101,114,46,104,97,110,100,108,101,95,99,97,108,108,47,51,10,32,32,32,32,32,32,32,32,32,32,32,32,40,115,116,100,108,105,98,32,53,46,50,46,51,41,32,103,101,110,95,115,101,114,118,101,114,46,101,114,108,58,49,49,51,49,58,32,58,103,101,110,95,115,101,114,118,101,114,46,116,114,121,95,104,97,110,100,108,101,95,99,97,108,108,47,52,10,32,32,32,32,32,32,32,32,32,32,32,32,40,115,116,100,108,105,98,32,53,46,50,46,51,41,32,103,101,110,95,115,101,114,118,101,114,46,101,114,108,58,49,49,54,48,58,32,58,103,101,110,95,115,101,114,118,101,114,46,104,97,110,100,108,101,95,109,115,103,47,54,10,32,32,32,32,32,32,32,32,32,32,32,32,40,115,116,100,108,105,98,32,53,46,50,46,51,41,32,112,114,111,99,95,108,105,98,46,101,114,108,58,50,52,49,58,32,58,112,114,111,99,95,108,105,98,46,105,110,105,116,95,112,95,100,111,95,97,112,112,108,121,47,51>>],[{file,"lib/enum.ex"},{line,1703}]},{'Elixir.Enum','-map/2-lists^map/1-1-',2,[{file,"lib/enum.ex"},{line,1703}]},{'Elixir.Enum','-map/2-lists^map/1-1-',2,[{file,"lib/enum.ex"},{line,1703}]},{'Elixir.Enum','-map/2-lists^map/1-1-',2,[{file,"lib/enum.ex"},{line,1703}]},{'Elixir.Enum','-map/2-lists^map/1-1-',2,[{file,"lib/enum.ex"},{line,1703}]},{'Elixir.Enum','-map/2-lists^map/1-1-',2,[{file,"lib/enum.ex"},{line,1703}]},{'Elixir.LoggerJSON.Formatter.RedactorEncoder',encode_key_value,2,[{file,"lib/logger_json/formatter/redactor_encoder.ex"},{line,69}]},{'Elixir.LoggerJSON.Formatter.RedactorEncoder','-encode/2-fun-0-',3,[{file,"lib/logger_json/formatter/redactor_encoder.ex"},{line,52}]}]}
2024-11-07T14:31:58.009549+00:00 error: FORMATTER CRASH: {string,[<<"Task #PID<0.166.0> started from #PID<0.98.0> terminating">>,[[<<"\n** (stop) ">>|<<"exited in: GenServer.call(CrashingGenServer, :boom, 5000)\n    ** (EXIT) an exception was raised:\n        ** (RuntimeError) boom\n            fail.exs:19: CrashingGenServer.handle_call/3\n            (stdlib 5.2.3) gen_server.erl:1131: :gen_server.try_handle_call/4\n            (stdlib 5.2.3) gen_server.erl:1160: :gen_server.handle_msg/6\n            (stdlib 5.2.3) proc_lib.erl:241: :proc_lib.init_p_do_apply/3">>],[<<"\n    ">>|<<"(elixir 1.17.2) lib/gen_server.ex:1128: GenServer.call/3">>],[<<"\n    ">>|<<"fail.exs:29: anonymous fn/1 in :elixir_compiler_0.__FILE__/1">>],[<<"\n    ">>|<<"(elixir 1.17.2) lib/task/supervised.ex:101: Task.Supervised.invoke_mfa/2">>]],<<"\nFunction: #Function<0.27189602 in file:fail.exs>">>,<<"\n    Args: []">>]}
2024-11-07T14:31:58.012119+00:00 debug: FORMATTER CRASH: {report,[{formatter_crashed,'Elixir.LoggerJSON.Formatters.Datadog'},{config,[{encoder_opts,[{pretty,true}]}]},{log_event,#{meta => #{error_logger => #{tag => error_msg},pid => <0.166.0>,time => 1730989918009549,gl => <0.69.0>,domain => [otp,elixir],report_cb => fun 'Elixir.Task.Supervised':format_report/1,callers => [<0.98.0>],crash_reason => {{{#{message => <<"boom">>,'__struct__' => 'Elixir.RuntimeError','__exception__' => true},[{'Elixir.CrashingGenServer',handle_call,3,[{file,"fail.exs"},{line,19},{error_info,#{module => 'Elixir.Exception'}}]},{gen_server,try_handle_call,4,[{file,"gen_server.erl"},{line,1131}]},{gen_server,handle_msg,6,[{file,"gen_server.erl"},{line,1160}]},{proc_lib,init_p_do_apply,3,[{file,"proc_lib.erl"},{line,241}]}]},{'Elixir.GenServer',call,['Elixir.CrashingGenServer',boom,5000]}},[{'Elixir.GenServer',call,3,[{file,"lib/gen_server.ex"},{line,1128}]},{elixir_compiler_0,'-__FILE__/1-fun-0-',1,[{file,"fail.exs"},{line,29}]},{'Elixir.Task.Supervised',invoke_mfa,2,[{file,"lib/task/supervised.ex"},{line,101}]}]}},msg => {string,[<<"Task #PID<0.166.0> started from #PID<0.98.0> terminating">>,[[<<"\n** (stop) ">>|<<"exited in: GenServer.call(CrashingGenServer, :boom, 5000)\n    ** (EXIT) an exception was raised:\n        ** (RuntimeError) boom\n            fail.exs:19: CrashingGenServer.handle_call/3\n            (stdlib 5.2.3) gen_server.erl:1131: :gen_server.try_handle_call/4\n            (stdlib 5.2.3) gen_server.erl:1160: :gen_server.handle_msg/6\n            (stdlib 5.2.3) proc_lib.erl:241: :proc_lib.init_p_do_apply/3">>],[<<"\n    ">>|<<"(elixir 1.17.2) lib/gen_server.ex:1128: GenServer.call/3">>],[<<"\n    ">>|<<"fail.exs:29: anonymous fn/1 in :elixir_compiler_0.__FILE__/1">>],[<<"\n    ">>|<<"(elixir 1.17.2) lib/task/supervised.ex:101: Task.Supervised.invoke_mfa/2">>]],<<"\nFunction: #Function<0.27189602 in file:fail.exs>">>,<<"\n    Args: []">>]},level => error}},{reason,{error,function_clause,[{'Elixir.Enum','-map/2-lists^map/1-1-',[#Fun<Elixir.LoggerJSON.Formatter.RedactorEncoder.3.73320869>,<<"exited in: GenServer.call(CrashingGenServer, :boom, 5000)\n    ** (EXIT) an exception was raised:\n        ** (RuntimeError) boom\n            fail.exs:19: CrashingGenServer.handle_call/3\n            (stdlib 5.2.3) gen_server.erl:1131: :gen_server.try_handle_call/4\n            (stdlib 5.2.3) gen_server.erl:1160: :gen_server.handle_msg/6\n            (stdlib 5.2.3) proc_lib.erl:241: :proc_lib.init_p_do_apply/3">>],[{file,"lib/enum.ex"},{line,1703}]},{'Elixir.Enum','-map/2-lists^map/1-1-',2,[{file,"lib/enum.ex"},{line,1703}]},{'Elixir.Enum','-map/2-lists^map/1-1-',2,[{file,"lib/enum.ex"},{line,1703}]},{'Elixir.Enum','-map/2-lists^map/1-1-',2,[{file,"lib/enum.ex"},{line,1703}]},{'Elixir.LoggerJSON.Formatter.RedactorEncoder',encode_key_value,2,[{file,"lib/logger_json/formatter/redactor_encoder.ex"},{line,69}]},{'Elixir.LoggerJSON.Formatter.RedactorEncoder','-encode/2-fun-0-',3,[{file,"lib/logger_json/formatter/redactor_encoder.ex"},{line,52}]},{maps,fold_1,4,[{file,"maps.erl"},{line,416}]},{'Elixir.LoggerJSON.Formatter.RedactorEncoder',encode,2,[{file,"lib/logger_json/formatter/redactor_encoder.ex"},{line,51}]}]}}]}

[ruslandoga]

Maybe it might make sense to call meta.report_cb if it's set. AFAIK that's what Logger.Formatter does. It might be difficult to handle all possible reports "on our own" (even Elixir fails sometimes: elixir-lang/elixir#13682 elixir-lang/elixir#14020) and IMO a less structured meta.report_cb is better than a crash.

UPDATE: LoggerJSON already uses report_cb when available:

logger_json/lib/logger_json/formatter/message.ex

Lines 15 to 31 in 60a5d48

	def format_message(
	{:report, data},
	%{report_cb: callback} = meta,
	%{binary: binary_fmt, structured: structured_fmt} = formatters
	) do
	cond do
	is_function(callback, 1) and callback != (&:logger.format_otp_report/1) ->
	format_message(callback.(data), meta, formatters)
	is_function(callback, 2) ->
	callback.(data, %{depth: :unlimited, chars_limit: :unlimited, single_line: false})
	|> binary_fmt.()
	true ->
	structured_fmt.(data)
	end
	end