SisMaker
/
eLog
1
0
포크 0
코드 이슈 0 풀 리퀘스트 0 Projects 0 릴리즈 0 위키 활동
rewrite from lager
25개 이상의 토픽을 선택하실 수 없습니다. Topics must start with a letter or number, can include dashes ('-') and can be up to 35 characters long.
6 커밋
1 브렌치
4.1 MiB
 
트리: 0b8748cf78
브랜치 태그
${ item.name }
${ searchTerm } 브랜치 생성
from '0b8748cf78'
${ noResults }
eLog/test/lager_test_backend.erl

1917 lines
86 KiB
Raw Blame 히스토리

%% -------------------------------------------------------------------
%%
%% Copyright (c) 2011-2017 Basho Technologies, Inc.
%%
%% 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).
-behaviour(gen_event).
-export([init/1, handle_call/2, handle_event/2, handle_info/2, terminate/2,
code_change/3]).
-include("rum.hrl").
-define(TEST_SINK_NAME, '__lager_test_sink'). %% <-- used by parse transform
-define(TEST_SINK_EVENT, '__lager_test_sink_lager_event'). %% <-- used by lager API calls and internals for gen_event
-record(state, {
level :: list(),
buffer :: list(),
ignored :: term()
}).
-compile({parse_transform, lager_transform}).
-ifdef(TEST).
-include_lib("eunit/include/eunit.hrl").
-record(test, {
attrs :: list(),
format :: list(),
args :: list()
}).
-export([
count/0,
count_ignored/0,
flush/0,
message_stuffer/3,
pop/0,
pop_ignored/0,
print_state/0,
get_buffer/0
]).
-endif.
init(Level) ->
{ok, #state{level = rumUtil:config_to_mask(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(pop_ignored, #state{ignored = Ignored} = State) ->
case Ignored of
[] ->
{ok, undefined, State};
[H | T] ->
{ok, H, State#state{ignored = T}}
end;
handle_call(get_buffer, #state{buffer = Buffer} = State) ->
{ok, Buffer, State};
handle_call(get_loglevel, #state{level = Level} = State) ->
{ok, Level, State};
handle_call({set_loglevel, Level}, State) ->
{ok, ok, State#state{level = rumUtil:config_to_mask(Level)}};
handle_call(print_state, State) ->
spawn(fun() -> eRum:info("State ~p", [eRum:pr(State, ?MODULE)]) end),
timer:sleep(100),
{ok, ok, State};
handle_call(print_bad_state, State) ->
spawn(fun() -> eRum:info("State ~p", [eRum:pr({state, 1}, ?MODULE)]) end),
timer:sleep(100),
{ok, ok, State};
handle_call(_Request, State) ->
{ok, ok, State}.
handle_event({log, Msg},
#state{level = LogLevel, buffer = Buffer, ignored = Ignored} = State) ->
case rumUtil:is_loggable(Msg, LogLevel, ?MODULE) of
true ->
{ok, State#state{buffer = Buffer ++
[{rumMsg:severity_as_int(Msg),
rumMsg:datetime(Msg),
rumMsg:message(Msg), rumMsg:metadata(Msg)}]}};
_ ->
{ok, State#state{ignored = Ignored ++ [Msg]}}
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() ->
pop(lager_event).
pop_ignored() ->
pop_ignored(lager_event).
get_buffer() ->
get_buffer(lager_event).
count() ->
count(lager_event).
count_ignored() ->
count_ignored(lager_event).
flush() ->
flush(lager_event).
print_state() ->
print_state(lager_event).
print_bad_state() ->
print_bad_state(lager_event).
pop(Sink) ->
gen_event:call(Sink, ?MODULE, pop).
pop_ignored(Sink) ->
gen_event:call(Sink, ?MODULE, pop_ignored).
get_buffer(Sink) ->
gen_event:call(Sink, ?MODULE, get_buffer).
count(Sink) ->
gen_event:call(Sink, ?MODULE, count).
count_ignored(Sink) ->
gen_event:call(Sink, ?MODULE, count_ignored).
flush(Sink) ->
gen_event:call(Sink, ?MODULE, flush).
print_state(Sink) ->
gen_event:call(Sink, ?MODULE, print_state).
print_bad_state(Sink) ->
gen_event:call(Sink, ?MODULE, print_bad_state).
not_running_test() ->
?assertEqual({error, lager_not_running}, eRum: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
},
{"test sink not running",
fun() ->
?assertEqual({error, {sink_not_configured, test}}, eRum:log(test, info, self(), "~p", "not running"))
end
},
{"logging works",
fun() ->
eRum:warning("test message"),
?assertEqual(1, count()),
{Level, _Time, Message, _Metadata} = pop(),
?assertMatch(Level, rumUtil:level_to_num(warning)),
?assertEqual("test message", Message),
ok
end
},
{"logging with macro works",
fun() ->
?rumWarning("test message", []),
?assertEqual(1, count()),
{Level, _Time, Message, _Metadata} = pop(),
?assertMatch(Level, rumUtil:level_to_num(warning)),
?assertEqual("test message", Message),
ok
end
},
{"unsafe logging works",
fun() ->
eRum:warning_unsafe("test message"),
?assertEqual(1, count()),
{Level, _Time, Message, _Metadata} = pop(),
?assertMatch(Level, rumUtil:level_to_num(warning)),
?assertEqual("test message", Message),
ok
end
},
{"logging with arguments works",
fun() ->
eRum:warning("test message ~p", [self()]),
?assertEqual(1, count()),
{Level, _Time, Message, _Metadata} = pop(),
?assertMatch(Level, rumUtil:level_to_num(warning)),
?assertEqual(lists:flatten(io_lib:format("test message ~p", [self()])), lists:flatten(Message)),
ok
end
},
{"logging with macro and arguments works",
fun() ->
?rumWarning("test message ~p", [self()]),
?assertEqual(1, count()),
{Level, _Time, Message, _Metadata} = pop(),
?assertMatch(Level, rumUtil:level_to_num(warning)),
?assertEqual(lists:flatten(io_lib:format("test message ~p", [self()])), lists:flatten(Message)),
ok
end
},
{"unsafe logging with args works",
fun() ->
eRum:warning_unsafe("test message ~p", [self()]),
?assertEqual(1, count()),
{Level, _Time, Message, _Metadata} = pop(),
?assertMatch(Level, rumUtil: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
eRum:warning("test message 2")
end,
?assertEqual(1, count()),
ok
end
},
{"logging works from inside a list comprehension",
fun() ->
?assertEqual(0, count()),
[eRum:warning("test message") || _N <- lists:seq(1, 10)],
?assertEqual(10, count()),
ok
end
},
{"logging works from a begin/end block inside a list comprehension",
fun() ->
?assertEqual(0, count()),
[begin eRum:warning("test message") end || _N <- lists:seq(1, 10)],
?assertEqual(10, count()),
ok
end
},
{"logging works from a nested list comprehension",
fun() ->
?assertEqual(0, count()),
[[eRum:warning("test message") || _N <- lists:seq(1, 10)] ||
_I <- lists:seq(1, 10)],
?assertEqual(100, count()),
ok
end
},
{"logging with only metadata works",
fun() ->
?assertEqual(0, count()),
eRum:warning([{just, metadata}]),
eRum:warning([{just, metadata}, {foo, bar}]),
?assertEqual(2, count()),
ok
end
},
{"variables inplace of literals in logging statements work",
fun() ->
?assertEqual(0, count()),
Attr = [{a, alpha}, {b, beta}],
Fmt = "format ~p",
Args = [world],
eRum:info(Attr, "hello"),
eRum:info(Attr, "hello ~p", [world]),
eRum:info(Fmt, [world]),
eRum:info("hello ~p", Args),
eRum:info(Attr, "hello ~p", Args),
eRum:info([{d, delta}, {g, gamma}], Fmt, Args),
?assertEqual(6, count()),
{_Level, _Time, Message, Metadata} = pop(),
?assertMatch([{a, alpha}, {b, beta} | _], Metadata),
?assertEqual("hello", lists:flatten(Message)),
{_Level, _Time2, Message2, _Metadata2} = pop(),
?assertEqual("hello world", lists:flatten(Message2)),
{_Level, _Time3, Message3, _Metadata3} = pop(),
?assertEqual("format world", lists:flatten(Message3)),
{_Level, _Time4, Message4, _Metadata4} = pop(),
?assertEqual("hello world", lists:flatten(Message4)),
{_Level, _Time5, Message5, _Metadata5} = pop(),
?assertEqual("hello world", lists:flatten(Message5)),
{_Level, _Time6, Message6, Metadata6} = pop(),
?assertMatch([{d, delta}, {g, gamma} | _], Metadata6),
?assertEqual("format world", lists:flatten(Message6)),
ok
end
},
{"list comprehension inplace of literals in logging statements work",
fun() ->
?assertEqual(0, count()),
Attr = [{a, alpha}, {b, beta}],
Fmt = "format ~p",
Args = [world],
eRum:info([{K, atom_to_list(V)} || {K, V} <- Attr], "hello"),
eRum:info([{K, atom_to_list(V)} || {K, V} <- Attr], "hello ~p", [{atom, X} || X <- Args]),
eRum:info([X || X <- Fmt], [world]),
eRum:info("hello ~p", [{atom, X} || X <- Args]),
eRum:info([{K, atom_to_list(V)} || {K, V} <- Attr], "hello ~p", [{atom, X} || X <- Args]),
eRum:info([{d, delta}, {g, gamma}], Fmt, [{atom, X} || X <- Args]),
?assertEqual(6, count()),
{_Level, _Time, Message, Metadata} = pop(),
?assertMatch([{a, "alpha"}, {b, "beta"} | _], Metadata),
?assertEqual("hello", lists:flatten(Message)),
{_Level, _Time2, Message2, _Metadata2} = pop(),
?assertEqual("hello {atom,world}", lists:flatten(Message2)),
{_Level, _Time3, Message3, _Metadata3} = pop(),
?assertEqual("format world", lists:flatten(Message3)),
{_Level, _Time4, Message4, _Metadata4} = pop(),
?assertEqual("hello {atom,world}", lists:flatten(Message4)),
{_Level, _Time5, Message5, _Metadata5} = pop(),
?assertEqual("hello {atom,world}", lists:flatten(Message5)),
{_Level, _Time6, Message6, Metadata6} = pop(),
?assertMatch([{d, delta}, {g, gamma} | _], Metadata6),
?assertEqual("format {atom,world}", lists:flatten(Message6)),
ok
end
},
{"function calls inplace of literals in logging statements work",
fun() ->
?assertEqual(0, count()),
put(attrs, [{a, alpha}, {b, beta}]),
put(format, "format ~p"),
put(args, [world]),
eRum:info(get(attrs), "hello"),
eRum:info(get(attrs), "hello ~p", get(args)),
eRum:info(get(format), [world]),
eRum:info("hello ~p", erlang:get(args)),
eRum:info(fun() -> get(attrs) end(), "hello ~p", get(args)),
eRum:info([{d, delta}, {g, gamma}], get(format), get(args)),
?assertEqual(6, count()),
{_Level, _Time, Message, Metadata} = pop(),
?assertMatch([{a, alpha}, {b, beta} | _], Metadata),
?assertEqual("hello", lists:flatten(Message)),
{_Level, _Time2, Message2, _Metadata2} = pop(),
?assertEqual("hello world", lists:flatten(Message2)),
{_Level, _Time3, Message3, _Metadata3} = pop(),
?assertEqual("format world", lists:flatten(Message3)),
{_Level, _Time4, Message4, _Metadata4} = pop(),
?assertEqual("hello world", lists:flatten(Message4)),
{_Level, _Time5, Message5, _Metadata5} = pop(),
?assertEqual("hello world", lists:flatten(Message5)),
{_Level, _Time6, Message6, Metadata6} = pop(),
?assertMatch([{d, delta}, {g, gamma} | _], Metadata6),
?assertEqual("format world", lists:flatten(Message6)),
ok
end
},
{"record fields inplace of literals in logging statements work",
fun() ->
?assertEqual(0, count()),
Test = #test{attrs = [{a, alpha}, {b, beta}], format = "format ~p", args = [world]},
eRum:info(Test#test.attrs, "hello"),
eRum:info(Test#test.attrs, "hello ~p", Test#test.args),
eRum:info(Test#test.format, [world]),
eRum:info("hello ~p", Test#test.args),
eRum:info(Test#test.attrs, "hello ~p", Test#test.args),
eRum:info([{d, delta}, {g, gamma}], Test#test.format, Test#test.args),
?assertEqual(6, count()),
{_Level, _Time, Message, Metadata} = pop(),
?assertMatch([{a, alpha}, {b, beta} | _], Metadata),
?assertEqual("hello", lists:flatten(Message)),
{_Level, _Time2, Message2, _Metadata2} = pop(),
?assertEqual("hello world", lists:flatten(Message2)),
{_Level, _Time3, Message3, _Metadata3} = pop(),
?assertEqual("format world", lists:flatten(Message3)),
{_Level, _Time4, Message4, _Metadata4} = pop(),
?assertEqual("hello world", lists:flatten(Message4)),
{_Level, _Time5, Message5, _Metadata5} = pop(),
?assertEqual("hello world", lists:flatten(Message5)),
{_Level, _Time6, Message6, Metadata6} = pop(),
?assertMatch([{d, delta}, {g, gamma} | _], Metadata6),
?assertEqual("format world", lists:flatten(Message6)),
ok
end
},
{"log messages below the threshold are ignored",
fun() ->
?assertEqual(0, count()),
eRum:debug("this message will be ignored"),
?assertEqual(0, count()),
?assertEqual(0, count_ignored()),
rumConfig:set(loglevel, {element(2, rumUtil:config_to_mask(debug)), []}),
eRum:debug("this message should be ignored"),
?assertEqual(0, count()),
?assertEqual(1, count_ignored()),
eRum:set_loglevel(?MODULE, debug),
?assertEqual({?DEBUG bor ?INFO bor ?NOTICE bor ?WARNING bor ?ERROR bor ?CRITICAL bor ?ALERT bor ?EMERGENCY, []}, rumConfig:get(loglevel)),
eRum:debug("this message should be logged"),
?assertEqual(1, count()),
?assertEqual(1, count_ignored()),
?assertEqual(debug, eRum:get_loglevel(?MODULE)),
ok
end
},
{"tracing works",
fun() ->
rumConfig:set(loglevel, {element(2, rumUtil:config_to_mask(error)), []}),
ok = eRum:info("hello world"),
?assertEqual(0, count()),
eRum:trace(?MODULE, [{module, ?MODULE}], debug),
?assertMatch({?ERROR bor ?CRITICAL bor ?ALERT bor ?EMERGENCY, _}, rumConfig:get(loglevel)),
%% elegible for tracing
ok = eRum:info("hello world"),
%% NOT elegible for tracing
ok = eRum:log(info, [{pid, self()}], "hello world"),
?assertEqual(1, count()),
ok
end
},
{"tracing works with custom attributes",
fun() ->
eRum:set_loglevel(?MODULE, error),
?assertEqual({?ERROR bor ?CRITICAL bor ?ALERT bor ?EMERGENCY, []}, rumConfig:get(loglevel)),
rumConfig:set(loglevel, {element(2, rumUtil:config_to_mask(error)), []}),
eRum:info([{requestid, 6}], "hello world"),
?assertEqual(0, count()),
eRum:trace(?MODULE, [{requestid, 6}, {foo, bar}], debug),
eRum:info([{requestid, 6}, {foo, bar}], "hello world"),
?assertEqual(1, count()),
eRum:trace(?MODULE, [{requestid, '*'}], debug),
eRum:info([{requestid, 6}], "hello world"),
?assertEqual(2, count()),
eRum:clear_all_traces(),
eRum:info([{requestid, 6}], "hello world"),
?assertEqual(2, count()),
ok
end
},
{"tracing works with custom attributes and event stream processing",
fun() ->
eRum:set_loglevel(?MODULE, error),
?assertEqual({?ERROR bor ?CRITICAL bor ?ALERT bor ?EMERGENCY, []}, rumConfig:get(loglevel)),
rumConfig:set(loglevel, {element(2, rumUtil:config_to_mask(error)), []}),
eRum:info([{requestid, 6}], "hello world"),
?assertEqual(0, count()),
eRum:trace(?MODULE, [{requestid, '>', 5}, {requestid, '<', 7}, {foo, bar}], debug),
eRum:info([{requestid, 5}, {foo, bar}], "hello world"),
eRum:info([{requestid, 6}, {foo, bar}], "hello world"),
?assertEqual(1, count()),
eRum:clear_all_traces(),
eRum:trace(?MODULE, [{requestid, '>', 8}, {foo, bar}]),
eRum:info([{foo, bar}], "hello world"),
eRum:info([{requestid, 6}], "hello world"),
eRum:info([{requestid, 7}], "hello world"),
eRum:info([{requestid, 8}], "hello world"),
eRum:info([{requestid, 9}, {foo, bar}], "hello world"),
eRum:info([{requestid, 10}], "hello world"),
?assertEqual(2, count()),
eRum:trace(?MODULE, [{requestid, '>', 8}]),
eRum:info([{foo, bar}], "hello world"),
eRum:info([{requestid, 6}], "hello world"),
eRum:info([{requestid, 7}], "hello world"),
eRum:info([{requestid, 8}], "hello world"),
eRum:info([{requestid, 9}, {foo, bar}], "hello world"),
eRum:info([{requestid, 10}], "hello world"),
?assertEqual(4, count()),
eRum:trace(?MODULE, [{foo, '=', bar}]),
eRum:info([{foo, bar}], "hello world"),
eRum:info([{requestid, 6}], "hello world"),
eRum:info([{requestid, 7}], "hello world"),
eRum:info([{requestid, 8}], "hello world"),
eRum:info([{requestid, 9}, {foo, bar}], "hello world"),
eRum:info([{requestid, 10}], "hello world"),
eRum:trace(?MODULE, [{fu, '!'}]),
eRum:info([{foo, bar}], "hello world"),
eRum:info([{ooh, car}], "hello world"),
eRum:info([{fu, bar}], "hello world"),
eRum:trace(?MODULE, [{fu, '*'}]),
eRum:info([{fu, bar}], "hello world"),
?assertEqual(10, count()),
eRum:clear_all_traces(),
eRum:info([{requestid, 6}], "hello world"),
?assertEqual(10, count()),
eRum:clear_all_traces(),
eRum:trace(?MODULE, [{requestid, '>=', 5}, {requestid, '=<', 7}], debug),
eRum:info([{requestid, 4}], "nope!"),
eRum:info([{requestid, 5}], "hello world"),
eRum:info([{requestid, 7}], "hello world again"),
?assertEqual(12, count()),
eRum:clear_all_traces(),
eRum:trace(?MODULE, [{foo, '!=', bar}]),
eRum:info([{foo, bar}], "hello world"),
?assertEqual(12, count()),
eRum:info([{foo, baz}], "blarg"),
?assertEqual(13, count()),
eRum:clear_all_traces(),
eRum:trace(?MODULE, [{all, [{foo, '=', bar}, {null, false}]}]),
eRum:info([{foo, bar}], "should not be logged"),
?assertEqual(13, count()),
eRum:clear_all_traces(),
eRum:trace(?MODULE, [{any, [{foo, '=', bar}, {null, true}]}]),
eRum:info([{foo, qux}], "should be logged"),
?assertEqual(14, count()),
ok
end
},
{"tracing custom attributes works with event stream processing statistics and reductions",
fun() ->
eRum:set_loglevel(?MODULE, error),
?assertEqual({?ERROR bor ?CRITICAL bor ?ALERT bor ?EMERGENCY, []}, rumConfig:get(loglevel)),
rumConfig:set(loglevel, {element(2, rumUtil:config_to_mask(error)), []}),
eRum:info([{requestid, 6}], "hello world"),
?assertEqual(0, count()),
eRum:trace(?MODULE, [{beta, '*'}]),
eRum:trace(?MODULE, [{meta, "data"}]),
eRum:info([{meta, "data"}], "hello world"),
eRum:info([{beta, 2}], "hello world"),
eRum:info([{beta, 2.1}, {foo, bar}], "hello world"),
eRum:info([{meta, <<"data">>}], "hello world"),
?assertEqual(8, ?RumDefTracer:info(input)),
?assertEqual(6, ?RumDefTracer:info(output)),
?assertEqual(2, ?RumDefTracer:info(filter)),
eRum:clear_all_traces(),
eRum:trace(?MODULE, [{meta, "data"}]),
eRum:trace(?MODULE, [{beta, '>', 2}, {beta, '<', 2.12}]),
eRum:info([{meta, "data"}], "hello world"),
eRum:info([{beta, 2}], "hello world"),
eRum:info([{beta, 2.1}, {foo, bar}], "hello world"),
eRum:info([{meta, <<"data">>}], "hello world"),
?assertEqual(8, ?RumDefTracer:info(input)),
?assertEqual(4, ?RumDefTracer:info(output)),
?assertEqual(4, ?RumDefTracer:info(filter)),
eRum:clear_all_traces(),
eRum:trace_console([{beta, '>', 2}, {meta, "data"}]),
eRum:trace_console([{beta, '>', 2}, {beta, '<', 2.12}]),
Reduced = {all, [{any, [{beta, '<', 2.12}, {meta, '=', "data"}]},
{beta, '>', 2}]},
?assertEqual(Reduced, ?RumDefTracer:info('query')),
eRum:clear_all_traces(),
eRum:info([{requestid, 6}], "hello world"),
?assertEqual(5, count()),
ok
end
},
{"persistent traces work",
fun() ->
?assertEqual(0, count()),
eRum:debug([{foo, bar}], "hello world"),
?assertEqual(0, count()),
application:stop(lager),
application:set_env(lager, traces, [{lager_test_backend, [{foo, bar}], debug}]),
eRum:start(),
timer:sleep(5),
flush(),
eRum:debug([{foo, bar}], "hello world"),
?assertEqual(1, count()),
application:unset_env(lager, traces),
ok
end
},
{"tracing honors loglevel",
fun() ->
eRum:set_loglevel(?MODULE, error),
?assertEqual({?ERROR bor ?CRITICAL bor ?ALERT bor ?EMERGENCY, []}, rumConfig:get(loglevel)),
{ok, T} = eRum:trace(?MODULE, [{module, ?MODULE}], notice),
ok = eRum:info("hello world"),
?assertEqual(0, count()),
ok = eRum:notice("hello world"),
?assertEqual(1, count()),
eRum:stop_trace(T),
ok = eRum:notice("hello world"),
?assertEqual(1, count()),
ok
end
},
{"stopped trace stops and removes its event handler - default sink (gh#267)",
{timeout, 10,
fun() ->
Sink = ?RumDefSink,
StartHandlers = gen_event:which_handlers(Sink),
{_, T0} = rumConfig:get({Sink, loglevel}),
StartGlobal = rumConfig:global_get(handlers),
?assertEqual([], T0),
{ok, TestTrace1} = eRum:trace_file("/tmp/test", [{a, b}]),
MidHandlers = gen_event:which_handlers(Sink),
{ok, TestTrace2} = eRum:trace_file("/tmp/test", [{c, d}]),
MidHandlers = gen_event:which_handlers(Sink),
?assertEqual(length(StartHandlers) + 1, length(MidHandlers)),
MidGlobal = rumConfig:global_get(handlers),
?assertEqual(length(StartGlobal) + 1, length(MidGlobal)),
{_, T1} = rumConfig:get({Sink, loglevel}),
?assertEqual(2, length(T1)),
ok = eRum:stop_trace(TestTrace1),
{_, T2} = rumConfig:get({Sink, loglevel}),
?assertEqual(1, length(T2)),
?assertEqual(length(StartHandlers) + 1, length(
gen_event:which_handlers(Sink))),
?assertEqual(length(StartGlobal) + 1, length(rumConfig:global_get(handlers))),
ok = eRum:stop_trace(TestTrace2),
EndHandlers = gen_event:which_handlers(Sink),
EndGlobal = rumConfig:global_get(handlers),
{_, T3} = rumConfig:get({Sink, loglevel}),
?assertEqual([], T3),
?assertEqual(StartHandlers, EndHandlers),
?assertEqual(StartGlobal, EndGlobal),
ok
end}
},
{"record printing works",
fun() ->
print_state(),
{Level, _Time, Message, _Metadata} = pop(),
?assertMatch(Level, rumUtil:level_to_num(info)),
{mask, Mask} = rumUtil:config_to_mask(info),
?assertEqual("State #state{level={mask," ++ integer_to_list(Mask) ++ "},buffer=[],ignored=[]}", lists:flatten(Message)),
ok
end
},
{"record printing fails gracefully",
fun() ->
print_bad_state(),
{Level, _Time, Message, _Metadata} = pop(),
?assertMatch(Level, rumUtil:level_to_num(info)),
?assertEqual("State {state,1}", lists:flatten(Message)),
ok
end
},
{"record printing fails gracefully when no lager_record attribute",
fun() ->
spawn(fun() -> eRum:info("State ~p", [eRum:pr({state, 1}, lager)]) end),
timer:sleep(100),
{Level, _Time, Message, _Metadata} = pop(),
?assertMatch(Level, rumUtil:level_to_num(info)),
?assertEqual("State {state,1}", lists:flatten(Message)),
ok
end
},
{"record printing fails gracefully when input is not a tuple",
fun() ->
spawn(fun() -> eRum:info("State ~p", [eRum:pr(ok, lager)]) end),
timer:sleep(100),
{Level, _Time, Message, _Metadata} = pop(),
?assertMatch(Level, rumUtil:level_to_num(info)),
?assertEqual("State ok", lists:flatten(Message)),
ok
end
},
{"record printing fails gracefully when module is invalid",
fun() ->
spawn(fun() -> eRum:info("State ~p", [eRum:pr({state, 1}, not_a_module)]) end),
timer:sleep(1000),
{Level, _Time, Message, _Metadata} = pop(),
?assertMatch(Level, rumUtil:level_to_num(info)),
?assertEqual("State {state,1}", lists:flatten(Message)),
ok
end
},
{"installing a new handler adjusts the global loglevel if necessary",
fun() ->
?assertEqual({?INFO bor ?NOTICE bor ?WARNING bor ?ERROR bor ?CRITICAL bor ?ALERT bor ?EMERGENCY, []}, rumConfig:get(loglevel)),
supervisor:start_child(lager_handler_watcher_sup, [lager_event, {?MODULE, foo}, debug]),
?assertEqual({?DEBUG bor ?INFO bor ?NOTICE bor ?WARNING bor ?ERROR bor ?CRITICAL bor ?ALERT bor ?EMERGENCY, []}, rumConfig:get(loglevel)),
ok
end
},
{"metadata in the process dictionary works",
fun() ->
eRum:md([{platypus, gravid}, {sloth, hirsute}, {duck, erroneous}]),
eRum:info("I sing the animal kingdom electric!"),
{_Level, _Time, _Message, Metadata} = pop(),
?assertEqual(gravid, proplists:get_value(platypus, Metadata)),
?assertEqual(hirsute, proplists:get_value(sloth, Metadata)),
?assertEqual(erroneous, proplists:get_value(duck, Metadata)),
?assertEqual(undefined, proplists:get_value(eagle, Metadata)),
eRum:md([{platypus, gravid}, {sloth, hirsute}, {eagle, superincumbent}]),
eRum:info("I sing the animal kingdom dielectric!"),
{_Level2, _Time2, _Message2, Metadata2} = pop(),
?assertEqual(gravid, proplists:get_value(platypus, Metadata2)),
?assertEqual(hirsute, proplists:get_value(sloth, Metadata2)),
?assertEqual(undefined, proplists:get_value(duck, Metadata2)),
?assertEqual(superincumbent, proplists:get_value(eagle, Metadata2)),
ok
end
},
{"unsafe messages really are not truncated",
fun() ->
eRum:info_unsafe("doom, doom has come upon you all ~p", [string:copies("doom", 1500)]),
{_, _, Msg, _Metadata} = pop(),
?assert(length(lists:flatten(Msg)) == 6035)
end
},
{"can't store invalid metadata",
fun() ->
?assertEqual(ok, eRum:md([{platypus, gravid}, {sloth, hirsute}, {duck, erroneous}])),
?assertError(badarg, eRum:md({flamboyant, flamingo})),
?assertError(badarg, eRum:md("zookeeper zephyr")),
ok
end
},
{"dates should be local by default",
fun() ->
eRum:warning("so long, and thanks for all the fish"),
?assertEqual(1, count()),
{_Level, {_Date, Time}, _Message, _Metadata} = pop(),
?assertEqual(nomatch, binary:match(iolist_to_binary(Time), <<"UTC">>)),
ok
end
},
{"dates should be UTC if SASL is configured as UTC",
fun() ->
application:set_env(sasl, utc_log, true),
eRum:warning("so long, and thanks for all the fish"),
application:set_env(sasl, utc_log, false),
?assertEqual(1, count()),
{_Level, {_Date, Time}, _Message, _Metadata} = pop(),
?assertNotEqual(nomatch, binary:match(iolist_to_binary(Time), <<"UTC">>)),
ok
end
}
]
}.
extra_sinks_test_() ->
{foreach,
fun setup_sink/0,
fun cleanup/1,
[
{"observe that there is nothing up my sleeve",
fun() ->
?assertEqual(undefined, pop(?TEST_SINK_EVENT)),
?assertEqual(0, count(?TEST_SINK_EVENT))
end
},
{"logging works",
fun() ->
?TEST_SINK_NAME:warning("test message"),
?assertEqual(1, count(?TEST_SINK_EVENT)),
{Level, _Time, Message, _Metadata} = pop(?TEST_SINK_EVENT),
?assertMatch(Level, rumUtil:level_to_num(warning)),
?assertEqual("test message", Message),
ok
end
},
{"logging with arguments works",
fun() ->
?TEST_SINK_NAME:warning("test message ~p", [self()]),
?assertEqual(1, count(?TEST_SINK_EVENT)),
{Level, _Time, Message, _Metadata} = pop(?TEST_SINK_EVENT),
?assertMatch(Level, rumUtil:level_to_num(warning)),
?assertEqual(lists:flatten(io_lib:format("test message ~p", [self()])), lists:flatten(Message)),
ok
end
},
{"variables inplace of literals in logging statements work",
fun() ->
?assertEqual(0, count(?TEST_SINK_EVENT)),
Attr = [{a, alpha}, {b, beta}],
Fmt = "format ~p",
Args = [world],
?TEST_SINK_NAME:info(Attr, "hello"),
?TEST_SINK_NAME:info(Attr, "hello ~p", [world]),
?TEST_SINK_NAME:info(Fmt, [world]),
?TEST_SINK_NAME:info("hello ~p", Args),
?TEST_SINK_NAME:info(Attr, "hello ~p", Args),
?TEST_SINK_NAME:info([{d, delta}, {g, gamma}], Fmt, Args),
?assertEqual(6, count(?TEST_SINK_EVENT)),
{_Level, _Time, Message, Metadata} = pop(?TEST_SINK_EVENT),
?assertMatch([{a, alpha}, {b, beta} | _], Metadata),
?assertEqual("hello", lists:flatten(Message)),
{_Level, _Time2, Message2, _Metadata2} = pop(?TEST_SINK_EVENT),
?assertEqual("hello world", lists:flatten(Message2)),
{_Level, _Time3, Message3, _Metadata3} = pop(?TEST_SINK_EVENT),
?assertEqual("format world", lists:flatten(Message3)),
{_Level, _Time4, Message4, _Metadata4} = pop(?TEST_SINK_EVENT),
?assertEqual("hello world", lists:flatten(Message4)),
{_Level, _Time5, Message5, _Metadata5} = pop(?TEST_SINK_EVENT),
?assertEqual("hello world", lists:flatten(Message5)),
{_Level, _Time6, Message6, Metadata6} = pop(?TEST_SINK_EVENT),
?assertMatch([{d, delta}, {g, gamma} | _], Metadata6),
?assertEqual("format world", lists:flatten(Message6)),
ok
end
},
{"stopped trace stops and removes its event handler - test sink (gh#267)",
fun() ->
Sink = ?TEST_SINK_EVENT,
StartHandlers = gen_event:which_handlers(Sink),
{_, T0} = rumConfig:get({Sink, loglevel}),
StartGlobal = rumConfig:global_get(handlers),
?assertEqual([], T0),
{ok, TestTrace1} = eRum:trace_file("/tmp/test", [{sink, Sink}, {a, b}]),
MidHandlers = gen_event:which_handlers(Sink),
{ok, TestTrace2} = eRum:trace_file("/tmp/test", [{sink, Sink}, {c, d}]),
MidHandlers = gen_event:which_handlers(Sink),
?assertEqual(length(StartHandlers) + 1, length(MidHandlers)),
MidGlobal = rumConfig:global_get(handlers),
?assertEqual(length(StartGlobal) + 1, length(MidGlobal)),
{_, T1} = rumConfig:get({Sink, loglevel}),
?assertEqual(2, length(T1)),
ok = eRum:stop_trace(TestTrace1),
{_, T2} = rumConfig:get({Sink, loglevel}),
?assertEqual(1, length(T2)),
?assertEqual(length(StartHandlers) + 1, length(
gen_event:which_handlers(Sink))),
?assertEqual(length(StartGlobal) + 1, length(rumConfig:global_get(handlers))),
ok = eRum:stop_trace(TestTrace2),
EndHandlers = gen_event:which_handlers(Sink),
EndGlobal = rumConfig:global_get(handlers),
{_, T3} = rumConfig:get({Sink, loglevel}),
?assertEqual([], T3),
?assertEqual(StartHandlers, EndHandlers),
?assertEqual(StartGlobal, EndGlobal),
ok
end
},
{"log messages below the threshold are ignored",
fun() ->
?assertEqual(0, count(?TEST_SINK_EVENT)),
?TEST_SINK_NAME:debug("this message will be ignored"),
?assertEqual(0, count(?TEST_SINK_EVENT)),
?assertEqual(0, count_ignored(?TEST_SINK_EVENT)),
rumConfig:set({?TEST_SINK_EVENT, loglevel}, {element(2, rumUtil:config_to_mask(debug)), []}),
?TEST_SINK_NAME:debug("this message should be ignored"),
?assertEqual(0, count(?TEST_SINK_EVENT)),
?assertEqual(1, count_ignored(?TEST_SINK_EVENT)),
eRum:set_loglevel(?TEST_SINK_EVENT, ?MODULE, undefined, debug),
?assertEqual({?DEBUG bor ?INFO bor ?NOTICE bor ?WARNING bor ?ERROR bor ?CRITICAL bor ?ALERT bor ?EMERGENCY, []}, rumConfig:get({?TEST_SINK_EVENT, loglevel})),
?TEST_SINK_NAME:debug("this message should be logged"),
?assertEqual(1, count(?TEST_SINK_EVENT)),
?assertEqual(1, count_ignored(?TEST_SINK_EVENT)),
?assertEqual(debug, eRum:get_loglevel(?TEST_SINK_EVENT, ?MODULE)),
ok
end
}
]
}.
setup_sink() ->
error_logger:tty(false),
application:load(lager),
application:set_env(lager, handlers, []),
application:set_env(lager, error_logger_redirect, false),
application:set_env(lager, extra_sinks, [{?TEST_SINK_EVENT, [{handlers, [{?MODULE, info}]}]}]),
eRum:start(),
gen_event:call(lager_event, ?MODULE, flush),
gen_event:call(?TEST_SINK_EVENT, ?MODULE, flush).
setup() ->
error_logger:tty(false),
application:load(lager),
application:set_env(lager, handlers, [{?MODULE, info}]),
application:set_env(lager, error_logger_redirect, false),
application:unset_env(lager, traces),
eRum:start(),
%% There is a race condition between the application start up, lager logging its own
%% start up condition and several tests that count messages or parse the output of
%% tests. When the lager start up message wins the race, it causes these tests
%% which parse output or count message arrivals to fail.
%%
%% We introduce a sleep here to allow `flush' to arrive *after* the start up
%% message has been received and processed.
%%
%% This race condition was first exposed during the work on
%% 4b5260c4524688b545cc12da6baa2dfa4f2afec9 which introduced the lager
%% manager killer PR.
application:set_env(lager, suppress_supervisor_start_stop, true),
application:set_env(lager, suppress_application_start_stop, true),
timer:sleep(1000),
gen_event:call(lager_event, ?MODULE, flush).
cleanup(_) ->
catch ets:delete(lager_config), %% kill the ets config table with fire
application:stop(lager),
application:stop(goldrush),
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) ->
ExLen = length(Expected),
{Body, Rest} = case length(Actual) > ExLen of
true ->
{string:substr(Actual, 1, ExLen),
string:substr(Actual, (ExLen + 1))};
_ ->
{Actual, []}
end,
?assertEqual(Expected, Body),
% OTP-17 (and maybe later releases) may tack on additional info
% about the failure, so if Actual starts with Expected (already
% confirmed by having gotten past assertEqual above) and ends
% with " line NNN" we can ignore what's in-between. By extension,
% since there may not be line information appended at all, any
% text we DO find is reportable, but not a test failure.
case Rest of
[] ->
ok;
_ ->
% isolate the extra data and report it if it's not just
% a line number indicator
case re:run(Rest, "^.*( line \\d+)$", [{capture, [1]}]) of
nomatch ->
?debugFmt(
"Trailing data \"~s\" following \"~s\"",
[Rest, Expected]);
{match, [{0, _}]} ->
% the whole sting is " line NNN"
ok;
{match, [{Off, _}]} ->
?debugFmt(
"Trailing data \"~s\" following \"~s\"",
[string:substr(Rest, 1, Off), Expected])
end
end.
error_logger_redirect_crash_setup() ->
error_logger:tty(false),
application:load(lager),
application:set_env(lager, error_logger_redirect, true),
application:set_env(lager, handlers, [{?MODULE, error}]),
eRum:start(),
crash:start(),
lager_event.
error_logger_redirect_crash_setup_sink() ->
error_logger:tty(false),
application:load(lager),
application:set_env(lager, error_logger_redirect, true),
application:unset_env(lager, handlers),
application:set_env(lager, extra_sinks, [
{error_logger_lager_event, [
{handlers, [{?MODULE, error}]}]}]),
eRum:start(),
crash:start(),
error_logger_lager_event.
error_logger_redirect_crash_cleanup(_Sink) ->
application:stop(lager),
application:stop(goldrush),
application:unset_env(lager, extra_sinks),
case whereis(crash) of
undefined -> ok;
Pid -> exit(Pid, kill)
end,
error_logger:tty(true).
crash_fsm_setup() ->
error_logger:tty(false),
application:load(lager),
application:set_env(lager, error_logger_redirect, true),
application:set_env(lager, handlers, [{?MODULE, error}]),
eRum:start(),
crash_fsm:start(),
crash_statem:start(),
eRum:log(error, self(), "flush flush"),
timer:sleep(100),
gen_event:call(lager_event, ?MODULE, flush),
lager_event.
crash_fsm_sink_setup() ->
ErrorSink = error_logger_lager_event,
error_logger:tty(false),
application:load(lager),
application:set_env(lager, error_logger_redirect, true),
application:set_env(lager, handlers, []),
application:set_env(lager, extra_sinks, [{ErrorSink, [{handlers, [{?MODULE, error}]}]}]),
eRum:start(),
crash_fsm:start(),
crash_statem:start(),
eRum:log(ErrorSink, error, self(), "flush flush", []),
timer:sleep(100),
flush(ErrorSink),
ErrorSink.
crash_fsm_cleanup(_Sink) ->
application:stop(lager),
application:stop(goldrush),
application:unset_env(lager, extra_sinks),
lists:foreach(fun(N) -> kill_crasher(N) end, [crash_fsm, crash_statem]),
error_logger:tty(true).
kill_crasher(RegName) ->
case whereis(RegName) of
undefined -> ok;
Pid -> exit(Pid, kill)
end.
spawn_fsm_crash(Module, Function, Args) ->
spawn(fun() -> erlang:apply(Module, Function, Args) end),
timer:sleep(100),
_ = gen_event:which_handlers(error_logger),
ok.
crash_fsm_test_() ->
TestBody = fun(Name, FsmModule, FSMFunc, FSMArgs, Expected) ->
fun(Sink) ->
{Name,
fun() ->
case {FsmModule =:= crash_statem, rumUtil:otp_version() < 19} of
{true, true} -> ok;
_ ->
Pid = whereis(FsmModule),
spawn_fsm_crash(FsmModule, FSMFunc, FSMArgs),
{Level, _, Msg, Metadata} = pop(Sink),
test_body(Expected, lists:flatten(Msg)),
?assertEqual(Pid, proplists:get_value(pid, Metadata)),
?assertEqual(rumUtil:level_to_num(error), Level)
end
end
}
end
end,
Tests = [
fun(Sink) ->
{"again, there is nothing up my sleeve",
fun() ->
?assertEqual(undefined, pop(Sink)),
?assertEqual(0, count(Sink))
end
}
end,
TestBody("gen_fsm crash", crash_fsm, crash, [], "gen_fsm crash_fsm in state state1 terminated with reason: call to undefined function crash_fsm:state1/3 from gen_fsm:handle_msg/"),
TestBody("gen_statem crash", crash_statem, crash, [], "gen_statem crash_statem in state state1 terminated with reason: no function clause matching crash_statem:handle"),
TestBody("gen_statem stop", crash_statem, stop, [explode], "gen_statem crash_statem in state state1 terminated with reason: explode"),
TestBody("gen_statem timeout", crash_statem, timeout, [], "gen_statem crash_statem in state state1 terminated with reason: timeout")
],
{"FSM crash output tests", [
{"Default sink",
{foreach,
fun crash_fsm_setup/0,
fun crash_fsm_cleanup/1,
Tests}},
{"Error logger sink",
{foreach,
fun crash_fsm_sink_setup/0,
fun crash_fsm_cleanup/1,
Tests}}
]}.
error_logger_redirect_crash_test_() ->
TestBody = fun(Name, CrashReason, Expected) ->
fun(Sink) ->
{Name,
fun() ->
Pid = whereis(crash),
crash(CrashReason),
{Level, _, Msg, Metadata} = pop(Sink),
test_body(Expected, lists:flatten(Msg)),
?assertEqual(Pid, proplists:get_value(pid, Metadata)),
?assertEqual(rumUtil:level_to_num(error), Level)
end
}
end
end,
Tests = [
fun(Sink) ->
{"again, there is nothing up my sleeve",
fun() ->
?assertEqual(undefined, pop(Sink)),
?assertEqual(0, count(Sink))
end
}
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("noproc_proc_lib", noproc_proc_lib, "gen_server crash terminated with reason: no such process or port in call to proc_lib:stop/3"),
TestBody("badfun", badfun, "gen_server crash terminated with reason: bad function booger in crash:handle_call/3")
],
{"Error logger redirect crash", [
{"Redirect to default sink",
{foreach,
fun error_logger_redirect_crash_setup/0,
fun error_logger_redirect_crash_cleanup/1,
Tests}},
{"Redirect to error_logger_lager_event sink",
{foreach,
fun error_logger_redirect_crash_setup_sink/0,
fun error_logger_redirect_crash_cleanup/1,
Tests}}
]}.
error_logger_redirect_setup() ->
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, suppress_supervisor_start_stop, false),
application:set_env(lager, suppress_application_start_stop, false),
eRum:start(),
eRum:log(error, self(), "flush flush"),
timer:sleep(1000),
gen_event:call(lager_event, ?MODULE, flush),
lager_event.
error_logger_redirect_setup_sink() ->
error_logger:tty(false),
application:load(lager),
application:set_env(lager, error_logger_redirect, true),
application:unset_env(lager, handlers),
application:set_env(lager, extra_sinks, [
{error_logger_lager_event, [
{handlers, [{?MODULE, info}]}]}]),
application:set_env(lager, suppress_supervisor_start_stop, false),
application:set_env(lager, suppress_application_start_stop, false),
eRum:start(),
eRum:log(error_logger_lager_event, error, self(), "flush flush", []),
timer:sleep(1000),
gen_event:call(error_logger_lager_event, ?MODULE, flush),
error_logger_lager_event.
error_logger_redirect_cleanup(_) ->
application:stop(lager),
application:stop(goldrush),
application:unset_env(lager, extra_sinks),
error_logger:tty(true).
error_logger_redirect_test_() ->
Tests = [
{"error reports are printed",
fun(Sink) ->
sync_error_logger:error_report([{this, is}, a, {silly, format}]),
_ = gen_event:which_handlers(error_logger),
{Level, _, Msg, Metadata} = pop(Sink),
?assertEqual(rumUtil: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(Sink) ->
sync_error_logger:error_report("this is less silly"),
_ = gen_event:which_handlers(error_logger),
{Level, _, Msg, Metadata} = pop(Sink),
?assertEqual(rumUtil: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(Sink) ->
sync_error_logger:error_msg("doom, doom has come upon you all"),
_ = gen_event:which_handlers(error_logger),
{Level, _, Msg, Metadata} = pop(Sink),
?assertEqual(rumUtil: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 with unicode characters in Args are printed",
fun(Sink) ->
sync_error_logger:error_msg("~ts", ["Привет!"]),
_ = gen_event:which_handlers(error_logger),
{Level, _, Msg, Metadata} = pop(Sink),
?assertEqual(rumUtil:level_to_num(error), Level),
?assertEqual(self(), proplists:get_value(pid, Metadata)),
?assertEqual("Привет!", lists:flatten(Msg))
end
},
{"error messages are truncated at 4096 characters",
fun(Sink) ->
sync_error_logger:error_msg("doom, doom has come upon you all ~p", [string:copies("doom", 10000)]),
_ = gen_event:which_handlers(error_logger),
{_, _, Msg, _Metadata} = pop(Sink),
?assert(length(lists:flatten(Msg)) < 5100)
end
},
{"info reports are printed",
fun(Sink) ->
sync_error_logger:info_report([{this, is}, a, {silly, format}]),
_ = gen_event:which_handlers(error_logger),
{Level, _, Msg, Metadata} = pop(Sink),
?assertEqual(rumUtil: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(Sink) ->
sync_error_logger:info_report([[{this, is}, a, {silly, format}] || _ <- lists:seq(0, 600)]),
_ = gen_event:which_handlers(error_logger),
{Level, _, Msg, Metadata} = pop(Sink),
?assertEqual(rumUtil: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(Sink) ->
sync_error_logger:info_report({foolish, bees}),
_ = gen_event:which_handlers(error_logger),
{Level, _, Msg, Metadata} = pop(Sink),
?assertEqual(rumUtil: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(Sink) ->
sync_error_logger:error_report({foolish, bees}),
_ = gen_event:which_handlers(error_logger),
{Level, _, Msg, Metadata} = pop(Sink),
?assertEqual(rumUtil: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(Sink) ->
sync_error_logger:info_report("this is less silly"),
_ = gen_event:which_handlers(error_logger),
{Level, _, Msg, Metadata} = pop(Sink),
?assertEqual(rumUtil: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(Sink) ->
sync_error_logger:info_report(string:copies("this is less silly", 1000)),
_ = gen_event:which_handlers(error_logger),
{Level, _, Msg, Metadata} = pop(Sink),
?assertEqual(rumUtil: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(Sink) ->
sync_error_logger:info_report(["this is less silly", {than, "this"}]),
_ = gen_event:which_handlers(error_logger),
{Level, _, Msg, Metadata} = pop(Sink),
?assertEqual(rumUtil: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(Sink) ->
sync_error_logger:info_msg("doom, doom has come upon you all"),
_ = gen_event:which_handlers(error_logger),
{Level, _, Msg, Metadata} = pop(Sink),
?assertEqual(rumUtil: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(Sink) ->
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(Sink),
?assertEqual(rumUtil:level_to_num(info), Level),
?assertEqual(self(), proplists:get_value(pid, Metadata)),
?assert(length(lists:flatten(Msg)) < 5100)
end
},
{"info messages with unicode characters in Args are printed",
fun(Sink) ->
sync_error_logger:info_msg("~ts", ["Привет!"]),
_ = gen_event:which_handlers(error_logger),
{Level, _, Msg, Metadata} = pop(Sink),
?assertEqual(rumUtil:level_to_num(info), Level),
?assertEqual(self(), proplists:get_value(pid, Metadata)),
?assertEqual("Привет!", lists:flatten(Msg))
end
},
{"warning messages with unicode characters in Args are printed",
%% The next 4 tests need to store the current value of
%% `error_logger:warning_map/0' into a process dictionary
%% key `warning_map' so that the error message level used
%% to process the log messages will match what lager
%% expects.
%%
%% The atom returned by `error_logger:warning_map/0'
%% changed between OTP 17 and 18 (and later releases)
%%
%% `warning_map' is consumed in the `test/sync_error_logger.erl'
%% module. The default message level used in sync_error_logger
%% was fine for OTP releases through 17 and then broke
%% when 18 was released. By storing the expected value
%% in the process dictionary, sync_error_logger will
%% use the correct message level to process the
%% messages and these tests will no longer
%% break.
fun(Sink) ->
Lvl = error_logger:warning_map(),
put(warning_map, Lvl),
sync_error_logger:warning_msg("~ts", ["Привет!"]),
_ = gen_event:which_handlers(error_logger),
{Level, _, Msg, Metadata} = pop(Sink),
?assertEqual(rumUtil:level_to_num(Lvl), Level),
?assertEqual(self(), proplists:get_value(pid, Metadata)),
?assertEqual("Привет!", lists:flatten(Msg))
end
},
{"warning messages are printed at the correct level",
fun(Sink) ->
Lvl = error_logger:warning_map(),
put(warning_map, Lvl),
sync_error_logger:warning_msg("doom, doom has come upon you all"),
_ = gen_event:which_handlers(error_logger),
{Level, _, Msg, Metadata} = pop(Sink),
?assertEqual(rumUtil:level_to_num(Lvl), 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(Sink) ->
Lvl = error_logger:warning_map(),
put(warning_map, Lvl),
sync_error_logger:warning_report([{i, like}, pie]),
_ = gen_event:which_handlers(error_logger),
{Level, _, Msg, Metadata} = pop(Sink),
?assertEqual(rumUtil:level_to_num(Lvl), 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(Sink) ->
Lvl = error_logger:warning_map(),
put(warning_map, Lvl),
sync_error_logger:warning_report({foolish, bees}),
_ = gen_event:which_handlers(error_logger),
{Level, _, Msg, Metadata} = pop(Sink),
?assertEqual(rumUtil:level_to_num(Lvl), Level),
?assertEqual(self(), proplists:get_value(pid, Metadata)),
?assertEqual("{foolish,bees}", lists:flatten(Msg))
end
},
{"application stop reports",
fun(Sink) ->
sync_error_logger:info_report([{application, foo}, {exited, quittin_time}, {type, lazy}]),
_ = gen_event:which_handlers(error_logger),
{Level, _, Msg, Metadata} = pop(Sink),
?assertEqual(rumUtil: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(Sink) ->
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(Sink),
?assertEqual(rumUtil: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(Sink) ->
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(Sink),
?assertEqual(rumUtil: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 reports with real error and pid",
fun(Sink) ->
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, somepid}]),
_ = gen_event:which_handlers(error_logger),
{Level, _, Msg, Metadata} = pop(Sink),
?assertEqual(rumUtil:level_to_num(error), Level),
?assertEqual(self(), proplists:get_value(pid, Metadata)),
?assertEqual("Supervisor somepid 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(Sink) ->
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(Sink),
?assertEqual(rumUtil: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(Sink) ->
sync_error_logger:info_report(progress, [{application, foo}, {started_at, node()}]),
_ = gen_event:which_handlers(error_logger),
{Level, _, Msg, Metadata} = pop(Sink),
?assertEqual(rumUtil: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(Sink) ->
eRum:set_loglevel(Sink, ?MODULE, undefined, debug),
?assertEqual({?DEBUG bor ?INFO bor ?NOTICE bor ?WARNING bor ?ERROR bor ?CRITICAL bor ?ALERT bor ?EMERGENCY, []}, rumConfig:get({Sink, loglevel})),
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(Sink),
?assertEqual(rumUtil: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
},
{"supervisor progress report with pid",
fun(Sink) ->
eRum:set_loglevel(Sink, ?MODULE, undefined, debug),
?assertEqual({?DEBUG bor ?INFO bor ?NOTICE bor ?WARNING bor ?ERROR bor ?CRITICAL bor ?ALERT bor ?EMERGENCY, []}, rumConfig:get({Sink, loglevel})),
sync_error_logger:info_report(progress, [{supervisor, somepid}, {started, [{mfargs, {foo, bar, 1}}, {pid, baz}]}]),
_ = gen_event:which_handlers(error_logger),
{Level, _, Msg, Metadata} = pop(Sink),
?assertEqual(rumUtil:level_to_num(debug), Level),
?assertEqual(self(), proplists:get_value(pid, Metadata)),
?assertEqual("Supervisor somepid started foo:bar/1 at pid baz", lists:flatten(Msg))
end
},
{"crash report for emfile",
fun(Sink) ->
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(Sink),
?assertEqual(rumUtil: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(Sink) ->
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(Sink),
?assertEqual(rumUtil: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(Sink) ->
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(Sink),
?assertEqual(rumUtil: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(Sink) ->
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(Sink),
?assertEqual(rumUtil: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(Sink) ->
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(Sink),
?assertEqual(rumUtil: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(Sink) ->
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(Sink),
?assertEqual(rumUtil: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(Sink) ->
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(Sink),
?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(Sink) ->
{ok, Pid} = special_process:start(),
unlink(Pid),
Pid ! function_clause,
timer:sleep(500),
_ = gen_event:which_handlers(error_logger),
{_, _, Msg, _Metadata} = pop(Sink),
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(Sink) ->
{ok, Pid} = special_process:start(),
unlink(Pid),
Pid ! {case_clause, wtf},
timer:sleep(500),
_ = gen_event:which_handlers(error_logger),
{_, _, Msg, _Metadata} = pop(Sink),
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(Sink) ->
{ok, Pid} = special_process:start(),
unlink(Pid),
Pid ! exit,
timer:sleep(500),
_ = gen_event:which_handlers(error_logger),
{_, _, Msg, _Metadata} = pop(Sink),
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(Sink) ->
{ok, Pid} = special_process:start(),
unlink(Pid),
Pid ! error,
timer:sleep(500),
_ = gen_event:which_handlers(error_logger),
{_, _, Msg, _Metadata} = pop(Sink),
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
},
{"webmachine error reports",
fun(Sink) ->
Path = "/cgi-bin/phpmyadmin",
Reason = {error, {error, {badmatch, {error, timeout}},
[{myapp, dostuff, 2, [{file, "src/myapp.erl"}, {line, 123}]},
{webmachine_resource, resource_call, 3, [{file, "src/webmachine_resource.erl"}, {line, 169}]}]}},
sync_error_logger:error_msg("webmachine error: path=~p~n~p~n", [Path, Reason]),
_ = gen_event:which_handlers(error_logger),
{Level, _, Msg, Metadata} = pop(Sink),
?assertEqual(rumUtil:level_to_num(error), Level),
?assertEqual(self(), proplists:get_value(pid, Metadata)),
?assertEqual("Webmachine error at path \"/cgi-bin/phpmyadmin\" : no match of right hand value {error,timeout} in myapp:dostuff/2 line 123", lists:flatten(Msg))
end
},
{"Cowboy error reports, 8 arg version",
fun(Sink) ->
Stack = [{my_handler, init, 3, [{file, "src/my_handler.erl"}, {line, 123}]},
{cowboy_handler, handler_init, 4, [{file, "src/cowboy_handler.erl"}, {line, 169}]}],
sync_error_logger:error_msg(
"** Cowboy handler ~p terminating in ~p/~p~n"
" for the reason ~p:~p~n"
"** Options were ~p~n"
"** Request was ~p~n"
"** Stacktrace: ~p~n~n",
[my_handler, init, 3, error, {badmatch, {error, timeout}}, [],
"Request", Stack]),
_ = gen_event:which_handlers(error_logger),
{Level, _, Msg, Metadata} = pop(Sink),
?assertEqual(rumUtil:level_to_num(error), Level),
?assertEqual(self(), proplists:get_value(pid, Metadata)),
?assertEqual("Cowboy handler my_handler terminated in my_handler:init/3 with reason: no match of right hand value {error,timeout} in my_handler:init/3 line 123", lists:flatten(Msg))
end
},
{"Cowboy error reports, 10 arg version",
fun(Sink) ->
Stack = [{my_handler, somecallback, 3, [{file, "src/my_handler.erl"}, {line, 123}]},
{cowboy_handler, handler_init, 4, [{file, "src/cowboy_handler.erl"}, {line, 169}]}],
sync_error_logger:error_msg(
"** Cowboy handler ~p terminating in ~p/~p~n"
" for the reason ~p:~p~n** Message was ~p~n"
"** Options were ~p~n** Handler state was ~p~n"
"** Request was ~p~n** Stacktrace: ~p~n~n",
[my_handler, somecallback, 3, error, {badmatch, {error, timeout}}, hello, [],
{}, "Request", Stack]),
_ = gen_event:which_handlers(error_logger),
{Level, _, Msg, Metadata} = pop(Sink),
?assertEqual(rumUtil:level_to_num(error), Level),
?assertEqual(self(), proplists:get_value(pid, Metadata)),
?assertEqual("Cowboy handler my_handler terminated in my_handler:somecallback/3 with reason: no match of right hand value {error,timeout} in my_handler:somecallback/3 line 123", lists:flatten(Msg))
end
},
{"Cowboy error reports, 5 arg version",
fun(Sink) ->
sync_error_logger:error_msg(
"** Cowboy handler ~p terminating; "
"function ~p/~p was not exported~n"
"** Request was ~p~n** State was ~p~n~n",
[my_handler, to_json, 2, "Request", {}]),
_ = gen_event:which_handlers(error_logger),
{Level, _, Msg, Metadata} = pop(Sink),
?assertEqual(rumUtil:level_to_num(error), Level),
?assertEqual(self(), proplists:get_value(pid, Metadata)),
?assertEqual("Cowboy handler my_handler terminated with reason: call to undefined function my_handler:to_json/2", lists:flatten(Msg))
end
},
{"Cowboy error reports, 6 arg version",
fun(Sink) ->
Stack = [{app_http, init, 2, [{file, "app_http.erl"}, {line, 9}]},
{cowboy_handler, execute, 2, [{file, "cowboy_handler.erl"}, {line, 41}]}],
ConnectionPid = list_to_pid("<0.82.0>"),
sync_error_logger:error_msg(
"Ranch listener ~p, connection process ~p, stream ~p "
"had its request process ~p exit with reason "
"~999999p and stacktrace ~999999p~n",
[my_listner, ConnectionPid, 1, self(), {badmatch, 2}, Stack]),
_ = gen_event:which_handlers(error_logger),
{Level, _, Msg, Metadata} = pop(Sink),
?assertEqual(rumUtil:level_to_num(error), Level),
?assertEqual(self(), proplists:get_value(pid, Metadata)),
?assertEqual("Cowboy stream 1 with ranch listener my_listner and "
"connection process <0.82.0> had its request process exit "
"with reason: no match of right hand value 2 "
"in app_http:init/2 line 9", lists:flatten(Msg))
end
},
{"messages should not be generated if they don't satisfy the threshold",
fun(Sink) ->
eRum:set_loglevel(Sink, ?MODULE, undefined, error),
?assertEqual({?ERROR bor ?CRITICAL bor ?ALERT bor ?EMERGENCY, []}, rumConfig:get({Sink, loglevel})),
sync_error_logger:info_report([hello, world]),
_ = gen_event:which_handlers(error_logger),
?assertEqual(0, count(Sink)),
?assertEqual(0, count_ignored(Sink)),
eRum:set_loglevel(Sink, ?MODULE, undefined, info),
?assertEqual({?INFO bor ?NOTICE bor ?WARNING bor ?ERROR bor ?CRITICAL bor ?ALERT bor ?EMERGENCY, []}, rumConfig:get({Sink, loglevel})),
sync_error_logger:info_report([hello, world]),
_ = gen_event:which_handlers(error_logger),
?assertEqual(1, count(Sink)),
?assertEqual(0, count_ignored(Sink)),
eRum:set_loglevel(Sink, ?MODULE, undefined, error),
?assertEqual({?ERROR bor ?CRITICAL bor ?ALERT bor ?EMERGENCY, []}, rumConfig:get({Sink, loglevel})),
rumConfig:set({Sink, loglevel}, {element(2, rumUtil:config_to_mask(debug)), []}),
sync_error_logger:info_report([hello, world]),
_ = gen_event:which_handlers(error_logger),
?assertEqual(1, count(Sink)),
?assertEqual(1, count_ignored(Sink))
end
}
],
SinkTests = lists:map(
fun({Name, F}) ->
fun(Sink) -> {Name, fun() -> F(Sink) end} end
end,
Tests),
{"Error logger redirect", [
{"Redirect to default sink",
{foreach,
fun error_logger_redirect_setup/0,
fun error_logger_redirect_cleanup/1,
SinkTests}},
{"Redirect to error_logger_lager_event sink",
{foreach,
fun error_logger_redirect_setup_sink/0,
fun error_logger_redirect_cleanup/1,
SinkTests}}
]}.
safe_format_test() ->
?assertEqual("foo bar", lists:flatten(eRum:safe_format("~p ~p", [foo, bar], 1024))),
?assertEqual("FORMAT ERROR: \"~p ~p ~p\" [foo,bar]", lists:flatten(eRum:safe_format("~p ~p ~p", [foo, bar], 1024))),
ok.
unsafe_format_test() ->
?assertEqual("foo bar", lists:flatten(eRum:unsafe_format("~p ~p", [foo, bar]))),
?assertEqual("FORMAT ERROR: \"~p ~p ~p\" [foo,bar]", lists:flatten(eRum:unsafe_format("~p ~p ~p", [foo, bar]))),
ok.
async_threshold_test_() ->
Cleanup = fun(Reset) ->
_ = error_logger:tty(false),
_ = application:stop(lager),
_ = application:stop(goldrush),
_ = application:unset_env(lager, async_threshold),
if
Reset ->
true = ets:delete(async_threshold_test),
error_logger:tty(true);
true ->
_ = (catch ets:delete(async_threshold_test)),
ok
end
end,
Setup = fun() ->
% Evidence suggests that previous tests somewhere are leaving some of this stuff
% loaded, and cleaning it out forcefully to allows the test to succeed.
_ = Cleanup(false),
_ = ets:new(async_threshold_test, [set, named_table, public]),
?assertEqual(true, ets:insert_new(async_threshold_test, {sync_toggled, 0})),
?assertEqual(true, ets:insert_new(async_threshold_test, {async_toggled, 0})),
_ = application:load(lager),
ok = application:set_env(lager, error_logger_redirect, false),
ok = application:set_env(lager, async_threshold, 2),
ok = application:set_env(lager, async_threshold_window, 1),
ok = application:set_env(lager, handlers, [{?MODULE, info}]),
ok = eRum:start(),
true
end,
{foreach, Setup, Cleanup, [
{"async threshold works",
{timeout, 30, fun() ->
Sleep = get_long_sleep_value(),
%% we start out async
?assertEqual(true, rumConfig:get(async)),
?assertEqual([{sync_toggled, 0}],
ets:lookup(async_threshold_test, sync_toggled)),
%% put a ton of things in the queue
WorkCnt = erlang:max(10, (erlang:system_info(schedulers) * 2)),
OtpVsn = rumUtil:otp_version(),
% newer OTPs *may* handle the messages faster, so we'll send more
MsgCnt = ((OtpVsn * OtpVsn) div 2),
Workers = spawn_stuffers(WorkCnt, [MsgCnt, info, "hello world"], []),
%% serialize on mailbox
_ = gen_event:which_handlers(lager_event),
timer:sleep(Sleep),
%% By now the flood of messages should have forced the backend throttle
%% to turn off async mode, but it's possible all outstanding requests
%% have been processed, so checking the current status (sync or async)
%% is an exercise in race control.
%% Instead, we'll see whether the backend throttle has toggled into sync
%% mode at any point in the past.
?assertMatch([{sync_toggled, N}] when N > 0,
ets:lookup(async_threshold_test, sync_toggled)),
%% Wait for all the workers to return, meaning that all the messages have
%% been logged (since we're definitely in sync mode at the end of the run).
collect_workers(Workers),
%% serialize on the mailbox again
_ = gen_event:which_handlers(lager_event),
timer:sleep(Sleep),
eRum:info("hello world"),
_ = gen_event:which_handlers(lager_event),
timer:sleep(Sleep),
%% async is true again now that the mailbox has drained
?assertEqual(true, rumConfig:get(async)),
ok
end}}
]}.
% Fire off the stuffers with minimal resource overhead - speed is of the essence.
spawn_stuffers(0, _, Refs) ->
% Attempt to return them in about the order that they'll finish.
lists:reverse(Refs);
spawn_stuffers(N, Args, Refs) ->
{_Pid, Ref} = erlang:spawn_monitor(?MODULE, message_stuffer, Args),
spawn_stuffers((N - 1), Args, [Ref | Refs]).
% Spawned process to stuff N copies of Message into lager's message queue as fast as possible.
% Skip using a list function for speed and low memory footprint - don't want to take the
% resources to create a sequence (or pass one in).
message_stuffer(N, Level, Message) ->
message_stuffer_(N, Level, [{pid, erlang:self()}], Message).
message_stuffer_(0, _, _, _) ->
ok;
message_stuffer_(N, Level, Meta, Message) ->
eRum:log(Level, Meta, Message),
message_stuffer_((N - 1), Level, Meta, Message).
collect_workers([]) ->
ok;
collect_workers([Ref | Refs]) ->
receive
{'DOWN', Ref, _, _, _} ->
collect_workers(Refs)
end.
produce_n_error_logger_msgs(N) ->
lists:foreach(fun(K) ->
error_logger:error_msg("Foo ~p!", [K])
end,
lists:seq(0, N - 1)
).
high_watermark_test_() ->
{foreach,
fun() ->
error_logger:tty(false),
application:load(lager),
application:set_env(lager, error_logger_redirect, true),
application:set_env(lager, handlers, [{lager_test_backend, info}]),
application:set_env(lager, async_threshold, undefined),
eRum:start()
end,
fun(_) ->
application:stop(lager),
error_logger:tty(true)
end,
[
{"Nothing dropped when error_logger high watermark is undefined",
fun() ->
ok = rumErrLoggerH:set_high_water(undefined),
timer:sleep(100),
produce_n_error_logger_msgs(10),
timer:sleep(500),
?assert(count() >= 10)
end
},
{"Mostly dropped according to error_logger high watermark",
fun() ->
ok = rumErrLoggerH:set_high_water(5),
timer:sleep(100),
produce_n_error_logger_msgs(50),
timer:sleep(1000),
?assert(count() < 20)
end
},
{"Non-notifications are not dropped",
fun() ->
ok = rumErrLoggerH:set_high_water(2),
timer:sleep(100),
spawn(fun() -> produce_n_error_logger_msgs(300) end),
timer:sleep(50),
%% if everything were dropped, this call would be dropped
%% too, so lets hope it's not
?assert(is_integer(count())),
timer:sleep(1000),
?assert(count() < 10)
end
}
]
}.
get_long_sleep_value() ->
case os:getenv("CI") of
false ->
500;
_ ->
5000
end.
-endif.