Fix logger watcher race condition

Previously a backend could be removed from logger and the watcher would
not have exited before the remove_backend/1 call returned. This meant
that a new watcher could not always be started because the child
(watcher) might still exist but be about to die.

Author: fishcakez

lib/logger/lib/logger/watcher.ex

@@ -9,8 +9,11 @@ defmodule Logger.Watcher do
   Starts the watcher supervisor.
   """
   def start_link(m, f, a) do
-    options  = [strategy: :one_for_one, name: @name]
-    case Supervisor.start_link([], options) do
+    import Supervisor.Spec
+    child = worker(__MODULE__, [],
+      [function: :watcher, restart: :transient])
+    options  = [strategy: :simple_one_for_one, name: @name]
+    case Supervisor.start_link([child], options) do
       {:ok, _} = ok ->
         _ = for {mod, handler, args} <- apply(m, f, a) do
           {:ok, _} = watch(mod, handler, args)
@@ -32,16 +35,9 @@ defmodule Logger.Watcher do
   Watches the given handler as part of the watcher supervision tree.
   """
   def watch(mod, handler, args) do
-    import Supervisor.Spec
-    id = {mod, handler}
-    child = worker(__MODULE__, [mod, handler, args],
-      [id: id, function: :watcher, restart: :transient])
-    case Supervisor.start_child(@name, child) do
+    case Supervisor.start_child(@name, [mod, handler, args]) do
       {:ok, _pid} = result ->
         result
-      {:error, :already_present} ->
-        _ = Supervisor.delete_child(@name, id)
-        watch(mod, handler, args)
       {:error, _reason} = error ->
         error
     end
@@ -64,17 +60,28 @@ defmodule Logger.Watcher do
     ref = Process.monitor(mod)
 
     case GenEvent.add_handler(mod, handler, args, monitor: true) do
-      :ok               -> {:ok, {mod, handler, ref}}
-      {:error, :ignore} -> :ignore
-      {:error, reason}  -> {:stop, reason}
+      :ok ->
+        {:ok, {mod, handler, ref}}
+      {:error, :ignore} ->
+        # Can't return :ignore as a transient child under a simple_one_for_one.
+        # Instead return ok and then immediately exit normally - using a fake
+        # message.
+        send(self(), {:gen_event_EXIT, handler, :normal})
+        {:ok, {mod, handler, ref}}
+      {:error, reason}  ->
+        {:stop, reason}
     end
   end
 
   def init({mod, handler, args, :link}) do
     case :gen_event.add_sup_handler(mod, handler, args) do
-      :ok               -> {:ok, {mod, handler, nil}}
-      {:error, :ignore} -> :ignore
-      {:error, reason}  -> {:stop, reason}
+      :ok ->
+        {:ok, {mod, handler, nil}}
+      {:error, :ignore} ->
+        send(self(), {:gen_event_EXIT, handler, :normal})
+        {:ok, {mod, handler, nil}}
+      {:error, reason} ->
+        {:stop, reason}
     end
   end
 

lib/logger/test/logger/backends/console_test.exs

@@ -10,7 +10,7 @@ defmodule Logger.Backends.ConsoleTest do
   end
 
   test "does not start when there is no user" do
-    Logger.remove_backend(:console)
+    :ok = Logger.remove_backend(:console)
     user = Process.whereis(:user)
 
     try do
@@ -21,7 +21,7 @@ defmodule Logger.Backends.ConsoleTest do
       Process.register(user, :user)
     end
   after
-    Logger.add_backend(:console)
+    {:ok, _} = Logger.add_backend(:console)
   end
 
   test "can configure format" do

lib/logger/test/logger_test.exs

@@ -40,10 +40,9 @@ defmodule LoggerTest do
       assert Logger.debug("hello", []) == :ok
     end) == ""
 
-    assert {:ok, pid} = Logger.add_backend(:console)
+    assert {:ok, _pid} = Logger.add_backend(:console)
     assert Application.get_env(:logger, :backends) == [:console]
-    assert Logger.add_backend(:console) ==
-           {:error, {:already_started, pid}}
+    assert Logger.add_backend(:console) == {:error, :already_added}
     assert Application.get_env(:logger, :backends) == [:console]
   end
 
@@ -57,7 +56,7 @@ defmodule LoggerTest do
     end
 
     assert {:ok, _} = Logger.add_backend({MyBackend, :hello})
-    assert {:error, {:already_started, _}} = Logger.add_backend({MyBackend, :hello})
+    assert {:error, :already_added} = Logger.add_backend({MyBackend, :hello})
     assert :ok = Logger.remove_backend({MyBackend, :hello})
   end
 
@@ -181,7 +180,7 @@ defmodule LoggerTest do
 
     assert {:ok, pid} = Logger.add_backend(:console)
     assert Logger.add_backend(:console) ==
-           {:error, {:already_started, pid}}
+           {:error, :already_added}
   after
     Application.put_env(:logger, :backends, [:console])
     Logger.App.stop()