eLog/src/backend/rumBkdFile.erl

-module(rumBkdFile).

%% @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.

-include("eRum.hrl").
-include_lib("kernel/include/file.hrl").

-behaviour(gen_emm).

-ifdef(TEST).
-include_lib("eunit/include/eunit.hrl").
-compile([{parse_transform, lager_transform}]).
-endif.

-export([config_to_id/1]).

-export([
   init/1
   , handleCall/2
   , handleEvent/2
   , handleInfo/2
   , terminate/2
   , code_change/3
]).

-record(state, {
   fileName :: 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(),
   formatterConfig :: any(),
   sync_on :: {'mask', integer()},
   checkInterval = ?RumDefCheckInterval :: non_neg_integer(),
   syncInterval = ?RumDefSyncInterval :: non_neg_integer(),
   sync_size = ?RumDefSyncSize :: non_neg_integer(),
   lastCheck = os:timestamp() :: erlang:timestamp(),
   osType :: 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(Opts) ->
   true = checkOpts(Opts, false),
   RelName = rumUtil:get_opt(file, Opts, undefined),
   CfgLevel = rumUtil:get_opt(level, Opts, ?RumDefLogLevel),
   CfgDate = rumUtil:get_opt(date, Opts, ?RumDefRotateDate),
   Size = rumUtil:get_opt(size, Opts, ?RumDefRotateSize),
   Count = rumUtil:get_opt(count, Opts, ?RumDefRotateCnt),
   Rotator = rumUtil:get_opt(rotator, Opts, ?RumDefRotateMod),
   HighWaterMark = rumUtil:get_opt(high_water_mark, Opts, ?RumDefCheckHWM),
   Flush = rumUtil:get_opt(flush_queue, Opts, ?RumDefFlushQueue),
   FlushThr = rumUtil:get_opt(flush_threshold, Opts, ?RumDefFlushThreshold),
   SyncInterval = rumUtil:get_opt(sync_interval, Opts, ?RumDefSyncInterval),
   CfgCheckInterval = rumUtil:get_opt(check_interval, Opts, ?RumDefCheckInterval),
   SyncSize = rumUtil:get_opt(sync_size, Opts, ?RumDefSyncSize),
   CfgSyncOn = rumUtil:get_opt(sync_on, Opts, ?RumDefSyncLevel),
   Formatter = rumUtil:get_opt(formatter, Opts, ?RumDefFormatter),
   FormatterConfig = rumUtil:get_opt(formatter_config, Opts, ?RumDefFormatterCfg),

   %% 需要二次转换的配置在这里处理
   Level = validate_loglevel(CfgLevel),
   SyncOn = validate_loglevel(CfgSyncOn),
   CheckInterval = ?IIF(CfgCheckInterval == always, 0, CfgCheckInterval),
   {ok, Date} = rumUtil:parseRotateSpec(CfgDate),

   FileName = rumUtil:parsePath(RelName),
   scheduleRotation(Date, FileName),
   Shaper = rumUtil:maybe_flush(Flush, #rumShaper{hwm = HighWaterMark, flushThreshold = FlushThr, id = FileName}),
   TemState = #state{
      fileName = FileName, level = Level, size = Size, date = Date
      , count = Count, rotator = Rotator, shaper = Shaper
      , formatter = Formatter, formatterConfig = FormatterConfig
      , sync_on = SyncOn, syncInterval = SyncInterval
      , sync_size = SyncSize, checkInterval = CheckInterval
   },
   case Rotator:createLogfile(FileName, {SyncSize, SyncInterval}) of
      {ok, Fd, Inode, Ctime, _Size} ->
         {ok, TemState#state{fd = Fd, inode = Inode, ctime = Ctime}};
      {error, Reason} ->
         ?INT_LOG(error, "Failed to open log file ~ts with error ~s", [FileName, file:format_error(Reason)]),
         {ok, TemState#state{flap = true}}
   end.

handleCall(mGetLogLevel, #state{level = Level} = State) ->
   {reply, Level, State};
handleCall({mSetLogLevel, Level}, #state{fileName = Ident} = State) ->
   case validate_loglevel(Level) of
      false ->
         {reply, {error, bad_loglevel}, State};
      Levels ->
         ?INT_LOG(notice, "Changed loglevel of ~s to ~p", [Ident, Level]),
         {reply, ok, State#state{level = Levels}}
   end;

handleCall({mSetLogHwm, Hwm}, #state{shaper = Shaper, fileName = FileName} = State) ->
   case checkOpts([{high_water_mark, Hwm}], true) of
      false ->
         {reply, {error, bad_log_hwm}, State};
      _ ->
         NewShaper = Shaper#rumShaper{hwm = Hwm},
         ?INT_LOG(notice, "Changed loghwm of ~ts to ~p", [FileName, Hwm]),
         {reply, {last_loghwm, Shaper#rumShaper.hwm}, State#state{shaper = NewShaper}}
   end;
handleCall(mRotate, State = #state{fileName = File}) ->
   {ok, NewState} = handleInfo({mRotate, File}, State),
   {reply, ok, NewState};
handleCall(_Msg, State) ->
   ?ERR("~p call receive unexpect msg ~p ~n ", [?MODULE, _Msg]),
   {reply, ok, State}.

handleEvent({mWriteLog, Message}, #state{fileName = FileName, level = L, shaper = Shaper, formatter = Formatter, formatterConfig = FormatConfig} = State) ->
   case rumUtil:is_loggable(Message, L, {rumBkdFile, FileName}) 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));
                     _ ->
                        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;
      _ ->
         kpS
   end;
handleEvent(_Msg, _State) ->
   ?ERR("~p event receive unexpect msg ~p ~n ", [?MODULE, _Msg]),
   kpS.

handleInfo({mRotate, File}, #state{fileName = File, count = Count, date = Date, rotator = Rotator} = State0) ->
   State1 = close_file(State0),
   _ = Rotator:rotateLogfile(File, Count),
   scheduleRotation(File, Date),
   {ok, State1};
handleInfo({shaper_expired, Name}, #state{shaper = Shaper, fileName = Name, formatter = Formatter, formatterConfig = 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()}}};
handleInfo(_Info, State) ->
   {ok, State}.

terminate(_Reason, State) ->
   %% leaving this function call unmatched makes dialyzer cranky
   _ = close_file(State),
   ok.

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{fileName = 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.syncInterval},
         case Rotator:ensureLogfile(Name, FD, Inode, Ctime, Buffer) of
            {ok, {_FD, _Inode, _Ctime, Size}} when RotSize > 0, Size > RotSize ->
               State1 = close_file(State0),
               case Rotator:rotateLogfile(Name, Count) of
                  ok ->
                     %% go around the loop again, we'll do another rotation check and hit the next clause of ensureLogfile
                     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{lastCheck = 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{lastCheck = LastCheck0, checkInterval = CheckInterval,
   fileName = 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:isFileChanged(Name, Inode0, Ctime0),
         Result
   end.

do_write(#state{fd = FD, fileName = 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.

checkOpts([], IsFile) ->
   ?IIF(IsFile, true, {error, no_file_name});
checkOpts([{file, _File} | Tail], _IsFile) ->
   checkOpts(Tail, true);
checkOpts([{level, Level} | Tail], IsFile) ->
   ?IIF(validate_loglevel(Level), checkOpts(Tail, IsFile), ({error, {invalid_log_level, Level}}));
checkOpts([{size, Size} | Tail], IsFile) when is_integer(Size), Size >= 0 ->
   checkOpts(Tail, IsFile);
checkOpts([{count, Count} | Tail], IsFile) when is_integer(Count), Count >= 0 ->
   checkOpts(Tail, IsFile);
checkOpts([{rotator, Rotator} | Tail], IsFile) when is_atom(Rotator) ->
   checkOpts(Tail, IsFile);
checkOpts([{high_water_mark, HighWaterMark} | Tail], IsFile) when is_integer(HighWaterMark), HighWaterMark >= 0 ->
   checkOpts(Tail, IsFile);
checkOpts([{date, _Date} | Tail], IsFile) ->
   checkOpts(Tail, IsFile);
checkOpts([{sync_interval, SyncInt} | Tail], IsFile) when is_integer(SyncInt), SyncInt >= 0 ->
   checkOpts(Tail, IsFile);
checkOpts([{sync_size, SyncSize} | Tail], IsFile) when is_integer(SyncSize), SyncSize >= 0 ->
   checkOpts(Tail, IsFile);
checkOpts([{check_interval, CheckInt} | Tail], IsFile) when is_integer(CheckInt), CheckInt >= 0; CheckInt == always ->
   checkOpts(Tail, IsFile);
checkOpts([{sync_on, _Level} | Tail], IsFile) ->
   checkOpts(Tail, IsFile);
checkOpts([{formatter, Fmt} | Tail], IsFile) when is_atom(Fmt) ->
   checkOpts(Tail, IsFile);
checkOpts([{formatter_config, FmtCfg} | Tail], IsFile) when is_list(FmtCfg) ->
   checkOpts(Tail, IsFile);
checkOpts([{flush_queue, FlushCfg} | Tail], IsFile) when is_boolean(FlushCfg) ->
   checkOpts(Tail, IsFile);
checkOpts([{flush_threshold, Thr} | Tail], IsFile) when is_integer(Thr), Thr >= 0 ->
   checkOpts(Tail, IsFile);
checkOpts([Other | _Tail], _IsFile) ->
   {error, {invalid_opt, Other}}.

scheduleRotation(undefined, _FileName) ->
   ok;
scheduleRotation(Date, Name) ->
   erlang:send_after(rumUtil:calcNextRotateMs(Date), self(), {mRotate, 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, _} = handleCall(mGetLogLevel,
      #state{fileName = "bar", level = rumUtil:config_to_mask(info), fd = 0, inode = 0, ctime = undefined}),
   ?assertEqual(Level, rumUtil:config_to_mask(info)),
   {ok, Level2, _} = handleCall(mGetLogLevel,
      #state{fileName = "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(?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,
            sync_on = SyncLevel,
            sync_size = 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, sync_size = 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 = write(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 = write(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 = write(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, sync_size = 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 = 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.lastCheck),
               ?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) ! {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: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,
            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.