Port Erlang/OTP 21.0 logger from master

Erlang/OTP 21.0 only forwards certain events to the error_logger,
which means we need to bring the full logger implementation from
master.

Author: José Valim

lib/ex_unit/lib/ex_unit/capture_log.ex

@@ -70,7 +70,7 @@ defmodule ExUnit.CaptureLog do
     {:ok, string_io} = StringIO.open("")
 
     try do
-      _ = :gen_event.which_handlers(:error_logger)
+      _ = Process.whereis(:error_logger) && :gen_event.which_handlers(:error_logger)
       :ok = add_capture(string_io, opts)
       ref = ExUnit.CaptureServer.log_capture_on(self())
 

lib/logger/lib/logger.ex

@@ -16,8 +16,10 @@ defmodule Logger do
       performant when required but also apply backpressure
       when under stress.
 
-    * Wraps OTP's [`:error_logger`](http://erlang.org/doc/man/error_logger.html)
-      to prevent it from overflowing.
+    * Plugs into Erlang's [`:logger`](http://erlang.org/doc/man/logger.html)
+      (from Erlang/OTP 21) to convert terms to Elixir syntax or wraps
+      Erlang's [`:error_logger`](http://erlang.org/doc/man/error_logger.html)
+      in earlier Erlang/OTP versions to prevent it from overflowing.
 
   Logging is useful for tracking when an event of interest happens in your
   system. For example, it may be helpful to log whenever a user is deleted.
@@ -62,8 +64,8 @@ defmodule Logger do
     * Runtime configuration - can be set before the `:logger`
       application is started, but may be changed during runtime
 
-    * Error logger configuration - configuration for the
-      wrapper around OTP's [`:error_logger`](http://erlang.org/doc/man/error_logger.html)
+    * Erlang configuration - options that handle integration with
+      Erlang's logging facilities
 
   ### Application configuration
 
@@ -152,19 +154,24 @@ defmodule Logger do
   ### Error logger configuration
 
   The following configuration applies to `Logger`'s wrapper around
-  OTP's [`:error_logger`](http://erlang.org/doc/man/error_logger.html).
-  All the configurations below must be set before the `:logger` application starts.
+  Erlang's logging functionalities. All the configurations below must
+  be set before the `:logger` application starts.
 
     * `:handle_otp_reports` - redirects OTP reports to `Logger` so
-      they are formatted in Elixir terms. This uninstalls OTP's
-      logger that prints terms to terminal. Defaults to `true`.
+      they are formatted in Elixir terms. This effectively disables
+      Erlang standard logger. Defaults to `true`.
 
     * `:handle_sasl_reports` - redirects supervisor, crash and
       progress reports to `Logger` so they are formatted in Elixir
       terms. Your application must guarantee `:sasl` is started before
       `:logger`. This means you may see some initial reports written
-      in Erlang syntax until the Logger application kicks in and
-      uninstalls SASL's logger in favor of its own. Defaults to `false`.
+      in Erlang syntax until the Logger application kicks in.
+      Defaults to `false`.
+
+  From Erlang/OTP 21, `:handle_sasl_reports` only has an effect if
+  `:handle_otp_reports` is true.
+
+  The following configurations apply only for Erlang/OTP 20 and earlier:
 
     * `:discard_threshold_for_error_logger` - if `:error_logger` has more than
       `discard_threshold` messages in its inbox, messages will be dropped
@@ -176,19 +183,17 @@ defmodule Logger do
       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 Erlang 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`
-  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
-  information.
+  Furthermore, `Logger` allows messages sent by Erlang to be translated
+  into an Elixir format via translators. Translators can be added at any
+  time with the `add_translator/1` and `remove_translator/1` APIs. Check
+  `Logger.Translator` for more information.
 
   ## Backends
 
@@ -523,7 +528,7 @@ defmodule Logger do
   """
   @spec flush :: :ok
   def flush do
-    _ = :gen_event.which_handlers(:error_logger)
+    _ = Process.whereis(:error_logger) && :gen_event.which_handlers(:error_logger)
     :gen_event.sync_notify(Logger, :flush)
   end
 
@@ -533,8 +538,7 @@ defmodule Logger do
   ## Options
 
     * `:flush` - when `true`, guarantees all messages currently sent
-      to both Logger and OTP's [`:error_logger`](http://erlang.org/doc/man/error_logger.html)
-      are processed before the backend is added
+      to `Logger` are processed before the backend is added
 
   """
   @spec add_backend(atom, keyword) :: Supervisor.on_start_child()
@@ -560,8 +564,7 @@ defmodule Logger do
   ## Options
 
     * `:flush` - when `true`, guarantees all messages currently sent
-      to both Logger and OTP's [`:error_logger`](http://erlang.org/doc/man/error_logger.html)
-      are processed before the backend is removed
+      to `Logger` are processed before the backend is removed
 
   """
   @spec remove_backend(atom, keyword) :: :ok | {:error, term}
@@ -610,14 +613,17 @@ defmodule Logger do
       when level in @levels and is_list(metadata) do
     case __metadata__() do
       {true, pdict} ->
-        %{mode: mode, truncate: truncate, level: min_level, utc_log: utc_log?} =
-          Logger.Config.__data__()
-
-        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)
+        %{
+          mode: mode,
+          truncate: truncate,
+          level: min_level,
+          utc_log: utc_log?
+        } = Logger.Config.__data__()
+
+        with true <- compare_levels(level, min_level) != :lt and mode != :discard,
+             metadata = [pid: self()] ++ Keyword.merge(pdict, metadata),
+             {message, metadata} <- normalize_message(chardata_or_fun, metadata) do
           truncated = truncate(message, truncate)
-
           tuple = {Logger, truncated, Logger.Utils.timestamp(utc_log?), metadata}
 
           try do
@@ -629,7 +635,7 @@ defmodule Logger do
             :exit, reason -> {:error, reason}
           end
         else
-          :ok
+          _ -> :ok
         end
 
       {false, _} ->
@@ -755,15 +761,17 @@ defmodule Logger do
   end
 
   defp normalize_message(fun, metadata) when is_function(fun, 0) do
-    normalize_message(fun.(), metadata)
+    case fun.() do
+      {message, fun_metadata} -> {message, Keyword.merge(metadata, fun_metadata)}
+      :skip -> :skip
+      message -> {message, metadata}
+    end
   end
 
-  defp normalize_message({message, fun_metadata}, metadata) when is_list(fun_metadata) do
-    {message, Keyword.merge(metadata, fun_metadata)}
+  defp normalize_message(message, metadata) do
+    {message, metadata}
   end
 
-  defp normalize_message(message, metadata), do: {message, metadata}
-
   defp truncate(data, n) when is_list(data) or is_binary(data), do: Logger.Utils.truncate(data, n)
   defp truncate(data, n), do: Logger.Utils.truncate(to_string(data), n)
 

lib/logger/lib/logger/app.ex

@@ -7,8 +7,15 @@ defmodule Logger.App do
   def start(_type, _args) do
     otp_reports? = Application.get_env(:logger, :handle_otp_reports)
     sasl_reports? = Application.get_env(:logger, :handle_sasl_reports)
-    threshold = Application.get_env(:logger, :discard_threshold_for_error_logger)
-    error_handler = {:error_logger, Logger.ErrorHandler, {otp_reports?, sasl_reports?, threshold}}
+
+    otp_children =
+      if otp_logger?() do
+        []
+      else
+        threshold = Application.get_env(:logger, :discard_threshold_for_error_logger)
+        arg = {:error_logger, Logger.ErrorHandler, {otp_reports?, sasl_reports?, threshold}}
+        [%{id: Logger.ErrorHandler, start: {Logger.Watcher, :start_link, [arg]}}]
+      end
 
     children = [
       %{
@@ -17,19 +24,21 @@ defmodule Logger.App do
         modules: :dynamic
       },
       {Logger.Watcher, {Logger, Logger.Config, []}},
-      {Logger.WatcherSupervisor, {Logger.Config, :handlers, []}},
-      %{
-        id: Logger.ErrorHandler,
-        start: {Logger.Watcher, :start_link, [error_handler]}
-      }
+      {Logger.WatcherSupervisor, {Logger.Config, :handlers, []}}
+      | otp_children
     ]
 
     config = Logger.Config.new()
 
     case Supervisor.start_link(children, strategy: :rest_for_one, name: Logger.Supervisor) do
       {:ok, sup} ->
-        if otp_reports? or sasl_reports? do
-          delete_handlers(otp_reports?, sasl_reports?)
+        if otp_logger?() do
+          if otp_reports? do
+            add_elixir_handler(sasl_reports?)
+            delete_erlang_handler()
+          end
+        else
+          delete_old_handlers(otp_reports?, sasl_reports?)
         end
 
         {:ok, sup, config}
@@ -47,6 +56,10 @@ defmodule Logger.App do
 
   @doc false
   def stop(config) do
+    if otp_logger?() do
+      _ = :logger.remove_handler(Logger)
+    end
+
     add_handlers(Logger.Config.deleted_handlers())
     Logger.Config.delete(config)
   end
@@ -73,20 +86,35 @@ defmodule Logger.App do
     end
   end
 
-  defp delete_handlers(otp_reports?, sasl_reports?) do
+  # TODO: Remove conditional error_logger code once we require Erlang/OTP 21+.
+  defp otp_logger? do
+    is_pid(Process.whereis(:logger))
+  end
+
+  defp add_elixir_handler(sasl_reports?) do
+    config = %{level: :debug, sasl_reports?: sasl_reports?}
+    :logger.add_handler(Logger, Logger.ErlangHandler, config)
+  end
+
+  defp delete_erlang_handler() do
+    with {:ok, %{module: module} = config} <- :logger.get_handler_config(:default),
+         :ok <- :logger.remove_handler(:default) do
+      %{level: level} = :logger.get_primary_config()
+      :logger.update_primary_config(%{level: :debug})
+      primary_config = {:primary, %{level: level}}
+      handler_config = {:default, module, config}
+      [] = Logger.Config.deleted_handlers([primary_config, handler_config])
+      :ok
+    else
+      _ -> :ok
+    end
+  end
+
+  defp delete_old_handlers(otp_reports?, sasl_reports?) do
     deleted =
-      if is_pid(Process.whereis(:logger)) and Code.ensure_loaded?(:logger) do
-        with {:ok, {module, config}} <- :logger.get_handler_config(:default),
-             :ok <- :logger.remove_handler(:default) do
-          [{:default, module, config}]
-        else
-          _ -> []
-        end
-      else
-        for {tty, true} <- [error_logger_tty_h: otp_reports?, sasl_report_tty_h: sasl_reports?],
-            :error_logger.delete_report_handler(tty) != {:error, :module_not_found},
-            do: tty
-      end
+      for {tty, true} <- [error_logger_tty_h: otp_reports?, sasl_report_tty_h: sasl_reports?],
+          :error_logger.delete_report_handler(tty) != {:error, :module_not_found},
+          do: tty
 
     [] = Logger.Config.deleted_handlers(deleted)
     :ok
@@ -95,8 +123,14 @@ defmodule Logger.App do
   defp add_handlers(handlers) do
     for handler <- handlers do
       case handler do
-        {handler, module, config} -> :logger.add_handler(handler, module, config)
-        handler -> :error_logger.add_report_handler(handler)
+        {handler, module, config} ->
+          :logger.add_handler(handler, module, config)
+
+        {:primary, config} ->
+          :logger.update_primary_config(config)
+
+        handler ->
+          :error_logger.add_report_handler(handler)
       end
     end
 

lib/logger/lib/logger/error_handler.ex

@@ -2,6 +2,8 @@ defmodule Logger.ErrorHandler do
   @moduledoc false
   @behaviour :gen_event
 
+  # TODO: Remove this when we require Erlang/OTP 21+.
+
   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
@@ -83,17 +85,13 @@ defmodule Logger.ErrorHandler do
     %{
       mode: mode,
       level: min_level,
-      truncate: truncate,
-      utc_log: utc_log?,
-      translators: translators
+      utc_log: utc_log?
     } = Logger.Config.__data__()
 
     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)
-
+         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
-      meta = [pid: ensure_pid(pid), error_logger: ensure_type(type)]
       event = {Logger, message, Logger.Utils.timestamp(utc_log?), meta}
       :gen_event.notify(state.logger, {level, gl, event})
     end
@@ -155,25 +153,4 @@ defmodule Logger.ErrorHandler do
       0 -> :ok
     end
   end
-
-  defp translate([{mod, fun} | t], min_level, level, kind, data, truncate) do
-    case apply(mod, fun, [min_level, level, kind, data]) do
-      {:ok, chardata} -> {:ok, chardata}
-      :skip -> :skip
-      :none -> translate(t, min_level, level, kind, data, truncate)
-    end
-  end
-
-  defp translate([], _min_level, _level, :format, {format, args}, truncate) do
-    msg =
-      format
-      |> Logger.Utils.scan_inspect(args, truncate)
-      |> :io_lib.build_text()
-
-    {:ok, msg}
-  end
-
-  defp translate([], _min_level, _level, :report, {_type, data}, _truncate) do
-    {:ok, Kernel.inspect(data)}
-  end
 end

lib/logger/lib/logger/formatter.ex

@@ -20,7 +20,7 @@ defmodule Logger.Formatter do
     * `$message`  - the log message
     * `$level`    - the log level
     * `$node`     - the node that prints the message
-    * `$metadata` - user controlled data presented in `"key=val key2=val2"` format
+    * `$metadata` - user controlled data presented in `"key=val key2=val2 "` format
     * `$levelpad` - sets to a single space if level is 4 characters long,
       otherwise set to the empty space. Used to align the message after level.