diff options
author | José Valim <jose.valim@gmail.com> | 2018-05-07 14:45:17 +0200 |
---|---|---|
committer | GitHub <noreply@github.com> | 2018-05-07 14:45:17 +0200 |
commit | 2c770ba9d65f1c75437b392a1782585d8db05cc6 (patch) | |
tree | 1394c2d8b3c6252dc7180296bcc481412c5003f7 | |
parent | ae0389eea9e0c9ed25896dfcd7fbfa320f9432bf (diff) | |
download | elixir-2c770ba9d65f1c75437b392a1782585d8db05cc6.tar.gz |
Erlang/OTP 21 logger integration (#7649)
-rw-r--r-- | lib/ex_unit/lib/ex_unit/capture_log.ex | 2 | ||||
-rw-r--r-- | lib/logger/lib/logger.ex | 80 | ||||
-rw-r--r-- | lib/logger/lib/logger/app.ex | 77 | ||||
-rw-r--r-- | lib/logger/lib/logger/erlang_handler.ex | 133 | ||||
-rw-r--r-- | lib/logger/lib/logger/error_handler.ex | 33 | ||||
-rw-r--r-- | lib/logger/lib/logger/translator.ex | 344 | ||||
-rw-r--r-- | lib/logger/test/logger/config_test.exs | 1 | ||||
-rw-r--r-- | lib/logger/test/logger/erlang_handler_test.exs | 109 | ||||
-rw-r--r-- | lib/logger/test/logger/error_handler_test.exs | 29 | ||||
-rw-r--r-- | lib/logger/test/logger/translator_test.exs | 18 | ||||
-rw-r--r-- | lib/logger/test/logger_test.exs | 33 | ||||
-rw-r--r-- | lib/logger/test/test_helper.exs | 4 |
12 files changed, 628 insertions, 235 deletions
diff --git a/lib/ex_unit/lib/ex_unit/capture_log.ex b/lib/ex_unit/lib/ex_unit/capture_log.ex index 603ad5e25..88d4baab9 100644 --- a/lib/ex_unit/lib/ex_unit/capture_log.ex +++ b/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()) diff --git a/lib/logger/lib/logger.ex b/lib/logger/lib/logger.ex index b1e14bda7..1e0f663b2 100644 --- a/lib/logger/lib/logger.ex +++ b/lib/logger/lib/logger.ex @@ -16,8 +16,10 @@ defmodule Logger do performant when required but also apply backpressure when under stress. - * Wraps Erlang'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 Erlangs'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 - Erlang'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 Erlang'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 375 (0.75 * threshold) entries and 50 (0.1 * threshold) 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 Erlang'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 @@ -530,7 +535,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 @@ -540,8 +545,7 @@ defmodule Logger do ## Options * `:flush` - when `true`, guarantees all messages currently sent - to both `Logger` and Erlangs'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() @@ -567,8 +571,7 @@ defmodule Logger do ## Options * `:flush` - when `true`, guarantees all messages currently sent - to both `Logger` and Erlangs's [`:error_logger`](http://erlang.org/doc/man/error_logger.html) - are processed before the backend is removed + to both `Logger` are processed before the backend is removed """ @spec remove_backend(atom, keyword) :: :ok | {:error, term} @@ -617,14 +620,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 @@ -636,7 +642,7 @@ defmodule Logger do :exit, reason -> {:error, reason} end else - :ok + _ -> :ok end {false, _} -> @@ -767,15 +773,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) diff --git a/lib/logger/lib/logger/app.ex b/lib/logger/lib/logger/app.ex index 58f982609..61b505bdb 100644 --- a/lib/logger/lib/logger/app.ex +++ b/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,23 @@ 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} -> - handlers = [error_logger_tty_h: otp_reports?, sasl_report_tty_h: sasl_reports?] - delete_handlers(handlers) + 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} {:error, _} = error -> @@ -45,9 +56,11 @@ defmodule Logger.App do @doc false def stop(config) do - Logger.Config.deleted_handlers() - |> add_handlers() + if otp_logger?() do + _ = :logger.remove_handler(Logger) + end + add_handlers(Logger.Config.deleted_handlers()) Logger.Config.delete(config) end @@ -73,17 +86,45 @@ defmodule Logger.App do end end - defp delete_handlers(handlers) do - to_delete = - for {handler, delete?} <- handlers, - delete? && :error_logger.delete_report_handler(handler) != {:error, :module_not_found}, - do: handler + # 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.set_logger_config(%{level: :debug}) + :logger.add_handler(Logger, Logger.ErlangHandler, config) + end - [] = Logger.Config.deleted_handlers(to_delete) + defp delete_erlang_handler() do + with {:ok, {module, config}} <- :logger.get_handler_config(:logger_std_h), + :ok <- :logger.remove_handler(:logger_std_h) do + [] = Logger.Config.deleted_handlers([{:logger_std_h, module, config}]) + :ok + else + _ -> :ok + end + end + + defp delete_old_handlers(otp_reports?, sasl_reports?) do + deleted = + 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 end defp add_handlers(handlers) do - Enum.each(handlers, &:error_logger.add_report_handler/1) + for handler <- handlers do + case handler do + {handler, module, config} -> :logger.add_handler(handler, module, config) + handler -> :error_logger.add_report_handler(handler) + end + end + + :ok end end diff --git a/lib/logger/lib/logger/erlang_handler.ex b/lib/logger/lib/logger/erlang_handler.ex new file mode 100644 index 000000000..3973d51fa --- /dev/null +++ b/lib/logger/lib/logger/erlang_handler.ex @@ -0,0 +1,133 @@ +defmodule Logger.ErlangHandler do + @moduledoc false + + @doc """ + Hook required by `:logger`. + """ + def log(%{meta: %{domain: [:beam, :erlang, :otp, :sasl | _]}}, %{sasl_reports?: false}) do + :ok + end + + def log(%{meta: %{domain: [:supervisor_report]}}, %{sasl_reports?: false}) do + :ok + end + + def log(%{level: level, msg: msg, meta: erl_meta}, _config) do + level = erlang_level_to_elixir_level(level) + + Logger.bare_log(level, fn -> + try do + meta = extract_metadata(erl_meta) + + case msg do + {:string, string} -> + {string, meta} + + {:report, %{label: label, report: report} = complete} when map_size(complete) == 2 -> + translate(level, :report, {label, report}, meta, erl_meta) + + {:report, %{label: {:error_logger, _}, format: format, args: args}} -> + translate(level, :format, {format, args}, meta, erl_meta) + + {:report, report} -> + translate(level, :report, {:logger, report}, meta, erl_meta) + + {format, args} -> + translate(level, :format, {format, args}, meta, erl_meta) + end + rescue + e -> + [ + "Failure while translating Erlang's logger event\n", + Exception.format(:error, e, __STACKTRACE__) + ] + end + end) + end + + defp erlang_level_to_elixir_level(:emergency), do: :error + defp erlang_level_to_elixir_level(:alert), do: :error + defp erlang_level_to_elixir_level(:critical), do: :error + defp erlang_level_to_elixir_level(:error), do: :error + defp erlang_level_to_elixir_level(:warning), do: :warn + defp erlang_level_to_elixir_level(:notice), do: :info + defp erlang_level_to_elixir_level(:info), do: :info + defp erlang_level_to_elixir_level(:debug), do: :debug + + defp extract_metadata(map) do + metadata = [] + + metadata = + case map do + %{mfa: {mod, fun, arity}} -> [module: mod, function: form_fa(fun, arity)] ++ metadata + _ -> metadata + end + + metadata = + case map do + %{file: file, line: line} -> [file: List.to_string(file), line: line] ++ metadata + _ -> metadata + end + + metadata = + case map do + %{pid: pid} -> [pid: pid] ++ metadata + _ -> metadata + end + + metadata + rescue + _ -> [] + end + + defp form_fa(fun, arity) do + Atom.to_string(fun) <> "/" <> Integer.to_string(arity) + end + + @doc """ + Shared translation convenience. + """ + def translate(level, kind, data, meta, erl_meta) do + %{ + level: min_level, + truncate: truncate, + translators: translators + } = Logger.Config.__data__() + + case translate(translators, min_level, level, kind, data, meta) do + :none -> {translate_fallback(kind, data, erl_meta, truncate), meta} + other -> other + end + end + + defp translate([{mod, fun} | t], min_level, level, kind, data, meta) do + case apply(mod, fun, [min_level, level, kind, data]) do + {:ok, chardata, transdata} -> {chardata, Keyword.merge(meta, transdata)} + {:ok, chardata} -> {chardata, meta} + :skip -> :skip + :none -> translate(t, min_level, level, kind, data, meta) + end + end + + defp translate([], _min_level, _level, _kind, _data, _meta) do + :none + end + + defp translate_fallback(:report, {:logger, data}, %{report_cb: callback} = meta, truncate) do + translate_fallback(:format, callback.(data), meta, truncate) + end + + defp translate_fallback(:format, {format, args}, _meta, truncate) do + format + |> Logger.Utils.scan_inspect(args, truncate) + |> :io_lib.build_text() + end + + defp translate_fallback(:report, {_type, %{} = data}, _meta, _truncate) do + Kernel.inspect(Map.to_list(data)) + end + + defp translate_fallback(:report, {_type, data}, _meta, _truncate) do + Kernel.inspect(data) + end +end diff --git a/lib/logger/lib/logger/error_handler.ex b/lib/logger/lib/logger/error_handler.ex index 4769348b7..e6f8cc173 100644 --- a/lib/logger/lib/logger/error_handler.ex +++ b/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 diff --git a/lib/logger/lib/logger/translator.ex b/lib/logger/lib/logger/translator.ex index bbce72bf3..8bbe407a1 100644 --- a/lib/logger/lib/logger/translator.ex +++ b/lib/logger/lib/logger/translator.ex @@ -13,14 +13,15 @@ defmodule Logger.Translator do * `min_level` - the current Logger level * `level` - the level of the message being translated - * `kind` - if the message is a report or a format - * `message` - the message to format. If it is a report, it is a tuple - with `{report_type, report_data}`, if it is a format, it is a - tuple with `{format_message, format_args}` + * `kind` - if the message is a `:report` or `:format` + * `message` - the message to format. If it is :report`, it is a tuple + with `{report_type, report_data}`, if it is `:format`, it is a + tuple with `{format_message, format_args}`. The function must return: - * `{:ok, chardata}` - if the message was translated with its translation + * `{:ok, chardata, metadata}` - if the message translation with its metadata + * `{:ok, chardata}` - the translated message * `:skip` - if the message is not meant to be translated nor logged * `:none` - if there is no translation, which triggers the next translator @@ -28,17 +29,67 @@ defmodule Logger.Translator do and the default messages translated by Logger. """ - # The name_or_id checks are required to support old Erlang projects. - + @doc """ + Built-in translation function. + """ def translate(min_level, level, kind, message) + ## Erlang/OTP 21 and after + + def translate(min_level, _level, :report, {:logger, %{label: label} = report}) do + case label do + {:gen_server, :terminate} -> + report_gen_server_terminate(min_level, report) + + {:gen_event, :terminate} -> + report_gen_event_terminate(min_level, report) + + _ -> + :skip + end + end + + def translate(min_level, _level, :report, {{:proc_lib, :crash}, data}) do + report_crash(min_level, data) + end + + def translate(min_level, _level, :report, {{:supervisor, :progress}, data}) do + report_supervisor_progress(min_level, data) + end + + def translate(min_level, _level, :report, {{:supervisor, _}, data}) do + report_supervisor(min_level, data) + end + + def translate( + _min_level, + _level, + :report, + {{:application_controller, :progress}, [application: app, started_at: node]} + ) do + {:ok, ["Application ", Atom.to_string(app), " started at " | inspect(node)]} + end + + def translate( + _min_level, + _level, + :report, + {{:application_controller, :exit}, [application: app, exited: reason, type: _type]} + ) do + {:ok, ["Application ", Atom.to_string(app), " exited: " | Application.format_error(reason)]} + end + + ## Erlang/OTP 20 and before + def translate(min_level, :error, :format, message) do opts = Application.get_env(:logger, :translator_inspect_opts) case message do {'** Generic server ' ++ _, [name, last, state, reason | client]} -> + {formatted, _reason} = format_reason(reason) + msg = - ["GenServer #{inspect(name)} terminating", format_stop(reason)] ++ + ["GenServer #{inspect(name)} terminating", formatted] ++ ["\nLast message#{format_from(client)}: #{inspect(last, opts)}"] if min_level == :debug do @@ -48,9 +99,11 @@ defmodule Logger.Translator do end {'** gen_event handler ' ++ _, [name, manager, last, state, reason]} -> + {formatted, _reason} = format_reason(reason) + msg = ["GenEvent handler #{inspect(name)} installed in #{inspect(manager)} terminating"] ++ - [format_stop(reason), "\nLast message: #{inspect(last, opts)}"] + [formatted, "\nLast message: #{inspect(last, opts)}"] if min_level == :debug do {:ok, [msg | "\nState: #{inspect(state, opts)}"]} @@ -59,9 +112,11 @@ defmodule Logger.Translator do end {'** Task ' ++ _, [name, starter, function, args, reason]} -> + {formatted, _reason} = format_reason(reason) + msg = ["Task #{inspect(name)} started from #{inspect(starter)} terminating"] ++ - [format_stop(reason), "\nFunction: #{inspect(function, opts)}"] ++ + [formatted, "\nFunction: #{inspect(function, opts)}"] ++ ["\n Args: #{inspect(args, opts)}"] {:ok, msg} @@ -80,121 +135,177 @@ defmodule Logger.Translator do :std_info, [application: app, exited: reason, type: _type] }) do - {:ok, "Application #{app} exited: #{Application.format_error(reason)}"} + {:ok, ["Application ", Atom.to_string(app), " exited: " | Application.format_error(reason)]} + end + + def translate(min_level, :error, :report, {{:error_logger, :error_report}, data}) do + report_supervisor(min_level, data) end def translate(min_level, :error, :report, {:supervisor_report, data}) do - translate_supervisor(min_level, data) + report_supervisor(min_level, data) end def translate(min_level, :error, :report, {:crash_report, data}) do - translate_crash(min_level, data) + report_crash(min_level, data) + end + + def translate(min_level, :info, :report, {:progress, [{:supervisor, _} | _] = data}) do + report_supervisor_progress(min_level, data) end - def translate(min_level, :info, :report, {:progress, data}) do - translate_progress(min_level, data) + def translate(_min_level, :info, :report, {:progress, [application: app, started_at: node]}) do + {:ok, ["Application ", Atom.to_string(app), " started at " | inspect(node)]} end + ## Helpers + def translate(_min_level, _level, _kind, _message) do :none end - defp translate_supervisor( + defp report_gen_server_terminate(min_level, report) do + inspect_opts = Application.get_env(:logger, :translator_inspect_opts) + + %{ + client_info: client, + last_message: last, + name: name, + reason: reason, + state: state + } = report + + {formatted, _reason} = format_reason(reason) + + msg = + ["GenServer ", inspect(name), " terminating", formatted] ++ + ["\nLast message", format_last_message_from(client), ": ", inspect(last, inspect_opts)] + + if min_level == :debug do + {:ok, [msg, "\nState: ", inspect(state, inspect_opts) | format_client_info(client)]} + else + {:ok, msg} + end + end + + defp report_gen_event_terminate(min_level, report) do + inspect_opts = Application.get_env(:logger, :translator_inspect_opts) + + %{ + handler: handler, + last_message: last, + name: name, + reason: reason, + state: state + } = report + + reason = + case reason do + {:EXIT, why} -> why + _ -> reason + end + + {formatted, _reason} = format_reason(reason) + + msg = + ["GenEvent handler ", inspect(handler), " installed in ", inspect(name), " terminating"] ++ + [formatted, "\nLast message: ", inspect(last, inspect_opts)] + + if min_level == :debug do + {:ok, [msg, "\nState: ", inspect(state, inspect_opts)]} + else + {:ok, msg} + end + end + + defp report_supervisor_progress( min_level, supervisor: sup, - errorContext: context, - reason: reason, - offender: [{:pid, pid}, {name_or_id, name} | offender] - ) - when is_pid(pid) and context !== :shutdown and name_or_id in [:name, :id] do + started: [{:pid, pid}, {:id, id} | started] + ) do msg = - ["Child ", inspect(name), " of Supervisor ", sup_name(sup)] ++ - [?\s, sup_context(context), "\n** (exit) "] ++ - [offender_reason(reason, context), "\nPid: ", inspect(pid)] ++ - child_info(min_level, offender) + ["Child ", inspect(id), " of Supervisor ", sup_name(sup), " started"] ++ + ["\nPid: ", inspect(pid)] ++ child_info(min_level, started) {:ok, msg} end - defp translate_supervisor( + defp report_supervisor_progress( min_level, supervisor: sup, - errorContext: context, - reason: reason, - offender: [{:pid, _pid}, {name_or_id, name} | offender] - ) - when name_or_id in [:name, :id] do + started: [{:pid, pid} | started] + ) do msg = - ["Child ", inspect(name), " of Supervisor ", sup_name(sup)] ++ - [?\s, sup_context(context), "\n** (exit) ", offender_reason(reason, context)] ++ - child_info(min_level, offender) + ["Child of Supervisor ", sup_name(sup), " started", "\nPid: ", inspect(pid)] ++ + child_info(min_level, started) {:ok, msg} end - defp translate_supervisor( + defp report_supervisor_progress(_min_level, _other), do: :none + + defp report_supervisor( min_level, supervisor: sup, errorContext: context, reason: reason, - offender: [{:pid, pid} | offender] + offender: [{:pid, pid}, {:id, id} | offender] ) do + pid_info = + if is_pid(pid) and context != :shutdown do + ["\nPid: ", inspect(pid)] + else + [] + end + msg = - ["Child of Supervisor ", sup_name(sup), ?\s, sup_context(context), "\n** (exit) "] ++ - [offender_reason(reason, context), "\nPid: ", inspect(pid)] ++ - child_info(min_level, offender) + ["Child ", inspect(id), " of Supervisor ", sup_name(sup)] ++ + [?\s, sup_context(context), "\n** (exit) ", offender_reason(reason, context)] ++ + pid_info ++ child_info(min_level, offender) {:ok, msg} end - defp translate_supervisor( + defp report_supervisor( min_level, supervisor: sup, errorContext: context, reason: reason, - offender: [{:nb_children, n}, {name_or_id, name} | offender] - ) - when name_or_id in [:name, :id] do + offender: [{:nb_children, n}, {:id, id} | offender] + ) do msg = - ["Children ", inspect(name), " of Supervisor ", sup_name(sup), ?\s, sup_context(context)] ++ - ["\n** (exit) ", offender_reason(reason, context), "\nNumber: ", inspect(n)] ++ + ["Children ", inspect(id), " of Supervisor ", sup_name(sup), ?\s, sup_context(context)] ++ + ["\n** (exit) ", offender_reason(reason, context), "\nNumber: ", Integer.to_string(n)] ++ child_info(min_level, offender) {:ok, msg} end - defp translate_supervisor(_min_level, _other), do: :none - - defp translate_progress(_min_level, application: app, started_at: node_name) do - {:ok, ["Application ", to_string(app), " started at " | inspect(node_name)]} - end - - defp translate_progress( + defp report_supervisor( min_level, supervisor: sup, - started: [{:pid, pid}, {name_or_id, name} | started] - ) - when name_or_id in [:name, :id] do + errorContext: context, + reason: reason, + offender: [{:pid, pid} | offender] + ) do msg = - ["Child ", inspect(name), " of Supervisor ", sup_name(sup)] ++ - [" started", "\nPid: ", inspect(pid)] ++ child_info(min_level, started) + ["Child of Supervisor ", sup_name(sup), ?\s, sup_context(context)] ++ + ["\n** (exit) ", offender_reason(reason, context), "\nPid: ", inspect(pid)] ++ + child_info(min_level, offender) {:ok, msg} end - defp translate_progress( - min_level, - supervisor: sup, - started: [{:pid, pid} | started] - ) do - msg = - ["Child of Supervisor ", sup_name(sup), " started", "\nPid: ", inspect(pid)] ++ - child_info(min_level, started) + defp report_supervisor(_min_level, _other), do: :none - {:ok, msg} + # If start call raises reason will be of form {:EXIT, reason} + defp offender_reason({:EXIT, reason}, :start_error) do + Exception.format_exit(reason) end - defp translate_progress(_min_level, _other), do: :none + defp offender_reason(reason, _context) do + Exception.format_exit(reason) + end defp sup_name({:local, name}), do: inspect(name) defp sup_name({:global, name}), do: inspect(name) @@ -210,10 +321,12 @@ defmodule Logger.Translator do ["\nStart Call: ", format_mfa(mod, fun, args) | child_debug(min_level, debug)] end + # Comes from bridge with MFA defp child_info(min_level, [{:mfa, {mod, fun, args}} | debug]) do ["\nStart Call: ", format_mfa(mod, fun, args) | child_debug(min_level, debug)] end + # Comes from bridge with Mod defp child_info(min_level, [{:mod, mod} | debug]) do ["\nStart Module: ", inspect(mod) | child_debug(min_level, debug)] end @@ -227,16 +340,7 @@ defmodule Logger.Translator do [] end - # If start call raises reason will be of form {:EXIT, reason} - defp offender_reason({:EXIT, reason}, :start_error) do - Exception.format_exit(reason) - end - - defp offender_reason(reason, _context) do - Exception.format_exit(reason) - end - - defp translate_crash(min_level, [ + defp report_crash(min_level, [ [ {:initial_call, _} = initial_call, {:pid, pid}, @@ -245,14 +349,16 @@ defmodule Logger.Translator do ], linked ]) do + reason = Exception.normalize(kind, exception, stack) + msg = - ["Process ", crash_name(pid, name), " terminating", format(kind, exception, stack)] ++ + ["Process ", crash_name(pid, name), " terminating", format(kind, reason, stack)] ++ [crash_info(min_level, [initial_call | crashed])] ++ crash_linked(min_level, linked) {:ok, msg} end - defp translate_crash(min_level, [ + defp report_crash(min_level, [ [ {:pid, pid}, {:registered_name, name}, @@ -260,8 +366,10 @@ defmodule Logger.Translator do ], linked ]) do + reason = Exception.normalize(kind, exception, stack) + msg = - ["Process ", crash_name(pid, name), " terminating", format(kind, exception, stack)] ++ + ["Process ", crash_name(pid, name), " terminating", format(kind, reason, stack)] ++ [crash_info(min_level, crashed), crash_linked(min_level, linked)] {:ok, msg} @@ -309,7 +417,6 @@ defmodule Logger.Translator do defp crash_debug(:current_stacktrace, stack, prefix) do stack_prefix = [prefix | " "] stacktrace = Enum.map(stack, &[stack_prefix | Exception.format_stacktrace_entry(&1)]) - [prefix, "Current Stacktrace:" | stacktrace] end @@ -339,43 +446,59 @@ defmodule Logger.Translator do end) end - defp crash_neighbour(min_level, [{:pid, pid}, {:registered_name, []} | info]) do - indent = " " + @indent " " - [?\n, indent, inspect(pid) | crash_info(min_level, info, [?\n, indent | indent])] + defp crash_neighbour(min_level, [{:pid, pid}, {:registered_name, []} | info]) do + [?\n, @indent, inspect(pid) | crash_info(min_level, info, [?\n, @indent | @indent])] end defp crash_neighbour(min_level, [{:pid, pid}, {:registered_name, name} | info]) do - indent = " " - - [?\n, indent, inspect(name), " (", inspect(pid), ")"] ++ - crash_info(min_level, info, [?\n, indent | indent]) + [?\n, @indent, inspect(name), " (", inspect(pid), ")"] ++ + crash_info(min_level, info, [?\n, @indent | @indent]) end - defp format_stop({maybe_exception, [_ | _] = maybe_stacktrace} = reason) do + defp format_last_message_from({_, {name, _}}), do: [" (from ", inspect(name), ")"] + defp format_last_message_from({from, _}), do: [" (from ", inspect(from), ")"] + defp format_last_message_from(_), do: [] + + defp format_client_info({from, :dead}), + do: ["\nClient ", inspect(from), " is dead"] + + defp format_client_info({from, :remote}), + do: ["\nClient ", inspect(from), " is remote on node ", inspect(node(from))] + + defp format_client_info({_, {name, stacktrace}}), + do: ["\nClient ", inspect(name), " is alive\n" | format_stacktrace(stacktrace)] + + defp format_client_info(_), + do: [] + + defp format_reason({maybe_exception, [_ | _] = maybe_stacktrace} = reason) do try do format_stacktrace(maybe_stacktrace) catch :error, _ -> - format_stop_banner(reason) + {format_stop(reason), {reason, []}} else formatted_stacktrace -> - [format_stop_banner(maybe_exception, maybe_stacktrace) | formatted_stacktrace] + {formatted, reason} = maybe_normalize(maybe_exception, maybe_stacktrace) + {[formatted | formatted_stacktrace], {reason, maybe_stacktrace}} end end - defp format_stop(reason) do - format_stop_banner(reason) + defp format_reason(reason) do + {format_stop(reason), {reason, []}} end - defp format_stop_banner(reason) do + defp format_stop(reason) do ["\n** (stop) " | Exception.format_exit(reason)] end # Erlang processes rewrite the :undef error to these reasons when logging + # TODO: This clause can be removed when we support only Erlang/OTP 21+. @gen_undef [:"module could not be loaded", :"function not exported"] - defp format_stop_banner(undef, [{mod, fun, args, _info} | _] = stacktrace) + defp maybe_normalize(undef, [{mod, fun, args, _info} | _] = stacktrace) when undef in @gen_undef and is_atom(mod) and is_atom(fun) do cond do is_list(args) -> @@ -385,47 +508,44 @@ defmodule Logger.Translator do format_undef(mod, fun, args, undef, stacktrace) true -> - format_stop_banner(undef) + {format_stop(undef), undef} end end - defp format_stop_banner(reason, stacktrace) do + defp maybe_normalize(reason, stacktrace) do # If this is already an exception (even an ErlangError), we format it as an # exception. Otherwise, we try to normalize it, and if it's normalized as an # ErlangError we instead format it as an exit. if Exception.exception?(reason) do - [?\n | Exception.format_banner(:error, reason, stacktrace)] + {[?\n | Exception.format_banner(:error, reason, stacktrace)], reason} else case Exception.normalize(:error, reason, stacktrace) do %ErlangError{} -> - format_stop_banner(reason) + {format_stop(reason), reason} exception -> - [?\n | Exception.format_banner(:error, exception, stacktrace)] + {[?\n | Exception.format_banner(:error, exception, stacktrace)], exception} end end end - defp format_undef(mod, fun, arity, undef, stacktrace) do - opts = [module: mod, function: fun, arity: arity, reason: undef] - exception = UndefinedFunctionError.exception(opts) - [?\n | Exception.format_banner(:error, exception, stacktrace)] - end - defp format(kind, payload, stacktrace) do [?\n, Exception.format_banner(kind, payload, stacktrace) | format_stacktrace(stacktrace)] end defp format_stacktrace(stacktrace) do for entry <- stacktrace do - [<<"\n ">> | Exception.format_stacktrace_entry(entry)] + ["\n " | Exception.format_stacktrace_entry(entry)] end end defp format_mfa(mod, fun, :undefined), do: [inspect(mod), ?., Code.Identifier.inspect_as_function(fun) | "/?"] - defp format_mfa(mod, fun, args), do: Exception.format_mfa(mod, fun, args) + defp format_mfa(mod, fun, args), + do: Exception.format_mfa(mod, fun, args) + + ## Deprecated helpers defp format_from([]), do: "" defp format_from([from]), do: " (from #{inspect(from)})" @@ -439,10 +559,16 @@ defmodule Logger.Translator do end defp format_client([from, stacktrace]) when is_list(stacktrace) do - ["\nClient #{inspect(from)} is alive\n" | Exception.format_stacktrace(stacktrace)] + ["\nClient #{inspect(from)} is alive\n" | format_stacktrace(stacktrace)] end defp format_client(_) do [] end + + defp format_undef(mod, fun, arity, undef, stacktrace) do + opts = [module: mod, function: fun, arity: arity, reason: undef] + exception = UndefinedFunctionError.exception(opts) + {[?\n | Exception.format_banner(:error, exception, stacktrace)], exception} + end end diff --git a/lib/logger/test/logger/config_test.exs b/lib/logger/test/logger/config_test.exs index 8d78c8ed7..4100f0446 100644 --- a/lib/logger/test/logger/config_test.exs +++ b/lib/logger/test/logger/config_test.exs @@ -24,7 +24,6 @@ defmodule Logger.ConfigTest 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 diff --git a/lib/logger/test/logger/erlang_handler_test.exs b/lib/logger/test/logger/erlang_handler_test.exs new file mode 100644 index 000000000..5adddc1a5 --- /dev/null +++ b/lib/logger/test/logger/erlang_handler_test.exs @@ -0,0 +1,109 @@ +defmodule Logger.ErlangHandlerTest do + use Logger.Case + @moduletag :logger + + defmodule CustomTranslator do + def t(:debug, :info, :format, {'hello: ~p', [:ok]}) do + :skip + end + + def t(:debug, :info, :format, {'world: ~p', [:ok]}) do + {:ok, "rewritten"} + end + + def t(:debug, :info, :report, {:logger, %{hello: :ok}}) do + :skip + end + + def t(:debug, :info, :report, {:logger, %{world: :ok}}) do + {:ok, "rewritten"} + end + + def t(:debug, :info, :report, {:logger, %{error: error}}) do + raise(error) + end + + def t(_, _, _, _) do + :none + end + end + + test "add_translator/1 and remove_translator/1 for error_logger" do + assert Logger.add_translator({CustomTranslator, :t}) + + assert capture_log(fn -> + :error_logger.info_msg('hello: ~p', [:ok]) + end) == "" + + assert capture_log(fn -> + :error_logger.info_msg('world: ~p', [:ok]) + end) =~ "[info] rewritten" + after + assert Logger.remove_translator({CustomTranslator, :t}) + end + + test "add_translator/1 and remove_translator/1 for logger formats" do + assert Logger.add_translator({CustomTranslator, :t}) + + assert capture_log(fn -> + :logger.info('hello: ~p', [:ok]) + end) == "" + + assert capture_log(fn -> + :logger.info('world: ~p', [:ok]) + end) =~ "[info] rewritten" + + assert capture_log(fn -> + :logger.info(%{hello: :ok}) + end) == "" + + assert capture_log(fn -> + :logger.info(%{world: :ok}) + end) =~ "[info] rewritten" + after + assert Logger.remove_translator({CustomTranslator, :t}) + end + + test "handles translation error" do + assert Logger.add_translator({CustomTranslator, :t}) + + message = capture_log(fn -> :logger.info(%{error: "oops"}) end) + assert message =~ "[info] Failure while translating Erlang's logger event\n" + assert message =~ "** (RuntimeError) oops\n" + after + assert Logger.remove_translator({CustomTranslator, :t}) + end + + test "converts Erlang metadata" do + Logger.configure_backend(:console, metadata: [:file, :line, :module, :function]) + + message = + capture_log(fn -> + :logger.info("ok", %{file: 'file.erl', line: 13, mfa: {Foo, :bar, 3}}) + end) + + assert message =~ "module=Foo" + assert message =~ "function=bar/3" + assert message =~ "file=file.erl" + assert message =~ "line=13" + after + Logger.configure_backend(:console, metadata: []) + end + + test "uses reporting callback with Elixir inspection" do + assert capture_log(fn -> + callback = fn %{hello: :world} -> {"~p~n", [:formatted]} end + :logger.info(%{hello: :world}, %{report_cb: callback}) + end) =~ "[info] :formatted" + end + + test "converts log levels" do + assert capture_log(fn -> :logger.emergency('ok') end) =~ "[error] ok" + assert capture_log(fn -> :logger.alert('ok') end) =~ "[error] ok" + assert capture_log(fn -> :logger.critical('ok') end) =~ "[error] ok" + assert capture_log(fn -> :logger.error('ok') end) =~ "[error] ok" + assert capture_log(fn -> :logger.warning('ok') end) =~ "[warn] ok" + assert capture_log(fn -> :logger.info('ok') end) =~ "[info] ok" + assert capture_log(fn -> :logger.debug('ok') end) =~ "[debug] ok" + end +end diff --git a/lib/logger/test/logger/error_handler_test.exs b/lib/logger/test/logger/error_handler_test.exs index 9ebc9cba8..45ff77090 100644 --- a/lib/logger/test/logger/error_handler_test.exs +++ b/lib/logger/test/logger/error_handler_test.exs @@ -1,5 +1,34 @@ defmodule Logger.ErrorHandlerTest do use Logger.Case + @moduletag :error_logger + + test "add_translator/1 and remove_translator/1" do + defmodule CustomTranslator do + def t(:debug, :info, :format, {'hello: ~p', [:ok]}) do + :skip + end + + def t(:debug, :info, :format, {'world: ~p', [:ok]}) do + {:ok, "rewritten"} + end + + def t(_, _, _, _) do + :none + end + end + + assert Logger.add_translator({CustomTranslator, :t}) + + assert capture_log(fn -> + :error_logger.info_msg('hello: ~p', [:ok]) + end) == "" + + assert capture_log(fn -> + :error_logger.info_msg('world: ~p', [:ok]) + end) =~ "\[info\] rewritten" + after + assert Logger.remove_translator({CustomTranslator, :t}) + end test "survives after crashes" do expected_result = diff --git a/lib/logger/test/logger/translator_test.exs b/lib/logger/test/logger/translator_test.exs index cddf75c51..64bcd9b78 100644 --- a/lib/logger/test/logger/translator_test.exs +++ b/lib/logger/test/logger/translator_test.exs @@ -339,21 +339,21 @@ defmodule Logger.TranslatorTest do """s end - test "translates application stop" do + test "translates application start" do assert capture_log(fn -> - :ok = Application.start(:eex) + Application.start(:eex) Application.stop(:eex) end) =~ """ - Application eex exited: :stopped + Application eex started at #{inspect(node())} """ end - test "translates application start" do + test "translates application stop" do assert capture_log(fn -> - Application.start(:eex) + :ok = Application.start(:eex) Application.stop(:eex) end) =~ """ - Application eex started at #{inspect(node())} + Application eex exited: :stopped """ end @@ -484,7 +484,7 @@ defmodule Logger.TranslatorTest do receive do: ({:DOWN, ^ref, _, _, _} -> :ok) end) =~ ~r""" Ancestors: \[#PID<\d+\.\d+\.\d+>\](?: - Message Queue Length: 1(?#TODO: Require once depend on 20)|) + Message Queue Length: 1(?#TODO: Require once depend on Erlang/OTP 20)|) Messages: \[:message\] Links: \[\] Dictionary: \[\] @@ -516,7 +516,7 @@ defmodule Logger.TranslatorTest do Stack Size: \d+ Reductions: \d+(?: Current Stacktrace: - test/logger/translator_test.exs:\d+: Logger.TranslatorTest.sleep/1(?#TODO: Require once depend on 20)|) + test/logger/translator_test.exs:\d+: Logger.TranslatorTest.sleep/1(?#TODO: Require once depend on Erlang/OTP 20)|) """ end @@ -775,7 +775,7 @@ defmodule Logger.TranslatorTest do """ end - test "handles :undefined MFA properly" do + test "reports :undefined MFA properly" do defmodule WeirdFunctionNamesGenServer do use GenServer diff --git a/lib/logger/test/logger_test.exs b/lib/logger/test/logger_test.exs index 6484adab3..b53f1624d 100644 --- a/lib/logger/test/logger_test.exs +++ b/lib/logger/test/logger_test.exs @@ -4,44 +4,13 @@ defmodule LoggerTest do setup_all do Logger.configure_backend(:console, metadata: [:application, :module]) - - on_exit(fn -> - Logger.configure_backend(:console, metadata: []) - end) + on_exit(fn -> Logger.configure_backend(:console, metadata: []) end) end defp msg_with_meta(text) do msg("module=LoggerTest #{text}") end - test "add_translator/1 and remove_translator/1" do - defmodule CustomTranslator do - def t(:debug, :info, :format, {'hello: ~p', [:ok]}) do - :skip - end - - def t(:debug, :info, :format, {'world: ~p', [:ok]}) do - {:ok, "rewritten"} - end - - def t(_, _, _, _) do - :none - end - end - - assert Logger.add_translator({CustomTranslator, :t}) - - assert capture_log(fn -> - :error_logger.info_msg('hello: ~p', [:ok]) - end) == "" - - assert capture_log(fn -> - :error_logger.info_msg('world: ~p', [:ok]) - end) =~ "\[info\] rewritten" - after - assert Logger.remove_translator({CustomTranslator, :t}) - end - test "add_backend/1 and remove_backend/1" do assert :ok = Logger.remove_backend(:console) assert Application.get_env(:logger, :backends) == [] diff --git a/lib/logger/test/test_helper.exs b/lib/logger/test/test_helper.exs index 13ecb4eb2..1ce124b16 100644 --- a/lib/logger/test/test_helper.exs +++ b/lib/logger/test/test_helper.exs @@ -1,5 +1,7 @@ Logger.configure_backend(:console, colors: [enabled: false]) -ExUnit.start() + +exclude = if Process.whereis(:logger), do: [:error_logger], else: [:logger] +ExUnit.start(exclude: exclude) defmodule Logger.Case do use ExUnit.CaseTemplate |