Fix infinite logging loop (#657)

Closes #656.

Author: whatyouhide

lib/sentry.ex

@@ -171,7 +171,7 @@ defmodule Sentry do
   > with `:source_code_exclude_patterns`.
   """
 
-  alias Sentry.{Config, Event}
+  alias Sentry.{Config, Event, LoggerUtils}
 
   require Logger
 
@@ -324,7 +324,7 @@ defmodule Sentry do
 
     cond do
       is_nil(event.message) and event.exception == [] ->
-        Logger.log(Config.log_level(), "Sentry: unable to parse exception")
+        LoggerUtils.log("Cannot report event without message or exception: #{inspect(event)}")
         :ignored
 
       !Config.dsn() ->

lib/sentry/client.ex

@@ -5,7 +5,7 @@ defmodule Sentry.Client do
   # and sampling.
   # See https://develop.sentry.dev/sdk/unified-api/#client.
 
-  alias Sentry.{Config, Dedupe, Envelope, Event, Interfaces, Transport}
+  alias Sentry.{Config, Dedupe, Envelope, Event, Interfaces, LoggerUtils, Transport}
 
   require Logger
 
@@ -72,7 +72,10 @@ defmodule Sentry.Client do
           :ok
 
         :existing ->
-          log("Event dropped due to being a duplicate of a previously-captured event.")
+          LoggerUtils.log(
+            "Event dropped due to being a duplicate of a previously-captured event."
+          )
+
           :excluded
       end
     else
@@ -241,10 +244,6 @@ defmodule Sentry.Client do
           nil
       end
 
-    if message, do: log(fn -> ["Failed to send Sentry event. ", message] end)
-  end
-
-  defp log(message) do
-    Logger.log(Config.log_level(), message, domain: [:sentry])
+    if message, do: LoggerUtils.log(fn -> ["Failed to send Sentry event. ", message] end)
   end
 end

lib/sentry/logger_utils.ex

@@ -1,7 +1,14 @@
 defmodule Sentry.LoggerUtils do
   @moduledoc false
 
-  # Utilities that are shared between Sentry.LoggerHandler and Sentry.LoggerBackend.
+  # Utilities that are shared between Sentry.LoggerHandler and Sentry.LoggerBackend, plus
+  # functions that wrap Elixir's Logger and that make sure we use the right options for Logger
+  # calls. For example, if we (the Sentry SDK) log without using `domain: [:sentry]`, then we can
+  # run into loops in which Sentry reports messages that the SDK itself logs.
+
+  alias Sentry.Config
+
+  require Logger
 
   @spec build_sentry_options(Logger.level(), keyword() | nil, map(), [atom()] | :all) ::
           keyword()
@@ -19,9 +26,10 @@ defmodule Sentry.LoggerUtils do
     |> Map.to_list()
   end
 
+  # Always excludes the :sentry domain, to avoid infinite logging loops.
   @spec excluded_domain?([atom()], [atom()]) :: boolean()
   def excluded_domain?(logged_domains, excluded_domains) do
-    Enum.any?(logged_domains, &(&1 in excluded_domains))
+    Enum.any?(logged_domains, &(&1 == :sentry or &1 in excluded_domains))
   end
 
   defp elixir_logger_level_to_sentry_level(level) do
@@ -76,4 +84,10 @@ defmodule Sentry.LoggerUtils do
   defp attempt_to_convert_iodata(other) do
     other
   end
+
+  @spec log(iodata() | (-> iodata()), keyword()) :: :ok
+  def log(message_or_fun, meta \\ []) when is_list(meta) do
+    meta = Keyword.merge(meta, domain: [:sentry])
+    Logger.log(Config.log_level(), message_or_fun, meta)
+  end
 end

lib/sentry/transport/sender.ex

@@ -3,7 +3,7 @@ defmodule Sentry.Transport.Sender do
 
   use GenServer
 
-  alias Sentry.{Config, Envelope, Event, Transport}
+  alias Sentry.{Envelope, Event, LoggerUtils, Transport}
 
   require Logger
 
@@ -72,8 +72,7 @@ defmodule Sentry.Transport.Sender do
         end
 
       if message do
-        level = Config.log_level()
-        Logger.log(level, fn -> ["Failed to send Sentry event. ", message] end, domain: [:sentry])
+        LoggerUtils.log(fn -> ["Failed to send Sentry event. ", message] end)
       end
     end
   end

test/logger_backend_test.exs

@@ -306,6 +306,15 @@ defmodule Sentry.LoggerBackendTest do
     assert event.message == "Error"
   end
 
+  test "doesn't log events with :sentry as a domain" do
+    Logger.configure_backend(Sentry.LoggerBackend, capture_log_messages: true)
+    ref = register_before_send()
+
+    Logger.error("Error", domain: [:sentry])
+
+    refute_receive {^ref, _event}
+  end
+
   test "sets event level to Logger message level" do
     Logger.configure_backend(Sentry.LoggerBackend,
       level: :warning,

test/sentry/logger_handler_test.exs

@@ -143,6 +143,12 @@ defmodule Sentry.LoggerHandlerTest do
       assert_receive {^ref, event}
       assert event.message == "no domain"
     end
+
+    @tag handler_config: %{capture_log_messages: true}
+    test "ignores log messages that are logged by Sentry itself", %{sender_ref: ref} do
+      Logger.error("Sentry had an error", domain: [:sentry])
+      refute_receive {^ref, _event}
+    end
   end
 
   describe "with a crashing GenServer" do

test/sentry_test.exs

@@ -76,7 +76,47 @@ defmodule SentryTest do
         assert Sentry.send_event(Sentry.Event.create_event([])) == :ignored
       end)
 
-    assert log =~ "Sentry: unable to parse exception"
+    assert log =~ "Cannot report event without message or exception: %Sentry.Event{"
+  end
+
+  test "doesn't incur into infinite logging loops because we prevent that", %{bypass: bypass} do
+    put_test_config(dedup_events: true)
+    message_to_report = "Hello #{System.unique_integer([:positive])}"
+
+    Bypass.expect(bypass, fn conn ->
+      Plug.Conn.send_resp(conn, 200, ~s<{"id": "340"}>)
+    end)
+
+    :ok =
+      :logger.add_handler(:sentry_handler, Sentry.LoggerHandler, %{
+        config: %{capture_log_messages: true, level: :debug}
+      })
+
+    on_exit(fn ->
+      _ = :logger.remove_handler(:sentry_handler)
+    end)
+
+    # First one is reported correctly as it has no duplicates
+    assert {:ok, "340"} = Sentry.capture_message(message_to_report)
+
+    log =
+      capture_log(fn ->
+        # Then, we log the same message, which triggers the SDK to log that the message wasn't sent
+        # because it's a duplicate.
+        assert :excluded = Sentry.capture_message(message_to_report)
+
+        # Then we log the same message again, which again triggers the SDK to log that the message
+        # wasn't sent. But this time, *that* log (the one about the duplicate event) is also a
+        # duplicate. So, we can test that it doesn't result in an infinite logging loop.
+        assert :excluded = Sentry.capture_message(message_to_report)
+      end)
+
+    logged_count =
+      ~r/Event dropped due to being a duplicate/
+      |> Regex.scan(log)
+      |> length()
+
+    assert logged_count == 2
   end
 
   test "does not send events if :dsn is not configured or nil" do