Skip to content

Commit 61485d4

Browse files
whatyouhidewhatyouhide
authored
Add rate-limiting to :logger handler (#717)
1 parent 68e808f commit 61485d4

File tree

3 files changed

+257
-5
lines changed

3 files changed

+257
-5
lines changed

‎lib/sentry/logger_handler.ex‎

Lines changed: 67 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -4,7 +4,9 @@ defmodule Sentry.LoggerHandler do
44
55
This module is similar to `Sentry.LoggerBackend`, but it implements a
66
[`:logger` handler](https://erlang.org/doc/man/logger_chapter.html#handlers) rather
7-
than an Elixir's `Logger` backend.
7+
than an Elixir's `Logger` backend. It provides additional functionality compared to
8+
the `Logger` backend, such as rate-limiting of reported messages, better fingerprinting,
9+
and better handling of crashes.
810
911
*This module is available since v9.0.0 of this library*.
1012
@@ -96,23 +98,38 @@ defmodule Sentry.LoggerHandler do
9698
send **crash reports**, which are messages with metadata that has the
9799
shape of an exit reason and a stacktrace.
98100
101+
* `:rate_limiting` (`t:keyword/0`, since *v10.4.0*) - if present, enables rate
102+
limiting of reported messages. This can help avoid "spamming" Sentry with
103+
repeated log messages. To disable rate limiting, set this to `nil` or don't
104+
pass it altogether (which is the default). If this option is present, these
105+
nested options are **required**:
106+
107+
* `:max_events` (`t:non_neg_integer/0`) - the maximum number of events
108+
to send to Sentry in the `:interval` period.
109+
110+
* `:interval` (`t:non_neg_integer/0`) - the interval (in *milliseconds*)
111+
to send `:max_events` events.
112+
99113
"""
100114

101115
@moduledoc since: "9.0.0"
102116

103117
alias Sentry.LoggerUtils
118+
alias Sentry.LoggerHandler.RateLimiter
104119

105120
# The config for this logger handler.
106121
defstruct level: :error,
107122
excluded_domains: [:cowboy],
108123
metadata: [],
109-
capture_log_messages: false
124+
capture_log_messages: false,
125+
rate_limiting: nil
110126

111127
@valid_config_keys [
112128
:excluded_domains,
113129
:capture_log_messages,
114130
:metadata,
115-
:level
131+
:level,
132+
:rate_limiting
116133
]
117134

118135
## Logger handler callbacks
@@ -122,28 +139,73 @@ defmodule Sentry.LoggerHandler do
122139
@spec adding_handler(:logger.handler_config()) :: {:ok, :logger.handler_config()}
123140
def adding_handler(config) do
124141
config = Map.put_new(config, :config, %__MODULE__{})
125-
{:ok, update_in(config.config, &cast_config(__MODULE__, &1))}
142+
config = update_in(config.config, &cast_config(__MODULE__, &1))
143+
144+
if rate_limiting_config = config.config.rate_limiting do
145+
_ = RateLimiter.start_under_sentry_supervisor(config.id, rate_limiting_config)
146+
{:ok, config}
147+
else
148+
{:ok, config}
149+
end
126150
end
127151

128152
# Callback for :logger handlers
129153
@doc false
130154
@spec changing_config(:update, :logger.handler_config(), :logger.handler_config()) ::
131155
{:ok, :logger.handler_config()}
132156
def changing_config(:update, old_config, new_config) do
157+
_ignored =
158+
cond do
159+
new_config.config.rate_limiting == old_config.config.rate_limiting ->
160+
:ok
161+
162+
# Turn off rate limiting.
163+
old_config.config.rate_limiting && is_nil(new_config.config.rate_limiting) ->
164+
:ok = RateLimiter.terminate_and_delete(new_config.id)
165+
166+
# Turn on rate limiting.
167+
is_nil(old_config.config.rate_limiting) && new_config.config.rate_limiting ->
168+
RateLimiter.start_under_sentry_supervisor(
169+
new_config.id,
170+
new_config.config.rate_limiting
171+
)
172+
173+
# The config changed, so restart the rate limiter with the new config.
174+
true ->
175+
:ok = RateLimiter.terminate_and_delete(new_config.id)
176+
177+
RateLimiter.start_under_sentry_supervisor(
178+
new_config.id,
179+
new_config.config.rate_limiting
180+
)
181+
end
182+
133183
{:ok, update_in(old_config.config, &cast_config(&1, new_config.config))}
134184
end
135185

186+
# Callback for :logger handlers
187+
@doc false
188+
def removing_handler(%{id: id}) do
189+
:ok = RateLimiter.terminate_and_delete(id)
190+
end
191+
136192
# Callback for :logger handlers
137193
@doc false
138194
@spec log(:logger.log_event(), :logger.handler_config()) :: :ok
139-
def log(%{level: log_level, meta: log_meta} = log_event, %{config: %__MODULE__{} = config}) do
195+
def log(%{level: log_level, meta: log_meta} = log_event, %{
196+
config: %__MODULE__{} = config,
197+
id: handler_id
198+
}) do
140199
cond do
141200
Logger.compare_levels(log_level, config.level) == :lt ->
142201
:ok
143202

144203
LoggerUtils.excluded_domain?(Map.get(log_meta, :domain, []), config.excluded_domains) ->
145204
:ok
146205

206+
config.rate_limiting && RateLimiter.increment(handler_id) == :rate_limited ->
207+
:ok
208+
147209
true ->
148210
# Logger handlers run in the process that logs, so we already read all the
149211
# necessary Sentry context from the process dictionary (when creating the event).

‎lib/sentry/logger_handler/rate_limiter.ex‎

Lines changed: 74 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,74 @@
1+
defmodule Sentry.LoggerHandler.RateLimiter do
2+
@moduledoc false
3+
4+
# A generic rate-limiter implemented on top of :atomics (requires OTP 21.2+).
5+
# Allows you to rate limit to N events every M milliseconds.
6+
7+
use GenServer
8+
9+
@type id() :: :logger.handler_id()
10+
11+
@atomics_index 1
12+
13+
## Public API
14+
15+
@spec start_under_sentry_supervisor(id(), keyword()) :: Supervisor.on_start_child()
16+
def start_under_sentry_supervisor(id, options) when is_atom(id) and is_list(options) do
17+
max_events = Keyword.fetch!(options, :max_events)
18+
interval = Keyword.fetch!(options, :interval)
19+
20+
spec = Supervisor.child_spec(child_spec({id, max_events, interval}), id: {__MODULE__, id})
21+
22+
case Supervisor.start_child(Sentry.Supervisor, spec) do
23+
{:ok, _pid} -> :ok
24+
{:error, {:already_started, _pid}} -> :ok
25+
{:error, reason} -> {:error, reason}
26+
end
27+
end
28+
29+
@spec terminate_and_delete(id()) :: :ok
30+
def terminate_and_delete(id) when is_atom(id) do
31+
_ = Supervisor.terminate_child(Sentry.Supervisor, child_id(id))
32+
_ = Supervisor.delete_child(Sentry.Supervisor, child_id(id))
33+
:ok
34+
end
35+
36+
@spec start_link({id(), non_neg_integer(), non_neg_integer()}) :: GenServer.on_start()
37+
def start_link({id, max_events, interval}) do
38+
GenServer.start_link(__MODULE__, {id, max_events, interval})
39+
end
40+
41+
@spec increment(id()) :: :ok | :rate_limited
42+
def increment(id) when is_atom(id) do
43+
{atomics_ref, max_events} = :persistent_term.get(persistent_term_key(id))
44+
value = :atomics.add_get(atomics_ref, @atomics_index, _incr = 1)
45+
46+
if value > max_events do
47+
:rate_limited
48+
else
49+
:ok
50+
end
51+
end
52+
53+
## Callbacks
54+
55+
@impl GenServer
56+
def init({id, max_events, interval}) do
57+
atomics_ref = :atomics.new(_size = 1, signed: false)
58+
:persistent_term.put(persistent_term_key(id), {atomics_ref, max_events})
59+
_ = :timer.send_interval(interval, :tick)
60+
{:ok, id}
61+
end
62+
63+
@impl GenServer
64+
def handle_info(:tick, id) do
65+
{atomics_ref, _max_events} = :persistent_term.get(persistent_term_key(id))
66+
:ok = :atomics.put(atomics_ref, @atomics_index, 0)
67+
{:noreply, id}
68+
end
69+
70+
@compile {:inline, persistent_term_key: 1}
71+
defp persistent_term_key(id), do: {__MODULE__, id}
72+
73+
defp child_id(id), do: {__MODULE__, id}
74+
end

‎test/sentry/logger_handler_test.exs‎

Lines changed: 116 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -392,6 +392,122 @@ defmodule Sentry.LoggerHandlerTest do
392392
end
393393
end
394394

395+
describe "rate limiting" do
396+
@tag handler_config: %{
397+
rate_limiting: [max_events: 2, interval: 150],
398+
capture_log_messages: true
399+
}
400+
test "limits logged messages", %{sender_ref: ref} do
401+
Logger.error("First")
402+
assert_receive {^ref, %{message: %{formatted: "First"}}}
403+
404+
Logger.error("Second")
405+
assert_receive {^ref, %{message: %{formatted: "Second"}}}
406+
407+
Logger.error("Third")
408+
refute_receive {^ref, _event}, 100
409+
410+
Process.sleep(150)
411+
Logger.error("Fourth")
412+
assert_receive {^ref, %{message: %{formatted: "Fourth"}}}
413+
end
414+
415+
@tag handler_config: %{capture_log_messages: true}
416+
test "without rate limiting, doens't rate limit", %{sender_ref: ref} do
417+
for index <- 1..10 do
418+
message = "Message #{index}"
419+
Logger.error(message)
420+
assert_receive {^ref, %{message: %{formatted: ^message}}}
421+
end
422+
end
423+
424+
@tag handler_config: %{
425+
rate_limiting: [max_events: 2, interval: 150],
426+
capture_log_messages: true
427+
}
428+
test "works with changing config to disable rate limiting", %{sender_ref: ref} do
429+
assert {:ok, %{config: config}} = :logger.get_handler_config(@handler_name)
430+
431+
:ok =
432+
:logger.update_handler_config(@handler_name, :config, put_in(config.rate_limiting, nil))
433+
434+
for index <- 1..10 do
435+
message = "Message #{index}"
436+
Logger.error(message)
437+
assert_receive {^ref, %{message: %{formatted: ^message}}}
438+
end
439+
end
440+
441+
@tag handler_config: %{capture_log_messages: true}
442+
test "works with changing config to enable rate limiting", %{sender_ref: ref} do
443+
for index <- 1..10 do
444+
message = "Message #{index}"
445+
Logger.error(message)
446+
assert_receive {^ref, %{message: %{formatted: ^message}}}
447+
end
448+
449+
assert {:ok, %{config: config}} = :logger.get_handler_config(@handler_name)
450+
451+
:ok =
452+
:logger.update_handler_config(
453+
@handler_name,
454+
:config,
455+
put_in(config.rate_limiting, max_events: 1, interval: 100)
456+
)
457+
458+
Logger.error("RL1")
459+
assert_receive {^ref, %{message: %{formatted: "RL1"}}}
460+
461+
Logger.error("RL2")
462+
refute_receive {^ref, _event}, 100
463+
end
464+
465+
@tag handler_config: %{
466+
rate_limiting: [max_events: 2, interval: 100],
467+
capture_log_messages: true
468+
}
469+
test "works with changing config to update rate limiting", %{sender_ref: ref} do
470+
assert {:ok, %{config: config}} = :logger.get_handler_config(@handler_name)
471+
472+
:ok =
473+
:logger.update_handler_config(
474+
@handler_name,
475+
:config,
476+
put_in(config.rate_limiting, max_events: 1, interval: 100)
477+
)
478+
479+
Logger.error("RL1")
480+
assert_receive {^ref, %{message: %{formatted: "RL1"}}}
481+
482+
Logger.error("RL2")
483+
refute_receive {^ref, _event}, 100
484+
end
485+
486+
@tag handler_config: %{
487+
rate_limiting: [max_events: 2, interval: 100],
488+
capture_log_messages: true
489+
}
490+
test "works with changing config but without changing rate limiting", %{sender_ref: ref} do
491+
assert {:ok, %{config: config}} = :logger.get_handler_config(@handler_name)
492+
493+
:ok =
494+
:logger.update_handler_config(
495+
@handler_name,
496+
:config,
497+
put_in(config.rate_limiting, max_events: 2, interval: 100)
498+
)
499+
500+
Logger.error("RL1")
501+
assert_receive {^ref, %{message: %{formatted: "RL1"}}}
502+
503+
Logger.error("RL2")
504+
assert_receive {^ref, %{message: %{formatted: "RL2"}}}
505+
506+
Logger.error("RL3")
507+
refute_receive {^ref, _event}, 100
508+
end
509+
end
510+
395511
defp register_before_send(_context) do
396512
pid = self()
397513
ref = make_ref()

0 commit comments

Comments
 (0)