No crash reports in default Logger configuration

legoscia

I just spent some time chasing down a bug that would have been easier to find if I had seen a certain crash report - but it seems like crash reports are not being shown in Elixir by default?

For example, when a process started with proc_lib:spawn crashes in Erlang, a crash report is printed:

$ erl
Erlang/OTP 21 [erts-10.0] [source] [64-bit] [smp:8:8] [ds:8:8:10] [async-threads:1] [hipe]

Eshell V10.0  (abort with ^G)
1> proc_lib:spawn(fun() -> error(pang) end).
<0.78.0>
2> =CRASH REPORT==== 14-May-2019::10:00:59.621479 ===
  crasher:
    initial call: erl_eval:'-expr/5-fun-3-'/0
    pid: <0.78.0>
    registered_name: []
    exception error: pang
      in function  shell:apply_fun/3 (shell.erl, line 907)
    ancestors: [<0.76.0>]
    message_queue_len: 0
    messages: []
    links: []
    dictionary: []
    trap_exit: false
    status: running
    heap_size: 376
    stack_size: 27
    reductions: 207
  neighbours:

But not when doing the same thing in Elixir:

$ iex
Erlang/OTP 21 [erts-10.0] [source] [64-bit] [smp:8:8] [ds:8:8:10] [async-threads:1] [hipe]

Interactive Elixir (1.7.3) - press Ctrl+C to exit (type h() ENTER for help)
iex(1)> :proc_lib.spawn(fn -> :erlang.error(:pang) end)
#PID<0.103.0>

(it’s better to use a plain spawn than proc_lib:spawn in code like this, but this is an easy way to provoke a crash report - and this is how the code I was debugging was written. With a plain spawn, we get an error report instead of a crash report, and it’s displayed clearly in both Erlang and Elixir.)

My questions:

Why does this happen?
Is this a bug or a feature? It seems to me like dropping error messages like this is incorrect, but perhaps I’m missing something.
Should I change my Logger configuration somehow?

8 comments

#logger

1 3098 8

2020-04-22 20:35:51 UTC

Showing Posts 1 to 8

Show Best Posts
Show All (oldest first)
Show All (newest first)

dom

Have you been able to find an answer? Enabling :handle_sasl_reports in Logger config helps, but my understanding on OTP-21+ is that error reports go directly to the logger without involving SASL, so I don’t get why the flag would be needed.

It’s a problem in dev because I need to choose between enabling the flag, which adds a ton of log spam due to SASL progress reports, or not enabling it, in which case processes die completely silently…

Edit: Perhaps it’s because Elixir calls the old :error_logger:

https://github.com/elixir-lang/elixir/blob/1fa111de78036fbc2ec0300d8444313e5dd3d060/lib/elixir/lib/dynamic_supervisor.ex#L990

So the error reports go through SASL, unlike the Erlang ones, which use the new logger directly:

https://github.com/erlang/otp/blob/master/lib/stdlib/src/supervisor.erl#L40

Post #1

lud

I can’t have any SASL reports in the console, is is very hard to understand why my whole application crashes when I kill some processes under load to see how the app would recover its state.

I have :sasl before :logger in extra applications (mix.exs), I have the both options (handle_sasl_reports and handle_otp_reports to true) in config/dev.exs … but nothing : no info when supervisors start, progress, or crash.

So, as the topic title says, there is no crash reports in the default configuration. But is there any configuration to write to have them back ?

Post #2

hauleth

Which version of Elixir do you use? Maybe I will be able to pinpoint the problem.

Post #3

lud

Elixir 1.10.2 and Erlang/OTP 22 [erts-10.6.4]

config :logger, level: :debug
config :logger, :console,
  format: "[$level] $message\n",
  handle_otp_reports: true,
  handle_sasl_reports: true

  def application do
    [
      mod: {Jwp.Application, []},
      extra_applications: [:sasl, :logger, :runtime_tools]
    ]
  end

Also I run Phoenix 1.5.0-rc.0, maybe there is a config override from it ?

Post #4

hauleth

No, it cannot override logger configuration.

First of all, starting sasl and runtime_tools should not be needed.

Second - Your problem is that you configure :handle_otp_reports and :handle_sasl_reports on :console handler while handlers just do not care about it. Instead use:

config :logger,
  handle_sasl_reports: true

No need for other options are defined to their default values so you can just ignore setting them.

Post #5

lud

runtime_tools is added by mix phx.new, and adding sasl is recommended by many sources I read. Also that as of erlang 21 handle_otp_reports must be set although true is the default (which makes no sens). But all of this is wrong actually (at least on my ex/erl versions), and you are right.

This works well then, if anyone else wants to keep custom console format:

config :logger, 
  console: [format: "[$level] $message\n"],
  handle_sasl_reports: true

I forgot about the config format, and was setting all those options only for the console display options.

Thank you ! (Oh and I found my error, I have to use a rest-for-one strategy, so thanks again)

Post #6

hauleth

You still could use:

config :logger, :console,
  format: "[$level] $message\n"

As config will be automatically merged for 1 level.

as of erlang 21 handle_otp_reports must be set although true is the default

This is not true, you need only :handle_sasl_reports as handle_otp_reports: true is default (trust me, I have written Logger for Elixir 1.10+). The only thing is that :handle_sasl_reports will be ignored if :handle_otp_reports is false (which with current implementation is quite problematic, and IMHO setting handle_otp_reports: false should be deprecated).

Post #7

lud

trust me, I have written Logger for Elixir 1.10+

I do. I was saying that i’ve read that it should be always set, but as I have tested it following your advice, it is obvioulsy a no-op to set this (any) option to its default value.

edit: yeah my previous comment was heavily refactored before posting, it was not clear that I was reporting what I found in online resources