lager is stuck on lager:do_log_impl about lager

[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,"[email protected]"},
           {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,"[email protected]"},
           {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, "[email protected]"},
				{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, "[email protected]"},
				{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.