Crash Reports are seen on Console but not being logged to Log File

Question

I am seeing Elixir Crash Logs on Console but they are not being logged to the log file.

I have tried setting the config:

config :logger,
  handle_otp_reports: true,
  handle_sasl_reports: true,
  compile_time_purge_level: :info,
  backends: [:console, LogToLager],
  level: :info,
  utc_log: true

I expect the crash reports to go to the log file as well along with console. I am using lager to log. Here's lagers config:

config :lager,
  level: :info,
  async_threshold: 500,
  async_threshold_window: 50,
  log_root: '/log/path',
  handlers: [ lager_console_backend: :info ],
  extra_sinks: [
    dispatcher_lager_event: [
      handlers: [
        lager_file_backend: [
          file: String.to_charlist("beam@" <> System.get_env("COMPUTERNAME") <> ".log"),
          level: :info,
          size: 100 * 1024 * 1024,
          date: '$D0',
          count: 10
        ]
      ]
    ]
  ]

Answer 1

Given lager config has extra_sinks specified with a custom dispatcher_lager_event sink name, I am assuming LogToLager uses dispatcher_lager_event to dispatch lager logs.

That said, I've replicated your setup with a custom lager backend module, inspired by LoggerLagerBackend module from logger_lager_backend package:

defmodule MyLagerBackend do
  @behaviour :gen_event

  def init(__MODULE__), do: {:ok, nil}
  def handle_call({:configure, _opts}, state), do: {:ok, :ok, state}

  def handle_event({:error, _groupleader, {Logger, message, _timestamp, metadata}}, state) do
    :lager.dispatch_log(:dispatcher_lager_event, :error, metadata, '~ts', [message], 4096, :safe)
    {:ok, state}
  end

  def handle_event({level, _groupleader, {Logger, message, _timestamp, metadata}}, state) do
    :lager.dispatch_log(:lager_event, to_lager_level(level), metadata, '~ts', [message], 4096, :safe)
    {:ok, state}
  end

  def handle_event(:flush, state), do: {:ok, state}

  # gen_event boilerplate

  def handle_info(_msg, state), do: {:ok, state}
  def terminate(_reason, _state), do: :ok
  def code_change(_old, state, _extra), do: {:ok, state}

  # Private functions

  defp to_lager_level(:warn), do: :warning
  defp to_lager_level(level), do: level
end

Having the following contents in config/config.exs:

use Mix.Config

config :logger,
  handle_otp_reports: true,
  handle_sasl_reports: true,
  compile_time_purge_level: :info,
  backends: [MyLagerBackend],
  level: :info,
  utc_log: true

config :lager,
  handlers: [
    lager_console_backend: [level: :info]
  ],
  extra_sinks: [
    dispatcher_lager_event: [
      handlers: [
        lager_file_backend: [
          file: "my_custom_file.log",
          level: :info,
          size: 100 * 1024 * 1024,
          date: '$D0',
          count: 10
        ]
      ]
    ]
  ]

I open iex and run Task.async(fn -> 1 / 0 end), which produces a crash report in the console:

$ iex -S mix
Erlang/OTP 22 [erts-10.4.4] [source] [64-bit] [smp:12:12] [ds:12:12:10] [async-threads:1] [hipe] [dtrace]

...a bunch of auxiliary messages removed for brevity...

Interactive Elixir (1.9.0) - press Ctrl+C to exit (type h() ENTER for help)
iex(1)> Task.async(fn -> 1 / 0 end)
11:11:52.580 [error] ** Task <0.226.0> terminating
** Started from <0.224.0>
** When function  == #Fun<erl_eval.21.91303403>
**      arguments == []
** Reason for termination ==
** {badarith,[{erlang,'/',[1,0],[]},{'Elixir.Task.Supervised',invoke_mfa,2,[{file,"lib/task/supervised.ex"},{line,90}]},{'Elixir.Task.Supervised',reply,5,[{file,"lib/task/supervised.ex"},{line,35}]},{proc_lib,init_p_do_apply,3,[{file,"proc_lib.erl"},{line,249}]}]}
%Task{
  owner: #PID<0.224.0>,
  pid: #PID<0.226.0>,
  ref: #Reference<0.265415656.4091019275.172412>
}
iex(2)> 11:11:52.615 [error] CRASH REPORT Process <0.226.0> with 1 neighbours crashed with reason: bad arithmetic expression in erlang:'/'(1, 0)
** (EXIT from #PID<0.224.0>) shell process exited with reason: an exception was raised:
    ** (ArithmeticError) bad argument in arithmetic expression
        :erlang./(1, 0)
        (elixir) lib/task/supervised.ex:90: Task.Supervised.invoke_mfa/2
        (elixir) lib/task/supervised.ex:35: Task.Supervised.reply/5
        (stdlib) proc_lib.erl:249: :proc_lib.init_p_do_apply/3

Interactive Elixir (1.9.0) - press Ctrl+C to exit (type h() ENTER for help)
iex(1)>

...as well in my my_custom_file.log:

$ cat my_custom_file.log
2019-07-11 11:11:52.615 [error] <0.226.0> Task #PID<0.226.0> started from #PID<0.224.0> terminating
** (ArithmeticError) bad argument in arithmetic expression
    :erlang./(1, 0)
    (elixir) lib/task/supervised.ex:90: Task.Supervised.invoke_mfa/2
    (elixir) lib/task/supervised.ex:35: Task.Supervised.reply/5
    (stdlib) proc_lib.erl:249: :proc_lib.init_p_do_apply/3
Function: #Function<21.91303403/0 in :erl_eval.expr/5>
    Args: []
2019-07-11 11:11:52.623 [error] <0.226.0>@proc_lib:crash_report/4:508 Process #PID<0.226.0> terminating
** (ArithmeticError) bad argument in arithmetic expression
    :erlang./(1, 0)
    (elixir) lib/task/supervised.ex:90: Task.Supervised.invoke_mfa/2
    (elixir) lib/task/supervised.ex:35: Task.Supervised.reply/5
    (stdlib) proc_lib.erl:249: :proc_lib.init_p_do_apply/3
Initial Call: anonymous fn/0 in :erl_eval.expr/5
Ancestors: [#PID<0.224.0>, #PID<0.81.0>]
Neighbours:
    #PID<0.224.0>
        Initial Call: IEx.Evaluator.init/4
        Current Call: IEx.Evaluator.loop/1
        Ancestors: [#PID<0.81.0>]
$