Improve reporting of crashes in :logger handler

Author: whatyouhide

lib/sentry/logger_handler.ex

@@ -169,8 +169,7 @@ defmodule Sentry.LoggerHandler do
          sentry_opts,
          %__MODULE__{} = config
        ) do
-    message = :unicode.characters_to_binary(unicode_chardata)
-    log_from_crash_reason(log_event.meta[:crash_reason], message, sentry_opts, config)
+    log_from_crash_reason(log_event.meta[:crash_reason], unicode_chardata, sentry_opts, config)
   end
 
   # "report" here is of type logger:report/0, which is a map or keyword list.
@@ -222,7 +221,7 @@ defmodule Sentry.LoggerHandler do
 
   defp log_from_crash_reason(
          {exception, stacktrace},
-         _string_message,
+         _chardata_message,
          sentry_opts,
          %__MODULE__{}
        )
@@ -231,23 +230,61 @@ defmodule Sentry.LoggerHandler do
     Sentry.capture_exception(exception, sentry_opts)
   end
 
-  defp log_from_crash_reason({reason, stacktrace}, string_message, sentry_opts, %__MODULE__{})
+  defp log_from_crash_reason({reason, stacktrace}, chardata_message, sentry_opts, %__MODULE__{})
        when is_list(stacktrace) do
     sentry_opts =
       sentry_opts
       |> Keyword.put(:stacktrace, stacktrace)
       |> Keyword.update!(:extra, &Map.put(&1, :crash_reason, inspect(reason)))
+      |> Keyword.update!(:extra, &Map.merge(extra_info_from_message(chardata_message), &1))
 
-    Sentry.capture_message(string_message, sentry_opts)
+    case reason do
+      {type, {GenServer, :call, [_pid, call, _timeout]}} = reason
+      when type in [:noproc, :timeout] ->
+        sentry_opts =
+          Keyword.put_new(sentry_opts, :fingerprint, [
+            Atom.to_string(type),
+            "genserver_call",
+            inspect(call)
+          ])
+
+        Sentry.capture_message(Exception.format_exit(reason), sentry_opts)
+
+      _other ->
+        string_message = :unicode.characters_to_binary(chardata_message)
+        Sentry.capture_message(string_message, sentry_opts)
+    end
   end
 
-  defp log_from_crash_reason(_other_reason, string_message, sentry_opts, %__MODULE__{
+  defp log_from_crash_reason(_other_reason, chardata_message, sentry_opts, %__MODULE__{
          capture_log_messages: true
        }) do
+    string_message = :unicode.characters_to_binary(chardata_message)
     Sentry.capture_message(string_message, sentry_opts)
   end
 
   defp log_from_crash_reason(_other_reason, _string_message, _sentry_opts, _config) do
     :ok
   end
+
+  defp extra_info_from_message([
+         [
+           "GenServer ",
+           _pid,
+           " terminating",
+           _reason,
+           "\nLast message",
+           _from,
+           ": ",
+           last_message
+         ],
+         "\nState: ",
+         state | _rest
+       ]) do
+    %{genserver_state: state, last_message: last_message}
+  end
+
+  defp extra_info_from_message(_message) do
+    %{}
+  end
 end

lib/sentry/logger_utils.ex

@@ -13,7 +13,11 @@ defmodule Sentry.LoggerUtils do
   @spec build_sentry_options(Logger.level(), keyword() | nil, map(), [atom()] | :all) ::
           keyword()
   def build_sentry_options(level, sentry_context, meta, allowed_meta) do
-    default_extra = %{logger_metadata: logger_metadata(meta, allowed_meta), logger_level: level}
+    default_extra =
+      Map.merge(
+        %{logger_metadata: logger_metadata(meta, allowed_meta), logger_level: level},
+        Map.take(meta, [:domain])
+      )
 
     (sentry_context || get_sentry_options_from_callers(meta[:callers]) || %{})
     |> Map.new()

test/sentry/logger_handler_test.exs

@@ -185,9 +185,63 @@ defmodule Sentry.LoggerHandlerTest do
       if System.otp_release() >= "26" do
         assert [] = event.exception
         assert [_thread] = event.threads
+        assert event.extra.genserver_state == ":no_state"
+        assert event.extra.last_message =~ "{:run, #Function"
       end
     end
 
+    test "an exit while calling another GenServer is reported nicely",
+         %{sender_ref: ref, test_genserver: test_genserver} do
+      # Get a PID and make sure it's done before using it.
+      {pid, monitor_ref} = spawn_monitor(fn -> :ok end)
+      assert_receive {:DOWN, ^monitor_ref, _, _, _}
+
+      run_and_catch_exit(test_genserver, fn ->
+        GenServer.call(pid, :ping)
+      end)
+
+      assert_receive {^ref, event}
+
+      assert event.exception == []
+      assert event.extra.domain == [:otp]
+      assert event.extra.logger_level == :error
+      assert event.extra.logger_metadata == %{}
+      assert event.extra.crash_reason =~ "{:noproc, {GenServer, :call"
+      assert event.fingerprint == ["noproc", "genserver_call", ":ping"]
+
+      assert event.message.formatted == """
+             exited in: GenServer.call(#{inspect(pid)}, :ping, 5000)
+                 ** (EXIT) no process: the process is not alive or there's no process currently \
+             associated with the given name, possibly because its application isn't started\
+             """
+
+      assert [%{stacktrace: stacktrace}] = event.threads
+      assert Enum.find(stacktrace.frames, &(&1.function == "GenServer.call/3"))
+    end
+
+    test "a timeout while calling another GenServer is reported nicely",
+         %{sender_ref: ref, test_genserver: test_genserver} do
+      {:ok, agent} = Agent.start_link(fn -> nil end)
+
+      run_and_catch_exit(test_genserver, fn ->
+        Agent.get(agent, & &1, 0)
+      end)
+
+      assert_receive {^ref, event}
+
+      assert event.exception == []
+      assert event.extra.domain == [:otp]
+      assert event.extra.logger_level == :error
+      assert event.extra.logger_metadata == %{}
+      assert event.extra.crash_reason =~ "{:timeout, {GenServer, :call"
+      assert ["timeout", "genserver_call", "{:get" <> _] = event.fingerprint
+
+      assert event.message.formatted =~ "exited in: GenServer.call(#{inspect(agent)}, {:get, "
+
+      assert [%{stacktrace: stacktrace}] = event.threads
+      assert Enum.find(stacktrace.frames, &(&1.function == "GenServer.call/3"))
+    end
+
     @tag handler_config: %{metadata: [:string, :number, :map, :list, :chardata]}
     test "includes Logger metadata for keys configured to be included",
          %{sender_ref: ref, test_genserver: test_genserver} do
@@ -285,7 +339,7 @@ defmodule Sentry.LoggerHandlerTest do
       assert [] = event.exception
       assert [thread] = event.threads
 
-      assert event.message.formatted =~ "** (stop) exited in: GenServer.call("
+      assert event.message.formatted =~ "exited in: GenServer.call("
       assert event.message.formatted =~ "** (EXIT) time out"
       assert length(thread.stacktrace.frames) > 0
     end