Add overload protection to :logger handler

Closes #725.

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