Make sure Logger v1.8 does not get stuck in discard mode (#9029)

Author: José Valim

lib/logger/lib/logger.ex

@@ -555,6 +555,7 @@ defmodule Logger do
     :level,
     :utc_log,
     :discard_threshold,
+    :discard_threshold_periodic_check,
     :translator_inspect_opts
   ]
   @spec configure(keyword) :: :ok

lib/logger/lib/logger/config.ex

@@ -4,6 +4,7 @@ defmodule Logger.Config do
   @behaviour :gen_event
   @name __MODULE__
   @table __MODULE__
+  @check_discard {__MODULE__, :check_discard}
 
   def start_link do
     GenServer.start_link(__MODULE__, :ok, name: @name)
@@ -76,29 +77,7 @@ defmodule Logger.Config do
   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
+    {:ok, {compute_mode_and_persist_state(state, thresholds), thresholds}}
   end
 
   def handle_call({:configure, options}, {%{mode: mode}, _}) do
@@ -127,6 +106,16 @@ defmodule Logger.Config do
     {:ok, old, state}
   end
 
+  def handle_info(@check_discard, {%{mode: :discard} = state, thresholds}) do
+    state = compute_mode_and_persist_state(state, thresholds)
+
+    if state.mode == :discard do
+      Process.send_after(self(), @check_discard, state.discard_threshold_periodic_check)
+    end
+
+    {:ok, {state, thresholds}}
+  end
+
   def handle_info(_msg, state) do
     {:ok, state}
   end
@@ -139,6 +128,31 @@ defmodule Logger.Config do
     {:ok, state}
   end
 
+  defp compute_mode_and_persist_state(%{mode: mode} = state, thresholds) do
+    case compute_mode(mode, thresholds) do
+      ^mode ->
+        state
+
+      new_mode ->
+        if new_mode == :discard do
+          Process.send_after(self(), @check_discard, state.discard_threshold_periodic_check)
+
+          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
+
+        persist(%{state | mode: new_mode})
+    end
+  end
+
   ## Helpers
 
   defp log(level, message, state) do
@@ -163,7 +177,9 @@ defmodule Logger.Config do
       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)
+      utc_log: Application.get_env(:logger, :utc_log),
+      discard_threshold_periodic_check:
+        Application.get_env(:logger, :discard_threshold_periodic_check)
     })
   end
 

lib/logger/mix.exs

@@ -24,6 +24,7 @@ defmodule Logger.MixProject do
         handle_otp_reports: true,
         handle_sasl_reports: false,
         discard_threshold_for_error_logger: 500,
+        discard_threshold_periodic_check: 30_000,
         compile_time_purge_level: :debug,
         compile_time_purge_matching: [],
         compile_time_application: nil,

lib/logger/test/logger/config_test.exs

@@ -12,11 +12,29 @@ defmodule Logger.ConfigTest do
   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)
+  end
+
+  test "log/2 recovers from discard_threshold" do
+    Logger.remove_backend(:console)
+    Logger.configure(discard_threshold: 1, discard_threshold_periodic_check: 0)
+
+    :sys.suspend(Logger)
+    assert Logger.log(:info, "BEGIN") == :ok
+    send(Logger, :garbage)
+    :sys.resume(Logger)
+
+    # Simulate a sync operation to make sure we are in :discard mode
+    Logger.add_translator({Unknown, :translate})
+    Logger.remove_translator({Unknown, :translate})
+
+    # It should eventually heal
+    wait_for_mode(:async)
+  after
+    Logger.configure(discard_threshold: 10000, discard_threshold_periodic_check: 30000)
     Logger.add_backend(:console)
   end
 
@@ -37,4 +55,11 @@ defmodule Logger.ConfigTest do
       Logger.configure(level: :debug)
     end
   end
+
+  def wait_for_mode(mode) do
+    unless Logger.Config.__data__().mode == mode do
+      Process.sleep(10)
+      wait_for_mode(mode)
+    end
+  end
 end