From 0415d21669305185ab0b27d495d910fe65af4a77 Mon Sep 17 00:00:00 2001 From: Jason Wagner Date: Thu, 1 Dec 2011 23:51:05 -0500 Subject: [PATCH] Changed the messages sent to the backends to include metadata and separated formatting from the backend. Added documentation, fixed tests, and removed some unused code. --- .gitignore | 1 + README.org | 39 +++ include/lager.hrl | 21 +- src/lager.erl | 98 +++----- src/lager_app.erl | 42 +++- src/lager_backend_utils.erl | 41 +++ src/lager_console_backend.erl | 54 ++-- src/lager_crash_log.erl | 8 +- src/lager_default_formatter.erl | 107 ++++++++ src/lager_file_backend.erl | 65 +++-- src/lager_handler_watcher.erl | 6 +- src/lager_transform.erl | 32 +-- test/lager_test_backend.erl | 427 +++++++++++++------------------- 13 files changed, 546 insertions(+), 395 deletions(-) create mode 100644 src/lager_backend_utils.erl create mode 100644 src/lager_default_formatter.erl diff --git a/.gitignore b/.gitignore index 2b8b8d3..e04c657 100644 --- a/.gitignore +++ b/.gitignore @@ -4,3 +4,4 @@ ebin doc *.swp erl_crash.dump +.project diff --git a/README.org b/README.org index 3ff3ea0..5089a28 100644 --- a/README.org +++ b/README.org @@ -74,6 +74,45 @@ The available configuration options for each backend are listed in their module's documentation. +* Custom Formatting + All loggers have a default formatting that can be overriden. A formatter is any module that + exports format(#lager_log_message{},Config#any()). It is specified as part of the configuration + for the backend: + +#+BEGIN_EXAMPLE + {lager, [ + {handlers, [ + {lager_console_backend, [info, {lager_default_formatter, [time," [",severity,"] ", message, "\n"]}}, + {lager_file_backend, [ + [{"error.log", error, 10485760, "$D0", 5,{lager_default_formatter,[date, " ", time," [",severity,"] ",pid, " ", message, "\n"]}], + {"console.log", info, 10485760, "$D0", 5} + ]} + ]} + ]}. +#+END_EXAMPLE + + Included is lager_default_formatter. This provides a generic, default formatting for log messages using a "semi-iolist" + as configuration. Any iolist allowed elements in the configuration are printed verbatim. Atoms in the configuration + are treated as metadata properties and extracted from the log message. + The metadata properties date,time, message, and severity will always exist. + The properties pid, file, line, module, and function will always exist if the parser transform is used. + +#+BEGIN_EXAMPLE + ["Foo"] -> "Foo", regardless of message content. + [message] -> The content of the logged message, alone. + [{pid,"Unknown Pid"}] -> "" if pid is in the metadata, "Unknown Pid" if not. + [date, " ", time," [",severity,"] ",pid, " ", message, "\n"] -> default formatting if none is provided +#+END_EXAMPLE + + Optionally, a tuple of {atom(),semi-iolist()} + can be used. The atom will look up the property, but if not found it will use the semi-iolist() instead. These fallbacks + can be nested or refer to other properties. + +#+BEGIN_EXAMPLE + [{pid,"Unknown Pid"}] -> "" if pid is in the metadata, "Unknown Pid" if not. + [{server,[$(,{pid,"Unknown Server"},$)]}}] -> user provided server metadata, otherwise "()", otherwise "(Unknown Server)" +#+END_EXAMPLE + * Error logger integration Lager is also supplied with a error_logger handler module that translates traditional erlang error messages into a friendlier format and sends them into diff --git a/include/lager.hrl b/include/lager.hrl index bb42f7b..9bcf558 100644 --- a/include/lager.hrl +++ b/include/lager.hrl @@ -14,6 +14,15 @@ %% specific language governing permissions and limitations %% under the License. +-record(lager_log_message,{ + destinations, + metadata, + severity_as_int, + timestamp, + message + }). + + -define(LEVELS, [debug, info, notice, warning, error, critical, alert, emergency, none]). @@ -55,10 +64,13 @@ lager_util:level_to_num(Level) =< element(1, lager_mochiglobal:get(loglevel, {?LOG_NONE, []}))). -define(NOTIFY(Level, Pid, Format, Args), - gen_event:notify(lager_event, {log, lager_util:level_to_num(Level), - lager_util:format_time(), [io_lib:format("[~p] ", [Level]), - io_lib:format("~p ", [Pid]), io_lib:format(Format, Args)]})). - + gen_event:notify(lager_event,#lager_log_message{destinations=[], + message=io_lib:format(Format,Args), + metadata=[{pid,Pid},{line,?LINE},{file,?FILE},{module,?MODULE}], + timestamp=lager_util:format_time(), + severity_as_int=lager_util:level_to_num(Level) + })). + %% FOR INTERNAL USE ONLY %% internal non-blocking logging call %% there's some special handing for when we try to log (usually errors) while @@ -93,3 +105,4 @@ end end)). -endif. + diff --git a/src/lager.erl b/src/lager.erl index 02b1066..6a451ee 100644 --- a/src/lager.erl +++ b/src/lager.erl @@ -19,15 +19,16 @@ -module(lager). -include("lager.hrl"). +-include_lib("eunit/include/eunit.hrl"). %% API -export([start/0, - log/9, log_dest/10, log/3, log/4, + log/3, log/4, trace_file/2, trace_file/3, trace_console/1, trace_console/2, clear_all_traces/0, stop_trace/1, status/0, get_loglevel/1, set_loglevel/2, set_loglevel/3, get_loglevels/0, minimum_loglevel/1, posix_error/1, - safe_format/3, safe_format_chop/3,dispatch_log/9]). + safe_format/3, safe_format_chop/3,dispatch_log/5]). -type log_level() :: debug | info | notice | warning | error | critical | alert | emergency. -type log_level_number() :: 0..7. @@ -52,69 +53,47 @@ start_ok(App, {error, Reason}) -> erlang:error({app_start_failed, App, Reason}). --spec dispatch_log(log_level(), atom(), atom(), pos_integer(), pid(), list(), string(), list(), integer()) -> - ok | {error, lager_not_running}. +-spec dispatch_log(log_level(), list(), string(), list() | none, integer()) -> ok | {error, lager_not_running}. +dispatch_log(Severity, Metadata, Format, Args, Size) when is_atom(Severity)-> + case whereis(lager_event) of + undefined -> + %% lager isn't running + {error, lager_not_running}; + Pid -> -dispatch_log(Severity, Module, Function, Line, Pid, Traces, Format, Args, TruncSize) -> - {LevelThreshold,TraceFilters} = lager_mochiglobal:get(loglevel,{?LOG_NONE,[]}), - Result= - case LevelThreshold >= lager_util:level_to_num(Severity) of - true -> lager:log(Severity,Module,Function,Line,Pid, - lager_util:maybe_utc(lager_util:localtime_ms()), - Format,Args,TruncSize); - _ -> ok - end, - case TraceFilters of - [] -> Result; - Match when is_list(Match) -> - lager:log_dest(Severity,Module,Function,Line,Pid, - lager_util:maybe_utc(lager_util:localtime_ms()), - lager_util:check_traces(Traces, - lager_util:level_to_num(Severity), - TraceFilters, - []), - Format,Args,TruncSize); - _ -> ok + {LevelThreshold,TraceFilters} = lager_mochiglobal:get(loglevel,{?LOG_NONE,[]}), + SeverityAsInt=lager_util:level_to_num(Severity), + Destinations = case TraceFilters of + [] -> []; + _ -> + lager_util:check_traces(Metadata,SeverityAsInt,TraceFilters,[]) + end, + case (LevelThreshold >= SeverityAsInt orelse Destinations =/= []) of + true -> + Timestamp = lager_util:format_time(), + Msg=case Args of + A when is_list(A) ->safe_format_chop(Format,Args, Size); + _ -> Format + end, + gen_event:sync_notify(Pid, #lager_log_message{destinations=Destinations, + metadata=Metadata, + severity_as_int=SeverityAsInt, + timestamp=Timestamp, + message=Msg}); + _ -> + ok + end end. -%% @private --spec log(log_level(), atom(), atom(), pos_integer(), pid(), tuple(), string(), list(), integer()) -> - ok | {error, lager_not_running}. -log(Level, Module, Function, Line, Pid, Time, Format, Args, TruncSize) -> - Timestamp = lager_util:format_time(Time), - Msg = [["[", atom_to_list(Level), "] "], - io_lib:format("~p@~p:~p:~p ", [Pid, Module, Function, Line]), - safe_format_chop(Format, Args, TruncSize)], - safe_notify({log, lager_util:level_to_num(Level), Timestamp, Msg}). - -%% @private --spec log_dest(log_level(), atom(), atom(), pos_integer(), pid(), tuple(), list(), string(), list(), integer()) -> - ok | {error, lager_not_running}. -log_dest(_Level, _Module, _Function, _Line, _Pid, _Time, [], _Format, _Args, _TruncSize) -> - ok; -log_dest(Level, Module, Function, Line, Pid, Time, Dest, Format, Args, TruncSize) -> - Timestamp = lager_util:format_time(Time), - Msg = [["[", atom_to_list(Level), "] "], - io_lib:format("~p@~p:~p:~p ", [Pid, Module, Function, Line]), - safe_format_chop(Format, Args, TruncSize)], - safe_notify({log, Dest, lager_util:level_to_num(Level), Timestamp, Msg}). - - %% @doc Manually log a message into lager without using the parse transform. -spec log(log_level(), pid(), list()) -> ok | {error, lager_not_running}. log(Level, Pid, Message) -> - Timestamp = lager_util:format_time(), - Msg = [["[", atom_to_list(Level), "] "], io_lib:format("~p ", [Pid]), - safe_format_chop("~s", [Message], 4096)], - safe_notify({log, lager_util:level_to_num(Level), Timestamp, Msg}). + dispatch_log(Level, [{pid,Pid}], Message,none, 4096). %% @doc Manually log a message into lager without using the parse transform. -spec log(log_level(), pid(), string(), list()) -> ok | {error, lager_not_running}. log(Level, Pid, Format, Args) -> - Timestamp = lager_util:format_time(), - Msg = [["[", atom_to_list(Level), "] "], io_lib:format("~p ", [Pid]), - safe_format_chop(Format, Args, 4096)], - safe_notify({log, lager_util:level_to_num(Level), Timestamp, Msg}). + dispatch_log(Level, [{pid,Pid}], Format, Args, 4096). trace_file(File, Filter) -> trace_file(File, Filter, debug). @@ -270,15 +249,6 @@ minimum_loglevel([]) -> minimum_loglevel(Levels) -> erlang:hd(lists:reverse(lists:sort(Levels))). -safe_notify(Event) -> - case whereis(lager_event) of - undefined -> - %% lager isn't running - {error, lager_not_running}; - Pid -> - gen_event:sync_notify(Pid, Event) - end. - %% @doc Print the format string `Fmt' with `Args' safely with a size %% limit of `Limit'. If the format string is invalid, or not enough %% arguments are supplied 'FORMAT ERROR' is printed with the offending diff --git a/src/lager_app.erl b/src/lager_app.erl index 3d9846b..6a402e1 100644 --- a/src/lager_app.erl +++ b/src/lager_app.erl @@ -22,7 +22,9 @@ -behaviour(application). -include("lager.hrl"). - +-ifdef(TEST). +-include_lib("eunit/include/eunit.hrl"). +-endif. -export([start/0, start/2, stop/1]). @@ -77,7 +79,43 @@ stop(Handlers) -> expand_handlers([]) -> []; expand_handlers([{lager_file_backend, Configs}|T]) -> - [{{lager_file_backend, element(1, Config)}, Config} || Config <- Configs] ++ + [ to_config(Config) || Config <- Configs] ++ expand_handlers(T); expand_handlers([H|T]) -> [H | expand_handlers(T)]. + +to_config({Name,Severity}) -> + {{lager_file_backend, Name}, {Name, Severity}}; +to_config({Name,_Severity,_Size,_Rotation,_Count}=Config) -> + {{lager_file_backend, Name}, Config}; +to_config({Name,Severity,Size,Rotation,Count,Format}) -> + {{lager_file_backend, Name}, {Name,Severity,Size,Rotation,Count},Format}. + + + +-ifdef(TEST). +application_config_mangling_test_() -> + [{"Explode the file backend handlers", + ?_assertMatch( + [{lager_console_backend, info}, + {{lager_file_backend,"error.log"},{"error.log",error,10485760, "$D0",5}}, + {{lager_file_backend,"console.log"},{"console.log",info,10485760, "$D0",5}} + ], + expand_handlers([{lager_console_backend, info}, + {lager_file_backend, [ + {"error.log", error, 10485760, "$D0", 5}, + {"console.log", info, 10485760, "$D0", 5} + ]}] + ))}, + {"Explode with formatter info", + ?_assertMatch( + [{{lager_file_backend,"test.log"}, {"test.log", debug, 10485760, "$D0", 5},{lager_default_formatter,["[",severity,"] ", message, "\n"]}}, + {{lager_file_backend,"test2.log"}, {"test2.log",debug, 10485760, "$D0", 5},{lager_default_formatter,["2>[",severity,"] ", message, "\n"]}}], + expand_handlers([{lager_file_backend, [ + {"test.log", debug, 10485760, "$D0", 5,{lager_default_formatter,["[",severity,"] ", message, "\n"]}}, + {"test2.log",debug, 10485760, "$D0", 5,{lager_default_formatter,["2>[",severity,"] ",message, "\n"]}} + ] + }]) + ) + }]. +-endif. diff --git a/src/lager_backend_utils.erl b/src/lager_backend_utils.erl new file mode 100644 index 0000000..d6065de --- /dev/null +++ b/src/lager_backend_utils.erl @@ -0,0 +1,41 @@ +%% Author: jason +%% Created: Jan 16, 2012 +%% Description: TODO: Add description to lager_backend_utils +-module(lager_backend_utils). + +%% +%% Include files +%% +-include_lib("lager/include/lager.hrl"). +-ifdef(TEST). +-include_lib("eunit/include/eunit.hrl"). +-endif. + +%% +%% Exported Functions +%% +-export([is_loggable/3]). + +%% +%% API Functions +%% + + +-spec is_loggable(#lager_log_message{},integer(),term()) -> boolean(). +is_loggable(#lager_log_message{severity_as_int=Severity,destinations=Destinations},SeverityThreshold,MyName)-> +%% ?debugFmt("is_loggable: Severity=~p, Threshold=~p, Destinations=~p, MyName=~p", [Severity,SeverityThreshold,Destinations,MyName]), + Severity =< SeverityThreshold orelse lists:member(MyName, Destinations). + + +-ifdef(TEST). + +is_loggable_test_() -> + [ + {"Loggable by severity only", ?_assert(is_loggable(#lager_log_message{severity_as_int=1,destinations=[]},2,me))}, + {"Not loggable by severity only", ?_assertNot(is_loggable(#lager_log_message{severity_as_int=2,destinations=[]},1,me))}, + {"Loggable by severity with destination", ?_assert(is_loggable(#lager_log_message{severity_as_int=1,destinations=[you]},2,me))}, + {"Not loggable by severity with destination", ?_assertNot(is_loggable(#lager_log_message{severity_as_int=2,destinations=[you]},1,me))}, + {"Loggable by destination overriding severity", ?_assert(is_loggable(#lager_log_message{severity_as_int=2,destinations=[me]},1,me))} + ]. + +-endif. diff --git a/src/lager_console_backend.erl b/src/lager_console_backend.erl index 78561ca..a0a184b 100644 --- a/src/lager_console_backend.erl +++ b/src/lager_console_backend.erl @@ -24,7 +24,7 @@ -export([init/1, handle_call/2, handle_event/2, handle_info/2, terminate/2, code_change/3]). --record(state, {level, verbose}). +-record(state, {level, formatter,format_config}). -ifdef(TEST). -include_lib("eunit/include/eunit.hrl"). @@ -33,18 +33,24 @@ -include("lager.hrl"). +-define(VERBOSE_FORMAT,[date, " ", time, " [", severity, "] ", pid, "@", module,":", function, ":",line," ", message, "\r\n"]). +-define(TERSE_FORMAT,[time, " [", severity,"] ", message, "\r\n"]). + %% @private init(Level) when is_atom(Level) -> + init([Level,{lager_default_formatter,?TERSE_FORMAT}]); +init([Level, true]) -> % for backwards compatibility + init([Level,{lager_default_formatter,?VERBOSE_FORMAT}]); +init([Level,false]) -> % for backwards compatibility + init([Level,{lager_default_formatter,?TERSE_FORMAT}]); +init([Level,{Formatter,[]}]) -> + init([Level,{Formatter,[]}]); +init([Level,{Formatter,FormatterConfig}]) when is_atom(Level), is_atom(Formatter)-> case lists:member(Level, ?LEVELS) of true -> - {ok, #state{level=lager_util:level_to_num(Level), verbose=false}}; - _ -> - {error, bad_log_level} - end; -init([Level, Verbose]) -> - case lists:member(Level, ?LEVELS) of - true -> - {ok, #state{level=lager_util:level_to_num(Level), verbose=Verbose}}; + {ok, #state{level=lager_util:level_to_num(Level), + formatter=Formatter, + format_config=FormatterConfig}}; _ -> {error, bad_log_level} end. @@ -64,29 +70,15 @@ handle_call(_Request, State) -> {ok, ok, State}. %% @private -handle_event({log, Dest, Level, {Date, Time}, [LevelStr, Location, Message]}, - #state{level=L, verbose=Verbose} = State) when Level > L -> - case lists:member(lager_console_backend, Dest) of +handle_event(#lager_log_message{}=Message, + #state{level=L,formatter=Formatter,format_config=FormatConfig} = State) -> + case lager_backend_utils:is_loggable(Message, L, ?MODULE) of true -> - case Verbose of - true -> - io:put_chars(user, [Date, " ", Time, " ", LevelStr, Location, Message, "\r\n"]); - _ -> - io:put_chars(user, [Time, " ", LevelStr, Message, "\r\n"]) - end, + io:put_chars(user, Formatter:format(Message,FormatConfig)), {ok, State}; false -> {ok, State} end; -handle_event({log, Level, {Date, Time}, [LevelStr, Location, Message]}, - #state{level=LogLevel, verbose=Verbose} = State) when Level =< LogLevel -> - case Verbose of - true -> - io:put_chars(user, [Date, " ", Time, " ", LevelStr, Location, Message, "\r\n"]); - _ -> - io:put_chars(user, [Time, " ", LevelStr, Message, "\r\n"]) - end, - {ok, State}; handle_event(_Event, State) -> {ok, State}. @@ -146,6 +138,7 @@ console_log_test_() -> unregister(user), register(user, Pid), erlang:group_leader(Pid, whereis(lager_event)), + lager_mochiglobal:put(loglevel, {?INFO, []}), lager:log(info, self(), "Test message"), receive {io_request, From, ReplyAs, {put_chars, unicode, Msg}} -> @@ -164,12 +157,13 @@ console_log_test_() -> register(user, Pid), erlang:group_leader(Pid, whereis(lager_event)), gen_event:add_handler(lager_event, lager_console_backend, [info, true]), - lager:log(info, self(), "Test message"), - lager:log(info, self(), "Test message"), + lager_mochiglobal:put(loglevel, {?INFO, []}), + lager:info("Test message"), + lager:info("Test message"), PidStr = pid_to_list(self()), receive {io_request, _, _, {put_chars, unicode, Msg}} -> - ?assertMatch([_, _, "[info]", PidStr, "Test message\r\n"], re:split(Msg, " ", [{return, list}, {parts, 5}])) + ?assertMatch([_, _, "[info]", PidStr, _,"Test message\r\n"], re:split(Msg, "[ @]", [{return, list}, {parts, 6}])) after 500 -> ?assert(false) diff --git a/src/lager_crash_log.erl b/src/lager_crash_log.erl index a02e5f9..723856b 100644 --- a/src/lager_crash_log.erl +++ b/src/lager_crash_log.erl @@ -53,7 +53,7 @@ date, count, flap=false - }). +}). %% @private start_link(Filename, MaxBytes, Size, Date, Count) -> @@ -273,7 +273,7 @@ filesystem_test_() -> file:write_file_info("crash_test.log", FInfo#file_info{mode = 0}), {ok, _} = ?MODULE:start_link("crash_test.log", 65535, 0, undefined, 0), ?assertEqual(1, lager_test_backend:count()), - {_Level, _Time, [_, _, Message]} = lager_test_backend:pop(), + {_Level, _Time, Message,_Metadata} = lager_test_backend:pop(), ?assertEqual("Failed to open crash log file crash_test.log with error: permission denied", lists:flatten(Message)) end }, @@ -292,7 +292,7 @@ filesystem_test_() -> _ = gen_event:which_handlers(error_logger), ?assertEqual(3, lager_test_backend:count()), lager_test_backend:pop(), - {_Level, _Time, [_, _, Message]} = lager_test_backend:pop(), + {_Level, _Time, Message,_Metadata} = lager_test_backend:pop(), ?assertEqual("Failed to reopen crash log crash_test.log with error: permission denied", lists:flatten(Message)) end }, @@ -303,7 +303,7 @@ filesystem_test_() -> file:write_file_info("crash_test.log", FInfo#file_info{mode = 0}), {ok, _} = ?MODULE:start_link("crash_test.log", 65535, 0, undefined, 0), ?assertEqual(1, lager_test_backend:count()), - {_Level, _Time, [_, _, Message]} = lager_test_backend:pop(), + {_Level, _Time, Message,_Metadata} = lager_test_backend:pop(), ?assertEqual("Failed to open crash log file crash_test.log with error: permission denied", lists:flatten(Message)), file:write_file_info("crash_test.log", FInfo#file_info{mode = OldPerms}), sync_error_logger:error_msg("Test message~n"), diff --git a/src/lager_default_formatter.erl b/src/lager_default_formatter.erl new file mode 100644 index 0000000..d480cbd --- /dev/null +++ b/src/lager_default_formatter.erl @@ -0,0 +1,107 @@ +%% Author: jason +%% Created: Jan 15, 2012 +%% Description: TODO: Add description to lager_default_formatter +-module(lager_default_formatter). + +%% +%% Include files +%% +-include_lib("lager/include/lager.hrl"). +-ifdef(TEST). +-include_lib("eunit/include/eunit.hrl"). +-endif. + +%% +%% Exported Functions +%% +-export([format/2]). + +%% +%% API Functions +%% + +%% @doc Provides a generic, default formatting for log messages using a semi-iolist as configuration. Any iolist allowed +%% elements in the configuration are printed verbatim. Atoms in the configuration are treated as metadata properties +%% and extracted from the log message. Optionally, a tuple of {atom(),semi-iolist()} can be used. The atom will look +%% up the property, but if not found it will use the semi-iolist() instead. These fallbacks can be similarly nested +%% or refer to other properties, if desired. +%% +%% The metadata properties date,time, message, and severity will always exist. +%% The properties pid, file, line, module, and function will always exist if the parser transform is used. +%% +%% Example: +%% ["Foo"] -> "Foo", regardless of message content. +%% [message] -> The content of the logged message, alone. +%% [{pid,"Unknown Pid"}] -> "" if pid is in the metadata, "Unknown Pid" if not. +%% [date, " ", time," [",severity,"] ",pid, " ", message, "\n"] -> default formatting if none is provided +%% @end +-spec format(#lager_log_message{},list()) -> any(). +format(#lager_log_message{}=Msg,[]) -> + format(Msg,[date, " ", time," [",severity,"] ",pid, " ", message, "\n"]); +format(Message,Config) -> + [ output(V,Message) || V <- Config ]. + + +-spec output(term(),#lager_log_message{}) -> iolist(). +output(message,#lager_log_message{message=M}) -> M; +output(date,#lager_log_message{timestamp={D,_T}}) -> D; +output(time,#lager_log_message{timestamp={_D,T}}) -> T; +output(severity,#lager_log_message{severity_as_int=S}) -> atom_to_list(lager_util:num_to_level(S)); +output(Prop,#lager_log_message{metadata=Metadata}) when is_atom(Prop) -> make_printable(proplists:get_value(Prop,Metadata,<<"Undefined">>)); +output({Prop,Default},#lager_log_message{metadata=Metadata}=L) when is_atom(Prop) -> make_printable(proplists:get_value(Prop,Metadata,output(Default,L))); +output(Other,_) -> make_printable(Other). + +-spec make_printable(any()) -> iolist(). +make_printable(A) when is_atom(A) -> atom_to_list(A); +make_printable(P) when is_pid(P) -> pid_to_list(P); +make_printable(L) when is_list(L) orelse is_binary(L) -> L; +make_printable(Other) -> io_lib:format("~p",[Other]). + +-ifdef(TEST). +basic_test_() -> + [{"Default formatting test", + ?_assertEqual(iolist_to_binary([<<"Day Time [error] ">>, pid_to_list(self()), <<" Message\n">>]), + iolist_to_binary(format(#lager_log_message{timestamp={"Day","Time"}, + message="Message", + severity_as_int=lager_util:level_to_num(error), + metadata=[{pid,self()}]}, + []))) + }, + {"Basic Formatting", + ?_assertEqual(<<"Simplist Format">>, + iolist_to_binary(format(#lager_log_message{timestamp={"Day","Time"}, + message="Message", + severity_as_int=lager_util:level_to_num(error), + metadata=[{pid,self()}]}, + ["Simplist Format"]))) + }, + {"Default equivalent formatting test", + ?_assertEqual(iolist_to_binary([<<"Day Time [error] ">>, pid_to_list(self()), <<" Message\n">>]), + iolist_to_binary(format(#lager_log_message{timestamp={"Day","Time"}, + message="Message", + severity_as_int=lager_util:level_to_num(error), + metadata=[{pid,self()}]}, + [date, " ", time," [",severity,"] ",pid, " ", message, "\n"] + ))) + }, + {"Non existant metadata can default to string", + ?_assertEqual(iolist_to_binary([<<"Day Time [error] Fallback Message\n">>]), + iolist_to_binary(format(#lager_log_message{timestamp={"Day","Time"}, + message="Message", + severity_as_int=lager_util:level_to_num(error), + metadata=[]}, + [date, " ", time," [",severity,"] ",{does_not_exist,"Fallback"}, " ", message, "\n"] + ))) + }, + {"Non existant metadata can default to other metadata", + ?_assertEqual(iolist_to_binary([<<"Day Time [error] Fallback Message\n">>]), + iolist_to_binary(format(#lager_log_message{timestamp={"Day","Time"}, + message="Message", + severity_as_int=lager_util:level_to_num(error), + metadata=[{pid,"Fallback"}]}, + [date, " ", time," [",severity,"] ",{does_not_exist,pid}, " ", message, "\n"] + ))) + } + ]. + +-endif. diff --git a/src/lager_file_backend.erl b/src/lager_file_backend.erl index 60051e8..96b46b1 100644 --- a/src/lager_file_backend.erl +++ b/src/lager_file_backend.erl @@ -49,29 +49,37 @@ flap=false :: boolean(), size = 0 :: integer(), date, - count = 10 + count = 10, + formatter, + formatter_config }). %% @private -spec init([{string(), lager:log_level()},...]) -> {ok, #state{}}. -init(LogFile) -> - case validate_logfile(LogFile) of +init([LogFile,{Formatter}]) -> + init([LogFile,{Formatter,[]}]); +init([LogFile,{Formatter,FormatterConfig}]) -> + case validate_logfile(LogFile) of {Name, Level, Size, Date, Count} -> schedule_rotation(Name, Date), State = case lager_util:open_logfile(Name, true) of {ok, {FD, Inode, _}} -> #state{name=Name, level=lager_util:level_to_num(Level), - fd=FD, inode=Inode, size=Size, date=Date, count=Count}; + fd=FD, inode=Inode, size=Size, date=Date, count=Count, formatter=Formatter, formatter_config=FormatterConfig}; {error, Reason} -> ?INT_LOG(error, "Failed to open log file ~s with error ~s", [Name, file:format_error(Reason)]), #state{name=Name, level=lager_util:level_to_num(Level), - flap=true, size=Size, date=Date, count=Count} + flap=true, size=Size, date=Date, count=Count, formatter=Formatter, formatter_config=FormatterConfig} end, + {ok, State}; false -> ignore - end. + end; +init(LogFile) -> + init([LogFile,{lager_default_formatter,[]}]). + %% @private handle_call({set_loglevel, Level}, #state{name=Ident} = State) -> @@ -83,17 +91,14 @@ handle_call(_Request, State) -> {ok, ok, State}. %% @private -handle_event({log, Dest, Level, {Date, Time}, Message}, - #state{name=Name, level=L} = State) when Level > L -> - case lists:member({lager_file_backend, Name}, Dest) of +handle_event(Message, + #state{name=Name, level=L,formatter=Formatter,formatter_config=FormatConfig} = State) -> + case lager_backend_utils:is_loggable(Message,L,{lager_file_backend, Name}) of true -> - {ok, write(State, Level, [Date, " ", Time, " ", Message, "\n"])}; + {ok,write(State, Message#lager_log_message.severity_as_int, Formatter:format(Message,FormatConfig)) }; false -> {ok, State} end; -handle_event({log, Level, {Date, Time}, Message}, #state{level=L} = State) when Level =< L-> - NewState = write(State, Level, [Date, " ", Time, " ", Message, "\n"]), - {ok, NewState}; handle_event(_Event, State) -> {ok, State}. @@ -261,7 +266,7 @@ filesystem_test_() -> file:write_file_info("test.log", FInfo#file_info{mode = 0}), gen_event:add_handler(lager_event, lager_file_backend, {"test.log", info}), ?assertEqual(1, lager_test_backend:count()), - {_Level, _Time, [_, _, Message]} = lager_test_backend:pop(), + {_Level, _Time,Message,_Metadata} = lager_test_backend:pop(), ?assertEqual("Failed to open log file test.log with error permission denied", lists:flatten(Message)) end }, @@ -279,7 +284,7 @@ filesystem_test_() -> ?assertEqual(3, lager_test_backend:count()), lager_test_backend:pop(), lager_test_backend:pop(), - {_Level, _Time, [_, _, Message]} = lager_test_backend:pop(), + {_Level, _Time, Message,_Metadata} = lager_test_backend:pop(), ?assertEqual("Failed to reopen log file test.log with error permission denied", lists:flatten(Message)) end }, @@ -290,7 +295,7 @@ filesystem_test_() -> file:write_file_info("test.log", FInfo#file_info{mode = 0}), gen_event:add_handler(lager_event, lager_file_backend, {"test.log", info}), ?assertEqual(1, lager_test_backend:count()), - {_Level, _Time, [_, _, Message]} = lager_test_backend:pop(), + {_Level, _Time, Message,_Metadata} = lager_test_backend:pop(), ?assertEqual("Failed to open log file test.log with error permission denied", lists:flatten(Message)), file:write_file_info("test.log", FInfo#file_info{mode = OldPerms}), lager:log(error, self(), "Test message"), @@ -352,6 +357,7 @@ filesystem_test_() -> ?MODULE}], ?DEBUG, {lager_file_backend, "test.log"}}]}), lager:error("Test message"), + timer:sleep(1000), {ok, Bin} = file:read_file("test.log"), ?assertMatch([_, _, "[error]", _, "Test message\n"], re:split(Bin, " ", [{return, list}, {parts, 5}])) end @@ -389,6 +395,33 @@ filesystem_test_() -> ] }. +formatting_test_() -> + {foreach, + fun() -> + file:write_file("test.log", ""), + file:write_file("test2.log", ""), + error_logger:tty(false), + application:load(lager), + application:set_env(lager, handlers, [{lager_test_backend, info}]), + application:set_env(lager, error_logger_redirect, false), + application:start(lager) + end, + fun(_) -> + file:delete("test.log"), + file:delete("test2.log"), + application:stop(lager), + error_logger:tty(true) + end, + [{"Should have two log files, the second prefixed with 2>", + fun() -> + gen_event:add_handler(lager_event, lager_file_backend,[{"test.log", debug},{lager_default_formatter,["[",severity,"] ", message, "\n"]}]), + gen_event:add_handler(lager_event, lager_file_backend,[{"test2.log", debug},{lager_default_formatter,["2> [",severity,"] ", message, "\n"]}]), + lager:log(error, self(), "Test message"), + ?assertMatch({ok, <<"[error] Test message\n">>},file:read_file("test.log")), + ?assertMatch({ok, <<"2> [error] Test message\n">>},file:read_file("test2.log")) + end + } + ]}. -endif. diff --git a/src/lager_handler_watcher.erl b/src/lager_handler_watcher.erl index a7e4744..462f2e5 100644 --- a/src/lager_handler_watcher.erl +++ b/src/lager_handler_watcher.erl @@ -117,7 +117,7 @@ reinstall_on_initial_failure_test_() -> application:start(lager), try ?assertEqual(1, lager_test_backend:count()), - {_Level, _Time, [_, _, Message]} = lager_test_backend:pop(), + {_Level, _Time, Message, _Metadata} = lager_test_backend:pop(), ?assertMatch("Lager failed to install handler lager_crash_backend into lager_event, retrying later :"++_, lists:flatten(Message)), ?assertEqual(0, lager_test_backend:count()), timer:sleep(6000), @@ -148,9 +148,9 @@ reinstall_on_runtime_failure_test_() -> ?assert(lists:member(lager_crash_backend, gen_event:which_handlers(lager_event))), timer:sleep(6000), ?assertEqual(2, lager_test_backend:count()), - {_Level, _Time, [_, _, Message]} = lager_test_backend:pop(), + {_Level, _Time, Message, _Metadata} = lager_test_backend:pop(), ?assertEqual("Lager event handler lager_crash_backend exited with reason crash", lists:flatten(Message)), - {_Level2, _Time2, [_, _, Message2]} = lager_test_backend:pop(), + {_Level2, _Time2, Message2, _Metadata} = lager_test_backend:pop(), ?assertMatch("Lager failed to install handler lager_crash_backend into lager_event, retrying later :"++_, lists:flatten(Message2)), ?assertEqual(false, lists:member(lager_crash_backend, gen_event:which_handlers(lager_event))) after diff --git a/src/lager_transform.erl b/src/lager_transform.erl index b9da5c8..9892677 100644 --- a/src/lager_transform.erl +++ b/src/lager_transform.erl @@ -59,8 +59,8 @@ walk_body(Acc, []) -> walk_body(Acc, [H|T]) -> walk_body([transform_statement(H)|Acc], T). -transform_statement({call, Line, {remote, Line1, {atom, Line2, lager}, - {atom, Line3, Severity}}, Arguments0} = Stmt) -> +transform_statement({call, Line, {remote, _Line1, {atom, _Line2, lager}, + {atom, _Line3, Severity}}, Arguments0} = Stmt) -> case lists:member(Severity, ?LEVELS) of true -> DefaultAttrs = {cons, Line, {tuple, Line, [ @@ -77,7 +77,7 @@ transform_statement({call, Line, {remote, Line1, {atom, Line2, lager}, {nil, Line}}}}}, {Traces, Message, Arguments} = case Arguments0 of [Format] -> - {DefaultAttrs, Format, {nil, Line}}; + {DefaultAttrs, Format, {atom, Line, none}}; [Arg1, Arg2] -> %% some ambiguity here, figure out if these arguments are %% [Format, Args] or [Attr, Format]. @@ -86,29 +86,23 @@ transform_statement({call, Line, {remote, Line1, {atom, Line2, lager}, case Arg1 of {cons, _, {tuple, _, _}, _} -> {concat_lists(Arg1, DefaultAttrs), - Arg2, {nil,Line}}; + Arg2, {atom, Line, none}}; _ -> {DefaultAttrs, Arg1, Arg2} end; [Attrs, Format, Args] -> {concat_lists(Attrs, DefaultAttrs), Format, Args} end, - {block, Line, + + {call, Line, {remote, Line, {atom,Line,lager},{atom,Line,dispatch_log}}, [ - {call, Line, {remote, Line, {atom,Line1,lager},{atom,Line2,dispatch_log}}, - [ - {atom, Line3, Severity}, - {atom, Line3, get(module)}, - {atom, Line3, get(function)}, - {integer, Line3, Line}, - {call, Line3, {atom, Line3 ,self}, []}, - Traces, - Message, - Arguments, - {integer, Line3, get(truncation_size)} - ] - } - ]}; % block contents + {atom,Line,Severity}, + Traces, + Message, + Arguments, + {integer, Line, get(truncation_size)} + ] + }; false -> Stmt end; diff --git a/test/lager_test_backend.erl b/test/lager_test_backend.erl index 64a04f5..62ce2db 100644 --- a/test/lager_test_backend.erl +++ b/test/lager_test_backend.erl @@ -54,13 +54,12 @@ handle_call({set_loglevel, Level}, State) -> handle_call(_Request, State) -> {ok, ok, State}. -handle_event({log, [?MODULE], Level, Time, Message}, #state{buffer=Buffer} = State) -> - {ok, State#state{buffer=Buffer ++ [{Level, Time, Message}]}}; -handle_event({log, Level, Time, Message}, #state{level=LogLevel, - buffer=Buffer} = State) when Level =< LogLevel -> - {ok, State#state{buffer=Buffer ++ [{Level, Time, Message}]}}; -handle_event({log, _Level, _Time, _Message}, #state{ignored=Ignored} = State) -> - {ok, State#state{ignored=Ignored ++ [ignored]}}; +handle_event(#lager_log_message{severity_as_int=Level,timestamp=Time, message=Message, metadata=Metadata}=Msg, + #state{level=LogLevel,buffer=Buffer,ignored=Ignored} = State) -> + case lager_backend_utils:is_loggable(Msg, LogLevel, ?MODULE) of + true -> {ok, State#state{buffer=Buffer ++ [{Level, Time, Message, Metadata}]}}; + _ -> {ok, State#state{ignored=Ignored ++ [ignored]}} + end; handle_event(_Event, State) -> {ok, State}. @@ -88,10 +87,10 @@ flush() -> gen_event:call(lager_event, ?MODULE, flush). has_line_numbers() -> - %% are we R15 or greater - Rel = erlang:system_info(otp_release), - {match, [Major]} = re:run(Rel, "^R(\\d+)[A|B](|0(\\d))$", [{capture, [1], list}]), - list_to_integer(Major) >= 15. + %% are we R15 or greater + Rel = erlang:system_info(otp_release), + {match, [Major]} = re:run(Rel, "^R(\\d+)[A|B](|0(\\d))$", [{capture, [1], list}]), + list_to_integer(Major) >= 15. not_running_test() -> ?assertEqual({error, lager_not_running}, lager:log(info, self(), "not running")). @@ -111,11 +110,9 @@ lager_test_() -> fun() -> lager:warning("test message"), ?assertEqual(1, count()), - {Level, _Time, Message} = pop(), + {Level, _Time, Message, _Metadata} = pop(), ?assertMatch(Level, lager_util:level_to_num(warning)), - [LevelStr, _LocStr, MsgStr] = re:split(Message, " ", [{return, list}, {parts, 3}]), - ?assertEqual("[warning]", LevelStr), - ?assertEqual("test message", MsgStr), + ?assertEqual("test message", Message), ok end }, @@ -123,11 +120,9 @@ lager_test_() -> fun() -> lager:warning("test message ~p", [self()]), ?assertEqual(1, count()), - {Level, _Time, Message} = pop(), + {Level, _Time, Message,_Metadata} = pop(), ?assertMatch(Level, lager_util:level_to_num(warning)), - [LevelStr, _LocStr, MsgStr] = re:split(Message, " ", [{return, list}, {parts, 3}]), - ?assertEqual("[warning]", LevelStr), - ?assertEqual(lists:flatten(io_lib:format("test message ~p", [self()])), MsgStr), + ?assertEqual(lists:flatten(io_lib:format("test message ~p", [self()])), lists:flatten(Message)), ok end }, @@ -253,13 +248,33 @@ test_body(Expected, Actual) -> FileLine = string:substr(Actual, length(Expected)+1), Body = string:substr(Actual, 1, length(Expected)), ?assertEqual(Expected, Body), - ?assertEqual(" line ", string:substr(FileLine, 1, 6)); + case string:substr(FileLine, 1, 6) of + [] -> + %% sometimes there's no line information... + ?assert(true); + " line " -> + ?assert(true); + Other -> + ?debugFmt("unexpected trailing data ~p", [Other]), + ?assert(false) + end; false -> ?assertEqual(Expected, Actual) end. error_logger_redirect_crash_test_() -> + TestBody=fun(Name,CrashReason,Expected) -> {Name, + fun() -> + Pid = whereis(crash), + crash(CrashReason), + {Level, _, Msg,Metadata} = pop(), + test_body(Expected, lists:flatten(Msg)), + ?assertEqual(Pid,proplists:get_value(pid,Metadata)), + ?assertEqual(lager_util:level_to_num(error),Level) + end + } + end, {foreach, fun() -> error_logger:tty(false), @@ -287,160 +302,24 @@ error_logger_redirect_crash_test_() -> ?assertEqual(0, count()) end }, - {"bad return value", - fun() -> - Pid = whereis(crash), - crash(bad_return), - {_, _, Msg} = pop(), - Expected = lists:flatten(io_lib:format("[error] ~w gen_server crash terminated with reason: bad return value: bleh", [Pid])), - ?assertEqual(Expected, lists:flatten(Msg)) - end - }, - {"bad return value with string", - fun() -> - Pid = whereis(crash), - crash(bad_return_string), - {_, _, Msg} = pop(), - Expected = lists:flatten(io_lib:format("[error] ~w gen_server crash terminated with reason: bad return value: {tuple,{tuple,\"string\"}}", [Pid])), - ?assertEqual(Expected, lists:flatten(Msg)) - end - }, - {"bad return value uncaught throw", - fun() -> - Pid = whereis(crash), - crash(throw), - {_, _, Msg} = pop(), - Expected = lists:flatten(io_lib:format("[error] ~w gen_server crash terminated with reason: bad return value: a_ball", [Pid])), - ?assertEqual(Expected, lists:flatten(Msg)) - end - }, - {"case clause", - fun() -> - Pid = whereis(crash), - crash(case_clause), - {_, _, Msg} = pop(), - Expected = lists:flatten(io_lib:format("[error] ~w gen_server crash terminated with reason: no case clause matching {} in crash:handle_call/3", [Pid])), - test_body(Expected, lists:flatten(Msg)) - end - }, - {"case clause string", - fun() -> - Pid = whereis(crash), - crash(case_clause_string), - {_, _, Msg} = pop(), - Expected = lists:flatten(io_lib:format("[error] ~w gen_server crash terminated with reason: no case clause matching \"crash\" in crash:handle_call/3", [Pid])), - test_body(Expected, lists:flatten(Msg)) - end - }, - {"function clause", - fun() -> - Pid = whereis(crash), - crash(function_clause), - {_, _, Msg} = pop(), - Expected = lists:flatten(io_lib:format("[error] ~w gen_server crash terminated with reason: no function clause matching crash:function({})", [Pid])), - test_body(Expected, lists:flatten(Msg)) - end - }, - {"if clause", - fun() -> - Pid = whereis(crash), - crash(if_clause), - {_, _, Msg} = pop(), - Expected = lists:flatten(io_lib:format("[error] ~w gen_server crash terminated with reason: no true branch found while evaluating if expression in crash:handle_call/3", [Pid])), - test_body(Expected, lists:flatten(Msg)) - end - }, - {"try clause", - fun() -> - Pid = whereis(crash), - crash(try_clause), - {_, _, Msg} = pop(), - Expected = lists:flatten(io_lib:format("[error] ~w gen_server crash terminated with reason: no try clause matching [] in crash:handle_call/3", [Pid])), - test_body(Expected, lists:flatten(Msg)) - end - }, - {"undefined function", - fun() -> - Pid = whereis(crash), - crash(undef), - {_, _, Msg} = pop(), - Expected = lists:flatten(io_lib:format("[error] ~w gen_server crash terminated with reason: call to undefined function crash:booger/0 from crash:handle_call/3", [Pid])), - test_body(Expected, lists:flatten(Msg)) - end - }, - {"bad math", - fun() -> - Pid = whereis(crash), - crash(badarith), - {_, _, Msg} = pop(), - Expected = lists:flatten(io_lib:format("[error] ~w gen_server crash terminated with reason: bad arithmetic expression in crash:handle_call/3", [Pid])), - test_body(Expected, lists:flatten(Msg)) - end - }, - {"bad match", - fun() -> - Pid = whereis(crash), - crash(badmatch), - {_, _, Msg} = pop(), - Expected = lists:flatten(io_lib:format("[error] ~w gen_server crash terminated with reason: no match of right hand value {} in crash:handle_call/3", [Pid])), - test_body(Expected, lists:flatten(Msg)) - end - }, - {"bad arity", - fun() -> - Pid = whereis(crash), - crash(badarity), - {_, _, Msg} = pop(), - Expected = lists:flatten(io_lib:format("[error] ~w gen_server crash terminated with reason: fun called with wrong arity of 1 instead of 3 in crash:handle_call/3", [Pid])), - test_body(Expected, lists:flatten(Msg)) - end - }, - {"bad arg1", - fun() -> - Pid = whereis(crash), - crash(badarg1), - {_, _, Msg} = pop(), - Expected = lists:flatten(io_lib:format("[error] ~w gen_server crash terminated with reason: bad argument in crash:handle_call/3", [Pid])), - test_body(Expected, lists:flatten(Msg)) - end - }, - {"bad arg2", - fun() -> - Pid = whereis(crash), - crash(badarg2), - {_, _, Msg} = pop(), - Expected = lists:flatten(io_lib:format("[error] ~w gen_server crash terminated with reason: bad argument in call to erlang:iolist_to_binary([\"foo\",bar]) in crash:handle_call/3", [Pid])), - test_body(Expected, lists:flatten(Msg)) - end - }, - {"bad record", - fun() -> - Pid = whereis(crash), - crash(badrecord), - {_, _, Msg} = pop(), - Expected = lists:flatten(io_lib:format("[error] ~w gen_server crash terminated with reason: bad record state in crash:handle_call/3", [Pid])), - test_body(Expected, lists:flatten(Msg)) - end - }, - {"noproc", - fun() -> - Pid = whereis(crash), - crash(noproc), - {_, _, Msg} = pop(), - Expected = lists:flatten(io_lib:format("[error] ~w gen_server crash terminated with reason: no such process or port in call to gen_event:call(foo, bar, baz)", [Pid])), - ?assertEqual(Expected, lists:flatten(Msg)) - end - }, - {"badfun", - fun() -> - Pid = whereis(crash), - crash(badfun), - {_, _, Msg} = pop(), - Expected = lists:flatten(io_lib:format("[error] ~w gen_server crash terminated with reason: bad function booger in crash:handle_call/3", [Pid])), - test_body(Expected, lists:flatten(Msg)) - end - } + TestBody("bad return value",bad_return,"gen_server crash terminated with reason: bad return value: bleh"), + TestBody("bad return value with string",bad_return_string,"gen_server crash terminated with reason: bad return value: {tuple,{tuple,\"string\"}}"), + TestBody("bad return uncaught throw",throw,"gen_server crash terminated with reason: bad return value: a_ball"), + TestBody("case clause",case_clause,"gen_server crash terminated with reason: no case clause matching {} in crash:handle_call/3"), + TestBody("case clause string",case_clause_string,"gen_server crash terminated with reason: no case clause matching \"crash\" in crash:handle_call/3"), + TestBody("function clause",function_clause,"gen_server crash terminated with reason: no function clause matching crash:function({})"), + TestBody("if clause",if_clause,"gen_server crash terminated with reason: no true branch found while evaluating if expression in crash:handle_call/3"), + TestBody("try clause",try_clause,"gen_server crash terminated with reason: no try clause matching [] in crash:handle_call/3"), + TestBody("undefined function",undef,"gen_server crash terminated with reason: call to undefined function crash:booger/0 from crash:handle_call/3"), + TestBody("bad math",badarith,"gen_server crash terminated with reason: bad arithmetic expression in crash:handle_call/3"), + TestBody("bad match",badmatch,"gen_server crash terminated with reason: no match of right hand value {} in crash:handle_call/3"), + TestBody("bad arity",badarity,"gen_server crash terminated with reason: fun called with wrong arity of 1 instead of 3 in crash:handle_call/3"), + TestBody("bad arg1",badarg1,"gen_server crash terminated with reason: bad argument in crash:handle_call/3"), + TestBody("bad arg2",badarg2,"gen_server crash terminated with reason: bad argument in call to erlang:iolist_to_binary([\"foo\",bar]) in crash:handle_call/3"), + TestBody("bad record",badrecord,"gen_server crash terminated with reason: bad record state in crash:handle_call/3"), + TestBody("noproc",noproc,"gen_server crash terminated with reason: no such process or port in call to gen_event:call(foo, bar, baz)"), + TestBody("badfun",badfun,"gen_server crash terminated with reason: bad function booger in crash:handle_call/3") ] }. @@ -466,17 +345,22 @@ error_logger_redirect_test_() -> fun() -> sync_error_logger:error_report([{this, is}, a, {silly, format}]), _ = gen_event:which_handlers(error_logger), - {_, _, Msg} = pop(), - Expected = lists:flatten(io_lib:format("[error] ~w this: is, a, silly: format", [self()])), + {Level, _, Msg,Metadata} = pop(), + ?assertEqual(lager_util:level_to_num(error),Level), + ?assertEqual(self(),proplists:get_value(pid,Metadata)), + Expected = "this: is, a, silly: format", ?assertEqual(Expected, lists:flatten(Msg)) + end }, {"string error reports are printed", fun() -> sync_error_logger:error_report("this is less silly"), _ = gen_event:which_handlers(error_logger), - {_, _, Msg} = pop(), - Expected = lists:flatten(io_lib:format("[error] ~w this is less silly", [self()])), + {Level, _, Msg,Metadata} = pop(), + ?assertEqual(lager_util:level_to_num(error),Level), + ?assertEqual(self(),proplists:get_value(pid,Metadata)), + Expected = "this is less silly", ?assertEqual(Expected, lists:flatten(Msg)) end }, @@ -484,8 +368,10 @@ error_logger_redirect_test_() -> fun() -> sync_error_logger:error_msg("doom, doom has come upon you all"), _ = gen_event:which_handlers(error_logger), - {_, _, Msg} = pop(), - Expected = lists:flatten(io_lib:format("[error] ~w doom, doom has come upon you all", [self()])), + {Level, _, Msg,Metadata} = pop(), + ?assertEqual(lager_util:level_to_num(error),Level), + ?assertEqual(self(),proplists:get_value(pid,Metadata)), + Expected = "doom, doom has come upon you all", ?assertEqual(Expected, lists:flatten(Msg)) end }, @@ -493,7 +379,7 @@ error_logger_redirect_test_() -> fun() -> sync_error_logger:error_msg("doom, doom has come upon you all ~p", [string:copies("doom", 10000)]), _ = gen_event:which_handlers(error_logger), - {_, _, Msg} = pop(), + {_, _, Msg,_Metadata} = pop(), ?assert(length(lists:flatten(Msg)) < 5100) end }, @@ -501,8 +387,10 @@ error_logger_redirect_test_() -> fun() -> sync_error_logger:info_report([{this, is}, a, {silly, format}]), _ = gen_event:which_handlers(error_logger), - {_, _, Msg} = pop(), - Expected = lists:flatten(io_lib:format("[info] ~w this: is, a, silly: format", [self()])), + {Level, _, Msg,Metadata} = pop(), + ?assertEqual(lager_util:level_to_num(info),Level), + ?assertEqual(self(),proplists:get_value(pid,Metadata)), + Expected = "this: is, a, silly: format", ?assertEqual(Expected, lists:flatten(Msg)) end }, @@ -510,7 +398,9 @@ error_logger_redirect_test_() -> fun() -> sync_error_logger:info_report([[{this, is}, a, {silly, format}] || _ <- lists:seq(0, 600)]), _ = gen_event:which_handlers(error_logger), - {_, _, Msg} = pop(), + {Level, _, Msg,Metadata} = pop(), + ?assertEqual(lager_util:level_to_num(info),Level), + ?assertEqual(self(),proplists:get_value(pid,Metadata)), ?assert(length(lists:flatten(Msg)) < 5000) end }, @@ -518,34 +408,39 @@ error_logger_redirect_test_() -> fun() -> sync_error_logger:info_report({foolish, bees}), _ = gen_event:which_handlers(error_logger), - {_, _, Msg} = pop(), - Expected = lists:flatten(io_lib:format("[info] ~w {foolish,bees}", [self()])), - ?assertEqual(Expected, lists:flatten(Msg)) + {Level, _, Msg,Metadata} = pop(), + ?assertEqual(lager_util:level_to_num(info),Level), + ?assertEqual(self(),proplists:get_value(pid,Metadata)), + ?assertEqual("{foolish,bees}", lists:flatten(Msg)) end }, {"single term error reports are printed", fun() -> sync_error_logger:error_report({foolish, bees}), _ = gen_event:which_handlers(error_logger), - {_, _, Msg} = pop(), - Expected = lists:flatten(io_lib:format("[error] ~w {foolish,bees}", [self()])), - ?assertEqual(Expected, lists:flatten(Msg)) + {Level, _, Msg,Metadata} = pop(), + ?assertEqual(lager_util:level_to_num(error),Level), + ?assertEqual(self(),proplists:get_value(pid,Metadata)), + ?assertEqual("{foolish,bees}", lists:flatten(Msg)) end }, {"string info reports are printed", fun() -> sync_error_logger:info_report("this is less silly"), _ = gen_event:which_handlers(error_logger), - {_, _, Msg} = pop(), - Expected = lists:flatten(io_lib:format("[info] ~w this is less silly", [self()])), - ?assertEqual(Expected, lists:flatten(Msg)) + {Level, _, Msg,Metadata} = pop(), + ?assertEqual(lager_util:level_to_num(info),Level), + ?assertEqual(self(),proplists:get_value(pid,Metadata)), + ?assertEqual("this is less silly", lists:flatten(Msg)) end }, {"string info reports are truncated at 4096 characters", fun() -> sync_error_logger:info_report(string:copies("this is less silly", 1000)), _ = gen_event:which_handlers(error_logger), - {_, _, Msg} = pop(), + {Level, _, Msg,Metadata} = pop(), + ?assertEqual(lager_util:level_to_num(info),Level), + ?assertEqual(self(),proplists:get_value(pid,Metadata)), ?assert(length(lists:flatten(Msg)) < 5100) end }, @@ -553,25 +448,29 @@ error_logger_redirect_test_() -> fun() -> sync_error_logger:info_report(["this is less silly", {than, "this"}]), _ = gen_event:which_handlers(error_logger), - {_, _, Msg} = pop(), - Expected = lists:flatten(io_lib:format("[info] ~w \"this is less silly\", than: \"this\"", [self()])), - ?assertEqual(Expected, lists:flatten(Msg)) + {Level, _, Msg,Metadata} = pop(), + ?assertEqual(lager_util:level_to_num(info),Level), + ?assertEqual(self(),proplists:get_value(pid,Metadata)), + ?assertEqual("\"this is less silly\", than: \"this\"", lists:flatten(Msg)) end }, {"info messages are printed", fun() -> sync_error_logger:info_msg("doom, doom has come upon you all"), _ = gen_event:which_handlers(error_logger), - {_, _, Msg} = pop(), - Expected = lists:flatten(io_lib:format("[info] ~w doom, doom has come upon you all", [self()])), - ?assertEqual(Expected, lists:flatten(Msg)) + {Level, _, Msg,Metadata} = pop(), + ?assertEqual(lager_util:level_to_num(info),Level), + ?assertEqual(self(),proplists:get_value(pid,Metadata)), + ?assertEqual("doom, doom has come upon you all", lists:flatten(Msg)) end }, {"info messages are truncated at 4096 characters", fun() -> sync_error_logger:info_msg("doom, doom has come upon you all ~p", [string:copies("doom", 10000)]), _ = gen_event:which_handlers(error_logger), - {_, _, Msg} = pop(), + {Level, _, Msg,Metadata} = pop(), + ?assertEqual(lager_util:level_to_num(info),Level), + ?assertEqual(self(),proplists:get_value(pid,Metadata)), ?assert(length(lists:flatten(Msg)) < 5100) end }, @@ -581,9 +480,10 @@ error_logger_redirect_test_() -> sync_error_logger:warning_msg("doom, doom has come upon you all"), Map = error_logger:warning_map(), _ = gen_event:which_handlers(error_logger), - {_, _, Msg} = pop(), - Expected = lists:flatten(io_lib:format("[~w] ~w doom, doom has come upon you all", [Map, self()])), - ?assertEqual(Expected, lists:flatten(Msg)) + {Level, _, Msg,Metadata} = pop(), + ?assertEqual(lager_util:level_to_num(Map),Level), + ?assertEqual(self(),proplists:get_value(pid,Metadata)), + ?assertEqual("doom, doom has come upon you all", lists:flatten(Msg)) end }, {"warning reports are printed at the correct level", @@ -591,9 +491,10 @@ error_logger_redirect_test_() -> sync_error_logger:warning_report([{i, like}, pie]), Map = error_logger:warning_map(), _ = gen_event:which_handlers(error_logger), - {_, _, Msg} = pop(), - Expected = lists:flatten(io_lib:format("[~w] ~w i: like, pie", [Map, self()])), - ?assertEqual(Expected, lists:flatten(Msg)) + {Level, _, Msg,Metadata} = pop(), + ?assertEqual(lager_util:level_to_num(Map),Level), + ?assertEqual(self(),proplists:get_value(pid,Metadata)), + ?assertEqual("i: like, pie", lists:flatten(Msg)) end }, {"single term warning reports are printed at the correct level", @@ -601,36 +502,40 @@ error_logger_redirect_test_() -> sync_error_logger:warning_report({foolish, bees}), Map = error_logger:warning_map(), _ = gen_event:which_handlers(error_logger), - {_, _, Msg} = pop(), - Expected = lists:flatten(io_lib:format("[~w] ~w {foolish,bees}", [Map, self()])), - ?assertEqual(Expected, lists:flatten(Msg)) + {Level, _, Msg,Metadata} = pop(), + ?assertEqual(lager_util:level_to_num(Map),Level), + ?assertEqual(self(),proplists:get_value(pid,Metadata)), + ?assertEqual("{foolish,bees}", lists:flatten(Msg)) end }, {"application stop reports", fun() -> sync_error_logger:info_report([{application, foo}, {exited, quittin_time}, {type, lazy}]), _ = gen_event:which_handlers(error_logger), - {_, _, Msg} = pop(), - Expected = lists:flatten(io_lib:format("[info] ~w Application foo exited with reason: quittin_time", [self()])), - ?assertEqual(Expected, lists:flatten(Msg)) + {Level, _, Msg,Metadata} = pop(), + ?assertEqual(lager_util:level_to_num(info),Level), + ?assertEqual(self(),proplists:get_value(pid,Metadata)), + ?assertEqual("Application foo exited with reason: quittin_time", lists:flatten(Msg)) end }, {"supervisor reports", fun() -> sync_error_logger:error_report(supervisor_report, [{errorContext, france}, {offender, [{name, mini_steve}, {mfargs, {a, b, [c]}}, {pid, bleh}]}, {reason, fired}, {supervisor, {local, steve}}]), _ = gen_event:which_handlers(error_logger), - {_, _, Msg} = pop(), - Expected = lists:flatten(io_lib:format("[error] ~w Supervisor steve had child mini_steve started with a:b(c) at bleh exit with reason fired in context france", [self()])), - ?assertEqual(Expected, lists:flatten(Msg)) + {Level, _, Msg,Metadata} = pop(), + ?assertEqual(lager_util:level_to_num(error),Level), + ?assertEqual(self(),proplists:get_value(pid,Metadata)), + ?assertEqual("Supervisor steve had child mini_steve started with a:b(c) at bleh exit with reason fired in context france", lists:flatten(Msg)) end }, {"supervisor reports with real error", fun() -> sync_error_logger:error_report(supervisor_report, [{errorContext, france}, {offender, [{name, mini_steve}, {mfargs, {a, b, [c]}}, {pid, bleh}]}, {reason, {function_clause,[{crash,handle_info,[foo]}]}}, {supervisor, {local, steve}}]), _ = gen_event:which_handlers(error_logger), - {_, _, Msg} = pop(), - Expected = lists:flatten(io_lib:format("[error] ~w Supervisor steve had child mini_steve started with a:b(c) at bleh exit with reason no function clause matching crash:handle_info(foo) in context france", [self()])), - ?assertEqual(Expected, lists:flatten(Msg)) + {Level, _, Msg,Metadata} = pop(), + ?assertEqual(lager_util:level_to_num(error),Level), + ?assertEqual(self(),proplists:get_value(pid,Metadata)), + ?assertEqual("Supervisor steve had child mini_steve started with a:b(c) at bleh exit with reason no function clause matching crash:handle_info(foo) in context france", lists:flatten(Msg)) end }, @@ -638,17 +543,20 @@ error_logger_redirect_test_() -> fun() -> sync_error_logger:error_report(supervisor_report, [{errorContext, france}, {offender, [{mod, mini_steve}, {pid, bleh}]}, {reason, fired}, {supervisor, {local, steve}}]), _ = gen_event:which_handlers(error_logger), - {_, _, Msg} = pop(), - Expected = lists:flatten(io_lib:format("[error] ~w Supervisor steve had child at module mini_steve at bleh exit with reason fired in context france", [self()])), - ?assertEqual(Expected, lists:flatten(Msg)) + {Level, _, Msg,Metadata} = pop(), + ?assertEqual(lager_util:level_to_num(error),Level), + ?assertEqual(self(),proplists:get_value(pid,Metadata)), + ?assertEqual("Supervisor steve had child at module mini_steve at bleh exit with reason fired in context france", lists:flatten(Msg)) end }, {"application progress report", fun() -> sync_error_logger:info_report(progress, [{application, foo}, {started_at, node()}]), _ = gen_event:which_handlers(error_logger), - {_, _, Msg} = pop(), - Expected = lists:flatten(io_lib:format("[info] ~w Application foo started on node ~w", [self(), node()])), + {Level, _, Msg,Metadata} = pop(), + ?assertEqual(lager_util:level_to_num(info),Level), + ?assertEqual(self(),proplists:get_value(pid,Metadata)), + Expected = lists:flatten(io_lib:format("Application foo started on node ~w", [node()])), ?assertEqual(Expected, lists:flatten(Msg)) end }, @@ -657,17 +565,20 @@ error_logger_redirect_test_() -> lager:set_loglevel(?MODULE, debug), sync_error_logger:info_report(progress, [{supervisor, {local, foo}}, {started, [{mfargs, {foo, bar, 1}}, {pid, baz}]}]), _ = gen_event:which_handlers(error_logger), - {_, _, Msg} = pop(), - Expected = lists:flatten(io_lib:format("[debug] ~w Supervisor foo started foo:bar/1 at pid baz", [self()])), - ?assertEqual(Expected, lists:flatten(Msg)) + {Level, _, Msg,Metadata} = pop(), + ?assertEqual(lager_util:level_to_num(debug),Level), + ?assertEqual(self(),proplists:get_value(pid,Metadata)), + ?assertEqual("Supervisor foo started foo:bar/1 at pid baz", lists:flatten(Msg)) end }, {"crash report for emfile", fun() -> sync_error_logger:error_report(crash_report, [[{pid, self()}, {registered_name, []}, {error_info, {error, emfile, [{stack, trace, 1}]}}], []]), _ = gen_event:which_handlers(error_logger), - {_, _, Msg} = pop(), - Expected = lists:flatten(io_lib:format("[error] ~w CRASH REPORT Process ~w with 0 neighbours crashed with reason: maximum number of file descriptors exhausted, check ulimit -n", [self(), self()])), + {Level, _, Msg,Metadata} = pop(), + ?assertEqual(lager_util:level_to_num(error),Level), + ?assertEqual(self(),proplists:get_value(pid,Metadata)), + Expected = lists:flatten(io_lib:format("CRASH REPORT Process ~w with 0 neighbours crashed with reason: maximum number of file descriptors exhausted, check ulimit -n", [self()])), ?assertEqual(Expected, lists:flatten(Msg)) end }, @@ -675,8 +586,10 @@ error_logger_redirect_test_() -> fun() -> sync_error_logger:error_report(crash_report, [[{pid, self()}, {registered_name, []}, {error_info, {error, system_limit, [{erlang, spawn, 1}]}}], []]), _ = gen_event:which_handlers(error_logger), - {_, _, Msg} = pop(), - Expected = lists:flatten(io_lib:format("[error] ~w CRASH REPORT Process ~w with 0 neighbours crashed with reason: system limit: maximum number of processes exceeded", [self(), self()])), + {Level, _, Msg,Metadata} = pop(), + ?assertEqual(lager_util:level_to_num(error),Level), + ?assertEqual(self(),proplists:get_value(pid,Metadata)), + Expected = lists:flatten(io_lib:format("CRASH REPORT Process ~w with 0 neighbours crashed with reason: system limit: maximum number of processes exceeded", [self()])), ?assertEqual(Expected, lists:flatten(Msg)) end }, @@ -684,8 +597,10 @@ error_logger_redirect_test_() -> fun() -> sync_error_logger:error_report(crash_report, [[{pid, self()}, {registered_name, []}, {error_info, {error, system_limit, [{erlang, spawn_opt, 1}]}}], []]), _ = gen_event:which_handlers(error_logger), - {_, _, Msg} = pop(), - Expected = lists:flatten(io_lib:format("[error] ~w CRASH REPORT Process ~w with 0 neighbours crashed with reason: system limit: maximum number of processes exceeded", [self(), self()])), + {Level, _, Msg,Metadata} = pop(), + ?assertEqual(lager_util:level_to_num(error),Level), + ?assertEqual(self(),proplists:get_value(pid,Metadata)), + Expected = lists:flatten(io_lib:format("CRASH REPORT Process ~w with 0 neighbours crashed with reason: system limit: maximum number of processes exceeded", [self()])), ?assertEqual(Expected, lists:flatten(Msg)) end }, @@ -693,8 +608,10 @@ error_logger_redirect_test_() -> fun() -> sync_error_logger:error_report(crash_report, [[{pid, self()}, {registered_name, []}, {error_info, {error, system_limit, [{erlang, open_port, 1}]}}], []]), _ = gen_event:which_handlers(error_logger), - {_, _, Msg} = pop(), - Expected = lists:flatten(io_lib:format("[error] ~w CRASH REPORT Process ~w with 0 neighbours crashed with reason: system limit: maximum number of ports exceeded", [self(), self()])), + {Level, _, Msg,Metadata} = pop(), + ?assertEqual(lager_util:level_to_num(error),Level), + ?assertEqual(self(),proplists:get_value(pid,Metadata)), + Expected = lists:flatten(io_lib:format("CRASH REPORT Process ~w with 0 neighbours crashed with reason: system limit: maximum number of ports exceeded", [self()])), ?assertEqual(Expected, lists:flatten(Msg)) end }, @@ -702,8 +619,10 @@ error_logger_redirect_test_() -> fun() -> sync_error_logger:error_report(crash_report, [[{pid, self()}, {registered_name, []}, {error_info, {error, system_limit, [{erlang, list_to_atom, 1}]}}], []]), _ = gen_event:which_handlers(error_logger), - {_, _, Msg} = pop(), - Expected = lists:flatten(io_lib:format("[error] ~w CRASH REPORT Process ~w with 0 neighbours crashed with reason: system limit: tried to create an atom larger than 255, or maximum atom count exceeded", [self(), self()])), + {Level, _, Msg,Metadata} = pop(), + ?assertEqual(lager_util:level_to_num(error),Level), + ?assertEqual(self(),proplists:get_value(pid,Metadata)), + Expected = lists:flatten(io_lib:format("CRASH REPORT Process ~w with 0 neighbours crashed with reason: system limit: tried to create an atom larger than 255, or maximum atom count exceeded", [self()])), ?assertEqual(Expected, lists:flatten(Msg)) end }, @@ -711,8 +630,10 @@ error_logger_redirect_test_() -> fun() -> sync_error_logger:error_report(crash_report, [[{pid, self()}, {registered_name, test}, {error_info, {error, system_limit, [{ets,new,[segment_offsets,[ordered_set,public]]},{mi_segment,open_write,1},{mi_buffer_converter,handle_cast,2},{gen_server,handle_msg,5},{proc_lib,init_p_do_apply,3}]}}], []]), _ = gen_event:which_handlers(error_logger), - {_, _, Msg} = pop(), - Expected = lists:flatten(io_lib:format("[error] ~w CRASH REPORT Process ~w with 0 neighbours crashed with reason: system limit: maximum number of ETS tables exceeded", [self(), test])), + {Level, _, Msg,Metadata} = pop(), + ?assertEqual(lager_util:level_to_num(error),Level), + ?assertEqual(self(),proplists:get_value(pid,Metadata)), + Expected = lists:flatten(io_lib:format("CRASH REPORT Process ~w with 0 neighbours crashed with reason: system limit: maximum number of ETS tables exceeded", [test])), ?assertEqual(Expected, lists:flatten(Msg)) end }, @@ -720,9 +641,9 @@ error_logger_redirect_test_() -> fun() -> sync_error_logger:error_report(crash_report, [[{pid, self()}, {error_info, {error, system_limit, [{wtf,boom,[string:copies("aaaa", 4096)]}]}}], []]), _ = gen_event:which_handlers(error_logger), - {_, _, Msg} = pop(), - ?assert(length(lists:flatten(Msg)) > 600), - ?assert(length(lists:flatten(Msg)) < 650) + {_, _, Msg,_Metadata} = pop(), + ?assert(length(lists:flatten(Msg)) > 550), + ?assert(length(lists:flatten(Msg)) < 600) end }, {"crash reports for 'special processes' should be handled right - function_clause", @@ -732,9 +653,9 @@ error_logger_redirect_test_() -> Pid ! function_clause, timer:sleep(500), _ = gen_event:which_handlers(error_logger), - {_, _, Msg} = pop(), - Expected = lists:flatten(io_lib:format("[error] ~p CRASH REPORT Process ~p with 0 neighbours crashed with reason: no function clause matching special_process:foo(bar)", - [Pid, Pid])), + {_, _, Msg, _Metadata} = pop(), + Expected = lists:flatten(io_lib:format("CRASH REPORT Process ~p with 0 neighbours crashed with reason: no function clause matching special_process:foo(bar)", + [Pid])), test_body(Expected, lists:flatten(Msg)) end }, @@ -745,9 +666,9 @@ error_logger_redirect_test_() -> Pid ! {case_clause, wtf}, timer:sleep(500), _ = gen_event:which_handlers(error_logger), - {_, _, Msg} = pop(), - Expected = lists:flatten(io_lib:format("[error] ~p CRASH REPORT Process ~p with 0 neighbours crashed with reason: no case clause matching wtf in special_process:loop/0", - [Pid, Pid])), + {_, _, Msg, _Metadata} = pop(), + Expected = lists:flatten(io_lib:format("CRASH REPORT Process ~p with 0 neighbours crashed with reason: no case clause matching wtf in special_process:loop/0", + [Pid])), test_body(Expected, lists:flatten(Msg)) end }, @@ -758,9 +679,9 @@ error_logger_redirect_test_() -> Pid ! exit, timer:sleep(500), _ = gen_event:which_handlers(error_logger), - {_, _, Msg} = pop(), - Expected = lists:flatten(io_lib:format("[error] ~p CRASH REPORT Process ~p with 0 neighbours exited with reason: byebye in special_process:loop/0", - [Pid, Pid])), + {_, _, Msg, _Metadata} = pop(), + Expected = lists:flatten(io_lib:format("CRASH REPORT Process ~p with 0 neighbours exited with reason: byebye in special_process:loop/0", + [Pid])), test_body(Expected, lists:flatten(Msg)) end }, @@ -771,9 +692,9 @@ error_logger_redirect_test_() -> Pid ! error, timer:sleep(500), _ = gen_event:which_handlers(error_logger), - {_, _, Msg} = pop(), - Expected = lists:flatten(io_lib:format("[error] ~p CRASH REPORT Process ~p with 0 neighbours crashed with reason: mybad in special_process:loop/0", - [Pid, Pid])), + {_, _, Msg, _Metadata} = pop(), + Expected = lists:flatten(io_lib:format("CRASH REPORT Process ~p with 0 neighbours crashed with reason: mybad in special_process:loop/0", + [Pid])), test_body(Expected, lists:flatten(Msg)) end },