Add overload protection to :logger handler (#727)

Closes #725.

Author: whatyouhide

lib/sentry/logger_backend.ex

@@ -1,7 +1,17 @@
 defmodule Sentry.LoggerBackend do
   @moduledoc """
-  Report Logger events like crashed processes to Sentry. To include in your
-  application, start this backend in your application `start/2` callback:
+  An Elixir `Logger` backend that reports logged messages and crashes to Sentry.
+
+  > #### `:logger` handler {: .warn}
+  >
+  > This module will eventually become **legacy**. Elixir `Logger` backends will
+  > eventually be deprecated in favor of Erlang [`:logger`
+  > handlers](https://erlang.org/doc/man/logger_chapter.html#handlers).
+  >
+  > Sentry already has a `:logger` handler, `Sentry.LoggerHandler`. In new projects
+  > and wherever possible, use `Sentry.LoggerHandler` in favor of this backend.
+
+  To include in your application, start this backend in your application `start/2` callback:
 
       # lib/my_app/application.ex
       def start(_type, _args) do

lib/sentry/logger_handler.ex

@@ -66,26 +66,34 @@ defmodule Sentry.LoggerHandler do
       """,
       type_doc: "`t:keyword/0` or `nil`",
       default: nil
+    ],
+    sync_threshold: [
+      type: :non_neg_integer,
+      default: 100,
+      doc: """
+      *since v10.6.0* - The number of queued events after which this handler switches
+      to *sync mode*. Generally, this handler sends messages to Sentry **asynchronously**,
+      equivalent to using `result: :none` in `Sentry.send_event/2`. However, if the number
+      of queued events exceeds this threshold, the handler will switch to *sync mode*,
+      where it starts using `result: :sync` to block until the event is sent. If you always
+      want to use sync mode, set this option to `0`. This option effectively implements
+      **overload protection**.
+      """
     ]
   ]
 
   @options_schema NimbleOptions.new!(options_schema)
 
   @moduledoc """
-  `:logger` handler to report logged events to Sentry.
-
-  This module is similar to `Sentry.LoggerBackend`, but it implements a
-  [`:logger` handler](https://erlang.org/doc/man/logger_chapter.html#handlers) rather
-  than an Elixir's `Logger` backend. It provides additional functionality compared to
-  the `Logger` backend, such as rate-limiting of reported messages, better fingerprinting,
-  and better handling of crashes.
+  A highly-configurable [`:logger` handler](https://erlang.org/doc/man/logger_chapter.html#handlers)
+  that reports logged messages and crashes to Sentry.
 
   *This module is available since v9.0.0 of this library*.
 
   > #### When to Use the Handler vs the Backend? {: .info}
   >
-  > There is **no functional difference in behavior** between `Sentry.LoggerHandler` and
-  > `Sentry.LoggerBackend` when it comes to reporting to Sentry. The main functional
+  > Sentry's Elixir SDK also ships with `Sentry.LoggerBackend`, an Elixir `Logger`
+  > backend. The backend has similar functionality to this handler. The main functional
   > difference is that `Sentry.LoggerBackend` runs in its own process, while
   > `Sentry.LoggerHandler` runs in the process that logs. The latter is generally
   > preferable.
@@ -94,11 +102,15 @@ defmodule Sentry.LoggerHandler do
   > feature in Erlang/OTP, and `Sentry.LoggerBackend` was created before `:logger`
   > handlers were introduced.
   >
-  > In general, try to use `Sentry.LoggerHandler` if possible. In future Elixir releases,
+  > In general, use `Sentry.LoggerHandler` whenever possible. In future Elixir releases,
   > `Logger` backends may become deprecated and hence `Sentry.LoggerBackend` may be
   > eventually removed.
 
-  ## Crash Reports
+  ## Features
+
+  This logger handler provides the features listed here.
+
+  ### Crash Reports
 
   The reason you'll want to add this handler to your application is so that you can
   report **crashes** in your system to Sentry. Sometimes, you're able to catch exceptions
@@ -111,6 +123,24 @@ defmodule Sentry.LoggerHandler do
   crash reports in Sentry. That's where this handler comes in. This handler hooks
   into `:logger` and reports nicely-formatted crash reports to Sentry.
 
+  ### Overload Protection
+
+  This handler has built-in *overload protection* via the `:sync_threshold`
+  configuration option. Under normal circumstances, this handler sends events to
+  Sentry asynchronously, without blocking the logging process. However, if the
+  number of queued up events exceeds the `:sync_threshold`, then this handler
+  starts *blocking* the logging process until the event is sent.
+
+  *Overload protection is available since v10.6.0*.
+
+  ### Rate Limiting
+
+  You can configure this handler to rate-limit the number of messages it sends to
+  Sentry. This can help avoid "spamming" Sentry. See the `:rate_limiting` configuration
+  option.
+
+  *Rate limiting is available since v10.5.0*.
+
   ## Usage
 
   To add this handler to your system, see [the documentation for handlers in
@@ -183,9 +213,17 @@ defmodule Sentry.LoggerHandler do
 
   alias Sentry.LoggerUtils
   alias Sentry.LoggerHandler.RateLimiter
+  alias Sentry.Transport.SenderPool
 
   # The config for this logger handler.
-  defstruct [:level, :excluded_domains, :metadata, :capture_log_messages, :rate_limiting]
+  defstruct [
+    :level,
+    :excluded_domains,
+    :metadata,
+    :capture_log_messages,
+    :rate_limiting,
+    :sync_threshold
+  ]
 
   ## Logger handler callbacks
 
@@ -301,30 +339,29 @@ defmodule Sentry.LoggerHandler do
   end
 
   # "report" here is of type logger:report/0, which is a map or keyword list.
-  defp log_unfiltered(%{msg: {:report, report}}, sentry_opts, %__MODULE__{} = _config) do
+  defp log_unfiltered(%{msg: {:report, report}}, sentry_opts, %__MODULE__{} = config) do
     case Map.new(report) do
       %{report: %{reason: {exception, stacktrace}}}
       when is_exception(exception) and is_list(stacktrace) ->
         sentry_opts = Keyword.merge(sentry_opts, stacktrace: stacktrace, handled: false)
-        Sentry.capture_exception(exception, sentry_opts)
+        capture(:exception, exception, sentry_opts, config)
 
       %{report: %{reason: {reason, stacktrace}}} when is_list(stacktrace) ->
         sentry_opts = Keyword.put(sentry_opts, :stacktrace, stacktrace)
-        Sentry.capture_message("** (stop) " <> Exception.format_exit(reason), sentry_opts)
+        capture(:message, "** (stop) " <> Exception.format_exit(reason), sentry_opts, config)
 
       %{report: report_info} ->
-        Sentry.capture_message(inspect(report_info), sentry_opts)
+        capture(:message, inspect(report_info), sentry_opts, config)
 
       %{reason: {reason, stacktrace}} when is_list(stacktrace) ->
         sentry_opts = Keyword.put(sentry_opts, :stacktrace, stacktrace)
-        Sentry.capture_message("** (stop) " <> Exception.format_exit(reason), sentry_opts)
+        capture(:message, "** (stop) " <> Exception.format_exit(reason), sentry_opts, config)
 
       %{reason: reason} ->
         sentry_opts =
           Keyword.update!(sentry_opts, :extra, &Map.put(&1, :crash_reason, inspect(reason)))
 
-        msg = "** (stop) #{Exception.format_exit(reason)}"
-        Sentry.capture_message(msg, sentry_opts)
+        capture(:message, "** (stop) #{Exception.format_exit(reason)}", sentry_opts, config)
 
       _other ->
         :ok
@@ -355,14 +392,19 @@ defmodule Sentry.LoggerHandler do
          {exception, stacktrace},
          _chardata_message,
          sentry_opts,
-         %__MODULE__{}
+         %__MODULE__{} = config
        )
        when is_exception(exception) and is_list(stacktrace) do
     sentry_opts = Keyword.merge(sentry_opts, stacktrace: stacktrace, handled: false)
-    Sentry.capture_exception(exception, sentry_opts)
+    capture(:exception, exception, sentry_opts, config)
   end
 
-  defp log_from_crash_reason({reason, stacktrace}, chardata_message, sentry_opts, %__MODULE__{})
+  defp log_from_crash_reason(
+         {reason, stacktrace},
+         chardata_message,
+         sentry_opts,
+         %__MODULE__{} = config
+       )
        when is_list(stacktrace) do
     sentry_opts =
       sentry_opts
@@ -380,18 +422,23 @@ defmodule Sentry.LoggerHandler do
             inspect(call)
           ])
 
-        Sentry.capture_message(Exception.format_exit(reason), sentry_opts)
+        capture(:message, Exception.format_exit(reason), sentry_opts, config)
 
       _other ->
-        try_to_parse_message_or_just_report_it(chardata_message, sentry_opts)
+        try_to_parse_message_or_just_report_it(chardata_message, sentry_opts, config)
     end
   end
 
-  defp log_from_crash_reason(_other_reason, chardata_message, sentry_opts, %__MODULE__{
-         capture_log_messages: true
-       }) do
+  defp log_from_crash_reason(
+         _other_reason,
+         chardata_message,
+         sentry_opts,
+         %__MODULE__{
+           capture_log_messages: true
+         } = config
+       ) do
     string_message = :unicode.characters_to_binary(chardata_message)
-    Sentry.capture_message(string_message, sentry_opts)
+    capture(:message, string_message, sentry_opts, config)
   end
 
   defp log_from_crash_reason(_other_reason, _string_message, _sentry_opts, _config) do
@@ -439,7 +486,8 @@ defmodule Sentry.LoggerHandler do
            "\nState: ",
            inspected_state | _
          ],
-         sentry_opts
+         sentry_opts,
+         config
        ) do
     string_reason = chardata_reason |> :unicode.characters_to_binary() |> String.trim()
 
@@ -452,7 +500,7 @@ defmodule Sentry.LoggerHandler do
         genserver_state: inspected_state
       })
 
-    Sentry.capture_message("GenServer %s terminating: #{string_reason}", sentry_opts)
+    capture(:message, "GenServer %s terminating: #{string_reason}", sentry_opts, config)
   end
 
   defp try_to_parse_message_or_just_report_it(
@@ -468,7 +516,8 @@ defmodule Sentry.LoggerHandler do
            "\nState: ",
            inspected_state | _
          ],
-         sentry_opts
+         sentry_opts,
+         config
        ) do
     string_reason = chardata_reason |> :unicode.characters_to_binary() |> String.trim()
 
@@ -480,15 +529,30 @@ defmodule Sentry.LoggerHandler do
         genserver_state: inspected_state
       })
 
-    Sentry.capture_message("GenServer %s terminating: #{string_reason}", sentry_opts)
+    capture(:message, "GenServer %s terminating: #{string_reason}", sentry_opts, config)
   end
 
-  defp try_to_parse_message_or_just_report_it(chardata_message, sentry_opts) do
+  defp try_to_parse_message_or_just_report_it(chardata_message, sentry_opts, config) do
     string_message = :unicode.characters_to_binary(chardata_message)
-    Sentry.capture_message(string_message, sentry_opts)
+    capture(:message, string_message, sentry_opts, config)
   end
 
   defp add_extra_to_sentry_opts(sentry_opts, new_extra) do
     Keyword.update(sentry_opts, :extra, %{}, &Map.merge(new_extra, &1))
   end
+
+  for function <- [:exception, :message] do
+    sentry_fun = :"capture_#{function}"
+
+    defp capture(unquote(function), exception_or_message, sentry_opts, %__MODULE__{} = config) do
+      sentry_opts =
+        if SenderPool.get_queued_events_counter() >= config.sync_threshold do
+          Keyword.put(sentry_opts, :result, :sync)
+        else
+          sentry_opts
+        end
+
+      Sentry.unquote(sentry_fun)(exception_or_message, sentry_opts)
+    end
+  end
 end

lib/sentry/transport/sender.ex

@@ -20,7 +20,7 @@ defmodule Sentry.Transport.Sender do
   @spec send_async(module(), Event.t()) :: :ok
   def send_async(client, %Event{} = event) when is_atom(client) do
     random_index = Enum.random(1..Transport.SenderPool.pool_size())
-
+    Transport.SenderPool.increase_queued_events_counter()
     GenServer.cast({:via, Registry, {@registry, random_index}}, {:send, client, event})
   end
 
@@ -42,6 +42,9 @@ defmodule Sentry.Transport.Sender do
     |> Transport.post_envelope(client)
     |> maybe_log_send_result([event])
 
+    # We sent an event, so we can decrease the number of queued events.
+    Transport.SenderPool.decrease_queued_events_counter()
+
     {:noreply, state}
   end
 

lib/sentry/transport/sender_pool.ex

@@ -3,13 +3,18 @@ defmodule Sentry.Transport.SenderPool do
 
   use Supervisor
 
+  @queued_events_key {__MODULE__, :queued_events}
+
   @spec start_link(keyword()) :: Supervisor.on_start()
   def start_link([] = _opts) do
     Supervisor.start_link(__MODULE__, [])
   end
 
   @impl true
   def init([]) do
+    queued_events_counter = :counters.new(1, [])
+    :persistent_term.put(@queued_events_key, queued_events_counter)
+
     children =
       for index <- 1..pool_size() do
         Supervisor.child_spec({Sentry.Transport.Sender, index: index},
@@ -30,4 +35,22 @@ defmodule Sentry.Transport.SenderPool do
       value
     end
   end
+
+  @spec increase_queued_events_counter() :: :ok
+  def increase_queued_events_counter do
+    counter = :persistent_term.get(@queued_events_key)
+    :counters.add(counter, 1, 1)
+  end
+
+  @spec decrease_queued_events_counter() :: :ok
+  def decrease_queued_events_counter do
+    counter = :persistent_term.get(@queued_events_key)
+    :counters.sub(counter, 1, 1)
+  end
+
+  @spec get_queued_events_counter() :: non_neg_integer()
+  def get_queued_events_counter do
+    counter = :persistent_term.get(@queued_events_key)
+    :counters.get(counter, 1)
+  end
 end