lager is stuck on lager:do_log_impl

[ophirzk]

Hi,

I am using RabbitMQ which uses lager version 3.9.1 and after a few hours of normal logging, it gets stuck.
I traced it and got the stack trace which I added below.
lager:do_log_impl doesn't return and it looks like gen_event:notify() is stuck.

Can you please assist?

18:35:26:521621 (<11678.17484.10>) spawned <14514.95.0> {erts_internal,dist_spawn_init,[{erpc,execute_call,4}]}
18:35:26:521623 (<11678.17484.10>) call lager:log/5
18:35:26:521624 (<11678.17484.10>) call lager:dispatch_log/7
18:35:26:521625 (<11678.17484.10>) call lager:do_log/10
18:35:26:521626 (<11678.17484.10>) call lager:do_log_impl/10
18:35:26:521627 (<11678.17484.10>) call lager:'-do_log/10-fun-0-'/3
18:35:26:521628 (<11678.17484.10>) call lager:safe_format_chop/3
18:35:26:521629 (<11678.17484.10>) call lager:safe_format/4
18:35:26:521630 (<11678.17484.10>) returned from lager:safe_format/4 -> "aaa"
18:35:26:521631 (<11678.17484.10>) returned from lager:safe_format_chop/3 -> "aaa"
18:35:26:521632 (<11678.17484.10>) returned from lager:'-do_log/10-fun-0-'/3 -> "aaa"
18:35:27:646509 (<11678.17485.10>) spawned <11678.390.0> {mnesia_controller,dump_and_reply,[<11678.390.0>,{dump_log,time_threshold,undefined,dump_log}]}
18:35:27:646510 (<11678.17485.10>) getting_linked <11678.390.0>
18:35:27:646512 (<11678.17485.10>) unlink <11678.390.0>
18:35:27:646513 (<11678.17485.10>) exit normal
18:35:27:646514 (<11678.17485.10>) out_exited 0

[Vagabond]

What is your lager config, are you logging to a remote node somehow?

[ophirzk]

1 local node, called rabbit@localhost.
I do not try to log to a remote node, everything is local.
Lager env:

[{error_logger_hwm_original,1000},
 {crash_log_rotator,lager_rotator_default},
 {error_logger_format_raw,true},
 {colors,
     [{debug,"\e[0;38m"},
      {info,"\e[1;37m"},
      {notice,"\e[1;36m"},
      {warning,"\e[1;33m"},
      {error,"\e[1;31m"},
      {critical,"\e[1;35m"},
      {alert,"\e[1;44m"},
      {emergency,"\e[1;41m"}]},
 {crash_log_date,"$D0"},
 {colored,false},
 {extra_sinks,
     [{error_logger_lager_event,
          [{handlers,[{lager_forwarder_backend,[lager_event,info]}]},
           {rabbit_handlers,[{lager_forwarder_backend,[lager_event,info]}]}]},
      {rabbit_log_lager_event,
          [{handlers,[{lager_forwarder_backend,[lager_event,info]}]},
           {rabbit_handlers,[{lager_forwarder_backend,[lager_event,info]}]}]},
      {rabbit_log_channel_lager_event,
          [{handlers,[{lager_forwarder_backend,[lager_event,info]}]},
           {rabbit_handlers,[{lager_forwarder_backend,[lager_event,info]}]}]},
      {rabbit_log_connection_lager_event,
          [{handlers,[{lager_forwarder_backend,[lager_event,info]}]},
           {rabbit_handlers,[{lager_forwarder_backend,[lager_event,info]}]}]},
      {rabbit_log_feature_flags_lager_event,
          [{handlers,[{lager_forwarder_backend,[lager_event,info]}]},
           {rabbit_handlers,[{lager_forwarder_backend,[lager_event,info]}]}]},
      {rabbit_log_federation_lager_event,
          [{handlers,[{lager_forwarder_backend,[lager_event,info]}]},
           {rabbit_handlers,[{lager_forwarder_backend,[lager_event,info]}]}]},
      {rabbit_log_ldap_lager_event,
          [{handlers,[{lager_forwarder_backend,[lager_event,info]}]},
           {rabbit_handlers,[{lager_forwarder_backend,[lager_event,info]}]}]},
      {rabbit_log_mirroring_lager_event,
          [{handlers,[{lager_forwarder_backend,[lager_event,info]}]},
           {rabbit_handlers,[{lager_forwarder_backend,[lager_event,info]}]}]},
      {rabbit_log_prelaunch_lager_event,
          [{handlers,[{lager_forwarder_backend,[lager_event,info]}]},
           {rabbit_handlers,[{lager_forwarder_backend,[lager_event,info]}]}]},
      {rabbit_log_queue_lager_event,
          [{handlers,[{lager_forwarder_backend,[lager_event,info]}]},
           {rabbit_handlers,[{lager_forwarder_backend,[lager_event,info]}]}]},
      {rabbit_log_ra_lager_event,
          [{handlers,[{lager_forwarder_backend,[lager_event,info]}]},
           {rabbit_handlers,[{lager_forwarder_backend,[lager_event,info]}]}]},
      {rabbit_log_shovel_lager_event,
          [{handlers,[{lager_forwarder_backend,[lager_event,info]}]},
           {rabbit_handlers,[{lager_forwarder_backend,[lager_event,info]}]}]},
      {rabbit_log_upgrade_lager_event,
          [{handlers,
               [{lager_exchange_backend,
                    [{formatter_config,
                         [date," ",time," ",color,"[",severity,"] ",
                          {pid,[]},
                          " ",message,"\n"]},
                     {level,info}]},
                {lager_file_backend,
                    [{count,40},
                     {date,"$D0"},
                     {file,
                         "c:/sh/rmqcluster_service/log/rabbit@localhost_upgrade.log"},
                     {formatter_config,
                         [date," ",time," [",severity,"] ",
                          {pid,[]},
                          " ",message,"\r\n"]},
                     {level,info},
                     {size,268435456}]}]},
           {rabbit_handlers,
               [{lager_exchange_backend,
                    [{formatter_config,
                         [date," ",time," ",color,"[",severity,"] ",
                          {pid,[]},
                          " ",message,"\n"]},
                     {level,info}]},
                {lager_file_backend,
                    [{count,40},
                     {date,"$D0"},
                     {file,
                         "c:/sh/rmqcluster_service/log/rabbit@localhost_upgrade.log"},
                     {formatter_config,
                         [date," ",time," [",severity,"] ",
                          {pid,[]},
                          " ",message,"\r\n"]},
                     {level,info},
                     {size,268435456}]}]}]}]},
 {handlers,
     [{lager_file_backend,
          [{count,40},
           {date,"$D0"},
           {file,"L1244-DV1.rabbit@localhost.log"},
           {formatter_config,
               [date," ",time," [",severity,"] ",{pid,[]}," ",message,"\r\n"]},
           {level,debug},
           {size,268435456}]},
      {lager_exchange_backend,
          [{formatter_config,
               [date," ",time," ",color,"[",severity,"] ",
                {pid,[]},
                " ",message,"\n"]},
           {level,debug}]}]},
 {rabbit_handlers,
     [{lager_file_backend,
          [{count,40},
           {date,"$D0"},
           {file,"L1244-DV1.rabbit@localhost.log"},
           {formatter_config,
               [date," ",time," [",severity,"] ",{pid,[]}," ",message,"\r\n"]},
           {level,debug},
           {size,268435456}]},
      {lager_exchange_backend,
          [{formatter_config,
               [date," ",time," ",color,"[",severity,"] ",
                {pid,[]},
                " ",message,"\n"]},
           {level,debug}]}]},
 {crash_log_count,40},
 {async_threshold,20},
 {crash_log_msg_size,65536},
 {error_logger_hwm,100000},
 {async_threshold_window,5},
 {crash_log,"log/crash.log"},
 {crash_log_size,268435456},
 {error_logger_redirect,true},
 {log_root,"c:/sh/rmqcluster_service/rmqcluster_service/log"}]

I am using lager through RabbitMQ so my RabbitMQ log config sections is the following:

		{log, [
			{file, [
				{file, "L1244-DV1.rabbit@localhost.log"},
				{date, "$D0"},
				{size, 268435456},
				{count, 40},
				{formatter_config, [date," ",time," [",severity,"] ",{pid,[]}," ",message,"\r\n"]}]},

[Vagabond]

What is the lager_exchange_backend?I'm not familar with it but it appears to do something like publish a message to AMQP? I bet that's blocking somehow?

[Vagabond]

Also are you on windows?

[ophirzk]

Yes, runs on Windows.
Maybe it publishes to the log exchange of RabbitMQ, amq.rabbitmq.log.
Where did you see that it publishes something?
Do you think lager_exchange_backend is the problem? lager didn't write to the file as well.
What do you think might be going on here?

[ophirzk]

The issue is in the lager_event, killing it fixed the issue.
It looks very close to the following issue:
https://bugs.erlang.org/browse/ERL-710

[Vagabond]

Yes, a backend backing up will cause issues for other backends. Your lager config is very large and strange, I don't know why you'd configure it like this and I suggest you talk to the rabbitmq team if this is something they did.

[ophirzk]

@Vagabond
Why is it large and strange? the config that rabbit passes is the following:

{log, [
			{file, [
				{file, "L1244-DV1.rabbit@localhost.log"},
				{date, "$D0"},
				{size, 268435456},
				{count, 40},
				{formatter_config, [date," ",time," [",severity,"] ",{pid,[]}," ",message,"\r\n"]}]},

[Vagabond]

You have a ton of sinks configured and you're using several instances of lager_exchange_backend which is not something I know about and cannot support.