%% @doc File backend for lager, with multiple file support. %% Multiple files are supported, each with the path and the loglevel being %% configurable. The configuration paramter for this backend is a list of %% key-value 2-tuples. See the init() function for the available options. %% This backend supports external and internal log %% rotation and will re-open handles to files if the inode changes. It will %% also rotate the files itself if the size of the file exceeds the %% `size' and keep `count' rotated files. `date' is %% an alternate rotation trigger, based on time. See the README for %% documentation. %% For performance, the file backend does delayed writes, although it will %% sync at specific log levels, configured via the `sync_on' option. By default %% the error level or above will trigger a sync. -module(rumBackendFile). -include("eRum.hrl"). -include_lib("kernel/include/file.hrl"). -behaviour(gen_event). -ifdef(TEST). -include_lib("eunit/include/eunit.hrl"). -compile([{parse_transform, lager_transform}]). -endif. -export([init/1, handle_call/2, handle_event/2, handle_info/2, terminate/2, code_change/3]). -export([config_to_id/1]). -define(DEFAULT_LOG_LEVEL, info). -define(DEFAULT_ROTATION_SIZE, 10485760). %% 10mb -define(DEFAULT_ROTATION_DATE, "$D0"). %% midnight -define(DEFAULT_ROTATION_COUNT, 5). -define(DEFAULT_ROTATION_MOD, lager_rotator_default). -define(DEFAULT_SYNC_LEVEL, error). -define(DEFAULT_SYNC_INTERVAL, 1000). -define(DEFAULT_SYNC_SIZE, 1024 * 64). %% 64kb -define(DEFAULT_CHECK_INTERVAL, 1000). -record(state, { name :: string(), level :: {'mask', integer()}, fd :: file:io_device() | undefined, inode :: integer() | undefined, ctime :: file:date_time() | undefined, flap = false :: boolean(), size = 0 :: integer(), date :: undefined | string(), count = 10 :: integer(), rotator = lager_util :: atom(), shaper :: rumShaper(), formatter :: atom(), formatter_config :: any(), sync_on :: {'mask', integer()}, check_interval = ?DEFAULT_CHECK_INTERVAL :: non_neg_integer(), sync_interval = ?DEFAULT_SYNC_INTERVAL :: non_neg_integer(), sync_size = ?DEFAULT_SYNC_SIZE :: non_neg_integer(), last_check = os:timestamp() :: erlang:timestamp(), os_type :: atom() }). -type option() :: {file, string()} | {level, rumLevel()} | {size, non_neg_integer()} | {date, string()} | {count, non_neg_integer()} | {rotator, atom()} | {high_water_mark, non_neg_integer()} | {flush_queue, boolean()} | {flush_threshold, non_neg_integer()} | {sync_interval, non_neg_integer()} | {sync_size, non_neg_integer()} | {sync_on, rumLevel()} | {check_interval, non_neg_integer()} | {formatter, atom()} | {formatter_config, term()}. -spec init([option(), ...]) -> {ok, #state{}} | {error, {fatal, bad_config}}. init({FileName, LogLevel}) when is_list(FileName), is_atom(LogLevel) -> %% backwards compatibility hack init([{file, FileName}, {level, LogLevel}]); init({FileName, LogLevel, Size, Date, Count}) when is_list(FileName), is_atom(LogLevel) -> %% backwards compatibility hack init([{file, FileName}, {level, LogLevel}, {size, Size}, {date, Date}, {count, Count}]); init([{FileName, LogLevel, Size, Date, Count}, {Formatter, FormatterConfig}]) when is_list(FileName), is_atom(LogLevel), is_atom(Formatter) -> %% backwards compatibility hack init([{file, FileName}, {level, LogLevel}, {size, Size}, {date, Date}, {count, Count}, {formatter, Formatter}, {formatter_config, FormatterConfig}]); init([LogFile, {Formatter}]) -> %% backwards compatibility hack init([LogFile, {Formatter, []}]); init([{FileName, LogLevel}, {Formatter, FormatterConfig}]) when is_list(FileName), is_atom(LogLevel), is_atom(Formatter) -> %% backwards compatibility hack init([{file, FileName}, {level, LogLevel}, {formatter, Formatter}, {formatter_config, FormatterConfig}]); init(LogFileConfig) when is_list(LogFileConfig) -> case validate_logfile_proplist(LogFileConfig) of false -> %% falied to validate config {error, {fatal, bad_config}}; Config -> %% probabably a better way to do this, but whatever [RelName, Level, Date, Size, Count, Rotator, HighWaterMark, Flush, SyncInterval, SyncSize, SyncOn, CheckInterval, Formatter, FormatterConfig] = [proplists:get_value(Key, Config) || Key <- [file, level, date, size, count, rotator, high_water_mark, flush_queue, sync_interval, sync_size, sync_on, check_interval, formatter, formatter_config]], FlushThr = proplists:get_value(flush_threshold, Config, 0), Name = rumUtil:parsePath(RelName), schedule_rotation(Name, Date), Shaper = rumUtil:maybe_flush(Flush, #rumShaper{hwm = HighWaterMark, flushThreshold = FlushThr, id = Name}), State0 = #state{name = Name, level = Level, size = Size, date = Date, count = Count, rotator = Rotator, shaper = Shaper, formatter = Formatter, formatter_config = FormatterConfig, sync_on = SyncOn, sync_interval = SyncInterval, sync_size = SyncSize, check_interval = CheckInterval}, State = case Rotator:create_logfile(Name, {SyncSize, SyncInterval}) of {ok, {FD, Inode, Ctime, _Size}} -> State0#state{fd = FD, inode = Inode, ctime = Ctime}; {error, Reason} -> ?INT_LOG(error, "Failed to open log file ~ts with error ~s", [Name, file:format_error(Reason)]), State0#state{flap = true} end, {ok, State} end. %% @private handle_call({set_loglevel, Level}, #state{name = Ident} = State) -> case validate_loglevel(Level) of false -> {ok, {error, bad_loglevel}, State}; Levels -> ?INT_LOG(notice, "Changed loglevel of ~s to ~p", [Ident, Level]), {ok, ok, State#state{level = Levels}} end; handle_call(get_loglevel, #state{level = Level} = State) -> {ok, Level, State}; handle_call({set_loghwm, Hwm}, #state{shaper = Shaper, name = Name} = State) -> case validate_logfile_proplist([{file, Name}, {high_water_mark, Hwm}]) of false -> {ok, {error, bad_log_hwm}, State}; _ -> NewShaper = Shaper#rumShaper{hwm = Hwm}, ?INT_LOG(notice, "Changed loghwm of ~ts to ~p", [Name, Hwm]), {ok, {last_loghwm, Shaper#rumShaper.hwm}, State#state{shaper = NewShaper}} end; handle_call(rotate, State = #state{name = File}) -> {ok, NewState} = handle_info({rotate, File}, State), {ok, ok, NewState}; handle_call(_Request, State) -> {ok, ok, State}. %% @private handle_event({log, Message}, #state{name = Name, level = L, shaper = Shaper, formatter = Formatter, formatter_config = FormatConfig} = State) -> case rumUtil:is_loggable(Message, L, {lager_file_backend, Name}) of true -> case rumUtil:check_hwm(Shaper) of {true, Drop, #rumShaper{hwm = Hwm} = NewShaper} -> NewState = case Drop > 0 of true -> Report = io_lib:format( "lager_file_backend dropped ~p messages in the last second that exceeded the limit of ~p messages/sec", [Drop, Hwm]), ReportMsg = rumMsg:new(Report, warning, [], []), write(State, rumMsg:timestamp(ReportMsg), rumMsg:severity_as_int(ReportMsg), Formatter:format(ReportMsg, FormatConfig)); false -> State end, {ok, write(NewState#state{shaper = NewShaper}, rumMsg:timestamp(Message), rumMsg:severity_as_int(Message), Formatter:format(Message, FormatConfig))}; {false, _, #rumShaper{dropped = D} = NewShaper} -> {ok, State#state{shaper = NewShaper#rumShaper{dropped = D + 1}}} end; false -> {ok, State} end; handle_event(_Event, State) -> {ok, State}. %% @private handle_info({rotate, File}, #state{name = File, count = Count, date = Date, rotator = Rotator} = State0) -> State1 = close_file(State0), _ = Rotator:rotate_logfile(File, Count), schedule_rotation(File, Date), {ok, State1}; handle_info({shaper_expired, Name}, #state{shaper = Shaper, name = Name, formatter = Formatter, formatter_config = FormatConfig} = State) -> _ = case Shaper#rumShaper.dropped of 0 -> ok; Dropped -> Report = io_lib:format( "lager_file_backend dropped ~p messages in the last second that exceeded the limit of ~p messages/sec", [Dropped, Shaper#rumShaper.hwm]), ReportMsg = rumMsg:new(Report, warning, [], []), write(State, rumMsg:timestamp(ReportMsg), rumMsg:severity_as_int(ReportMsg), Formatter:format(ReportMsg, FormatConfig)) end, {ok, State#state{shaper = Shaper#rumShaper{dropped = 0, mps = 0, lastTime = os:timestamp()}}}; handle_info(_Info, State) -> {ok, State}. %% @private terminate(_Reason, State) -> %% leaving this function call unmatched makes dialyzer cranky _ = close_file(State), ok. %% @private code_change(_OldVsn, State, _Extra) -> {ok, State}. %% Convert the config into a gen_event handler ID config_to_id({Name, _Severity}) when is_list(Name) -> {?MODULE, Name}; config_to_id({Name, _Severity, _Size, _Rotation, _Count}) -> {?MODULE, Name}; config_to_id([{Name, _Severity, _Size, _Rotation, _Count}, _Format]) -> {?MODULE, Name}; config_to_id([{Name, _Severity}, _Format]) when is_list(Name) -> {?MODULE, Name}; config_to_id(Config) -> case proplists:get_value(file, Config) of undefined -> erlang:error(no_file); File -> {?MODULE, File} end. write(#state{name = Name, fd = FD, inode = Inode, ctime = Ctime, flap = Flap, size = RotSize, count = Count, rotator = Rotator} = State0, Timestamp, Level, Msg) -> case write_should_check(State0, Timestamp) of true -> %% need to check for rotation Buffer = {State0#state.sync_size, State0#state.sync_interval}, case Rotator:ensure_logfile(Name, FD, Inode, Ctime, Buffer) of {ok, {_FD, _Inode, _Ctime, Size}} when RotSize > 0, Size > RotSize -> State1 = close_file(State0), case Rotator:rotate_logfile(Name, Count) of ok -> %% go around the loop again, we'll do another rotation check and hit the next clause of ensure_logfile write(State1, Timestamp, Level, Msg); {error, Reason} -> case Flap of true -> State1; _ -> ?INT_LOG(error, "Failed to rotate log file ~ts with error ~s", [Name, file:format_error(Reason)]), State1#state{flap = true} end end; {ok, {NewFD, NewInode, NewCtime, _Size}} -> %% update our last check and try again State1 = State0#state{last_check = Timestamp, fd = NewFD, inode = NewInode, ctime = NewCtime}, do_write(State1, Level, Msg); {error, Reason} -> case Flap of true -> State0; _ -> ?INT_LOG(error, "Failed to reopen log file ~ts with error ~s", [Name, file:format_error(Reason)]), State0#state{flap = true} end end; false -> do_write(State0, Level, Msg) end. write_should_check(#state{fd = undefined}, _Timestamp) -> true; write_should_check(#state{last_check = LastCheck0, check_interval = CheckInterval, name = Name, inode = Inode0, ctime = Ctime0}, Timestamp) -> LastCheck1 = timer:now_diff(Timestamp, LastCheck0) div 1000, case LastCheck1 >= CheckInterval of true -> true; _ -> % We need to know if the file has changed "out from under lager" so we don't % write to an invalid FD {Result, _FInfo} = rumUtil:has_file_changed(Name, Inode0, Ctime0), Result end. do_write(#state{fd = FD, name = Name, flap = Flap} = State, Level, Msg) -> %% delayed_write doesn't report errors _ = file:write(FD, unicode:characters_to_binary(Msg)), {mask, SyncLevel} = State#state.sync_on, case (Level band SyncLevel) =/= 0 of true -> %% force a sync on any message that matches the 'sync_on' bitmask Flap2 = case file:datasync(FD) of {error, Reason2} when Flap == false -> ?INT_LOG(error, "Failed to write log message to file ~ts: ~s", [Name, file:format_error(Reason2)]), true; ok -> false; _ -> Flap end, State#state{flap = Flap2}; _ -> State end. validate_loglevel(Level) -> try rumUtil:config_to_mask(Level) of Levels -> Levels catch _:_ -> false end. validate_logfile_proplist(List) -> try validate_logfile_proplist(List, []) of Res -> case proplists:get_value(file, Res) of undefined -> ?INT_LOG(error, "Missing required file option", []), false; _File -> %% merge with the default options {ok, DefaultRotationDate} = rumUtil:parse_rotation_date_spec(?DEFAULT_ROTATION_DATE), lists:keymerge(1, lists:sort(Res), lists:sort([ {level, validate_loglevel(?DEFAULT_LOG_LEVEL)}, {date, DefaultRotationDate}, {size, ?DEFAULT_ROTATION_SIZE}, {count, ?DEFAULT_ROTATION_COUNT}, {rotator, ?DEFAULT_ROTATION_MOD}, {sync_on, validate_loglevel(?DEFAULT_SYNC_LEVEL)}, {sync_interval, ?DEFAULT_SYNC_INTERVAL}, {sync_size, ?DEFAULT_SYNC_SIZE}, {check_interval, ?DEFAULT_CHECK_INTERVAL}, {formatter, lager_default_formatter}, {formatter_config, []} ])) end catch {bad_config, Msg, Value} -> ?INT_LOG(error, "~s ~p for file ~tp", [Msg, Value, proplists:get_value(file, List)]), false end. validate_logfile_proplist([], Acc) -> Acc; validate_logfile_proplist([{file, File} | Tail], Acc) -> %% is there any reasonable validation we can do here? validate_logfile_proplist(Tail, [{file, File} | Acc]); validate_logfile_proplist([{level, Level} | Tail], Acc) -> case validate_loglevel(Level) of false -> throw({bad_config, "Invalid loglevel", Level}); Res -> validate_logfile_proplist(Tail, [{level, Res} | Acc]) end; validate_logfile_proplist([{size, Size} | Tail], Acc) -> case Size of S when is_integer(S), S >= 0 -> validate_logfile_proplist(Tail, [{size, Size} | Acc]); _ -> throw({bad_config, "Invalid rotation size", Size}) end; validate_logfile_proplist([{count, Count} | Tail], Acc) -> case Count of C when is_integer(C), C >= 0 -> validate_logfile_proplist(Tail, [{count, Count} | Acc]); _ -> throw({bad_config, "Invalid rotation count", Count}) end; validate_logfile_proplist([{rotator, Rotator} | Tail], Acc) -> case is_atom(Rotator) of true -> validate_logfile_proplist(Tail, [{rotator, Rotator} | Acc]); false -> throw({bad_config, "Invalid rotation module", Rotator}) end; validate_logfile_proplist([{high_water_mark, HighWaterMark} | Tail], Acc) -> case HighWaterMark of Hwm when is_integer(Hwm), Hwm >= 0 -> validate_logfile_proplist(Tail, [{high_water_mark, Hwm} | Acc]); _ -> throw({bad_config, "Invalid high water mark", HighWaterMark}) end; validate_logfile_proplist([{date, Date} | Tail], Acc) -> case rumUtil:parse_rotation_date_spec(Date) of {ok, Spec} -> validate_logfile_proplist(Tail, [{date, Spec} | Acc]); {error, _} when Date == "" -> %% legacy config allowed blanks validate_logfile_proplist(Tail, [{date, undefined} | Acc]); {error, _} -> throw({bad_config, "Invalid rotation date", Date}) end; validate_logfile_proplist([{sync_interval, SyncInt} | Tail], Acc) -> case SyncInt of Val when is_integer(Val), Val >= 0 -> validate_logfile_proplist(Tail, [{sync_interval, Val} | Acc]); _ -> throw({bad_config, "Invalid sync interval", SyncInt}) end; validate_logfile_proplist([{sync_size, SyncSize} | Tail], Acc) -> case SyncSize of Val when is_integer(Val), Val >= 0 -> validate_logfile_proplist(Tail, [{sync_size, Val} | Acc]); _ -> throw({bad_config, "Invalid sync size", SyncSize}) end; validate_logfile_proplist([{check_interval, CheckInt} | Tail], Acc) -> case CheckInt of Val when is_integer(Val), Val >= 0 -> validate_logfile_proplist(Tail, [{check_interval, Val} | Acc]); always -> validate_logfile_proplist(Tail, [{check_interval, 0} | Acc]); _ -> throw({bad_config, "Invalid check interval", CheckInt}) end; validate_logfile_proplist([{sync_on, Level} | Tail], Acc) -> case validate_loglevel(Level) of false -> throw({bad_config, "Invalid sync on level", Level}); Res -> validate_logfile_proplist(Tail, [{sync_on, Res} | Acc]) end; validate_logfile_proplist([{formatter, Fmt} | Tail], Acc) -> case is_atom(Fmt) of true -> validate_logfile_proplist(Tail, [{formatter, Fmt} | Acc]); false -> throw({bad_config, "Invalid formatter module", Fmt}) end; validate_logfile_proplist([{formatter_config, FmtCfg} | Tail], Acc) -> case is_list(FmtCfg) of true -> validate_logfile_proplist(Tail, [{formatter_config, FmtCfg} | Acc]); false -> throw({bad_config, "Invalid formatter config", FmtCfg}) end; validate_logfile_proplist([{flush_queue, FlushCfg} | Tail], Acc) -> case is_boolean(FlushCfg) of true -> validate_logfile_proplist(Tail, [{flush_queue, FlushCfg} | Acc]); false -> throw({bad_config, "Invalid queue flush flag", FlushCfg}) end; validate_logfile_proplist([{flush_threshold, Thr} | Tail], Acc) -> case Thr of _ when is_integer(Thr), Thr >= 0 -> validate_logfile_proplist(Tail, [{flush_threshold, Thr} | Acc]); _ -> throw({bad_config, "Invalid queue flush threshold", Thr}) end; validate_logfile_proplist([Other | _Tail], _Acc) -> throw({bad_config, "Invalid option", Other}). schedule_rotation(_, undefined) -> ok; schedule_rotation(Name, Date) -> erlang:send_after(rumUtil:calculate_next_rotation(Date) * 1000, self(), {rotate, Name}), ok. close_file(#state{fd = undefined} = State) -> State; close_file(#state{fd = FD} = State) -> %% Flush and close any file handles. %% delayed write can cause file:close not to do a close _ = file:datasync(FD), _ = file:close(FD), _ = file:close(FD), State#state{fd = undefined}. -ifdef(TEST). get_loglevel_test() -> {ok, Level, _} = handle_call(get_loglevel, #state{name = "bar", level = rumUtil:config_to_mask(info), fd = 0, inode = 0, ctime = undefined}), ?assertEqual(Level, rumUtil:config_to_mask(info)), {ok, Level2, _} = handle_call(get_loglevel, #state{name = "foo", level = rumUtil:config_to_mask(warning), fd = 0, inode = 0, ctime = undefined}), ?assertEqual(Level2, rumUtil:config_to_mask(warning)). rotation_test_() -> {foreach, fun() -> SyncLevel = validate_loglevel(?DEFAULT_SYNC_LEVEL), SyncSize = ?DEFAULT_SYNC_SIZE, SyncInterval = ?DEFAULT_SYNC_INTERVAL, Rotator = ?DEFAULT_ROTATION_MOD, CheckInterval = 0, %% hard to test delayed mode {ok, TestDir} = rumUtil:create_test_dir(), TestLog = filename:join(TestDir, "test.log"), {OsType, _} = os:type(), #state{name = TestLog, level = ?DEBUG, sync_on = SyncLevel, sync_size = SyncSize, sync_interval = SyncInterval, check_interval = CheckInterval, rotator = Rotator, os_type = OsType} end, fun(#state{}) -> ok = rumUtil:delete_test_dir() end, [ fun(DefaultState = #state{name = TestLog, os_type = OsType, sync_size = SyncSize, sync_interval = 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:open_logfile(TestLog, {SyncSize, SyncInterval}), State0 = DefaultState#state{fd = FD, inode = Inode, ctime = Ctime}, State1 = write(State0, os:timestamp(), ?DEBUG, "hello world"), ?assertMatch(#state{name = TestLog, level = ?DEBUG, fd = FD, inode = Inode, ctime = Ctime}, State1), ?assertEqual(ok, file:delete(TestLog)), State2 = write(State0, os:timestamp(), ?DEBUG, "hello world"), %% assert file has changed ExpState1 = #state{name = TestLog, level = ?DEBUG, fd = FD, inode = Inode, ctime = Ctime}, ?assertNotEqual(ExpState1, State2), ?assertMatch(#state{name = TestLog, level = ?DEBUG}, State2), ?assertEqual(ok, file:rename(TestLog, TestLog ++ ".1")), State3 = write(State2, os:timestamp(), ?DEBUG, "hello world"), %% assert file has changed ?assertNotEqual(State3, State2), ?assertMatch(#state{name = TestLog, level = ?DEBUG}, State3), ok end end} end, fun(DefaultState = #state{name = TestLog, sync_size = SyncSize, sync_interval = 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:open_logfile(TestLog, {SyncSize, SyncInterval}), State0 = DefaultState#state{ fd = FD, inode = Inode, ctime = Ctime, size = RotationSize, check_interval = CheckInterval, last_check = PreviousCheck}, %% new message within check interval with sync_on level Msg1Timestamp = add_secs(PreviousCheck, 1), State1 = write(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 = write(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.last_check), ?assertNot(filelib:is_regular(TestLog0)), %% new message after check interval Msg3Timestamp = add_secs(PreviousCheck, 4), _State3 = write(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) ! {rotate, 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}, rotate, 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:set_loglevel(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:set_loglevel(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}, {flush_queue, 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, validate_logfile_proplist([{level, info}, {size, 10}])) }, {"bad level", ?_assertEqual(false, validate_logfile_proplist([{file, "test.log"}, {level, blah}, {size, 10}])) }, {"bad size", ?_assertEqual(false, validate_logfile_proplist([{file, "test.log"}, {size, infinity}])) }, {"bad count", ?_assertEqual(false, validate_logfile_proplist([{file, "test.log"}, {count, infinity}])) }, {"bad high water mark", ?_assertEqual(false, validate_logfile_proplist([{file, "test.log"}, {high_water_mark, infinity}])) }, {"bad date", ?_assertEqual(false, validate_logfile_proplist([{file, "test.log"}, {date, "midnight"}])) }, {"blank date is ok", ?_assertMatch([_ | _], validate_logfile_proplist([{file, "test.log"}, {date, ""}])) }, {"bad sync_interval", ?_assertEqual(false, validate_logfile_proplist([{file, "test.log"}, {sync_interval, infinity}])) }, {"bad sync_size", ?_assertEqual(false, validate_logfile_proplist([{file, "test.log"}, {sync_size, infinity}])) }, {"bad check_interval", ?_assertEqual(false, validate_logfile_proplist([{file, "test.log"}, {check_interval, infinity}])) }, {"bad sync_on level", ?_assertEqual(false, validate_logfile_proplist([{file, "test.log"}, {sync_on, infinity}])) }, {"bad formatter module", ?_assertEqual(false, validate_logfile_proplist([{file, "test.log"}, {formatter, "io:format"}])) }, {"bad formatter config", ?_assertEqual(false, validate_logfile_proplist([{file, "test.log"}, {formatter_config, blah}])) }, {"unknown option", ?_assertEqual(false, validate_logfile_proplist([{file, "test.log"}, {rhubarb, spicy}])) } ]. -endif.