defmodule Timber.Integrations.ErrorLogger do @moduledoc """ Handles error reports from the `:error_logger` application. Timber can automatically log the exceptions that occur in your application as exception events with all the necessary metadata by registering as an `:error_logger` handler. To activate Timber's error logging system, you need to add a few configuration lines and add the `ErrorLogger` handler during application start: ``` # Enable Timber's error capturing system config :timber, :capture_errors, true # Disable Elixir's default error capturing system config :logger, :handle_otp_reports, false ``` ``` def start(_type, _opts) do children = [ supervisor(MyApp.Repo, []), supervisor(MyAppWeb.Endpoint, []) ] opts = [strategy: :one_for_one, name: MyApp.Supervisor] :ok = :error_logger.add_report_handler(Timber.Integrations.ErrorLogger) Supervisor.start_link(children, opts) end ``` Users should be aware that report handlers can be added multiple times, which can result in duplicated logs. This concern is most relevant to umbrella applications or applications with multiple entry-points. To solve this, the handler should be added only at the primary application entry-point. If that is not feasible, the other solution is to check if the handler exists before adding it. Example: ``` if !(Timber.Integrations.ErrorLogger in :gen_event.which_handlers(:error_logger)) do :ok = :error_logger.add_report_handler(Timber.Integrations.ErrorLogger) end ``` ## Elixir Logger's OTP Report Handler The `Logger` application (which is distributed with Elixir) has an OTP report handler which logs errors and will activate it by default. However, the logs it writes only contain textual information without any metadata. Keeping this handler active will cause duplicate errors to be reported to the log, which is why we recommend disabling it using the following configuration option: ``` config :logger, :handle_otp_reports, false ``` However, the OTP report handler handles additional report types as well. If you find that you would like these reports to be logged, just be aware that every exception will be displayed twice in the log. This module also consolidates many error reports into a single line that by default would be logged across multiple lines. Since the OTP report handler does not add the requisite metadata, Timber's console will not identify the errors it logs as exception events when you search. ## Elixir Logger's SASL Report Handler The Elixir `Logger` application also comes with a SASL (System Architecture Support Libraries) report handler. Timber does not currently handle these reports, so activating the standard handler will not cause duplicate logs. ## :error_logger Output When Timber's error capturing system is activated, it will also disable `:error_logger`'s `tty` output. In most cases, this is what you want, otherwise, otherwise it will print out reports to the `tty` in a plain text (and rather ugly) format. If you do not want the `tty` output to be disabled, you can keep it on using the following config: ``` config :timber, :disable_kernel_error_tty, false ``` """ @behaviour :gen_event alias Timber.Events.ErrorEvent @doc false def init(opts \\ []) do # As this is a :gen_event module, there is no built-in back-pressure mechanism. # To avoid holding too many messages, the process will keep up to a default of # 300 messages. This level is under the `:max_count` key in the state. # Once this level is reached, it will drop messages until it # is holding 75% of the maximum (225 by default). This level is under the # `:keep_count` key in the state. Once messages have been dropped, # it will process 10% of the maximum messages (the next 30 by default) # to avoid dropping too many consecutive messages before checking the message # count again. The number of messages to process during this is tracked under the # `:skip_count` key in the state. # The pid for the `Logger` process is also stored in state so messages can be # sent from this process to a pid instead of a named process. This is to avoid # crashing when sending messages to a named process. max_message_count = Keyword.get(opts, :max_message_count, 300) state = %{ logger: Process.whereis(Logger), skip_count: 0, max_count: max_message_count, keep_count: trunc(max_message_count * 0.75) } {:ok, state} end @doc false # Ignores log events from other nodes def handle_event({_, gl, _}, state) when node(gl) != node() do {:ok, state} end def handle_event(event, state) do state = check_threshold(state) log_event(event, state) {:ok, state} end def get_metadata({_format, [_pid, {error, stacktrace}]}, :error) do case handle_error_info({error, stacktrace}) do {:ok, event} -> Timber.Event.to_metadata(event) {:error, _} -> [] end end def get_metadata({_format, [_pid, _last_message, _state, {error, stacktrace}]}, :error) when is_list(stacktrace) do case handle_error_info({error, stacktrace}) do {:ok, event} -> Timber.Event.to_metadata(event) {:error, _} -> [] end end def get_metadata({_format, [_pid, _last_message, _state, reason]}, :error) do case handle_error_info({reason, []}) do {:ok, event} -> Timber.Event.to_metadata(event) {:error, _} -> [] end end def get_metadata({_format, [_, _, _, {error, stacktrace}]}, :error) do case handle_error_info({error, stacktrace}) do {:ok, event} -> Timber.Event.to_metadata(event) {:error, _} -> [] end end def get_metadata({_format, [_, _, _, error]}, :error) do case handle_error_info({error, []}) do {:ok, event} -> Timber.Event.to_metadata(event) {:error, _} -> [] end end def get_metadata({_format, [_pid, _message, _pid2, {error, stack}, _pid3, _stack2]}, :error) do case handle_error_info({error, stack}) do {:ok, event} -> Timber.Event.to_metadata(event) {:error, _} -> [] end end def get_metadata({_format, [_pid, _pid2, _function, _args, {error, stacktrace}]}, :error) do case handle_error_info({error, stacktrace}) do {:ok, event} -> Timber.Event.to_metadata(event) {:error, _} -> [] end end def get_metadata({_format, [_module, _pid, reason]}, :warn) do case handle_error_info({reason, []}) do {:ok, event} -> Timber.Event.to_metadata(event) {:error, _} -> [] end end def get_metadata(_data, _level) do [] end defp log_event({:error, gl, {pid, format, data}}, state), do: do_log_event(:error, :format, gl, pid, {format, data}, state) defp log_event({:error_report, gl, {pid, :std_error, format}}, state), do: do_log_event(:error, :report, gl, pid, {:std_error, format}, state) defp log_event({:warning_msg, gl, {pid, format, data}}, state), do: do_log_event(:warn, :format, gl, pid, {format, data}, state) defp log_event({:warning_report, gl, {pid, :std_warning, format}}, state), do: do_log_event(:warn, :report, gl, pid, {:std_warning, format}, state) defp log_event({:info_msg, gl, {pid, format, data}}, state), do: do_log_event(:info, :format, gl, pid, {format, data}, state) defp log_event({:info_report, gl, {pid, :std_info, format}}, state), do: do_log_event(:info, :report, gl, pid, {:std_info, format}, state) defp log_event(_, _state), do: :ok defp do_log_event(level, kind, gl, pid, data, state) do %{ mode: mode, level: min_level, utc_log: utc_log?, truncate: truncate, translators: translators } = 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 meta = get_metadata(data, level) |> Keyword.put(:pid, pid) message = Logger.Utils.truncate(message, truncate) event = {Logger, message, Logger.Utils.timestamp(utc_log?), meta} :gen_event.notify(state.logger, {level, gl, event}) end end def handle_info(_, state) do {:ok, state} end def handle_call(_, state) do {:ok, :ok, state} end def code_change(_old, state, _extra) do {:ok, state} end def terminate(_reason, _state) do :ok end defp handle_error_info({{%{__exception__: true} = error, stacktrace}, _stack}) when is_list(stacktrace) do {:ok, build_error_event(error, stacktrace, :error)} end defp handle_error_info({%{__exception__: true} = error, stacktrace}) when is_list(stacktrace) do {:ok, build_error_event(error, stacktrace, :error)} end defp handle_error_info({{type, reason}, stacktrace}) when is_list(stacktrace) do {:ok, build_error_event(reason, stacktrace, type)} end defp handle_error_info({error, stacktrace}) when is_list(stacktrace) do {:ok, build_error_event(error, stacktrace, :error)} end defp handle_error_info(_) do {:error, :no_info} end defp build_error_event(%{__exception__: true} = error, stacktrace, _type) do e = ErrorEvent.from_exception(error) |> ErrorEvent.add_backtrace(stacktrace) # %{e | type: to_string(type)} e end defp build_error_event(error, stacktrace, _type) do e = ErlangError.normalize(error, stacktrace) |> ErrorEvent.from_exception() |> ErrorEvent.add_backtrace(stacktrace) # %{e | type: to_string(type)} e end defp check_threshold(%{skip_count: 0, keep_count: keep_count, max_count: max_count} = state) do current_count = message_count() if current_count >= max_count do drop_count = current_count - keep_count discard_messages(drop_count) message = "Timber.ErrorLogger has discarded #{drop_count} of #{current_count} messages in " <> "its inbox. The maximum number of messages is #{max_count}. " <> "The current number of messages is now #{keep_count}" %{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}) # Send 10% of the maximum messages before checking message count again %{state | skip_count: trunc(max_count * 0.1)} else state end end defp check_threshold(%{skip_count: skip_count} = state) do %{state | skip_count: skip_count - 1} end defp message_count() do {:message_queue_len, count} = Process.info(self(), :message_queue_len) count end defp discard_messages(0) do :ok end defp discard_messages(count) do receive do {:notify, _event} -> discard_messages(count - 1) after 0 -> :ok end end # Elixir 1.6 stopped using :io_lib.format/2 in favor of :io_lib.build_text/1 # This also included an internal replacement of Logger.Utils.inspect/3 # with Logger.Utils.scan_inspect/3 defmacrop build_text(format, args, truncate) do if(Version.match?(System.version(), "~> 1.6")) do quote do msg = Logger.Utils.scan_inspect(unquote(format), unquote(args), unquote(truncate)) |> :io_lib.build_text() {:ok, msg} end else quote do {format, args} = Logger.Utils.inspect(unquote(format), unquote(args), unquote(truncate)) {:ok, :io_lib.format(format, args)} end 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 build_text(format, args, truncate) end defp translate([], _min_level, _level, :report, {_type, data}, _truncate) do {:ok, Kernel.inspect(data)} end end