lager
lager copied to clipboard
erlang-lager
lager is stuck on lager:do_log_impl
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
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"]}]},
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?
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?
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
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.
@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"]}]},
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.