Fix logger crash when :gen_statem format_status/2 does not return a tuple

Author: sabiwara

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)

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()