eLog/src/crashLog/rumCrashLog.erl

-module(rumCrashLog).

%% @doc eRum crash log writer。它将error_logger错误消息以其原始格式发送到`crash_log`指定的文件, 如果`crash_log`未设置则禁用crash logging
%% Crash logs are printed safely using trunc_io via code mostly lifted from riak_err.
%% `crashLogMsgSize` 应用程序var用于指定最大值要记录的任何消息的大小。
%% `crashLogFileSize` 用于指定崩溃日志的最大大小，然后将其旋转（0将禁用）。
%% `crashLogDate` 基于时间的轮播可通过配置，语法为自述文件中记录了
%% `crashLogCount` 控制要旋转的文件数已保留。

-behaviour(gen_srv).

-include("eRum.hrl").

-ifdef(TEST).
-include_lib("eunit/include/eunit.hrl").
-include_lib("kernel/include/file.hrl").
-endif.

-export([
   start/6
   , start_link/6

]).

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


-record(state, {
   fileName :: string()                          %% 文件名
   , fd :: pid() | undefined                     %% 文件句柄
   , inode :: integer() | undefined              %% 文件inode信息
   , ctime :: file:date_time() | undefined       %% 文件创建时间
   , maxFmtSize :: integer()                     %% 单个消息最大字节数
   , maxFileSize :: integer()                    %% 单个日志文件最大字节数
   , date :: undefined | string()                %% 旋转的时间格式
   , count :: integer()                          %% 要保留的已轮转崩溃日志的数量
   , flap = false :: boolean()                   %% ？？？？ 这是干啥的呢
   , rotator :: atom()                           %% 旋转模块实例
}).

start(Filename, MaxFmtSize, MaxFileSize, Date, Count, Rotator) ->
   gen_srv:start({local, ?MODULE}, ?MODULE, {Filename, MaxFmtSize, MaxFileSize, Date, Count, Rotator}, []).

start_link(Filename, MaxFmtSize, MaxFileSize, Date, Count, Rotator) ->
   gen_srv:start_link({local, ?MODULE}, ?MODULE, {Filename, MaxFmtSize, MaxFileSize, Date, Count, Rotator}, []).

init({RelFilename, MaxFmtSize, MaxFileSize, CfgDate, Count, Rotator} = A) ->
   {ok, Date} = rumUtil:parseRotateSpec(CfgDate),
   Filename = rumUtil:parsePath(RelFilename),
   case Rotator:openLogFile(Filename, false) of
      {ok, Fd, Inode, CTime, _Size} ->
         scheduleRotation(Date),
         {ok, #state{fileName = Filename, fd = Fd, inode = Inode, ctime = CTime, maxFmtSize = MaxFmtSize, maxFileSize = MaxFileSize, date = Date, count = Count, rotator = Rotator}};
      {error, Reason} ->
         ?INT_LOG(error, "Failed to open crash log file ~ts with error: ~s", [Filename, file:format_error(Reason)]),
         {ok, #state{fileName = Filename, maxFmtSize = MaxFmtSize, maxFileSize = MaxFileSize, date = Date, count = Count, flap = true, rotator = Rotator}}
   end.

handleCall({mWriteLog, Event}, State, _From) ->
   {Reply, NewState} = writeLog(Event, State),
   {reply, Reply, NewState};
handleCall(_Msg, _State, _From) ->
   ?ERR("~p call receive unexpect msg ~p ~n ", [?MODULE, _Msg]),
   {reply, ok}.

handleCast(_Msg, _State) ->
   ?ERR("~p cast receive unexpect msg ~p ~n ", [?MODULE, _Msg]),
   kpS.

handleInfo({mWriteLog, Event}, State) ->
   {_, NewState} = writeLog(Event, State),
   {noreply, NewState};
handleInfo(mRotate, #state{fileName = Name, count = Count, date = Date, rotator = Rotator}) ->
   _ = Rotator:rotateLogFile(Name, Count),
   scheduleRotation(Date),
   kpS;
handleInfo(_Msg, _State) ->
   ?ERR("~p info receive unexpect msg ~p ~n ", [?MODULE, _Msg]),
   kpS.

terminate(_Reason, _State) ->
   ok.

code_change(_OldVsn, State, _Extra) ->
   {ok, State}.

scheduleRotation(undefined) -> ok;
scheduleRotation(Date) ->
   erlang:send_after(rumUtil:calcNextRotateMs(Date), self(), mRotate),
   ok.

otherNodeSuffix(Pid) when node(Pid) =/= node() ->
   PidNode = node(Pid),
   case PidNode =/= node() of
      true ->
         <<"** at node ",  (atom_to_binary(node(Pid), utf8))/binary, " **\n">>;
      _ ->
         <<"">>
   end.

perhapsSaslReport(error_report, {Pid, Type, Report}, FmtMaxBytes) ->
   case rumStdlib:isErrorReport(Type) of
      true ->
         {saslTypeToReportHead(Type), Pid, saslLimitedStr(Type, Report, FmtMaxBytes), true};
      false ->
         {ignore, ignore, ignore, false}
   end;
%perhaps_a_sasl_report(info_report, {Pid, Type, Report}, FmtMaxBytes) ->
%case lager_stdlib:is_my_info_report(Type) of
%true ->
%{sasl_type_to_report_head(Type), Pid,
%sasl_limited_str(Type, Report, FmtMaxBytes), false};
%false ->
%{ignore, ignore, ignore, false}
%end;
perhapsSaslReport(_, _, _) ->
   {ignore, ignore, ignore, false}.

saslTypeToReportHead(supervisor_report) ->
   <<"SUPERVISOR REPORT">>;
saslTypeToReportHead(crash_report) ->
   <<"CRASH REPORT">>;
saslTypeToReportHead(progress) ->
   <<"PROGRESS REPORT">>.

saslLimitedStr(supervisor_report, Report, FmtMaxBytes) ->
   Name = rumStdlib:sup_get(supervisor, Report),
   Context = rumStdlib:sup_get(errorContext, Report),
   Reason = rumStdlib:sup_get(reason, Report),
   Offender = rumStdlib:sup_get(offender, Report),
   FmtString = <<"     Supervisor: ~p~n     Context:    ~p~n     Reason:     "
   "~s~n     Offender:   ~s~n~n">>,
   ReasonStr = eFmt:formatBin(<<"~p">>, [Reason], [{charsLimit, FmtMaxBytes}]),
   OffenderStr = eFmt:formatBin(<<"~p">>, [Offender], [{charsLimit, FmtMaxBytes}]),
   eFmt:format(FmtString, [Name, Context, ReasonStr, OffenderStr]);
saslLimitedStr(progress, Report, FmtMaxBytes) ->
   [begin
       BinStr = eFmt:formatBin(<<"~p">>, [Data], [{charsLimit, FmtMaxBytes}]),
       eFmt:formatBin("    ~16w: ~s~n", [Tag, BinStr])
    end || {Tag, Data} <- Report];
saslLimitedStr(crash_report, Report, FmtMaxBytes) ->
   rumStdlib:proc_lib_format(Report, FmtMaxBytes).

writeLog(Event, #state{fileName = FileName, fd = FD, inode = Inode, ctime = Ctime, flap = Flap, maxFmtSize = FmtMaxBytes, maxFileSize = RotSize, count = Count, rotator = Rotator} = State) ->
   %% borrowed from riak_err
   {ReportStr, Pid, MsgStr, _ErrorP} =
      case Event of
         {error, _GL, {Pid1, Fmt, Args}} ->
            {<<"ERROR REPORT">>, Pid1, eFmt:formatBin(Fmt, Args, [{charsLimit, FmtMaxBytes}]), true};
         {error_report, _GL, {Pid1, std_error, Rep}} ->
            {<<"ERROR REPORT">>, Pid1, eFmt:formatBin(<<"~p\n">>, [Rep], [{charsLimit, FmtMaxBytes}]), true};
         {error_report, _GL, Other} ->
            perhapsSaslReport(error_report, Other, FmtMaxBytes);
         _ ->
            {ignore, ignore, ignore, false}
      end,
   case ReportStr of
      ignore ->
         {ok, State};
      _ ->
         case Rotator:ensureLogFile(FileName, FD, Inode, Ctime, false) of
            {ok, NewFD, NewInode, NewCtime, FileSize} ->
               case RotSize > 0 andalso FileSize > RotSize of
                  true ->
                     _ = Rotator:rotateLogFile(FileName, Count),
                     handleCast({mWriteLog, Event}, State);
                  _ ->
                     TimeBinStr = rumUtil:msToBinStr(),
                     Time = [TimeBinStr, <<" =">>, ReportStr, <<"====\n">>],
                     NodeSuffix = otherNodeSuffix(Pid),
                     Msg = eFmt:formatBin("~s~s~s", [Time, MsgStr, NodeSuffix]),
                     case file:write(NewFD, unicode:characters_to_binary(Msg)) of
                        {error, Reason} when Flap == false ->
                           ?INT_LOG(error, "Failed to write log message to file ~ts: ~s", [FileName, file:format_error(Reason)]),
                           {ok, State#state{fd = NewFD, inode = NewInode, ctime = NewCtime, flap = true}};
                        ok ->
                           {ok, State#state{fd = NewFD, inode = NewInode, ctime = NewCtime, flap = false}};
                        _ ->
                           {ok, State#state{fd = NewFD, inode = NewInode, ctime = NewCtime}}
                     end
               end;
            {error, Reason} ->
               ?IIF(Flap, {ok, State}, begin ?INT_LOG(error, "Failed to reopen crash log ~ts with error: ~s", [FileName, file:format_error(Reason)]), {ok, State#state{flap = true}} end)
         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.