Handle OTP 20 GenServer log messages (#6071)

Signed-off-by: James Fish <james@fishcakez.com>

Author: fishcakez

lib/logger/lib/logger/translator.ex

@@ -36,11 +36,12 @@ defmodule Logger.Translator do
     opts = Application.get_env(:logger, :translator_inspect_opts)
 
     case message do
-      {'** Generic server ' ++ _, [name, last, state, reason]} ->
+      {'** Generic server ' ++ _, [name, last, state, reason | client]} ->
         msg = ["GenServer #{inspect name} terminating", format_stop(reason),
-               "\nLast message: #{inspect last, opts}"]
+               "\nLast message#{format_from(client)}: #{inspect last, opts}"]
         if min_level == :debug do
-          {:ok, [msg | "\nState: #{inspect state, opts}"]}
+          {:ok, [msg, "\nState: #{inspect state, opts}" |
+                 format_client(client)]}
         else
           {:ok, msg}
         end
@@ -375,4 +376,24 @@ defmodule Logger.Translator do
 
   defp format_mfa(mod, fun, :undefined), do: [inspect(mod), ?., to_string(fun) | "/?"]
   defp format_mfa(mod, fun, args), do: Exception.format_mfa(mod, fun, args)
+
+  defp format_from([]),
+    do: ""
+  defp format_from([from]),
+    do: " (from #{inspect(from)})"
+  defp format_from([from, stacktrace]) when is_list(stacktrace),
+    do: " (from #{inspect(from)})"
+  defp format_from([from, node_name]) when is_atom(node_name),
+    do: " (from #{inspect(from)} on #{inspect(node_name)})"
+
+  defp format_client([from]) do
+    "\nClient #{inspect(from)} is dead"
+  end
+  defp format_client([from, stacktrace]) when is_list(stacktrace) do
+    ["\nClient #{inspect(from)} is alive\n" |
+      Exception.format_stacktrace(stacktrace)]
+  end
+  defp format_client(_) do
+    []
+  end
 end

lib/logger/test/logger/translator_test.exs

@@ -5,9 +5,18 @@ defmodule Logger.TranslatorTest do
   defmodule MyGenServer do
     use GenServer
 
+    def handle_cast(:error, _) do
+      raise "oops"
+    end
+
     def handle_call(:error, _, _) do
       raise "oops"
     end
+    def handle_call(:error_on_down, {pid, _}, _) do
+      mon = Process.monitor(pid)
+      assert_receive {:DOWN, ^mon, _, _, _}
+      raise "oops"
+    end
   end
 
   defmodule MyGenEvent do
@@ -93,20 +102,101 @@ defmodule Logger.TranslatorTest do
     Application.put_env(:logger, :translator_inspect_opts, [])
   end
 
-  test "translates GenServer crashes on debug" do
+  # TODO: Remove this check once we depend only on 20
+  if :erlang.system_info(:otp_release) >= '20' do
+    test "translates GenServer crashes on debug" do
+      {:ok, pid} = GenServer.start(MyGenServer, :ok)
+
+      assert capture_log(:debug, fn ->
+        catch_exit(GenServer.call(pid, :error))
+      end) =~ ~r"""
+      \[error\] GenServer #PID<\d+\.\d+\.\d+> terminating
+      \*\* \(RuntimeError\) oops
+      .*
+      Last message \(from #PID<\d+\.\d+\.\d+>\): :error
+      State: :ok
+      Client #PID<\d+\.\d+\.\d+> is alive
+      .*
+      """s
+    end
+
+    test "translates GenServer crashes with named client on debug" do
+      {:ok, pid} = GenServer.start(MyGenServer, :ok)
+
+      assert capture_log(:debug, fn ->
+        Process.register(self(), :named_client)
+        catch_exit(GenServer.call(pid, :error))
+      end) =~ ~r"""
+      \[error\] GenServer #PID<\d+\.\d+\.\d+> terminating
+      \*\* \(RuntimeError\) oops
+      .*
+      Last message \(from :named_client\): :error
+      State: :ok
+      Client :named_client is alive
+      .*
+      """s
+    end
+
+    test "translates GenServer crashes with dead client on debug" do
+      {:ok, pid} = GenServer.start(MyGenServer, :ok)
+
+      assert capture_log(:debug, fn ->
+        mon = Process.monitor(pid)
+        spawn_link(fn() ->
+          catch_exit(GenServer.call(pid, :error_on_down, 0))
+        end)
+        assert_receive {:DOWN, ^mon, _, _, _}
+      end) =~ ~r"""
+      \[error\] GenServer #PID<\d+\.\d+\.\d+> terminating
+      \*\* \(RuntimeError\) oops
+      .*
+      Last message \(from #PID<\d+\.\d+\.\d+>\): :error_on_down
+      State: :ok
+      Client #PID<\d+\.\d+\.\d+> is dead
+      """s
+    end
+  else
+    test "translates GenServer crashes on debug" do
+      {:ok, pid} = GenServer.start(MyGenServer, :ok)
+
+      assert capture_log(:debug, fn ->
+        catch_exit(GenServer.call(pid, :error))
+      end) =~ ~r"""
+      \[error\] GenServer #PID<\d+\.\d+\.\d+> terminating
+      \*\* \(RuntimeError\) oops
+      .*
+      Last message: :error
+      State: :ok
+      """s
+    end
+  end
+
+  test "translates GenServer crashes with no client" do
     {:ok, pid} = GenServer.start(MyGenServer, :ok)
 
     assert capture_log(:debug, fn ->
-      catch_exit(GenServer.call(pid, :error))
+      mon = Process.monitor(pid)
+      GenServer.cast(pid, :error)
+      assert_receive {:DOWN, ^mon, _, _, _}
     end) =~ ~r"""
     \[error\] GenServer #PID<\d+\.\d+\.\d+> terminating
     \*\* \(RuntimeError\) oops
     .*
-    Last message: :error
+    Last message: {:"\$gen_cast", :error}
     State: :ok
     """s
   end
 
+  test "translates GenServer crashes with no client on debug" do
+    {:ok, pid} = GenServer.start(MyGenServer, :ok)
+
+    refute capture_log(:debug, fn ->
+      mon = Process.monitor(pid)
+      GenServer.cast(pid, :error)
+      assert_receive {:DOWN, ^mon, _, _, _}
+    end) =~ "Client"
+  end
+
   test "translates :gen_event crashes" do
     {:ok, pid} = :gen_event.start()
     :ok = :gen_event.add_handler(pid, MyGenEvent, :ok)