Skip to content
Browse files

Changed the messages sent to the backends to include metadata and sep…

…arated formatting from the backend. Added documentation, fixed tests, and removed some unused code.
  • Loading branch information...
1 parent 77e7b68 commit 0415d21669305185ab0b27d495d910fe65af4a77 @nialscorva nialscorva committed with Vagabond Dec 1, 2011
View
1 .gitignore
@@ -4,3 +4,4 @@ ebin
doc
*.swp
erl_crash.dump
+.project
View
39 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
View
21 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.
+
View
98 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
View
42 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.
View
41 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.
View
54 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)
View
8 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"),
View
107 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.
View
65 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.
View
6 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
View
32 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;
View
427 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,23 +110,19 @@ 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
},
{"logging with arguments works",
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,112 +345,132 @@ 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
},
{"error messages are printed",
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
},
{"error messages are truncated at 4096 characters",
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
},
{"info reports are printed",
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
},
{"info reports are truncated at 4096 characters",
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
},
{"single term info reports are printed",
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
},
{"strings in a mixed report are printed as strings",
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,74 +480,83 @@ 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",
fun() ->
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",
fun() ->
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
},
{"supervisor_bridge reports",
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,72 +565,85 @@ 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
},
{"crash report for system process limit",
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
},
{"crash report for system process limit2",
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
},
{"crash report for system port limit",
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
},
{"crash report for system port limit",
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
},
{"crash report for system ets table limit",
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
},
{"crash report for unknown system limit should be truncated at 500 characters",
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
},

0 comments on commit 0415d21

Please sign in to comment.
Something went wrong with that request. Please try again.