diff --git a/lib/logger/lib/logger.ex b/lib/logger/lib/logger.ex index e553ab69a6c..94a29c43dd1 100644 --- a/lib/logger/lib/logger.ex +++ b/lib/logger/lib/logger.ex @@ -133,15 +133,23 @@ defmodule Logger do `:sync_threshold` messages in its queue, `Logger` will change to *sync mode*, to apply backpressure to the clients. `Logger` will return to *async mode* once the number of messages - in the queue is reduced to `sync_threshold * 0.75` messages. - Defaults to 20 messages. `:sync_threshold` can be set to `0` to force *sync mode*. + in the queue is reduced to one below the `sync_threshold`. + Defaults to 20 messages. `:sync_threshold` can be set to `0` to + force *sync mode*. * `: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. + messages in the queue is reduced to one below the `discard_threshold`. + Defaults to 500 messages. + + * `:discard_threshold_periodic_check` - a periodic check that + checks and reports if logger is discarding messages. It logs a warn + message whenever the system is (or continues) in discard mode and + it logs a warn message whenever if the system was discarding messages + but stopped doing so after the previous check. By default it runs + every `30_000` milliseconds. * `:translator_inspect_opts` - when translating OTP reports and errors, the last message and state must be inspected in the @@ -501,10 +509,7 @@ defmodule Logger do The `Logger` level can be changed via `configure/1`. """ @spec level() :: level - def level() do - %{level: level} = Logger.Config.__data__() - level - end + defdelegate level(), to: Logger.Config @doc """ Compares log levels. @@ -525,18 +530,7 @@ defmodule Logger do """ @spec compare_levels(level, level) :: :lt | :eq | :gt - def compare_levels(level, level) do - :eq - end - - def compare_levels(left, right) do - if level_to_number(left) > level_to_number(right), do: :gt, else: :lt - end - - defp level_to_number(:debug), do: 0 - defp level_to_number(:info), do: 1 - defp level_to_number(:warn), do: 2 - defp level_to_number(:error), do: 3 + defdelegate compare_levels(left, right), to: Logger.Config @doc """ Configures the logger. @@ -669,12 +663,9 @@ defmodule Logger do def __should_log__(level) when level in @levels do case __metadata__() do {true, pdict} -> - %{mode: mode, level: min_level} = config = Logger.Config.__data__() - - if compare_levels(level, min_level) != :lt and mode != :discard do - {level, config, pdict} - else - :error + case Logger.Config.log_data(level) do + {:discard, _config} -> :error + {mode, config} -> {level, mode, config, pdict} end {false, _} -> @@ -683,8 +674,9 @@ defmodule Logger do end @doc false - def __do_log__({level, config, pdict}, chardata_or_fun, metadata) when is_list(metadata) do - %{utc_log: utc_log?, truncate: truncate, mode: mode} = config + def __do_log__({level, mode, config, pdict}, chardata_or_fun, metadata) + when is_list(metadata) do + %{utc_log: utc_log?, truncate: truncate} = config metadata = [pid: self()] ++ into_metadata(metadata, pdict) case normalize_message(chardata_or_fun, metadata) do @@ -829,7 +821,7 @@ defmodule Logger do Enum.any?(matching, fn filter -> Enum.all?(filter, fn {:level_lower_than, min_level} -> - compare_levels(level, min_level) == :lt + Logger.Config.compare_levels(level, min_level) == :lt {k, v} when is_atom(k) -> Keyword.fetch(compile_metadata, k) == {:ok, v} @@ -845,7 +837,7 @@ defmodule Logger do defp maybe_log(level, data, metadata, caller) do min_level = Application.get_env(:logger, :compile_time_purge_level, :debug) - if compare_levels(level, min_level) != :lt do + if Logger.Config.compare_levels(level, min_level) != :lt do macro_log(level, data, metadata, caller) else no_log(data, metadata) diff --git a/lib/logger/lib/logger/app.ex b/lib/logger/lib/logger/app.ex index 020322f39e6..90fc85f55dd 100644 --- a/lib/logger/lib/logger/app.ex +++ b/lib/logger/lib/logger/app.ex @@ -17,19 +17,19 @@ defmodule Logger.App do [%{id: Logger.ErrorHandler, start: {Logger.Watcher, :start_link, [arg]}}] end + config = Logger.Config.new() + children = [ %{ id: :gen_event, start: {:gen_event, :start_link, [{:local, Logger}]}, modules: :dynamic }, - {Logger.Watcher, {Logger, Logger.Config, []}}, + {Logger.Watcher, {Logger, Logger.Config, config}}, Logger.BackendSupervisor | otp_children ] - config = Logger.Config.new() - case Supervisor.start_link(children, strategy: :rest_for_one, name: Logger.Supervisor) do {:ok, sup} -> if otp_logger?() do diff --git a/lib/logger/lib/logger/config.ex b/lib/logger/lib/logger/config.ex index e15f8c03f9b..1ae09fa4cd8 100644 --- a/lib/logger/lib/logger/config.ex +++ b/lib/logger/lib/logger/config.ex @@ -4,10 +4,8 @@ defmodule Logger.Config do @behaviour :gen_event @name __MODULE__ @table __MODULE__ - - def start_link do - GenServer.start_link(__MODULE__, :ok, name: @name) - end + @counter_pos 1 + @update_counter_message {__MODULE__, :update_counter} def configure(options) do :gen_event.call(Logger, @name, {:configure, options}) @@ -21,27 +19,48 @@ defmodule Logger.Config do :gen_event.call(Logger, @name, {:remove_translator, translator}) end - def __data__() do - try do - :ets.lookup_element(@table, :data, 2) - rescue - ArgumentError -> - raise "cannot use Logger, the :logger application is not running" - else - nil -> - raise "cannot use Logger, the :logger application is not running" + def level do + %{level: level} = read_data!(:translation_data) + level + end - data -> - data + def compare_levels(level, level), do: :eq + + def compare_levels(left, right) do + if level_to_number(left) > level_to_number(right), do: :gt, else: :lt + end + + defp level_to_number(:debug), do: 0 + defp level_to_number(:info), do: 1 + defp level_to_number(:warn), do: 2 + defp level_to_number(:error), do: 3 + + def translation_data do + read_data!(:translation_data) + end + + def log_data(level) do + %{level: min_level} = config = read_data!(:log_data) + + if compare_levels(level, min_level) != :lt do + %{thresholds: {counter, sync, discard}} = config + value = bump_counter(counter) + + cond do + value >= discard -> {:discard, config} + value >= sync -> {:sync, config} + true -> {:async, config} + end + else + {:discard, config} end end - def deleted_handlers() do + def deleted_handlers do try do :ets.lookup_element(@table, :deleted_handlers, 2) rescue - ArgumentError -> - [] + ArgumentError -> [] end end @@ -49,22 +68,25 @@ defmodule Logger.Config do :gen_event.call(Logger, @name, {:deleted_handlers, handlers}) end - def new() do - tab = :ets.new(@table, [:named_table, :public, {:read_concurrency, true}]) - true = :ets.insert_new(@table, [{:data, nil}, {:deleted_handlers, []}]) - tab + def new do + {new_data(), new_counter()} end - def delete(@table) do - :ets.delete(@table) + def delete({data, counter}) do + delete_data(data) + delete_counter(counter) end ## Callbacks - def init(_) do - thresholds = compute_thresholds() - state = :ets.lookup_element(@table, :data, 2) || compute_state(:async, thresholds) - {:ok, {state, thresholds}} + def init({@table, counter}) do + state = + {counter, :log, Application.fetch_env!(:logger, :discard_threshold), + Application.fetch_env!(:logger, :discard_threshold_periodic_check)} + + :ets.lookup_element(@table, :log_data, 2) || compute_data(state) + state = update_counter(state, false) + {:ok, state} end def handle_event({_type, gl, _msg} = event, state) when node(gl) != node() do @@ -75,50 +97,27 @@ defmodule Logger.Config do {:ok, state} end - def handle_event(_event, {state, thresholds}) do - %{mode: mode} = state - - case compute_mode(mode, thresholds) do - ^mode -> - {:ok, {state, thresholds}} - - 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 - - state = persist(%{state | mode: new_mode}) - {:ok, {state, thresholds}} - end + def handle_event(_event, state) do + state = update_counter(state, false) + {:ok, state} end - def handle_call({:configure, options}, {%{mode: mode}, _}) do + def handle_call({:configure, options}, state) do Enum.each(options, fn {key, value} -> Application.put_env(:logger, key, value) end) - thresholds = compute_thresholds() - state = compute_state(mode, thresholds) - {:ok, :ok, {state, thresholds}} + {:ok, :ok, compute_data(state)} end - def handle_call({:add_translator, translator}, {state, thresholds}) do - state = update_translators(state, fn t -> [translator | List.delete(t, translator)] end) - {:ok, :ok, {state, thresholds}} + def handle_call({:add_translator, translator}, state) do + update_translators(fn t -> [translator | List.delete(t, translator)] end) + {:ok, :ok, state} end - def handle_call({:remove_translator, translator}, {state, thresholds}) do - state = update_translators(state, &List.delete(&1, translator)) - {:ok, :ok, {state, thresholds}} + def handle_call({:remove_translator, translator}, state) do + update_translators(&List.delete(&1, translator)) + {:ok, :ok, state} end def handle_call({:deleted_handlers, new}, state) do @@ -127,7 +126,13 @@ defmodule Logger.Config do {:ok, old, state} end - def handle_info(_msg, state) do + def handle_info(@update_counter_message, state) do + state = update_counter(state, true) + schedule_update_counter(state) + {:ok, state} + end + + def handle_info(_, state) do {:ok, state} end @@ -139,69 +144,147 @@ defmodule Logger.Config do {:ok, state} end - ## Helpers + defp update_counter({counter, log, discard_threshold, discard_period}, periodic_check?) do + # If length is more than the total, it means the counter is behind, + # due to non-log messages, so we need to increase the counter. + # + # If length is less than the total, then we either have a spike or + # the counter drifted due to failures. + # + # Because we always bump the counter and then we send the message, + # there is a chance clients have bumped the counter but they did not + # deliver the message yet. Those bumps will be lost. At the same time, + # we are careful to read the counter first here, so if the counter is + # bumped after we read from it, those bumps won't be lost. + total = read_counter(counter) + {:message_queue_len, length} = Process.info(self(), :message_queue_len) + add_counter(counter, length - total) + + # In case we are logging but we reached the threshold, we log that we + # started discarding messages. This can only be reverted by the periodic + # discard check. + cond do + total >= discard_threshold -> + if log == :log or periodic_check? do + warn("Attempted to log #{total} messages, which is above :discard_threshold") + end + + {counter, :discard, discard_threshold, discard_period} + + log == :discard and periodic_check? -> + warn("Attempted to log #{total} messages, which is below :discard_threshold") + {counter, :log, discard_threshold, discard_period} + + true -> + {counter, log, discard_threshold, discard_period} + end + end + + defp warn(message) do + utc_log = Application.fetch_env!(:logger, :utc_log) + event = {Logger, message, Logger.Utils.timestamp(utc_log), pid: self()} + :gen_event.notify(self(), {:warn, Process.group_leader(), event}) + end + + defp schedule_update_counter({_, _, _, discard_period}) do + Process.send_after(self(), @update_counter_message, discard_period) + end + + ## Counter Helpers + + # TODO: Use counters exclusively when we require Erlang/OTP 22+. + defp new_counter() do + if Code.ensure_loaded?(:counters) do + {:counters, :counters.new(1, [:atomics])} + else + table = :ets.new(@table.Counter, [:public]) + :ets.insert(table, [{@counter_pos, 0}]) + {:ets, table} + end + end + + defp delete_counter({:ets, counter}), do: :ets.delete(counter) + defp delete_counter({:counters, _}), do: :ok + + defp read_counter({:ets, counter}), do: :ets.lookup_element(counter, @counter_pos, 2) + defp read_counter({:counters, counter}), do: :counters.get(counter, @counter_pos) + + defp add_counter({:ets, counter}, value), + do: :ets.update_counter(counter, @counter_pos, {2, value}) - 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}) + defp add_counter({:counters, counter}, value), + do: :counters.add(counter, @counter_pos, value) + + defp bump_counter({:ets, counter}), + do: :ets.update_counter(counter, @counter_pos, {2, 1}) + + defp bump_counter({:counters, counter}) do + :counters.add(counter, @counter_pos, 1) + :counters.get(counter, @counter_pos) end - defp message_queue_length() do - {:message_queue_len, messages} = Process.info(self(), :message_queue_len) - messages + ## Data helpers + + defp new_data do + entries = [ + {:log_data, nil}, + {:translation_data, nil}, + {:deleted_handlers, []} + ] + + table = :ets.new(@table, [:named_table, :public, {:read_concurrency, true}]) + true = :ets.insert_new(@table, entries) + table end - defp update_translators(%{translators: translators} = state, fun) do - translators = fun.(translators) + defp delete_data(@table), do: :ets.delete(@table) + + defp update_translators(fun) do + translation_data = read_data!(:translation_data) + translators = fun.(translation_data.translators) Application.put_env(:logger, :translators, translators) - persist(%{state | translators: translators}) - end - - defp compute_state(mode, thresholds) do - persist(%{ - mode: compute_mode(mode, thresholds), - level: Application.get_env(:logger, :level), - translators: Application.get_env(:logger, :translators), - truncate: Application.get_env(:logger, :truncate), - utc_log: Application.get_env(:logger, :utc_log) - }) - end - - defp compute_mode(mode, thresholds) do - %{ - async_threshold: async_threshold, - sync_threshold: sync_threshold, - keep_threshold: keep_threshold, - discard_threshold: discard_threshold - } = thresholds - - Logger.Utils.compute_mode( - mode, - message_queue_length(), - async_threshold, - sync_threshold, - keep_threshold, - discard_threshold - ) - end - - defp compute_thresholds() 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) - - %{ - async_threshold: async_threshold, - sync_threshold: sync_threshold, - keep_threshold: keep_threshold, - discard_threshold: discard_threshold + update_data(:translation_data, %{translation_data | translators: translators}) + end + + defp compute_data({counter, _mode, _discard_threshold, _discard_period}) do + sync_threshold = Application.fetch_env!(:logger, :sync_threshold) + discard_threshold = Application.fetch_env!(:logger, :discard_threshold) + discard_period = Application.fetch_env!(:logger, :discard_threshold_periodic_check) + + log_data = %{ + level: Application.fetch_env!(:logger, :level), + utc_log: Application.fetch_env!(:logger, :utc_log), + truncate: Application.fetch_env!(:logger, :truncate), + thresholds: {counter, sync_threshold, discard_threshold} + } + + translation_data = %{ + level: Application.fetch_env!(:logger, :level), + translators: Application.fetch_env!(:logger, :translators), + truncate: Application.fetch_env!(:logger, :truncate) } + + update_data(:log_data, log_data) + update_data(:translation_data, translation_data) + {counter, :log, discard_threshold, discard_period} + end + + defp read_data!(key) do + try do + :ets.lookup_element(@table, key, 2) + rescue + ArgumentError -> + raise "cannot use Logger, the :logger application is not running" + else + nil -> + raise "cannot use Logger, the :logger application is not running" + + data -> + data + end end - defp persist(state) do - :ets.update_element(@table, :data, {2, state}) - state + defp update_data(key, value) do + :ets.update_element(@table, key, {2, value}) end end diff --git a/lib/logger/lib/logger/erlang_handler.ex b/lib/logger/lib/logger/erlang_handler.ex index a0b8f4a5ab6..d53d80b229a 100644 --- a/lib/logger/lib/logger/erlang_handler.ex +++ b/lib/logger/lib/logger/erlang_handler.ex @@ -92,7 +92,7 @@ defmodule Logger.ErlangHandler do level: min_level, truncate: truncate, translators: translators - } = Logger.Config.__data__() + } = Logger.Config.translation_data() case translate(translators, min_level, level, kind, data, meta) do :none -> {translate_fallback(kind, data, erl_meta, truncate), meta} diff --git a/lib/logger/lib/logger/error_handler.ex b/lib/logger/lib/logger/error_handler.ex index 913bc4d9cd3..789617b5743 100644 --- a/lib/logger/lib/logger/error_handler.ex +++ b/lib/logger/lib/logger/error_handler.ex @@ -82,13 +82,9 @@ defmodule Logger.ErrorHandler do defp log_event(_, _state), do: :ok defp log_event(level, kind, gl, pid, {type, _} = data, state) do - %{ - mode: mode, - level: min_level, - utc_log: utc_log? - } = Logger.Config.__data__() + {mode, %{utc_log: utc_log?}} = Logger.Config.log_data(level) - with true <- Logger.compare_levels(level, min_level) != :lt and mode != :discard, + with true <- mode != :discard, meta = [pid: ensure_pid(pid), error_logger: ensure_type(type)], {message, meta} <- Logger.ErlangHandler.translate(level, kind, data, meta, %{}) do # Mode is always async to avoid clogging the error_logger @@ -126,9 +122,12 @@ defmodule Logger.ErrorHandler do "its inbox, exceeding the amount of :discard_threshold #{discard_threshold} messages. " <> "The number of messages was reduced to #{keep_threshold} (75% of the threshold)" - %{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}) + {mode, %{utc_log: utc_log?}} = Logger.Config.log_data(:warn) + + if mode != :discard do + event = {Logger, message, Logger.Utils.timestamp(utc_log?), pid: self()} + :gen_event.notify(state.logger, {:warn, Process.group_leader(), event}) + end # We won't check the threshold for the next 10% of the threshold messages %{state | skip: trunc(discard_threshold * 0.1)} diff --git a/lib/logger/lib/logger/utils.ex b/lib/logger/lib/logger/utils.ex index 948420eed5a..50225bf380e 100644 --- a/lib/logger/lib/logger/utils.ex +++ b/lib/logger/lib/logger/utils.ex @@ -1,37 +1,6 @@ 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. diff --git a/lib/logger/mix.exs b/lib/logger/mix.exs index 583b011d1f1..ed457242ee4 100644 --- a/lib/logger/mix.exs +++ b/lib/logger/mix.exs @@ -23,6 +23,7 @@ defmodule Logger.MixProject do discard_threshold: 500, handle_otp_reports: true, handle_sasl_reports: false, + discard_threshold_periodic_check: 30_000, discard_threshold_for_error_logger: 500, compile_time_purge_level: :debug, compile_time_purge_matching: [], diff --git a/lib/logger/test/logger/config_test.exs b/lib/logger/test/logger/config_test.exs deleted file mode 100644 index 4100f0446f9..00000000000 --- a/lib/logger/test/logger/config_test.exs +++ /dev/null @@ -1,40 +0,0 @@ -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) - 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 diff --git a/lib/logger/test/logger/utils_test.exs b/lib/logger/test/logger/utils_test.exs index 4c6899cdd07..c75988aa7ed 100644 --- a/lib/logger/test/logger/utils_test.exs +++ b/lib/logger/test/logger/utils_test.exs @@ -11,57 +11,6 @@ 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, 0, 0, 0, 7500, 10000) == :sync - assert compute_mode(:async, 8000, 0, 0, 7500, 10000) == :sync - assert compute_mode(:async, 10000, 0, 0, 7500, 10000) == :discard - 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, 0, 0, 0, 7500, 10000) == :sync - assert compute_mode(:sync, 8000, 0, 0, 7500, 10000) == :sync - assert compute_mode(:sync, 10000, 0, 0, 7500, 10000) == :discard - 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, 0, 0, 0, 7500, 10000) == :sync - assert compute_mode(:discard, 8000, 0, 0, 7500, 10000) == :discard - assert compute_mode(:discard, 10000, 0, 0, 7500, 10000) == :discard - 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" diff --git a/lib/logger/test/logger_test.exs b/lib/logger/test/logger_test.exs index f4e083ac60e..9a22b7da3b7 100644 --- a/lib/logger/test/logger_test.exs +++ b/lib/logger/test/logger_test.exs @@ -426,9 +426,11 @@ defmodule LoggerTest do assert Application.get_env(:logger, :discard_threshold) == 10_000 assert Application.get_env(:logger, :translator_inspect_opts) == [limit: 3] - logger_data = Logger.Config.__data__() - assert logger_data.truncate == 4048 - assert logger_data.utc_log == true + {_, log_data} = Logger.Config.log_data(:debug) + assert log_data.utc_log == true + + translation_data = Logger.Config.translation_data() + assert translation_data.truncate == 4048 after Logger.configure(sync_threshold: 20) Logger.configure(truncate: 8096) @@ -436,4 +438,47 @@ defmodule LoggerTest do Logger.configure(discard_threshold: 500) Logger.configure(translator_inspect_opts: []) end + + test "logs when discarding messages" do + assert :ok = Logger.configure(discard_threshold: 5) + + log = + capture_log(fn -> + :sys.suspend(Logger) + for _ <- 1..10, do: Logger.warn("warning!") + :sys.resume(Logger) + Logger.flush() + + # This is a private message but the simplest way to test this functionality + send(Logger, {Logger.Config, :update_counter}) + + # We need to flush twice. Once for the send and another for the log in send + Logger.flush() + Logger.flush() + end) + + assert log =~ ~r"\[warn\] Attempted to log \d+ messages, which is above :discard_threshold" + assert log =~ ~r"\[warn\] Attempted to log \d+ messages, which is below :discard_threshold" + after + :sys.resume(Logger) + assert :ok = Logger.configure(discard_threshold: 500) + end + + test "restarts Logger.Config on Logger exits" do + Process.whereis(Logger) |> Process.exit(:kill) + wait_for_logger() + wait_for_handler(Logger, Logger.Config) + end + + test "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