瀏覽代碼

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.

pull/74/head
Jason Wagner 13 年之前
committed by Andrew Thompson
父節點
當前提交
0415d21669
共有 13 個檔案被更改,包括 546 行新增395 行删除
  1. +1
    -0
      .gitignore
  2. +39
    -0
      README.org
  3. +17
    -4
      include/lager.hrl
  4. +34
    -64
      src/lager.erl
  5. +40
    -2
      src/lager_app.erl
  6. +41
    -0
      src/lager_backend_utils.erl
  7. +24
    -30
      src/lager_console_backend.erl
  8. +4
    -4
      src/lager_crash_log.erl
  9. +107
    -0
      src/lager_default_formatter.erl
  10. +49
    -16
      src/lager_file_backend.erl
  11. +3
    -3
      src/lager_handler_watcher.erl
  12. +13
    -19
      src/lager_transform.erl
  13. +174
    -253
      test/lager_test_backend.erl

+ 1
- 0
.gitignore 查看文件

@ -4,3 +4,4 @@ ebin
doc
*.swp
erl_crash.dump
.project

+ 39
- 0
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

+ 17
- 4
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.

+ 34
- 64
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

+ 40
- 2
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.

+ 41
- 0
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.

+ 24
- 30
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)

+ 4
- 4
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"),

+ 107
- 0
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.

+ 49
- 16
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.

+ 3
- 3
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

+ 13
- 19
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;

+ 174
- 253
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
},

Loading…
取消
儲存