fix(callbacks): wrap log and metric callbacks

lib/sentry.ex

@@ -155,12 +155,11 @@ defmodule Sentry do
 
   ## Crashing Callbacks
 
-  If a `:before_send`, `:after_send_event`, or `:filter` callback raises, throws, or exits,
-  Sentry catches the failure and logs it at the `:error` level instead of letting it reach
-  the code that was reporting the event. The log carries the `:sentry` logger domain, so the
-  SDK never reports its own callback failure as an event. Other configurable callbacks, such
-  as `:before_send_log` and `:before_send_metric`, handle their own failures and are not
-  covered by this section.
+  If a `:before_send`, `:after_send_event`, `:filter`, `:before_send_log`, or
+  `:before_send_metric` callback raises, throws, or exits, Sentry catches the failure and logs
+  it at the `:error` level instead of letting it reach the code that was reporting the event.
+  The log carries the `:sentry` logger domain, so the SDK never reports its own callback
+  failure as an event.
 
   The item being handled is then dropped:
 
@@ -171,6 +170,10 @@ defmodule Sentry do
       `c:Sentry.EventFilter.exclude_exception?/2` crashes, is treated like one that
       excluded the exception. `capture_exception/2` returns `:excluded`.
 
+    * A `:before_send_log` or `:before_send_metric` callback that crashes is treated like one
+      that returned `nil`. The log event or metric is not sent, and the rest of the batch it
+      belongs to is unaffected.
+
   An `:after_send_event` callback runs once the event has already been sent and its
   return value is ignored, so a crash there changes nothing the caller sees: the send
   result is still the one the transport produced.
@@ -304,7 +307,8 @@ defmodule Sentry do
       Callback.run(
         :filter,
         fn -> filter_module.exclude_exception?(exception, event_source) end,
-        true
+        true,
+        discard: {:callback_error, "error"}
       )
 
     if exclude? do

lib/sentry/callback.ex

@@ -1,21 +1,34 @@
 defmodule Sentry.Callback do
   @moduledoc false
 
+  alias Sentry.ClientReport
   alias Sentry.LoggerUtils
 
   @type spec() :: (... -> term()) | {module(), atom()}
 
-  @spec run(atom(), (-> result), result) :: result when result: var
-  def run(name, fun, fallback) when is_atom(name) and is_function(fun, 0) do
-    fun.()
+  @spec run(atom(), (-> result), result, keyword()) :: result when result: var
+  def run(name, fun, fallback, opts \\ []) when is_list(opts) do
+    case run(name, fun) do
+      {:ok, result} ->
+        result
+
+      :failed ->
+        record_discard(Keyword.get(opts, :discard))
+        fallback
+    end
+  end
+
+  @spec run(atom(), (-> result)) :: {:ok, result} | :failed when result: var
+  def run(name, fun) when is_atom(name) and is_function(fun, 0) do
+    {:ok, fun.()}
   catch
     kind, reason ->
       LoggerUtils.error(
         "#{inspect(name)} callback failed: " <>
           Exception.format(kind, reason, __STACKTRACE__)
       )
 
-      fallback
+      :failed
   end
 
   @spec to_fun(atom(), spec(), [term()]) :: (-> term())
@@ -33,4 +46,11 @@ defmodule Sentry.Callback do
                 "got: #{inspect(other)}"
     end
   end
+
+  defp record_discard(nil), do: :ok
+
+  defp record_discard({reason, event_or_data_category}) do
+    _ = ClientReport.Sender.record_discarded_events(reason, event_or_data_category)
+    :ok
+  end
 end

lib/sentry/client.ex

@@ -191,16 +191,17 @@ defmodule Sentry.Client do
   end
 
   defp maybe_call_before_send(event, callback) do
-    if result = call_before_send(event, callback) do
-      {:ok, result}
-    else
-      :excluded
+    case Callback.run(:before_send, before_send_invocation(event, callback), false,
+           discard: {:callback_error, [event]}
+         ) do
+      false -> :excluded
+      result -> {:ok, result}
     end
   end
 
-  defp call_before_send(event, callback) do
+  defp before_send_invocation(event, callback) do
     invocation = Callback.to_fun(:before_send, callback, [event])
-    Callback.run(:before_send, fn -> invocation.() || false end, false)
+    fn -> invocation.() || false end
   end
 
   defp maybe_call_after_send(_event_or_transaction, _result, nil) do

lib/sentry/client_report.ex

@@ -23,6 +23,7 @@ defmodule Sentry.ClientReport do
     :network_error,
     :sample_rate,
     :before_send,
+    :callback_error,
     :event_processor,
     :insufficient_data,
     :backpressure,

lib/sentry/config.ex

@@ -973,6 +973,9 @@ defmodule Sentry.Config do
       well as filtering out the log event altogether.
       If the callback returns `nil` or `false`, the log event is not reported. If it returns a
       (potentially-updated) `Sentry.LogEvent`, then the updated log event is used instead.
+      If the callback crashes, the failure is logged at the `:error` level and the log event is
+      not reported. See the [*Crashing Callbacks*](#module-crashing-callbacks) section below for
+      more information.
       *Available since v12.0.0*.
       """
     ],
@@ -984,6 +987,9 @@ defmodule Sentry.Config do
       well as filtering out the metric altogether.
       If the callback returns `nil` or `false`, the metric is not reported. If it returns a
       (potentially-updated) `Sentry.Metric`, then the updated metric is used instead.
+      If the callback crashes, the failure is logged at the `:error` level and the metric is not
+      reported. See the [*Crashing Callbacks*](#module-crashing-callbacks) section below for more
+      information.
       *Available since v13.0.0*.
       """
     ]

lib/sentry/metric.ex

@@ -10,7 +10,6 @@ defmodule Sentry.Metric do
   @moduledoc since: "13.0.0"
 
   alias Sentry.Config
-  alias Sentry.LoggerUtils
 
   @type metric_type :: :counter | :gauge | :distribution
 
@@ -108,24 +107,6 @@ defmodule Sentry.Metric do
     |> maybe_put(:span_id, metric.span_id)
   end
 
-  @doc false
-  @spec call_before_send_callback(t(), function() | {module(), atom()}) :: t() | nil
-  def call_before_send_callback(metric, function) when is_function(function, 1) do
-    function.(metric)
-  rescue
-    error ->
-      LoggerUtils.warning("before_send_metric callback failed: #{inspect(error)}")
-      metric
-  end
-
-  def call_before_send_callback(metric, {mod, fun}) do
-    apply(mod, fun, [metric])
-  rescue
-    error ->
-      LoggerUtils.warning("before_send_metric callback failed: #{inspect(error)}")
-      metric
-  end
-
   defp maybe_put(map, _key, nil), do: map
   defp maybe_put(map, key, value), do: Map.put(map, key, value)
 

lib/sentry/telemetry/scheduler.ex

@@ -36,6 +36,7 @@ defmodule Sentry.Telemetry.Scheduler do
   alias Sentry.Telemetry.{Buffer, Category}
 
   alias Sentry.{
+    Callback,
     CheckIn,
     ClientError,
     ClientReport,
@@ -380,37 +381,33 @@ defmodule Sentry.Telemetry.Scheduler do
     end
   end
 
-  defp call_before_send_log(log_event, function) when is_function(function, 1) do
-    function.(log_event)
-  rescue
-    error ->
-      LoggerUtils.warning("before_send_log callback failed: #{inspect(error)}")
-
-      log_event
-  end
-
-  defp call_before_send_log(log_event, {mod, fun}) do
-    apply(mod, fun, [log_event])
-  rescue
-    error ->
-      LoggerUtils.warning("before_send_log callback failed: #{inspect(error)}")
-
-      log_event
+  defp call_before_send_log(log_event, callback) do
+    run_callback(:before_send_log, log_event, callback)
   end
 
   defp apply_before_send_metric_callbacks(metrics) do
     callback = Config.before_send_metric()
 
     if callback do
       for metric <- metrics,
-          %Metric{} = modified_metric <- [Metric.call_before_send_callback(metric, callback)] do
+          %Metric{} = modified_metric <- [call_before_send_metric(metric, callback)] do
         modified_metric
       end
     else
       metrics
     end
   end
 
+  defp call_before_send_metric(metric, callback) do
+    run_callback(:before_send_metric, metric, callback)
+  end
+
+  defp run_callback(name, item, callback) do
+    Callback.run(name, Callback.to_fun(name, callback, [item]), nil,
+      discard: {:callback_error, [item]}
+    )
+  end
+
   defp advance_cycle(%Scheduler{} = state) do
     cycle_length = length(state.priority_cycle)
     new_position = rem(state.cycle_position + 1, cycle_length)

test/sentry/metrics_integration_test.exs

@@ -3,20 +3,31 @@ defmodule Sentry.MetricsIntegrationTest do
 
   require OpenTelemetry.Tracer, as: Tracer
 
+  import ExUnit.CaptureLog
   import Sentry.TestHelpers
   import Sentry.Test.Assertions
 
   alias Sentry.{Metrics, TelemetryProcessor}
   alias Sentry.Telemetry.Buffer
 
   setup do
-    %{bypass: bypass, telemetry_processor: processor_name, ref: ref} =
+    %{
+      bypass: bypass,
+      telemetry_processor: processor_name,
+      ref: ref,
+      client_report_sender: client_report_sender
+    } =
       Sentry.Test.setup_sentry(
         collect_envelopes: true,
         telemetry_processor: [buffer_configs: %{metric: %{batch_size: 1}}]
       )
 
-    %{processor: processor_name, ref: ref, bypass: bypass}
+    %{
+      processor: processor_name,
+      ref: ref,
+      bypass: bypass,
+      client_report_sender: client_report_sender
+    }
   end
 
   describe "metric batching" do
@@ -84,6 +95,40 @@ defmodule Sentry.MetricsIntegrationTest do
     end
   end
 
+  describe "before_send_metric callback that crashes" do
+    test "drops the metric when the callback raises", ctx do
+      assert_metric_dropped(ctx, fn _metric -> raise "boom" end)
+    end
+
+    test "drops the metric when the callback throws", ctx do
+      assert_metric_dropped(ctx, fn _metric -> throw(:boom) end)
+    end
+
+    test "drops the metric when the callback exits", ctx do
+      assert_metric_dropped(ctx, fn _metric -> exit(:boom) end)
+    end
+
+    test "records a callback_error outcome for the dropped metric", ctx do
+      assert_metric_dropped(ctx, fn _metric -> raise "boom" end)
+
+      assert %{
+               {:callback_error, "trace_metric"} => 1,
+               {:callback_error, "trace_metric_byte"} => bytes
+             } = :sys.get_state(ctx.client_report_sender)
+
+      assert bytes > 0
+    end
+
+    test "records no outcome for a metric the callback filters out", ctx do
+      put_test_config(before_send_metric: fn _metric -> nil end)
+
+      Metrics.count("drop.me", 1)
+      :ok = TelemetryProcessor.flush(ctx.processor)
+
+      assert :sys.get_state(ctx.client_report_sender) == %{}
+    end
+  end
+
   describe "metric envelope format" do
     test "metrics include all required fields", ctx do
       Metrics.count("test.counter", 42, unit: "request", attributes: %{method: "GET"})
@@ -147,4 +192,16 @@ defmodule Sentry.MetricsIntegrationTest do
       assert metric["span_id"] == transaction["contexts"]["trace"]["span_id"]
     end
   end
+
+  defp assert_metric_dropped(ctx, crashing_callback) do
+    put_test_config(before_send_metric: crashing_callback)
+
+    capture_log(fn ->
+      Metrics.count("crash.me", 1)
+      :ok = TelemetryProcessor.flush(ctx.processor)
+    end)
+
+    assert [] == collect_sentry_metric_items(ctx.ref, 1, timeout: 200)
+    assert [] == Sentry.Test.pop_sentry_metrics()
+  end
 end