From e1c4ed113924be59722452a0ca34084421197a97 Mon Sep 17 00:00:00 2001 From: Andrew Thompson Date: Sat, 2 Feb 2019 16:24:11 -0800 Subject: [PATCH 01/35] Add a `lager_use_logger` parse transform to rewrite lager calls to logger --- src/lager_transform.erl | 185 +++++++++++++++++++++++----------------- 1 file changed, 106 insertions(+), 79 deletions(-) diff --git a/src/lager_transform.erl b/src/lager_transform.erl index 5c2134c8..590fd750 100644 --- a/src/lager_transform.erl +++ b/src/lager_transform.erl @@ -33,10 +33,12 @@ parse_transform(AST, Options) -> Enable = proplists:get_value(lager_print_records_flag, Options, true), Sinks = [lager] ++ proplists:get_value(lager_extra_sinks, Options, []), Functions = proplists:get_value(lager_function_transforms, Options, []), + UseLogger = proplists:get_value(lager_use_logger, Options, false), put(print_records_flag, Enable), put(truncation_size, TruncSize), put(sinks, Sinks), put(functions, lists:keysort(1, Functions)), + put(use_logger, UseLogger), erlang:put(records, []), %% .app file should either be in the outdir, or the same dir as the source file guess_application(proplists:get_value(outdir, Options), hd(AST)), @@ -63,6 +65,7 @@ walk_ast(Acc, [{attribute, _, lager_function_transforms, FromModule }=H|T]) -> walk_ast([H|Acc], T); walk_ast(Acc, [{function, Line, Name, Arity, Clauses}|T]) -> put(function, Name), + put(arity, Arity), walk_ast([{function, Line, Name, Arity, walk_clauses([], Clauses)}|Acc], T); walk_ast(Acc, [{attribute, _, record, {Name, Fields}}=H|T]) -> @@ -140,24 +143,40 @@ do_transform(Line, SinkName, Severity, Arguments0) -> do_transform(Line, SinkName, Severity, Arguments0, safe). do_transform(Line, SinkName, Severity, Arguments0, Safety) -> - SeverityAsInt=lager_util:level_to_num(Severity), - DefaultAttrs0 = {cons, Line, {tuple, Line, [ - {atom, Line, module}, {atom, Line, get(module)}]}, - {cons, Line, {tuple, Line, [ - {atom, Line, function}, {atom, Line, get(function)}]}, - {cons, Line, {tuple, Line, [ - {atom, Line, line}, - {integer, Line, Line}]}, - {cons, Line, {tuple, Line, [ - {atom, Line, pid}, - {call, Line, {atom, Line, pid_to_list}, [ - {call, Line, {atom, Line ,self}, []}]}]}, - {cons, Line, {tuple, Line, [ - {atom, Line, node}, - {call, Line, {atom, Line, node}, []}]}, - %% get the metadata with lager:md(), this will always return a list so we can use it as the tail here - {call, Line, {remote, Line, {atom, Line, lager}, {atom, Line, md}}, []}}}}}}, - %{nil, Line}}}}}}}, + DefaultAttrs0 = case get(use_logger) of + true -> + {cons, Line, {tuple, Line, [ + {atom, Line, pid}, {call, Line, {atom, Line, self}, []}]}, + {cons, Line, {tuple, Line, [ + {atom, Line, gl}, {call, Line, {atom, Line, group_leader}, []}]}, + {cons, Line, {tuple, Line, [ + {atom, Line, time}, {call, {remote, Line, {atom, Line, erlang}, {atom, Line, system_time}}, [{atom, Line, microsecond}]}]}, + {cons, Line, {tuple, Line, [ + {atom, Line, mfa}, {tuple, Line, [{atom, Line, get(module)}, {atom, Line, get(function)}, {atom, Line, get(arity)}]}]}, + {cons, Line, {tuple, Line, [ + {atom, Line, file}, {string, Line, get(filename)}]}, + {cons, Line, {tuple, Line, [ + {atom, Line, line}, {integer, Line, Line}]}, + %% get the metadata with lager:md(), this will always return a list so we can use it as the tail here + {call, Line, {remote, Line, {atom, Line, lager}, {atom, Line, md}}, []}}}}}}}; + false -> + {cons, Line, {tuple, Line, [ + {atom, Line, module}, {atom, Line, get(module)}]}, + {cons, Line, {tuple, Line, [ + {atom, Line, function}, {atom, Line, get(function)}]}, + {cons, Line, {tuple, Line, [ + {atom, Line, line}, + {integer, Line, Line}]}, + {cons, Line, {tuple, Line, [ + {atom, Line, pid}, + {call, Line, {atom, Line, pid_to_list}, [ + {call, Line, {atom, Line ,self}, []}]}]}, + {cons, Line, {tuple, Line, [ + {atom, Line, node}, + {call, Line, {atom, Line, node}, []}]}, + %% get the metadata with lager:md(), this will always return a list so we can use it as the tail here + {call, Line, {remote, Line, {atom, Line, lager}, {atom, Line, md}}, []}}}}}} + end, Functions = get(functions), DefaultAttrs1 = add_function_transforms(Line, DefaultAttrs0, Functions), DefaultAttrs = case erlang:get(application) of @@ -171,67 +190,74 @@ do_transform(Line, SinkName, Severity, Arguments0, Safety) -> {nil, Line}}, DefaultAttrs1) end, {Meta, Message, Arguments} = handle_args(DefaultAttrs, Line, Arguments0), - %% Generate some unique variable names so we don't accidentally export from case clauses. - %% Note that these are not actual atoms, but the AST treats variable names as atoms. - LevelVar = make_varname("__Level", Line), - TracesVar = make_varname("__Traces", Line), - PidVar = make_varname("__Pid", Line), - LogFun = case Safety of - safe -> - do_log; - unsafe -> - do_log_unsafe - end, - %% Wrap the call to lager:dispatch_log/6 in case that will avoid doing any work if this message is not elegible for logging - %% See lager.erl (lines 89-100) for lager:dispatch_log/6 - %% case {whereis(Sink), whereis(?DEFAULT_SINK), lager_config:get({Sink, loglevel}, {?LOG_NONE, []})} of - {'case',Line, - {tuple,Line, - [{call,Line,{atom,Line,whereis},[{atom,Line,SinkName}]}, - {call,Line,{atom,Line,whereis},[{atom,Line,?DEFAULT_SINK}]}, - {call,Line, - {remote,Line,{atom,Line,lager_config},{atom,Line,get}}, - [{tuple,Line,[{atom,Line,SinkName},{atom,Line,loglevel}]}, - {tuple,Line,[{integer,Line,0},{nil,Line}]}]}]}, - %% {undefined, undefined, _} -> {error, lager_not_running}; - [{clause,Line, - [{tuple,Line, - [{atom,Line,undefined},{atom,Line,undefined},{var,Line,'_'}]}], - [], - %% trick the linter into avoiding a 'term constructed but not used' error: - %% (fun() -> {error, lager_not_running} end)() - [{call, Line, {'fun', Line, {clauses, [{clause, Line, [],[], [{tuple, Line, [{atom, Line, error},{atom, Line, lager_not_running}]}]}]}}, []}] - }, - %% {undefined, _, _} -> {error, {sink_not_configured, Sink}}; - {clause,Line, - [{tuple,Line, - [{atom,Line,undefined},{var,Line,'_'},{var,Line,'_'}]}], - [], - %% same trick as above to avoid linter error - [{call, Line, {'fun', Line, {clauses, [{clause, Line, [],[], [{tuple,Line, [{atom,Line,error}, {tuple,Line,[{atom,Line,sink_not_configured},{atom,Line,SinkName}]}]}]}]}}, []}] - }, - %% {SinkPid, _, {Level, Traces}} when ... -> lager:do_log/9; - {clause,Line, - [{tuple,Line, - [{var,Line,PidVar}, - {var,Line,'_'}, - {tuple,Line,[{var,Line,LevelVar},{var,Line,TracesVar}]}]}], - [[{op, Line, 'orelse', - {op, Line, '/=', {op, Line, 'band', {var, Line, LevelVar}, {integer, Line, SeverityAsInt}}, {integer, Line, 0}}, - {op, Line, '/=', {var, Line, TracesVar}, {nil, Line}}}]], - [{call,Line,{remote, Line, {atom, Line, lager}, {atom, Line, LogFun}}, - [{atom,Line,Severity}, - Meta, - Message, - Arguments, - {integer, Line, get(truncation_size)}, - {integer, Line, SeverityAsInt}, - {var, Line, LevelVar}, - {var, Line, TracesVar}, - {atom, Line, SinkName}, - {var, Line, PidVar}]}]}, - %% _ -> ok - {clause,Line,[{var,Line,'_'}],[],[{atom,Line,ok}]}]}. + case get(use_logger) of + true -> + {call,Line,{remote, Line, {atom, Line, logger}, {atom, Line, log}}, + [{atom,Line,Severity}, Message, Arguments, Meta]}; + false -> + SeverityAsInt=lager_util:level_to_num(Severity), + %% Generate some unique variable names so we don't accidentally export from case clauses. + %% Note that these are not actual atoms, but the AST treats variable names as atoms. + LevelVar = make_varname("__Level", Line), + TracesVar = make_varname("__Traces", Line), + PidVar = make_varname("__Pid", Line), + LogFun = case Safety of + safe -> + do_log; + unsafe -> + do_log_unsafe + end, + %% Wrap the call to lager:dispatch_log/6 in case that will avoid doing any work if this message is not elegible for logging + %% See lager.erl (lines 89-100) for lager:dispatch_log/6 + %% case {whereis(Sink), whereis(?DEFAULT_SINK), lager_config:get({Sink, loglevel}, {?LOG_NONE, []})} of + {'case',Line, + {tuple,Line, + [{call,Line,{atom,Line,whereis},[{atom,Line,SinkName}]}, + {call,Line,{atom,Line,whereis},[{atom,Line,?DEFAULT_SINK}]}, + {call,Line, + {remote,Line,{atom,Line,lager_config},{atom,Line,get}}, + [{tuple,Line,[{atom,Line,SinkName},{atom,Line,loglevel}]}, + {tuple,Line,[{integer,Line,0},{nil,Line}]}]}]}, + %% {undefined, undefined, _} -> {error, lager_not_running}; + [{clause,Line, + [{tuple,Line, + [{atom,Line,undefined},{atom,Line,undefined},{var,Line,'_'}]}], + [], + %% trick the linter into avoiding a 'term constructed but not used' error: + %% (fun() -> {error, lager_not_running} end)() + [{call, Line, {'fun', Line, {clauses, [{clause, Line, [],[], [{tuple, Line, [{atom, Line, error},{atom, Line, lager_not_running}]}]}]}}, []}] + }, + %% {undefined, _, _} -> {error, {sink_not_configured, Sink}}; + {clause,Line, + [{tuple,Line, + [{atom,Line,undefined},{var,Line,'_'},{var,Line,'_'}]}], + [], + %% same trick as above to avoid linter error + [{call, Line, {'fun', Line, {clauses, [{clause, Line, [],[], [{tuple,Line, [{atom,Line,error}, {tuple,Line,[{atom,Line,sink_not_configured},{atom,Line,SinkName}]}]}]}]}}, []}] + }, + %% {SinkPid, _, {Level, Traces}} when ... -> lager:do_log/9; + {clause,Line, + [{tuple,Line, + [{var,Line,PidVar}, + {var,Line,'_'}, + {tuple,Line,[{var,Line,LevelVar},{var,Line,TracesVar}]}]}], + [[{op, Line, 'orelse', + {op, Line, '/=', {op, Line, 'band', {var, Line, LevelVar}, {integer, Line, SeverityAsInt}}, {integer, Line, 0}}, + {op, Line, '/=', {var, Line, TracesVar}, {nil, Line}}}]], + [{call,Line,{remote, Line, {atom, Line, lager}, {atom, Line, LogFun}}, + [{atom,Line,Severity}, + Meta, + Message, + Arguments, + {integer, Line, get(truncation_size)}, + {integer, Line, SeverityAsInt}, + {var, Line, LevelVar}, + {var, Line, TracesVar}, + {atom, Line, SinkName}, + {var, Line, PidVar}]}]}, + %% _ -> ok + {clause,Line,[{var,Line,'_'}],[],[{atom,Line,ok}]}]} + end. handle_args(DefaultAttrs, Line, [{cons, LineNum, {tuple, _, _}, _} = Attrs]) -> {concat_lists(DefaultAttrs, Attrs), {string, LineNum, ""}, {atom, Line, none}}; @@ -317,6 +343,7 @@ guess_application(Dirname, Attr) when Dirname /= undefined -> ok end; guess_application(undefined, {attribute, _, file, {Filename, _}}) -> + put(filename, Filename), Dir = filename:dirname(Filename), find_app_file(Dir); guess_application(_, _) -> From f1c7e3ad118c4d2f5cfb19548c39e89322ea6e71 Mon Sep 17 00:00:00 2001 From: Andrew Thompson Date: Sat, 2 Feb 2019 16:38:35 -0800 Subject: [PATCH 02/35] Couple fixes --- src/lager_transform.erl | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/src/lager_transform.erl b/src/lager_transform.erl index 590fd750..f2485807 100644 --- a/src/lager_transform.erl +++ b/src/lager_transform.erl @@ -150,7 +150,7 @@ do_transform(Line, SinkName, Severity, Arguments0, Safety) -> {cons, Line, {tuple, Line, [ {atom, Line, gl}, {call, Line, {atom, Line, group_leader}, []}]}, {cons, Line, {tuple, Line, [ - {atom, Line, time}, {call, {remote, Line, {atom, Line, erlang}, {atom, Line, system_time}}, [{atom, Line, microsecond}]}]}, + {atom, Line, time}, {call, Line, {remote, Line, {atom, Line, erlang}, {atom, Line, system_time}}, [{atom, Line, microsecond}]}]}, {cons, Line, {tuple, Line, [ {atom, Line, mfa}, {tuple, Line, [{atom, Line, get(module)}, {atom, Line, get(function)}, {atom, Line, get(arity)}]}]}, {cons, Line, {tuple, Line, [ @@ -193,7 +193,7 @@ do_transform(Line, SinkName, Severity, Arguments0, Safety) -> case get(use_logger) of true -> {call,Line,{remote, Line, {atom, Line, logger}, {atom, Line, log}}, - [{atom,Line,Severity}, Message, Arguments, Meta]}; + [{atom,Line,Severity}, Message, Arguments, {call, Line, {remote, Line, {atom, Line, maps}, {atom, Line, from_list}}, [Meta]}]}; false -> SeverityAsInt=lager_util:level_to_num(Severity), %% Generate some unique variable names so we don't accidentally export from case clauses. From 7aaad5ca156e9b2b74c08e4ca62d415a41273d23 Mon Sep 17 00:00:00 2001 From: Andrew Thompson Date: Sat, 2 Feb 2019 16:46:42 -0800 Subject: [PATCH 03/35] Handle log messages with no format arguments --- src/lager_transform.erl | 12 ++++++++++-- 1 file changed, 10 insertions(+), 2 deletions(-) diff --git a/src/lager_transform.erl b/src/lager_transform.erl index f2485807..c8b5d316 100644 --- a/src/lager_transform.erl +++ b/src/lager_transform.erl @@ -192,8 +192,16 @@ do_transform(Line, SinkName, Severity, Arguments0, Safety) -> {Meta, Message, Arguments} = handle_args(DefaultAttrs, Line, Arguments0), case get(use_logger) of true -> - {call,Line,{remote, Line, {atom, Line, logger}, {atom, Line, log}}, - [{atom,Line,Severity}, Message, Arguments, {call, Line, {remote, Line, {atom, Line, maps}, {atom, Line, from_list}}, [Meta]}]}; + case Arguments of + {atom, _, none} -> + %% logger:log(Level, Format, Args, Metadata) + {call,Line,{remote, Line, {atom, Line, logger}, {atom, Line, log}}, + [{atom,Line,Severity}, Message, Arguments, {call, Line, {remote, Line, {atom, Line, maps}, {atom, Line, from_list}}, [Meta]}]}; + _ -> + %% logger:log(Level, String, Metadata) + {call,Line,{remote, Line, {atom, Line, logger}, {atom, Line, log}}, + [{atom,Line,Severity}, Message, {call, Line, {remote, Line, {atom, Line, maps}, {atom, Line, from_list}}, [Meta]}]} + end; false -> SeverityAsInt=lager_util:level_to_num(Severity), %% Generate some unique variable names so we don't accidentally export from case clauses. From a68e456aa25e3f3886022ea3ef8f02bf71ef4c86 Mon Sep 17 00:00:00 2001 From: Andrew Thompson Date: Sat, 2 Feb 2019 16:48:29 -0800 Subject: [PATCH 04/35] Backwards --- src/lager_transform.erl | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/src/lager_transform.erl b/src/lager_transform.erl index c8b5d316..8f5a483d 100644 --- a/src/lager_transform.erl +++ b/src/lager_transform.erl @@ -196,11 +196,11 @@ do_transform(Line, SinkName, Severity, Arguments0, Safety) -> {atom, _, none} -> %% logger:log(Level, Format, Args, Metadata) {call,Line,{remote, Line, {atom, Line, logger}, {atom, Line, log}}, - [{atom,Line,Severity}, Message, Arguments, {call, Line, {remote, Line, {atom, Line, maps}, {atom, Line, from_list}}, [Meta]}]}; + [{atom,Line,Severity}, Message, {call, Line, {remote, Line, {atom, Line, maps}, {atom, Line, from_list}}, [Meta]}]}; _ -> %% logger:log(Level, String, Metadata) {call,Line,{remote, Line, {atom, Line, logger}, {atom, Line, log}}, - [{atom,Line,Severity}, Message, {call, Line, {remote, Line, {atom, Line, maps}, {atom, Line, from_list}}, [Meta]}]} + [{atom,Line,Severity}, Message, Arguments, {call, Line, {remote, Line, {atom, Line, maps}, {atom, Line, from_list}}, [Meta]}]} end; false -> SeverityAsInt=lager_util:level_to_num(Severity), From ad25bf83114a433b3a63ecc8c0fabeb27417edf9 Mon Sep 17 00:00:00 2001 From: Andrew Thompson Date: Sat, 2 Feb 2019 17:06:09 -0800 Subject: [PATCH 05/35] Add an env var to stop lager actually booting --- src/lager_app.erl | 15 ++++++++++----- src/lager_sup.erl | 41 +++++++++++++++++++++++------------------ 2 files changed, 33 insertions(+), 23 deletions(-) diff --git a/src/lager_app.erl b/src/lager_app.erl index 1475f800..53f880d5 100644 --- a/src/lager_app.erl +++ b/src/lager_app.erl @@ -226,11 +226,16 @@ get_env(Application, Key, Default) -> start(_StartType, _StartArgs) -> {ok, Pid} = lager_sup:start_link(), - SavedHandlers = boot(), - _ = boot('__all_extra'), - _ = boot('__traces'), - clean_up_config_checks(), - {ok, Pid, SavedHandlers}. + case application:get_env(lager, lager_use_logger, false) of + false -> + SavedHandlers = boot(), + _ = boot('__all_extra'), + _ = boot('__traces'), + clean_up_config_checks(), + {ok, Pid, SavedHandlers}; + true -> + {ok, Pid} + end. boot() -> %% Handle the default sink. diff --git a/src/lager_sup.erl b/src/lager_sup.erl index 97bfd009..890f272e 100644 --- a/src/lager_sup.erl +++ b/src/lager_sup.erl @@ -32,24 +32,29 @@ start_link() -> supervisor:start_link({local, ?MODULE}, ?MODULE, []). init([]) -> - %% set up the config, is safe even during relups - lager_config:new(), - %% TODO: - %% Always start lager_event as the default and make sure that - %% other gen_event stuff can start up as needed - %% - %% Maybe a new API to handle the sink and its policy? - Children = [ - {lager, {gen_event, start_link, [{local, lager_event}]}, - permanent, 5000, worker, dynamic}, - {lager_handler_watcher_sup, {lager_handler_watcher_sup, start_link, []}, - permanent, 5000, supervisor, [lager_handler_watcher_sup]}], - - CrashLog = decide_crash_log(application:get_env(lager, crash_log, false)), - - {ok, {{one_for_one, 10, 60}, - Children ++ CrashLog - }}. + case application:get_env(lager, lager_use_logger, false) of + true -> + {ok, {{one_for_one, 10, 60}, []}}; + false -> + %% set up the config, is safe even during relups + lager_config:new(), + %% TODO: + %% Always start lager_event as the default and make sure that + %% other gen_event stuff can start up as needed + %% + %% Maybe a new API to handle the sink and its policy? + Children = [ + {lager, {gen_event, start_link, [{local, lager_event}]}, + permanent, 5000, worker, dynamic}, + {lager_handler_watcher_sup, {lager_handler_watcher_sup, start_link, []}, + permanent, 5000, supervisor, [lager_handler_watcher_sup]}], + + CrashLog = decide_crash_log(application:get_env(lager, crash_log, false)), + + {ok, {{one_for_one, 10, 60}, + Children ++ CrashLog + }} + end. validate_positive({ok, Val}, _Default) when is_integer(Val) andalso Val >= 0 -> Val; From 62d95d24f7aefe6338d7b2c55947c28546c1d07f Mon Sep 17 00:00:00 2001 From: Andrew Thompson Date: Sat, 2 Feb 2019 18:27:54 -0800 Subject: [PATCH 06/35] Add a module to convert logger formatters to lager formatters --- src/lager_logger_formatter.erl | 34 ++++++++++++++++++++++++++++++++++ 1 file changed, 34 insertions(+) create mode 100644 src/lager_logger_formatter.erl diff --git a/src/lager_logger_formatter.erl b/src/lager_logger_formatter.erl new file mode 100644 index 00000000..c8a6edbc --- /dev/null +++ b/src/lager_logger_formatter.erl @@ -0,0 +1,34 @@ +-module(lager_logger_formatter). + +%% convert logger formatter calls into lager formatter ones + +-export([format/2]).%, check_config/1]). + +format(#{level := Level, msg := {report, _Report}, meta := Metadata}, Config) -> + do_format(Level, erlang:error(wtf), Metadata, Config); +format(#{level := Level, msg := {string, String}, meta := Metadata}, Config) -> + do_format(Level, String, Metadata, Config); +format(#{level := Level, msg := {FmtStr, FmtArgs}, meta := Metadata}, Config) -> + Msg = lager_format:format(FmtStr, FmtArgs, maps:get(max_size, Config, 1024)), + do_format(Level, Msg, Metadata, Config). + +do_format(Level, Msg, Metadata, Config) -> + FormatModule = maps:get(formatter, Config, lager_default_formatter), + Timestamp = maps:get(time, Metadata), + MegaSecs = Timestamp div 1000000000000, + Secs = (1549018253268942 rem 1000000000000) div 1000000, + MicroSecs = (1549018253268942 rem 1000000000000) rem 1000000, + Colors = case maps:get(colors, Config, false) of + true -> + application:get_env(lager, colors, []); + false -> + [] + end, + FormatModule:format(lager_msg:new(Msg, {MegaSecs, Secs, MicroSecs}, Level, convert_metadata(Metadata), []), maps:get(formatter_config, Config, []), Colors). + +convert_metadata(Metadata) -> + maps:fold(fun(mfa, {Module, Function, Arity}, Acc) -> + [{module, Module}, {function, Function}, {arity, Arity}|Acc]; + (K, V, Acc) -> + [{K, V}|Acc] + end, [], Metadata). From 0970513d2dc941a34c0ab5bb968e17cd9f1dae41 Mon Sep 17 00:00:00 2001 From: Andrew Thompson Date: Sat, 2 Feb 2019 18:38:15 -0800 Subject: [PATCH 07/35] Clear colors at end of line --- src/lager_logger_formatter.erl | 12 ++++++------ 1 file changed, 6 insertions(+), 6 deletions(-) diff --git a/src/lager_logger_formatter.erl b/src/lager_logger_formatter.erl index c8a6edbc..224127a2 100644 --- a/src/lager_logger_formatter.erl +++ b/src/lager_logger_formatter.erl @@ -18,13 +18,13 @@ do_format(Level, Msg, Metadata, Config) -> MegaSecs = Timestamp div 1000000000000, Secs = (1549018253268942 rem 1000000000000) div 1000000, MicroSecs = (1549018253268942 rem 1000000000000) rem 1000000, - Colors = case maps:get(colors, Config, false) of + {Colors, End} = case maps:get(colors, Config, false) of true -> - application:get_env(lager, colors, []); - false -> - [] - end, - FormatModule:format(lager_msg:new(Msg, {MegaSecs, Secs, MicroSecs}, Level, convert_metadata(Metadata), []), maps:get(formatter_config, Config, []), Colors). + {application:get_env(lager, colors, []), "\e[0m"}; + false -> + "" + end, + [FormatModule:format(lager_msg:new(Msg, {MegaSecs, Secs, MicroSecs}, Level, convert_metadata(Metadata), []), maps:get(formatter_config, Config, []), Colors), End]. convert_metadata(Metadata) -> maps:fold(fun(mfa, {Module, Function, Arity}, Acc) -> From e53ecb0fe5fd85b78d1b874fc8d2d22ba12ba217 Mon Sep 17 00:00:00 2001 From: Andrew Thompson Date: Sat, 2 Feb 2019 19:04:12 -0800 Subject: [PATCH 08/35] Typo --- src/lager_logger_formatter.erl | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/lager_logger_formatter.erl b/src/lager_logger_formatter.erl index 224127a2..49159883 100644 --- a/src/lager_logger_formatter.erl +++ b/src/lager_logger_formatter.erl @@ -22,7 +22,7 @@ do_format(Level, Msg, Metadata, Config) -> true -> {application:get_env(lager, colors, []), "\e[0m"}; false -> - "" + {[], ""} end, [FormatModule:format(lager_msg:new(Msg, {MegaSecs, Secs, MicroSecs}, Level, convert_metadata(Metadata), []), maps:get(formatter_config, Config, []), Colors), End]. From 8a2cf8d5a8e004d55f2cb54ceb5015361436162d Mon Sep 17 00:00:00 2001 From: Andrew Thompson Date: Sun, 3 Feb 2019 13:56:29 -0800 Subject: [PATCH 09/35] Add some formatters for the standard OTP reports --- src/lager_logger_formatter.erl | 40 ++++++++++++++++++++++++++++++++++ 1 file changed, 40 insertions(+) diff --git a/src/lager_logger_formatter.erl b/src/lager_logger_formatter.erl index 49159883..0ffe3202 100644 --- a/src/lager_logger_formatter.erl +++ b/src/lager_logger_formatter.erl @@ -4,6 +4,46 @@ -export([format/2]).%, check_config/1]). +format(#{level := Level, msg := {report, #{label := {gen_server, terminate}, name := Name, reason := Reason}}, meta := Metadata}, Config) -> + {_Md, Formatted} = error_logger_lager_h:format_reason_md(Reason), + Msg = lager_format:format("gen_server ~w terminated with reason: ~s", [Name, Formatted], maps:get(max_size, Config, 1024)), + do_format(Level, Msg, Metadata, Config); +format(#{level := Level, msg := {report, #{label := {gen_fsm, terminate}, name := Name, state_name := StateName, reason := Reason}}, meta := Metadata}, Config) -> + {_Md, Formatted} = error_logger_lager_h:format_reason_md(Reason), + Msg = lager_format:format("gen_fsm ~w in state ~w terminated with reason: ~s", [Name, StateName, Formatted], maps:get(max_size, Config, 1024)), + do_format(Level, Msg, Metadata, Config); +format(#{level := Level, msg := {report, #{label := {gen_event, terminate}, name := Name, handler := Handler, reason := Reason}}, meta := Metadata}, Config) -> + {_Md, Formatted} = error_logger_lager_h:format_reason_md(Reason), + Msg = lager_format:format("gen_event ~w installed in ~w terminated with reason: ~s", [Handler, Name, Formatted], maps:get(max_size, Config, 1024)), + do_format(Level, Msg, Metadata, Config); +format(#{level := Level, msg := {report, #{label := {gen_statem, terminate}, name := Name, reason := Reason}}, meta := Metadata}, Config) -> + {_Md, Formatted} = error_logger_lager_h:format_reason_md(Reason), + %% XXX I can't find the FSM statename in the error report, maybe it should be added + Msg = lager_format:format("gen_statem ~w terminated with reason: ~s", [Name, Formatted], maps:get(max_size, Config, 1024)), + do_format(Level, Msg, Metadata, Config); +format(#{level := Level, msg := {report, #{label := {Behaviour, no_handle_info}, mod := Mod, msg := Msg}}, meta := Metadata}, Config) -> + Msg = lager_format:format("undefined handle_info for ~p in ~s ~p", [Msg, Behaviour, Mod], maps:get(max_size, Config, 1024)), + do_format(Level, Msg, Metadata, Config); +format(#{level := Level, msg := {report, #{label := {supervisor, progress}, report := Report}}, meta := Metadata}, Config) -> + {supervisor, Name} = lists:keyfind(supervisor, 1, Report), + {started, Started} = lists:keyfind(started, 1, Report), + Msg = case lists:keyfind(id, 1, Started) of + false -> + %% supervisor itself starting + {mfa, {Module, Function, Args}} = lists:keyfind(mfa, 1, Started), + {pid, Pid} = lists:keyfind(pid, 1, Started), + lager_format:format("Supervisor ~w started as ~p at pid ~w", [Name, error_logger_lager_h:format_mfa(Module, Function, Args), Pid], maps:get(max_size, Config, 1024)); + {id, ChildID} -> + case lists:keyfind(pid, 1, Started) of + {pid, Pid} -> + lager_format:format("Supervisor ~w started child ~s at pid ~w", [Name, ChildID, Pid], maps:get(max_size, Config, 1024)); + false -> + %% children is a list of pids for some reason? and we only get the count + {nb_children, ChildCount} = lists:keyfind(nb_children, 1, Started), + lager_format:format("Supervisor ~w started ~b children ~s", [Name, ChildCount, ChildID], maps:get(max_size, Config, 1024)) + end + end, + do_format(Level, Msg, Metadata, Config); format(#{level := Level, msg := {report, _Report}, meta := Metadata}, Config) -> do_format(Level, erlang:error(wtf), Metadata, Config); format(#{level := Level, msg := {string, String}, meta := Metadata}, Config) -> From 0176941b90c2e66c384ed54ee847c4ee06fff7fb Mon Sep 17 00:00:00 2001 From: Andrew Thompson Date: Sun, 3 Feb 2019 14:03:12 -0800 Subject: [PATCH 10/35] Fallback for unhandled reports --- src/lager_logger_formatter.erl | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/src/lager_logger_formatter.erl b/src/lager_logger_formatter.erl index 0ffe3202..8bc133a1 100644 --- a/src/lager_logger_formatter.erl +++ b/src/lager_logger_formatter.erl @@ -44,8 +44,8 @@ format(#{level := Level, msg := {report, #{label := {supervisor, progress}, repo end end, do_format(Level, Msg, Metadata, Config); -format(#{level := Level, msg := {report, _Report}, meta := Metadata}, Config) -> - do_format(Level, erlang:error(wtf), Metadata, Config); +format(#{level := Level, msg := {report, Report}, meta := Metadata}, Config) -> + do_format(Level, (maps:get(report_cb, Metadata))(Report), Metadata, Config); format(#{level := Level, msg := {string, String}, meta := Metadata}, Config) -> do_format(Level, String, Metadata, Config); format(#{level := Level, msg := {FmtStr, FmtArgs}, meta := Metadata}, Config) -> From c793c030d0517d32d370878a460a1aaa4bfdd830 Mon Sep 17 00:00:00 2001 From: Andrew Thompson Date: Sun, 3 Feb 2019 14:05:22 -0800 Subject: [PATCH 11/35] Tweak --- src/lager_logger_formatter.erl | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/src/lager_logger_formatter.erl b/src/lager_logger_formatter.erl index 8bc133a1..9e6d31a3 100644 --- a/src/lager_logger_formatter.erl +++ b/src/lager_logger_formatter.erl @@ -36,11 +36,11 @@ format(#{level := Level, msg := {report, #{label := {supervisor, progress}, repo {id, ChildID} -> case lists:keyfind(pid, 1, Started) of {pid, Pid} -> - lager_format:format("Supervisor ~w started child ~s at pid ~w", [Name, ChildID, Pid], maps:get(max_size, Config, 1024)); + lager_format:format("Supervisor ~w started child ~p at pid ~w", [Name, ChildID, Pid], maps:get(max_size, Config, 1024)); false -> %% children is a list of pids for some reason? and we only get the count {nb_children, ChildCount} = lists:keyfind(nb_children, 1, Started), - lager_format:format("Supervisor ~w started ~b children ~s", [Name, ChildCount, ChildID], maps:get(max_size, Config, 1024)) + lager_format:format("Supervisor ~w started ~b children ~p", [Name, ChildCount, ChildID], maps:get(max_size, Config, 1024)) end end, do_format(Level, Msg, Metadata, Config); From 9b8ee2342c659ec277a6eec3937e2ed4cdc682ca Mon Sep 17 00:00:00 2001 From: Andrew Thompson Date: Sun, 3 Feb 2019 14:07:20 -0800 Subject: [PATCH 12/35] Honor supervisor message suppression config --- src/lager_logger_formatter.erl | 40 +++++++++++++++++++--------------- 1 file changed, 22 insertions(+), 18 deletions(-) diff --git a/src/lager_logger_formatter.erl b/src/lager_logger_formatter.erl index 9e6d31a3..2ef7763d 100644 --- a/src/lager_logger_formatter.erl +++ b/src/lager_logger_formatter.erl @@ -25,25 +25,29 @@ format(#{level := Level, msg := {report, #{label := {Behaviour, no_handle_info}, Msg = lager_format:format("undefined handle_info for ~p in ~s ~p", [Msg, Behaviour, Mod], maps:get(max_size, Config, 1024)), do_format(Level, Msg, Metadata, Config); format(#{level := Level, msg := {report, #{label := {supervisor, progress}, report := Report}}, meta := Metadata}, Config) -> - {supervisor, Name} = lists:keyfind(supervisor, 1, Report), - {started, Started} = lists:keyfind(started, 1, Report), - Msg = case lists:keyfind(id, 1, Started) of - false -> - %% supervisor itself starting - {mfa, {Module, Function, Args}} = lists:keyfind(mfa, 1, Started), - {pid, Pid} = lists:keyfind(pid, 1, Started), - lager_format:format("Supervisor ~w started as ~p at pid ~w", [Name, error_logger_lager_h:format_mfa(Module, Function, Args), Pid], maps:get(max_size, Config, 1024)); - {id, ChildID} -> - case lists:keyfind(pid, 1, Started) of - {pid, Pid} -> - lager_format:format("Supervisor ~w started child ~p at pid ~w", [Name, ChildID, Pid], maps:get(max_size, Config, 1024)); + case application:get_env(lager, suppress_supervisor_start_stop, false) of + true -> ""; + false -> + {supervisor, Name} = lists:keyfind(supervisor, 1, Report), + {started, Started} = lists:keyfind(started, 1, Report), + Msg = case lists:keyfind(id, 1, Started) of false -> - %% children is a list of pids for some reason? and we only get the count - {nb_children, ChildCount} = lists:keyfind(nb_children, 1, Started), - lager_format:format("Supervisor ~w started ~b children ~p", [Name, ChildCount, ChildID], maps:get(max_size, Config, 1024)) - end - end, - do_format(Level, Msg, Metadata, Config); + %% supervisor itself starting + {mfa, {Module, Function, Args}} = lists:keyfind(mfa, 1, Started), + {pid, Pid} = lists:keyfind(pid, 1, Started), + lager_format:format("Supervisor ~w started as ~p at pid ~w", [Name, error_logger_lager_h:format_mfa(Module, Function, Args), Pid], maps:get(max_size, Config, 1024)); + {id, ChildID} -> + case lists:keyfind(pid, 1, Started) of + {pid, Pid} -> + lager_format:format("Supervisor ~w started child ~p at pid ~w", [Name, ChildID, Pid], maps:get(max_size, Config, 1024)); + false -> + %% children is a list of pids for some reason? and we only get the count + {nb_children, ChildCount} = lists:keyfind(nb_children, 1, Started), + lager_format:format("Supervisor ~w started ~b children ~p", [Name, ChildCount, ChildID], maps:get(max_size, Config, 1024)) + end + end, + do_format(Level, Msg, Metadata, Config) + end; format(#{level := Level, msg := {report, Report}, meta := Metadata}, Config) -> do_format(Level, (maps:get(report_cb, Metadata))(Report), Metadata, Config); format(#{level := Level, msg := {string, String}, meta := Metadata}, Config) -> From 4f8d24513d0547184373d76f82094e9aa74aa144 Mon Sep 17 00:00:00 2001 From: Andrew Thompson Date: Sun, 3 Feb 2019 14:15:38 -0800 Subject: [PATCH 13/35] Feh --- src/lager_logger_formatter.erl | 6 ++++-- 1 file changed, 4 insertions(+), 2 deletions(-) diff --git a/src/lager_logger_formatter.erl b/src/lager_logger_formatter.erl index 2ef7763d..3cdfdfc4 100644 --- a/src/lager_logger_formatter.erl +++ b/src/lager_logger_formatter.erl @@ -26,7 +26,8 @@ format(#{level := Level, msg := {report, #{label := {Behaviour, no_handle_info}, do_format(Level, Msg, Metadata, Config); format(#{level := Level, msg := {report, #{label := {supervisor, progress}, report := Report}}, meta := Metadata}, Config) -> case application:get_env(lager, suppress_supervisor_start_stop, false) of - true -> ""; + true -> + ""; false -> {supervisor, Name} = lists:keyfind(supervisor, 1, Report), {started, Started} = lists:keyfind(started, 1, Report), @@ -49,7 +50,8 @@ format(#{level := Level, msg := {report, #{label := {supervisor, progress}, repo do_format(Level, Msg, Metadata, Config) end; format(#{level := Level, msg := {report, Report}, meta := Metadata}, Config) -> - do_format(Level, (maps:get(report_cb, Metadata))(Report), Metadata, Config); + %do_format(Level, (maps:get(report_cb, Metadata))(Report), Metadata, Config); + ""; format(#{level := Level, msg := {string, String}, meta := Metadata}, Config) -> do_format(Level, String, Metadata, Config); format(#{level := Level, msg := {FmtStr, FmtArgs}, meta := Metadata}, Config) -> From 9ed7ee8f69fac0985c7358c4c756d00bfeafbdd2 Mon Sep 17 00:00:00 2001 From: Andrew Thompson Date: Sun, 3 Feb 2019 16:53:59 -0800 Subject: [PATCH 14/35] Add supervisor error reports --- src/lager_logger_formatter.erl | 25 +++++++++++++++++++++++-- 1 file changed, 23 insertions(+), 2 deletions(-) diff --git a/src/lager_logger_formatter.erl b/src/lager_logger_formatter.erl index 3cdfdfc4..58b90509 100644 --- a/src/lager_logger_formatter.erl +++ b/src/lager_logger_formatter.erl @@ -49,9 +49,30 @@ format(#{level := Level, msg := {report, #{label := {supervisor, progress}, repo end, do_format(Level, Msg, Metadata, Config) end; -format(#{level := Level, msg := {report, Report}, meta := Metadata}, Config) -> +format(#{level := Level, msg := {report, #{label := {supervisor, _Error}, report := Report}}, meta := Metadata}, Config) -> + {supervisor, Name} = lists:keyfind(supervisor, 1, Report), + {reason, Reason} = lists:keyfind(reason, 1, Report), + {_Md, Formatted} = error_logger_lager_h:format_reason_md(Reason), + {errorContext, ErrorContext} = lists:keyfind(errorContext, 1, Report), + {offender, Offender} = lists:keyfind(offender, 1, Report), + Msg = case lists:keyfind(mod, 1, Offender) of + {mod, _Mod} -> + {pid, Pid} = lists:keyfind(pid, 1, Offender), + %% this comes from supervisor_bridge + lager_format:format("Supervisor ~w had ~p ~p with reason ~s", [Name, Pid, ErrorContext, Formatted], maps:get(max_size, Config, 1024)); + false -> + {id, ChildID} = lists:keyfind(id, 1, Offender), + case lists:keyfind(pid, 1, Offender) of + {pid, Pid} -> + lager_format:format("Supervisor ~w had ~p ~p ~p with reason ~s", [Name, ChildID, Pid, ErrorContext, Formatted], maps:get(max_size, Config, 1024)); + false -> + lager_format:format("Supervisor ~w had ~p ~p with reason ~s", [Name, ChildID, ErrorContext, Formatted], maps:get(max_size, Config, 1024)) + end + end, + do_format(Level, Msg, Metadata, Config); +format(#{level := _Level, msg := {report, Report}, meta := _Metadata}, _Config) -> %do_format(Level, (maps:get(report_cb, Metadata))(Report), Metadata, Config); - ""; + io_lib:format("REPORT ~p~n", [Report]); format(#{level := Level, msg := {string, String}, meta := Metadata}, Config) -> do_format(Level, String, Metadata, Config); format(#{level := Level, msg := {FmtStr, FmtArgs}, meta := Metadata}, Config) -> From 8ac924b748a2e6ade1cf3014aa56c47d03b639be Mon Sep 17 00:00:00 2001 From: Andrew Thompson Date: Sun, 3 Feb 2019 16:58:20 -0800 Subject: [PATCH 15/35] Debugging --- src/lager_logger_formatter.erl | 1 + 1 file changed, 1 insertion(+) diff --git a/src/lager_logger_formatter.erl b/src/lager_logger_formatter.erl index 58b90509..c48aaeab 100644 --- a/src/lager_logger_formatter.erl +++ b/src/lager_logger_formatter.erl @@ -36,6 +36,7 @@ format(#{level := Level, msg := {report, #{label := {supervisor, progress}, repo %% supervisor itself starting {mfa, {Module, Function, Args}} = lists:keyfind(mfa, 1, Started), {pid, Pid} = lists:keyfind(pid, 1, Started), + io:format("~p ~p ~p", [Name, {Module, Function, Args}, Pid]), lager_format:format("Supervisor ~w started as ~p at pid ~w", [Name, error_logger_lager_h:format_mfa(Module, Function, Args), Pid], maps:get(max_size, Config, 1024)); {id, ChildID} -> case lists:keyfind(pid, 1, Started) of From 7e247dc761157c9039c3694ce5ff06c8fa320ad9 Mon Sep 17 00:00:00 2001 From: Andrew Thompson Date: Sun, 3 Feb 2019 17:01:33 -0800 Subject: [PATCH 16/35] Typo: --- src/lager_logger_formatter.erl | 3 +-- 1 file changed, 1 insertion(+), 2 deletions(-) diff --git a/src/lager_logger_formatter.erl b/src/lager_logger_formatter.erl index c48aaeab..279825b1 100644 --- a/src/lager_logger_formatter.erl +++ b/src/lager_logger_formatter.erl @@ -36,8 +36,7 @@ format(#{level := Level, msg := {report, #{label := {supervisor, progress}, repo %% supervisor itself starting {mfa, {Module, Function, Args}} = lists:keyfind(mfa, 1, Started), {pid, Pid} = lists:keyfind(pid, 1, Started), - io:format("~p ~p ~p", [Name, {Module, Function, Args}, Pid]), - lager_format:format("Supervisor ~w started as ~p at pid ~w", [Name, error_logger_lager_h:format_mfa(Module, Function, Args), Pid], maps:get(max_size, Config, 1024)); + lager_format:format("Supervisor ~w started as ~p at pid ~w", [Name, error_logger_lager_h:format_mfa({Module, Function, Args}), Pid], maps:get(max_size, Config, 1024)); {id, ChildID} -> case lists:keyfind(pid, 1, Started) of {pid, Pid} -> From 0ba40a2d40b0acbade7e707d9f5bdc8eaef137a8 Mon Sep 17 00:00:00 2001 From: Andrew Thompson Date: Sun, 3 Feb 2019 17:07:04 -0800 Subject: [PATCH 17/35] Add application start --- src/lager_logger_formatter.erl | 9 +++++++++ 1 file changed, 9 insertions(+) diff --git a/src/lager_logger_formatter.erl b/src/lager_logger_formatter.erl index 279825b1..165a9673 100644 --- a/src/lager_logger_formatter.erl +++ b/src/lager_logger_formatter.erl @@ -70,6 +70,15 @@ format(#{level := Level, msg := {report, #{label := {supervisor, _Error}, report end end, do_format(Level, Msg, Metadata, Config); +format(#{level := Level, msg := {report, #{label := {application_controller, progress}, report := Report}}, meta := Metadata}, Config) -> + case application:get_env(lager, suppress_application_start_stop, false) of + true -> ""; + false -> + {name, Name} = lists:keyfind(name, 1, Report), + {node, Node} = lists:keyfind(node, 1, Report), + Msg = lager_format:format("Application ~w started on node ~w", [Name, Node], maps:get(max_size, Config, 1024)), + do_format(Level, Msg, Metadata, Config) + end; format(#{level := _Level, msg := {report, Report}, meta := _Metadata}, _Config) -> %do_format(Level, (maps:get(report_cb, Metadata))(Report), Metadata, Config); io_lib:format("REPORT ~p~n", [Report]); From 24651deb76061bd7993284af595cf3d6d3325f38 Mon Sep 17 00:00:00 2001 From: Andrew Thompson Date: Sun, 3 Feb 2019 17:08:15 -0800 Subject: [PATCH 18/35] Use the right key names --- src/lager_logger_formatter.erl | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/src/lager_logger_formatter.erl b/src/lager_logger_formatter.erl index 165a9673..ce60da64 100644 --- a/src/lager_logger_formatter.erl +++ b/src/lager_logger_formatter.erl @@ -74,8 +74,8 @@ format(#{level := Level, msg := {report, #{label := {application_controller, pro case application:get_env(lager, suppress_application_start_stop, false) of true -> ""; false -> - {name, Name} = lists:keyfind(name, 1, Report), - {node, Node} = lists:keyfind(node, 1, Report), + {application, Name} = lists:keyfind(application, 1, Report), + {started_at, Node} = lists:keyfind(started_at, 1, Report), Msg = lager_format:format("Application ~w started on node ~w", [Name, Node], maps:get(max_size, Config, 1024)), do_format(Level, Msg, Metadata, Config) end; From 0e07296df79dcdbaf07515b8c2af128c6cffc1d4 Mon Sep 17 00:00:00 2001 From: Andrew Thompson Date: Sun, 3 Feb 2019 17:34:33 -0800 Subject: [PATCH 19/35] Add application stops --- src/lager_logger_formatter.erl | 12 ++++++++++++ 1 file changed, 12 insertions(+) diff --git a/src/lager_logger_formatter.erl b/src/lager_logger_formatter.erl index ce60da64..e694b16f 100644 --- a/src/lager_logger_formatter.erl +++ b/src/lager_logger_formatter.erl @@ -79,6 +79,18 @@ format(#{level := Level, msg := {report, #{label := {application_controller, pro Msg = lager_format:format("Application ~w started on node ~w", [Name, Node], maps:get(max_size, Config, 1024)), do_format(Level, Msg, Metadata, Config) end; +format(#{level := Level, msg := {report, #{label := {application_controller, exit}, report := Report}}, meta := Metadata}, Config) -> + {exited, Reason} = lists:keyfind(exited, 1, Report), + case application:get_env(lager, suppress_application_start_stop) of + {ok, true} when Reason == stopped -> + ok; + _ -> + {application, Name} = lists:keyfind(application, 1, Report), + {_Md, Formatted} = format_reason_md(Reason), + Msg = lager_format:format("Application ~w exited with reason: ~s", [Name, Formatted], maps:get(max_size, Config, 1024)), + do_format(Level, Msg, Metadata, Config) + end; +%% TODO handle proc_lib crash format(#{level := _Level, msg := {report, Report}, meta := _Metadata}, _Config) -> %do_format(Level, (maps:get(report_cb, Metadata))(Report), Metadata, Config); io_lib:format("REPORT ~p~n", [Report]); From 5667c95ba06de31e7dd420ceabd7f1fa6daab26e Mon Sep 17 00:00:00 2001 From: Andrew Thompson Date: Sun, 3 Feb 2019 17:52:40 -0800 Subject: [PATCH 20/35] Try to switch to using a report_cb --- src/lager_logger_formatter.erl | 114 +++++++++++++++------------------ 1 file changed, 53 insertions(+), 61 deletions(-) diff --git a/src/lager_logger_formatter.erl b/src/lager_logger_formatter.erl index e694b16f..c081ec43 100644 --- a/src/lager_logger_formatter.erl +++ b/src/lager_logger_formatter.erl @@ -2,95 +2,87 @@ %% convert logger formatter calls into lager formatter ones --export([format/2]).%, check_config/1]). +-export([report_cb/1, format/2]).%, check_config/1]). -format(#{level := Level, msg := {report, #{label := {gen_server, terminate}, name := Name, reason := Reason}}, meta := Metadata}, Config) -> +report_cb(#{msg := {report, #{label := {gen_server, terminate}, name := Name, reason := Reason}}}) -> {_Md, Formatted} = error_logger_lager_h:format_reason_md(Reason), - Msg = lager_format:format("gen_server ~w terminated with reason: ~s", [Name, Formatted], maps:get(max_size, Config, 1024)), - do_format(Level, Msg, Metadata, Config); -format(#{level := Level, msg := {report, #{label := {gen_fsm, terminate}, name := Name, state_name := StateName, reason := Reason}}, meta := Metadata}, Config) -> + {"gen_server ~w terminated with reason: ~s", [Name, Formatted]}; +report_cb(#{msg := {report, #{label := {gen_fsm, terminate}, name := Name, state_name := StateName, reason := Reason}}}) -> {_Md, Formatted} = error_logger_lager_h:format_reason_md(Reason), - Msg = lager_format:format("gen_fsm ~w in state ~w terminated with reason: ~s", [Name, StateName, Formatted], maps:get(max_size, Config, 1024)), - do_format(Level, Msg, Metadata, Config); -format(#{level := Level, msg := {report, #{label := {gen_event, terminate}, name := Name, handler := Handler, reason := Reason}}, meta := Metadata}, Config) -> + {"gen_fsm ~w in state ~w terminated with reason: ~s", [Name, StateName, Formatted]}; +report_cb(#{msg := {report, #{label := {gen_event, terminate}, name := Name, handler := Handler, reason := Reason}}}) -> {_Md, Formatted} = error_logger_lager_h:format_reason_md(Reason), - Msg = lager_format:format("gen_event ~w installed in ~w terminated with reason: ~s", [Handler, Name, Formatted], maps:get(max_size, Config, 1024)), - do_format(Level, Msg, Metadata, Config); -format(#{level := Level, msg := {report, #{label := {gen_statem, terminate}, name := Name, reason := Reason}}, meta := Metadata}, Config) -> + {"gen_event ~w installed in ~w terminated with reason: ~s", [Handler, Name, Formatted]}; +report_cb(#{msg := {report, #{label := {gen_statem, terminate}, name := Name, reason := Reason}}}) -> {_Md, Formatted} = error_logger_lager_h:format_reason_md(Reason), %% XXX I can't find the FSM statename in the error report, maybe it should be added - Msg = lager_format:format("gen_statem ~w terminated with reason: ~s", [Name, Formatted], maps:get(max_size, Config, 1024)), - do_format(Level, Msg, Metadata, Config); -format(#{level := Level, msg := {report, #{label := {Behaviour, no_handle_info}, mod := Mod, msg := Msg}}, meta := Metadata}, Config) -> - Msg = lager_format:format("undefined handle_info for ~p in ~s ~p", [Msg, Behaviour, Mod], maps:get(max_size, Config, 1024)), - do_format(Level, Msg, Metadata, Config); -format(#{level := Level, msg := {report, #{label := {supervisor, progress}, report := Report}}, meta := Metadata}, Config) -> + {"gen_statem ~w terminated with reason: ~s", [Name, Formatted]}; +report_cb(#{msg := {report, #{label := {Behaviour, no_handle_info}, mod := Mod, msg := Msg}}}) -> + {"undefined handle_info for ~p in ~s ~p", [Msg, Behaviour, Mod]}; +report_cb(#{msg := {report, #{label := {supervisor, progress}, report := Report}}}) -> case application:get_env(lager, suppress_supervisor_start_stop, false) of true -> - ""; + {"", []}; false -> {supervisor, Name} = lists:keyfind(supervisor, 1, Report), {started, Started} = lists:keyfind(started, 1, Report), - Msg = case lists:keyfind(id, 1, Started) of - false -> - %% supervisor itself starting - {mfa, {Module, Function, Args}} = lists:keyfind(mfa, 1, Started), - {pid, Pid} = lists:keyfind(pid, 1, Started), - lager_format:format("Supervisor ~w started as ~p at pid ~w", [Name, error_logger_lager_h:format_mfa({Module, Function, Args}), Pid], maps:get(max_size, Config, 1024)); - {id, ChildID} -> - case lists:keyfind(pid, 1, Started) of - {pid, Pid} -> - lager_format:format("Supervisor ~w started child ~p at pid ~w", [Name, ChildID, Pid], maps:get(max_size, Config, 1024)); - false -> - %% children is a list of pids for some reason? and we only get the count - {nb_children, ChildCount} = lists:keyfind(nb_children, 1, Started), - lager_format:format("Supervisor ~w started ~b children ~p", [Name, ChildCount, ChildID], maps:get(max_size, Config, 1024)) - end - end, - do_format(Level, Msg, Metadata, Config) + case lists:keyfind(id, 1, Started) of + false -> + %% supervisor itself starting + {mfa, {Module, Function, Args}} = lists:keyfind(mfa, 1, Started), + {pid, Pid} = lists:keyfind(pid, 1, Started), + {"Supervisor ~w started as ~p at pid ~w", [Name, error_logger_lager_h:format_mfa({Module, Function, Args}), Pid]}; + {id, ChildID} -> + case lists:keyfind(pid, 1, Started) of + {pid, Pid} -> + {"Supervisor ~w started child ~p at pid ~w", [Name, ChildID, Pid]}; + false -> + %% children is a list of pids for some reason? and we only get the count + {nb_children, ChildCount} = lists:keyfind(nb_children, 1, Started), + {"Supervisor ~w started ~b children ~p", [Name, ChildCount, ChildID]} + end + end end; -format(#{level := Level, msg := {report, #{label := {supervisor, _Error}, report := Report}}, meta := Metadata}, Config) -> +report_cb(#{msg := {report, #{label := {supervisor, _Error}, report := Report}}}) -> {supervisor, Name} = lists:keyfind(supervisor, 1, Report), {reason, Reason} = lists:keyfind(reason, 1, Report), {_Md, Formatted} = error_logger_lager_h:format_reason_md(Reason), {errorContext, ErrorContext} = lists:keyfind(errorContext, 1, Report), {offender, Offender} = lists:keyfind(offender, 1, Report), - Msg = case lists:keyfind(mod, 1, Offender) of - {mod, _Mod} -> - {pid, Pid} = lists:keyfind(pid, 1, Offender), - %% this comes from supervisor_bridge - lager_format:format("Supervisor ~w had ~p ~p with reason ~s", [Name, Pid, ErrorContext, Formatted], maps:get(max_size, Config, 1024)); - false -> - {id, ChildID} = lists:keyfind(id, 1, Offender), - case lists:keyfind(pid, 1, Offender) of - {pid, Pid} -> - lager_format:format("Supervisor ~w had ~p ~p ~p with reason ~s", [Name, ChildID, Pid, ErrorContext, Formatted], maps:get(max_size, Config, 1024)); - false -> - lager_format:format("Supervisor ~w had ~p ~p with reason ~s", [Name, ChildID, ErrorContext, Formatted], maps:get(max_size, Config, 1024)) - end - end, - do_format(Level, Msg, Metadata, Config); -format(#{level := Level, msg := {report, #{label := {application_controller, progress}, report := Report}}, meta := Metadata}, Config) -> + case lists:keyfind(mod, 1, Offender) of + {mod, _Mod} -> + {pid, Pid} = lists:keyfind(pid, 1, Offender), + %% this comes from supervisor_bridge + {"Supervisor ~w had ~p ~p with reason ~s", [Name, Pid, ErrorContext, Formatted]}; + false -> + {id, ChildID} = lists:keyfind(id, 1, Offender), + case lists:keyfind(pid, 1, Offender) of + {pid, Pid} -> + {"Supervisor ~w had ~p ~p ~p with reason ~s", [Name, ChildID, Pid, ErrorContext, Formatted]}; + false -> + {"Supervisor ~w had ~p ~p with reason ~s", [Name, ChildID, ErrorContext, Formatted]} + end + end; +report_cb(#{msg := {report, #{label := {application_controller, progress}, report := Report}}}) -> case application:get_env(lager, suppress_application_start_stop, false) of - true -> ""; + true -> {"", []}; false -> {application, Name} = lists:keyfind(application, 1, Report), {started_at, Node} = lists:keyfind(started_at, 1, Report), - Msg = lager_format:format("Application ~w started on node ~w", [Name, Node], maps:get(max_size, Config, 1024)), - do_format(Level, Msg, Metadata, Config) + {"Application ~w started on node ~w", [Name, Node]} end; -format(#{level := Level, msg := {report, #{label := {application_controller, exit}, report := Report}}, meta := Metadata}, Config) -> +report_cb(#{msg := {report, #{label := {application_controller, exit}, report := Report}}}) -> {exited, Reason} = lists:keyfind(exited, 1, Report), case application:get_env(lager, suppress_application_start_stop) of {ok, true} when Reason == stopped -> - ok; + {"", []}; _ -> {application, Name} = lists:keyfind(application, 1, Report), - {_Md, Formatted} = format_reason_md(Reason), - Msg = lager_format:format("Application ~w exited with reason: ~s", [Name, Formatted], maps:get(max_size, Config, 1024)), - do_format(Level, Msg, Metadata, Config) - end; + {_Md, Formatted} = error_logger_lager_h:format_reason_md(Reason), + {"Application ~w exited with reason: ~s", [Name, Formatted]} + end. %% TODO handle proc_lib crash + format(#{level := _Level, msg := {report, Report}, meta := _Metadata}, _Config) -> %do_format(Level, (maps:get(report_cb, Metadata))(Report), Metadata, Config); io_lib:format("REPORT ~p~n", [Report]); From 7b8d2c54243b2e87c5d09ae4a0adadabe5a4e550 Mon Sep 17 00:00:00 2001 From: Andrew Thompson Date: Sun, 3 Feb 2019 18:08:20 -0800 Subject: [PATCH 21/35] More fighting with report_cb --- src/lager_logger_formatter.erl | 16 ++++++++-------- 1 file changed, 8 insertions(+), 8 deletions(-) diff --git a/src/lager_logger_formatter.erl b/src/lager_logger_formatter.erl index c081ec43..34b60101 100644 --- a/src/lager_logger_formatter.erl +++ b/src/lager_logger_formatter.erl @@ -4,22 +4,22 @@ -export([report_cb/1, format/2]).%, check_config/1]). -report_cb(#{msg := {report, #{label := {gen_server, terminate}, name := Name, reason := Reason}}}) -> +report_cb(#{label := {gen_server, terminate}, name := Name, reason := Reason}) -> {_Md, Formatted} = error_logger_lager_h:format_reason_md(Reason), {"gen_server ~w terminated with reason: ~s", [Name, Formatted]}; -report_cb(#{msg := {report, #{label := {gen_fsm, terminate}, name := Name, state_name := StateName, reason := Reason}}}) -> +report_cb(#{label := {gen_fsm, terminate}, name := Name, state_name := StateName, reason := Reason}) -> {_Md, Formatted} = error_logger_lager_h:format_reason_md(Reason), {"gen_fsm ~w in state ~w terminated with reason: ~s", [Name, StateName, Formatted]}; -report_cb(#{msg := {report, #{label := {gen_event, terminate}, name := Name, handler := Handler, reason := Reason}}}) -> +report_cb(#{label := {gen_event, terminate}, name := Name, handler := Handler, reason := Reason}) -> {_Md, Formatted} = error_logger_lager_h:format_reason_md(Reason), {"gen_event ~w installed in ~w terminated with reason: ~s", [Handler, Name, Formatted]}; -report_cb(#{msg := {report, #{label := {gen_statem, terminate}, name := Name, reason := Reason}}}) -> +report_cb(#{label := {gen_statem, terminate}, name := Name, reason := Reason}) -> {_Md, Formatted} = error_logger_lager_h:format_reason_md(Reason), %% XXX I can't find the FSM statename in the error report, maybe it should be added {"gen_statem ~w terminated with reason: ~s", [Name, Formatted]}; report_cb(#{msg := {report, #{label := {Behaviour, no_handle_info}, mod := Mod, msg := Msg}}}) -> {"undefined handle_info for ~p in ~s ~p", [Msg, Behaviour, Mod]}; -report_cb(#{msg := {report, #{label := {supervisor, progress}, report := Report}}}) -> +report_cb(#{label := {supervisor, progress}, report := Report}) -> case application:get_env(lager, suppress_supervisor_start_stop, false) of true -> {"", []}; @@ -43,7 +43,7 @@ report_cb(#{msg := {report, #{label := {supervisor, progress}, report := Report} end end end; -report_cb(#{msg := {report, #{label := {supervisor, _Error}, report := Report}}}) -> +report_cb(#{label := {supervisor, _Error}, report := Report}) -> {supervisor, Name} = lists:keyfind(supervisor, 1, Report), {reason, Reason} = lists:keyfind(reason, 1, Report), {_Md, Formatted} = error_logger_lager_h:format_reason_md(Reason), @@ -63,7 +63,7 @@ report_cb(#{msg := {report, #{label := {supervisor, _Error}, report := Report}}} {"Supervisor ~w had ~p ~p with reason ~s", [Name, ChildID, ErrorContext, Formatted]} end end; -report_cb(#{msg := {report, #{label := {application_controller, progress}, report := Report}}}) -> +report_cb(#{label := {application_controller, progress}, report := Report}) -> case application:get_env(lager, suppress_application_start_stop, false) of true -> {"", []}; false -> @@ -71,7 +71,7 @@ report_cb(#{msg := {report, #{label := {application_controller, progress}, repor {started_at, Node} = lists:keyfind(started_at, 1, Report), {"Application ~w started on node ~w", [Name, Node]} end; -report_cb(#{msg := {report, #{label := {application_controller, exit}, report := Report}}}) -> +report_cb(#{label := {application_controller, exit}, report := Report}) -> {exited, Reason} = lists:keyfind(exited, 1, Report), case application:get_env(lager, suppress_application_start_stop) of {ok, true} when Reason == stopped -> From ce11e41ea9da03c55ebc2d00632c1e4a6e610630 Mon Sep 17 00:00:00 2001 From: Andrew Thompson Date: Sun, 3 Feb 2019 18:23:25 -0800 Subject: [PATCH 22/35] Use report_cb from config or from metadata --- src/lager_logger_formatter.erl | 10 +++++++--- 1 file changed, 7 insertions(+), 3 deletions(-) diff --git a/src/lager_logger_formatter.erl b/src/lager_logger_formatter.erl index 34b60101..c399d6e8 100644 --- a/src/lager_logger_formatter.erl +++ b/src/lager_logger_formatter.erl @@ -83,9 +83,13 @@ report_cb(#{label := {application_controller, exit}, report := Report}) -> end. %% TODO handle proc_lib crash -format(#{level := _Level, msg := {report, Report}, meta := _Metadata}, _Config) -> - %do_format(Level, (maps:get(report_cb, Metadata))(Report), Metadata, Config); - io_lib:format("REPORT ~p~n", [Report]); +format(#{msg := {report, _Report}, meta := Metadata} = Event, #{report_cb := Fun} = Config) when is_function(Fun, 1); is_function(Fun, 2) -> + format(Event#{meta => Metadata#{report_cb => Fun}}, maps:remove(report_cb, Config)); +format(#{level := _Level, msg := {report, Report}, meta := #{report_cb := Fun}} = Event, Config) when is_function(Fun, 1) -> + case Fun(Report) of + {Format, Args} when is_list(Format), is_list(Args) -> + format(Event#{msg => {Format, Args}}, Config) + end; format(#{level := Level, msg := {string, String}, meta := Metadata}, Config) -> do_format(Level, String, Metadata, Config); format(#{level := Level, msg := {FmtStr, FmtArgs}, meta := Metadata}, Config) -> From 7af01ccab764c5cd19cf9fc468a8a6adbd25ae3d Mon Sep 17 00:00:00 2001 From: Andrew Thompson Date: Sat, 9 Feb 2019 10:22:53 -0800 Subject: [PATCH 23/35] Try to supress log messages better --- src/lager_logger_formatter.erl | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/src/lager_logger_formatter.erl b/src/lager_logger_formatter.erl index c399d6e8..95db56f3 100644 --- a/src/lager_logger_formatter.erl +++ b/src/lager_logger_formatter.erl @@ -22,7 +22,7 @@ report_cb(#{msg := {report, #{label := {Behaviour, no_handle_info}, mod := Mod, report_cb(#{label := {supervisor, progress}, report := Report}) -> case application:get_env(lager, suppress_supervisor_start_stop, false) of true -> - {"", []}; + ""; false -> {supervisor, Name} = lists:keyfind(supervisor, 1, Report), {started, Started} = lists:keyfind(started, 1, Report), @@ -65,7 +65,7 @@ report_cb(#{label := {supervisor, _Error}, report := Report}) -> end; report_cb(#{label := {application_controller, progress}, report := Report}) -> case application:get_env(lager, suppress_application_start_stop, false) of - true -> {"", []}; + true -> ""; false -> {application, Name} = lists:keyfind(application, 1, Report), {started_at, Node} = lists:keyfind(started_at, 1, Report), @@ -75,7 +75,7 @@ report_cb(#{label := {application_controller, exit}, report := Report}) -> {exited, Reason} = lists:keyfind(exited, 1, Report), case application:get_env(lager, suppress_application_start_stop) of {ok, true} when Reason == stopped -> - {"", []}; + ""; _ -> {application, Name} = lists:keyfind(application, 1, Report), {_Md, Formatted} = error_logger_lager_h:format_reason_md(Reason), From 566d0f386b58cdd0c7e1ee8c16e33ab0e4838aaa Mon Sep 17 00:00:00 2001 From: Andrew Thompson Date: Sat, 9 Feb 2019 10:24:33 -0800 Subject: [PATCH 24/35] Fix --- src/lager_logger_formatter.erl | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/src/lager_logger_formatter.erl b/src/lager_logger_formatter.erl index 95db56f3..63ed2200 100644 --- a/src/lager_logger_formatter.erl +++ b/src/lager_logger_formatter.erl @@ -88,7 +88,9 @@ format(#{msg := {report, _Report}, meta := Metadata} = Event, #{report_cb := Fun format(#{level := _Level, msg := {report, Report}, meta := #{report_cb := Fun}} = Event, Config) when is_function(Fun, 1) -> case Fun(Report) of {Format, Args} when is_list(Format), is_list(Args) -> - format(Event#{msg => {Format, Args}}, Config) + format(Event#{msg => {Format, Args}}, Config); + String -> + format(Event#{msg => String}, Config) end; format(#{level := Level, msg := {string, String}, meta := Metadata}, Config) -> do_format(Level, String, Metadata, Config); From 60f6b38842b022869dc554e26ae0de6eba4921ba Mon Sep 17 00:00:00 2001 From: Andrew Thompson Date: Sat, 9 Feb 2019 10:48:55 -0800 Subject: [PATCH 25/35] Typo --- src/lager_logger_formatter.erl | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/lager_logger_formatter.erl b/src/lager_logger_formatter.erl index 63ed2200..577b954e 100644 --- a/src/lager_logger_formatter.erl +++ b/src/lager_logger_formatter.erl @@ -90,7 +90,7 @@ format(#{level := _Level, msg := {report, Report}, meta := #{report_cb := Fun}} {Format, Args} when is_list(Format), is_list(Args) -> format(Event#{msg => {Format, Args}}, Config); String -> - format(Event#{msg => String}, Config) + format(Event#{msg => {string, String}}, Config) end; format(#{level := Level, msg := {string, String}, meta := Metadata}, Config) -> do_format(Level, String, Metadata, Config); From 225990798f6dbbf8a846a9745b8fac124598f78a Mon Sep 17 00:00:00 2001 From: Andrew Thompson Date: Sat, 9 Feb 2019 10:50:59 -0800 Subject: [PATCH 26/35] Fix --- src/lager_logger_formatter.erl | 2 ++ 1 file changed, 2 insertions(+) diff --git a/src/lager_logger_formatter.erl b/src/lager_logger_formatter.erl index 577b954e..55035266 100644 --- a/src/lager_logger_formatter.erl +++ b/src/lager_logger_formatter.erl @@ -87,8 +87,10 @@ format(#{msg := {report, _Report}, meta := Metadata} = Event, #{report_cb := Fun format(Event#{meta => Metadata#{report_cb => Fun}}, maps:remove(report_cb, Config)); format(#{level := _Level, msg := {report, Report}, meta := #{report_cb := Fun}} = Event, Config) when is_function(Fun, 1) -> case Fun(Report) of + {"", []} -> ""; {Format, Args} when is_list(Format), is_list(Args) -> format(Event#{msg => {Format, Args}}, Config); + "" -> ""; String -> format(Event#{msg => {string, String}}, Config) end; From 3d38191ceeb90b7bec05277c36649b2b50ed95ce Mon Sep 17 00:00:00 2001 From: Andrew Thompson Date: Sat, 9 Feb 2019 13:22:27 -0800 Subject: [PATCH 27/35] Fix --- src/lager_logger_formatter.erl | 11 ++++------- 1 file changed, 4 insertions(+), 7 deletions(-) diff --git a/src/lager_logger_formatter.erl b/src/lager_logger_formatter.erl index 55035266..9871c83b 100644 --- a/src/lager_logger_formatter.erl +++ b/src/lager_logger_formatter.erl @@ -22,7 +22,7 @@ report_cb(#{msg := {report, #{label := {Behaviour, no_handle_info}, mod := Mod, report_cb(#{label := {supervisor, progress}, report := Report}) -> case application:get_env(lager, suppress_supervisor_start_stop, false) of true -> - ""; + {"", []}; false -> {supervisor, Name} = lists:keyfind(supervisor, 1, Report), {started, Started} = lists:keyfind(started, 1, Report), @@ -65,7 +65,7 @@ report_cb(#{label := {supervisor, _Error}, report := Report}) -> end; report_cb(#{label := {application_controller, progress}, report := Report}) -> case application:get_env(lager, suppress_application_start_stop, false) of - true -> ""; + true -> {"", []}; false -> {application, Name} = lists:keyfind(application, 1, Report), {started_at, Node} = lists:keyfind(started_at, 1, Report), @@ -75,7 +75,7 @@ report_cb(#{label := {application_controller, exit}, report := Report}) -> {exited, Reason} = lists:keyfind(exited, 1, Report), case application:get_env(lager, suppress_application_start_stop) of {ok, true} when Reason == stopped -> - ""; + {"", []}; _ -> {application, Name} = lists:keyfind(application, 1, Report), {_Md, Formatted} = error_logger_lager_h:format_reason_md(Reason), @@ -89,10 +89,7 @@ format(#{level := _Level, msg := {report, Report}, meta := #{report_cb := Fun}} case Fun(Report) of {"", []} -> ""; {Format, Args} when is_list(Format), is_list(Args) -> - format(Event#{msg => {Format, Args}}, Config); - "" -> ""; - String -> - format(Event#{msg => {string, String}}, Config) + format(Event#{msg => {Format, Args}}, Config) end; format(#{level := Level, msg := {string, String}, meta := Metadata}, Config) -> do_format(Level, String, Metadata, Config); From 3c275e4399a1b8f8cb3434c46b9135909e865762 Mon Sep 17 00:00:00 2001 From: Andrew Thompson Date: Sat, 23 Feb 2019 18:47:42 -0800 Subject: [PATCH 28/35] Use better function --- src/lager_logger_formatter.erl | 12 ++++++------ 1 file changed, 6 insertions(+), 6 deletions(-) diff --git a/src/lager_logger_formatter.erl b/src/lager_logger_formatter.erl index 9871c83b..f60febcd 100644 --- a/src/lager_logger_formatter.erl +++ b/src/lager_logger_formatter.erl @@ -5,16 +5,16 @@ -export([report_cb/1, format/2]).%, check_config/1]). report_cb(#{label := {gen_server, terminate}, name := Name, reason := Reason}) -> - {_Md, Formatted} = error_logger_lager_h:format_reason_md(Reason), + Formatted = error_logger_lager_h:format_reason(Reason), {"gen_server ~w terminated with reason: ~s", [Name, Formatted]}; report_cb(#{label := {gen_fsm, terminate}, name := Name, state_name := StateName, reason := Reason}) -> - {_Md, Formatted} = error_logger_lager_h:format_reason_md(Reason), + Formatted = error_logger_lager_h:format_reason(Reason), {"gen_fsm ~w in state ~w terminated with reason: ~s", [Name, StateName, Formatted]}; report_cb(#{label := {gen_event, terminate}, name := Name, handler := Handler, reason := Reason}) -> - {_Md, Formatted} = error_logger_lager_h:format_reason_md(Reason), + Formatted = error_logger_lager_h:format_reason(Reason), {"gen_event ~w installed in ~w terminated with reason: ~s", [Handler, Name, Formatted]}; report_cb(#{label := {gen_statem, terminate}, name := Name, reason := Reason}) -> - {_Md, Formatted} = error_logger_lager_h:format_reason_md(Reason), + Formatted = error_logger_lager_h:format_reason(Reason), %% XXX I can't find the FSM statename in the error report, maybe it should be added {"gen_statem ~w terminated with reason: ~s", [Name, Formatted]}; report_cb(#{msg := {report, #{label := {Behaviour, no_handle_info}, mod := Mod, msg := Msg}}}) -> @@ -46,7 +46,7 @@ report_cb(#{label := {supervisor, progress}, report := Report}) -> report_cb(#{label := {supervisor, _Error}, report := Report}) -> {supervisor, Name} = lists:keyfind(supervisor, 1, Report), {reason, Reason} = lists:keyfind(reason, 1, Report), - {_Md, Formatted} = error_logger_lager_h:format_reason_md(Reason), + Formatted = error_logger_lager_h:format_reason(Reason), {errorContext, ErrorContext} = lists:keyfind(errorContext, 1, Report), {offender, Offender} = lists:keyfind(offender, 1, Report), case lists:keyfind(mod, 1, Offender) of @@ -78,7 +78,7 @@ report_cb(#{label := {application_controller, exit}, report := Report}) -> {"", []}; _ -> {application, Name} = lists:keyfind(application, 1, Report), - {_Md, Formatted} = error_logger_lager_h:format_reason_md(Reason), + Formatted = error_logger_lager_h:format_reason(Reason), {"Application ~w exited with reason: ~s", [Name, Formatted]} end. %% TODO handle proc_lib crash From 0803df062045e22b83503c582aa904dcb45cfc2e Mon Sep 17 00:00:00 2001 From: Andrew Thompson Date: Sun, 1 Mar 2020 14:42:07 -0800 Subject: [PATCH 29/35] How the heck did this slip in? --- src/lager_logger_formatter.erl | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/src/lager_logger_formatter.erl b/src/lager_logger_formatter.erl index f60febcd..d8f2e2ae 100644 --- a/src/lager_logger_formatter.erl +++ b/src/lager_logger_formatter.erl @@ -101,8 +101,8 @@ do_format(Level, Msg, Metadata, Config) -> FormatModule = maps:get(formatter, Config, lager_default_formatter), Timestamp = maps:get(time, Metadata), MegaSecs = Timestamp div 1000000000000, - Secs = (1549018253268942 rem 1000000000000) div 1000000, - MicroSecs = (1549018253268942 rem 1000000000000) rem 1000000, + Secs = (Timestamp rem 1000000000000) div 1000000, + MicroSecs = (Timestamp rem 1000000000000) rem 1000000, {Colors, End} = case maps:get(colors, Config, false) of true -> {application:get_env(lager, colors, []), "\e[0m"}; From 0dff9110517a5572d16356c9a288c081669b1c3c Mon Sep 17 00:00:00 2001 From: Andrew Thompson Date: Sun, 1 Mar 2020 18:09:01 -0800 Subject: [PATCH 30/35] Add some docs --- README.md | 59 +++++++++++++++++++++++++++++++++++++++++++++++++++++++ 1 file changed, 59 insertions(+) diff --git a/README.md b/README.md index 1d6b2208..9f70145c 100644 --- a/README.md +++ b/README.md @@ -1138,6 +1138,65 @@ Example Usage: :lager.warning('Some message with a term: ~p', [term]) ``` +Integration with OTP's Logger +----------------------------- + +Now that OTP includes a modern log event pipeline, the Lager project has decided +to work on winding down Lager development in favor of unifying the Erlang +ecosystem behind Logger. To that end, Lager now supports being configured to use +its parse transform to rewrite lager calls into logger calls. To enable this +mode, the following changes are required: + +In sys.config: +``` +[ + {kernel, + [{logger, + [{handler, default, logger_std_h, + #{formatter => {lager_logger_formatter, #{report_cb => fun lager_logger_formatter:report_cb/1}}}}, + ]}]}, +... +{lager, [ + {lager_use_logger, true}, + ... +]} +] +``` + +The logger stanza changes are not needed if you wish to use logger's default +formatter. + +In your applications top level rebar.config (probably requires rebar3): + +``` +{overrides, [{add, [{erl_opts, [{lager_use_logger, true}]}]}]}. +``` + +This will force the parse transform configuration to apply to all the +dependencies as well. Make sure you've defined the lager version in your +toplevel application's rebar.config and that the version is high enough to +support these options. A toplevel dependency will override any lager +dependencies in any of your application's dependencies and thus ensure the parse +transform is the right version. + +XXX the following is not yet implemented: + +To generate a logger configuration from your lager configuration you can do: + +``` +lager:generate_logger_configuration() +``` + +If you wish to simply use your existing lager configuration as is, and have +lager configure logger you can, in your sys.config in the lager stanza: + +``` +{lager, [ + {configure_logger, true}, + ... +]} +``` + 3.x Changelog ------------- 3.6.8 - 21 December 2018 From c62732dab3f424a210760805c9756180290d925d Mon Sep 17 00:00:00 2001 From: Andrew Thompson Date: Sun, 1 Mar 2020 19:08:42 -0800 Subject: [PATCH 31/35] WIP function to turn lager config into logger config --- src/lager.erl | 53 ++++++++++++++++++++++++++++++++++++++++++++++- src/lager_app.erl | 6 +++++- 2 files changed, 57 insertions(+), 2 deletions(-) diff --git a/src/lager.erl b/src/lager.erl index c8ffb0ee..025f7684 100644 --- a/src/lager.erl +++ b/src/lager.erl @@ -36,7 +36,8 @@ get_loglevel/1, get_loglevel/2, set_loglevel/2, set_loglevel/3, set_loglevel/4, get_loglevels/1, update_loglevel_config/1, posix_error/1, set_loghwm/2, set_loghwm/3, set_loghwm/4, safe_format/3, safe_format_chop/3, unsafe_format/2, dispatch_log/5, dispatch_log/7, dispatch_log/9, - do_log/9, do_log/10, do_log_unsafe/10, pr/2, pr/3, pr_stacktrace/1, pr_stacktrace/2]). + do_log/9, do_log/10, do_log_unsafe/10, pr/2, pr/3, pr_stacktrace/1, pr_stacktrace/2, + configure_logger/0]). -type log_level() :: none | debug | info | notice | warning | error | critical | alert | emergency. -type log_level_number() :: 0..7. @@ -689,6 +690,56 @@ rotate_handler(Handler) -> rotate_handler(Handler, Sink) -> gen_event:call(Sink, Handler, rotate, ?ROTATE_TIMEOUT). + +configure_logger() -> + Handlers = application:get_env(lager, handlers, lager_app:default_handlers()), + WhitelistedLoggerHandlers = application:get_env(lager, whitelisted_logger_handlers, []), + [ ok = logger:remove_handler(Id) || #{id := Id} <- logger:get_handler_config(), not lists:member(Id, WhitelistedLoggerHandlers) ], + add_logger_handlers(Handlers). + +add_logger_handlers([]) -> + ok; +add_logger_handlers([{lager_console_backend, Config}|Tail]) -> + Level = proplists:get_value(level, Config, info), + Formatter = proplists:get_value(formatter, Config, lager_default_formatter), + FormatterConfig = proplists:get_value(formatter_config, Config, []), + logger:add_handler(console, logger_std_h, #{level => Level, formatter => + {lager_logger_formatter, #{report_cb => fun lager_logger_formatter:report_cb/1, + formatter => Formatter, + formatter_config => FormatterConfig}}}), + PriConfig = #{level := CurrentLevel} = logger:get_primary_config(), + case lager_util:level_to_num(Level) > lager_util:level_to_num(CurrentLevel) of + true -> + logger:set_primary_config(maps:merge(PriConfig, #{level => Level})); + false -> + ok + end, + add_logger_handlers(Tail); +add_logger_handlers([{lager_file_backend, Config}|Tail]) -> + Level = proplists:get_value(level, Config, info), + File = proplists:get_value(file, Config), + Size = proplists:get_value(size, Config), + Count = proplists:get_value(count, Config), + Formatter = proplists:get_value(formatter, Config, lager_default_formatter), + FormatterConfig = proplists:get_value(formatter_config, Config, []), + logger:add_handler(list_to_atom(File), logger_disk_log_h, #{level => Level, + file => File, + max_no_files => Count, + max_no_bytes => Size, + formatter => + {lager_logger_formatter, #{report_cb => fun lager_logger_formatter:report_cb/1, + formatter => Formatter, + formatter_config => FormatterConfig}}}), + PriConfig = #{level := CurrentLevel} = logger:get_primary_config(), + case lager_util:level_to_num(Level) > lager_util:level_to_num(CurrentLevel) of + true -> + logger:set_primary_config(maps:merge(PriConfig, #{level => Level})); + false -> + ok + end, + add_logger_handlers(Tail). + + %% @private trace_func(#trace_func_state_v1{pid=Pid, level=Level, format_string=Fmt}=FuncState, Event, ProcState) -> lager:log(Level, Pid, Fmt, [Event, ProcState]), diff --git a/src/lager_app.erl b/src/lager_app.erl index 53f880d5..78150052 100644 --- a/src/lager_app.erl +++ b/src/lager_app.erl @@ -31,7 +31,8 @@ start_handler/3, configure_sink/2, stop/1, - boot/1]). + boot/1, + default_handlers/0]). %% The `application:get_env/3` compatibility wrapper was useful %% for other modules in r15 and before @@ -281,6 +282,9 @@ stop(Handlers) -> error_logger:add_report_handler(Handler) end, Handlers). +default_handlers() -> + ?DEFAULT_HANDLER_CONF. + expand_handlers([]) -> []; expand_handlers([{lager_file_backend, [{Key, _Value}|_]=Config}|T]) when is_atom(Key) -> From 67466436aa40a968a104c5babb0c6f4bfae23fec Mon Sep 17 00:00:00 2001 From: Andrew Thompson Date: Sun, 1 Mar 2020 19:56:49 -0800 Subject: [PATCH 32/35] Rework logger configuration and add logger config generator --- README.md | 8 +++-- src/lager.erl | 76 ++++++++++++++++++++++++++--------------------- src/lager_app.erl | 6 ++++ 3 files changed, 54 insertions(+), 36 deletions(-) diff --git a/README.md b/README.md index 9f70145c..e5585d26 100644 --- a/README.md +++ b/README.md @@ -1179,8 +1179,6 @@ support these options. A toplevel dependency will override any lager dependencies in any of your application's dependencies and thus ensure the parse transform is the right version. -XXX the following is not yet implemented: - To generate a logger configuration from your lager configuration you can do: ``` @@ -1197,6 +1195,12 @@ lager configure logger you can, in your sys.config in the lager stanza: ]} ``` +Alternatively you can use: + +``` +lager:configure_logger() +``` + 3.x Changelog ------------- 3.6.8 - 21 December 2018 diff --git a/src/lager.erl b/src/lager.erl index 025f7684..a905904c 100644 --- a/src/lager.erl +++ b/src/lager.erl @@ -37,7 +37,7 @@ update_loglevel_config/1, posix_error/1, set_loghwm/2, set_loghwm/3, set_loghwm/4, safe_format/3, safe_format_chop/3, unsafe_format/2, dispatch_log/5, dispatch_log/7, dispatch_log/9, do_log/9, do_log/10, do_log_unsafe/10, pr/2, pr/3, pr_stacktrace/1, pr_stacktrace/2, - configure_logger/0]). + generate_logger_config/0, configure_logger/0]). -type log_level() :: none | debug | info | notice | warning | error | critical | alert | emergency. -type log_level_number() :: 0..7. @@ -690,54 +690,62 @@ rotate_handler(Handler) -> rotate_handler(Handler, Sink) -> gen_event:call(Sink, Handler, rotate, ?ROTATE_TIMEOUT). +generate_logger_config() -> + Handlers = application:get_env(lager, handlers, lager_app:default_handlers()), + {Level, NewHandlers} = generate_logger_handlers(Handlers, {notice, []}), + {kernel, [{logger_level, Level}, {logger, NewHandlers}]}. configure_logger() -> Handlers = application:get_env(lager, handlers, lager_app:default_handlers()), WhitelistedLoggerHandlers = application:get_env(lager, whitelisted_logger_handlers, []), [ ok = logger:remove_handler(Id) || #{id := Id} <- logger:get_handler_config(), not lists:member(Id, WhitelistedLoggerHandlers) ], - add_logger_handlers(Handlers). + {Level, NewHandlers} = generate_logger_handlers(Handlers, {notice, []}), + logger:set_primary_config(maps:merge(logger:get_primary_config(), #{level => Level})), + [ ok = logger:add_handler(HandlerId, HandlerModule, HandlerConfig) || {handler, HandlerId, HandlerModule, HandlerConfig} <- NewHandlers ], + ok. -add_logger_handlers([]) -> - ok; -add_logger_handlers([{lager_console_backend, Config}|Tail]) -> +generate_logger_handlers([], Acc) -> + Acc; +generate_logger_handlers([{lager_console_backend, Config}|Tail], {CurrentLevel, Acc}) -> Level = proplists:get_value(level, Config, info), Formatter = proplists:get_value(formatter, Config, lager_default_formatter), FormatterConfig = proplists:get_value(formatter_config, Config, []), - logger:add_handler(console, logger_std_h, #{level => Level, formatter => - {lager_logger_formatter, #{report_cb => fun lager_logger_formatter:report_cb/1, - formatter => Formatter, - formatter_config => FormatterConfig}}}), - PriConfig = #{level := CurrentLevel} = logger:get_primary_config(), - case lager_util:level_to_num(Level) > lager_util:level_to_num(CurrentLevel) of - true -> - logger:set_primary_config(maps:merge(PriConfig, #{level => Level})); - false -> - ok - end, - add_logger_handlers(Tail); -add_logger_handlers([{lager_file_backend, Config}|Tail]) -> + Handler = {handler, console, logger_std_h, #{level => Level, formatter => + {lager_logger_formatter, #{report_cb => fun lager_logger_formatter:report_cb/1, + formatter => Formatter, + formatter_config => FormatterConfig}}}}, + NewLevel = case lager_util:level_to_num(Level) > lager_util:level_to_num(CurrentLevel) of + true -> + Level; + false -> + CurrentLevel + end, + generate_logger_handlers(Tail, {NewLevel, [Handler|Acc]}); +generate_logger_handlers([{lager_file_backend, Config}|Tail], {CurrentLevel, Acc}) -> Level = proplists:get_value(level, Config, info), File = proplists:get_value(file, Config), + LogRoot = application:get_env(lager, log_root, ""), Size = proplists:get_value(size, Config), Count = proplists:get_value(count, Config), Formatter = proplists:get_value(formatter, Config, lager_default_formatter), FormatterConfig = proplists:get_value(formatter_config, Config, []), - logger:add_handler(list_to_atom(File), logger_disk_log_h, #{level => Level, - file => File, - max_no_files => Count, - max_no_bytes => Size, - formatter => - {lager_logger_formatter, #{report_cb => fun lager_logger_formatter:report_cb/1, - formatter => Formatter, - formatter_config => FormatterConfig}}}), - PriConfig = #{level := CurrentLevel} = logger:get_primary_config(), - case lager_util:level_to_num(Level) > lager_util:level_to_num(CurrentLevel) of - true -> - logger:set_primary_config(maps:merge(PriConfig, #{level => Level})); - false -> - ok - end, - add_logger_handlers(Tail). + %% XXX I don't think disk_log is suitable as it is, we should provide a logger compatible version of + %% lager's file_backend and try to patch disk_log upstream + Handler = {handler, list_to_atom(File), logger_disk_log_h, #{level => Level, + file => filename:join(LogRoot, File), + max_no_files => Count, + max_no_bytes => Size, + formatter => + {lager_logger_formatter, #{report_cb => fun lager_logger_formatter:report_cb/1, + formatter => Formatter, + formatter_config => FormatterConfig}}}}, + NewLevel = case lager_util:level_to_num(Level) > lager_util:level_to_num(CurrentLevel) of + true -> + Level; + false -> + CurrentLevel + end, + generate_logger_handlers(Tail, {NewLevel, [Handler|Acc]}). %% @private diff --git a/src/lager_app.erl b/src/lager_app.erl index 78150052..e0d50948 100644 --- a/src/lager_app.erl +++ b/src/lager_app.erl @@ -235,6 +235,12 @@ start(_StartType, _StartArgs) -> clean_up_config_checks(), {ok, Pid, SavedHandlers}; true -> + case application:get_env(lager, configure_logger, false) of + true -> + ok = lager:configure_logger(); + false -> + ok + end, {ok, Pid} end. From 244463e954027936ea69c2df55f94397088f7140 Mon Sep 17 00:00:00 2001 From: Andrew Thompson Date: Mon, 2 Mar 2020 08:23:26 -0800 Subject: [PATCH 33/35] logger_std_h supports file rotation better than disk_log, so use that --- src/lager.erl | 25 +++++++++++++------------ 1 file changed, 13 insertions(+), 12 deletions(-) diff --git a/src/lager.erl b/src/lager.erl index a905904c..2b6ba210 100644 --- a/src/lager.erl +++ b/src/lager.erl @@ -725,20 +725,21 @@ generate_logger_handlers([{lager_file_backend, Config}|Tail], {CurrentLevel, Acc Level = proplists:get_value(level, Config, info), File = proplists:get_value(file, Config), LogRoot = application:get_env(lager, log_root, ""), - Size = proplists:get_value(size, Config), - Count = proplists:get_value(count, Config), + Size = proplists:get_value(size, Config, 10485760), + Count = proplists:get_value(count, Config, 5), Formatter = proplists:get_value(formatter, Config, lager_default_formatter), FormatterConfig = proplists:get_value(formatter_config, Config, []), - %% XXX I don't think disk_log is suitable as it is, we should provide a logger compatible version of - %% lager's file_backend and try to patch disk_log upstream - Handler = {handler, list_to_atom(File), logger_disk_log_h, #{level => Level, - file => filename:join(LogRoot, File), - max_no_files => Count, - max_no_bytes => Size, - formatter => - {lager_logger_formatter, #{report_cb => fun lager_logger_formatter:report_cb/1, - formatter => Formatter, - formatter_config => FormatterConfig}}}}, + %% the standard log handler has a file mode with size based rotation support that is much saner than + %% disk_log's, so use that here + Handler = {handler, list_to_atom(File), logger_std_h, #{level => Level, + config => #{type => file, + file => filename:join(LogRoot, File), + max_no_files => Count, + max_no_bytes => Size}, + formatter => + {lager_logger_formatter, #{report_cb => fun lager_logger_formatter:report_cb/1, + formatter => Formatter, + formatter_config => FormatterConfig}}}}, NewLevel = case lager_util:level_to_num(Level) > lager_util:level_to_num(CurrentLevel) of true -> Level; From 1121d28a373445250a11e18c27d6fef14f08d1d4 Mon Sep 17 00:00:00 2001 From: Andrew Thompson Date: Wed, 2 Oct 2024 15:17:55 -0700 Subject: [PATCH 34/35] Handle columns in transform --- src/lager_transform.erl | 2 ++ 1 file changed, 2 insertions(+) diff --git a/src/lager_transform.erl b/src/lager_transform.erl index 8f5a483d..7e449ac9 100644 --- a/src/lager_transform.erl +++ b/src/lager_transform.erl @@ -301,6 +301,8 @@ handle_args(DefaultAttrs, Line, [Arg1, Arg2]) -> handle_args(DefaultAttrs, _Line, [Attrs, Format, Args]) -> {concat_lists(Attrs, DefaultAttrs), Format, Args}. +make_varname(Prefix, {Line, Column}) -> + list_to_atom(Prefix ++ atom_to_list(get(module)) ++ integer_to_list(Line) ++ "_" ++ integer_to_list(Column)); make_varname(Prefix, Line) -> list_to_atom(Prefix ++ atom_to_list(get(module)) ++ integer_to_list(Line)). From 20ee7596867705d8ec9f6194bc937cc8250c6e33 Mon Sep 17 00:00:00 2001 From: Andrew Thompson Date: Tue, 15 Oct 2024 10:04:30 -0700 Subject: [PATCH 35/35] Attempt to handle modern wacky crash reports better --- src/error_logger_lager_h.erl | 62 +++++++++++++++++++++++++++++------- 1 file changed, 50 insertions(+), 12 deletions(-) diff --git a/src/error_logger_lager_h.erl b/src/error_logger_lager_h.erl index 72ff9d94..fd4fca21 100644 --- a/src/error_logger_lager_h.erl +++ b/src/error_logger_lager_h.erl @@ -185,6 +185,7 @@ log_event(Event, #state{sink=Sink} = State) -> case {FormatRaw, Fmt} of {false, "** Generic server "++_} -> %% gen_server terminate + ?CRASH_LOG(Event), {Reason, Name} = case Args of [N, _Msg, _State, R] -> {R, N}; @@ -196,31 +197,68 @@ log_event(Event, #state{sink=Sink} = State) -> %% TODO do something with them {R, N} end, - ?CRASH_LOG(Event), {Md, Formatted} = format_reason_md(Reason), ?LOGFMT(Sink, error, [{pid, Pid}, {name, Name} | Md], "gen_server ~w terminated with reason: ~s", [Name, Formatted]); {false, "** State machine "++_} -> + ?CRASH_LOG(Event), %% Check if the terminated process is gen_fsm or gen_statem %% since they generate the same exit message - {Type, Name, StateName, Reason} = case Args of - [TName, _Msg, TStateName, _StateData, TReason] -> - {gen_fsm, TName, TStateName, TReason}; - [TName, _Msg, {TStateName, _StateData}, _ExitType, TReason, _FsmType, Stacktrace] -> - {gen_statem, TName, TStateName, {TReason, Stacktrace}}; - [TName, _Msg, [{TStateName, _StateData}], _ExitType, TReason, _FsmType, Stacktrace] -> - %% sometimes gen_statem wraps its statename/data in a list for some reason??? - {gen_statem, TName, TStateName, {TReason, Stacktrace}} - end, + + %% gen_statem has a variable set of fields it will include + %% so we have to parse the format string to find the ones we want + %% + %% first, get rid of any newline formatters + Fm2 = lists:flatten(string:replace(Fmt, "~n", "", all)), + Tokens = string:tokens(Fm2, "~"), + + + {FormatArgs, _} = lists:foldl(fun(Token, {Acc, [H|T]}) -> + case string:tokens(Token, "**") of + [" State machine "] -> + {maps:put(name, H, Acc), T}; + [_ ," Last event = "] -> + {maps:put(last_event, H, Acc), T}; + [_, " When server state = "] -> + {maps:put(state, H, Acc), T}; + [_, " Reason for termination = "] -> + {maps:put(reason, H, Acc), T}; + [_, " Callback modules = "] -> + {maps:put(callback_modules, H, Acc), T}; + [_, " Callback mode = "] -> + {maps:put(callback_mode, H, Acc), T}; + [_, " Stacktrace =" |_] -> + {maps:put(stacktrace, H, Acc), T}; + [_, " Time-outs: " |_] -> + {maps:put(time_outs, H, Acc), T}; + Unknown -> + {Acc, T} + end; + (_Token, {Acc, []}) -> + {Acc, []} + end, {maps:new(), Args}, Tokens), + + %%{Type, Name, StateName, Reason} = case Args of + %% [TName, _Msg, TStateName, _StateData, TReason] -> + %% {gen_fsm, TName, TStateName, TReason}; + %% [TName, _Msg, {TStateName, _StateData}, _ExitType, TReason, _FsmType, Stacktrace] -> + %% {gen_statem, TName, TStateName, {TReason, Stacktrace}}; + %% [TName, _Msg, [{TStateName, _StateData}], _ExitType, TReason, _FsmType, Stacktrace] -> + %% %% sometimes gen_statem wraps its statename/data in a list for some reason??? + %% {gen_statem, TName, TStateName, {TReason, Stacktrace}} + %%end, + Type = 'state machine', + Name = maps:get(name, FormatArgs), + {StateName, _StateData} = maps:get(state, FormatArgs), + Reason = maps:get(reason, FormatArgs), {Md, Formatted} = format_reason_md(Reason), - ?CRASH_LOG(Event), ?LOGFMT(Sink, error, [{pid, Pid}, {name, Name} | Md], "~s ~w in state ~w terminated with reason: ~s", [Type, Name, StateName, Formatted]); {false, "** gen_event handler"++_} -> %% gen_event handler terminate + ?CRASH_LOG(Event), [ID, Name, _Msg, _State, Reason] = Args, {Md, Formatted} = format_reason_md(Reason), - ?CRASH_LOG(Event), ?LOGFMT(Sink, error, [{pid, Pid}, {name, Name} | Md], "gen_event ~w installed in ~w terminated with reason: ~s", [ID, Name, Formatted]); {false, "** Cowboy handler"++_} ->