diff --git a/include/eRum.hrl b/include/eRum.hrl index 57da890..8b7aea1 100644 --- a/include/eRum.hrl +++ b/include/eRum.hrl @@ -1,6 +1,7 @@ +-include("rumCom.hrl"). + %% 默认的元数据 %% Level, Pid, Node, Module, Function, FunctionArity, File, Line, Other --define(RumDefSink, rumEvent). %% 获取元数据的宏定义 -define(RumMetadata(Extras), [ @@ -15,14 +16,13 @@ ]). -define(rumLog(Severity, Format, Args, Safety), - ?rumLog(?RumDefSink, Severity, self(), node(), ?MODULE, ?FUNCTION_NAME, ?RumMetadata(eRum:md()), Format, Args, ?RumDefTruncation, Safety)). + ?rumLog(?RumDefSink, Severity, self(), node(), ?MODULE, ?FUNCTION_NAME, ?FILE, ?LINE, eRum:md(), Format, Args, ?RumDefTruncation, Safety)). -define(rumLog(Severity, Metadata, Format, Args, Safety), - ?rumLog(?RumDefSink, Severity, ?RumMetadata(Metadata ++ eRum:md()), Format, Args, ?RumDefTruncation, Safety)). + ?rumLog(?RumDefSink, Severity, self(), node(), ?MODULE, ?FUNCTION_NAME, ?FILE, ?LINE, Metadata ++ eRum:md(), Format, Args, ?RumDefTruncation, Safety)). -define(rumLog(Sink, Severity, Metadata, Format, Args, Size, Safety), - eRum:dispatch_log(Sink, Severity, Metadata, Format, Args, Size, Safety)). - + eRum:dispatch_log(Sink, Severity, Pid, Node, Module, Function, File, Line, Metadata, Format, Args, Size, Safety)). -define(rumNone(Format, Args), ?rumLog(none, Format, Args, safe)). -define(rumNone(Metadata, Format, Args), ?rumLog(none, Metadata, Format, Args, safe)). diff --git a/include/rumCom.hrl b/include/rumCom.hrl new file mode 100644 index 0000000..f740683 --- /dev/null +++ b/include/rumCom.hrl @@ -0,0 +1,2 @@ +-define(RumDefSink, rumEvent). +-define(RumDefTruncation, 4096). \ No newline at end of file diff --git a/include/rumDef.hrl b/include/rumDef.hrl index 3a2c629..252c251 100644 --- a/include/rumDef.hrl +++ b/include/rumDef.hrl @@ -18,8 +18,6 @@ -define(RumRotateTimeout, 100000). %% 部分默认配置值 --define(RumDefSink, rumEvent). --define(RumDefTruncation, 4096). -define(RumDefTracer, lager_default_tracer). -define(RumErrLogSink, error_logger_lager_event). @@ -94,15 +92,6 @@ , filter = fun(_) -> false end :: fun() }). --record(rumMsg, { - destinations :: list(), - metadata :: [tuple()], - severity :: rumAtomLevel(), - datetime :: binary(), - timestamp :: non_neg_integer(), - message :: list() -}). - -type rumShaper() :: #rumShaper{}. -type rumAtomLevel() :: none | debug | info | notice | warning | error | critical | alert | emergency. diff --git a/include/rumMsg.hrl b/include/rumMsg.hrl new file mode 100644 index 0000000..8065b39 --- /dev/null +++ b/include/rumMsg.hrl @@ -0,0 +1,30 @@ +-record(rumMsg, { + severity :: rumAtomLevel() + , pid + , node + , module + , function + , file + , line + , metadata :: [tuple()] + , datetime :: binary() + , timestamp :: non_neg_integer() + , message :: list() + , destinations :: list() +}). + +-define(newMsg(Severity, Pid, Node, Module, Function, File, Line, Metadata, Destinations, TimeMs, Msg), + #rumMsg{ + severity = Severity + , pid =Pid + , node = Node + , module = Module + , function = Function + , file =File + , line =Line + , metadata =Metadata + , datetime = rumUtil:msToBinStr(TimeMs) + , timestamp = TimeMs + , message = Msg + , destinations = Destinations + }). \ No newline at end of file diff --git a/src/backend/rumBkdConsole.erl b/src/backend/rumBkdConsole.erl index 336a492..bbb348b 100644 --- a/src/backend/rumBkdConsole.erl +++ b/src/backend/rumBkdConsole.erl @@ -9,11 +9,6 @@ -include("rumDef.hrl"). --ifdef(TEST). --include_lib("eunit/include/eunit.hrl"). --compile([{parse_transform, rumTransform}]). --endif. - -define(TERSE_FORMAT, [time, " ", color, "[", severity, "] ", message]). -define(RumDefConsoleFmtCfg, ?TERSE_FORMAT ++ [eol()]). -define(RumDefConsoleOpts, [{use_stderr, false}, {group_leader, false}, {id, ?MODULE}, {formatter, rumFormatter}, {formatter_config, ?RumDefConsoleFmtCfg}]). @@ -131,376 +126,3 @@ isNewStyleConsole() -> %% 'user_drv' is a registered proc name used by the "new" %% console driver. init:get_argument(noshell) /= error orelse element(1, os:type()) /= win32 orelse is_pid(whereis(user_drv)). - --ifdef(TEST). -console_config_validation_test_() -> - Good = [{level, info}, {use_stderr, true}], - Bad1 = [{level, foo}, {use_stderr, flase}], - Bad2 = [{level, info}, {use_stderr, flase}], - AllGood = [{level, info}, {formatter, my_formatter}, - {formatter_config, ["blort", "garbage"]}, - {use_stderr, false}], - [ - ?_assertEqual(true, checkOpts(Good)), - ?_assertThrow({error, {fatal, {bad_level, foo}}}, checkOpts(Bad1)), - ?_assertThrow({error, {fatal, {bad_console_config, {use_stderr, flase}}}}, checkOpts(Bad2)), - ?_assertEqual(true, checkOpts(AllGood)) - ]. - -console_log_test_() -> - %% tiny recursive fun that pretends to be a group leader - F = fun(Self) -> - fun() -> - YComb = fun(Fun) -> - receive - {io_request, From, ReplyAs, {put_chars, unicode, _Msg}} = Y -> - From ! {io_reply, ReplyAs, ok}, - Self ! Y, - Fun(Fun); - Other -> - ?debugFmt("unexpected message ~p~n", [Other]), - Self ! Other - end - end, - YComb(YComb) - end - end, - {foreach, - fun() -> - error_logger:tty(false), - application:load(lager), - application:set_env(lager, handlers, []), - application:set_env(lager, errLoggerRedirect, false), - eRum:start(), - whereis(user) - end, - fun(User) -> - unregister(user), - register(user, User), - application:stop(lager), - application:stop(goldrush), - error_logger:tty(true) - end, - [ - {"regular console logging", - fun() -> - Pid = spawn(F(self())), - unregister(user), - register(user, Pid), - erlang:group_leader(Pid, whereis(rumEvent)), - gen_event:add_handler(rumEvent, lager_console_backend, [{level, info}]), - rumConfig:set({rumEvent, loglevel}, {rumUtil:configToMask(info), []}), - eRum:log(info, self(), "Test message"), - receive - {io_request, From, ReplyAs, {put_chars, unicode, Msg}} -> - From ! {io_reply, ReplyAs, ok}, - TestMsg = "Test message" ++ eol(), - ?assertMatch([_, "[info]", TestMsg], re:split(Msg, " ", [{return, list}, {parts, 3}])) - after - 500 -> - ?assert(false) - end - end - }, - {"verbose console logging", - fun() -> - Pid = spawn(F(self())), - unregister(user), - register(user, Pid), - erlang:group_leader(Pid, whereis(rumEvent)), - gen_event:add_handler(rumEvent, lager_console_backend, [info, true]), - rumConfig:set({rumEvent, loglevel}, {rumUtil:configToMask(info), []}), - eRum:info("Test message"), - PidStr = pid_to_list(self()), - receive - {io_request, _, _, {put_chars, unicode, Msg}} -> - TestMsg = "Test message" ++ eol(), - ?assertMatch([_, _, "[info]", PidStr, _, TestMsg], re:split(Msg, "[ @]", [{return, list}, {parts, 6}])) - after - 500 -> - ?assert(false) - end - end - }, - {"custom format console logging", - fun() -> - Pid = spawn(F(self())), - unregister(user), - register(user, Pid), - erlang:group_leader(Pid, whereis(rumEvent)), - gen_event:add_handler(rumEvent, lager_console_backend, - [{level, info}, {formatter, lager_default_formatter}, {formatter_config, [date, "#", time, "#", severity, "#", node, "#", pid, "#", - module, "#", function, "#", file, "#", line, "#", message, "\r\n"]}]), - rumConfig:set({rumEvent, loglevel}, {?INFO, []}), - eRum:info("Test message"), - PidStr = pid_to_list(self()), - NodeStr = atom_to_list(node()), - ModuleStr = atom_to_list(?MODULE), - receive - {io_request, _, _, {put_chars, unicode, Msg}} -> - TestMsg = "Test message" ++ eol(), - ?assertMatch([_, _, "info", NodeStr, PidStr, ModuleStr, _, _, _, TestMsg], - re:split(Msg, "#", [{return, list}, {parts, 10}])) - after - 500 -> - ?assert(false) - end - end - }, - {"tracing should work", - fun() -> - Pid = spawn(F(self())), - unregister(user), - register(user, Pid), - gen_event:add_handler(rumEvent, lager_console_backend, [{level, info}]), - erlang:group_leader(Pid, whereis(rumEvent)), - rumConfig:set({rumEvent, loglevel}, {rumUtil:configToMask(info), []}), - eRum:debug("Test message"), - receive - {io_request, From, ReplyAs, {put_chars, unicode, _Msg}} -> - From ! {io_reply, ReplyAs, ok}, - ?assert(false) - after - 500 -> - ?assert(true) - end, - {ok, _} = eRum:trace_console([{module, ?MODULE}]), - eRum:debug("Test message"), - receive - {io_request, From1, ReplyAs1, {put_chars, unicode, Msg1}} -> - From1 ! {io_reply, ReplyAs1, ok}, - TestMsg = "Test message" ++ eol(), - ?assertMatch([_, "[debug]", TestMsg], re:split(Msg1, " ", [{return, list}, {parts, 3}])) - after - 500 -> - ?assert(false) - end - end - }, - {"tracing doesn't duplicate messages", - fun() -> - Pid = spawn(F(self())), - unregister(user), - register(user, Pid), - gen_event:add_handler(rumEvent, lager_console_backend, [{level, info}]), - rumConfig:set({rumEvent, loglevel}, {rumUtil:configToMask(info), []}), - erlang:group_leader(Pid, whereis(rumEvent)), - eRum:debug("Test message"), - receive - {io_request, From, ReplyAs, {put_chars, unicode, _Msg}} -> - From ! {io_reply, ReplyAs, ok}, - ?assert(false) - after - 500 -> - ?assert(true) - end, - {ok, _} = eRum:trace_console([{module, ?MODULE}]), - eRum:error("Test message"), - receive - {io_request, From1, ReplyAs1, {put_chars, unicode, Msg1}} -> - From1 ! {io_reply, ReplyAs1, ok}, - TestMsg = "Test message" ++ eol(), - ?assertMatch([_, "[error]", TestMsg], re:split(Msg1, " ", [{return, list}, {parts, 3}])) - after - 1000 -> - ?assert(false) - end, - %% make sure this event wasn't duplicated - receive - {io_request, From2, ReplyAs2, {put_chars, unicode, _Msg2}} -> - From2 ! {io_reply, ReplyAs2, ok}, - ?assert(false) - after - 500 -> - ?assert(true) - end - end - }, - {"blacklisting a loglevel works", - fun() -> - Pid = spawn(F(self())), - unregister(user), - register(user, Pid), - gen_event:add_handler(rumEvent, lager_console_backend, [{level, info}]), - rumConfig:set({rumEvent, loglevel}, {rumUtil:configToMask(info), []}), - eRum:setLogLevel(lager_console_backend, '!=info'), - erlang:group_leader(Pid, whereis(rumEvent)), - eRum:debug("Test message"), - receive - {io_request, From1, ReplyAs1, {put_chars, unicode, Msg1}} -> - From1 ! {io_reply, ReplyAs1, ok}, - TestMsg = "Test message" ++ eol(), - ?assertMatch([_, "[debug]", TestMsg], re:split(Msg1, " ", [{return, list}, {parts, 3}])) - after - 1000 -> - ?assert(false) - end, - %% info is blacklisted - eRum:info("Test message"), - receive - {io_request, From2, ReplyAs2, {put_chars, unicode, _Msg2}} -> - From2 ! {io_reply, ReplyAs2, ok}, - ?assert(false) - after - 500 -> - ?assert(true) - end - end - }, - {"whitelisting a loglevel works", - fun() -> - Pid = spawn(F(self())), - unregister(user), - register(user, Pid), - gen_event:add_handler(rumEvent, lager_console_backend, [{level, info}]), - rumConfig:set({rumEvent, loglevel}, {rumUtil:configToMask(info), []}), - eRum:setLogLevel(lager_console_backend, '=debug'), - erlang:group_leader(Pid, whereis(rumEvent)), - eRum:debug("Test message"), - receive - {io_request, From1, ReplyAs1, {put_chars, unicode, Msg1}} -> - From1 ! {io_reply, ReplyAs1, ok}, - TestMsg = "Test message" ++ eol(), - ?assertMatch([_, "[debug]", TestMsg], re:split(Msg1, " ", [{return, list}, {parts, 3}])) - after - 1000 -> - ?assert(false) - end, - %% info is blacklisted - eRum:error("Test message"), - receive - {io_request, From2, ReplyAs2, {put_chars, unicode, _Msg2}} -> - From2 ! {io_reply, ReplyAs2, ok}, - ?assert(false) - after - 500 -> - ?assert(true) - end - end - }, - {"console backend with custom group leader", - fun() -> - Pid = spawn(F(self())), - gen_event:add_handler(rumEvent, lager_console_backend, [{level, info}, {group_leader, Pid}]), - rumConfig:set({rumEvent, loglevel}, {rumUtil:configToMask(info), []}), - eRum:info("Test message"), - ?assertNotEqual({group_leader, Pid}, erlang:process_info(whereis(rumEvent), group_leader)), - receive - {io_request, From1, ReplyAs1, {put_chars, unicode, Msg1}} -> - From1 ! {io_reply, ReplyAs1, ok}, - TestMsg = "Test message" ++ eol(), - ?assertMatch([_, "[info]", TestMsg], re:split(Msg1, " ", [{return, list}, {parts, 3}])) - after - 1000 -> - ?assert(false) - end, - %% killing the pid should prevent any new log messages (to prove we haven't accidentally redirected - %% the group leader some other way - exit(Pid, kill), - timer:sleep(100), - %% additionally, check the lager backend has been removed (because the group leader process died) - ?assertNot(lists:member(lager_console_backend, gen_event:which_handlers(rumEvent))), - eRum:error("Test message"), - receive - {io_request, From2, ReplyAs2, {put_chars, unicode, _Msg2}} -> - From2 ! {io_reply, ReplyAs2, ok}, - ?assert(false) - after - 500 -> - ?assert(true) - end - end - }, - {"console backend with custom group leader using a trace and an ID", - fun() -> - Pid = spawn(F(self())), - ID = {?MODULE, trace_test}, - Handlers = rumConfig:global_get(handlers, []), - HandlerInfo = lager_app:start_handler(rumEvent, ID, - [{level, none}, {group_leader, Pid}, - {id, ID}]), - rumConfig:global_set(handlers, [HandlerInfo | Handlers]), - eRum:info("Test message"), - ?assertNotEqual({group_leader, Pid}, erlang:process_info(whereis(rumEvent), group_leader)), - receive - {io_request, From, ReplyAs, {put_chars, unicode, _Msg}} -> - From ! {io_reply, ReplyAs, ok}, - ?assert(false) - after - 500 -> - ?assert(true) - end, - eRum:trace(ID, [{module, ?MODULE}], debug), - eRum:info("Test message"), - receive - {io_request, From1, ReplyAs1, {put_chars, unicode, Msg1}} -> - From1 ! {io_reply, ReplyAs1, ok}, - TestMsg = "Test message" ++ eol(), - ?assertMatch([_, "[info]", TestMsg], re:split(Msg1, " ", [{return, list}, {parts, 3}])) - after - 500 -> - ?assert(false) - end, - ?assertNotEqual({0, []}, rumConfig:get({rumEvent, loglevel})), - %% killing the pid should prevent any new log messages (to prove we haven't accidentally redirected - %% the group leader some other way - exit(Pid, kill), - timer:sleep(100), - %% additionally, check the lager backend has been removed (because the group leader process died) - ?assertNot(lists:member(lager_console_backend, gen_event:which_handlers(rumEvent))), - %% finally, check the trace has been removed - ?assertEqual({0, []}, rumConfig:get({rumEvent, loglevel})), - eRum:error("Test message"), - receive - {io_request, From3, ReplyAs3, {put_chars, unicode, _Msg3}} -> - From3 ! {io_reply, ReplyAs3, ok}, - ?assert(false) - after - 500 -> - ?assert(true) - end - end - } - ] - }. - -set_loglevel_test_() -> - {foreach, - fun() -> - error_logger:tty(false), - application:load(lager), - application:set_env(lager, handlers, [{lager_console_backend, [{level, info}]}]), - application:set_env(lager, errLoggerRedirect, false), - eRum:start() - end, - fun(_) -> - application:stop(lager), - application:stop(goldrush), - error_logger:tty(true) - end, - [ - {"Get/set loglevel test", - fun() -> - ?assertEqual(info, eRum:getLogLevel(lager_console_backend)), - eRum:setLogLevel(lager_console_backend, debug), - ?assertEqual(debug, eRum:getLogLevel(lager_console_backend)), - eRum:setLogLevel(lager_console_backend, '!=debug'), - ?assertEqual(info, eRum:getLogLevel(lager_console_backend)), - eRum:setLogLevel(lager_console_backend, '!=info'), - ?assertEqual(debug, eRum:getLogLevel(lager_console_backend)), - ok - end - }, - {"Get/set invalid loglevel test", - fun() -> - ?assertEqual(info, eRum:getLogLevel(lager_console_backend)), - ?assertEqual({error, bad_log_level}, - eRum:setLogLevel(lager_console_backend, fatfinger)), - ?assertEqual(info, eRum:getLogLevel(lager_console_backend)) - end - } - - ] - }. - --endif. diff --git a/src/backend/rumBkdFile.erl b/src/backend/rumBkdFile.erl index 50d34ab..69e3b89 100644 --- a/src/backend/rumBkdFile.erl +++ b/src/backend/rumBkdFile.erl @@ -14,11 +14,6 @@ -behaviour(gen_emm). --ifdef(TEST). --include_lib("eunit/include/eunit.hrl"). --compile([{parse_transform, lager_transform}]). --endif. - -export([configToId/1]). -export([ @@ -297,717 +292,3 @@ closeFile(#state{fd = Fd} = State) -> _ = file:close(Fd), State#state{fd = undefined} end. - --ifdef(TEST). - -get_loglevel_test() -> - {ok, Level, _} = handleCall(mGetLogLevel, - #state{fileName = "bar", level = rumUtil:configToMask(info), fd = 0, inode = 0, ctime = undefined}), - ?assertEqual(Level, rumUtil:configToMask(info)), - {ok, Level2, _} = handleCall(mGetLogLevel, - #state{fileName = "foo", level = rumUtil:configToMask(warning), fd = 0, inode = 0, ctime = undefined}), - ?assertEqual(Level2, rumUtil:configToMask(warning)). - -rotation_test_() -> - {foreach, - fun() -> - SyncLevel = rumUtil:configToMask(?RumDefSyncLevel), - SyncSize = ?RumDefSyncSize, - SyncInterval = ?RumDefSyncInterval, - Rotator = ?RumDefRotateMod, - CheckInterval = 0, %% hard to test delayed mode - {ok, TestDir} = rumUtil:create_test_dir(), - TestLog = filename:join(TestDir, "test.log"), - {OsType, _} = os:type(), - #state{fileName = TestLog, - level = ?DEBUG, - syncOn = SyncLevel, - syncSize = SyncSize, - syncInterval = SyncInterval, - checkInterval = CheckInterval, - rotator = Rotator, - osType = OsType} - end, - fun(#state{}) -> - ok = rumUtil:delete_test_dir() - end, [ - fun(DefaultState = #state{fileName = TestLog, osType = OsType, syncSize = SyncSize, syncInterval = SyncInterval, rotator = Rotator}) -> - {"External rotation should work", - fun() -> - case OsType of - win32 -> - % Note: test is skipped on win32 due to the fact that a file can't be deleted or renamed - % while a process has an open file handle referencing it - ok; - _ -> - {ok, FD, Inode, Ctime, _Size} = Rotator:openLogfile(TestLog, {SyncSize, SyncInterval}), - State0 = DefaultState#state{fd = FD, inode = Inode, ctime = Ctime}, - State1 = writeLog(State0, os:timestamp(), ?DEBUG, "hello world"), - ?assertMatch(#state{fileName = TestLog, level = ?DEBUG, fd = FD, inode = Inode, ctime = Ctime}, State1), - ?assertEqual(ok, file:delete(TestLog)), - State2 = writeLog(State0, os:timestamp(), ?DEBUG, "hello world"), - %% assert file has changed - ExpState1 = #state{fileName = TestLog, level = ?DEBUG, fd = FD, inode = Inode, ctime = Ctime}, - ?assertNotEqual(ExpState1, State2), - ?assertMatch(#state{fileName = TestLog, level = ?DEBUG}, State2), - ?assertEqual(ok, file:rename(TestLog, TestLog ++ ".1")), - State3 = writeLog(State2, os:timestamp(), ?DEBUG, "hello world"), - %% assert file has changed - ?assertNotEqual(State3, State2), - ?assertMatch(#state{fileName = TestLog, level = ?DEBUG}, State3), - ok - end - end} - end, - fun(DefaultState = #state{fileName = TestLog, syncSize = SyncSize, syncInterval = SyncInterval, rotator = Rotator}) -> - {"Internal rotation and delayed write", - fun() -> - TestLog0 = TestLog ++ ".0", - CheckInterval = 3000, % 3 sec - RotationSize = 15, - PreviousCheck = os:timestamp(), - - {ok, FD, Inode, Ctime, _Size} = Rotator:openLogfile(TestLog, {SyncSize, SyncInterval}), - State0 = DefaultState#state{ - fd = FD, inode = Inode, ctime = Ctime, size = RotationSize, - checkInterval = CheckInterval, lastCheck = PreviousCheck}, - - %% new message within check interval with sync_on level - Msg1Timestamp = add_secs(PreviousCheck, 1), - State1 = writeLog(State0, Msg1Timestamp, ?ERROR, "big big message 1"), - ?assertEqual(State0, State1), - - %% new message within check interval under sync_on level - %% not written to disk yet - Msg2Timestamp = add_secs(PreviousCheck, 2), - State2 = writeLog(State1, Msg2Timestamp, ?DEBUG, "buffered message 2"), - ?assertEqual(State0, State2), - - % Note: we must ensure at least one second (DEFAULT_SYNC_INTERVAL) has passed - % for message 1 and 2 to be written to disk - ElapsedMs = timer:now_diff(os:timestamp(), PreviousCheck) div 1000, - case ElapsedMs > SyncInterval of - true -> - ok; - _ -> - S = SyncInterval - ElapsedMs, - timer:sleep(S) - end, - - %% although file size is big enough... - {ok, FInfo} = file:read_file_info(TestLog, [raw]), - ?assert(RotationSize < FInfo#file_info.size), - %% ...no rotation yet - ?assertEqual(PreviousCheck, State2#state.lastCheck), - ?assertNot(filelib:is_regular(TestLog0)), - - %% new message after check interval - Msg3Timestamp = add_secs(PreviousCheck, 4), - _State3 = writeLog(State2, Msg3Timestamp, ?DEBUG, "message 3"), - - %% rotation happened - ?assert(filelib:is_regular(TestLog0)), - - {ok, Bin1} = file:read_file(TestLog0), - {ok, Bin2} = file:read_file(TestLog), - %% message 1-2 written to file - ?assertEqual(<<"big big message 1buffered message 2">>, Bin1), - %% message 3 buffered, not yet written to file - ?assertEqual(<<"">>, Bin2), - ok - end} - end - ]}. - -add_secs({Mega, Secs, Micro}, Add) -> - NewSecs = Secs + Add, - {Mega + NewSecs div 10000000, NewSecs rem 10000000, Micro}. - -filesystem_test_() -> - {foreach, - fun() -> - ok = error_logger:tty(false), - ok = rumUtil:safe_application_load(lager), - ok = application:set_env(lager, handlers, [{lager_test_backend, info}]), - ok = application:set_env(lager, errLoggerRedirect, false), - ok = application:set_env(lager, asyncThreshold, undefined), - {ok, _TestDir} = rumUtil:create_test_dir(), - ok = eRum:start(), - %% race condition where lager logs its own start up - %% makes several tests fail. See test/lager_test_backend - %% around line 800 for more information. - ok = timer:sleep(5), - ok = lager_test_backend:flush() - end, - fun(_) -> - ok = application:stop(lager), - ok = application:stop(goldrush), - ok = error_logger:tty(true), - ok = rumUtil:delete_test_dir() - end, [ - {"under normal circumstances, file should be opened", - fun() -> - {ok, TestDir} = rumUtil:get_test_dir(), - TestLog = filename:join(TestDir, "test.log"), - - gen_event:add_handler(rumEvent, lager_file_backend, - [{TestLog, info}, {lager_default_formatter}]), - eRum:log(error, self(), "Test message"), - {ok, Bin} = file:read_file(TestLog), - Pid = pid_to_list(self()), - ?assertMatch([_, _, "[error]", Pid, "Test message\n"], - re:split(Bin, " ", [{return, list}, {parts, 5}])) - end}, - {"don't choke on unicode", - fun() -> - {ok, TestDir} = rumUtil:get_test_dir(), - TestLog = filename:join(TestDir, "test.log"), - - gen_event:add_handler(rumEvent, lager_file_backend, - [{TestLog, info}, {lager_default_formatter}]), - eRum:log(error, self(), "~ts", [[20013, 25991, 27979, 35797]]), - {ok, Bin} = file:read_file(TestLog), - Pid = pid_to_list(self()), - ?assertMatch([_, _, "[error]", Pid, - [228, 184, 173, 230, 150, 135, 230, 181, 139, 232, 175, 149, $\n]], - re:split(Bin, " ", [{return, list}, {parts, 5}])) - end}, - {"don't choke on latin-1", - fun() -> - {ok, TestDir} = rumUtil:get_test_dir(), - TestLog = filename:join(TestDir, "test.log"), - - %% XXX if this test fails, check that this file is encoded latin-1, not utf-8! - gen_event:add_handler(rumEvent, lager_file_backend, - [{TestLog, info}, {lager_default_formatter}]), - eRum:log(error, self(), "~ts", [[76, 198, 221, 206, 78, $-, 239]]), - {ok, Bin} = file:read_file(TestLog), - Pid = pid_to_list(self()), - Res = re:split(Bin, " ", [{return, list}, {parts, 5}]), - ?assertMatch([_, _, "[error]", Pid, - [76, 195, 134, 195, 157, 195, 142, 78, 45, 195, 175, $\n]], Res) - end}, - {"file can't be opened on startup triggers an error message", - fun() -> - {ok, TestDir} = rumUtil:get_test_dir(), - TestLog = filename:join(TestDir, "test.log"), - ?assertEqual(ok, rumUtil:safe_write_file(TestLog, [])), - - {ok, FInfo0} = file:read_file_info(TestLog, [raw]), - FInfo1 = FInfo0#file_info{mode = 0}, - ?assertEqual(ok, file:write_file_info(TestLog, FInfo1)), - - gen_event:add_handler(rumEvent, lager_file_backend, - {TestLog, info, 10 * 1024 * 1024, "$D0", 5}), - - % Note: required on win32, do this early to prevent subsequent failures - % from preventing cleanup - ?assertEqual(ok, file:write_file_info(TestLog, FInfo0)), - - ?assertEqual(1, lager_test_backend:count()), - {_Level, _Time, Message, _Metadata} = lager_test_backend:pop(), - MessageFlat = lists:flatten(Message), - ?assertEqual( - "Failed to open log file " ++ TestLog ++ " with error permission denied", - MessageFlat) - end}, - {"file that becomes unavailable at runtime should trigger an error message", - fun() -> - case os:type() of - {win32, _} -> - % Note: test is skipped on win32 due to the fact that a file can't be - % deleted or renamed while a process has an open file handle referencing it - ok; - _ -> - {ok, TestDir} = rumUtil:get_test_dir(), - TestLog = filename:join(TestDir, "test.log"), - - gen_event:add_handler(rumEvent, lager_file_backend, - [{file, TestLog}, {level, info}, {check_interval, 0}]), - ?assertEqual(0, lager_test_backend:count()), - eRum:log(error, self(), "Test message"), - ?assertEqual(1, lager_test_backend:count()), - ?assertEqual(ok, file:delete(TestLog)), - ?assertEqual(ok, rumUtil:safe_write_file(TestLog, "")), - {ok, FInfo0} = file:read_file_info(TestLog, [raw]), - FInfo1 = FInfo0#file_info{mode = 0}, - ?assertEqual(ok, file:write_file_info(TestLog, FInfo1)), - eRum:log(error, self(), "Test message"), - lager_test_backend:pop(), - lager_test_backend:pop(), - {_Level, _Time, Message, _Metadata} = lager_test_backend:pop(), - ?assertEqual( - "Failed to reopen log file " ++ TestLog ++ " with error permission denied", - lists:flatten(Message)) - end - end}, - {"unavailable files that are fixed at runtime should start having log messages written", - fun() -> - {ok, TestDir} = rumUtil:get_test_dir(), - TestLog = filename:join(TestDir, "test.log"), - ?assertEqual(ok, rumUtil:safe_write_file(TestLog, [])), - - {ok, FInfo} = file:read_file_info(TestLog, [raw]), - OldPerms = FInfo#file_info.mode, - ?assertEqual(ok, file:write_file_info(TestLog, FInfo#file_info{mode = 0})), - gen_event:add_handler(rumEvent, lager_file_backend, - [{file, TestLog}, {check_interval, 0}]), - ?assertEqual(1, lager_test_backend:count()), - {_Level, _Time, Message, _Metadata} = lager_test_backend:pop(), - ?assertEqual( - "Failed to open log file " ++ TestLog ++ " with error permission denied", - lists:flatten(Message)), - ?assertEqual(ok, file:write_file_info(TestLog, FInfo#file_info{mode = OldPerms})), - eRum:log(error, self(), "Test message"), - {ok, Bin} = file:read_file(TestLog), - Pid = pid_to_list(self()), - ?assertMatch([_, _, "[error]", Pid, "Test message\n"], - re:split(Bin, " ", [{return, list}, {parts, 5}])) - end}, - {"external logfile rotation/deletion should be handled", - fun() -> - case os:type() of - {win32, _} -> - % Note: test is skipped on win32 due to the fact that a file can't be deleted or renamed - % while a process has an open file handle referencing it - ok; - _ -> - {ok, TestDir} = rumUtil:get_test_dir(), - TestLog = filename:join(TestDir, "test.log"), - TestLog0 = TestLog ++ ".0", - - gen_event:add_handler(rumEvent, lager_file_backend, - [{file, TestLog}, {level, info}, {check_interval, 0}]), - ?assertEqual(0, lager_test_backend:count()), - eRum:log(error, self(), "Test message1"), - ?assertEqual(1, lager_test_backend:count()), - ?assertEqual(ok, file:delete(TestLog)), - ?assertEqual(ok, rumUtil:safe_write_file(TestLog, "")), - eRum:log(error, self(), "Test message2"), - ?assertEqual(2, lager_test_backend:count()), - {ok, Bin} = file:read_file(TestLog), - Pid = pid_to_list(self()), - ?assertMatch([_, _, "[error]", Pid, "Test message2\n"], - re:split(Bin, " ", [{return, list}, {parts, 5}])), - ?assertEqual(ok, file:rename(TestLog, TestLog0)), - eRum:log(error, self(), "Test message3"), - ?assertEqual(3, lager_test_backend:count()), - {ok, Bin2} = file:read_file(TestLog), - ?assertMatch([_, _, "[error]", Pid, "Test message3\n"], - re:split(Bin2, " ", [{return, list}, {parts, 5}])) - end - end}, - {"internal size rotation should work", - fun() -> - {ok, TestDir} = rumUtil:get_test_dir(), - TestLog = filename:join(TestDir, "test.log"), - TestLog0 = TestLog ++ ".0", - - gen_event:add_handler(rumEvent, lager_file_backend, - [{file, TestLog}, {level, info}, {check_interval, 0}, {size, 10}]), - eRum:log(error, self(), "Test message1"), - eRum:log(error, self(), "Test message1"), - ?assert(filelib:is_regular(TestLog0)) - end}, - {"internal time rotation should work", - fun() -> - {ok, TestDir} = rumUtil:get_test_dir(), - TestLog = filename:join(TestDir, "test.log"), - TestLog0 = TestLog ++ ".0", - - gen_event:add_handler(rumEvent, lager_file_backend, - [{file, TestLog}, {level, info}, {check_interval, 1000}]), - eRum:log(error, self(), "Test message1"), - eRum:log(error, self(), "Test message1"), - whereis(rumEvent) ! {mRotate, TestLog}, - eRum:log(error, self(), "Test message1"), - ?assert(filelib:is_regular(TestLog0)) - end}, - {"rotation call should work", - fun() -> - {ok, TestDir} = rumUtil:get_test_dir(), - TestLog = filename:join(TestDir, "test.log"), - TestLog0 = TestLog ++ ".0", - - gen_event:add_handler(rumEvent, {lager_file_backend, TestLog}, - [{file, TestLog}, {level, info}, {check_interval, 1000}]), - eRum:log(error, self(), "Test message1"), - eRum:log(error, self(), "Test message1"), - gen_event:call(rumEvent, {lager_file_backend, TestLog}, mRotate, infinity), - eRum:log(error, self(), "Test message1"), - ?assert(filelib:is_regular(TestLog0)) - end}, - {"sync_on option should work", - fun() -> - {ok, TestDir} = rumUtil:get_test_dir(), - TestLog = filename:join(TestDir, "test.log"), - - gen_event:add_handler(rumEvent, lager_file_backend, [{file, TestLog}, - {level, info}, {sync_on, "=info"}, {check_interval, 5000}, {sync_interval, 5000}]), - eRum:log(error, self(), "Test message1"), - eRum:log(error, self(), "Test message1"), - ?assertEqual({ok, <<>>}, file:read_file(TestLog)), - eRum:log(info, self(), "Test message1"), - {ok, Bin} = file:read_file(TestLog), - ?assert(<<>> /= Bin) - end}, - {"sync_on none option should work (also tests sync_interval)", - fun() -> - {ok, TestDir} = rumUtil:get_test_dir(), - TestLog = filename:join(TestDir, "test.log"), - - gen_event:add_handler(rumEvent, lager_file_backend, [{file, TestLog}, - {level, info}, {sync_on, "none"}, {check_interval, 5000}, {sync_interval, 1000}]), - eRum:log(error, self(), "Test message1"), - eRum:log(error, self(), "Test message1"), - ?assertEqual({ok, <<>>}, file:read_file(TestLog)), - eRum:log(info, self(), "Test message1"), - ?assertEqual({ok, <<>>}, file:read_file(TestLog)), - timer:sleep(2000), - {ok, Bin} = file:read_file(TestLog), - ?assert(<<>> /= Bin) - end}, - {"sync_size option should work", - fun() -> - {ok, TestDir} = rumUtil:get_test_dir(), - TestLog = filename:join(TestDir, "test.log"), - - gen_event:add_handler(rumEvent, lager_file_backend, [{file, TestLog}, {level, info}, - {sync_on, "none"}, {check_interval, 5001}, {sync_size, 640}, {sync_interval, 5001}]), - eRum:log(error, self(), "Test messageis64bytes"), - eRum:log(error, self(), "Test messageis64bytes"), - eRum:log(error, self(), "Test messageis64bytes"), - eRum:log(error, self(), "Test messageis64bytes"), - eRum:log(error, self(), "Test messageis64bytes"), - ?assertEqual({ok, <<>>}, file:read_file(TestLog)), - eRum:log(error, self(), "Test messageis64bytes"), - eRum:log(error, self(), "Test messageis64bytes"), - eRum:log(error, self(), "Test messageis64bytes"), - eRum:log(error, self(), "Test messageis64bytes"), - ?assertEqual({ok, <<>>}, file:read_file(TestLog)), - %% now we've written enough bytes - eRum:log(error, self(), "Test messageis64bytes"), - {ok, Bin} = file:read_file(TestLog), - ?assert(<<>> /= Bin) - end}, - {"runtime level changes", - fun() -> - {ok, TestDir} = rumUtil:get_test_dir(), - TestLog = filename:join(TestDir, "test.log"), - - gen_event:add_handler(rumEvent, {lager_file_backend, TestLog}, {TestLog, info}), - ?assertEqual(0, lager_test_backend:count()), - eRum:log(info, self(), "Test message1"), - eRum:log(error, self(), "Test message2"), - {ok, Bin} = file:read_file(TestLog), - Lines = length(re:split(Bin, "\n", [{return, list}, trim])), - ?assertEqual(Lines, 2), - ?assertEqual(ok, eRum:setLogLevel(lager_file_backend, TestLog, warning)), - eRum:log(info, self(), "Test message3"), %% this won't get logged - eRum:log(error, self(), "Test message4"), - {ok, Bin2} = file:read_file(TestLog), - Lines2 = length(re:split(Bin2, "\n", [{return, list}, trim])), - ?assertEqual(Lines2, 3) - end}, - {"invalid runtime level changes", - fun() -> - {ok, TestDir} = rumUtil:get_test_dir(), - TestLog = filename:join(TestDir, "test.log"), - TestLog3 = filename:join(TestDir, "test3.log"), - - gen_event:add_handler(rumEvent, lager_file_backend, - [{TestLog, info, 10 * 1024 * 1024, "$D0", 5}, {lager_default_formatter}]), - gen_event:add_handler(rumEvent, lager_file_backend, {TestLog3, info}), - ?assertEqual({error, bad_module}, eRum:setLogLevel(lager_file_backend, TestLog, warning)) - end}, - {"tracing should work", - fun() -> - {ok, TestDir} = rumUtil:get_test_dir(), - TestLog = filename:join(TestDir, "test.log"), - - gen_event:add_handler(rumEvent, lager_file_backend, {TestLog, critical}), - eRum:error("Test message"), - ?assertEqual({ok, <<>>}, file:read_file(TestLog)), - {Level, _} = rumConfig:get({rumEvent, loglevel}), - rumConfig:set({rumEvent, loglevel}, {Level, - [{[{module, ?MODULE}], ?DEBUG, {lager_file_backend, TestLog}}]}), - eRum:error("Test message"), - timer:sleep(1000), - {ok, Bin} = file:read_file(TestLog), - ?assertMatch([_, _, "[error]", _, "Test message\n"], - re:split(Bin, " ", [{return, list}, {parts, 5}])) - end}, - {"tracing should not duplicate messages", - fun() -> - case os:type() of - {win32, _} -> - % Note: test is skipped on win32 due to the fact that a file can't be - % deleted or renamed while a process has an open file handle referencing it - ok; - _ -> - {ok, TestDir} = rumUtil:get_test_dir(), - TestLog = filename:join(TestDir, "test.log"), - - gen_event:add_handler(rumEvent, lager_file_backend, - [{file, TestLog}, {level, critical}, {check_interval, always}]), - timer:sleep(500), - eRum:critical("Test message"), - {ok, Bin1} = file:read_file(TestLog), - ?assertMatch([_, _, "[critical]", _, "Test message\n"], - re:split(Bin1, " ", [{return, list}, {parts, 5}])), - ?assertEqual(ok, file:delete(TestLog)), - {Level, _} = rumConfig:get({rumEvent, loglevel}), - rumConfig:set({rumEvent, loglevel}, - {Level, [{[{module, ?MODULE}], ?DEBUG, {lager_file_backend, TestLog}}]}), - eRum:critical("Test message"), - {ok, Bin2} = file:read_file(TestLog), - ?assertMatch([_, _, "[critical]", _, "Test message\n"], - re:split(Bin2, " ", [{return, list}, {parts, 5}])), - ?assertEqual(ok, file:delete(TestLog)), - eRum:error("Test message"), - {ok, Bin3} = file:read_file(TestLog), - ?assertMatch([_, _, "[error]", _, "Test message\n"], - re:split(Bin3, " ", [{return, list}, {parts, 5}])) - end - end}, - {"tracing to a dedicated file should work", - fun() -> - {ok, TestDir} = rumUtil:get_test_dir(), - TestLog = filename:join(TestDir, "foo.log"), - - {ok, _} = eRum:trace_file(TestLog, [{module, ?MODULE}]), - eRum:error("Test message"), - %% not eligible for trace - eRum:log(error, self(), "Test message"), - {ok, Bin3} = file:read_file(TestLog), - ?assertMatch([_, _, "[error]", _, "Test message\n"], - re:split(Bin3, " ", [{return, list}, {parts, 5}])) - end}, - {"tracing to a dedicated file should work even if root_log is set", - fun() -> - {ok, TestDir} = rumUtil:get_test_dir(), - LogName = "foo.log", - LogPath = filename:join(TestDir, LogName), - - application:set_env(lager, logRoot, TestDir), - {ok, _} = eRum:trace_file(LogName, [{module, ?MODULE}]), - eRum:error("Test message"), - %% not eligible for trace - eRum:log(error, self(), "Test message"), - {ok, Bin3} = file:read_file(LogPath), - application:unset_env(lager, logRoot), - ?assertMatch([_, _, "[error]", _, "Test message\n"], - re:split(Bin3, " ", [{return, list}, {parts, 5}])) - end}, - {"tracing with options should work", - fun() -> - {ok, TestDir} = rumUtil:get_test_dir(), - TestLog = filename:join(TestDir, "foo.log"), - TestLog0 = TestLog ++ ".0", - - {ok, _} = eRum:trace_file(TestLog, [{module, ?MODULE}], - [{size, 20}, {check_interval, 1}]), - eRum:error("Test message"), - ?assertNot(filelib:is_regular(TestLog0)), - %% rotation is sensitive to intervals between - %% writes so we sleep to exceed the 1 - %% millisecond interval specified by - %% check_interval above - timer:sleep(2), - eRum:error("Test message"), - timer:sleep(10), - ?assert(filelib:is_regular(TestLog0)) - end}, - {"no silent hwm drops", - fun() -> - MsgCount = 15, - {ok, TestDir} = rumUtil:get_test_dir(), - TestLog = filename:join(TestDir, "test.log"), - gen_event:add_handler(rumEvent, lager_file_backend, [{file, TestLog}, {level, info}, - {high_water_mark, 5}, {flushQueue, false}, {sync_on, "=warning"}]), - {_, _, MS} = os:timestamp(), - % start close to the beginning of a new second - ?assertEqual(ok, timer:sleep((1000000 - MS) div 1000 + 1)), - [eRum:log(info, self(), "Foo ~p", [K]) || K <- lists:seq(1, MsgCount)], - ?assertEqual(MsgCount, lager_test_backend:count()), - % Note: bumped from 1000 to 1250 to ensure delayed write flushes to disk - ?assertEqual(ok, timer:sleep(1250)), - {ok, Bin} = file:read_file(TestLog), - Last = lists:last(re:split(Bin, "\n", [{return, list}, trim])), - ?assertMatch([_, _, _, _, "lager_file_backend dropped 10 messages in the last second that exceeded the limit of 5 messages/sec"], - re:split(Last, " ", [{return, list}, {parts, 5}])) - end} - ]}. - -trace_files_test_() -> - {foreach, - fun() -> - {ok, TestDir} = rumUtil:get_test_dir(), - Log = filename:join(TestDir, "test.log"), - Debug = filename:join(TestDir, "debug.log"), - Events = filename:join(TestDir, "events.log"), - - ok = error_logger:tty(false), - ok = rumUtil:safe_application_load(lager), - ok = application:set_env(lager, handlers, [ - {lager_file_backend, [ - {file, Log}, - {level, error}, - {formatter, lager_default_formatter}, - {formatter_config, [message, "\n"]} - ]} - ]), - ok = application:set_env(lager, traces, [ - { % get default level of debug - {lager_file_backend, Debug}, [{module, ?MODULE}] - }, - { % Handler Filters Level - {lager_file_backend, Events}, [{module, ?MODULE}], notice - } - ]), - ok = application:set_env(lager, asyncThreshold, undefined), - ok = eRum:start(), - {Log, Debug, Events} - end, - fun({_, _, _}) -> - catch ets:delete(lager_config), - ok = application:unset_env(lager, traces), - ok = application:stop(lager), - ok = rumUtil:delete_test_dir(), - ok = error_logger:tty(true) - end, [ - fun({Log, Debug, Events}) -> - {"a trace using file backend set up in configuration should work", - fun() -> - eRum:error("trace test error message"), - eRum:info("info message"), - %% not eligible for trace - eRum:log(error, self(), "Not trace test message"), - {ok, BinInfo} = file:read_file(Events), - ?assertMatch([_, _, "[error]", _, "trace test error message\n"], - re:split(BinInfo, " ", [{return, list}, {parts, 5}])), - ?assert(filelib:is_regular(Log)), - {ok, BinInfo2} = file:read_file(Log), - ?assertMatch(["trace test error message", "Not trace test message\n"], - re:split(BinInfo2, "\n", [{return, list}, {parts, 2}])), - ?assert(filelib:is_regular(Debug)), - %% XXX Aughhhh, wish I could force this to flush somehow... - % should take about 1 second, try for 3 ... - ?assertEqual(2, count_lines_until(2, add_secs(os:timestamp(), 3), Debug, 0)) - end} - end - ]}. - -count_lines_until(Lines, Timeout, File, Last) -> - case timer:now_diff(Timeout, os:timestamp()) > 0 of - true -> - timer:sleep(333), - {ok, Bin} = file:read_file(File), - case erlang:length(re:split(Bin, "\n", [{return, list}, trim])) of - Count when Count < Lines -> - count_lines_until(Lines, Timeout, File, Count); - Count -> - Count - end; - _ -> - Last - end. - -formatting_test_() -> - {foreach, - fun() -> - {ok, TestDir} = rumUtil:get_test_dir(), - Log1 = filename:join(TestDir, "test.log"), - Log2 = filename:join(TestDir, "test2.log"), - ?assertEqual(ok, rumUtil:safe_write_file(Log1, [])), - ?assertEqual(ok, rumUtil:safe_write_file(Log2, [])), - ok = error_logger:tty(false), - ok = rumUtil:safe_application_load(lager), - ok = application:set_env(lager, handlers, [{lager_test_backend, info}]), - ok = application:set_env(lager, errLoggerRedirect, false), - ok = eRum:start(), - %% same race condition issue - ok = timer:sleep(5), - {ok, Log1, Log2} - end, - fun({ok, _, _}) -> - ok = application:stop(lager), - ok = application:stop(goldrush), - ok = rumUtil:delete_test_dir(), - ok = error_logger:tty(true) - end, [ - fun({ok, Log1, Log2}) -> - {"Should have two log files, the second prefixed with 2>", - fun() -> - gen_event:add_handler(rumEvent, lager_file_backend, - [{Log1, debug}, {lager_default_formatter, ["[", severity, "] ", message, "\n"]}]), - gen_event:add_handler(rumEvent, lager_file_backend, - [{Log2, debug}, {lager_default_formatter, ["2> [", severity, "] ", message, "\n"]}]), - eRum:log(error, self(), "Test message"), - ?assertMatch({ok, <<"[error] Test message\n">>}, file:read_file(Log1)), - ?assertMatch({ok, <<"2> [error] Test message\n">>}, file:read_file(Log2)) - end} - end - ]}. - -config_validation_test_() -> - [ - {"missing file", - ?_assertEqual(false, - checkOpts([{level, info}, {size, 10}])) - }, - {"bad level", - ?_assertEqual(false, - checkOpts([{file, "test.log"}, {level, blah}, {size, 10}])) - }, - {"bad size", - ?_assertEqual(false, - checkOpts([{file, "test.log"}, {size, infinity}])) - }, - {"bad count", - ?_assertEqual(false, - checkOpts([{file, "test.log"}, {count, infinity}])) - }, - {"bad high water mark", - ?_assertEqual(false, - checkOpts([{file, "test.log"}, {high_water_mark, infinity}])) - }, - {"bad date", - ?_assertEqual(false, - checkOpts([{file, "test.log"}, {date, "midnight"}])) - }, - {"blank date is ok", - ?_assertMatch([_ | _], - checkOpts([{file, "test.log"}, {date, ""}])) - }, - {"bad sync_interval", - ?_assertEqual(false, - checkOpts([{file, "test.log"}, {sync_interval, infinity}])) - }, - {"bad sync_size", - ?_assertEqual(false, - checkOpts([{file, "test.log"}, {sync_size, infinity}])) - }, - {"bad check_interval", - ?_assertEqual(false, - checkOpts([{file, "test.log"}, {check_interval, infinity}])) - }, - {"bad sync_on level", - ?_assertEqual(false, - checkOpts([{file, "test.log"}, {sync_on, infinity}])) - }, - {"bad formatter module", - ?_assertEqual(false, - checkOpts([{file, "test.log"}, {formatter, "io:format"}])) - }, - {"bad formatter config", - ?_assertEqual(false, - checkOpts([{file, "test.log"}, {formatter_config, blah}])) - }, - {"unknown option", - ?_assertEqual(false, - checkOpts([{file, "test.log"}, {rhubarb, spicy}])) - } - ]. - --endif. diff --git a/src/crashLog/rumCrashLog.erl b/src/crashLog/rumCrashLog.erl index 5809818..6170b83 100644 --- a/src/crashLog/rumCrashLog.erl +++ b/src/crashLog/rumCrashLog.erl @@ -11,11 +11,6 @@ -include("rumDef.hrl"). --ifdef(TEST). --include_lib("eunit/include/eunit.hrl"). --include_lib("kernel/include/file.hrl"). --endif. - -export([ start/6 , start_link/6 @@ -191,146 +186,3 @@ writeLog(Event, #state{fileName = FileName, fd = FD, inode = Inode, ctime = Ctim end end. - --ifdef(TEST). - -filesystem_test_() -> - {foreach, - fun() -> - {ok, TestDir} = rumUtil:create_test_dir(), - CrashLog = filename:join(TestDir, "crash_test.log"), - ok = rumUtil:safe_write_file(CrashLog, []), - ok = error_logger:tty(false), - ok = rumUtil:safe_application_load(lager), - ok = application:set_env(lager, handlers, [{lager_test_backend, info}]), - ok = application:set_env(lager, errLoggerRedirect, true), - ok = application:unset_env(lager, crash_log), - ok = eRum:start(), - ok = timer:sleep(1000), - ok = lager_test_backend:flush(), - CrashLog - end, - fun(_CrashLog) -> - case whereis(lager_crash_log) of - P when is_pid(P) -> - gen_server:stop(P); - _ -> - ok - end, - ok = application:stop(lager), - ok = application:stop(goldrush), - ok = rumUtil:delete_test_dir(), - ok = error_logger:tty(true) - end, [ - fun(CrashLog) -> - {"under normal circumstances, file should be opened", - fun() -> - {ok, _} = ?MODULE:start_link(CrashLog, 65535, 0, undefined, 0, lager_rotator_default), - _ = gen_event:which_handlers(error_logger), - sync_error_logger:error_msg("Test message\n"), - {ok, Bin} = file:read_file(CrashLog), - ?assertMatch([_, "Test message\n"], re:split(Bin, "\n", [{return, list}, {parts, 2}])) - end} - end, - fun(CrashLog) -> - {"file can't be opened on startup triggers an error message", - fun() -> - {ok, FInfo0} = file:read_file_info(CrashLog, [raw]), - FInfo1 = FInfo0#file_info{mode = 0}, - ?assertEqual(ok, file:write_file_info(CrashLog, FInfo1)), - {ok, _} = ?MODULE:start_link(CrashLog, 65535, 0, undefined, 0, lager_rotator_default), - % Note: required on win32, do this early to prevent subsequent failures - % from preventing cleanup - ?assertEqual(ok, file:write_file_info(CrashLog, FInfo0)), - ?assertEqual(1, lager_test_backend:count()), - {_Level, _Time, Message, _Metadata} = lager_test_backend:pop(), - ?assertEqual( - "Failed to open crash log file " ++ CrashLog ++ " with error: permission denied", - lists:flatten(Message)) - end} - end, - fun(CrashLog) -> - {"file that becomes unavailable at runtime should trigger an error message", - fun() -> - case os:type() of - {win32, _} -> - % Note: test is skipped on win32 due to the fact that a file can't be deleted or renamed - % while a process has an open file handle referencing it - ok; - _ -> - {ok, _} = ?MODULE:start_link(CrashLog, 65535, 0, undefined, 0, lager_rotator_default), - ?assertEqual(0, lager_test_backend:count()), - sync_error_logger:error_msg("Test message\n"), - _ = gen_event:which_handlers(error_logger), - ?assertEqual(1, lager_test_backend:count()), - ?assertEqual(ok, file:delete(CrashLog)), - ?assertEqual(ok, rumUtil:safe_write_file(CrashLog, "")), - {ok, FInfo0} = file:read_file_info(CrashLog, [raw]), - FInfo1 = FInfo0#file_info{mode = 0}, - ?assertEqual(ok, file:write_file_info(CrashLog, FInfo1)), - sync_error_logger:error_msg("Test message\n"), - _ = gen_event:which_handlers(error_logger), - % Note: required on win32, do this early to prevent subsequent failures - % from preventing cleanup - ?assertEqual(ok, file:write_file_info(CrashLog, FInfo0)), - ?assertEqual(3, lager_test_backend:count()), - lager_test_backend:pop(), - {_Level, _Time, Message, _Metadata} = lager_test_backend:pop(), - ?assertEqual( - "Failed to reopen crash log " ++ CrashLog ++ " with error: permission denied", - lists:flatten(Message)) - end - end} - end, - fun(CrashLog) -> - {"unavailable files that are fixed at runtime should start having log messages written", - fun() -> - {ok, FInfo} = file:read_file_info(CrashLog, [raw]), - OldPerms = FInfo#file_info.mode, - file:write_file_info(CrashLog, FInfo#file_info{mode = 0}), - {ok, _} = ?MODULE:start_link(CrashLog, 65535, 0, undefined, 0, lager_rotator_default), - ?assertEqual(1, lager_test_backend:count()), - {_Level, _Time, Message, _Metadata} = lager_test_backend:pop(), - ?assertEqual( - "Failed to open crash log file " ++ CrashLog ++ " with error: permission denied", - lists:flatten(Message)), - file:write_file_info(CrashLog, FInfo#file_info{mode = OldPerms}), - sync_error_logger:error_msg("Test message~n"), - _ = gen_event:which_handlers(error_logger), - {ok, Bin} = file:read_file(CrashLog), - ?assertMatch([_, "Test message\n"], re:split(Bin, "\n", [{return, list}, {parts, 2}])) - end} - end, - fun(CrashLog) -> - {"external logfile rotation/deletion should be handled", - fun() -> - case os:type() of - {win32, _} -> - % Note: test is skipped on win32 due to the fact that a file can't be deleted or renamed - % while a process has an open file handle referencing it - ok; - _ -> - {ok, _} = ?MODULE:start_link(CrashLog, 65535, 0, undefined, 0, lager_rotator_default), - ?assertEqual(0, lager_test_backend:count()), - sync_error_logger:error_msg("Test message~n"), - _ = gen_event:which_handlers(error_logger), - {ok, Bin} = file:read_file(CrashLog), - ?assertMatch([_, "Test message\n"], re:split(Bin, "\n", [{return, list}, {parts, 2}])), - ?assertEqual(ok, file:delete(CrashLog)), - ?assertEqual(ok, rumUtil:safe_write_file(CrashLog, "")), - sync_error_logger:error_msg("Test message1~n"), - _ = gen_event:which_handlers(error_logger), - {ok, Bin1} = file:read_file(CrashLog), - ?assertMatch([_, "Test message1\n"], re:split(Bin1, "\n", [{return, list}, {parts, 2}])), - file:rename(CrashLog, CrashLog ++ ".0"), - sync_error_logger:error_msg("Test message2~n"), - _ = gen_event:which_handlers(error_logger), - {ok, Bin2} = file:read_file(CrashLog), - ?assertMatch([_, "Test message2\n"], re:split(Bin2, "\n", [{return, list}, {parts, 2}])) - end - end} - end - ]}. - --endif. - diff --git a/src/eRum.erl b/src/eRum.erl index 9a5d414..69789ce 100644 --- a/src/eRum.erl +++ b/src/eRum.erl @@ -1,6 +1,8 @@ -module(eRum). -include("rumDef.hrl"). +-include("rumMsg.hrl"). +-include("rumCom.hrl"). -ifdef(TEST). -include_lib("eunit/include/eunit.hrl"). @@ -13,16 +15,14 @@ , stop/0 %% log and log param - , log/3 , log/4 , log/5 , log_unsafe/4 - , do_log/9 - , do_log/10 - , do_log_unsafe/10 - , dispatch_log/5 - , dispatch_log/7 - , dispatch_log/9 + , do_log/15 + , do_log/16 + , do_log_unsafe/16 + , dispatch_log/11 + , dispatch_log/13 , safe_format/3 , safe_format_chop/3 , unsafe_format/2 @@ -86,13 +86,6 @@ start() -> stop() -> application:stop(eRum). -%% @doc Manually log a message into eRum without using the parse transform. --spec log(rumAtomLevel(), pid() | atom() | [tuple(), ...], list()) -> ok | {error, lager_not_running}. -log(Level, Pid, Message) when is_pid(Pid); is_atom(Pid) -> - dispatch_log(Level, [{pid, Pid}], Message, [], ?RumDefTruncation); -log(Level, Metadata, Message) when is_list(Metadata) -> - dispatch_log(Level, Metadata, Message, [], ?RumDefTruncation). - %% @doc Manually log a message into eRum without using the parse transform. -spec log(rumAtomLevel(), pid() | atom() | [tuple(), ...], string(), list()) -> ok | {error, lager_not_running}. log(Level, Pid, Format, Args) when is_pid(Pid); is_atom(Pid) -> @@ -113,28 +106,28 @@ log_unsafe(Level, Metadata, Format, Args) when is_list(Metadata) -> -spec dispatch_log(atom(), rumAtomLevel(), list(), string(), list() | none, pos_integer(), safe | unsafe) -> ok | {error, lager_not_running} | {error, {sink_not_configured, atom()}}. %% this is the same check that the parse transform bakes into the module at compile time %% see rumTransform (lines 173-216) -dispatch_log(Sink, Severity, Metadata, Format, Args, Size, Safety) when is_atom(Severity) -> +dispatch_log(Sink, Severity, Pid, Node, Module, Function, File, Line, Metadata, Format, Args, Size, Safety) when is_atom(Severity) -> SeverityAsInt = rumUtil:levelToNum(Severity), case {whereis(Sink), whereis(?RumDefSink), rumConfig:get({Sink, loglevel}, {?LOG_NONE, []})} of {undefined, undefined, _} -> {error, lager_not_running}; {undefined, _LagerEventPid0, _} -> {error, {sink_not_configured, Sink}}; {SinkPid, _LagerEventPid1, {Level, Traces}} when Safety =:= safe andalso ((Level band SeverityAsInt) /= 0 orelse Traces /= []) -> - do_log(Severity, Metadata, Format, Args, Size, SeverityAsInt, Level, Traces, Sink, SinkPid); + do_log(Severity, Pid, Node, Module, Function, File, Line, Metadata, Format, Args, Size, SeverityAsInt, Level, Traces, Sink, SinkPid); {SinkPid, _LagerEventPid1, {Level, Traces}} when Safety =:= unsafe andalso ((Level band SeverityAsInt) /= 0 orelse Traces /= []) -> - do_log_unsafe(Severity, Metadata, Format, Args, Size, SeverityAsInt, Level, Traces, Sink, SinkPid); + do_log_unsafe(Severity, Pid, Node, Module, Function, File, Line, Metadata, Format, Args, Size, SeverityAsInt, Level, Traces, Sink, SinkPid); _ -> ok end. %% 向后兼容使用eRum 2.x编译的梁 -do_log(Severity, Metadata, Format, Args, Size, SeverityAsInt, LevelThreshold, TraceFilters, SinkPid) -> - do_log(Severity, Metadata, Format, Args, Size, SeverityAsInt, LevelThreshold, TraceFilters, ?RumDefSink, SinkPid). +do_log(Severity, Pid, Node, Module, Function, File, Line, Metadata, Format, Args, Size, SeverityAsInt, LevelThreshold, TraceFilters, SinkPid) -> + do_log(Severity, Pid, Node, Module, Function, File, Line, Metadata, Format, Args, Size, SeverityAsInt, LevelThreshold, TraceFilters, ?RumDefSink, SinkPid). %% @private Should only be called externally from code generated from the parse transform -do_log(Severity, Metadata, Format, Args, Size, SeverityAsInt, LevelThreshold, TraceFilters, Sink, SinkPid) when is_atom(Severity) -> +do_log(Severity, Pid, Node, Module, Function, File, Line, Metadata, Format, Args, Size, SeverityAsInt, LevelThreshold, TraceFilters, Sink, SinkPid) when is_atom(Severity) -> FormatFun = fun() -> safe_format_chop(Format, Args, Size) end, - do_log_impl(Severity, Metadata, Format, Args, SeverityAsInt, LevelThreshold, TraceFilters, Sink, SinkPid, FormatFun). + do_log_impl(Severity, Pid, Node, Module, Function, File, Line, Metadata, Format, Args, SeverityAsInt, LevelThreshold, TraceFilters, Sink, SinkPid, FormatFun). -do_log_impl(Severity, Metadata, Format, Args, SeverityAsInt, LevelThreshold, TraceFilters, Sink, SinkPid, FormatFun) -> +do_log_impl(Severity, Pid, Node, Module, Function, File, Line, Metadata, Format, Args, SeverityAsInt, LevelThreshold, TraceFilters, Sink, SinkPid, FormatFun) -> {Destinations, TraceSinkPid} = case TraceFilters of [] -> @@ -151,8 +144,7 @@ do_log_impl(Severity, Metadata, Format, Args, SeverityAsInt, LevelThreshold, Tra _ -> Format end, - LagerMsg = rumMsg:new(Msg, - Severity, Metadata, Destinations), + LagerMsg = ?newMsg(Severity, Pid, Node, Module, Function, File, Line, Metadata, Destinations, rumUtil:nowMs(), Msg), case rumConfig:get({Sink, async}, false) of true -> gen_emm:info_notify(SinkPid, {mWriteLog, LagerMsg}); @@ -171,18 +163,14 @@ do_log_impl(Severity, Metadata, Format, Args, SeverityAsInt, LevelThreshold, Tra %% @private Should only be called externally from code generated from the parse transform %% Specifically, it would be level ++ `_unsafe' as in `info_unsafe'. -do_log_unsafe(Severity, Metadata, Format, Args, _Size, SeverityAsInt, LevelThreshold, TraceFilters, Sink, SinkPid) when is_atom(Severity) -> +do_log_unsafe(Severity, Pid, Node, Module, Function, File, Line, Metadata, Format, Args, _Size, SeverityAsInt, LevelThreshold, TraceFilters, Sink, SinkPid) when is_atom(Severity) -> FormatFun = fun() -> unsafe_format(Format, Args) end, - do_log_impl(Severity, Metadata, Format, Args, SeverityAsInt, LevelThreshold, TraceFilters, Sink, SinkPid, FormatFun). + do_log_impl(Severity, Pid, Node, Module, Function, File, Line, Metadata, Format, Args, SeverityAsInt, LevelThreshold, TraceFilters, Sink, SinkPid, FormatFun). -%% backwards compatible with beams compiled with lager 1.x -dispatch_log(Severity, _Module, _Function, _Line, _Pid, Metadata, Format, Args, Size) -> - dispatch_log(Severity, Metadata, Format, Args, Size). - %% backwards compatible with beams compiled with lager 2.x -dispatch_log(Severity, Metadata, Format, Args, Size) -> - dispatch_log(?RumDefSink, Severity, Metadata, Format, Args, Size, safe). +dispatch_log(Severity, Pid, Node, Module, Function, File, Line, Metadata, Format, Args, Size) -> + dispatch_log(?RumDefSink, Severity, Pid, Node, Module, Function, File, Line, Metadata, Format, Args, Size, safe). %% @doc Get lager metadata for current process -spec md() -> [{atom(), any()}]. @@ -722,23 +710,4 @@ check_timeout(#trace_func_state_v1{timeout = Timeout, started = Started} = FuncS done; false -> FuncState - end. - --ifdef(TEST). -get_sink_handler_status_ascii_test() -> - File = "C:\\ProgramData\\Directory With Spaces\\lager.log", - validate_status(File). - -get_sink_handler_status_latin_test() -> - File = "C:\\ProgramData\\Tést Directory\\lager.log", - validate_status(File). - -get_sink_handler_status_unicode_test() -> - File = "C:\\ProgramData\\찦차를 타고 온 펲시맨과 쑛다리 똠방각하 (Korean)\\lager.log", - validate_status(File). - -validate_status(File) -> - Handler = {rumBkdFile, File}, - Status = get_sink_handler_status(?RumDefSink, Handler, debug), - ?assertNotEqual(nomatch, string:find(Status, File)). --endif. + end. \ No newline at end of file diff --git a/src/eRum_app.erl b/src/eRum_app.erl index 358a282..5876740 100644 --- a/src/eRum_app.erl +++ b/src/eRum_app.erl @@ -2,6 +2,7 @@ -behaviour(application). +-include("rumCom.hrl"). -include("rumDef.hrl"). -export([ diff --git a/src/errLogger/rumErrLoggerH.erl b/src/errLogger/rumErrLoggerH.erl index c7e45ce..d7365c2 100644 --- a/src/errLogger/rumErrLoggerH.erl +++ b/src/errLogger/rumErrLoggerH.erl @@ -3,10 +3,11 @@ %% 一个error_logger后端，用于将事件重定向到eRum。 %% 错误消息和崩溃日志也可以选择写入崩溃日志。 @see rumCrashLog --include("rumDef.hrl"). - -behaviour(gen_event). +-include("rumDef.hrl"). +-include("eRum.hrl"). + -export([ setHighWater/1 , formatReason/1 @@ -582,172 +583,3 @@ get_value(Key, List, Default) -> supervisorName({local, Name}) -> Name; supervisorName(Name) -> Name. - --ifdef(TEST). --include_lib("eunit/include/eunit.hrl"). - -no_silent_hwm_drops_test_() -> - {timeout, 10000, - [ - fun() -> - error_logger:tty(false), - application:load(lager), - application:set_env(lager, handlers, [{lager_test_backend, warning}]), - application:set_env(lager, errLoggerRedirect, true), - application:set_env(lager, errLoggerHwm, 5), - application:set_env(lager, errLoggerFlushQueue, false), - application:set_env(lager, suppress_supervisor_start_stop, true), - application:set_env(lager, suppress_application_start_stop, true), - application:unset_env(lager, crash_log), - eRum:start(), - try - {_, _, MS} = os:timestamp(), - timer:sleep((1000000 - MS) div 1000 + 1), - % start close to the beginning of a new second - [error_logger:error_msg("Foo ~p~n", [K]) || K <- lists:seq(1, 15)], - wait_for_message("lager_error_logger_h dropped 10 messages in the last second that exceeded the limit of 5 messages/sec", 100, 50), - % and once again - [error_logger:error_msg("Foo1 ~p~n", [K]) || K <- lists:seq(1, 20)], - wait_for_message("lager_error_logger_h dropped 15 messages in the last second that exceeded the limit of 5 messages/sec", 100, 50) - after - application:stop(lager), - application:stop(goldrush), - error_logger:tty(true) - end - end - ] - }. - -shaper_does_not_forward_sup_progress_messages_to_info_level_backend_test_() -> - {timeout, 10000, - [fun() -> - error_logger:tty(false), - application:load(lager), - application:set_env(lager, handlers, [{lager_test_backend, info}]), - application:set_env(lager, errLoggerRedirect, true), - application:set_env(lager, errLoggerHwm, 5), - application:set_env(lager, suppress_supervisor_start_stop, false), - application:set_env(lager, suppress_application_start_stop, false), - application:unset_env(lager, crash_log), - eRum:start(), - try - PidPlaceholder = self(), - SupervisorMsg = - [{supervisor, {PidPlaceholder, rabbit_connection_sup}}, - {started, - [{pid, PidPlaceholder}, - {name, helper_sup}, - {mfargs, - {rabbit_connection_helper_sup, start_link, []}}, - {restart_type, intrinsic}, - {shutdown, infinity}, - {child_type, supervisor}]}], - ApplicationExit = - [{application, error_logger_lager_h_test}, - {exited, stopped}, - {type, permanent}], - - error_logger:info_report("This is not a progress message"), - error_logger:info_report(ApplicationExit), - [error_logger:info_report(progress, SupervisorMsg) || _K <- lists:seq(0, 100)], - error_logger:info_report("This is not a progress message 2"), - - % Note: this gets logged in slow environments: - % Application lager started on node nonode@nohost - wait_for_count(fun lager_test_backend:count/0, [3, 4], 100, 50), - % Note: this debug msg gets ignored in slow environments: - % Lager installed handler lager_test_backend into lager_event - wait_for_count(fun lager_test_backend:count_ignored/0, [0, 1], 100, 50) - after - application:stop(lager), - application:stop(goldrush), - error_logger:tty(true) - end - end - ] - }. - -supressed_messages_are_not_counted_for_hwm_test_() -> - {timeout, 10000, - [fun() -> - error_logger:tty(false), - application:load(lager), - application:set_env(lager, handlers, [{lager_test_backend, debug}]), - application:set_env(lager, errLoggerRedirect, true), - application:set_env(lager, errLoggerHwm, 5), - application:set_env(lager, suppress_supervisor_start_stop, true), - application:set_env(lager, suppress_application_start_stop, true), - application:unset_env(lager, crash_log), - eRum:start(), - try - PidPlaceholder = self(), - SupervisorMsg = - [{supervisor, {PidPlaceholder, rabbit_connection_sup}}, - {started, - [{pid, PidPlaceholder}, - {name, helper_sup}, - {mfargs, - {rabbit_connection_helper_sup, start_link, []}}, - {restart_type, intrinsic}, - {shutdown, infinity}, - {child_type, supervisor}]}], - ApplicationExit = - [{application, error_logger_lager_h_test}, - {exited, stopped}, - {type, permanent}], - - lager_test_backend:flush(), - error_logger:info_report("This is not a progress message"), - [error_logger:info_report(ApplicationExit) || _K <- lists:seq(0, 100)], - [error_logger:info_report(progress, SupervisorMsg) || _K <- lists:seq(0, 100)], - error_logger:info_report("This is not a progress message 2"), - - wait_for_count(fun lager_test_backend:count/0, 2, 100, 50), - wait_for_count(fun lager_test_backend:count_ignored/0, 0, 100, 50) - after - application:stop(lager), - application:stop(goldrush), - error_logger:tty(true) - end - end - ] - }. - -wait_for_message(Expected, Tries, Sleep) -> - maybe_find_expected_message(lager_test_backend:get_buffer(), Expected, Tries, Sleep). - -maybe_find_expected_message(_Buffer, Expected, 0, _Sleep) -> - throw({not_found, Expected}); -maybe_find_expected_message([], Expected, Tries, Sleep) -> - timer:sleep(Sleep), - maybe_find_expected_message(lager_test_backend:get_buffer(), Expected, Tries - 1, Sleep); -maybe_find_expected_message([{_Severity, _Date, Msg, _Metadata} | T], Expected, Tries, Sleep) -> - case lists:flatten(Msg) of - Expected -> - ok; - _ -> - maybe_find_expected_message(T, Expected, Tries, Sleep) - end. - -wait_for_count(Fun, _Expected, 0, _Sleep) -> - Actual = Fun(), - Msg = io_lib:format("wait_for_count: fun ~p final value: ~p~n", [Fun, Actual]), - throw({failed, Msg}); -wait_for_count(Fun, Expected, Tries, Sleep) when is_list(Expected) -> - Actual = Fun(), - case lists:member(Actual, Expected) of - true -> - ok; - false -> - timer:sleep(Sleep), - wait_for_count(Fun, Expected, Tries - 1, Sleep) - end; -wait_for_count(Fun, Expected, Tries, Sleep) -> - case Fun() of - Expected -> - ok; - _ -> - timer:sleep(Sleep), - wait_for_count(Fun, Expected, Tries - 1, Sleep) - end. --endif. diff --git a/src/formatter/rumFormatter.erl b/src/formatter/rumFormatter.erl index c8ec997..f2227b3 100644 --- a/src/formatter/rumFormatter.erl +++ b/src/formatter/rumFormatter.erl @@ -2,10 +2,6 @@ -include("rumDef.hrl"). --ifdef(TEST). --include_lib("eunit/include/eunit.hrl"). --endif. - -export([ format/2 , format/3 @@ -237,307 +233,3 @@ uppercase_severity(error) -> "ERROR"; uppercase_severity(critical) -> "CRITICAL"; uppercase_severity(alert) -> "ALERT"; uppercase_severity(emergency) -> "EMERGENCY". - --ifdef(TEST). - - -basic_test_() -> - Date = {1, 1, 1}, - Time = {1, 1, 1}, - Now = 11, - [{"Default formatting test", - ?_assertEqual(iolist_to_binary([Date, " ", Time, " [error] ", pid_to_list(self()), " Message\n"]), - iolist_to_binary(format(rumMsg:new("Message", - Now, - error, - [{pid, self()}], - []), - []))) - }, - {"Basic Formatting", - ?_assertEqual(<<"Simplist Format">>, - iolist_to_binary(format(rumMsg:new("Message", - Now, - error, - [{pid, self()}], - []), - ["Simplist Format"]))) - }, - {"Default equivalent formatting test", - ?_assertEqual(iolist_to_binary([Date, " ", Time, " [error] ", pid_to_list(self()), " Message\n"]), - iolist_to_binary(format(rumMsg:new("Message", - Now, - error, - [{pid, self()}], - []), - [date, " ", time, " [", severity, "] ", pid, " ", message, "\n"] - ))) - }, - {"Non existent metadata can default to string", - ?_assertEqual(iolist_to_binary([Date, " ", Time, " [error] Fallback Message\n"]), - iolist_to_binary(format(rumMsg:new("Message", - Now, - error, - [{pid, self()}], - []), - [date, " ", time, " [", severity, "] ", {does_not_exist, "Fallback"}, " ", message, "\n"] - ))) - }, - {"Non existent metadata can default to other metadata", - ?_assertEqual(iolist_to_binary([Date, " ", Time, " [error] Fallback Message\n"]), - iolist_to_binary(format(rumMsg:new("Message", - Now, - error, - [{pid, "Fallback"}], - []), - [date, " ", time, " [", severity, "] ", {does_not_exist, pid}, " ", message, "\n"] - ))) - }, - {"Non existent metadata can default to a string2", - ?_assertEqual(iolist_to_binary(["Unknown Pid"]), - iolist_to_binary(format(rumMsg:new("Message", - Now, - error, - [], - []), - [{pid, ["My pid is ", pid], ["Unknown Pid"]}] - ))) - }, - {"Metadata can have extra formatting", - ?_assertEqual(iolist_to_binary(["My pid is hello"]), - iolist_to_binary(format(rumMsg:new("Message", - Now, - error, - [{pid, hello}], - []), - [{pid, ["My pid is ", pid], ["Unknown Pid"]}] - ))) - }, - {"Metadata can have extra formatting1", - ?_assertEqual(iolist_to_binary(["servername"]), - iolist_to_binary(format(rumMsg:new("Message", - Now, - error, - [{pid, hello}, {server, servername}], - []), - [{server, {pid, ["(", pid, ")"], ["(Unknown Server)"]}}] - ))) - }, - {"Metadata can have extra formatting2", - ?_assertEqual(iolist_to_binary(["(hello)"]), - iolist_to_binary(format(rumMsg:new("Message", - Now, - error, - [{pid, hello}], - []), - [{server, {pid, ["(", pid, ")"], ["(Unknown Server)"]}}] - ))) - }, - {"Metadata can have extra formatting3", - ?_assertEqual(iolist_to_binary(["(Unknown Server)"]), - iolist_to_binary(format(rumMsg:new("Message", - Now, - error, - [], - []), - [{server, {pid, ["(", pid, ")"], ["(Unknown Server)"]}}] - ))) - }, - {"Metadata can be printed in its enterity", - ?_assertEqual(iolist_to_binary(["bar=2 baz=3 foo=1"]), - iolist_to_binary(format(rumMsg:new("Message", - Now, - error, - [{foo, 1}, {bar, 2}, {baz, 3}], - []), - [metadata] - ))) - }, - {"Metadata can be printed in its enterity with custom seperators", - ?_assertEqual(iolist_to_binary(["bar->2, baz->3, foo->1"]), - iolist_to_binary(format(rumMsg:new("Message", - Now, - error, - [{foo, 1}, {bar, 2}, {baz, 3}], - []), - [{metadata, "->", ", "}] - ))) - }, - {"Metadata can have extra formatting with width 1", - ?_assertEqual(iolist_to_binary(["(hello )(hello )(hello)(hello)(hello)"]), - iolist_to_binary(format(rumMsg:new("Message", - Now, - error, - [{pid, hello}], - []), - ["(", {pid, [pid], "", 10}, ")", - "(", {pid, [pid], "", {bad_align, 10}}, ")", - "(", {pid, [pid], "", bad10}, ")", - "(", {pid, [pid], "", {right, bad20}}, ")", - "(", {pid, [pid], "", {bad_align, bad20}}, ")"] - ))) - }, - {"Metadata can have extra formatting with width 2", - ?_assertEqual(iolist_to_binary(["(hello )"]), - iolist_to_binary(format(rumMsg:new("Message", - Now, - error, - [{pid, hello}], - []), - ["(", {pid, [pid], "", {left, 10}}, ")"] - ))) - }, - {"Metadata can have extra formatting with width 3", - ?_assertEqual(iolist_to_binary(["( hello)"]), - iolist_to_binary(format(rumMsg:new("Message", - Now, - error, - [{pid, hello}], - []), - ["(", {pid, [pid], "", {right, 10}}, ")"] - ))) - }, - {"Metadata can have extra formatting with width 4", - ?_assertEqual(iolist_to_binary(["( hello )"]), - iolist_to_binary(format(rumMsg:new("Message", - Now, - error, - [{pid, hello}], - []), - ["(", {pid, [pid], "", {centre, 10}}, ")"] - ))) - }, - {"Metadata can have extra formatting with width 5", - ?_assertEqual(iolist_to_binary(["error |hello ! ( hello )"]), - iolist_to_binary(format(rumMsg:new("Message", - Now, - error, - [{pid, hello}], - []), - [{x, "", [severity, {blank, "|"}, pid], 10}, "!", blank, "(", {pid, [pid], "", {centre, 10}}, ")"] - ))) - }, - {"Metadata can have extra formatting with width 6", - ?_assertEqual(iolist_to_binary([Time, Date, " bar=2 baz=3 foo=1 pid=hello EMessage"]), - iolist_to_binary(format(rumMsg:new("Message", - Now, - error, - [{pid, hello}, {foo, 1}, {bar, 2}, {baz, 3}], - []), - [{x, "", [time]}, {x, "", [date], 20}, blank, {x, "", [metadata], 30}, blank, {x, "", [sev], 10}, message, {message, message, "", {right, 20}}] - ))) - }, - {"Uppercase Severity Formatting - DEBUG", - ?_assertEqual(<<"DEBUG Simplist Format">>, - iolist_to_binary(format(rumMsg:new("Message", - Now, - debug, - [{pid, self()}], - []), - [severity_upper, " Simplist Format"]))) - }, - {"Uppercase Severity Formatting - INFO", - ?_assertEqual(<<"INFO Simplist Format">>, - iolist_to_binary(format(rumMsg:new("Message", - Now, - info, - [{pid, self()}], - []), - [severity_upper, " Simplist Format"]))) - }, - {"Uppercase Severity Formatting - NOTICE", - ?_assertEqual(<<"NOTICE Simplist Format">>, - iolist_to_binary(format(rumMsg:new("Message", - Now, - notice, - [{pid, self()}], - []), - [severity_upper, " Simplist Format"]))) - }, - {"Uppercase Severity Formatting - WARNING", - ?_assertEqual(<<"WARNING Simplist Format">>, - iolist_to_binary(format(rumMsg:new("Message", - Now, - warning, - [{pid, self()}], - []), - [severity_upper, " Simplist Format"]))) - }, - {"Uppercase Severity Formatting - ERROR", - ?_assertEqual(<<"ERROR Simplist Format">>, - iolist_to_binary(format(rumMsg:new("Message", - Now, - error, - [{pid, self()}], - []), - [severity_upper, " Simplist Format"]))) - }, - {"Uppercase Severity Formatting - CRITICAL", - ?_assertEqual(<<"CRITICAL Simplist Format">>, - iolist_to_binary(format(rumMsg:new("Message", - Now, - critical, - [{pid, self()}], - []), - [severity_upper, " Simplist Format"]))) - }, - {"Uppercase Severity Formatting - ALERT", - ?_assertEqual(<<"ALERT Simplist Format">>, - iolist_to_binary(format(rumMsg:new("Message", - Now, - alert, - [{pid, self()}], - []), - [severity_upper, " Simplist Format"]))) - }, - {"Uppercase Severity Formatting - EMERGENCY", - ?_assertEqual(<<"EMERGENCY Simplist Format">>, - iolist_to_binary(format(rumMsg:new("Message", - Now, - emergency, - [{pid, self()}], - []), - [severity_upper, " Simplist Format"]))) - }, - {"pterm presence test", - %% skip test on OTP < 21 - case list_to_integer(erlang:system_info(otp_release)) >= 21 of - true -> - ?_assertEqual(<<"Pterm is: something">>, - begin - persistent_term:put(thing, something), - Ret = iolist_to_binary(format(rumMsg:new("Message", - Now, - emergency, - [{pid, self()}], - []), - ["Pterm is: ", {pterm, thing}])), - persistent_term:erase(thing), - Ret - end); - false -> ?_assert(true) - end - }, - {"pterm absence test", - ?_assertEqual(<<"Pterm is: nothing">>, - iolist_to_binary(format(rumMsg:new("Message", - Now, - emergency, - [{pid, self()}], - []), - ["Pterm is: ", {pterm, thing, "nothing"}]))) - }, - {"node formatting basic", - begin - [N, "foo"] = format(rumMsg:new("Message", - Now, - info, - [{pid, self()}], - []), - [node, "foo"]), - ?_assertNotMatch(nomatch, re:run(N, <<"@">>)) - end - } - ]. - --endif. diff --git a/src/rotator/rumRotatorIns.erl b/src/rotator/rumRotatorIns.erl index 0359571..0a7e61c 100644 --- a/src/rotator/rumRotatorIns.erl +++ b/src/rotator/rumRotatorIns.erl @@ -11,10 +11,6 @@ , rotateLogFile/2 ]). --ifdef(TEST). --include_lib("eunit/include/eunit.hrl"). --endif. - createLogFile(FileName, Buffer) -> openLogFile(FileName, Buffer). @@ -104,90 +100,3 @@ tryUpdateCTime(Name, FileInfo) -> _ -> element(#file_info.ctime, FileInfo) end. - --ifdef(TEST). - -rotate_file_test() -> - RotCount = 10, - {ok, TestDir} = rumUtil:create_test_dir(), - TestLog = filename:join(TestDir, "rotation.log"), - Outer = fun(N) -> - ?assertEqual(ok, rumUtil:safe_write_file(TestLog, erlang:integer_to_list(N))), - Inner = fun(M) -> - File = lists:flatten([TestLog, $., erlang:integer_to_list(M)]), - ?assert(filelib:is_regular(File)), - %% check the expected value is in the file - Number = erlang:list_to_binary(integer_to_list(N - M - 1)), - ?assertEqual({ok, Number}, file:read_file(File)) - end, - Count = erlang:min(N, RotCount), - % The first time through, Count == 0, so the sequence is empty, - % effectively skipping the inner loop so a rotation can occur that - % creates the file that Inner looks for. - % Don't shoot the messenger, it was worse before this refactoring. - lists:foreach(Inner, lists:seq(0, Count - 1)), - rotateLogFile(TestLog, RotCount) - end, - lists:foreach(Outer, lists:seq(0, (RotCount * 2))), - rumUtil:delete_test_dir(TestDir). - -rotate_file_zero_count_test() -> - %% Test that a rotation count of 0 simply truncates the file - {ok, TestDir} = rumUtil:create_test_dir(), - TestLog = filename:join(TestDir, "rotation.log"), - ?assertMatch(ok, rotateLogFile(TestLog, 0)), - ?assertNot(filelib:is_regular(TestLog ++ ".0")), - ?assertEqual(true, filelib:is_regular(TestLog)), - ?assertEqual(1, length(filelib:wildcard(TestLog ++ "*"))), - %% assert the new file is 0 size: - case file:read_file_info(TestLog, [raw]) of - {ok, FInfo} -> - ?assertEqual(0, FInfo#file_info.size); - _ -> - ?assert(false) - end, - rumUtil:delete_test_dir(TestDir). - -rotate_file_fail_test() -> - {ok, TestDir} = rumUtil:create_test_dir(), - TestLog = filename:join(TestDir, "rotation.log"), - - %% set known permissions on it - ok = rumUtil:set_dir_permissions("u+rwx", TestDir), - - %% write a file - ?assertEqual(ok, rumUtil:safe_write_file(TestLog, "hello")), - - case os:type() of - {win32, _} -> ok; - _ -> - %% hose up the permissions - ok = rumUtil:set_dir_permissions("u-w", TestDir), - ?assertMatch({error, _}, rotateLogFile(TestLog, 10)) - end, - - %% check we still only have one file, rotation.log - ?assertEqual([TestLog], filelib:wildcard(TestLog ++ "*")), - ?assert(filelib:is_regular(TestLog)), - - %% fix the permissions - ok = rumUtil:set_dir_permissions("u+w", TestDir), - - ?assertMatch(ok, rotateLogFile(TestLog, 10)), - ?assert(filelib:is_regular(TestLog ++ ".0")), - ?assertEqual(true, filelib:is_regular(TestLog)), - ?assertEqual(2, length(filelib:wildcard(TestLog ++ "*"))), - - %% assert the new file is 0 size: - case file:read_file_info(TestLog, [raw]) of - {ok, FInfo} -> - ?assertEqual(0, FInfo#file_info.size); - _ -> - ?assert(false) - end, - - %% check that the .0 file now has the contents "hello" - ?assertEqual({ok, <<"hello">>}, file:read_file(TestLog ++ ".0")), - rumUtil:delete_test_dir(TestDir). - --endif. diff --git a/src/utils/rumConfig.erl b/src/utils/rumConfig.erl index 9b86b27..a6f4ec5 100644 --- a/src/utils/rumConfig.erl +++ b/src/utils/rumConfig.erl @@ -1,6 +1,7 @@ -module(rumConfig). -include("rumDef.hrl"). +-include("rumCom.hrl"). -export([ init/0 diff --git a/src/utils/rumMsg.erl b/src/utils/rumMsg.erl index 66b7c80..6118a75 100644 --- a/src/utils/rumMsg.erl +++ b/src/utils/rumMsg.erl @@ -1,6 +1,7 @@ -module(rumMsg). -include("rumDef.hrl"). +-include("rumMsg.hrl"). -export([new/4, new/5]). -export([message/1]). @@ -11,46 +12,35 @@ -export([metadata/1]). -export([destinations/1]). --opaque rumMsg() :: #rumMsg{}. --export_type([rumMsg/0]). %% create with provided timestamp, handy for testing mostly --spec new(list(), erlang:timestamp(), rumAtomLevel(), [tuple()], list()) -> rumMsg(). new(Msg, MsTick, Severity, Metadata, Destinations) -> TimeBinStr = rumUtil:msToBinStr(MsTick), #rumMsg{message = Msg, datetime = TimeBinStr, timestamp = MsTick, severity = Severity, metadata = Metadata, destinations = Destinations}. --spec new(list(), rumAtomLevel(), [tuple()], list()) -> rumMsg(). new(Msg, Severity, Metadata, Destinations) -> NowMs = rumUtil:nowMs(), new(Msg, NowMs, Severity, Metadata, Destinations). --spec message(rumMsg()) -> list(). message(Msg) -> Msg#rumMsg.message. --spec timestamp(rumMsg()) -> erlang:timestamp(). timestamp(Msg) -> Msg#rumMsg.timestamp. --spec datetime(rumMsg()) -> {string(), string()}. datetime(Msg) -> Msg#rumMsg.datetime. --spec severity(rumMsg()) -> rumAtomLevel(). severity(Msg) -> Msg#rumMsg.severity. --spec severity_as_int(rumMsg()) -> rumMaskLevel(). severity_as_int(Msg) -> rumUtil:levelToNum(Msg#rumMsg.severity). --spec metadata(rumMsg()) -> [tuple()]. metadata(Msg) -> Msg#rumMsg.metadata. --spec destinations(rumMsg()) -> list(). destinations(Msg) -> Msg#rumMsg.destinations. diff --git a/src/utils/rumUtil.erl b/src/utils/rumUtil.erl index 1749d58..1b56b74 100644 --- a/src/utils/rumUtil.erl +++ b/src/utils/rumUtil.erl @@ -637,350 +637,4 @@ get_opt(Key, Opts, Def) -> Def; V -> element(2, V) - end. - --ifdef(TEST). -parse_test() -> - ?assertEqual({ok, {undefined, undefined, 0, undefined}}, rumUtil:parseRotateSpec("$H0")), - ?assertEqual({ok, {undefined, undefined, 59, undefined}}, rumUtil:parseRotateSpec("$H59")), - ?assertEqual({ok, {undefined, 0, 0, undefined}}, rumUtil:parseRotateSpec("$D0")), - ?assertEqual({ok, {undefined, 23, 0, undefined}}, rumUtil:parseRotateSpec("$D23")), - ?assertEqual({ok, {day, 23, 0, 7}}, rumUtil:parseRotateSpec("$W7D23")), - ?assertEqual({ok, {day, 16, 0, 5}}, rumUtil:parseRotateSpec("$W5D16")), - ?assertEqual({ok, {day, 12, 30, 7}}, rumUtil:parseRotateSpec("$W7D12H30")), - ?assertEqual({ok, {date, 0, 0, 1}}, rumUtil:parseRotateSpec("$M1D0")), - ?assertEqual({ok, {date, 6, 0, 5}}, rumUtil:parseRotateSpec("$M5D6")), - ?assertEqual({ok, {date, 0, 0, 5}}, rumUtil:parseRotateSpec("$M5")), - ?assertEqual({ok, {date, 0, 0, 31}}, rumUtil:parseRotateSpec("$M31")), - ?assertEqual({ok, {date, 1, 0, 31}}, rumUtil:parseRotateSpec("$M31D1")), - ?assertEqual({ok, {last, 0, 0, undefined}}, rumUtil:parseRotateSpec("$ML")), - ?assertEqual({ok, {last, 0, 0, undefined}}, rumUtil:parseRotateSpec("$Ml")), - ?assertEqual({ok, {day, 0, 0, 5}}, rumUtil:parseRotateSpec("$W5")), - ?assertEqual({ok, {date, 12, 36, 5}}, rumUtil:parseRotateSpec("$M5D12H36")), - ok. - -parse_fail_test() -> - ?assertEqual({error, invalid_date_spec}, rumUtil:parseRotateSpec("$H")), - ?assertEqual({error, invalid_date_spec}, rumUtil:parseRotateSpec("$H60")), - ?assertEqual({error, invalid_date_spec}, rumUtil:parseRotateSpec("$D")), - ?assertEqual({error, invalid_date_spec}, rumUtil:parseRotateSpec("$D24")), - ?assertEqual({error, invalid_date_spec}, rumUtil:parseRotateSpec("$W0")), - ?assertEqual({error, invalid_date_spec}, rumUtil:parseRotateSpec("$W0D1")), - ?assertEqual({error, invalid_date_spec}, rumUtil:parseRotateSpec("$M32")), - ?assertEqual({error, invalid_date_spec}, rumUtil:parseRotateSpec("$M32D1")), - ?assertEqual({error, invalid_date_spec}, rumUtil:parseRotateSpec("$")), - ?assertEqual({error, invalid_date_spec}, rumUtil:parseRotateSpec("")), - ?assertEqual({error, invalid_date_spec}, rumUtil:parseRotateSpec("$D15M5")), - ?assertEqual({error, invalid_date_spec}, rumUtil:parseRotateSpec("$M5W5")), - ok. - -rotation_calculation_test() -> - ?assertMatch({{2000, 1, 1}, {13, 0, 0}}, - rumUtil:calcNextRotateDt({undefined, undefined, 0, 0}, {{2000, 1, 1}, {12, 34, 43}})), - ?assertMatch({{2000, 1, 1}, {12, 45, 0}}, - rumUtil:calcNextRotateDt({undefined, undefined, 45, 0}, {{2000, 1, 1}, {12, 34, 43}})), - ?assertMatch({{2000, 1, 2}, {0, 0, 0}}, - rumUtil:calcNextRotateDt({undefined, undefined, 0, 0}, {{2000, 1, 1}, {23, 45, 43}})), - ?assertMatch({{2000, 1, 2}, {0, 0, 0}}, - rumUtil:calcNextRotateDt({undefined, 0, 0, 0}, {{2000, 1, 1}, {12, 34, 43}})), - ?assertMatch({{2000, 1, 1}, {16, 0, 0}}, - rumUtil:calcNextRotateDt({undefined, 16, 0, 0}, {{2000, 1, 1}, {12, 34, 43}})), - ?assertMatch({{2000, 1, 2}, {12, 0, 0}}, - rumUtil:calcNextRotateDt({undefined, 12, 0, 0}, {{2000, 1, 1}, {12, 34, 43}})), - ?assertMatch({{2000, 2, 1}, {12, 0, 0}}, - rumUtil:calcNextRotateDt({date, 12, 0, 1}, {{2000, 1, 1}, {12, 34, 43}})), - ?assertMatch({{2000, 2, 1}, {12, 0, 0}}, - rumUtil:calcNextRotateDt({date, 12, 0, 1}, {{2000, 1, 15}, {12, 34, 43}})), - ?assertMatch({{2000, 2, 1}, {12, 0, 0}}, - rumUtil:calcNextRotateDt({date, 12, 0, 1}, {{2000, 1, 2}, {12, 34, 43}})), - ?assertMatch({{2000, 2, 1}, {12, 0, 0}}, - rumUtil:calcNextRotateDt({date, 12, 0, 1}, {{2000, 1, 31}, {12, 34, 43}})), - ?assertMatch({{2000, 1, 1}, {16, 0, 0}}, - rumUtil:calcNextRotateDt({date, 16, 0, 1}, {{2000, 1, 1}, {12, 34, 43}})), - ?assertMatch({{2000, 1, 15}, {16, 0, 0}}, - rumUtil:calcNextRotateDt({date, 16, 0, 15}, {{2000, 1, 1}, {12, 34, 43}})), - ?assertMatch({{2000, 1, 31}, {16, 0, 0}}, - rumUtil:calcNextRotateDt({last, 16, 0, 0}, {{2000, 1, 1}, {12, 34, 43}})), - ?assertMatch({{2000, 1, 31}, {16, 0, 0}}, - rumUtil:calcNextRotateDt({last, 16, 0, 0}, {{2000, 1, 31}, {12, 34, 43}})), - ?assertMatch({{2000, 2, 29}, {16, 0, 0}}, - rumUtil:calcNextRotateDt({last, 16, 0, 0}, {{2000, 1, 31}, {17, 34, 43}})), - ?assertMatch({{2001, 2, 28}, {16, 0, 0}}, - rumUtil:calcNextRotateDt({last, 16, 0, 0}, {{2001, 1, 31}, {17, 34, 43}})), - ?assertMatch({{2000, 1, 1}, {16, 0, 0}}, - rumUtil:calcNextRotateDt({day, 16, 0, 6}, {{2000, 1, 1}, {12, 34, 43}})), - ?assertMatch({{2000, 1, 8}, {16, 0, 0}}, - rumUtil:calcNextRotateDt({day, 16, 0, 6}, {{2000, 1, 1}, {17, 34, 43}})), - ?assertMatch({{2000, 1, 7}, {16, 0, 0}}, - rumUtil:calcNextRotateDt({day, 16, 0, 5}, {{2000, 1, 1}, {17, 34, 43}})), - ?assertMatch({{2000, 1, 3}, {16, 0, 0}}, - rumUtil:calcNextRotateDt({day, 16, 0, 1}, {{2000, 1, 1}, {17, 34, 43}})), - ?assertMatch({{2000, 1, 2}, {16, 0, 0}}, - rumUtil:calcNextRotateDt({day, 16, 0, 7}, {{2000, 1, 1}, {17, 34, 43}})), - ?assertMatch({{2000, 1, 9}, {16, 0, 0}}, - rumUtil:calcNextRotateDt({day, 16, 0, 7}, {{2000, 1, 2}, {17, 34, 43}})), - ?assertMatch({{2000, 2, 3}, {16, 0, 0}}, - rumUtil:calcNextRotateDt({day, 16, 0, 4}, {{2000, 1, 29}, {17, 34, 43}})), - ?assertMatch({{2000, 1, 7}, {16, 0, 0}}, - rumUtil:calcNextRotateDt({day, 16, 0, 5}, {{2000, 1, 3}, {17, 34, 43}})), - ?assertMatch({{2000, 1, 3}, {16, 0, 0}}, - rumUtil:calcNextRotateDt({day, 16, 0, 1}, {{1999, 12, 28}, {17, 34, 43}})), - ok. - -check_trace_test() -> - eRum:start(), - trace_filter(none), - %% match by module - ?assertEqual([foo], check_traces([{module, ?MODULE}], ?EMERGENCY, [ - {[{module, ?MODULE}], configToMask(emergency), foo}, - {[{module, test}], configToMask(emergency), bar}], [])), - %% match by module, but other unsatisfyable attribute - ?assertEqual([], check_traces([{module, ?MODULE}], ?EMERGENCY, [ - {[{module, ?MODULE}, {foo, bar}], configToMask(emergency), foo}, - {[{module, test}], configToMask(emergency), bar}], [])), - %% match by wildcard module - ?assertEqual([bar], check_traces([{module, ?MODULE}], ?EMERGENCY, [ - {[{module, ?MODULE}, {foo, bar}], configToMask(emergency), foo}, - {[{module, '*'}], configToMask(emergency), bar}], [])), - %% wildcard module, one trace with unsatisfyable attribute - ?assertEqual([bar], check_traces([{module, ?MODULE}], ?EMERGENCY, [ - {[{module, '*'}, {foo, bar}], configToMask(emergency), foo}, - {[{module, '*'}], configToMask(emergency), bar}], [])), - %% wildcard but not present custom trace attribute - ?assertEqual([bar], check_traces([{module, ?MODULE}], ?EMERGENCY, [ - {[{module, '*'}, {foo, '*'}], configToMask(emergency), foo}, - {[{module, '*'}], configToMask(emergency), bar}], [])), - %% wildcarding a custom attribute works when it is present - ?assertEqual([bar, foo], check_traces([{module, ?MODULE}, {foo, bar}], ?EMERGENCY, [ - {[{module, '*'}, {foo, '*'}], configToMask(emergency), foo}, - {[{module, '*'}], configToMask(emergency), bar}], [])), - %% denied by level - ?assertEqual([], check_traces([{module, ?MODULE}, {foo, bar}], ?INFO, [ - {[{module, '*'}, {foo, '*'}], configToMask(emergency), foo}, - {[{module, '*'}], configToMask(emergency), bar}], [])), - %% allowed by level - ?assertEqual([foo], check_traces([{module, ?MODULE}, {foo, bar}], ?INFO, [ - {[{module, '*'}, {foo, '*'}], configToMask(debug), foo}, - {[{module, '*'}], configToMask(emergency), bar}], [])), - ?assertEqual([anythingbutnotice, infoandbelow, infoonly], check_traces([{module, ?MODULE}], ?INFO, [ - {[{module, '*'}], configToMask('=debug'), debugonly}, - {[{module, '*'}], configToMask('=info'), infoonly}, - {[{module, '*'}], configToMask('<=info'), infoandbelow}, - {[{module, '*'}], configToMask('!=info'), anythingbutinfo}, - {[{module, '*'}], configToMask('!=notice'), anythingbutnotice} - ], [])), - application:stop(lager), - application:stop(goldrush), - ok. - -is_loggable_test_() -> - [ - {"Loggable by severity only", ?_assert(isLoggAble(rumMsg:new("", alert, [], []), 2, me))}, - {"Not loggable by severity only", ?_assertNot(isLoggAble(rumMsg:new("", critical, [], []), 1, me))}, - {"Loggable by severity with destination", ?_assert(isLoggAble(rumMsg:new("", alert, [], [you]), 2, me))}, - {"Not loggable by severity with destination", ?_assertNot(isLoggAble(rumMsg:new("", critical, [], [you]), 1, me))}, - {"Loggable by destination overriding severity", ?_assert(isLoggAble(rumMsg:new("", critical, [], [me]), 1, me))} - ]. - -format_time_test_() -> - [ - ?_assertEqual("2012-10-04 11:16:23.002", - begin - {D, T} = msToBinStr({{2012, 10, 04}, {11, 16, 23, 2}}), - lists:flatten([D, $ , T]) - end), - ?_assertEqual("2012-10-04 11:16:23.999", - begin - {D, T} = msToBinStr({{2012, 10, 04}, {11, 16, 23, 999}}), - lists:flatten([D, $ , T]) - end), - ?_assertEqual("2012-10-04 11:16:23", - begin - {D, T} = msToBinStr({{2012, 10, 04}, {11, 16, 23}}), - lists:flatten([D, $ , T]) - end), - ?_assertEqual("2012-10-04 00:16:23.092 UTC", - begin - {D, T} = msToBinStr({utc, {{2012, 10, 04}, {0, 16, 23, 92}}}), - lists:flatten([D, $ , T]) - end), - ?_assertEqual("2012-10-04 11:16:23 UTC", - begin - {D, T} = msToBinStr({utc, {{2012, 10, 04}, {11, 16, 23}}}), - lists:flatten([D, $ , T]) - end) - ]. - -config_to_levels_test() -> - ?assertEqual([none], atomCfgToLevels('none')), - ?assertEqual(0, configToMask('none')), - ?assertEqual([debug], atomCfgToLevels('=debug')), - ?assertEqual([debug], atomCfgToLevels('debug')), - ?assertEqual(levels() -- [debug], atomCfgToLevels('>=info')), - ?assertEqual(levels() -- [debug], atomCfgToLevels('=>info')), - ?assertEqual([debug, info, notice], atomCfgToLevels('<=notice')), - ?assertEqual([debug, info, notice], atomCfgToLevels('=info')), - ?assertError(badarg, atomCfgToLevels('=<=info')), - ?assertError(badarg, atomCfgToLevels('<==>=<=>info')), - %% double negatives DO work, however - ?assertEqual([debug], atomCfgToLevels('!!=debug')), - ?assertEqual(levels() -- [debug], atomCfgToLevels('!!!=debug')), - ok. - -config_to_mask_test() -> - ?assertEqual(0, configToMask('none')), - ?assertEqual(?DEBUG bor ?INFO bor ?NOTICE bor ?WARNING bor ?ERROR bor ?CRITICAL bor ?ALERT bor ?EMERGENCY, configToMask('debug')), - ?assertEqual(?WARNING bor ?ERROR bor ?CRITICAL bor ?ALERT bor ?EMERGENCY, configToMask('warning')), - ?assertEqual(?DEBUG bor ?NOTICE bor ?WARNING bor ?ERROR bor ?CRITICAL bor ?ALERT bor ?EMERGENCY, configToMask('!=info')), - ok. - -mask_to_levels_test() -> - ?assertEqual([], maskToLevels(0)), - ?assertEqual([debug], maskToLevels(2#10000000)), - ?assertEqual([debug, info], maskToLevels(2#11000000)), - ?assertEqual([debug, info, emergency], maskToLevels(2#11000001)), - ?assertEqual([debug, notice, error], maskToLevels(?DEBUG bor ?NOTICE bor ?ERROR)), - ok. - -expand_path_test() -> - OldRootVal = application:get_env(lager, logRoot), - - ok = application:unset_env(lager, logRoot), - ?assertEqual(filename:absname("/foo/bar"), parsePath("/foo/bar")), - ?assertEqual(filename:absname("foo/bar"), parsePath("foo/bar")), - - ok = application:set_env(lager, logRoot, "log/dir"), - ?assertEqual(filename:absname("/foo/bar"), parsePath("/foo/bar")), % Absolute path should not be changed - ?assertEqual(filename:absname("log/dir/foo/bar"), parsePath("foo/bar")), - ?assertEqual(filename:absname("log/dir/foo/bar"), parsePath("log/dir/foo/bar")), %% gh #304 - - case OldRootVal of - undefined -> application:unset_env(lager, logRoot); - {ok, Root} -> application:set_env(lager, logRoot, Root) - end, - ok. - -sink_name_test_() -> - [ - ?_assertEqual(rumEvent, makeInnerSinkName(lager)), - ?_assertEqual(audit_lager_event, makeInnerSinkName(audit)) - ]. - -create_test_dir() -> - {ok, Tmp} = get_temp_dir(), - Dir = filename:join([Tmp, "lager_test", - erlang:integer_to_list(erlang:phash2(os:timestamp()))]), - ?assertEqual(ok, filelib:ensure_dir(Dir)), - TestDir = case file:make_dir(Dir) of - ok -> - Dir; - Err -> - ?assertEqual({error, eexist}, Err), - create_test_dir() - end, - ok = application:set_env(lager, test_dir, TestDir), - {ok, TestDir}. - -get_test_dir() -> - case application:get_env(lager, test_dir) of - undefined -> - create_test_dir(); - {ok, _} = Res -> - Res - end. - -get_temp_dir() -> - Tmp = case os:getenv("TEMP") of - false -> - case os:getenv("TMP") of - false -> "/tmp"; - Dir1 -> Dir1 - end; - Dir0 -> Dir0 - end, - ?assertEqual(true, filelib:is_dir(Tmp)), - {ok, Tmp}. - -delete_test_dir() -> - {ok, TestDir} = get_test_dir(), - ok = delete_test_dir(TestDir). - -delete_test_dir(TestDir) -> - ok = application:unset_env(lager, test_dir), - ok = - case os:type() of - {win32, _} -> - application:stop(lager), - do_delete_test_dir(TestDir); - {_, _} -> - do_delete_test_dir(TestDir) - end. - -do_delete_test_dir(Dir) -> - ListRet = file:list_dir_all(Dir), - ?assertMatch({ok, _}, ListRet), - {_, Entries} = ListRet, - lists:foreach( - fun(Entry) -> - FsElem = filename:join(Dir, Entry), - case filelib:is_dir(FsElem) of - true -> - delete_test_dir(FsElem); - _ -> - case file:delete(FsElem) of - ok -> ok; - Error -> - io:format(standard_error, "[ERROR]: error deleting file ~p~n", [FsElem]), - ?assertEqual(ok, Error) - end - end - end, Entries), - ?assertEqual(ok, file:del_dir(Dir)). - -do_delete_file(_FsElem, 0) -> - ?assert(false); -do_delete_file(FsElem, Attempts) -> - case file:delete(FsElem) of - ok -> ok; - _Error -> - do_delete_file(FsElem, Attempts - 1) - end. - -set_dir_permissions(Perms, Dir) -> - do_set_dir_permissions(os:type(), Perms, Dir). - -do_set_dir_permissions({win32, _}, _Perms, _Dir) -> - ok; -do_set_dir_permissions({unix, _}, Perms, Dir) -> - os:cmd("chmod -R " ++ Perms ++ " " ++ Dir), - ok. - -safe_application_load(App) -> - case application:load(App) of - ok -> - ok; - {error, {already_loaded, App}} -> - ok; - Error -> - ?assertEqual(ok, Error) - end. - -safe_write_file(File, Content) -> - % Note: ensures that the new creation time is at least one second - % in the future - ?assertEqual(ok, file:write_file(File, Content)), - Ctime0 = calendar:local_time(), - Ctime0Sec = calendar:datetime_to_gregorian_seconds(Ctime0), - Ctime1Sec = Ctime0Sec + 1, - Ctime1 = calendar:gregorian_seconds_to_datetime(Ctime1Sec), - {ok, FInfo0} = file:read_file_info(File, [raw]), - FInfo1 = FInfo0#file_info{ctime = Ctime1}, - ?assertEqual(ok, file:write_file_info(File, FInfo1, [raw])). - --endif. + end. \ No newline at end of file diff --git a/src/watcher/rumHWatcherSrv.erl b/src/watcher/rumHWatcherSrv.erl index f0edf87..aae6de9 100644 --- a/src/watcher/rumHWatcherSrv.erl +++ b/src/watcher/rumHWatcherSrv.erl @@ -120,104 +120,3 @@ installHandler(Module, Config, Sink) -> erlang:send_after(5000, self(), mReinstallHandler), ok end. - --ifdef(TEST). - -from_now(Seconds) -> - {Mega, Secs, Micro} = os:timestamp(), - {Mega, Secs + Seconds, Micro}. - -reinstall_on_initial_failure_test_() -> - {timeout, 60000, - [ - fun() -> - error_logger:tty(false), - application:load(lager), - application:set_env(lager, handlers, [{lager_test_backend, info}, {lager_crash_backend, [from_now(2), undefined]}]), - application:set_env(lager, errLoggerRedirect, false), - application:unset_env(lager, crash_log), - eRum:start(), - try - {_Level, _Time, Message, _Metadata} = lager_test_backend:pop(), - ?assertMatch("Lager failed to install handler lager_crash_backend into lager_event, retrying later :" ++ _, lists:flatten(Message)), - timer:sleep(6000), - lager_test_backend:flush(), - ?assertEqual(0, lager_test_backend:count()), - ?assert(lists:member(lager_crash_backend, gen_event:which_handlers(rumEvent))) - after - application:stop(lager), - application:stop(goldrush), - error_logger:tty(true) - end - end - ] - }. - -reinstall_on_runtime_failure_test_() -> - {timeout, 60000, - [ - fun() -> - error_logger:tty(false), - application:load(lager), - application:set_env(lager, handlers, [{lager_test_backend, info}, {lager_crash_backend, [undefined, from_now(5)]}]), - application:set_env(lager, errLoggerRedirect, false), - application:unset_env(lager, crash_log), - eRum:start(), - try - ?assert(lists:member(lager_crash_backend, gen_event:which_handlers(rumEvent))), - timer:sleep(6000), - - pop_until("Lager event handler lager_crash_backend exited with reason crash", fun lists:flatten/1), - pop_until("Lager failed to install handler lager_crash_backend into lager_event, retrying later", - fun(Msg) -> string:substr(lists:flatten(Msg), 1, 84) end), - ?assertEqual(false, lists:member(lager_crash_backend, gen_event:which_handlers(rumEvent))) - after - application:stop(lager), - application:stop(goldrush), - error_logger:tty(true) - end - end - ] - }. - -reinstall_handlers_after_killer_hwm_test_() -> - {timeout, 60000, - [ - fun() -> - error_logger:tty(false), - application:load(lager), - application:set_env(lager, handlers, [{lager_manager_killer, [1000, 5000]}]), - application:set_env(lager, errLoggerRedirect, false), - application:set_env(lager, killerReTime, 5000), - application:unset_env(lager, crash_log), - eRum:start(), - eRum:trace_file("foo", [{foo, "bar"}], error), - L = length(gen_event:which_handlers(rumEvent)), - try - rumMgrKiller:kill_me(), - timer:sleep(6000), - ?assertEqual(L, length(gen_event:which_handlers(rumEvent))), - file:delete("foo") - after - application:stop(lager), - application:stop(goldrush), - error_logger:tty(true) - end - end - ] - }. - -pop_until(String, Fun) -> - try_backend_pop(lager_test_backend:pop(), String, Fun). - -try_backend_pop(undefined, String, _Fun) -> - throw("Not found: " ++ String); -try_backend_pop({_Severity, _Date, Msg, _Metadata}, String, Fun) -> - case Fun(Msg) of - String -> - ok; - _ -> - try_backend_pop(lager_test_backend:pop(), String, Fun) - end. - --endif. diff --git a/test/compress_pr_record_test.erl b/test/compress_pr_record_test.erl deleted file mode 100644 index 22faaa2..0000000 --- a/test/compress_pr_record_test.erl +++ /dev/null @@ -1,22 +0,0 @@ --module(compress_pr_record_test). - --compile([{parse_transform, lager_transform}]). - --record(a, {field1 :: term(), - field2 :: term(), - foo :: term(), - bar :: term(), - baz :: term(), - zyu :: term(), - zix :: term()}). - --ifdef(TEST). --include_lib("eunit/include/eunit.hrl"). --endif. - -nested_record_test() -> - A = #a{field1 = "Notice me senpai"}, - Pr_A = eRum:pr(A, ?MODULE), - Pr_A_Comp = eRum:pr(A, ?MODULE, [compress]), - ?assertMatch({'$lager_record', a, [{field1, "Notice me senpai"}, {field2, undefined} | _]}, Pr_A), - ?assertEqual({'$lager_record', a, [{field1, "Notice me senpai"}]}, Pr_A_Comp). diff --git a/test/crash.erl b/test/crash.erl deleted file mode 100644 index 75ab3ce..0000000 --- a/test/crash.erl +++ /dev/null @@ -1,109 +0,0 @@ - -%% a module that crashes in just about every way possible - --module(crash). - --behaviour(gen_server). - --export([init/1, handle_call/3, handle_cast/2, handle_info/2, terminate/2, code_change/3]). - --export([start/0]). - --record(state, { - host :: term(), - port :: term() -}). - -start() -> - gen_server:start({local, ?MODULE}, ?MODULE, [], []). - -init(_) -> - {ok, {}}. - -handle_call(undef, _, State) -> - {reply, ?MODULE:booger(), State}; -handle_call(badfun, _, State) -> - M = booger, - {reply, M(), State}; -handle_call(bad_return, _, _) -> - bleh; -handle_call(bad_return_string, _, _) -> - {tuple, {tuple, "string"}}; -handle_call(case_clause, _, State) -> - case State of - goober -> - {reply, ok, State} - end; -handle_call(case_clause_string, _, State) -> - Foo = atom_to_list(?MODULE), - case Foo of - State -> - {reply, ok, State} - end; -handle_call(if_clause, _, State) -> - if State == 1 -> - {reply, ok, State} - end; -handle_call(try_clause, _, State) -> - Res = try tuple_to_list(State) of - [_A, _B] -> ok - catch - _:_ -> ok - end, - {reply, Res, State}; -handle_call(badmatch, _, State) -> - {A, B, C} = State, - {reply, [A, B, C], State}; -handle_call(badrecord, _, State) -> - Host = State#state.host, - {reply, Host, State}; -handle_call(function_clause, _, State) -> - {reply, function(State), State}; -handle_call(badarith, _, State) -> - Res = 1 / length(tuple_to_list(State)), - {reply, Res, State}; -handle_call(badarg1, _, State) -> - Res = list_to_binary(["foo", bar]), - {reply, Res, State}; -handle_call(badarg2, _, State) -> - Res = erlang:iolist_to_binary(["foo", bar]), - {reply, Res, State}; -handle_call(system_limit, _, State) -> - Res = list_to_atom(lists:flatten(lists:duplicate(256, "a"))), - {reply, Res, State}; -handle_call(process_limit, _, State) -> - %% run with +P 300 to make this crash - [erlang:spawn(fun() -> timer:sleep(5000) end) || _ <- lists:seq(0, 500)], - {reply, ok, State}; -handle_call(port_limit, _, State) -> - [erlang:open_port({spawn, "ls"}, []) || _ <- lists:seq(0, 1024)], - {reply, ok, State}; -handle_call(noproc, _, State) -> - Res = gen_event:call(foo, bar, baz), - {reply, Res, State}; -handle_call(noproc_proc_lib, _, State) -> - Res = proc_lib:stop(foo), - {reply, Res, State}; -handle_call(badarity, _, State) -> - F = fun(A, B, C) -> A + B + C end, - Res = F(State), - {reply, Res, State}; -handle_call(throw, _, _State) -> - throw(a_ball); -handle_call(_Call, _From, State) -> - {reply, ok, State}. - -handle_cast(_Cast, State) -> - {noreply, State}. - -handle_info(_Info, State) -> - {noreply, State}. - -terminate(_, _) -> - ok. - -code_change(_, State, _) -> - {ok, State}. - -function(X) when is_list(X) -> - ok. diff --git a/test/crash_fsm.erl b/test/crash_fsm.erl deleted file mode 100644 index 4d139fc..0000000 --- a/test/crash_fsm.erl +++ /dev/null @@ -1,35 +0,0 @@ --module(crash_fsm). --behaviour(gen_fsm). --compile([{nowarn_deprecated_function, [{gen_fsm, start, 4}, {gen_fsm, sync_send_event, 2}]}]). - --export([start/0, crash/0, state1/2]). - -%% gen_fsm callbacks --export([init/1, handle_event/3, handle_sync_event/4, handle_info/3, - terminate/3, code_change/4]). - --record(state, {}). - -start() -> - gen_fsm:start({local, ?MODULE}, ?MODULE, [], []). - -crash() -> - gen_fsm:sync_send_event(?MODULE, crash). - -%% gen_fsm callbacks -init([]) -> - {ok, state1, #state{}}. - -handle_event(_Event, StateName, State) -> - {next_state, StateName, State}. -handle_sync_event(_Event, _From, StateName, State) -> - Reply = ok, - {reply, Reply, StateName, State}. -handle_info(_Info, StateName, State) -> - {next_state, StateName, State}. -terminate(_Reason, _StateName, _State) -> - ok. -code_change(_OldVersion, StateName, State, _Extra) -> - {ok, StateName, State}. - -state1(_Event, S) -> {next_state, state1, S}. diff --git a/test/crash_statem.erl b/test/crash_statem.erl deleted file mode 100644 index 4ed8280..0000000 --- a/test/crash_statem.erl +++ /dev/null @@ -1,46 +0,0 @@ --module(crash_statem). -%% we're only going to compile this on OTP 19+ --behaviour(gen_statem). - --export([ - start/0, - crash/0, - stop/1, - timeout/0, - handle_event/4 -]). - --export([terminate/3, code_change/4, init/1, callback_mode/0]). - -start() -> - gen_statem:start({local, ?MODULE}, ?MODULE, [], []). - -crash() -> - gen_statem:call(?MODULE, boom). - -stop(Reason) -> - gen_statem:call(?MODULE, {stop, Reason}). - -timeout() -> - gen_statem:call(?MODULE, timeout). - -%% Mandatory callback functions -terminate(_Reason, _State, _Data) -> ok. -code_change(_Vsn, State, Data, _Extra) -> {ok, State, Data}. -init([]) -> - %% insert rant here about breaking changes in minor versions... - case erlang:system_info(version) of - "8.0" -> {callback_mode(), state1, undefined}; - _ -> {ok, state1, undefined} - end. - -callback_mode() -> handle_event_function. - -%%% state callback(s) - -handle_event(state_timeout, timeout, state1, _) -> - {stop, timeout}; -handle_event({call, _From}, timeout, _Arg, _Data) -> - {keep_state_and_data, [{state_timeout, 0, timeout}]}; -handle_event({call, _From}, {stop, Reason}, state1, _Data) -> - {stop, Reason}. diff --git a/test/lager_app_tests.erl b/test/lager_app_tests.erl deleted file mode 100644 index 12bdedd..0000000 --- a/test/lager_app_tests.erl +++ /dev/null @@ -1,15 +0,0 @@ --module(lager_app_tests). - --compile([{parse_transform, lager_transform}]). - --include_lib("eunit/include/eunit.hrl"). - - -get_env_test() -> - application:set_env(myapp, mykey1, <<"Value">>), - - ?assertEqual(<<"Some">>, lager_app:get_env(myapp, mykey0, <<"Some">>)), - ?assertEqual(<<"Value">>, lager_app:get_env(myapp, mykey1, <<"Some">>)), - - ok. - diff --git a/test/lager_crash_backend.erl b/test/lager_crash_backend.erl deleted file mode 100644 index 19f40c2..0000000 --- a/test/lager_crash_backend.erl +++ /dev/null @@ -1,68 +0,0 @@ -%% Copyright (c) 2011-2012 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_crash_backend). - --include("rumDef.hrl"). - --behaviour(gen_event). - --export([init/1, handle_call/2, handle_event/2, handle_info/2, terminate/2, - code_change/3]). - --ifdef(TEST). --include_lib("eunit/include/eunit.hrl"). --endif. - -init([CrashBefore, CrashAfter]) -> - case is_tuple(CrashBefore) andalso (timer:now_diff(CrashBefore, os:timestamp()) > 0) of - true -> - %?debugFmt("crashing!~n", []), - {error, crashed}; - _ -> - %?debugFmt("Not crashing!~n", []), - case is_tuple(CrashAfter) of - true -> - CrashTime = timer:now_diff(CrashAfter, os:timestamp()) div 1000, - case CrashTime > 0 of - true -> - %?debugFmt("crashing in ~p~n", [CrashTime]), - erlang:send_after(CrashTime, self(), crash), - {ok, {}}; - _ -> {error, crashed} - end; - _ -> - {ok, {}} - end - end. - -handle_call(_Request, State) -> - {ok, ok, State}. - -handle_event(_Event, State) -> - {ok, State}. - -handle_info(crash, _State) -> - %?debugFmt("Time to crash!~n", []), - crash; -handle_info(_Info, State) -> - {ok, State}. - -terminate(_Reason, _State) -> - ok. - -code_change(_OldVsn, State, _Extra) -> - {ok, State}. diff --git a/test/lager_manager_killer_test.erl b/test/lager_manager_killer_test.erl deleted file mode 100644 index 135c03d..0000000 --- a/test/lager_manager_killer_test.erl +++ /dev/null @@ -1,125 +0,0 @@ --module(lager_manager_killer_test). --author("Sungjin Park "). - --compile([{parse_transform, lager_transform}]). - --ifdef(TEST). --include_lib("eunit/include/eunit.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 - -overload_test_() -> - {timeout, 60, - fun() -> - application:stop(lager), - application:load(lager), - Delay = 1000, % sleep 1 sec on every log - KillerHWM = 10, % kill the manager if there are more than 10 pending logs - KillerReinstallAfter = 1000, % reinstall killer after 1 sec - application:set_env(lager, handlers, [{lager_slow_backend, [{delay, Delay}]}]), - application:set_env(lager, asyncThreshold, undefined), - application:set_env(lager, errLoggerRedirect, true), - application:set_env(lager, killerHwm, KillerHWM), - application:set_env(lager, killerReTime, KillerReinstallAfter), - ensure_started(lager), - rumConfig:set(async, true), - Manager = whereis(rumEvent), - erlang:trace(all, true, [procs]), - [eRum:info("~p'th message", [N]) || N <- lists:seq(1, KillerHWM + 2)], - Margin = 100, - ok = confirm_manager_exit(Manager, Delay + Margin), - ok = confirm_sink_reregister(rumEvent, Margin), - erlang:trace(all, false, [procs]), - wait_until(fun() -> - case proplists:get_value(lager_manager_killer, gen_event:which_handlers(rumEvent)) of - [] -> false; - _ -> true - end - end, Margin, 15), - wait_until(fun() -> - case gen_event:call(rumEvent, lager_manager_killer, get_settings) of - [KillerHWM, KillerReinstallAfter] -> true; - _Other -> false - end - end, Margin, 15), - application:stop(lager) - end}. - -overload_alternate_sink_test_() -> - {timeout, 60, - fun() -> - application:stop(lager), - application:load(lager), - Delay = 1000, % sleep 1 sec on every log - KillerHWM = 10, % kill the manager if there are more than 10 pending logs - KillerReinstallAfter = 1000, % reinstall killer after 1 sec - application:set_env(lager, handlers, []), - application:set_env(lager, extraSinks, [{?TEST_SINK_EVENT, [ - {handlers, [{lager_slow_backend, [{delay, Delay}]}]}, - {killerHwm, KillerHWM}, - {killerReTime, KillerReinstallAfter}, - {asyncThreshold, undefined} - ]}]), - application:set_env(lager, errLoggerRedirect, true), - ensure_started(lager), - rumConfig:set({?TEST_SINK_EVENT, async}, true), - Manager = whereis(?TEST_SINK_EVENT), - erlang:trace(all, true, [procs]), - [?TEST_SINK_NAME:info("~p'th message", [N]) || N <- lists:seq(1, KillerHWM + 2)], - Margin = 100, - ok = confirm_manager_exit(Manager, Delay + Margin), - ok = confirm_sink_reregister(?TEST_SINK_EVENT, Margin), - erlang:trace(all, false, [procs]), - wait_until(fun() -> - case proplists:get_value(lager_manager_killer, gen_event:which_handlers(?TEST_SINK_EVENT)) of - [] -> false; - _ -> true - end - end, Margin, 15), - wait_until(fun() -> - case gen_event:call(?TEST_SINK_EVENT, lager_manager_killer, get_settings) of - [KillerHWM, KillerReinstallAfter] -> true; - _Other -> false - end - end, Margin, 15), - application:stop(lager) - end}. - -ensure_started(App) -> - case application:start(App) of - ok -> - ok; - {error, {not_started, Dep}} -> - ensure_started(Dep), - ensure_started(App) - end. - -confirm_manager_exit(Manager, Delay) -> - receive - {trace, Manager, exit, killed} -> - ?debugFmt("Manager ~p killed", [Manager]); - Other -> - ?debugFmt("OTHER MSG: ~p", [Other]), - confirm_manager_exit(Manager, Delay) - after Delay -> - ?assert(false) - end. - -confirm_sink_reregister(Sink, Delay) -> - receive - {trace, _Pid, register, Sink} -> - ?assertNot(lists:member(lager_manager_killer, gen_event:which_handlers(Sink))) - after Delay -> - ?assert(false) - end. - -wait_until(_Fun, _Delay, 0) -> - {error, too_many_retries}; -wait_until(Fun, Delay, Retries) -> - case Fun() of - true -> ok; - false -> timer:sleep(Delay), wait_until(Fun, Delay, Retries - 1) - end. - --endif. diff --git a/test/lager_metadata_whitelist_test.erl b/test/lager_metadata_whitelist_test.erl deleted file mode 100644 index 24202e5..0000000 --- a/test/lager_metadata_whitelist_test.erl +++ /dev/null @@ -1,24 +0,0 @@ --module(lager_metadata_whitelist_test). - - --ifdef(TEST). --include_lib("eunit/include/eunit.hrl"). - -setup() -> - ok = error_logger:tty(false), - ok = rumUtil:safe_application_load(lager), - ok = application:set_env(lager, handlers, [{lager_common_test_backend, info}]), - ok = application:set_env(lager, errLoggerRedirect, false), - ok = application:unset_env(lager, traces), - ok = eRum:start(), - ok = timer:sleep(250), - ok. - -cleanup(_) -> - ok = application:unset_env(lager, metadataWhitelist), - catch ets:delete(lager_config), %% kill the ets config table with fire - ok = application:stop(lager), - ok = application:stop(goldrush), - ok = error_logger:tty(true). - --endif. diff --git a/test/lager_rotate.erl b/test/lager_rotate.erl deleted file mode 100644 index 10c9221..0000000 --- a/test/lager_rotate.erl +++ /dev/null @@ -1,185 +0,0 @@ -%% ------------------------------------------------------------------- -%% -%% Copyright (c) 2016-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_rotate). - --ifdef(TEST). --include_lib("eunit/include/eunit.hrl"). --endif. - --record(state, { - dir :: string(), - log1 :: string(), - log1r :: string(), - log2 :: string(), - log2r :: string(), - sink :: string(), - sinkr :: string() -}). - -rotate_test_() -> - {foreach, - fun() -> - {ok, Dir} = rumUtil:create_test_dir(), - Log1 = filename:join(Dir, "test1.log"), - Log2 = filename:join(Dir, "test2.log"), - Sink = filename:join(Dir, "sink.log"), - State = #state{ - dir = Dir, - log1 = Log1, - log1r = Log1 ++ ".0", - log2 = Log2, - log2r = Log2 ++ ".0", - sink = Sink, - sinkr = Sink ++ ".0" - }, - file:write_file(Log1, []), - file:write_file(Log2, []), - file:write_file(Sink, []), - - error_logger:tty(false), - application:load(lager), - application:set_env(lager, handlers, [ - {lager_file_backend, [{file, Log1}, {level, info}]}, - {lager_file_backend, [{file, Log2}, {level, info}]}]), - application:set_env(lager, extraSinks, [ - {sink_event, - [{handlers, - [{lager_file_backend, [{file, Sink}, {level, info}]}]} - ]}]), - application:set_env(lager, errLoggerRedirect, false), - application:set_env(lager, asyncThreshold, undefined), - eRum:start(), - timer:sleep(1000), - State - end, - fun(#state{}) -> - ok = application:stop(lager), - ok = application:stop(goldrush), - ok = rumUtil:delete_test_dir(), - ok = error_logger:tty(true) - end, [ - fun(State) -> - {"Rotate single file", - fun() -> - eRum:log(error, self(), "Test message 1"), - eRum:log(sink_event, error, self(), "Sink test message 1", []), - eRum:rotate_handler({lager_file_backend, State#state.log1}), - ok = wait_until(fun() -> filelib:is_regular(State#state.log1r) end, 10), - eRum:log(error, self(), "Test message 2"), - eRum:log(sink_event, error, self(), "Sink test message 2", []), - - {ok, File1} = file:read_file(State#state.log1), - {ok, File2} = file:read_file(State#state.log2), - {ok, SinkFile} = file:read_file(State#state.sink), - {ok, File1Old} = file:read_file(State#state.log1r), - - have_no_log(File1, <<"Test message 1">>), - have_log(File1, <<"Test message 2">>), - - have_log(File2, <<"Test message 1">>), - have_log(File2, <<"Test message 2">>), - - have_log(File1Old, <<"Test message 1">>), - have_no_log(File1Old, <<"Test message 2">>), - - have_log(SinkFile, <<"Sink test message 1">>), - have_log(SinkFile, <<"Sink test message 2">>) - end} - end, - fun(State) -> - {"Rotate sink", - fun() -> - eRum:log(error, self(), "Test message 1"), - eRum:log(sink_event, error, self(), "Sink test message 1", []), - eRum:rotate_sink(sink_event), - ok = wait_until(fun() -> filelib:is_regular(State#state.sinkr) end, 10), - eRum:log(error, self(), "Test message 2"), - eRum:log(sink_event, error, self(), "Sink test message 2", []), - {ok, File1} = file:read_file(State#state.log1), - {ok, File2} = file:read_file(State#state.log2), - {ok, SinkFile} = file:read_file(State#state.sink), - {ok, SinkFileOld} = file:read_file(State#state.sinkr), - - have_log(File1, <<"Test message 1">>), - have_log(File1, <<"Test message 2">>), - - have_log(File2, <<"Test message 1">>), - have_log(File2, <<"Test message 2">>), - - have_log(SinkFileOld, <<"Sink test message 1">>), - have_no_log(SinkFileOld, <<"Sink test message 2">>), - - have_no_log(SinkFile, <<"Sink test message 1">>), - have_log(SinkFile, <<"Sink test message 2">>) - end} - end, - fun(State) -> - {"Rotate all", - fun() -> - eRum:log(error, self(), "Test message 1"), - eRum:log(sink_event, error, self(), "Sink test message 1", []), - eRum:rotate_all(), - ok = wait_until(fun() -> filelib:is_regular(State#state.sinkr) end, 10), - eRum:log(error, self(), "Test message 2"), - eRum:log(sink_event, error, self(), "Sink test message 2", []), - {ok, File1} = file:read_file(State#state.log1), - {ok, File2} = file:read_file(State#state.log2), - {ok, SinkFile} = file:read_file(State#state.sink), - {ok, File1Old} = file:read_file(State#state.log1r), - {ok, File2Old} = file:read_file(State#state.log2r), - {ok, SinkFileOld} = file:read_file(State#state.sinkr), - - have_no_log(File1, <<"Test message 1">>), - have_log(File1, <<"Test message 2">>), - - have_no_log(File2, <<"Test message 1">>), - have_log(File2, <<"Test message 2">>), - - have_no_log(SinkFile, <<"Sink test message 1">>), - have_log(SinkFile, <<"Sink test message 2">>), - - have_log(SinkFileOld, <<"Sink test message 1">>), - have_no_log(SinkFileOld, <<"Sink test message 2">>), - - have_log(File1Old, <<"Test message 1">>), - have_no_log(File1Old, <<"Test message 2">>), - - have_log(File2Old, <<"Test message 1">>), - have_no_log(File2Old, <<"Test message 2">>) - - end} - end - ]}. - -have_log(Data, Log) -> - {_, _} = binary:match(Data, Log). - -have_no_log(Data, Log) -> - nomatch = binary:match(Data, Log). - -wait_until(_Fun, 0) -> {error, too_many_retries}; -wait_until(Fun, Retry) -> - case Fun() of - true -> ok; - false -> - timer:sleep(500), - wait_until(Fun, Retry - 1) - end. diff --git a/test/lager_slow_backend.erl b/test/lager_slow_backend.erl deleted file mode 100644 index ad9cf24..0000000 --- a/test/lager_slow_backend.erl +++ /dev/null @@ -1,34 +0,0 @@ --module(lager_slow_backend). --author("Sungjin Park "). --behavior(gen_event). - --export([init/1, handle_call/2, handle_event/2, handle_info/2, terminate/2, code_change/3]). - --include("rumDef.hrl"). - --record(state, { - delay :: non_neg_integer() -}). - -init([{delay, Delay}]) -> - {ok, #state{delay = Delay}}. - -handle_call(mGetLogLevel, State) -> - {ok, rumUtil:configToMask(debug), State}; -handle_call(_Request, State) -> - {ok, ok, State}. - -handle_event({mWriteLog, _Message}, State) -> - timer:sleep(State#state.delay), - {ok, State}; -handle_event(_Event, State) -> - {ok, State}. - -handle_info(_Info, State) -> - {ok, State}. - -terminate(_Reason, _State) -> - ok. - -code_change(_OldVsn, State, _Extra) -> - {ok, State}. diff --git a/test/lager_test_backend.erl b/test/lager_test_backend.erl deleted file mode 100644 index 9cdd7a9..0000000 --- a/test/lager_test_backend.erl +++ /dev/null @@ -1,1927 +0,0 @@ -%% ------------------------------------------------------------------- -%% -%% 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("lager.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 = lager_util: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(mGetLogLevel, #state{level = Level} = State) -> - {ok, Level, State}; -handle_call({mSetLogLevel, Level}, State) -> - {ok, ok, State#state{level = lager_util:config_to_mask(Level)}}; -handle_call(print_state, State) -> - spawn(fun() -> lager:info("State ~p", [lager:pr(State, ?MODULE)]) end), - timer:sleep(100), - {ok, ok, State}; -handle_call(print_bad_state, State) -> - spawn(fun() -> lager:info("State ~p", [lager:pr({state, 1}, ?MODULE)]) end), - timer:sleep(100), - {ok, ok, State}; -handle_call(_Request, State) -> - {ok, ok, State}. - -handle_event({mWriteLog, 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:datetime(Msg), - lager_msg:message(Msg), lager_msg: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}, 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 - }, - {"test sink not running", - fun() -> - ?assertEqual({error, {sink_not_configured, test}}, lager:log(test, info, self(), "~p", "not running")) - 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 macro 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 - }, - {"unsafe logging works", - fun() -> - lager:warning_unsafe("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 with macro and 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 - }, - {"unsafe logging with args works", - fun() -> - lager:warning_unsafe("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(10, count()), - 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(10, count()), - 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(100, count()), - ok - end - }, - {"logging with only metadata works", - fun() -> - ?assertEqual(0, count()), - lager:warning([{just, metadata}]), - lager: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], - lager:info(Attr, "hello"), - lager:info(Attr, "hello ~p", [world]), - lager:info(Fmt, [world]), - lager:info("hello ~p", Args), - lager:info(Attr, "hello ~p", Args), - lager: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], - lager:info([{K, atom_to_list(V)} || {K, V} <- Attr], "hello"), - lager:info([{K, atom_to_list(V)} || {K, V} <- Attr], "hello ~p", [{atom, X} || X <- Args]), - lager:info([X || X <- Fmt], [world]), - lager:info("hello ~p", [{atom, X} || X <- Args]), - lager:info([{K, atom_to_list(V)} || {K, V} <- Attr], "hello ~p", [{atom, X} || X <- Args]), - lager: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]), - lager:info(get(attrs), "hello"), - lager:info(get(attrs), "hello ~p", get(args)), - lager:info(get(format), [world]), - lager:info("hello ~p", erlang:get(args)), - lager:info(fun() -> get(attrs) end(), "hello ~p", get(args)), - lager: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]}, - lager:info(Test#test.attrs, "hello"), - lager:info(Test#test.attrs, "hello ~p", Test#test.args), - lager:info(Test#test.format, [world]), - lager:info("hello ~p", Test#test.args), - lager:info(Test#test.attrs, "hello ~p", Test#test.args), - lager: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()), - 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), - ?assertEqual({?DEBUG bor ?INFO bor ?NOTICE bor ?WARNING bor ?ERROR bor ?CRITICAL bor ?ALERT bor ?EMERGENCY, []}, lager_config:get(loglevel)), - 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), - ?assertMatch({?ERROR bor ?CRITICAL bor ?ALERT bor ?EMERGENCY, _}, lager_config:get(loglevel)), - %% elegible for tracing - ok = lager:info("hello world"), - %% NOT elegible for tracing - ok = lager:log(info, [{pid, self()}], "hello world"), - ?assertEqual(1, count()), - ok - end - }, - {"tracing works with custom attributes", - fun() -> - lager:set_loglevel(?MODULE, error), - ?assertEqual({?ERROR bor ?CRITICAL bor ?ALERT bor ?EMERGENCY, []}, lager_config:get(loglevel)), - 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 works with custom attributes and event stream processing", - fun() -> - lager:set_loglevel(?MODULE, error), - ?assertEqual({?ERROR bor ?CRITICAL bor ?ALERT bor ?EMERGENCY, []}, lager_config:get(loglevel)), - 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, '>', 5}, {requestid, '<', 7}, {foo, bar}], debug), - lager:info([{requestid, 5}, {foo, bar}], "hello world"), - lager:info([{requestid, 6}, {foo, bar}], "hello world"), - ?assertEqual(1, count()), - lager:clear_all_traces(), - lager:trace(?MODULE, [{requestid, '>', 8}, {foo, bar}]), - lager:info([{foo, bar}], "hello world"), - lager:info([{requestid, 6}], "hello world"), - lager:info([{requestid, 7}], "hello world"), - lager:info([{requestid, 8}], "hello world"), - lager:info([{requestid, 9}, {foo, bar}], "hello world"), - lager:info([{requestid, 10}], "hello world"), - ?assertEqual(2, count()), - lager:trace(?MODULE, [{requestid, '>', 8}]), - lager:info([{foo, bar}], "hello world"), - lager:info([{requestid, 6}], "hello world"), - lager:info([{requestid, 7}], "hello world"), - lager:info([{requestid, 8}], "hello world"), - lager:info([{requestid, 9}, {foo, bar}], "hello world"), - lager:info([{requestid, 10}], "hello world"), - ?assertEqual(4, count()), - lager:trace(?MODULE, [{foo, '=', bar}]), - lager:info([{foo, bar}], "hello world"), - lager:info([{requestid, 6}], "hello world"), - lager:info([{requestid, 7}], "hello world"), - lager:info([{requestid, 8}], "hello world"), - lager:info([{requestid, 9}, {foo, bar}], "hello world"), - lager:info([{requestid, 10}], "hello world"), - lager:trace(?MODULE, [{fu, '!'}]), - lager:info([{foo, bar}], "hello world"), - lager:info([{ooh, car}], "hello world"), - lager:info([{fu, bar}], "hello world"), - lager:trace(?MODULE, [{fu, '*'}]), - lager:info([{fu, bar}], "hello world"), - ?assertEqual(10, count()), - lager:clear_all_traces(), - lager:info([{requestid, 6}], "hello world"), - ?assertEqual(10, count()), - lager:clear_all_traces(), - lager:trace(?MODULE, [{requestid, '>=', 5}, {requestid, '=<', 7}], debug), - lager:info([{requestid, 4}], "nope!"), - lager:info([{requestid, 5}], "hello world"), - lager:info([{requestid, 7}], "hello world again"), - ?assertEqual(12, count()), - lager:clear_all_traces(), - lager:trace(?MODULE, [{foo, '!=', bar}]), - lager:info([{foo, bar}], "hello world"), - ?assertEqual(12, count()), - lager:info([{foo, baz}], "blarg"), - ?assertEqual(13, count()), - lager:clear_all_traces(), - lager:trace(?MODULE, [{all, [{foo, '=', bar}, {null, false}]}]), - lager:info([{foo, bar}], "should not be logged"), - ?assertEqual(13, count()), - lager:clear_all_traces(), - lager:trace(?MODULE, [{any, [{foo, '=', bar}, {null, true}]}]), - lager:info([{foo, qux}], "should be logged"), - ?assertEqual(14, count()), - ok - end - }, - {"tracing custom attributes works with event stream processing statistics and reductions", - fun() -> - lager:set_loglevel(?MODULE, error), - ?assertEqual({?ERROR bor ?CRITICAL bor ?ALERT bor ?EMERGENCY, []}, lager_config:get(loglevel)), - lager_config:set(loglevel, {element(2, lager_util:config_to_mask(error)), []}), - lager:info([{requestid, 6}], "hello world"), - ?assertEqual(0, count()), - lager:trace(?MODULE, [{beta, '*'}]), - lager:trace(?MODULE, [{meta, "data"}]), - lager:info([{meta, "data"}], "hello world"), - lager:info([{beta, 2}], "hello world"), - lager:info([{beta, 2.1}, {foo, bar}], "hello world"), - lager:info([{meta, <<"data">>}], "hello world"), - ?assertEqual(8, ?DEFAULT_TRACER:info(input)), - ?assertEqual(6, ?DEFAULT_TRACER:info(output)), - ?assertEqual(2, ?DEFAULT_TRACER:info(filter)), - lager:clear_all_traces(), - lager:trace(?MODULE, [{meta, "data"}]), - lager:trace(?MODULE, [{beta, '>', 2}, {beta, '<', 2.12}]), - lager:info([{meta, "data"}], "hello world"), - lager:info([{beta, 2}], "hello world"), - lager:info([{beta, 2.1}, {foo, bar}], "hello world"), - lager:info([{meta, <<"data">>}], "hello world"), - ?assertEqual(8, ?DEFAULT_TRACER:info(input)), - ?assertEqual(4, ?DEFAULT_TRACER:info(output)), - ?assertEqual(4, ?DEFAULT_TRACER:info(filter)), - lager:clear_all_traces(), - lager:trace_console([{beta, '>', 2}, {meta, "data"}]), - lager:trace_console([{beta, '>', 2}, {beta, '<', 2.12}]), - Reduced = {all, [{any, [{beta, '<', 2.12}, {meta, '=', "data"}]}, - {beta, '>', 2}]}, - ?assertEqual(Reduced, ?DEFAULT_TRACER:info('query')), - - lager:clear_all_traces(), - lager:info([{requestid, 6}], "hello world"), - ?assertEqual(5, count()), - ok - end - }, - {"persistent traces work", - fun() -> - ?assertEqual(0, count()), - lager:debug([{foo, bar}], "hello world"), - ?assertEqual(0, count()), - application:stop(lager), - application:set_env(lager, traces, [{lager_test_backend, [{foo, bar}], debug}]), - lager:start(), - timer:sleep(5), - flush(), - lager:debug([{foo, bar}], "hello world"), - ?assertEqual(1, count()), - application:unset_env(lager, traces), - ok - end - }, - {"tracing honors loglevel", - fun() -> - lager:set_loglevel(?MODULE, error), - ?assertEqual({?ERROR bor ?CRITICAL bor ?ALERT bor ?EMERGENCY, []}, lager_config:get(loglevel)), - {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 - }, - {"stopped trace stops and removes its event handler - default sink (gh#267)", - {timeout, 10, - fun() -> - Sink = ?DEFAULT_SINK, - StartHandlers = gen_event:which_handlers(Sink), - {_, T0} = lager_config:get({Sink, loglevel}), - StartGlobal = lager_config:global_get(handlers), - ?assertEqual([], T0), - {ok, TestTrace1} = lager:trace_file("/tmp/test", [{a, b}]), - MidHandlers = gen_event:which_handlers(Sink), - {ok, TestTrace2} = lager:trace_file("/tmp/test", [{c, d}]), - MidHandlers = gen_event:which_handlers(Sink), - ?assertEqual(length(StartHandlers) + 1, length(MidHandlers)), - MidGlobal = lager_config:global_get(handlers), - ?assertEqual(length(StartGlobal) + 1, length(MidGlobal)), - {_, T1} = lager_config:get({Sink, loglevel}), - ?assertEqual(2, length(T1)), - ok = lager:stop_trace(TestTrace1), - {_, T2} = lager_config:get({Sink, loglevel}), - ?assertEqual(1, length(T2)), - ?assertEqual(length(StartHandlers) + 1, length( - gen_event:which_handlers(Sink))), - - ?assertEqual(length(StartGlobal) + 1, length(lager_config:global_get(handlers))), - ok = lager:stop_trace(TestTrace2), - EndHandlers = gen_event:which_handlers(Sink), - EndGlobal = lager_config:global_get(handlers), - {_, T3} = lager_config: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, lager_util:level_to_num(info)), - {mask, Mask} = lager_util: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, lager_util: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() -> lager:info("State ~p", [lager:pr({state, 1}, lager)]) end), - timer:sleep(100), - {Level, _Time, Message, _Metadata} = pop(), - ?assertMatch(Level, lager_util: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() -> lager:info("State ~p", [lager:pr(ok, lager)]) end), - timer:sleep(100), - {Level, _Time, Message, _Metadata} = pop(), - ?assertMatch(Level, lager_util:level_to_num(info)), - ?assertEqual("State ok", lists:flatten(Message)), - ok - end - }, - {"record printing fails gracefully when module is invalid", - fun() -> - spawn(fun() -> lager:info("State ~p", [lager:pr({state, 1}, not_a_module)]) end), - timer:sleep(1000), - {Level, _Time, Message, _Metadata} = pop(), - ?assertMatch(Level, lager_util: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, []}, lager_config: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, []}, lager_config:get(loglevel)), - ok - end - }, - {"metadata in the process dictionary works", - fun() -> - lager:md([{platypus, gravid}, {sloth, hirsute}, {duck, erroneous}]), - lager: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)), - lager:md([{platypus, gravid}, {sloth, hirsute}, {eagle, superincumbent}]), - lager: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() -> - lager: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, lager:md([{platypus, gravid}, {sloth, hirsute}, {duck, erroneous}])), - ?assertError(badarg, lager:md({flamboyant, flamingo})), - ?assertError(badarg, lager:md("zookeeper zephyr")), - ok - end - }, - {"dates should be local by default", - fun() -> - lager: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), - lager: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, lager_util: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, lager_util: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} = lager_config:get({Sink, loglevel}), - StartGlobal = lager_config:global_get(handlers), - ?assertEqual([], T0), - {ok, TestTrace1} = lager:trace_file("/tmp/test", [{sink, Sink}, {a, b}]), - MidHandlers = gen_event:which_handlers(Sink), - {ok, TestTrace2} = lager:trace_file("/tmp/test", [{sink, Sink}, {c, d}]), - MidHandlers = gen_event:which_handlers(Sink), - ?assertEqual(length(StartHandlers) + 1, length(MidHandlers)), - MidGlobal = lager_config:global_get(handlers), - ?assertEqual(length(StartGlobal) + 1, length(MidGlobal)), - {_, T1} = lager_config:get({Sink, loglevel}), - ?assertEqual(2, length(T1)), - ok = lager:stop_trace(TestTrace1), - {_, T2} = lager_config:get({Sink, loglevel}), - ?assertEqual(1, length(T2)), - ?assertEqual(length(StartHandlers) + 1, length( - gen_event:which_handlers(Sink))), - - ?assertEqual(length(StartGlobal) + 1, length(lager_config:global_get(handlers))), - ok = lager:stop_trace(TestTrace2), - EndHandlers = gen_event:which_handlers(Sink), - EndGlobal = lager_config:global_get(handlers), - {_, T3} = lager_config: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)), - lager_config:set({?TEST_SINK_EVENT, loglevel}, {element(2, lager_util: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)), - lager:set_loglevel(?TEST_SINK_EVENT, ?MODULE, undefined, debug), - ?assertEqual({?DEBUG bor ?INFO bor ?NOTICE bor ?WARNING bor ?ERROR bor ?CRITICAL bor ?ALERT bor ?EMERGENCY, []}, lager_config: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, lager: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, errLoggerRedirect, false), - application:set_env(lager, extraSinks, [{?TEST_SINK_EVENT, [{handlers, [{?MODULE, info}]}]}]), - lager: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, errLoggerRedirect, false), - application:unset_env(lager, traces), - lager: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({slice, Expected}, Actual) -> - SlicedActual = string:slice(Actual, 0, length(Expected)), - ?assertEqual(Expected, SlicedActual, {Actual, sliced_to, SlicedActual, is_not_a_member_of, Expected}); -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, errLoggerRedirect, true), - application:set_env(lager, handlers, [{?MODULE, error}]), - lager:start(), - crash:start(), - lager_event. - -error_logger_redirect_crash_setup_sink() -> - error_logger:tty(false), - application:load(lager), - application:set_env(lager, errLoggerRedirect, true), - application:unset_env(lager, handlers), - application:set_env(lager, extraSinks, [ - {error_logger_lager_event, [ - {handlers, [{?MODULE, error}]}]}]), - lager:start(), - crash:start(), - error_logger_lager_event. - -error_logger_redirect_crash_cleanup(_Sink) -> - application:stop(lager), - application:stop(goldrush), - application:unset_env(lager, extraSinks), - 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, errLoggerRedirect, true), - application:set_env(lager, handlers, [{?MODULE, error}]), - lager:start(), - crash_fsm:start(), - crash_statem:start(), - lager: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, errLoggerRedirect, true), - application:set_env(lager, handlers, []), - application:set_env(lager, extraSinks, [{ErrorSink, [{handlers, [{?MODULE, error}]}]}]), - lager:start(), - crash_fsm:start(), - crash_statem:start(), - lager: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, extraSinks), - 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, lager_util: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(lager_util: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_statem crash", crash_statem, crash, [], {slice, "gen_statem crash_statem in state state1 terminated with reason"}), - TestBody("gen_statem stop", crash_statem, stop, [explode], {slice, "gen_statem crash_statem in state state1 terminated with reason"}), - TestBody("gen_statem timeout", crash_statem, timeout, [], {slice, "gen_statem crash_statem in state state1 terminated with reason"}) - ] ++ test_body_gen_fsm_crash(TestBody), - - {"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}} - ]}. - -- if (?OTP_RELEASE < 23). -test_body_gen_fsm_crash(TestBody) -> - [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/")]. --else. -test_body_gen_fsm_crash(_TestBody) -> - []. --endif. - -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(lager_util: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, errLoggerRedirect, 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), - lager:start(), - lager: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, errLoggerRedirect, true), - application:unset_env(lager, handlers), - application:set_env(lager, extraSinks, [ - {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), - lager:start(), - lager: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, extraSinks), - 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(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(Sink) -> - sync_error_logger:error_report("this is less silly"), - _ = gen_event:which_handlers(error_logger), - {Level, _, Msg, Metadata} = pop(Sink), - ?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(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(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 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(lager_util: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(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(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(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(Sink) -> - sync_error_logger:info_report({foolish, bees}), - _ = gen_event:which_handlers(error_logger), - {Level, _, Msg, Metadata} = pop(Sink), - ?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(Sink) -> - sync_error_logger:error_report({foolish, bees}), - _ = gen_event:which_handlers(error_logger), - {Level, _, Msg, Metadata} = pop(Sink), - ?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(Sink) -> - sync_error_logger:info_report("this is less silly"), - _ = gen_event:which_handlers(error_logger), - {Level, _, Msg, Metadata} = pop(Sink), - ?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(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(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(Sink) -> - sync_error_logger:info_report(["this is less silly", {than, "this"}]), - _ = gen_event:which_handlers(error_logger), - {Level, _, Msg, Metadata} = pop(Sink), - ?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(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(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(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(lager_util: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(lager_util: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(lager_util: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(lager_util: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(lager_util: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(lager_util: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(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(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(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(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(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 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(lager_util: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(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(Sink) -> - sync_error_logger:info_report(progress, [{application, foo}, {started_at, node()}]), - _ = gen_event:which_handlers(error_logger), - {Level, _, Msg, Metadata} = pop(Sink), - ?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(Sink) -> - lager:set_loglevel(Sink, ?MODULE, undefined, debug), - ?assertEqual({?DEBUG bor ?INFO bor ?NOTICE bor ?WARNING bor ?ERROR bor ?CRITICAL bor ?ALERT bor ?EMERGENCY, []}, lager_config: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(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 - }, - {"supervisor progress report with pid", - fun(Sink) -> - lager:set_loglevel(Sink, ?MODULE, undefined, debug), - ?assertEqual({?DEBUG bor ?INFO bor ?NOTICE bor ?WARNING bor ?ERROR bor ?CRITICAL bor ?ALERT bor ?EMERGENCY, []}, lager_config: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(lager_util: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(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(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(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(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(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(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(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(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(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(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(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(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(lager_util: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(lager_util: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(lager_util: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(lager_util: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(lager_util: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) -> - lager:set_loglevel(Sink, ?MODULE, undefined, error), - ?assertEqual({?ERROR bor ?CRITICAL bor ?ALERT bor ?EMERGENCY, []}, lager_config: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)), - lager:set_loglevel(Sink, ?MODULE, undefined, info), - ?assertEqual({?INFO bor ?NOTICE bor ?WARNING bor ?ERROR bor ?CRITICAL bor ?ALERT bor ?EMERGENCY, []}, lager_config: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)), - lager:set_loglevel(Sink, ?MODULE, undefined, error), - ?assertEqual({?ERROR bor ?CRITICAL bor ?ALERT bor ?EMERGENCY, []}, lager_config:get({Sink, loglevel})), - lager_config:set({Sink, 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(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(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. - -unsafe_format_test() -> - ?assertEqual("foo bar", lists:flatten(lager:unsafe_format("~p ~p", [foo, bar]))), - ?assertEqual("FORMAT ERROR: \"~p ~p ~p\" [foo,bar]", lists:flatten(lager: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, asyncThreshold), - 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, errLoggerRedirect, false), - ok = application:set_env(lager, asyncThreshold, 2), - ok = application:set_env(lager, asyncThresholdWindow, 1), - ok = application:set_env(lager, handlers, [{?MODULE, info}]), - ok = lager:start(), - true - end, - {foreach, Setup, Cleanup, [ - {"async threshold works", - {timeout, 30, fun() -> - Sleep = get_long_sleep_value(), - - %% we start out async - ?assertEqual(true, lager_config: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 = lager_util: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), - - lager:info("hello world"), - - _ = gen_event:which_handlers(lager_event), - timer:sleep(Sleep), - - %% async is true again now that the mailbox has drained - ?assertEqual(true, lager_config: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) -> - lager: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, errLoggerRedirect, true), - application:set_env(lager, handlers, [{lager_test_backend, info}]), - application:set_env(lager, asyncThreshold, undefined), - lager:start() - end, - fun(_) -> - application:stop(lager), - error_logger:tty(true) - end, - [ - {"Nothing dropped when error_logger high watermark is undefined", - fun() -> - ok = error_logger_lager_h: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 = error_logger_lager_h: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 = error_logger_lager_h: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. diff --git a/test/lager_test_function_transform.erl b/test/lager_test_function_transform.erl deleted file mode 100644 index c293c48..0000000 --- a/test/lager_test_function_transform.erl +++ /dev/null @@ -1,193 +0,0 @@ -%% ------------------------------------------------------------------- -%% -%% 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_function_transform). - --include("rumDef.hrl"). - --compile([{nowarn_deprecated_function, [{erlang, now, 0}]}]). - --lager_function_transforms([ - {returns_static_emit, on_emit, {lager_test_function_transform, transform_static}}, - {returns_dynamic_emit, on_emit, {lager_test_function_transform, transform_dynamic}}, - {returns_undefined_emit, on_emit, {not_real_module_fake, fake_not_real_function}}, - - {returns_static_log, on_log, {lager_test_function_transform, transform_static}}, - {returns_dynamic_log, on_log, {lager_test_function_transform, transform_dynamic}} -]). - --compile({parse_transform, lager_transform}). - --ifdef(TEST). --include_lib("eunit/include/eunit.hrl"). --export([ - transform_static/0, - transform_dynamic/0 -]). --endif. - --ifdef(TEST). - -transform_static() -> - static_result. - -transform_dynamic() -> - erlang:now(). - -not_running_test() -> - ?assertEqual({error, lager_not_running}, eRum:log(info, self(), "not running")). - -setup() -> - ok = error_logger:tty(false), - ok = rumUtil:safe_application_load(lager), - ok = application:set_env(lager, handlers, [{lager_test_backend, info}]), - ok = application:set_env(lager, errLoggerRedirect, false), - ok = application:unset_env(lager, traces), - ok = 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. - ok = timer:sleep(250), - ok = gen_event:call(rumEvent, lager_test_backend, flush). - -cleanup(_) -> - catch ets:delete(lager_config), %% kill the ets config table with fire - ok = application:stop(lager), - ok = application:stop(goldrush), - ok = error_logger:tty(true). - -transform_function_test_() -> - {foreach, - fun setup/0, - fun cleanup/1, - [ - {"observe that there is nothing up my sleeve", - fun() -> - ?assertEqual(undefined, lager_test_backend:pop()), - ?assertEqual(0, lager_test_backend:count()) - end - }, - {"logging works", - fun() -> - eRum:warning("test message"), - ?assertEqual(1, lager_test_backend:count()), - {Level, _Time, Message, _Metadata} = lager_test_backend:pop(), - ?assertMatch(Level, rumUtil:levelToNum(warning)), - ?assertEqual("test message", Message), - ok - end - }, - {"Testing calling a function returns the same content on emit", - fun() -> - eRum:warning("static message"), - ?assertEqual(1, lager_test_backend:count()), - {_Level, _Time, _Message, Metadata} = lager_test_backend:pop(), - Function = proplists:get_value(returns_static_emit, Metadata), - ?assertEqual(transform_static(), Function()), - ok - end - }, - {"Testing calling a function which returns content which can change on emit", - fun() -> - eRum:warning("dynamic message"), - ?assertEqual(1, lager_test_backend:count()), - {_Level, _Time, _Message, Metadata} = lager_test_backend:pop(), - Function = proplists:get_value(returns_dynamic_emit, Metadata), - ?assert(Function() =< Function()), - ?assert(Function() =< Function()), - ?assert(Function() =< Function()), - ?assert(Function() =< Function()), - ok - end - }, - {"Testing a undefined function returns undefined on emit", - fun() -> - eRum:warning("Undefined error"), - ?assertEqual(1, lager_test_backend:count()), - {_Level, _Time, _Message, Metadata} = lager_test_backend:pop(), - Function = proplists:get_value(returns_undefined_emit, Metadata), - [{module, Module}, {name, Name} | _] = erlang:fun_info(Function), - ?assertNot(erlang:function_exported(Module, Name, 0)), - ok - end - }, - {"Testing calling a function returns the same content on log", - fun() -> - eRum:warning("static message"), - ?assertEqual(1, lager_test_backend:count()), - {_Level, _Time, _Message, Metadata} = lager_test_backend:pop(), - ?assertEqual(transform_static(), proplists:get_value(returns_static_log, Metadata)), - ok - end - }, - {"Testing calling a dynamic function on log which returns the same value", - fun() -> - eRum:warning("dynamic message"), - ?assertEqual(1, lager_test_backend:count()), - {_Level, _Time, _Message, Metadata} = lager_test_backend:pop(), - Value = proplists:get_value(returns_dynamic_log, Metadata), - ?assert(Value =< transform_dynamic()), - ?assert(Value =< transform_dynamic()), - ?assert(Value =< transform_dynamic()), - ?assert(Value =< transform_dynamic()), - ?assert(Value =< transform_dynamic()), - ok - end - }, - {"Testing differences in results for on_log vs on emit from dynamic function", - fun() -> - eRum:warning("on_log vs on emit"), - ?assertEqual(1, lager_test_backend:count()), - {_Level, _Time, _Message, Metadata} = lager_test_backend:pop(), - Value = proplists:get_value(returns_dynamic_log, Metadata), - Function = proplists:get_value(returns_dynamic_emit, Metadata), - FunctionResult = Function(), - ?assert(Value =< FunctionResult), - ?assert(Value =< Function()), - ?assert(FunctionResult =< Function()), - ok - end - }, - {"Testing a function provided via metadata", - fun() -> - Provided = fun() -> - provided_metadata - end, - eRum:md([{provided, Provided}]), - eRum:warning("Provided metadata"), - ?assertEqual(1, lager_test_backend:count()), - {_Level, _Time, _Message, Metadata} = lager_test_backend:pop(), - Function = proplists:get_value(provided, Metadata), - ?assertEqual(Provided(), Function()), - ok - end - } - ] - }. - --endif. diff --git a/test/lager_trace_test.erl b/test/lager_trace_test.erl deleted file mode 100644 index b7480ba..0000000 --- a/test/lager_trace_test.erl +++ /dev/null @@ -1,55 +0,0 @@ --module(pr_stacktrace_test). - --compile([{parse_transform, lager_transform}]). - --include_lib("eunit/include/eunit.hrl"). - -make_throw() -> - throw({test, exception}). - -bad_arity() -> - lists:concat([], []). - -bad_arg() -> - integer_to_list(1.0). - -pr_stacktrace_throw_test() -> - Got = try - make_throw() - catch - Class:Reason:Stacktrace -> - lager:pr_stacktrace(Stacktrace, {Class, Reason}) - end, - Want = "pr_stacktrace_test:pr_stacktrace_throw_test/0 line 26\n pr_stacktrace_test:make_throw/0 line 16\nthrow:{test,exception}", - ?assertNotEqual(nomatch, string:find(Got, Want)). - -pr_stacktrace_bad_arg_test() -> - Got = try - bad_arg() - catch - Class:Reason:Stacktrace -> - lager:pr_stacktrace(Stacktrace, {Class, Reason}) - end, - Want = "pr_stacktrace_test:pr_stacktrace_bad_arg_test/0 line 36\n pr_stacktrace_test:bad_arg/0 line 22\nerror:badarg", - ?assertNotEqual(nomatch, string:find(Got, Want)). - -pr_stacktrace_bad_arity_test() -> - Got = try - bad_arity() - catch - Class:Reason:Stacktrace -> - lager:pr_stacktrace(Stacktrace, {Class, Reason}) - end, - Want = "pr_stacktrace_test:pr_stacktrace_bad_arity_test/0 line 46\n lists:concat([], [])\nerror:undef", - ?assertNotEqual(nomatch, string:find(Got, Want)). - -pr_stacktrace_no_reverse_test() -> - application:set_env(lager, reverse_pretty_stacktrace, false), - Got = try - bad_arity() - catch - Class:Reason:Stacktrace -> - lager:pr_stacktrace(Stacktrace, {Class, Reason}) - end, - Want = "error:undef\n lists:concat([], [])\n pr_stacktrace_test:pr_stacktrace_bad_arity_test/0 line 57", - ?assertEqual(nomatch, string:find(Got, Want)). diff --git a/test/pr_composite_test.erl b/test/pr_composite_test.erl deleted file mode 100644 index 097f871..0000000 --- a/test/pr_composite_test.erl +++ /dev/null @@ -1,47 +0,0 @@ --module(pr_composite_test). - --compile([{parse_transform, lager_transform}]). - --record(a, {field1 :: term(), field2 :: term()}). --record(b, {field1 :: term(), field2 :: term()}). - - --include_lib("eunit/include/eunit.hrl"). - -nested_record_test() -> - A = #a{field1 = x, field2 = y}, - B = #b{field1 = A, field2 = {}}, - Pr_B = eRum:pr(B, ?MODULE), - ?assertEqual({'$lager_record', b, - [{field1, {'$lager_record', a, - [{field1, x}, {field2, y}]}}, - {field2, {}}]}, - Pr_B). - -list_field_test() -> - As = [#a{field1 = 1, field2 = a2}, - #a{field1 = 2, field2 = a2}], - B = #b{field1 = As, field2 = b2}, - Pr_B = eRum:pr(B, ?MODULE), - ?assertEqual({'$lager_record', b, - [{field1, [{'$lager_record', a, - [{field1, 1}, {field2, a2}]}, - {'$lager_record', a, - [{field1, 2}, {field2, a2}]}]}, - {field2, b2}]}, - Pr_B). - -list_of_records_test() -> - As = [#a{field1 = 1, field2 = a2}, - #a{field1 = 2, field2 = a2}], - Pr_As = eRum:pr(As, ?MODULE), - ?assertEqual([{'$lager_record', a, [{field1, 1}, {field2, a2}]}, - {'$lager_record', a, [{field1, 2}, {field2, a2}]}], - Pr_As). - -improper_list_test() -> - A = #a{field1 = [1 | 2], field2 = a2}, - Pr_A = eRum:pr(A, ?MODULE), - ?assertEqual({'$lager_record', a, - [{field1, [1 | 2]}, {field2, a2}]}, - Pr_A). diff --git a/test/pr_stacktrace_test.erl b/test/pr_stacktrace_test.erl deleted file mode 100644 index 9f7753d..0000000 --- a/test/pr_stacktrace_test.erl +++ /dev/null @@ -1,63 +0,0 @@ --module(pr_stacktrace_test). - --compile([{parse_transform, lager_transform}]). - --ifdef(OTP_RELEASE). %% this implies 21 or higher --define(EXCEPTION(Class, Reason, Stacktrace), Class:Reason:Stacktrace). --define(GET_STACK(Stacktrace), Stacktrace). --else. --define(EXCEPTION(Class, Reason, _), Class:Reason). --define(GET_STACK(_), erlang:get_stacktrace()). --endif. - --include_lib("eunit/include/eunit.hrl"). - -make_throw() -> - throw({test, exception}). - -bad_arity() -> - lists:concat([], []). - -bad_arg() -> - integer_to_list(1.0). - -pr_stacktrace_throw_test() -> - Got = try - make_throw() - catch - ?EXCEPTION(Class, Reason, Stacktrace) -> - eRum:pr_stacktrace(?GET_STACK(Stacktrace), {Class, Reason}) - end, - Want = "pr_stacktrace_test:pr_stacktrace_throw_test/0 line 26\n pr_stacktrace_test:make_throw/0 line 16\nthrow:{test,exception}", - ?assertNotEqual(nomatch, string:find(Got, Want)). - -pr_stacktrace_bad_arg_test() -> - Got = try - bad_arg() - catch - ?EXCEPTION(Class, Reason, Stacktrace) -> - eRum:pr_stacktrace(?GET_STACK(Stacktrace), {Class, Reason}) - end, - Want = "pr_stacktrace_test:pr_stacktrace_bad_arg_test/0 line 36\n pr_stacktrace_test:bad_arg/0 line 22\nerror:badarg", - ?assertNotEqual(nomatch, string:find(Got, Want)). - -pr_stacktrace_bad_arity_test() -> - Got = try - bad_arity() - catch - ?EXCEPTION(Class, Reason, Stacktrace) -> - eRum:pr_stacktrace(?GET_STACK(Stacktrace), {Class, Reason}) - end, - Want = "pr_stacktrace_test:pr_stacktrace_bad_arity_test/0 line 46\n lists:concat([], [])\nerror:undef", - ?assertNotEqual(nomatch, string:find(Got, Want)). - -pr_stacktrace_no_reverse_test() -> - application:set_env(lager, reverse_pretty_stacktrace, false), - Got = try - bad_arity() - catch - ?EXCEPTION(Class, Reason, Stacktrace) -> - eRum:pr_stacktrace(?GET_STACK(Stacktrace), {Class, Reason}) - end, - Want = "error:undef\n lists:concat([], [])\n pr_stacktrace_test:pr_stacktrace_bad_arity_test/0 line 57", - ?assertEqual(nomatch, string:find(Got, Want)). diff --git a/test/special_process.erl b/test/special_process.erl deleted file mode 100644 index d7e10b1..0000000 --- a/test/special_process.erl +++ /dev/null @@ -1,36 +0,0 @@ --module(special_process). --export([start/0, init/1]). - -start() -> - proc_lib:start_link(?MODULE, init, [self()]). - -init(Parent) -> - proc_lib:init_ack(Parent, {ok, self()}), - loop(). - -loop() -> - receive - function_clause -> - foo(bar), - loop(); - exit -> - exit(byebye), - loop(); - error -> - erlang:error(mybad), - loop(); - {case_clause, X} -> - case X of - notgonnamatch -> - ok; - notthiseither -> - error - end, - loop(); - _ -> - loop() - end. - -foo(baz) -> - ok. - diff --git a/test/sync_error_logger.erl b/test/sync_error_logger.erl deleted file mode 100644 index 6f0e487..0000000 --- a/test/sync_error_logger.erl +++ /dev/null @@ -1,89 +0,0 @@ -%% -%% %CopyrightBegin% -%% -%% Copyright Ericsson AB 1996-2009. All Rights Reserved. -%% -%% The contents of this file are subject to the Erlang Public License, -%% Version 1.1, (the "License"); you may not use this file except in -%% compliance with the License. You should have received a copy of the -%% Erlang Public License along with this software. If not, it can be -%% retrieved online at http://www.erlang.org/. -%% -%% Software distributed under the License is distributed on an "AS IS" -%% basis, WITHOUT WARRANTY OF ANY KIND, either express or implied. See -%% the License for the specific language governing rights and limitations -%% under the License. -%% -%% %CopyrightEnd% -%% --module(sync_error_logger). - -%% The error_logger API, but synchronous! -%% This is helpful for tests, otherwise you need lots of nasty timer:sleep. -%% Additionally, the warning map can be set on a per-process level, for -%% convienience, via the process dictionary value `warning_map'. - --export([ - info_msg/1, info_msg/2, - warning_msg/1, warning_msg/2, - error_msg/1, error_msg/2 -]). - --export([ - info_report/1, info_report/2, - warning_report/1, warning_report/2, - error_report/1, error_report/2 -]). - -info_msg(Format) -> - info_msg(Format, []). - -info_msg(Format, Args) -> - gen_event:sync_notify(error_logger, {info_msg, group_leader(), {self(), Format, Args}}). - -warning_msg(Format) -> - warning_msg(Format, []). - -warning_msg(Format, Args) -> - gen_event:sync_notify(error_logger, {warning_msg_tag(), group_leader(), {self(), Format, Args}}). - -error_msg(Format) -> - error_msg(Format, []). - -error_msg(Format, Args) -> - gen_event:sync_notify(error_logger, {error, group_leader(), {self(), Format, Args}}). - -info_report(Report) -> - info_report(std_info, Report). - -info_report(Type, Report) -> - gen_event:sync_notify(error_logger, {info_report, group_leader(), {self(), Type, Report}}). - -warning_report(Report) -> - warning_report(std_warning, Report). - -warning_report(Type, Report) -> - {Tag, NType} = warning_report_tag(Type), - gen_event:sync_notify(error_logger, {Tag, group_leader(), {self(), NType, Report}}). - -error_report(Report) -> - error_report(std_error, Report). - -error_report(Type, Report) -> - gen_event:sync_notify(error_logger, {error_report, group_leader(), {self(), Type, Report}}). - -warning_msg_tag() -> - case get(warning_map) of - warning -> warning_msg; - info -> info_msg; - _ -> error - end. - -warning_report_tag(Type) -> - case {get(warning_map), Type == std_warning} of - {warning, _} -> {warning_report, Type}; - {info, true} -> {info_report, std_info}; - {info, false} -> {info_report, Type}; - {_, true} -> {error_report, std_error}; - {_, false} -> {error_report, Type} - end. diff --git a/test/trunc_io_eqc.erl b/test/trunc_io_eqc.erl deleted file mode 100644 index 9daefb1..0000000 --- a/test/trunc_io_eqc.erl +++ /dev/null @@ -1,244 +0,0 @@ -%% ------------------------------------------------------------------- -%% -%% trunc_io_eqc: QuickCheck test for trunc_io:format with maxlen -%% -%% Copyright (c) 2011-2012 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(trunc_io_eqc). - --ifdef(TEST). --ifdef(EQC). --export([test/0, test/1, check/0, prop_format/0, prop_equivalence/0]). - --include_lib("eqc/include/eqc.hrl"). --include_lib("eunit/include/eunit.hrl"). - --define(QC_OUT(P), - eqc:on_output(fun(Str, Args) -> io:format(user, Str, Args) end, P)). - -%%==================================================================== -%% eunit test -%%==================================================================== - -eqc_test_() -> - {timeout, 60, - {spawn, - [ - {timeout, 30, ?_assertEqual(true, eqc:quickcheck(eqc:testing_time(14, ?QC_OUT(prop_format()))))}, - {timeout, 30, ?_assertEqual(true, eqc:quickcheck(eqc:testing_time(14, ?QC_OUT(prop_equivalence()))))} - ] - }}. - -%%==================================================================== -%% Shell helpers -%%==================================================================== - -test() -> - test(100). - -test(N) -> - quickcheck(numtests(N, prop_format())). - -check() -> - check(prop_format(), current_counterexample()). - -%%==================================================================== -%% Generators -%%==================================================================== - -gen_fmt_args() -> - list(oneof([gen_print_str(), - "~~", - {"~10000000.p", gen_any(5)}, - {"~w", gen_any(5)}, - {"~s", oneof([gen_print_str(), gen_atom(), gen_quoted_atom(), gen_print_bin(), gen_iolist(5)])}, - {"~1000000.P", gen_any(5), 4}, - {"~W", gen_any(5), 4}, - {"~i", gen_any(5)}, - {"~B", nat()}, - {"~b", nat()}, - {"~X", nat(), "0x"}, - {"~x", nat(), "0x"}, - {"~.10#", nat()}, - {"~.10+", nat()}, - {"~.36B", nat()}, - {"~1000000.62P", gen_any(5), 4}, - {"~c", gen_char()}, - {"~tc", gen_char()}, - {"~f", real()}, - {"~10.f", real()}, - {"~g", real()}, - {"~10.g", real()}, - {"~e", real()}, - {"~10.e", real()} - ])). - - -%% Generates a printable string -gen_print_str() -> - ?LET(Xs, list(char()), [X || X <- Xs, io_lib:printable_list([X]), X /= $~, X < 256]). - -gen_print_bin() -> - ?LET(Xs, gen_print_str(), list_to_binary(Xs)). - -gen_any(MaxDepth) -> - oneof([largeint(), - gen_atom(), - gen_quoted_atom(), - nat(), - %real(), - binary(), - gen_bitstring(), - gen_pid(), - gen_port(), - gen_ref(), - gen_fun()] ++ - [?LAZY(list(gen_any(MaxDepth - 1))) || MaxDepth /= 0] ++ - [?LAZY(gen_tuple(gen_any(MaxDepth - 1))) || MaxDepth /= 0]). - -gen_iolist(0) -> - []; -gen_iolist(Depth) -> - list(oneof([gen_char(), gen_print_str(), gen_print_bin(), gen_iolist(Depth - 1)])). - -gen_atom() -> - elements([abc, def, ghi]). - -gen_quoted_atom() -> - elements(['abc@bar', '@bar', '10gen']). - -gen_bitstring() -> - ?LET(XS, binary(), <>). - -gen_tuple(Gen) -> - ?LET(Xs, list(Gen), list_to_tuple(Xs)). - -gen_max_len() -> %% Generate length from 3 to whatever. Needs space for ... in output - ?LET(Xs, int(), 3 + abs(Xs)). - -gen_pid() -> - ?LAZY(spawn(fun() -> ok end)). - -gen_port() -> - ?LAZY(begin - Port = erlang:open_port({spawn, "true"}, []), - catch (erlang:port_close(Port)), - Port - end). - -gen_ref() -> - ?LAZY(make_ref()). - -gen_fun() -> - ?LAZY(fun() -> ok end). - -gen_char() -> - oneof(lists:seq($A, $z)). - -%%==================================================================== -%% Property -%%==================================================================== - -%% Checks that trunc_io:format produces output less than or equal to MaxLen -prop_format() -> - ?FORALL({FmtArgs, MaxLen}, {gen_fmt_args(), gen_max_len()}, - begin - %% Because trunc_io will print '...' when its running out of - %% space, even if the remaining space is less than 3, it - %% doesn't *exactly* stick to the specified limit. - - %% Also, since we don't truncate terms not printed with - %% ~p/~P/~w/~W/~s, we also need to calculate the wiggle room - %% for those. Hence the fudge factor calculated below. - FudgeLen = calculate_fudge(FmtArgs, 50), - {FmtStr, Args} = build_fmt_args(FmtArgs), - try - Str = lists:flatten(rumTruncIo:format(FmtStr, Args, MaxLen)), - ?WHENFAIL(begin - io:format(user, "FmtStr: ~p\n", [FmtStr]), - io:format(user, "Args: ~p\n", [Args]), - io:format(user, "FudgeLen: ~p\n", [FudgeLen]), - io:format(user, "MaxLen: ~p\n", [MaxLen]), - io:format(user, "ActLen: ~p\n", [length(Str)]), - io:format(user, "Str: ~p\n", [Str]) - end, - %% Make sure the result is a printable list - %% and if the format string is less than the length, - %% the result string is less than the length. - conjunction([{printable, Str == "" orelse - io_lib:printable_list(Str)}, - {length, length(FmtStr) > MaxLen orelse - length(Str) =< MaxLen + FudgeLen}])) - catch - _:Err -> - io:format(user, "\nException: ~p\n", [Err]), - io:format(user, "FmtStr: ~p\n", [FmtStr]), - io:format(user, "Args: ~p\n", [Args]), - false - end - end). - -%% Checks for equivalent formatting to io_lib -prop_equivalence() -> - ?FORALL(FmtArgs, gen_fmt_args(), - begin - {FmtStr, Args} = build_fmt_args(FmtArgs), - Expected = lists:flatten(io_lib:format(FmtStr, Args)), - Actual = lists:flatten(rumTruncIo:format(FmtStr, Args, 10485760)), - ?WHENFAIL(begin - io:format(user, "FmtStr: ~p\n", [FmtStr]), - io:format(user, "Args: ~p\n", [Args]), - io:format(user, "Expected: ~p\n", [Expected]), - io:format(user, "Actual: ~p\n", [Actual]) - end, - Expected == Actual) - end). - - -%%==================================================================== -%% Internal helpers -%%==================================================================== - -%% Build a tuple of {Fmt, Args} from a gen_fmt_args() return -build_fmt_args(FmtArgs) -> - F = fun({Fmt, Arg}, {FmtStr0, Args0}) -> - {FmtStr0 ++ Fmt, Args0 ++ [Arg]}; - ({Fmt, Arg1, Arg2}, {FmtStr0, Args0}) -> - {FmtStr0 ++ Fmt, Args0 ++ [Arg1, Arg2]}; - (Str, {FmtStr0, Args0}) -> - {FmtStr0 ++ Str, Args0} - end, - lists:foldl(F, {"", []}, FmtArgs). - -calculate_fudge([], Acc) -> - Acc; -calculate_fudge([{"~62P", _Arg, _Depth} | T], Acc) -> - calculate_fudge(T, Acc + 62); -calculate_fudge([{Fmt, Arg} | T], Acc) when - Fmt == "~f"; Fmt == "~10.f"; - Fmt == "~g"; Fmt == "~10.g"; - Fmt == "~e"; Fmt == "~10.e"; - Fmt == "~x"; Fmt == "~X"; - Fmt == "~B"; Fmt == "~b"; Fmt == "~36B"; - Fmt == "~.10#"; Fmt == "~10+" -> - calculate_fudge(T, Acc + length(lists:flatten(io_lib:format(Fmt, [Arg])))); -calculate_fudge([_ | T], Acc) -> - calculate_fudge(T, Acc). - --endif. % (EQC). --endif. % (TEST). diff --git a/test/zzzz_gh280_crash.erl b/test/zzzz_gh280_crash.erl deleted file mode 100644 index 74c1116..0000000 --- a/test/zzzz_gh280_crash.erl +++ /dev/null @@ -1,35 +0,0 @@ -%% @doc This test is named zzzz_gh280_crash because it has to be run first and tests are run in -%% reverse alphabetical order. -%% -%% The problem we are attempting to detect here is when log_mf_h is installed as a handler for error_logger -%% and lager starts up to replace the current handlers with its own. This causes a start up crash because -%% OTP error logging modules do not have any notion of a lager-style log level. --module(zzzz_gh280_crash). - --include_lib("eunit/include/eunit.hrl"). - -gh280_crash_test() -> - {timeout, 30, fun() -> gh280_impl() end}. - -gh280_impl() -> - application:stop(lager), - application:stop(goldrush), - - error_logger:tty(false), - %% see https://github.com/erlang/otp/blob/maint/lib/stdlib/src/log_mf_h.erl#L81 - %% for an explanation of the init arguments to log_mf_h - ok = gen_event:add_sup_handler(error_logger, log_mf_h, log_mf_h:init("/tmp", 10000, 5)), - eRum:start(), - Result = receive - {gen_event_EXIT, log_mf_h, normal} -> - true; - {gen_event_EXIT, Handler, Reason} -> - {Handler, Reason}; - X -> - X - after 10000 -> - timeout - end, - ?assert(Result), - application:stop(lager), - application:stop(goldrush).