Skip to content

HTTPS clone URL

Subversion checkout URL

You can clone with HTTPS or Subversion.

Download ZIP
Browse files

Adding optional log deduplication to lager

This adds log deduplication based on a near-duplicate
analysis of formatted messages (without node or timestamp)
over a given period of time. The objective is to allow
long chains of repeated events in a short burst of time
to be reduced to smaller quantities of text transmitted
and buffered to the error logger. This should allow more
resilience to overload situations, and allow to take less
place during long cascades of failures.
  • Loading branch information...
commit 9ef0e7b94bf235572ef3f8abe00a3f1ed41e70bd 1 parent 7986ec4
@ferd authored
View
20 src/lager.app.src
@@ -34,6 +34,24 @@
%% current one - default is 0
{crash_log_count, 5},
%% Whether to redirect error_logger messages into lager - defaults to true
- {error_logger_redirect, true}
+ {error_logger_redirect, true},
+ %% How sensitive lager should be to near-duplicates. 0 means no
+ %% special handling is done
+ {duplicate_threshold, 0},
+ %% How frequently lager should dump its duplicate entries, in milliseconds.
+ %% only used if duplicate_threshold > 0
+ {duplicate_dump, 1000},
+ %% How many similar messages can be logged per dump. If 150 log
+ %% messages are identical but this limit is set to 5, the log handler
+ %% will only receive 5 of them and show (5 times+) instead of (N times).
+ %% a value of 0 or 'undefined' disables limits.
+ {duplicate_limit, undefined},
+ %% Duplicate detection, by default, will eat up all the messages in a given
+ %% time period before dumping them. If the waiting time is set high (say a
+ %% minute or so), it means reaction time is much higher. Setting
+ %% 'duplicate_quick_notification' to 'true' makes the first message of a
+ %% given error go through, while accumulating the later ones to make sure
+ %% you get both quick reporting and deduplication of messages.
+ {duplicate_quick_notification, false}
]}
]}.
View
9 src/lager.erl
@@ -76,8 +76,13 @@ dispatch_log(Severity, Metadata, Format, Args, Size) when is_atom(Severity)->
_ ->
Format
end,
- gen_event:sync_notify(Pid, {log, lager_msg:new(Msg, Timestamp,
- Severity, Metadata, Destinations)});
+ Event = {log, lager_msg:new(Msg, Timestamp, Severity, Metadata, Destinations)},
+ case lager_config:get(duplicate_threshold, 0) of
+ 0 ->
+ gen_event:sync_notify(Pid, Event);
+ N when N > 0 ->
+ lager_deduper:dedup_notify(Event)
+ end;
_ ->
ok
end
View
21 src/lager_app.erl
@@ -52,6 +52,27 @@ start(_StartType, _StartArgs) ->
{_, Traces} = lager_config:get(loglevel),
lager_config:set(loglevel, {MinLog, Traces}),
+ Threshold = case application:get_env(lager, duplicate_threshold) of
+ {ok, ThresV} when ThresV > 0 -> ThresV;
+ _ -> 0
+ end,
+ lager_config:set(duplicate_threshold, Threshold),
+ DumpDelay = case application:get_env(lager, duplicate_dump) of
+ {ok, DupDumpDelay} -> DupDumpDelay;
+ _ -> 1000
+ end,
+ lager_config:set(duplicate_dump, DumpDelay),
+ DupLimit = case application:get_env(lager, duplicate_limit) of
+ {ok, DupLim} -> DupLim;
+ _ -> undefined
+ end,
+ lager_config:set(duplicate_limit, DupLimit),
+ DupQuick = case application:get_env(lager, duplicate_quick_notification) of
+ {ok, QuickDup} -> QuickDup;
+ _ -> false
+ end,
+ lager_config:set(duplicate_quick_notification, DupQuick),
+
SavedHandlers = case application:get_env(lager, error_logger_redirect) of
{ok, false} ->
[];
View
299 src/lager_deduper.erl
@@ -0,0 +1,299 @@
+-module(lager_deduper).
+-behaviour(gen_server).
+-export([start_link/0, dedup_notify/1]).
+-export([init/1, handle_call/3, handle_cast/2, handle_info/2,
+ code_change/3, terminate/2]).
+
+-define(SERVER, ?MODULE).
+-define(TABLE, ?MODULE).
+-define(DEFAULT_TIMEOUT, 1000).
+-ifdef(TEST).
+-include_lib("eunit/include/eunit.hrl").
+-endif.
+
+-record(state, {timer, db}).
+
+
+start_link() ->
+ gen_server:start_link({local, ?SERVER}, ?MODULE, [], []).
+
+dedup_notify({log, Log}) ->
+ Hash = hash(Log),
+ Level = lager_msg:severity_as_int(Log),
+ Key = {Level, Hash},
+ case limit() of
+ undefined -> ask_seen(Key, Log);
+ 0 -> ask_seen(Key, Log);
+ Limit ->
+ case ets:lookup(?TABLE, Key) of
+ [] -> % not seen
+ ask_seen(Key, Log);
+ [{_,X,_}] when X < Limit -> % seen, but not too often
+ ask_seen(Key, Log);
+ [_] -> % seen too many times
+ ok
+ end
+ end.
+
+ask_seen(Key, Log) ->
+ case gen_server:call(?SERVER, {seen, Key}, infinity) of
+ yes ->
+ ok;
+ no ->
+ gen_server:cast(?SERVER, {set, Key, {log, Log}})
+ end.
+
+hash(Log) ->
+ %% The location can be important, but not always -- depends on
+ %% where error logging takes place. We give it a weight equivalent
+ %% to 25% of the total hash, which seemed to strike a fair balance.
+ %% For partial data (Mod:Fun) we give a weight of 10% (still arbitrary)
+ %% and under this, we let it be as is.
+ %% If no location data is found, only the message is used.
+ %% Note that we use a term_to_binary representation of the MFA data
+ %% given it is as relevent as strings, but likely quicker to obtain.
+ Res = shingle(lager_msg:message(Log)),
+ Meta = lager_msg:metadata(Log),
+ ToHash = case {proplists:get_value(module, Meta),
+ proplists:get_value(function, Meta),
+ proplists:get_value(line, Meta)} of
+ {undefined,undefined,undefined} ->
+ Res;
+ {_Mod,undefined,undefined} ->
+ Res;
+ {Mod,Fun,undefined} ->
+ Weight = round(length(Res) * 0.1),
+ [{Weight, term_to_binary({Mod,Fun})} | Res];
+ {Mod,Fun,Line} ->
+ Weight = round(length(Res) * 0.25),
+ [{Weight, term_to_binary({Mod,Fun,Line})} | Res]
+ end,
+ lager_simhash:hash(ToHash, fun erlang:md5/1, 128).
+
+shingle(IoList) ->
+ %% Equivalent to "\s|,|\\.", or \s|,|\. as a non-escaped regex
+ Pattern = {re_pattern,0,0,
+ <<69,82,67,80,67,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,48,0,
+ 0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,93,0,5,27,32,
+ 83,0,5,27,44,83,0,5,27,46,84,0,15,0>>},
+ Shingles = [{1, X} || X <- re:split(IoList, Pattern, [{return, binary}]), X =/= <<>>],
+ case Shingles of
+ [] ->
+ %% pathological case, message is only whitespace and punctuation.
+ %% We do it by taking things byte by byte instead. This is sub-optimal,
+ %% but better than crashing and burning!
+ [{1, <<Byte:8>>} || <<Byte:8>> <= iolist_to_binary(IoList)];
+ _ ->
+ Shingles
+ end.
+
+init([]) ->
+ Ref = erlang:start_timer(delay(), self(), dump),
+ {ok, #state{timer=Ref, db=empty()}}.
+
+handle_call({seen, Key}, _From, S = #state{db=DB}) ->
+ case lookup(Key, DB) of
+ {ok, _} ->
+ {reply, yes, S#state{db=increment(Key, DB)}};
+ undefined ->
+ case close_enough(Key, DB, threshold()) of
+ {_Dist, MatchKey} ->
+ {reply, yes, S#state{db=increment(MatchKey, DB)}};
+ _ ->
+ {reply, no, S#state{db=store(Key, undefined, DB)}}
+ end
+ end;
+%% hidden call, mostly useful for tests where we need to
+%% synchronously dump the messages.
+handle_call(dump, _From, S=#state{timer=Ref}) ->
+ erlang:cancel_timer(Ref),
+ {noreply, NewState} = handle_info({timeout, Ref, dump}, S),
+ {reply, ok, NewState}.
+
+handle_cast({set, Key, Val}, S=#state{db=DB}) ->
+ case quick() of
+ true -> safe_notify(Val);
+ false -> ok
+ end,
+ {noreply, S#state{db=store(Key, Val, DB)}}.
+
+handle_info({timeout, _Ref, dump}, S=#state{db=DB}) ->
+ NewRef = erlang:start_timer(delay(), self(), dump),
+ NewDB = dump(DB),
+ {noreply, S#state{timer=NewRef, db=NewDB}}.
+
+code_change(_OldVsn, State, _Extra) ->
+ {ok, State}.
+
+terminate(_, _) -> ok.
+
+delay() -> lager_config:get(duplicate_dump, ?DEFAULT_TIMEOUT).
+threshold() -> lager_config:get(duplicate_threshold, 1).
+limit() -> lager_config:get(duplicate_limit, undefined).
+quick() -> lager_config:get(duplicate_quick_notification, false).
+
+empty() -> ets:new(?TABLE, [protected,named_table]).
+
+lookup(Key, Tab) ->
+ case ets:lookup(Tab, Key) of
+ [] -> undefined;
+ [{_,Ct,Val}] -> {ok,{Ct,Val}}
+ end.
+
+%% assumes the key is present
+increment(Key, Tab) ->
+ ets:update_counter(Tab, Key, 1),
+ Tab.
+
+store(Key, Val, Tab) ->
+ case ets:update_element(Tab, Key, {3,Val}) of
+ false ->
+ case quick() of
+ false ->
+ ets:insert(Tab, {Key, 1, Val});
+ true ->
+ ets:insert(Tab, {Key, 0, Val})
+ end;
+ true -> ok
+ end,
+ Tab.
+
+close_enough(Key, Tab, Limit) ->
+ close_enough(Key, Tab, Limit, ets:first(Tab)).
+
+close_enough({Level, Hash}, Tab, Limit, Current = {Level, H}) ->
+ case lager_simhash:distance(Hash, H) of
+ X when X =< Limit ->
+ {X, {Level, H}};
+ _ ->
+ close_enough({Level, Hash}, Tab, Limit, ets:next(Tab, Current))
+ end;
+close_enough(_, _, _, '$end_of_table') ->
+ undefined;
+close_enough(Key, Tab, Limit, Current) ->
+ close_enough(Key, Tab, Limit, ets:next(Tab, Current)).
+
+dump(Tab) ->
+ dump(Tab, ets:first(Tab)).
+
+dump(Tab, '$end_of_table') ->
+ Tab;
+dump(Tab, Current) ->
+ case ets:lookup(Tab, Current) of
+ [{_,_,undefined}] -> % may occur between hash set and log
+ dump(Tab, ets:next(Tab, Current));
+ [{Key, 0, _Log}] -> % handled with quick notification, discard
+ Next = ets:next(Tab, Current),
+ ets:delete(Tab, Key),
+ dump(Tab, Next);
+ [{Key, 1, Log = {log, _}}] ->
+ safe_notify(Log),
+ Next = ets:next(Tab, Current),
+ ets:delete(Tab, Key),
+ dump(Tab, Next);
+ [{Key, Ct, {log, Log}}] ->
+ Msg = lager_msg:message(Log),
+ TS = lager_msg:timestamp(Log),
+ Lvl = lager_msg:severity(Log),
+ Meta = lager_msg:metadata(Log),
+ Dest = lager_msg:destinations(Log),
+ NewLog = lager_msg:new(
+ [Msg | io_lib:format(" (~b times~s)", [Ct, plus(Ct)])],
+ TS, Lvl, Meta, Dest
+ ),
+ safe_notify({log, NewLog}),
+ Next = ets:next(Tab, Current),
+ ets:delete(Tab,Key),
+ dump(Tab, Next)
+ end.
+
+%% helper to display log count
+plus(Ct) ->
+ Limit = limit(),
+ if Limit =/= undefined, Limit > 0, Ct >= Limit -> "+";
+ true -> ""
+ end.
+
+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.
+
+
+-ifdef(TEST_CANCELLED).
+setup(Threshold, Timer) ->
+ {ok, DedupPid} = start_link(),
+ unlink(DedupPid),
+ lager_config:new(),
+ lager_config:set(duplicate_threshold, Threshold),
+ lager_config:set(duplicate_dump, Timer),
+ lager_config:set(duplicate_limit, undefined),
+ lager_config:set(duplicate_quick_notification, false),
+ DedupPid.
+
+cleanup(Pid) ->
+ lager_config:set(duplicate_threshold, 0),
+ lager_config:set(duplicate_limit, undefined),
+ lager_config:set(duplicate_quick_notification, false),
+ exit(Pid, shutdown).
+
+low_threshold_test_() ->
+ {"Check that with low threshold, all messages are handled individually",
+ {foreach,
+ fun() -> setup(1, 100000) end,
+ fun cleanup/1,
+ [fun(Pid) ->
+ warning_counter(
+ Pid, 2,
+ [{warning, <<"hello mr bond, how are you today?">>},
+ {warning, <<"hella mr bond, how are you today?">>}])
+ end]}}.
+
+high_threshold_test_() ->
+ {"Check that with high threshold, all messages are handled according to "
+ "similarity. Super-high thresholds mean all messages get merged.",
+ {foreach,
+ fun() -> setup(100000, 100000) end,
+ fun cleanup/1,
+ [fun(Pid) ->
+ warning_counter(
+ Pid, 1,
+ [{warning, "hello mr bond, how are you today?"},
+ {warning, "hella mr bond, how are you today?"},
+ {warning, "my cat is blue."}])
+ end,
+ fun(Pid) ->
+ %% different levels won't mix, even with high thresholds.
+ warning_counter(
+ Pid, 2,
+ [{warning, "hello mr bond, how are you today?"},
+ {error, "hello mr bond, how are you today?"}])
+ end]}}.
+
+-spec warning_counter(pid(), Expected::number(), [{Level::atom(),Msg::binary()}]) -> term().
+warning_counter(Pid, Expected, Msgs) ->
+ register(lager_event, self()),
+ [dedup_notify({log, lager_msg:new(
+ Msg, lager_util:format_time(),
+ Lvl, [{pid, self()}], []
+ )}) || {Lvl, Msg} <- Msgs],
+ Pid ! {timeout, make_ref(), dump},
+ Dump = receive_sync_notify(1000),
+ unregister(lager_event),
+ ?_assertEqual(Expected, length(Dump)).
+
+receive_sync_notify(Timeout) ->
+ receive
+ {_P, {From, Ref}, {sync_notify, {log, Log}}} ->
+ From ! {Ref,ok},
+ [lager_msg:message(Log) | receive_sync_notify(Timeout)];
+ X -> io:format(user, "unexpected: ~p~n", [X])
+ after Timeout ->
+ []
+ end.
+
+-endif.
View
277 src/lager_simhash.erl
@@ -0,0 +1,277 @@
+%%% Module imported from
+%%% https://github.com/ferd/simhash
+-module(lager_simhash).
+-export([hash/1, hash/3, closest/2, distance/2]).
+
+-ifdef(TEST).
+-export([test/0, testlog/0, teststruct/0]).
+-endif.
+
+%% The shingle size determines how large the sliding
+%% window goes over binary data. A size of two is slower
+%% but is likely the most accurate we can have.
+-define(SHINGLE_SIZE, 2).
+%% Each time the same shingle is met more than once in
+%% a given bit of text, its weight is increased in the final
+%% simhash.
+-define(DUP_WEIGHT_ADD,1).
+
+%% Default random hash used by simhash is MD5
+-ifndef(PHASH). -ifndef(MD5). -ifndef(SHA).
+-define(MD5, true).
+-endif. -endif. -endif.
+
+%% erlang:phash2 is the fastest, but sadly
+%% only uses 32 bits, which is not very accurate on
+%% larger binary sizes ot hash.
+-ifdef(PHASH).
+-define(SIZE, 32). % bits
+-define(HASH(X), <<(erlang:phash2(X,4294967296)):32>>).
+-endif.
+%% MD5 is faster and less precise than SHA in tests ran
+%% by the author, but it's slower and more precise than
+%% PHASH.
+-ifdef(MD5).
+-define(SIZE, 128). % bits
+-define(HASH(X), erlang:md5(X)).
+-endif.
+%% SHA-160 seemed to give the best result in terms of
+%% accuracy. In a few contrived tests, it was
+%% the slowest mode.
+-ifdef(SHA).
+-define(SIZE, 160).
+-define(HASH(X), crypto:sha(X)).
+-endif.
+
+%%%%%%%%%%%%%%
+%%% PUBLIC %%%
+%%%%%%%%%%%%%%
+-type simhash() :: binary().
+-type feature() :: {Weight::pos_integer(), binary()}.
+-type features() :: [feature()].
+-type hashfun() :: fun((binary()) -> binary()).
+-type hashsize() :: pos_integer().
+-export_type([simhash/0, feature/0, features/0,
+ hashfun/0, hashsize/0]).
+
+%% Takes any binary and returns a simhash for that data.
+-spec hash(binary()) -> simhash()
+ ; (features()) -> simhash().
+hash(Bin = <<_/binary>>) ->
+ hashed_shingles(Bin, ?SHINGLE_SIZE);
+hash(Features = [_|_]) ->
+ simhash_features(Features).
+
+%% Takes any binary and returns a simhash for that data, based
+%% on whatever hash and size is given by the user.
+-spec hash(binary(), hashfun(), hashsize()) -> simhash()
+ ; (features(), hashfun(), hashsize()) -> simhash().
+hash(Bin = <<_/binary>>, HashFun, Size) ->
+ hashed_shingles(Bin, ?SHINGLE_SIZE, HashFun, Size);
+hash(Features = [_|_], HashFun, Size) ->
+ simhash_features(Features, HashFun, Size).
+
+%% Takes a given simhash and returns the closest simhash
+%% in a second list, based on their Hamming distance.
+-spec closest(simhash(), [simhash(),...]) -> {non_neg_integer(), simhash()}.
+closest(Hash, [H|T]) ->
+ closest(Hash, hamming(Hash,H), H, T).
+
+%% Takes two simhashes and returns their distance.
+-spec distance(simhash(), simhash()) -> non_neg_integer().
+distance(X,Y) -> hamming(X,Y).
+
+%%%%%%%%%%%%%%%
+%%% PRIVATE %%%
+%%%%%%%%%%%%%%%
+
+%% Takes a given set of features and hashes them according
+%% to the algorithm used when compiling the module.
+simhash_features(Features) ->
+ Hashes = [{W, ?HASH(Feature)} || {W,Feature} <- Features],
+ to_sim(reduce(Hashes, ?SIZE-1)).
+
+simhash_features(Features, Hash, Size) ->
+ Hashes = [{W, Hash(Feature)} || {W,Feature} <- Features],
+ to_sim(reduce(Hashes, Size-1)).
+
+%% Returns a set of shingles, hashed according to the algorithm
+%% used when compiling the module.
+hashed_shingles(Bin, Size) ->
+ simhash_features(shingles(Bin, Size)).
+
+hashed_shingles(Bin, Size, HashFun, HashSize) ->
+ simhash_features(shingles(Bin, Size), HashFun, HashSize).
+
+%% The vector returned from reduce/2 is taken and flattened
+%% by its content -- values greater or equal to 0 end up being 1,
+%% and those smaller than 0 end up being 0.
+to_sim(HashL) ->
+ << <<(case Val >= 0 of
+ true -> 1;
+ false -> 0
+ end):1>> || Val <- HashL >>.
+
+%% Takes individually hashed shingles and flattens them
+%% as the numeric simhash.
+%% Each N bit hash is treated as an N-vector, which is
+%% added bit-per-bit over an empty N-vector. The resulting
+%% N-vector can be used to create the sim hash.
+reduce(_, -1) -> [];
+reduce(L, Size) -> [add(L, Size, 0) | reduce(L, Size-1)].
+
+%% we add it left-to-right through shingles,
+%% rather than shingle-by-shingle first.
+add([], _, Acc) -> Acc;
+add([{W,Bin}|T], Pos, Acc) ->
+ <<_:Pos, Bit:1, _Rest/bitstring>> = Bin,
+ add(T, Pos,
+ case Bit of
+ 1 -> Acc+W;
+ 0 -> Acc-W
+ end).
+
+%% shingles are built using a sliding window of ?SIZE bytes,
+%% moving 1 byte at a time over the data. It might be interesting
+%% to move to a bit size instead.
+shingles(Bin, Size) ->
+ build(shingles(Bin, Size, (byte_size(Bin)-1)-Size, [])).
+
+shingles(Bin, Size, Pos, Acc) when Pos > 0 ->
+ <<_:Pos/binary, X:Size/binary, _/binary>> = Bin,
+ shingles(Bin, Size, Pos-1, [X|Acc]);
+shingles(_, _, _, Acc) -> Acc.
+
+build(Pieces) ->
+ build(lists:sort(Pieces), []).
+
+build([], Acc) -> Acc;
+build([H|T], [{N,H}|Acc]) -> build(T, [{N+?DUP_WEIGHT_ADD,H}|Acc]);
+build([H|T], Acc) -> build(T,[{1,H}|Acc]).
+
+%% Runs over the list of simhashes and returns the best
+%% match available.
+closest(_, D, Match, []) ->
+ {D, Match};
+closest(Hash, D, Old, [H|T]) ->
+ case hamming(Hash, H) of
+ Dist when Dist > D -> closest(Hash, D, Old, T);
+ Dist -> closest(Hash, Dist, H, T)
+ end.
+
+%% Finds the hamming distance between two different
+%% binaries.
+hamming(X,Y) ->
+ true = bit_size(X) == bit_size(Y),
+ hamming(X,Y,bit_size(X)-1,0).
+
+%% Hammign distance between two strings can be calculated
+%% by checking each of the characters and incrementing the
+%% counter by 1 each time the two values are different.
+%% In this case, we do it over individual bits of a binary.
+hamming(_,_,-1,Sum) -> Sum;
+hamming(X,Y,Pos,Sum) ->
+ case {X,Y} of
+ {<<_:Pos, Bit:1, _/bitstring>>,
+ <<_:Pos, Bit:1, _/bitstring>>} ->
+ hamming(X,Y,Pos-1,Sum);
+ {_,_} ->
+ hamming(X,Y,Pos-1,Sum+1)
+ end.
+
+-ifdef(TEST).
+%%% ad-hoc demos/benches, useful when fiddling with new features
+%%% that can require manual validation, without actually impacting
+%%% tests in test/simhash_SUITE.erl.
+
+test() ->
+ L = [<<"the cat sat on the mat">>,<<"the cat sat on a mat">>,
+ <<"my car is grey">>,<<"we all scream for ice cream">>,
+ <<"my heart will go on">>,
+ <<"bless this mess with all the might you have">>,
+ <<"the fat cat is a rat">>,
+ <<"a scream for the supreme cream">>,<<"my car is great">>],
+ DB = [{simhash:hash(Str), Str} || Str <- L],
+ F = fun(Str) -> {Dist, Hash} = simhash:closest(simhash:hash(Str), [Hash || {Hash, _} <- DB]),
+ {Dist, Str, proplists:get_value(Hash, DB)}
+ end,
+ [F(<<"my fat hat is a rat">>),
+ F(<<"unrelated text, entirely!!!">>),
+ F(<<"my cart will go long">>),
+ F(<<"the crop and top of the cream">>),
+ F(<<"I dream of ice cream">>)].
+
+testlog() ->
+ L = [[{0,<<"2012-09-11 14:56:15.959">>},{5,<<"[info]">>}, {0,<<"<0.7.0>">>}, {1,<<"Application">>}, {10,<<"eredis">>}, {1,<<"started on node">>}, {1, <<"'gateway@host.com'">>}],
+ [{0,<<"2012-09-11 14:56:15.972">>},{5,<<"[info]">>}, {0,<<"<0.7.0>">>}, {1,<<"Application">>}, {10,<<"omething">>}, {1,<<"started on node">>}, {1, <<"'gateway@host.com'">>}],
+ [{0,<<"2012-09-11 14:56:16.054">>},{5,<<"[info]">>}, {0,<<"<0.7.0>">>}, {1,<<"Application">>}, {10,<<"gateway">>},{1,<<"started on node">>}, {1, <<"'gateway@host.com'">>}],
+ [{0,<<"2012-09-11 15:15:49.374">>},{5,<<"[warning]">>},{0,<<"<0.15224.441>">>}, {5,<<"@gateway:valid_timestamp:167">>},{1,<<"Replay">>}, {1,<<"detected">>}, {1,<<"(G_TS):">>}, {1,<<"<<\"T428\">>">>}, {1, <<"41">>}, {1, <<"<<\"market\">>">>}],
+ [{0,<<"2012-09-11 15:16:10.074">>},{5,<<"[warning]">>},{0,<<"<0.4186.452>">>}, {5,<<"@gateway:valid_timestamp:167">>},{1,<<"Replay">>}, {1,<<"detected">>}, {1,<<"(G_TS):">>}, {1,<<"<<\"T43l\">>">>}, {1, <<"21">>}, {1, <<"<<\"market\">>">>}],
+ [{0,<<"2012-09-11 15:16:10.091">>},{5,<<"[warning]">>},{0,<<"<0.4455.452>">>}, {5,<<"@gateway:valid_timestamp:167">>},{1,<<"Replay">>}, {1,<<"detected">>}, {1,<<"(G_TS):">>}, {1,<<"<<\"T43U\">>">>}, {1, <<"38">>}, {1, <<"<<\"market\">>">>}],
+ [{0,<<"2012-09-11 15:16:11.486">>},{5,<<"[warning]">>},{0,<<"<0.6040.441>">>}, {5,<<"@gateway:valid_timestamp:167">>},{1,<<"Replay">>}, {1,<<"detected">>}, {1,<<"(G_TS):">>}, {1,<<"<<\"T43i\">>">>}, {1, <<"25">>}, {1, <<"<<\"market\">>">>}],
+ [{0,<<"2012-09-11 15:18:05.026">>}, {5,<<"[error]">>}, {0,<<"<0.19153.510>">>}, {5,<<"@market:generate_response:109">>}, {3,<<"invalid_json:">>}]
+ ++ [{1, X} || X <- re:split(<<"\"lexical error: invalid bytes in UTF8 string.\n\" at 1273 (...<<97,105,115,101,115,45,72,101,114,45,84,101,97,109,146,115,45,82,97,119,45,84,97,108,101,110,116,44,53,54>>...)">>, "\s|,|\\."), X =/= <<>>],
+ [{0,<<"2012-09-11 15:39:45.113">>}, {5,<<"[error]">>}, {0,<<"<0.32341.1177>">>}, {5,<<"@market:generate_response:109">>}, {3,<<"invalid_json">>}]
+ ++ [{1, X} || X <- re:split(<<"\"lexical error: invalid bytes in UTF8 string.\n\" at 1129 (...<<32,49,46,54,59,32,102,114,45,99,97,59,32,110,252,118,105,102,111,110,101,32,65,53,48,32,66,117,105,108>>...)">>, "\s|,|\\."), X =/= <<>>],
+ [{0,<<"2012-09-11 15:39:45.113">>},{5,<<"[warning]">>},{0,<<"<0.4506.1185>">>}, {5,<<"@market:valid_timestamp:167">>},
+ {1,<<"replay">>}, {1,<<"detected">>}, {1,<<"(g_ts):">>}, {1,<<"<<\"T5N1\">>">>}, {1, <<"24">>}, {1, <<"<<\"market\">>">>}],
+ [{0,<<"2012-09-11 15:40:01.456">>},{5,<<"[warning]">>},{0,<<"<0.10828.1178>">>}, {5,<<"@gateway:valid_timestamp:167">>},
+ {1,<<"replay">>}, {1,<<"detected">>}, {1,<<"(g_ts):">>}, {1,<<"<<\"T5N6\">>">>}, {1, <<"23">>}, {1, <<"<<\"market\">>">>}],
+ [{0,<<"2012-09-11 15:40:19.782">>}, {5,<<"[error]">>}, {0,<<"<0.23906.1197>">>}, {5,<<"@market:generate_response:109">>}]
+ ++ [{1, X} || X <- re:split(<<"\"lexical error: invalid bytes in UTF8 string.\n\" at 1241 (...<<46,104,116,109,197,166,202,177,45,202,178,195,180,200,195,214,208,185,250,200,203,212,218,201,238,210,185,215,248,193>>...)">>, "\s|,|\\."), X =/= <<>>],
+ [{0,<<"2012-09-11 16:44:24.472">>}, {5,<<"[error]">>}, {3,<<"emulator Error in process">>}, {0,<<"<0.2754.3785>">>},{0,<<"on node 'gateway@host.com'">>}]
+ ++ [{1, X} || X <- re:split(<<"with exit value: {{case_clause,{match,[[<<20 bytes>>],[<<15 bytes>>]]}},[{filters,is_blacklisted,1,[{file,\"src/filters.erl\"},{line,49}]},{other_market,generate_response,2,[{file,\"src/other_market.erl\"},{line,25}]}]}">>, "\s|,|\\."), X =/= <<>>],
+ [{0,<<"2012-09-11 15:57:42.827">>}, {5,<<"[error]">>}, {3,<<"emulator Error in process">>}, {0,<<"<0.15429.1866>">>},{0,<<"on node 'gateway@host.com'">>}]
+ ++ [{1, X} || X <- re:split(<<"with exit value: {{case_clause,{match,[[<<20 bytes>>],[<<5 bytes>>]]}},[{filters,is_blacklisted,1,[{file,\"src/filters.erl\"},{line,49}]},{other_market,generate_response,2,[{file,\"src/other_market.erl\"},{line,25}]}]}">>, "\s|,|\\."), X =/= <<>>]],
+ DB = [{simhash:hash(Features), Features} || Features <- L],
+ F = fun(Features) ->
+ {Dist, Hash} = simhash:closest(simhash:hash(Features),
+ [Hash || {Hash, _} <- DB]),
+ {Dist, Features, proplists:get_value(Hash, DB)}
+ end,
+ [F([{0,<<"2012-09-11 16:44:28.359">>}, {5,<<"[error]">>}, {3,<<"emulator Error in process">>}, {0,<<"<0.23466.3787>">>}, {0,<<"on node 'gateway@host.com'">>}]
+ ++ [{1, X} || X <- re:split(<<"{{case_clause,{match,[[<<20 bytes>>],[<<15 bytes>>]]}},[{filters,is_blacklisted,1,[{file,\"src/filters.erl\"},{line,49}]},{other_market,generate_response,2,[{file,\"src/other_market.erl\"},{line,25}]}]}">>, "\s|,|\\."), X =/= <<>>])
+ ,F([{0,<<"2012-09-11 16:52:08.593">>}, {5,<<"[error]">>}, {0,<<"<0.4986.4117>">>}, {5,<<"@market:generate_response:109">>}, {3,<<"invalid_json:">>}]
+ ++ [{1, X} || X <- re:split(<<"\"lexical error: invalid bytes in UTF8 string.\n\" at 1575 (...<<45,82,104,121,115,45,74,111,105,110,115,45,70,88,146,115,45,80,105,108,111,116,45,145,84,104,101,45,65,109>>...)">>, "\s|,|\\."), X =/= <<>>])
+ ,F([{0,<<"2012-09-11 16:52:18.036">>},{5,<<"[warning]">>},{0,<<"<0.28015.4123>">>}, {5,<<"@gateway:valid_timestamp:167">>},{1,<<"Replay">>}, {1,<<"detected">>}, {1,<<"(G_TS):">>}, {1,<<"<<\"T6Rf\">>">>}, {1, <<"35">>}, {1, <<"<<\"market\">>">>}])
+ ,F([{0,<<"2012-09-11 17:51:11.254">>}, {5,<<"[error]">>}, {3,<<"emulator Error in process">>}, {0,<<"<0.10101.6540>">>}, {0,<<"on node 'gateway@host.com'">>}]
+ ++ [{1, X} || X <- re:split(<<"{{case_clause,{match,[[<<20 bytes>>],[<<13 bytes>>]]}},[{filters,is_blacklisted,1,[{file,\"src/filters.erl\"},{line,49}]},{other_market,generate_response,2,[{file,\"src/other_market.erl\"},{line,25}]}]}">>, "\s|,|\\."), X =/= <<>>])
+ ,F([{0,<<"2012-09-11 19:01:35.403">>}, {5,<<"[error]">>}, {0,<<"<0.31990.1161>">>}, {2, <<"Unknown request for">>}, {1,<<"market">>},{2,<<"method: 'GET'">>}]
+ ++ [{1, X} || X <- re:split(<<"path: [<<\"win\">>,<<\"file:\">>,<<>>,<<>>,<<>>,<<\"data\">>,<<\"webkitrel\">>,<<\"miscdata\">>,<<\"html\">>,<<\"file:\">>,<<>>,<<>>,<<>>,<<\"data\">>,<<\"webkitrel\">>,<<\"miscdata\">>,<<\"html\">>,<<\"error.html\">>]">>, "\s|,|\\."), X =/= <<>>])
+ ].
+
+
+teststruct() ->
+ L = [
+ [a,b,c,d,e,f]
+ ,{{case_clause,{match,[[<<1:20>>],[<<0:3>>]]}},[{filters,is_blacklisted,1,[{file,"src/filters.erl"},{line,49}]},{other_market,generate_response,2,[{file,"src/other_market.erl"},{line,25}]}]}
+ ,{cowboy_http_protocol,request,[{http_response,{1,1},200,<<79,75>>},{state,"<0.945.0>","#Port<0.28861495>",cowboy_tcp_transport,[{'_',[{'_',rtb_handler,{config,cassanderl_dispatch,800,ets,61473,65570}}]}],{rtb_handler,{config,cassanderl_dispatch,800,ets,61473,65570}},0,5,10000,keepalive,<<67,97,99,104,101,45,67,111,110,116,114,111,108,58,32,110,111,45,99,97,99,104,101,44,32,110,111,45,115,116,111,114,101,44,32,109,117,115,116,45,114,101,118,97,108,105,100,97,116,101,44,32,112,114,111,120,121,45,114,101,118,97,108,105,100,97,116,101,13,10,67,111,110,110,101,99,116,105,111,110,58,32,107,101,101,112,45,97,108,105,118,101,13,10,67,111,110,116,101,110,116,45,76,101,110,103,116,104,58,32,57,50,53,13,10,67,111,110,116,101,110,116,45,84,121,112,101,58,32,97,112,112,108,105,99,97,116,105,111,110,47,106,97,118,97,115,99,114,105,112,116,13,10,68,97,116,101,58,32,70,114,105,44,32,49,52,32,83,101,112,32,50,48,49,50,32,48,49,58,48,53,58,48,57,32,71,77,84,13,10,80,51,80,58,32,67,80,61,34,78,79,73,32,79,84,67,32,79,84,80,32,79,85,82,32,78,79,82,34,13,10,80,114,97,103,109,97,58,32,110,111,45,99,97,99,104,101,13,10,83,101,114,118,101,114,58,32,67,111,119,98,111,121,13,10,88,45,83,101,114,118,101,114,58,32,104,48,49,49,13,10,88,45,65,110,116,105,118,105,114,117,115,58,32,97,118,97,115,116,33,32,52,13,10,88,45,65,110,116,105,118,105,114,117,115,45,83,116,97,116,117,115,58,32,67,108,101,97,110,13,10,13,10>>,2}],[{file,[115,114,99,47,99,111,119,98,111,121,95,104,116,116,112,95,112,114,111,116,111,99,111,108,46,101,114,108]},{line,97}]}
+ ,{a,
+ {b,[],[]},
+ {c,{d,{e,[],[]}},
+ {f,[],[]}}}
+ ,<<"a b c d">>
+ ,self()
+ ],
+ Format = fun erlang:term_to_binary/1,
+ DB = [{simhash:hash(Format(Str)), Str} || Str <- L],
+ F = fun(Str) ->
+ {Dist, Hash} = simhash:closest(simhash:hash(Format(Str)),
+ [Hash || {Hash, _} <- DB]),
+ {Dist, Str, proplists:get_value(Hash, DB)}
+ end,
+ [F([e,f,g,h])
+ ,F("a b c d e f")
+ ,F({'EXIT',{badarith,[{erlang,'/',[1,0],[]},
+ {erl_eval,do_apply,6,[{file,"erl_eval.erl"},{line,576}]},
+ {erl_eval,expr,5,[{file,"erl_eval.erl"},{line,360}]},
+ {shell,exprs,7,[{file,"shell.erl"},{line,668}]},
+ {shell,eval_exprs,7,[{file,"shell.erl"},{line,623}]},
+ {shell,eval_loop,3,[{file,"shell.erl"},{line,608}]}]}})
+ ,F({a,
+ {b,[],[]},
+ {c,{g,{e,[],[]}},
+ {f,[],[]}}})
+ ,F(spawn(fun() -> ok end))
+ ].
+-endif.
View
9 src/lager_sup.erl
@@ -76,7 +76,14 @@ init([]) ->
_ ->
[]
end,
+ Deduper = case application:get_env(lager, duplicate_threshold) of
+ {ok, N} when N > 0 ->
+ [{lager_deduper, {lager_deduper, start_link, []},
+ permanent, 5000, worker, [lager_deduper]}];
+ _ ->
+ []
+ end,
{ok, {{one_for_one, 10, 60},
- Children ++ Crash
+ Children ++ Crash ++ Deduper
}}.
View
68 test/lager_overload.erl
@@ -0,0 +1,68 @@
+%%% A modules that tries to crash stuff *a lot* to test how long it may
+%%% take to overload a given node with log messages, and then compare
+%%% that value with what log deduplication may do.
+%%% Has to be run by hand, nothing automated there.
+-module(lager_overload).
+-compile([{parse_transform, lager_transform}]).
+-compile(export_all).
+
+init_regular() ->
+ error_logger:tty(false),
+ application:load(lager),
+ application:set_env(lager, handlers, [{lager_console_backend, [info,true]}]),
+ application:set_env(lager, error_logger_redirect, false),
+ application:start(crypto),
+ ok=application:start(simhash),
+ application:start(compiler),
+ application:start(syntax_tools),
+ application:set_env(lager, duplicate_threshold, 0),
+ application:set_env(lager, duplicate_dump, infinity),
+ ok=application:start(lager).
+
+
+init_dedup() ->
+ error_logger:tty(false),
+ application:load(lager),
+ application:set_env(lager, handlers, [{lager_console_backend, [info,true]}]),
+ application:set_env(lager, error_logger_redirect, false),
+ application:start(crypto),
+ application:load(simhash),
+ application:start(simhash),
+ application:start(compiler),
+ application:start(syntax_tools),
+ application:set_env(lager, duplicate_threshold, 3),
+ application:set_env(lager, duplicate_dump, 1000),
+ ok=application:start(lager).
+
+regular(N) ->
+ init_regular(),
+ spawn(fun() -> spawn_errs(N) end).
+
+dedup(N) ->
+ init_dedup(),
+ spawn(fun() -> spawn_errs(N) end).
+
+spawn_errs(N) ->
+ [spawn(fun() -> err(X) end) || X <- lists:seq(1,N)],
+ spawn_errs(N).
+
+err(_) ->
+ %% 8: 1a 1b 2b 2c 3b
+ %% 6: 1b 1c 1d 2b 2c 3c 3b
+ Str = element(erlang:phash2(self(), 3)+1,
+ {"1 my error has the following stacktrace: ~p"
+ ,"2 module X failed with reason ~p"
+ ,"3 Some other different error message (~p) told me things failed."
+ }),
+ Stack = element(erlang:phash2(self(),4)+1,
+ {{a,'EXIT',{badarith,[{erlang,'/',[1,0],[]},
+ {erl_eval,do_apply,6,[{file,"erl_eval.erl"},{line,576}]},
+ {erl_eval,expr,5,[{file,"erl_eval.erl"},{line,360}]},
+ {shell,exprs,7,[{file,"shell.erl"},{line,668}]},
+ {shell,eval_exprs,7,[{file,"shell.erl"},{line,623}]},
+ {shell,eval_loop,3,[{file,"shell.erl"},{line,608}]}]}}
+ ,{b,badarg,[{erlang,atom_to_list,["y"],[]}]}
+ ,{c,{badarity,{"#Fun<erl_eval.20.82930912>",[1]}},[{lists,map,2,[{file,"lists.erl"},{line,1173}]}]}
+ ,{d,{shell_undef,apply,1,[]},[{shell,shell_undef,2,[{file,"shell.erl"},{line,1092}]},{erl_eval,local_func,5,[{file,"erl_eval.erl"},{line,475}]}]}
+ }),
+ lager:error(Str, [Stack]).
View
1,130 test/lager_test_backend_dedup.erl
@@ -0,0 +1,1130 @@
+%% Copyright (c) 2011 Basho Technologies, Inc. All Rights Reserved.
+%%
+%% This file is provided to you under the Apache License,
+%% Version 2.0 (the "License"); you may not use this file
+%% except in compliance with the License. You may obtain
+%% a copy of the License at
+%%
+%% http://www.apache.org/licenses/LICENSE-2.0
+%%
+%% Unless required by applicable law or agreed to in writing,
+%% software distributed under the License is distributed on an
+%% "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY
+%% KIND, either express or implied. See the License for the
+%% specific language governing permissions and limitations
+%% under the License.
+
+-module(lager_test_backend_dedup).
+
+-include("lager.hrl").
+
+-behaviour(gen_event).
+
+-export([init/1, handle_call/2, handle_event/2, handle_info/2, terminate/2,
+ code_change/3]).
+
+-record(state, {level, buffer, ignored}).
+-compile([{parse_transform, lager_transform}]).
+
+-ifdef(TEST).
+-include_lib("eunit/include/eunit.hrl").
+-export([pop/0, count/0, count_ignored/0, flush/0]).
+-endif.
+
+init(Level) ->
+ {ok, #state{level=lager_util:level_to_num(Level), buffer=[], ignored=[]}}.
+
+handle_call(count, #state{buffer=Buffer} = State) ->
+ {ok, length(Buffer), State};
+handle_call(count_ignored, #state{ignored=Ignored} = State) ->
+ {ok, length(Ignored), State};
+handle_call(flush, State) ->
+ {ok, ok, State#state{buffer=[], ignored=[]}};
+handle_call(pop, #state{buffer=Buffer} = State) ->
+ case Buffer of
+ [] ->
+ {ok, undefined, State};
+ [H|T] ->
+ {ok, H, State#state{buffer=T}}
+ end;
+handle_call(get_loglevel, #state{level=Level} = State) ->
+ {ok, Level, State};
+handle_call({set_loglevel, Level}, State) ->
+ {ok, ok, State#state{level=lager_util:level_to_num(Level)}};
+handle_call(_Request, State) ->
+ {ok, ok, State}.
+
+handle_event({log, Msg},
+ #state{level=LogLevel,buffer=Buffer,ignored=Ignored} = State) ->
+ case lager_util:is_loggable(Msg, LogLevel, ?MODULE) of
+ true -> {ok, State#state{buffer=Buffer ++
+ [{lager_msg:severity_as_int(Msg),
+ lager_msg:timestamp(Msg),
+ lager_msg:message(Msg), lager_msg:metadata(Msg)}]}};
+ _ -> {ok, State#state{ignored=Ignored ++ [ignored]}}
+ end;
+handle_event(_Event, State) ->
+ {ok, State}.
+
+handle_info(_Info, State) ->
+ {ok, State}.
+
+terminate(_Reason, _State) ->
+ ok.
+
+code_change(_OldVsn, State, _Extra) ->
+ {ok, State}.
+
+-ifdef(TEST).
+
+pop() ->
+ gen_server:call(lager_deduper, dump),
+ gen_event:call(lager_event, ?MODULE, pop).
+
+count() ->
+ gen_server:call(lager_deduper, dump),
+ gen_event:call(lager_event, ?MODULE, count).
+
+count_ignored() ->
+ gen_server:call(lager_deduper, dump),
+ gen_event:call(lager_event, ?MODULE, count_ignored).
+
+flush() ->
+ gen_server:call(lager_deduper, dump),
+ 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.
+
+not_running_test() ->
+ ?assertEqual({error, lager_not_running}, lager:log(info, self(), "not running")).
+
+lager_test_() ->
+ {foreach,
+ fun setup/0,
+ fun cleanup/1,
+ [
+ {"observe that there is nothing up my sleeve",
+ fun() ->
+ ?assertEqual(undefined, pop()),
+ ?assertEqual(0, count())
+ end
+ },
+ {"logging works",
+ fun() ->
+ lager:warning("test message"),
+ ?assertEqual(1, count()),
+ {Level, _Time, Message, _Metadata} = pop(),
+ ?assertMatch(Level, lager_util:level_to_num(warning)),
+ ?assertEqual("test message", Message),
+ ok
+ end
+ },
+ {"logging with arguments works",
+ fun() ->
+ lager:warning("test message ~p", [self()]),
+ ?assertEqual(1, count()),
+ {Level, _Time, Message, _Metadata} = pop(),
+ ?assertMatch(Level, lager_util:level_to_num(warning)),
+ ?assertEqual(lists:flatten(io_lib:format("test message ~p", [self()])), lists:flatten(Message)),
+ ok
+ end
+ },
+ {"logging works from inside a begin/end block",
+ fun() ->
+ ?assertEqual(0, count()),
+ begin
+ lager:warning("test message 2")
+ end,
+ ?assertEqual(1, count()),
+ ok
+ end
+ },
+ {"logging works from inside a list comprehension",
+ fun() ->
+ ?assertEqual(0, count()),
+ [lager:warning("test message") || _N <- lists:seq(1, 10)],
+ ?assertEqual(1, count()),
+ {Level, _Time, Message, _Metadata} = pop(),
+ ?assertMatch(Level, lager_util:level_to_num(warning)),
+ ?assertEqual("test message (10 times)", lists:flatten(Message)),
+ ok
+ end
+ },
+ {"logging works from a begin/end block inside a list comprehension",
+ fun() ->
+ ?assertEqual(0, count()),
+ [ begin lager:warning("test message") end || _N <- lists:seq(1, 10)],
+ ?assertEqual(1, count()),
+ {Level, _Time, Message, _Metadata} = pop(),
+ ?assertMatch(Level, lager_util:level_to_num(warning)),
+ ?assertEqual("test message (10 times)", lists:flatten(Message)),
+ ok
+ end
+ },
+ {"logging works from a nested list comprehension",
+ fun() ->
+ ?assertEqual(0, count()),
+ [ [lager:warning("test message") || _N <- lists:seq(1, 10)] ||
+ _I <- lists:seq(1, 10)],
+ ?assertEqual(1, count()),
+ {Level, _Time, Message, _Metadata} = pop(),
+ ?assertMatch(Level, lager_util:level_to_num(warning)),
+ ?assertEqual("test message (100 times)", lists:flatten(Message)),
+ ok
+ end
+ },
+ {"log messages below the threshold are ignored",
+ fun() ->
+ ?assertEqual(0, count()),
+ lager:debug("this message will be ignored"),
+ ?assertEqual(0, count()),
+ ?assertEqual(0, count_ignored()),
+ lager_config:set(loglevel, {element(2, lager_util:config_to_mask(debug)), []}),
+ lager:debug("this message should be ignored"),
+ ?assertEqual(0, count()),
+ ?assertEqual(1, count_ignored()),
+ lager:set_loglevel(?MODULE, debug),
+ lager:debug("this message should be logged"),
+ ?assertEqual(1, count()),
+ ?assertEqual(1, count_ignored()),
+ ?assertEqual(debug, lager:get_loglevel(?MODULE)),
+ ok
+ end
+ },
+ {"tracing works",
+ fun() ->
+ lager_config:set(loglevel, {element(2, lager_util:config_to_mask(error)), []}),
+ ok = lager:info("hello world"),
+ ?assertEqual(0, count()),
+ lager:trace(?MODULE, [{module, ?MODULE}], debug),
+ ok = lager:info("hello world"),
+ ?assertEqual(1, count()),
+ ok
+ end
+ },
+ {"tracing works with custom attributes",
+ fun() ->
+ lager:set_loglevel(?MODULE, error),
+ lager_config:set(loglevel, {element(2, lager_util:config_to_mask(error)), []}),
+ lager:info([{requestid, 6}], "hello world"),
+ ?assertEqual(0, count()),
+ lager:trace(?MODULE, [{requestid, 6}, {foo, bar}], debug),
+ lager:info([{requestid, 6}, {foo, bar}], "hello world"),
+ ?assertEqual(1, count()),
+ lager:trace(?MODULE, [{requestid, '*'}], debug),
+ lager:info([{requestid, 6}], "hello world"),
+ ?assertEqual(2, count()),
+ lager:clear_all_traces(),
+ lager:info([{requestid, 6}], "hello world"),
+ ?assertEqual(2, count()),
+ ok
+ end
+ },
+ {"tracing honors loglevel",
+ fun() ->
+ lager:set_loglevel(?MODULE, error),
+ {ok, T} = lager:trace(?MODULE, [{module, ?MODULE}], notice),
+ ok = lager:info("hello world"),
+ ?assertEqual(0, count()),
+ ok = lager:notice("hello world"),
+ ?assertEqual(1, count()),
+ lager:stop_trace(T),
+ ok = lager:notice("hello world"),
+ ?assertEqual(1, count()),
+ ok
+ end
+ }
+ ]
+ }.
+
+setup() ->
+ error_logger:tty(false),
+ application:load(lager),
+ application:set_env(lager, handlers, [{?MODULE, info}]),
+ application:set_env(lager, error_logger_redirect, false),
+ application:set_env(lager, duplicate_threshold, 1),
+ application:set_env(lager, duplicate_dump, 100000),
+ application:start(compiler),
+ application:start(syntax_tools),
+ ok=application:start(lager),
+ gen_server:call(lager_deduper, dump),
+ gen_event:call(lager_event, ?MODULE, flush).
+
+cleanup(_) ->
+ application:set_env(lager, duplicate_threshold, 0),
+ application:stop(lager),
+ error_logger:tty(true).
+
+lager_quick_notify_test_() ->
+ {foreach,
+ fun quick_notify_setup/0,
+ fun quick_notify_cleanup/1,
+ [
+ {"observe that there is nothing up my sleeve",
+ fun() ->
+ ?assertEqual(undefined, pop()),
+ ?assertEqual(0, count())
+ end
+ },
+ {"logging works",
+ fun() ->
+ lager:warning("test message"),
+ ?assertEqual(1, count()),
+ {Level, _Time, Message, _Metadata} = pop(),
+ ?assertMatch(Level, lager_util:level_to_num(warning)),
+ ?assertEqual("test message", Message),
+ ok
+ end
+ },
+ {"logging with arguments works",
+ fun() ->
+ lager:warning("test message ~p", [self()]),
+ ?assertEqual(1, count()),
+ {Level, _Time, Message, _Metadata} = pop(),
+ ?assertMatch(Level, lager_util:level_to_num(warning)),
+ ?assertEqual(lists:flatten(io_lib:format("test message ~p", [self()])),
+ lists:flatten(Message)),
+ ok
+ end
+ },
+ {"logging works from inside a begin/end block",
+ fun() ->
+ ?assertEqual(0, count()),
+ begin
+ lager:warning("test message 2")
+ end,
+ ?assertEqual(1, count()),
+ ok
+ end
+ },
+ {"logging works from inside a list comprehension",
+ fun() ->
+ ?assertEqual(0, count()),
+ [lager:warning("test message") || _N <- lists:seq(1, 10)],
+ ?assertEqual(2, count()),
+ {Level, _Time1, Message1, _Meta1} = pop(),
+ ?assertMatch(Level, lager_util:level_to_num(warning)),
+ ?assertEqual("test message", Message1),
+ {Level, _Time2, Message2, _Meta2} = pop(),
+ ?assertEqual("test message (9 times)", lists:flatten(Message2)),
+ ok
+ end
+ },
+ {"logging works from a begin/end block inside a list comprehension",
+ fun() ->
+ ?assertEqual(0, count()),
+ [ begin lager:warning("test message") end || _N <- lists:seq(1, 10)],
+ ?assertEqual(2, count()),
+ {Level, _Time1, Message1, _Meta1} = pop(),
+ ?assertMatch(Level, lager_util:level_to_num(warning)),
+ ?assertEqual("test message", Message1),
+ {Level, _Time2, Message2, _Meta2} = pop(),
+ ?assertEqual("test message (9 times)", lists:flatten(Message2)),
+ ok
+ end
+ },
+ {"logging works from a nested list comprehension",
+ fun() ->
+ ?assertEqual(0, count()),
+ [ [lager:warning("test message") || _N <- lists:seq(1, 10)] ||
+ _I <- lists:seq(1, 10)],
+ ?assertEqual(2, count()),
+ {Level, _Time, Message1, _Meta1} = pop(),
+ ?assertMatch(Level, lager_util:level_to_num(warning)),
+ ?assertEqual("test message", Message1),
+ {Level, _Time, Message2, _Meta2} = pop(),
+ ?assertEqual("test message (99 times)", lists:flatten(Message2)),
+ ok
+ end
+ },
+ {"log messages below the threshold are ignored",
+ fun() ->
+ ?assertEqual(0, count()),
+ lager:debug("this message will be ignored"),
+ ?assertEqual(0, count()),
+ ?assertEqual(0, count_ignored()),
+ lager_config:set(loglevel, {element(2, lager_util:config_to_mask(debug)), []}),
+ lager:debug("this message should be ignored"),
+ ?assertEqual(0, count()),
+ ?assertEqual(1, count_ignored()),
+ lager:set_loglevel(?MODULE, debug),
+ lager:debug("this message should be logged"),
+ ?assertEqual(1, count()),
+ ?assertEqual(1, count_ignored()),
+ ?assertEqual(debug, lager:get_loglevel(?MODULE)),
+ ok
+ end
+ },
+ {"tracing works",
+ fun() ->
+ lager_config:set(loglevel, {element(2, lager_util:config_to_mask(error)), []}),
+ ok = lager:info("hello world"),
+ ?assertEqual(0, count()),
+ lager:trace(?MODULE, [{module, ?MODULE}], debug),
+ ok = lager:info("hello world"),
+ ?assertEqual(1, count()),
+ ok
+ end
+ },
+ {"tracing works with custom attributes",
+ fun() ->
+ lager:set_loglevel(?MODULE, error),
+ lager_config:set(loglevel, {element(2, lager_util:config_to_mask(error)), []}),
+ lager:info([{requestid, 6}], "hello world"),
+ ?assertEqual(0, count()),
+ lager:trace(?MODULE, [{requestid, 6}, {foo, bar}], debug),
+ lager:info([{requestid, 6}, {foo, bar}], "hello world"),
+ ?assertEqual(1, count()),
+ lager:trace(?MODULE, [{requestid, '*'}], debug),
+ lager:info([{requestid, 6}], "hello world"),
+ ?assertEqual(2, count()),
+ lager:clear_all_traces(),
+ lager:info([{requestid, 6}], "hello world"),
+ ?assertEqual(2, count()),
+ ok
+ end
+ },
+ {"tracing honors loglevel",
+ fun() ->
+ lager:set_loglevel(?MODULE, error),
+ {ok, T} = lager:trace(?MODULE, [{module, ?MODULE}], notice),
+ ok = lager:info("hello world"),
+ ?assertEqual(0, count()),
+ ok = lager:notice("hello world"),
+ ?assertEqual(1, count()),
+ lager:stop_trace(T),
+ ok = lager:notice("hello world"),
+ ?assertEqual(1, count()),
+ ok
+ end
+ }
+ ]
+ }.
+
+quick_notify_setup() ->
+ error_logger:tty(false),
+ application:load(lager),
+ application:set_env(lager, handlers, [{?MODULE, info}]),
+ application:set_env(lager, error_logger_redirect, false),
+ application:set_env(lager, duplicate_threshold, 1),
+ application:set_env(lager, duplicate_dump, 100000),
+ application:set_env(lager, duplicate_quick_notification, true),
+ application:start(compiler),
+ application:start(syntax_tools),
+ ok=application:start(lager),
+ gen_server:call(lager_deduper, dump),
+ gen_event:call(lager_event, ?MODULE, flush).
+
+quick_notify_cleanup(_) ->
+ application:stop(lager),
+ error_logger:tty(true).
+
+crash(Type) ->
+ spawn(fun() -> gen_server:call(crash, Type) end),
+ timer:sleep(100),
+ _ = gen_event:which_handlers(error_logger),
+ ok.
+
+test_body(Expected, Actual) ->
+ case has_line_numbers() of
+ true ->
+ FileLine = string:substr(Actual, length(Expected)+1),
+ Body = string:substr(Actual, 1, length(Expected)),
+ ?assertEqual(Expected, Body),
+ 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.
+
+%% only one of the messages is valid!
+%test_multi_body(Expected, Received) ->
+% case has_line_numbers() of
+% true ->
+% Data = [{string:substr(Actual, length(Expected)+1),
+% string:substr(Actual, 1, length(Expected))}
+% || Actual <- Received],
+% Res =
+% [begin
+% ?assertEqual(Expected, Body),
+% ?assertEqual(" line ", string:substr(FileLine, 1, 6))
+% end || {FileLine, Body} <- Data,
+% Body =:= Expected],
+% ?assertNotEqual([], Res);
+% false ->
+% ?assert(lists:member(Expected, Received))
+% 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),
+ application:load(lager),
+ application:set_env(lager, error_logger_redirect, true),
+ application:set_env(lager, handlers, [{?MODULE, error}]),
+ application:set_env(lager, duplicate_threshold, 1),
+ application:set_env(lager, duplicate_dump, 100000),
+ application:start(compiler),
+ application:start(syntax_tools),
+ ok=application:start(lager),
+ crash:start()
+ end,
+
+ fun(_) ->
+ application:stop(lager),
+ case whereis(crash) of
+ undefined -> ok;
+ Pid -> exit(Pid, kill)
+ end,
+ error_logger:tty(true)
+ end,
+ [
+ {"again, there is nothing up my sleeve",
+ fun() ->
+ ?assertEqual(undefined, pop()),
+ ?assertEqual(0, count())
+ 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")
+% {"bad return value",
+% fun() ->
+% Pid = whereis(crash),
+% crash(bad_return),
+% {_, _, Msg, _Meta} = 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),
+% count(),
+% %% We need to pop twice, because the buffering imposed
+% %% by the deduper swaps messages that the
+% %% lager_test_backend suite receives in reverse.
+% {_, _, Msg1} = pop(),
+% {_, _, Msg2} = pop(),
+% Received = [lists:flatten(Msg) || Msg <- [Msg1, Msg2]],
+% Expected = lists:flatten(io_lib:format("[error] ~w gen_server crash terminated with reason: bad return value: {tuple,{tuple,\"string\"}}", [Pid])),
+% ?assert(lists:member(Expected, Received))
+% end
+% },
+% {"bad return value uncaught throw",
+% fun() ->
+% Pid = whereis(crash),
+% crash(throw),
+% {_, _, Msg1, _} = pop(),
+% {_, _, Msg2, _} = pop(),
+% Received = [lists:flatten(Msg) || Msg <- [Msg1, Msg2]],
+% Expected = lists:flatten(io_lib:format("[error] ~w gen_server crash terminated with reason: bad return value: a_ball", [Pid])),
+% ?assert(lists:member(Expected, Received))
+% end
+% },
+% {"case clause",
+% fun() ->
+% Pid = whereis(crash),
+% crash(case_clause),
+% {_, _, Msg1, _} = pop(),
+% {_, _, Msg2, _} = pop(),
+% Received = [lists:flatten(Msg) || Msg <- [Msg1, Msg2]],
+% 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_multi_body(Expected, Received)
+% end
+% },
+% {"case clause string",
+% fun() ->
+% Pid = whereis(crash),
+% crash(case_clause_string),
+% {_, _, Msg1, _} = pop(),
+% {_, _, Msg2, _} = pop(),
+% Received = [lists:flatten(Msg) || Msg <- [Msg1, Msg2]],
+% 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_multi_body(Expected, Received)
+% end
+% },
+% {"function clause",
+% fun() ->
+% Pid = whereis(crash),
+% crash(function_clause),
+% {_, _, Msg1, _} = pop(),
+% {_, _, Msg2, _} = pop(),
+% Received = [lists:flatten(Msg) || Msg <- [Msg1, Msg2]],
+% Expected = lists:flatten(io_lib:format("[error] ~w gen_server crash terminated with reason: no function clause matching crash:function({})", [Pid])),
+% test_multi_body(Expected, Received)
+% end
+% },
+% {"if clause",
+% fun() ->
+% Pid = whereis(crash),
+% crash(if_clause),
+% {_, _, Msg1, _} = pop(),
+% {_, _, Msg2, _} = pop(),
+% Received = [lists:flatten(Msg) || Msg <- [Msg1, Msg2]],
+% 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_multi_body(Expected, Received)
+% end
+% },
+% {"try clause",
+% fun() ->
+% Pid = whereis(crash),
+% crash(try_clause),
+% {_, _, Msg1, _} = pop(),
+% {_, _, Msg2, _} = pop(),
+% Received = [lists:flatten(Msg) || Msg <- [Msg1, Msg2]],
+% 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_multi_body(Expected, Received)
+% end
+% },
+% {"undefined function",
+% fun() ->
+% Pid = whereis(crash),
+% crash(undef),
+% {_, _, Msg1, _} = pop(),
+% {_, _, Msg2, _} = pop(),
+% Received = [lists:flatten(Msg) || Msg <- [Msg1, Msg2]],
+% 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_multi_body(Expected, Received)
+% end
+% },
+% {"bad math",
+% fun() ->
+% Pid = whereis(crash),
+% crash(badarith),
+% {_, _, Msg1, _} = pop(),
+% {_, _, Msg2, _} = pop(),
+% Received = [lists:flatten(Msg) || Msg <- [Msg1, Msg2]],
+% Expected = lists:flatten(io_lib:format("[error] ~w gen_server crash terminated with reason: bad arithmetic expression in crash:handle_call/3", [Pid])),
+% test_multi_body(Expected, Received)
+% end
+% },
+% {"bad match",
+% fun() ->
+% Pid = whereis(crash),
+% crash(badmatch),
+% {_, _, Msg1, _} = pop(),
+% {_, _, Msg2, _} = pop(),
+% Received = [lists:flatten(Msg) || Msg <- [Msg1, Msg2]],
+% 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_multi_body(Expected, Received)
+% end
+% },
+% {"bad arity",
+% fun() ->
+% Pid = whereis(crash),
+% crash(badarity),
+% {_, _, Msg1, _} = pop(),
+% {_, _, Msg2, _} = pop(),
+% Received = [lists:flatten(Msg) || Msg <- [Msg1, Msg2]],
+% 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_multi_body(Expected, Received)
+% end
+% },
+% {"bad arg1",
+% fun() ->
+% Pid = whereis(crash),
+% crash(badarg1),
+% {_, _, Msg1, _} = pop(),
+% {_, _, Msg2, _} = pop(),
+% Received = [lists:flatten(Msg) || Msg <- [Msg1, Msg2]],
+% Expected = lists:flatten(io_lib:format("[error] ~w gen_server crash terminated with reason: bad argument in crash:handle_call/3", [Pid])),
+% test_multi_body(Expected, Received)
+% end
+% },
+% {"bad arg2",
+% fun() ->
+% Pid = whereis(crash),
+% crash(badarg2),
+% {_, _, Msg1, _} = pop(),
+% {_, _, Msg2, _} = pop(),
+% Received = [lists:flatten(Msg) || Msg <- [Msg1, Msg2]],
+% 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_multi_body(Expected, Received)
+% end
+% },
+% {"bad record",
+% fun() ->
+% Pid = whereis(crash),
+% crash(badrecord),
+% {_, _, Msg1, _} = pop(),
+% {_, _, Msg2, _} = pop(),
+% Received = [lists:flatten(Msg) || Msg <- [Msg1, Msg2]],
+% Expected = lists:flatten(io_lib:format("[error] ~w gen_server crash terminated with reason: bad record state in crash:handle_call/3", [Pid])),
+% test_multi_body(Expected, Received)
+% end
+% },
+% {"noproc",
+% fun() ->
+% Pid = whereis(crash),
+% crash(noproc),
+% {_, _, Msg1, _} = pop(),
+% {_, _, Msg2, _} = pop(),
+% Received = [lists:flatten(Msg) || Msg <- [Msg1, Msg2]],
+% 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])),
+% ?assert(lists:member(Expected, Received))
+% end
+% },
+% {"badfun",
+% fun() ->
+% Pid = whereis(crash),
+% crash(badfun),
+% {_, _, Msg1, _} = pop(),
+% {_, _, Msg2, _} = pop(),
+% Received = [lists:flatten(Msg) || Msg <- [Msg1, Msg2]],
+% Expected = lists:flatten(io_lib:format("[error] ~w gen_server crash terminated with reason: bad function booger in crash:handle_call/3", [Pid])),
+% test_multi_body(Expected, Received)
+% end
+% }
+
+ ]
+ }.
+
+error_logger_redirect_test_() ->
+ {foreach,
+ fun() ->
+ error_logger:tty(false),
+ application:load(lager),
+ application:set_env(lager, error_logger_redirect, true),
+ application:set_env(lager, handlers, [{?MODULE, info}]),
+ application:set_env(lager, duplicate_threshold, 1),
+ application:set_env(lager, duplicate_dump, 100000),
+ ok=application:start(lager),
+ lager:log(error, self(), "flush flush"),
+ timer:sleep(100),
+ gen_server:call(lager_deduper, dump),
+ gen_event:call(lager_event, ?MODULE, flush)
+ end,
+
+ fun(_) ->
+ application:stop(lager),
+ error_logger:tty(true)
+ end,
+ [
+ {"error reports are printed",
+ fun() ->
+ sync_error_logger:error_report([{this, is}, a, {silly, format}]),
+ _ = gen_event:which_handlers(error_logger),
+ {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),
+ {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),
+ {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(),
+ ?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),
+ {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),
+ {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),
+ {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),
+ {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),
+ {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),
+ {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),
+ {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),
+ {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),
+ {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
+ },
+
+ {"warning messages are printed at the correct level",
+ fun() ->
+ sync_error_logger:warning_msg("doom, doom has come upon you all"),
+ Map = error_logger:warning_map(),
+ _ = gen_event:which_handlers(error_logger),
+ {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),
+ {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),
+ {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),
+ {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),
+ {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),
+ {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),
+ {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),
+ {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
+ },
+ {"supervisor progress report",
+ fun() ->
+ 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),
+ {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),
+ {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),
+ {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),
+ {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),
+ {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),
+ {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),
+ {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,_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",
+ fun() ->
+ {ok, Pid} = special_process:start(),
+ unlink(Pid),
+ Pid ! function_clause,
+ timer:sleep(500),
+ _ = gen_event:which_handlers(error_logger),
+ {_, _, Msg, _} = 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
+ },
+ {"crash reports for 'special processes' should be handled right - case_clause",
+ fun() ->
+ {ok, Pid} = special_process:start(),
+ unlink(Pid),
+ Pid ! {case_clause, wtf},
+ timer:sleep(500),
+ _ = gen_event:which_handlers(error_logger),
+ {_, _, Msg, _} = 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
+ },
+ {"crash reports for 'special processes' should be handled right - exit",
+ fun() ->
+ {ok, Pid} = special_process:start(),
+ unlink(Pid),
+ Pid ! exit,
+ timer:sleep(500),
+ _ = gen_event:which_handlers(error_logger),
+ {_, _, Msg, _} = 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
+ },
+ {"crash reports for 'special processes' should be handled right - error",
+ fun() ->
+ {ok, Pid} = special_process:start(),
+ unlink(Pid),
+ Pid ! error,
+ timer:sleep(500),
+ _ = gen_event:which_handlers(error_logger),
+ {_, _, Msg, _} = 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
+ },
+ {"messages should not be generated if they don't satisfy the threshold",
+ fun() ->
+ lager:set_loglevel(?MODULE, error),
+ sync_error_logger:info_report([hello, world]),
+ _ = gen_event:which_handlers(error_logger),
+ ?assertEqual(0, count()),
+ ?assertEqual(0, count_ignored()),
+ lager:set_loglevel(?MODULE, info),
+ sync_error_logger:info_report([hello, world]),
+ _ = gen_event:which_handlers(error_logger),
+ ?assertEqual(1, count()),
+ ?assertEqual(0, count_ignored()),
+ lager:set_loglevel(?MODULE, error),
+ lager_config:set(loglevel, {element(2, lager_util:config_to_mask(debug)), []}),
+ sync_error_logger:info_report([hello, world]),
+ _ = gen_event:which_handlers(error_logger),
+ ?assertEqual(1, count()),
+ ?assertEqual(1, count_ignored())
+ end
+ }
+ ]
+ }.
+
+safe_format_test() ->
+ ?assertEqual("foo bar", lists:flatten(lager:safe_format("~p ~p", [foo, bar], 1024))),
+ ?assertEqual("FORMAT ERROR: \"~p ~p ~p\" [foo,bar]", lists:flatten(lager:safe_format("~p ~p ~p", [foo, bar], 1024))),
+ ok.
+
+-endif.
+
+
+
Please sign in to comment.
Something went wrong with that request. Please try again.