Unexpected error_logger event

Questions / Help
, ,
1

I’m using lager to log to file from my Elixir release (I need the log rotation that lager provides). Some error messages are printing unhelpfully though:

2020-11-02 17:27:19.740 [warning] <0.865.0> Unexpected error_logger event {error_msg,<0.879.0>,{<0.884.0>,[42,42,32,84,97,115,107,32,126,112,32,116,101,114,109,105,110,97,116,105,110,103,126,110,42,42,32,83,116,97,114,116,101,100,32,102,114,111,109,32,126,112,126,110,42,42,32,87,104,101,110,32,102,117,110,99,116,105,111,110,32,32,61,61,32,126,112,126,110,42,42,32,32,32,32,32,32,97,114,103,117,109,101,110,116,115,32,61,61,32,126,112,126,110,42,42,32,82,101,97,115,111,110,32,102,111,114,32,116,101,114,109,105,110,97,116,105,111,110,32,61,61,32,126,110,42,42,32,126,112,126,110],[<0.884.0>,<0.882.0>,#Fun<Elixir.NetCmds.Supervisor.0.118374414>,[],{{badmatch,{error,badarg}},[{'Elixir.NetCmds.Server',loop_acceptor,1,[{file,[108,105,98,47,110,101,116,95,99,109,100,115,47,115,101,114,118,101,114,46,101,120]},{line,24}]},{'Elixir.Task.Supervised',invoke_mfa,2,[{file,[108,105,98,47,116,97,115,107,47,115,117,112,101,114,118,105,115,101,100,46,101,120]},{line,90}]},{proc_lib,init_p_do_apply,3,[{file,[112,114,111,99,95,108,105,98,46,101,114,108]},{line,249}]}]}]}}
2020-11-02 17:27:19.740 [info] <0.1645.0>@Elixir.NetCmds.Server:accept/1:17 Accepting connections on port 3900
2020-11-02 17:27:19.744 [error] <0.884.0>@Elixir.NetCmds.Server:loop_acceptor:24 CRASH REPORT Process <0.884.0> with 0 neighbours crashed with reason: no match of right hand value {error,badarg} in 'Elixir.NetCmds.Server':loop_acceptor/1 line 24
2020-11-02 17:27:19.748 [error] <0.882.0>@Elixir.NetCmds.Server:loop_acceptor:24 Supervisor {<0.882.0>,'Elixir.NetCmds.Supervisor'} had child 'Elixir.Task' started with 'Elixir.Task':start_link(#Fun<Elixir.NetCmds.Supervisor.0.118374414>) at <0.884.0> exit with reason no match of right hand value {error,badarg} in 'Elixir.NetCmds.Server':loop_acceptor/1 line 24 in context child_terminated

(the first line is the problematic one, I put the others in for context)

Those lists are clearly erlang charlists (you can put them in iex and get a string printed). I’m not clear on how the various pieces of logging interact - Elixir logger, erlang logger and Lager. I presume this is an incompatibility between a couple of them?

2

Check if you are on newest lager as I remember that there were some problems about integration with logger.

About other things, let’s first tackle log rotation - there are few possible solutions to that:

  • use external rotator
  • log to external service, that will handle rotation for you (journald or syslog for example)
  • use logger_std_h directly, so you will be able to have rotation without lager

About interaction between all of these:

  • Elixir’s Logger is currently set of macros that will dispatch Erlang’s logger events with compatibility handler used for supporting “old” Elixir’s backends. So all messages sent via Logger are also handled by Erlang’s logger handler, because these are the same in reality (with some compatibility on top)
  • lager is attaching itself to error_logger, which is handler for Erlang’s logger messages with level error or higher. This is needed for compatibility reasons. However lager internally uses completely different set of processes, so the communication between Erlang’s logger and lager is partial and only in one way (Erlang -> Lager, but not other way around). At least for the time of being.
2 Likes
3

Thanks for your answer. Based on that and some reading of documentation and code, this is how I understand the situation:

  • Elixir provides the Logger API. This ends up being a wrapper around calls info erlang’s central :logger (http://erlang.org/doc/man/logger.html).
  • All log messages go through Erlangs Logger. Some will come from our Elixir code, some will come from Erlang.
  • Log messages then are passed to a series of handlers that are registered with :logger. One of these is provided by Elixir, which which you can then register backends as described in the Elixir logger docs.

Lager doesn’t fit hugely well into the above setup, because (if I understand the history correctly) it was previously a replacement for the whole infrastructure. We’re using just a piece of it, and it isn’t quite compatible in the way we’d like.

Your suggestion is that instead I set up another handler, using logger_std_h, which I can configure for log rotation? External options for log rotation are unfortunately not possible.

4

I’m on the newest lager (3.8.2) yet i still get the unhelpfully printed logs, as in the first log-line in OP. How can i prevent these logs from appearing?

Here’s a sample Unexpected error_logger event:

08:03:52.138 [error] CRASH REPORT Process <0.8154.0> with 0 neighbours crashed with reason: #{'__exception__' => true,'__struct__' => 'Elixir.DBConnection.ConnectionError',message => <<"tcp recv: closed">>,reason => error,severity => error} in 'Elixir.Ecto.Adapters.SQL':raise_sql_call_error/1 line 749                                                                                                          08:03:52.148 [error] Supervisor 'Elixir.MyApp.ProcessorSupervisor' had child undefined started with 'Elixir.MyApp.Processor':start_link(<<"357796106095146">>) at <0.8154.0> exit with reason #{'__exception__' => true,'__struct__' => 'Elixir.DBConnection.ConnectionError',message => <<"tcp recv: closed">>,reason => error,severity => error} in 'Elixir.Ecto.Adapters.SQL':raise_sql_call_error/1 line 749 in context child_terminated                                                                                                                                                                08:03:52.148 [error] CRASH REPORT Process <0.8160.0> with 0 neighbours crashed with reason: #{'__exception__' => true,'__struct__' => 'Elixir.DBConnection.ConnectionError',message => <<"tcp recv: closed">
>,reason => error,severity => error} in 'Elixir.Ecto.Adapters.SQL':raise_sql_call_error/1 line 749
08:03:52.153 [warning] Unexpected error_logger event {error_msg,<0.4211.0>,{<0.8159.0>,[42,42,32,84,97,115,107,32,126,112,32,116,101,114,109,105,110,97,116,105,110,103,126,110,42,42,32,83,116,97,114,116,101,100,32,102,114,111,109,32,126,112,126,110,42,42,32,87,104,101,110,32,102,117,110,99,116,105,111,110,32,32,61,61,32,126,112,126,110,42,42,32,32,32,32,32,32,97,114,103,117,109,101,110,116,115,32,61,61,32,126,112,126,110,42,42,32,82,101,97,115,111,110,32,102,111,114,32,116,101,114,109,105,110,97,116,105,111,110,32,61,61,32,126,110,42,42,32,126,112,126,110],[<0.4669.0>,<0.8159.0>,fun erlang:apply/2,[#Fun<E
lixir.Kafka.MessageHandler.2.107032

These Unexpected error_logger event logs (seem to) always contain information that is already present (in one of the logs preceding it). If i print the example Unexpected error_logger event from above codeblock:

iex> IO.puts <<42,42,32,84,97,115,107,32,126,112,32,116,101,114,109,105,110,97,116,105,110,103,126,110,42,42,32,83,116,97,114,116,101,100,32,102,114,111,109,32,126,112,126,110,42,42,32,87,104,101,110,32,102,117,110,99,116,105,111,110,32,32,61,61,32,126,112,126,110,42,42,32,32,32,32,32,32,97,114,103,117,109,101,110,116,115,32,61,61,32,126,112,126,110,42,42,32,82,101,97,115,111,110,32,102,111,114,32,116,101,114,109,105,110,97,116,105,111,110,32,61,61,32,126,110,42,42,32,126,112,126,110>>

** Task ~p terminating~n** Started from ~p~n** When function  == ~p~n**      arguments == ~p~n** Reason for termination == ~n** ~p~n

Using

elixir 1.11.2-otp-23
erlang 23.1.5

but same also happens on

elixir 1.13
erlang 24