hermes-agent/n8n-openai-adapter
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

Add discard_threshold to Logger (#7193)

Browse Source
This commit is contained in:
José Valim
2018-01-11 10:07:10 +01:00
committed by GitHub
parent 17d83390d5
commit 2c54554f18
8 changed files with 227 additions and 101 deletions
Download Patch File Download Diff File Expand all files Collapse all files
lib/logger/lib/logger.ex
+21 -10
View File
@@ -130,6 +130,13 @@ defmodule Logger do
in the queue is reduced to `sync_threshold * 0.75` messages.
Defaults to 20 messages.
* `:discard_threshold` - if the `Logger` manager has more than
`:discard_threshold` messages in its queue, `Logger` will change
to *discard mode* and messages will be discarded directly in the
clients. `Logger` will return to *sync mode* once the number of
messages in the queue is reduced to `discard_threshold * 0.75`
messages. Defaults to 500 messages.
* `:translator_inspect_opts` - when translating OTP reports and
errors, the last message and state must be inspected in the
error reports. This configuration allow developers to change
@@ -159,21 +166,25 @@ defmodule Logger do
in Erlang syntax until the Logger application kicks in and
uninstalls SASL's logger in favor of its own. Defaults to `false`.
* `:discard_threshold_for_error_logger` - a value that, when
reached, triggers the error logger to discard messages. This
value must be a positive number that represents the maximum
number of messages accepted per second. Once above this
threshold, the [`:error_logger`](http://erlang.org/doc/man/error_logger.html)
enters discard mode for the remainder of that second. Defaults to 500 messages.
* `:discard_threshold_for_error_logger` - if `:error_logger` has more than
`discard_threshold` messages in its inbox, messages will be dropped
until the message queue goes down to `discard_threshold * 0.75`
entries. The threshold will be checked once again after 10% of thereshold
messages are processed, to avoid messages from being constantly dropped.
For exmaple, if the thereshold is 500 (the default) and the inbox has
600 messages, 250 messages will dropped, bringing the inbox down to
350 (0.75 * threshold) entries and 50 (0.1 * theshold) messages will
be processed before the threshold is checked once again.
For example, to configure `Logger` to redirect all [`:error_logger`](http://erlang.org/doc/man/error_logger.html)
messages using a `config/config.exs` file:
For example, to configure `Logger` to redirect all
[`:error_logger`](http://erlang.org/doc/man/error_logger.html) messages
using a `config/config.exs` file:
config :logger,
handle_otp_reports: true,
handle_sasl_reports: true
Furthermore, `Logger` allows messages sent by OTP's [`:error_logger`](http://erlang.org/doc/man/error_logger.html)
Furthermore, `Logger` allows messages sent by OTP's `:error_logger`
to be translated into an Elixir format via translators. Translators
can be dynamically added at any time with the `add_translator/1`
and `remove_translator/1` APIs. Check `Logger.Translator` for more
@@ -600,7 +611,7 @@ defmodule Logger do
%{mode: mode, truncate: truncate, level: min_level, utc_log: utc_log?} =
Logger.Config.__data__()
if compare_levels(level, min_level) != :lt do
if compare_levels(level, min_level) != :lt and mode != :discard do
metadata = [pid: self()] ++ Keyword.merge(pdict, metadata)
{message, metadata} = normalize_message(chardata_or_fun, metadata)
truncated = truncate(message, truncate)
lib/logger/lib/logger/config.ex
+45 -16
View File
@@ -105,10 +105,28 @@ defmodule Logger.Config do
{:ok, state}
new_mode ->
if new_mode == :discard do
message =
"Logger has #{message_queue_length()} messages in its queue, " <>
"which is above :discard_threshold. Messages will be discarded " <>
"until the message queue goes back to 75% of the threshold size"
log(:warn, message, state)
end
if mode == :discard do
log(:warn, "Logger has stopped discarding messages", state)
end
{:ok, persist(%{state | mode: new_mode})}
end
end
defp log(level, message, state) do
event = {Logger, message, Logger.Utils.timestamp(state.utc_log), pid: self()}
:gen_event.notify(self(), {level, Process.group_leader(), event})
end
def handle_call(:backends, state) do
{:ok, Application.get_env(:logger, :backends), state}
end
@@ -162,18 +180,27 @@ defmodule Logger.Config do
## Helpers
defp compute_mode(state) do
{:message_queue_len, len} = Process.info(self(), :message_queue_len)
%{
mode: mode,
async_threshold: async_threshold,
sync_threshold: sync_threshold,
keep_threshold: keep_threshold,
discard_threshold: discard_threshold
} = state
cond do
len > state.sync_threshold and state.mode == :async ->
:sync
Logger.Utils.compute_mode(
mode,
message_queue_length(),
async_threshold,
sync_threshold,
keep_threshold,
discard_threshold
)
end
len < state.async_threshold and state.mode == :sync ->
:async
true ->
state.mode
end
defp message_queue_length() do
{:message_queue_len, messages} = Process.info(self(), :message_queue_len)
messages
end
defp update_backends(fun) do
@@ -196,22 +223,24 @@ defmodule Logger.Config do
sync_threshold = Application.get_env(:logger, :sync_threshold)
async_threshold = trunc(sync_threshold * 0.75)
discard_threshold = Application.get_env(:logger, :discard_threshold)
keep_threshold = trunc(discard_threshold * 0.75)
state = %{
level: level,
mode: mode,
truncate: truncate,
utc_log: utc_log,
sync_threshold: sync_threshold,
async_threshold: async_threshold,
sync_threshold: sync_threshold,
keep_threshold: keep_threshold,
discard_threshold: discard_threshold,
translators: translators
}
case compute_mode(state) do
^mode ->
persist(state)
new_mode ->
persist(%{state | mode: new_mode})
^mode -> persist(state)
new_mode -> persist(%{state | mode: new_mode})
end
end
lib/logger/lib/logger/error_handler.ex
+43 -40
View File
@@ -1,10 +1,7 @@
defmodule Logger.ErrorHandler do
@moduledoc false
@behaviour :gen_event
require Logger
def init({otp?, sasl?, threshold}) do
# We store the Logger PID in the state because when we are shutting
# down the Logger application, the Logger process may be terminated
@@ -14,11 +11,10 @@ defmodule Logger.ErrorHandler do
state = %{
otp: otp?,
sasl: sasl?,
threshold: threshold,
discard_threshold: threshold,
keep_threshold: trunc(threshold * 0.75),
logger: Process.whereis(Logger),
last_length: 0,
last_time: :os.timestamp(),
dropped: 0
skip: 0
}
{:ok, state}
@@ -31,7 +27,7 @@ defmodule Logger.ErrorHandler do
end
def handle_event(event, state) do
state = check_threshold(state)
state = check_threshold_unless_skipping(state)
log_event(event, state)
{:ok, state}
end
@@ -84,10 +80,15 @@ defmodule Logger.ErrorHandler do
defp log_event(_, _state), do: :ok
defp log_event(level, kind, gl, pid, {type, _} = data, state) do
%{level: min_level, truncate: truncate, utc_log: utc_log?, translators: translators} =
Logger.Config.__data__()
%{
mode: mode,
level: min_level,
truncate: truncate,
utc_log: utc_log?,
translators: translators
} = Logger.Config.__data__()
with log when log != :lt <- Logger.compare_levels(level, min_level),
with true <- Logger.compare_levels(level, min_level) != :lt and mode != :discard,
{:ok, message} <- translate(translators, min_level, level, kind, data, truncate) do
message = Logger.Utils.truncate(message, truncate)
@@ -106,31 +107,35 @@ defmodule Logger.ErrorHandler do
defp ensure_pid(pid) when is_pid(pid), do: pid
defp ensure_pid(_), do: self()
defp check_threshold(state) do
%{last_time: last_time, last_length: last_length, dropped: dropped, threshold: threshold} =
state
defp check_threshold_unless_skipping(%{skip: 0} = state) do
check_threshold(state)
end
{m, s, _} = current_time = :os.timestamp()
defp check_threshold_unless_skipping(%{skip: skip} = state) do
%{state | skip: skip - 1}
end
def check_threshold(state) do
%{discard_threshold: discard_threshold, keep_threshold: keep_threshold} = state
current_length = message_queue_length()
cond do
match?({^m, ^s, _}, last_time) and current_length - last_length > threshold ->
count = drop_messages(current_time, 0)
%{state | dropped: dropped + count, last_length: message_queue_length()}
if current_length >= discard_threshold do
to_drop = current_length - keep_threshold
drop_messages(to_drop)
match?({^m, ^s, _}, last_time) ->
state
message =
"Logger dropped #{to_drop} OTP/SASL messages as it had #{current_length} messages in " <>
"its inbox, exceeding the amount of :discard_threshold #{discard_threshold} messages. " <>
"The number of messages was reduced to #{keep_threshold} (75% of the threshold)"
true ->
if dropped > 0 do
message =
"Logger dropped #{dropped} OTP/SASL messages as it " <>
"exceeded the amount of #{threshold} messages/second"
%{utc_log: utc_log?} = Logger.Config.__data__()
event = {Logger, message, Logger.Utils.timestamp(utc_log?), pid: self()}
:gen_event.notify(state.logger, {:warn, Process.group_leader(), event})
Logger.warn(message)
end
%{state | dropped: 0, last_time: current_time, last_length: current_length}
# We won't check the threshold for the next 10% of the threshold messages
%{state | skip: trunc(discard_threshold * 0.1)}
else
state
end
end
@@ -139,17 +144,15 @@ defmodule Logger.ErrorHandler do
len
end
defp drop_messages({m, s, _} = last_time, count) do
case :os.timestamp() do
{^m, ^s, _} ->
receive do
{:notify, _event} -> drop_messages(last_time, count + 1)
after
0 -> count
end
defp drop_messages(0) do
:ok
end
_ ->
count
defp drop_messages(count) do
receive do
{:notify, _event} -> drop_messages(count - 1)
after
0 -> :ok
end
end
lib/logger/lib/logger/utils.ex
+31
View File
@@ -1,6 +1,37 @@
defmodule Logger.Utils do
@moduledoc false
@doc """
Computes the logging mode.
The result may be either :sync, :async or :discard.
"""
@spec compute_mode(
mode,
non_neg_integer(),
non_neg_integer(),
non_neg_integer(),
non_neg_integer(),
non_neg_integer()
) :: mode
when mode: :sync | :async | :discard
def compute_mode(
mode,
messages,
async_threshold,
sync_threshold,
keep_threshold,
discard_threshold
) do
case mode do
_ when messages >= discard_threshold -> :discard
:discard when messages > keep_threshold -> :discard
_ when messages >= sync_threshold -> :sync
:sync when messages > async_threshold -> :sync
_ -> :async
end
end
@doc """
Truncates a `chardata` into `n` bytes.
lib/logger/mix.exs
+2 -1
View File
@@ -20,11 +20,12 @@ defmodule Logger.MixProject do
backends: [:console],
translators: [{Logger.Translator, :translate}],
sync_threshold: 20,
discard_threshold: 500,
handle_otp_reports: true,
handle_sasl_reports: false,
discard_threshold_for_error_logger: 500,
compile_time_purge_level: :debug,
compile_time_application: nil,
discard_threshold_for_error_logger: 500,
translator_inspect_opts: [],
console: []
]
lib/logger/test/logger/config_test.exs
+41
View File
@@ -0,0 +1,41 @@
defmodule Logger.ConfigTest do
use Logger.Case
require Logger
test "log/2 relies on sync_threshold" do
Logger.remove_backend(:console)
Logger.configure(sync_threshold: 0)
for _ <- 1..1000, do: Logger.log(:info, "some message")
after
Logger.configure(sync_threshold: 20)
Logger.add_backend(:console)
end
test "log/2 relies on discard_threshold" do
Logger.remove_backend(:console)
Logger.configure(discard_threshold: 0)
for _ <- 1..1000, do: Logger.log(:info, "some message")
after
Logger.configure(discard_threshold: 10000)
Logger.add_backend(:console)
end
test "restarts Logger.Config on Logger exits" do
Process.whereis(Logger) |> Process.exit(:kill)
wait_for_logger()
wait_for_handler(Logger, Logger.Config)
wait_for_handler(:error_logger, Logger.ErrorHandler)
end
test "Logger.Config updates config on config_change/3" do
:ok = Logger.configure(level: :debug)
try do
Application.put_env(:logger, :level, :error)
assert Logger.App.config_change([level: :error], [], []) === :ok
assert Logger.level() === :error
after
Logger.configure(level: :debug)
end
end
end
lib/logger/test/logger/utils_test.exs
+42
View File
@@ -11,6 +11,48 @@ defmodule Logger.UtilsTest do
|> :io_lib.unscan_format()
end
describe "compute_mode/2" do
test "starting async" do
assert compute_mode(:async, 0, 15, 20, 7500, 10000) == :async
assert compute_mode(:async, 10, 15, 20, 7500, 10000) == :async
assert compute_mode(:async, 18, 15, 20, 7500, 10000) == :async
assert compute_mode(:async, 20, 15, 20, 7500, 10000) == :sync
assert compute_mode(:async, 30, 15, 20, 7500, 10000) == :sync
assert compute_mode(:async, 8000, 15, 20, 7500, 10000) == :sync
assert compute_mode(:async, 10000, 15, 20, 7500, 10000) == :discard
end
test "starting sync" do
assert compute_mode(:sync, 0, 15, 20, 7500, 10000) == :async
assert compute_mode(:sync, 10, 15, 20, 7500, 10000) == :async
assert compute_mode(:sync, 18, 15, 20, 7500, 10000) == :sync
assert compute_mode(:sync, 20, 15, 20, 7500, 10000) == :sync
assert compute_mode(:sync, 30, 15, 20, 7500, 10000) == :sync
assert compute_mode(:sync, 8000, 15, 20, 7500, 10000) == :sync
assert compute_mode(:sync, 10000, 15, 20, 7500, 10000) == :discard
end
test "starting discard (with sync)" do
assert compute_mode(:discard, 0, 15, 20, 7500, 10000) == :async
assert compute_mode(:discard, 10, 15, 20, 7500, 10000) == :async
assert compute_mode(:discard, 18, 15, 20, 7500, 10000) == :async
assert compute_mode(:discard, 20, 15, 20, 7500, 10000) == :sync
assert compute_mode(:discard, 30, 15, 20, 7500, 10000) == :sync
assert compute_mode(:discard, 8000, 15, 20, 7500, 10000) == :discard
assert compute_mode(:discard, 10000, 15, 20, 7500, 10000) == :discard
end
test "starting discard (without sync)" do
assert compute_mode(:discard, 0, 75000, 100_000, 7500, 10000) == :async
assert compute_mode(:discard, 10, 75000, 100_000, 7500, 10000) == :async
assert compute_mode(:discard, 18, 75000, 100_000, 7500, 10000) == :async
assert compute_mode(:discard, 20, 75000, 100_000, 7500, 10000) == :async
assert compute_mode(:discard, 30, 75000, 100_000, 7500, 10000) == :async
assert compute_mode(:discard, 8000, 75000, 100_000, 7500, 10000) == :discard
assert compute_mode(:discard, 10000, 75000, 100_000, 7500, 10000) == :discard
end
end
test "truncate/2" do
# ASCII binaries
assert truncate("foo", 4) == "foo"
lib/logger/test/logger_test.exs
+2 -34
View File
@@ -253,7 +253,6 @@ defmodule LoggerTest do
# This should not warn, even if the Logger call is purged from the AST.
assert ExUnit.CaptureIO.capture_io(:stderr, fn ->
Code.eval_string("""
defmodule Unused do
require Logger
@@ -261,13 +260,10 @@ defmodule LoggerTest do
Logger.debug(["a: ", inspect(a), ", b: ", inspect(b)])
end
end
""")
end) == ""
assert Unused.hello(1, 2) == :ok
assert LoggerTest.Unused.hello(1, 2) == :ok
after
:code.purge(Unused)
:code.delete(Unused)
Logger.configure(compile_time_purge_level: :debug)
end
@@ -336,16 +332,7 @@ defmodule LoggerTest do
end) =~ "he�lo"
end
test "log/2 relies on sync_threshold" do
Logger.remove_backend(:console)
Logger.configure(sync_threshold: 0)
for _ <- 1..1000, do: Logger.log(:info, "some message")
after
Logger.configure(sync_threshold: 20)
Logger.add_backend(:console)
end
test "stop the application silently" do
test "stops the application silently" do
Application.put_env(:logger, :backends, [])
Logger.App.stop()
Application.start(:logger)
@@ -361,23 +348,4 @@ defmodule LoggerTest do
Logger.App.stop()
Application.start(:logger)
end
test "restarts Logger.Config on Logger exits" do
Process.whereis(Logger) |> Process.exit(:kill)
wait_for_logger()
wait_for_handler(Logger, Logger.Config)
wait_for_handler(:error_logger, Logger.ErrorHandler)
end
test "Logger.Config updates config on config_change/3" do
:ok = Logger.configure(level: :debug)
try do
Application.put_env(:logger, :level, :error)
assert Logger.App.config_change([level: :error], [], []) === :ok
assert Logger.level() === :error
after
Logger.configure(level: :debug)
end
end
end