From d6fc706109e5418f7ac3177192c9a8a1a8890436 Mon Sep 17 00:00:00 2001 From: sabiwara Date: Sat, 22 Jun 2024 10:11:43 +0900 Subject: [PATCH 1/3] Fix logger crash when :gen_statem format_status/2 does not return a tuple --- lib/logger/lib/logger/translator.ex | 17 ++++--- lib/logger/test/logger/translator_test.exs | 52 +++++++++++++++++++++- 2 files changed, 63 insertions(+), 6 deletions(-) diff --git a/lib/logger/lib/logger/translator.ex b/lib/logger/lib/logger/translator.ex index f529616ed85..8fb0609a51a 100644 --- a/lib/logger/lib/logger/translator.ex +++ b/lib/logger/lib/logger/translator.ex @@ -298,7 +298,7 @@ defmodule Logger.Translator do client_info: client, name: name, reason: {kind, reason, stack}, - state: {state, data}, + state: state, queue: queue, postponed: postponed, callback_mode: callback_mode, @@ -324,12 +324,19 @@ defmodule Logger.Translator do ["\nPostponed: #{inspect(postponed, inspect_opts)}"] if min_level == :debug do + state_info = + case state do + {state, data} -> + ["\nState: ", inspect(state, inspect_opts), "\nData: ", inspect(data, inspect_opts)] + + # Might be formatted by c:format_status/2 and not be a pair + state -> + ["\nState: ", inspect(state, inspect_opts)] + end + msg = [ msg, - "\nState: ", - inspect(state, inspect_opts), - "\nData: ", - inspect(data, inspect_opts), + state_info, "\nCallback mode: ", "#{inspect(callback_mode, inspect_opts)}, state_enter: #{state_enter?}" | format_client_info(client) diff --git a/lib/logger/test/logger/translator_test.exs b/lib/logger/test/logger/translator_test.exs index 331a4b8e125..ab2a96ab352 100644 --- a/lib/logger/test/logger/translator_test.exs +++ b/lib/logger/test/logger/translator_test.exs @@ -100,6 +100,28 @@ defmodule Logger.TranslatorTest do end end + defmodule MyGenStatemFormatStatus do + @behaviour :gen_statem + + @impl true + def callback_mode, do: :handle_event_function + + @impl true + def init(state) do + {:ok, :no_state, state} + end + + @impl true + def handle_event({:call, _}, :error, :no_state, _data) do + raise "oops" + end + + @impl :gen_statem + def format_status(_opts, [_pdict, _, state]) do + state + end + end + defmodule MyBridge do @behaviour :supervisor_bridge @@ -393,7 +415,7 @@ defmodule Logger.TranslatorTest do assert {%RuntimeError{message: "oops"}, [_ | _]} = process_metadata[:crash_reason] refute Map.has_key?(gen_statem_metadata, :initial_call) - assert process_metadata[:initial_call] == {Logger.TranslatorTest.MyGenStatem, :init, 1} + assert process_metadata[:initial_call] == {MyGenStatem, :init, 1} refute Map.has_key?(gen_statem_metadata, :registered_name) refute Map.has_key?(process_metadata, :registered_name) @@ -552,6 +574,34 @@ defmodule Logger.TranslatorTest do assert_receive {:event, {:string, ["Process " | _]}, _process_metadata} end + test "translates :gen_statem crashes when format_status/2 does not return a tuple" do + {:ok, pid} = :gen_statem.start(MyGenStatemFormatStatus, :ok, []) + + assert capture_log(:debug, fn -> + catch_exit(:gen_statem.call(pid, :error)) + end) =~ ~r""" + \[error\] :gen_statem #PID<\d+\.\d+\.\d+> terminating + \*\* \(RuntimeError\) oops + .* + Queue: .* + Postponed: \[\] + State: :ok + Callback mode: .*, state_enter: false + """s + + assert_receive {:event, {:string, [[":gen_statem " <> _ | _] | _]}, gen_statem_metadata} + assert_receive {:event, {:string, ["Process " | _]}, process_metadata} + + assert {%RuntimeError{message: "oops"}, [_ | _]} = gen_statem_metadata[:crash_reason] + assert {%RuntimeError{message: "oops"}, [_ | _]} = process_metadata[:crash_reason] + + refute Map.has_key?(gen_statem_metadata, :initial_call) + assert process_metadata[:initial_call] == {MyGenStatemFormatStatus, :init, 1} + + refute Map.has_key?(gen_statem_metadata, :registered_name) + refute Map.has_key?(process_metadata, :registered_name) + end + test "translates Task crashes" do {:ok, pid} = Task.start_link(__MODULE__, :task, [self()]) parent = self() From dadb7974bafa99cd28e781a71544c957edaf9893 Mon Sep 17 00:00:00 2001 From: sabiwara Date: Sat, 22 Jun 2024 17:16:37 +0900 Subject: [PATCH 2/3] Stop unpacking {state, data} --- lib/logger/lib/logger/translator.ex | 13 ++----------- lib/logger/test/logger/translator_test.exs | 14 +++++--------- 2 files changed, 7 insertions(+), 20 deletions(-) diff --git a/lib/logger/lib/logger/translator.ex b/lib/logger/lib/logger/translator.ex index 8fb0609a51a..a2850047741 100644 --- a/lib/logger/lib/logger/translator.ex +++ b/lib/logger/lib/logger/translator.ex @@ -324,19 +324,10 @@ defmodule Logger.Translator do ["\nPostponed: #{inspect(postponed, inspect_opts)}"] if min_level == :debug do - state_info = - case state do - {state, data} -> - ["\nState: ", inspect(state, inspect_opts), "\nData: ", inspect(data, inspect_opts)] - - # Might be formatted by c:format_status/2 and not be a pair - state -> - ["\nState: ", inspect(state, inspect_opts)] - end - msg = [ msg, - state_info, + "\nState: ", + inspect(state, inspect_opts), "\nCallback mode: ", "#{inspect(callback_mode, inspect_opts)}, state_enter: #{state_enter?}" | format_client_info(client) diff --git a/lib/logger/test/logger/translator_test.exs b/lib/logger/test/logger/translator_test.exs index ab2a96ab352..883e7076705 100644 --- a/lib/logger/test/logger/translator_test.exs +++ b/lib/logger/test/logger/translator_test.exs @@ -467,7 +467,7 @@ defmodule Logger.TranslatorTest do assert capture_log(:debug, fn -> catch_exit(:gen_statem.call(pid, :error)) end) =~ """ - [:ok, :ok, :ok, ...] + State: {:started, [:ok, ...]} """ after Application.put_env(:logger, :translator_inspect_opts, []) @@ -484,8 +484,7 @@ defmodule Logger.TranslatorTest do .* Queue: .* Postponed: \[\] - State: :started - Data: :ok + State: {:started, :ok} Callback mode: :state_functions, state_enter: false Client #PID<\d+\.\d+\.\d+> is alive .* @@ -510,8 +509,7 @@ defmodule Logger.TranslatorTest do .* Queue: .* Postponed: \[\] - State: :started - Data: :ok + State: {:started, :ok} Callback mode: :state_functions, state_enter: false Client :named_client is alive .* @@ -535,8 +533,7 @@ defmodule Logger.TranslatorTest do .* Queue: .* Postponed: \[\] - State: :started - Data: :ok + State: {:started, :ok} Callback mode: :state_functions, state_enter: false Client #PID<\d+\.\d+\.\d+> is dead """s @@ -555,8 +552,7 @@ defmodule Logger.TranslatorTest do .* Queue: .* Postponed: \[\] - State: :started - Data: :ok + State: {:started, :ok} Callback mode: :state_functions, state_enter: false """s end From 578e0434c69f1107d20019b21a27ebc895b15787 Mon Sep 17 00:00:00 2001 From: sabiwara Date: Sat, 22 Jun 2024 18:53:55 +0900 Subject: [PATCH 3/3] Rename test --- lib/logger/test/logger/translator_test.exs | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/lib/logger/test/logger/translator_test.exs b/lib/logger/test/logger/translator_test.exs index 883e7076705..23a4fef9f72 100644 --- a/lib/logger/test/logger/translator_test.exs +++ b/lib/logger/test/logger/translator_test.exs @@ -100,7 +100,7 @@ defmodule Logger.TranslatorTest do end end - defmodule MyGenStatemFormatStatus do + defmodule MyGenStatemHandleEvent do @behaviour :gen_statem @impl true @@ -570,8 +570,8 @@ defmodule Logger.TranslatorTest do assert_receive {:event, {:string, ["Process " | _]}, _process_metadata} end - test "translates :gen_statem crashes when format_status/2 does not return a tuple" do - {:ok, pid} = :gen_statem.start(MyGenStatemFormatStatus, :ok, []) + test "translates :gen_statem crashes when callback_mode is :handle_event_function" do + {:ok, pid} = :gen_statem.start(MyGenStatemHandleEvent, :ok, []) assert capture_log(:debug, fn -> catch_exit(:gen_statem.call(pid, :error)) @@ -592,7 +592,7 @@ defmodule Logger.TranslatorTest do assert {%RuntimeError{message: "oops"}, [_ | _]} = process_metadata[:crash_reason] refute Map.has_key?(gen_statem_metadata, :initial_call) - assert process_metadata[:initial_call] == {MyGenStatemFormatStatus, :init, 1} + assert process_metadata[:initial_call] == {MyGenStatemHandleEvent, :init, 1} refute Map.has_key?(gen_statem_metadata, :registered_name) refute Map.has_key?(process_metadata, :registered_name)