lager/src/lager_crash_log.erl

%% -------------------------------------------------------------------
%%
%% Copyright (c) 2011-2017 Basho Technologies, Inc.
%%
%% This file is provided to you under the Apache License,
%% Version 2.0 (the "License"); you may not use this file
%% except in compliance with the License.  You may obtain
%% a copy of the License at
%%
%%   http://www.apache.org/licenses/LICENSE-2.0
%%
%% Unless required by applicable law or agreed to in writing,
%% software distributed under the License is distributed on an
%% "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY
%% KIND, either express or implied.  See the License for the
%% specific language governing permissions and limitations
%% under the License.
%%
%% -------------------------------------------------------------------

%% @doc Lager crash log writer. This module implements a gen_server which writes
%% error_logger error messages out to a file in their original format. The
%% location to which it logs is configured by the application var `crash_log'.
%% Omitting this variable disables crash logging. Crash logs are printed safely
%% using trunc_io via code mostly lifted from riak_err.
%%
%% The `crash_log_msg_size' application var is used to specify the maximum
%% size of any message to be logged. `crash_log_size' is used to specify the
%% maximum size of the crash log before it will be rotated (0 will disable).
%% Time based rotation is configurable via `crash_log_date', the syntax is
%% documented in the README. To control the number of rotated files to be
%% retained, use `crash_log_count'.

-module(lager_crash_log).

-include("lager.hrl").

-behaviour(gen_server).

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

%% callbacks
-export([init/1, handle_call/3, handle_cast/2, handle_info/2, terminate/2,
        code_change/3]).

-export([start_link/6, start/6]).

-record(state, {
        name :: string(),
        fd :: pid() | undefined,
        inode :: integer() | undefined,
        ctime :: file:date_time() | undefined,
        fmtmaxbytes :: integer(),
        size :: integer(),
        date :: undefined | string(),
        count :: integer(),
        flap=false :: boolean(),
        rotator :: atom()
}).

%% @private
start_link(Filename, MaxBytes, Size, Date, Count, Rotator) ->
    gen_server:start_link({local, ?MODULE}, ?MODULE, [Filename, MaxBytes,
            Size, Date, Count, Rotator], []).

%% @private
start(Filename, MaxBytes, Size, Date, Count, Rotator) ->
    gen_server:start({local, ?MODULE}, ?MODULE, [Filename, MaxBytes, Size,
            Date, Count, Rotator], []).

%% @private
init([RelFilename, MaxBytes, Size, Date, Count, Rotator]) ->
    Filename = lager_util:expand_path(RelFilename),
    case Rotator:open_logfile(Filename, false) of
        {ok, {FD, Inode, Ctime, _Size}} ->
            schedule_rotation(Date),
            {ok, #state{name=Filename, fd=FD, inode=Inode, ctime=Ctime,
                    fmtmaxbytes=MaxBytes, size=Size, count=Count, date=Date,
                    rotator=Rotator}};
        {error, Reason} ->
            ?INT_LOG(error, "Failed to open crash log file ~s with error: ~s",
                [Filename, file:format_error(Reason)]),
            {ok, #state{name=Filename, fmtmaxbytes=MaxBytes, flap=true,
                    size=Size, count=Count, date=Date, rotator=Rotator}}
    end.

%% @private
handle_call({log, _} = Log, _From, State) ->
    {Reply, NewState} = do_log(Log, State),
    {reply, Reply, NewState};
handle_call(_Call, _From, State) ->
    {reply, ok, State}.

%% @private
handle_cast({log, _} = Log, State) ->
    {_, NewState} = do_log(Log, State),
    {noreply, NewState};
handle_cast(_Request, State) ->
    {noreply, State}.

%% @private
handle_info(rotate, #state{name=Name, count=Count, date=Date, rotator=Rotator} = State) ->
    _ = Rotator:rotate_logfile(Name, Count),
    schedule_rotation(Date),
    {noreply, State};
handle_info(_Info, State) ->
    {noreply, State}.

%% @private
terminate(_Reason, _State) ->
    ok.

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

schedule_rotation(undefined) ->
    ok;
schedule_rotation(Date) ->
    erlang:send_after(lager_util:calculate_next_rotation(Date) * 1000, self(), rotate),
    ok.

%% ===== Begin code lifted from riak_err =====

-spec limited_fmt(string(), list(), integer()) -> iolist().
%% @doc Format Fmt and Args similar to what io_lib:format/2 does but with
%%      limits on how large the formatted string may be.
%%
%% If the Args list's size is larger than TermMaxSize, then the
%% formatting is done by trunc_io:print/2, where FmtMaxBytes is used
%% to limit the formatted string's size.

limited_fmt(Fmt, Args, FmtMaxBytes) ->
    lager:safe_format(Fmt, Args, FmtMaxBytes).

limited_str(Term, FmtMaxBytes) ->
    {Str, _} = lager_trunc_io:print(Term, FmtMaxBytes),
    Str.

other_node_suffix(Pid) when node(Pid) =/= node() ->
    "** at node " ++ atom_to_list(node(Pid)) ++ " **\n";
other_node_suffix(_) ->
    "".

perhaps_a_sasl_report(error_report, {Pid, Type, Report}, FmtMaxBytes) ->
    case lager_stdlib:is_my_error_report(Type) of
        true ->
            {sasl_type_to_report_head(Type), Pid,
                sasl_limited_str(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;
perhaps_a_sasl_report(_, _, _) ->
    {ignore, ignore, ignore, false}.

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

sasl_limited_str(supervisor_report, Report, FmtMaxBytes) ->
    Name = lager_stdlib:sup_get(supervisor, Report),
    Context = lager_stdlib:sup_get(errorContext, Report),
    Reason = lager_stdlib:sup_get(reason, Report),
    Offender = lager_stdlib:sup_get(offender, Report),
    FmtString = "     Supervisor: ~p~n     Context:    ~p~n     Reason:     "
    "~s~n     Offender:   ~s~n~n",
    {ReasonStr, _} = lager_trunc_io:print(Reason, FmtMaxBytes),
    {OffenderStr, _} = lager_trunc_io:print(Offender, FmtMaxBytes),
    io_lib:format(FmtString, [Name, Context, ReasonStr, OffenderStr]);
sasl_limited_str(progress, Report, FmtMaxBytes) ->
    [begin
                {Str, _} = lager_trunc_io:print(Data, FmtMaxBytes),
                io_lib:format("    ~16w: ~s~n", [Tag, Str])
        end || {Tag, Data} <- Report];
sasl_limited_str(crash_report, Report, FmtMaxBytes) ->
    lager_stdlib:proc_lib_format(Report, FmtMaxBytes).

do_log({log, Event}, #state{name=Name, fd=FD, inode=Inode, ctime=Ctime, flap=Flap,
        fmtmaxbytes=FmtMaxBytes, size=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, limited_fmt(Fmt, Args, FmtMaxBytes), true};
        {error_report, _GL, {Pid1, std_error, Rep}} ->
            {"ERROR REPORT", Pid1, limited_str(Rep, FmtMaxBytes) ++ "\n", true};
        {error_report, _GL, Other} ->
            perhaps_a_sasl_report(error_report, Other, FmtMaxBytes);
        _ ->
            {ignore, ignore, ignore, false}
    end,
    if ReportStr == ignore ->
            {ok, State};
        true ->
            case Rotator:ensure_logfile(Name, FD, Inode, Ctime, false) of
                {ok, {_FD, _Inode, _Ctime, Size}} when RotSize /= 0, Size > RotSize ->
                    _ = Rotator:rotate_logfile(Name, Count),
                    handle_cast({log, Event}, State);
                {ok, {NewFD, NewInode, NewCtime, _Size}} ->
                    {Date, TS} = lager_util:format_time(
                        lager_stdlib:maybe_utc(erlang:localtime())),
                    Time = [Date, " ", TS," =", ReportStr, "====\n"],
                    NodeSuffix = other_node_suffix(Pid),
                    Msg = io_lib:format("~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 ~s: ~s",
                                [Name, 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;
                {error, Reason} ->
                    case Flap of
                        true ->
                            {ok, State};
                        _ ->
                            ?INT_LOG(error, "Failed to reopen crash log ~s with error: ~s",
                                [Name, file:format_error(Reason)]),
                            {ok, State#state{flap=true}}
                    end
            end
    end.


-ifdef(TEST).

filesystem_test_() ->
    {foreach,
        fun() ->
            {ok, TestDir} = lager_util:get_test_dir(),
            CrashLog = filename:join(TestDir, "crash_test.log"),
            ok = lager_test_util:safe_write_file(CrashLog, []),
            ok = error_logger:tty(false),
            ok = lager_test_util:safe_application_load(lager),
            ok = application:set_env(lager, handlers, [{lager_test_backend, info}]),
            ok = application:set_env(lager, error_logger_redirect, true),
            ok = application:unset_env(lager, crash_log),
            ok = lager: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 = lager_util: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() ->
                {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()),
                file:delete(CrashLog),
                ok = lager_test_util: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,
        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() ->
                {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, lager_test_util: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
    ]}.

-endif.