eLog/src/errLogger/rumErrLoggerH.erl

-module(rumErrLoggerH).

%% 一个error_logger后端，用于将事件重定向到eRum。
%% 错误消息和崩溃日志也可以选择写入崩溃日志。 @see rumCrashLog

-include("eRum.hrl").

-behaviour(gen_event).

-export([
   setHighWater/1
   , format_reason/1
   , format_mfa/1
   , format_args/3
]).

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

-record(state, {
   sink :: atom(),
   shaper :: rumShaper(),
   %% group leader strategy
   groupleader_strategy :: handle | ignore | mirror,
   raw :: boolean()
}).

-define(LOGMSG(Sink, Level, Pid, Msg),
   case ?RunShouldLog(Sink, Level) of
      true ->
         _ = eRum:log(Sink, Level, Pid, Msg, []),
         logged;
      _ -> no_log
   end).

-define(LOGFMT(Sink, Level, Pid, Fmt, Args),
   case ?RunShouldLog(Sink, Level) of
      true ->
         _ = eRum:log(Sink, Level, Pid, Fmt, Args),
         logged;
      _ -> no_log
   end).

-ifdef(TEST).
%% Make CRASH synchronous when testing, to avoid timing headaches
-define(CRASH_LOG(Event),
   catch (gen_srv:call(rumCrashLog, {mWriteLog, Event}))).
-else.
-define(CRASH_LOG(Event),
   gen_srv:send(rumCrashLog, {mWriteLog, Event})).
-endif.

setHighWater(N) ->
   gen_event:call(error_logger, ?MODULE, {mSetHighWater, N}, infinity).

-spec init(any()) -> {ok, #state{}}.
init([HighWaterMark, GlStrategy]) ->
   Flush = rumUtil:get_env(errLoggerFlushQueue, true),
   FlushThr = rumUtil:get_env(errLoggerFlushThreshold, 0),
   Shaper = #rumShaper{hwm = HighWaterMark, flushQueue = Flush, flushThreshold = FlushThr, filter = shaperFun(), id = ?MODULE},
   Raw = rumUtil:get_env(errLoggerFormatRaw, false),
   Sink = configSink(),
   {ok, #state{sink = Sink, shaper = Shaper, groupleader_strategy = GlStrategy, raw = Raw}}.

handle_call({mSetHighWater, N}, #state{shaper = Shaper} = State) ->
   NewShaper = Shaper#rumShaper{hwm = N},
   {ok, ok, State#state{shaper = NewShaper}};
handle_call(_Request, State) ->
   {ok, unknown_call, State}.

shaperFun() ->
   SupSS = rumUtil:get_env(suppress_supervisor_start_stop, false),
   AppSS = rumUtil:get_env(suppress_application_start_stop, false),
   if
      SupSS andalso AppSS ->
         fun suppress_supervisor_start_and_application_start/1;
      SupSS ->
         fun suppress_supervisor_start/1;
      AppSS ->
         fun suppress_application_start/1;
      true ->
         fun(_) -> false end
   end.

suppress_supervisor_start_and_application_start(E) ->
   suppress_supervisor_start(E) orelse suppress_application_start(E).

suppress_application_start({info_report, _GL, {_Pid, std_info, D}}) when is_list(D) ->
   lists:member({exited, stopped}, D);
suppress_application_start({info_report, _GL, {_P, progress, D}}) ->
   lists:keymember(application, 1, D) andalso lists:keymember(started_at, 1, D);
suppress_application_start(_) ->
   false.

suppress_supervisor_start({info_report, _GL, {_P, progress, D}}) ->
   lists:keymember(started, 1, D) andalso lists:keymember(supervisor, 1, D);
suppress_supervisor_start(_) ->
   false.

handle_event(Event, #state{sink = Sink, shaper = Shaper} = State) ->
   case rumUtil:checkHwm(Shaper, Event) of
      {true, _Drop, NewShaper} ->
         evalGl(Event, State#state{shaper = NewShaper});
      {drop, Drop, NewShaper} ->
         case Drop =< 0 of
            true ->
               {ok, State#state{shaper = NewShaper}};
            _ ->
               ?LOGFMT(Sink, warning, self(), "lager_error_logger_h dropped ~p messages in the last second that exceeded the limit of ~p messages/sec", [Drop, NewShaper#rumShaper.hwm]),
               evalGl(Event, State#state{shaper = NewShaper})
         end;
      {false, _, NewShaper} ->
         {ok, State#state{shaper = NewShaper}}
   end.

handle_info({mShaperExpired, ?MODULE}, #state{sink = Sink, shaper = Shaper} = State) ->
   case Shaper#rumShaper.dropped of
      0 ->
         ignore;
      Dropped ->
         ?LOGFMT(Sink, warning, self(), "lager_error_logger_h dropped ~p messages in the last second that exceeded the limit of ~p messages/sec", [Dropped, Shaper#rumShaper.hwm])
   end,
   {ok, State#state{shaper = Shaper#rumShaper{dropped = 0, mps = 0, lastTime = rumTime:now()}}};
handle_info(_Info, State) ->
   {ok, State}.

terminate(_Reason, _State) ->
   ok.

code_change(_OldVsn, {state, Shaper, GLStrategy}, _Extra) ->
   Raw = rumUtil:get_env(errLoggerFormatRaw, false),
   {ok, #state{
      sink = configSink(),
      shaper = Shaper,
      groupleader_strategy = GLStrategy,
      raw = Raw
   }};
code_change(_OldVsn, {state, Sink, Shaper, GLS}, _Extra) ->
   Raw = rumUtil:get_env(errLoggerFormatRaw, false),
   {ok, #state{sink = Sink, shaper = Shaper, groupleader_strategy = GLS, raw = Raw}};
code_change(_OldVsn, State, _Extra) ->
   {ok, State}.

configSink() ->
   case rumUtil:get_opt(?RumErrLogSink, rumUtil:get_env(extraSinks, []), undefined) of
      undefined -> ?RumDefSink;
      _ -> ?RumErrLogSink
   end.

evalGl(Event, #state{groupleader_strategy = GlStrategy0} = State) ->
   GL = element(2, Event),
   case is_pid(GL) andalso node(GL) =/= node() of
      true ->
         case GlStrategy0 of
            ignore ->
               gen_event:notify({error_logger, node(GL)}, Event),
               {ok, State};
            mirror ->
               gen_event:notify({error_logger, node(GL)}, Event),
               logEvent(Event, State);
            _ ->
               logEvent(Event, State)
         end;
      _ ->
         logEvent(Event, State)
   end.

logEvent(Event, #state{sink = Sink, raw = FormatRaw} = State) ->
   DidLog =
      case Event of
         {error, _GL, {Pid, Fmt, Args}} ->
            case FormatRaw of
               false ->
                  case Fmt of
                     "** Generic server " ++ _ ->
                        %% gen_server terminate
                        {Reason, Name} =
                           case Args of
                              [N, _Msg, _State, R] ->
                                 {R, N};
                              [N, _Msg, _State, R, _Client] ->
                                 %% OTP 20 crash reports where the client pid is dead don't include the stacktrace
                                 {R, N};
                              [N, _Msg, _State, R, _Client, _Stacktrace] ->
                                 %% OTP 20 crash reports contain the pid of the client and stacktrace
                                 %% TODO do something with them
                                 {R, N}
                           end,
                        ?CRASH_LOG(Event),
                        {Md, Formatted} = format_reason_md(Reason),
                        ?LOGFMT(Sink, error, [{pid, Pid}, {name, Name} | Md], "gen_server ~w terminated with reason: ~s", [Name, Formatted]);
                     "** gen_ipc State machine " ++ _ ->
                        %% gen_server terminate
                        {Reason, Name} =
                           case Args of
                              [N, _Msg, _State, R] ->
                                 {R, N};
                              [N, _Msg, _State, R, _Client] ->
                                 %% OTP 20 crash reports where the client pid is dead don't include the stacktrace
                                 {R, N};
                              [N, _Msg, _State, R, _Client, _Stacktrace] ->
                                 %% OTP 20 crash reports contain the pid of the client and stacktrace
                                 %% TODO do something with them
                                 {R, N}
                           end,
                        ?CRASH_LOG(Event),
                        {Md, Formatted} = format_reason_md(Reason),
                        ?LOGFMT(Sink, error, [{pid, Pid}, {name, Name} | Md], "gen_ipc ~w terminated with reason: ~s", [Name, Formatted]);
                     "** State machine " ++ _ ->
                        %% Check if the terminated process is gen_fsm or gen_statem
                        %% since they generate the same exit message
                        {Type, Name, StateName, Reason} =
                           case Args of
                              [TName, _Msg, TStateName, _StateData, TReason] ->
                                 {gen_fsm, TName, TStateName, TReason};
                              %% Handle changed logging in gen_fsm stdlib-3.9 (TPid, ClientArgs)
                              [TName, _Msg, TPid, TStateName, _StateData, TReason | _ClientArgs] when is_pid(TPid), is_atom(TStateName) ->
                                 {gen_fsm, TName, TStateName, TReason};
                              %% Handle changed logging in gen_statem stdlib-3.9 (ClientArgs)
                              [TName, _Msg, {TStateName, _StateData}, _ExitType, TReason, _CallbackMode, Stacktrace | _ClientArgs] ->
                                 {gen_statem, TName, TStateName, {TReason, Stacktrace}};
                              %% Handle changed logging in gen_statem stdlib-3.9 (ClientArgs)
                              [TName, {TStateName, _StateData}, _ExitType, TReason, _CallbackMode, Stacktrace | _ClientArgs] ->
                                 {gen_statem, TName, TStateName, {TReason, Stacktrace}};
                              [TName, _Msg, [{TStateName, _StateData}], _ExitType, TReason, _CallbackMode, Stacktrace | _ClientArgs] ->
                                 %% sometimes gen_statem wraps its statename/data in a list for some reason???
                                 {gen_statem, TName, TStateName, {TReason, Stacktrace}}
                           end,
                        {Md, Formatted} = format_reason_md(Reason),
                        ?CRASH_LOG(Event),
                        ?LOGFMT(Sink, error, [{pid, Pid}, {name, Name} | Md], "~s ~w in state ~w terminated with reason: ~s", [Type, Name, StateName, Formatted]);
                     "** gen_event handler" ++ _ ->
                        %% gen_event handler terminate
                        [ID, Name, _Msg, _State, Reason] = Args,
                        {Md, Formatted} = format_reason_md(Reason),
                        ?CRASH_LOG(Event),
                        ?LOGFMT(Sink, error, [{pid, Pid}, {name, Name} | Md], "gen_event ~w installed in ~w terminated with reason: ~s", [ID, Name, Formatted]);
                     "** Cowboy handler" ++ _ ->
                        %% Cowboy HTTP server error
                        ?CRASH_LOG(Event),
                        case Args of
                           [Module, Function, Arity, _Request, _State] ->
                              %% we only get the 5-element list when its a non-exported function
                              ?LOGFMT(Sink, error, Pid,
                                 "Cowboy handler ~p terminated with reason: call to undefined function ~p:~p/~p",
                                 [Module, Module, Function, Arity]);
                           [Module, Function, Arity, _Class, Reason | Tail] ->
                              %% any other cowboy error_format list *always* ends with the stacktrace
                              StackTrace = lists:last(Tail),
                              {Md, Formatted} = format_reason_md({Reason, StackTrace}),
                              ?LOGFMT(Sink, error, [{pid, Pid} | Md],
                                 "Cowboy handler ~p terminated in ~p:~p/~p with reason: ~s", [Module, Module, Function, Arity, Formatted])
                        end;
                     "Ranch listener " ++ _ ->
                        %% Ranch errors
                        ?CRASH_LOG(Event),
                        case Args of
                           %% Error logged by cowboy, which starts as ranch error
                           [Ref, ConnectionPid, StreamID, RequestPid, Reason, StackTrace] ->
                              {Md, Formatted} = format_reason_md({Reason, StackTrace}),
                              ?LOGFMT(Sink, error, [{pid, RequestPid} | Md],
                                 "Cowboy stream ~p with ranch listener ~p and connection process ~p "
                                 "had its request process exit with reason: ~s", [StreamID, Ref, ConnectionPid, Formatted]);
                           [Ref, _Protocol, Worker, {[{reason, Reason}, {mfa, {Module, Function, Arity}}, {stacktrace, StackTrace} | _], _}] ->
                              {Md, Formatted} = format_reason_md({Reason, StackTrace}),
                              ?LOGFMT(Sink, error, [{pid, Worker} | Md], "Ranch listener ~p terminated in ~p:~p/~p with reason: ~s", [Ref, Module, Function, Arity, Formatted]);
                           [Ref, _Protocol, Worker, Reason] ->
                              {Md, Formatted} = format_reason_md(Reason),
                              ?LOGFMT(Sink, error, [{pid, Worker} | Md], "Ranch listener ~p terminated with reason: ~s", [Ref, Formatted]);
                           [Ref, Protocol, Ret] ->
                              %% ranch_conns_sup.erl module line 119-123 has three parameters error msg, log it.
                              {Md, Formatted} = format_reason_md(Ret),
                              ?LOGFMT(Sink, error, [{pid, Protocol} | Md], "Ranch listener ~p terminated with result:~s", [Ref, Formatted])
                        end;
                     "webmachine error" ++ _ ->
                        %% Webmachine HTTP server error
                        ?CRASH_LOG(Event),
                        [Path, Error] = Args,
                        %% webmachine likes to mangle the stack, for some reason
                        StackTrace =
                           case Error of
                              {error, {error, Reason, Stack}} ->
                                 {Reason, Stack};
                              _ ->
                                 Error
                           end,
                        {Md, Formatted} = format_reason_md(StackTrace),
                        ?LOGFMT(Sink, error, [{pid, Pid} | Md], "Webmachine error at path ~p : ~s", [Path, Formatted])
                  end;
               _ ->
                  ?CRASH_LOG(Event),
                  ?LOGFMT(Sink, error, Pid, Fmt, Args)
            end;
         {error_report, _GL, {Pid, std_error, D}} ->
            ?CRASH_LOG(Event),
            ?LOGMSG(Sink, error, Pid, print_silly_list(D));
         {error_report, _GL, {Pid, supervisor_report, D}} ->
            ?CRASH_LOG(Event),
            case lists:sort(D) of
               [{errorContext, Ctx}, {offender, Off}, {reason, Reason}, {supervisor, Name}] ->
                  Offender = format_offender(Off),
                  {Md, Formatted} = format_reason_md(Reason),
                  ?LOGFMT(Sink, error, [{pid, Pid} | Md],
                     "Supervisor ~w had child ~s exit with reason ~s in context ~w",
                     [supervisor_name(Name), Offender, Formatted, Ctx]);
               _ ->
                  ?LOGMSG(Sink, error, Pid, "SUPERVISOR REPORT " ++ print_silly_list(D))
            end;
         {error_report, _GL, {Pid, crash_report, [Self, Neighbours]}} ->
            ?CRASH_LOG(Event),
            {Md, Formatted} = format_crash_report(Self, Neighbours),
            ?LOGMSG(Sink, error, [{pid, Pid} | Md], "CRASH REPORT " ++ Formatted);
         {warning_msg, _GL, {Pid, Fmt, Args}} ->
            ?LOGFMT(Sink, warning, Pid, Fmt, Args);
         {warning_report, _GL, {Pid, std_warning, Report}} ->
            ?LOGMSG(Sink, warning, Pid, print_silly_list(Report));
         {info_msg, _GL, {Pid, Fmt, Args}} ->
            ?LOGFMT(Sink, info, Pid, Fmt, Args);
         {info_report, _GL, {Pid, std_info, D}} when is_list(D) ->
            Details = lists:sort(D),
            case Details of
               [{application, App}, {exited, Reason}, {type, _Type}] ->
                  case rumUtil:get_env(suppress_application_start_stop, false) of
                     true when Reason == stopped ->
                        no_log;
                     _ ->
                        {Md, Formatted} = format_reason_md(Reason),
                        ?LOGFMT(Sink, info, [{pid, Pid} | Md], "Application ~w exited with reason: ~s",
                           [App, Formatted])
                  end;
               _ ->
                  ?LOGMSG(Sink, info, Pid, print_silly_list(D))
            end;
         {info_report, _GL, {Pid, std_info, D}} ->
            ?LOGFMT(Sink, info, Pid, "~w", [D]);
         {info_report, _GL, {P, progress, D}} ->
            Details = lists:sort(D),
            case Details of
               [{application, App}, {started_at, Node}] ->
                  case rumUtil:get_env(suppress_application_start_stop, false) of
                     true ->
                        no_log;
                     _ ->
                        ?LOGFMT(Sink, info, P, "Application ~w started on node ~w",
                           [App, Node])
                  end;
               [{started, Started}, {supervisor, Name}] ->
                  case rumUtil:get_env(suppress_supervisor_start_stop, false) of
                     true ->
                        no_log;
                     _ ->
                        MFA = format_mfa(get_value(mfargs, Started)),
                        Pid = get_value(pid, Started),
                        ?LOGFMT(Sink, debug, P, "Supervisor ~w started ~s at pid ~w",
                           [supervisor_name(Name), MFA, Pid])
                  end;
               _ ->
                  ?LOGMSG(Sink, info, P, "PROGRESS REPORT " ++ print_silly_list(D))
            end;
         _ ->
            ?LOGFMT(Sink, warning, self(), "Unexpected error_logger event ~w", [Event])
      end,
   case DidLog of
      logged ->
         {ok, State};
      no_log ->
         Shaper = State#state.shaper,
         {ok, State#state{shaper = Shaper#rumShaper{mps = Shaper#rumShaper.mps - 1}}}
   end.

format_crash_report(Report, Neighbours) ->
   Name =
      case get_value(registered_name, Report, []) of
         [] ->
            %% process_info(Pid, registered_name) returns [] for unregistered processes
            get_value(pid, Report);
         Atom -> Atom
      end,
   Md0 =
      case get_value(dictionary, Report, []) of
         [] ->
            %% process_info(Pid, registered_name) returns [] for unregistered processes
            [];
         Dict ->
            %% pull the lager metadata out of the process dictionary, if we can
            get_value('_lager_metadata', Dict, [])
      end,

   {Class, Reason, Trace} = get_value(error_info, Report),
   {Md, ReasonStr} = format_reason_md({Reason, Trace}),
   Type = ?IIF(Class == exit, <<"exited">>, <<"crashed">>),
   {Md0 ++ Md, eFmt:formatBin("Process ~w with ~w neighbours ~s with reason: ~s", [Name, length(Neighbours), Type, ReasonStr])}.

format_offender(Off) ->
   case get_value(mfargs, Off) of
      undefined ->
         %% supervisor_bridge
         io_lib:format("at module ~w at ~w",
            [get_value(mod, Off), get_value(pid, Off)]);
      MFArgs ->
         %% regular supervisor
         {_, MFA} = formatMfaMd(MFArgs),

         %% In 2014 the error report changed from `name' to
         %% `id', so try that first.
         Name = case get_value(id, Off) of
                   undefined ->
                      get_value(name, Off);
                   Id ->
                      Id
                end,
         io_lib:format("~p started with ~s at ~w",
            [Name, MFA, get_value(pid, Off)])
   end.

%% backwards compatability shim
format_reason(Reason) ->
   element(2, format_reason_md(Reason)).

-spec format_reason_md(Stacktrace :: any()) -> {Metadata :: [{atom(), any()}], String :: list()}.
format_reason_md({'function not exported', [{M, F, A}, MFA | _]}) ->
   {Md, Formatted} = formatMfaMd(MFA),
   {_, Formatted2} = formatMfaMd({M, F, length(A)}),
   {[{reason, 'function not exported'} | Md], ["call to undefined function ", Formatted2, " from ", Formatted]};
format_reason_md({'function not exported', [{M, F, A, _Props}, MFA | _]}) ->
   %% R15 line numbers
   {Md, Formatted} = formatMfaMd(MFA),
   {_, Formatted2} = formatMfaMd({M, F, length(A)}),
   {[{reason, 'function not exported'} | Md], ["call to undefined function ", Formatted2, " from ", Formatted]};
format_reason_md({undef, [MFA | _]}) ->
   {Md, Formatted} = formatMfaMd(MFA),
   {[{reason, undef} | Md], ["call to undefined function ", Formatted]};
format_reason_md({bad_return, {_MFA, {'EXIT', Reason}}}) ->
   format_reason_md(Reason);
format_reason_md({bad_return, {MFA, Val}}) ->
   {Md, Formatted} = formatMfaMd(MFA),
   {[{reason, bad_return} | Md], ["bad return value ", print_val(Val), " from ", Formatted]};
format_reason_md({bad_return_value, Val}) ->
   {[{reason, bad_return}], ["bad return value: ", print_val(Val)]};
format_reason_md({{bad_return_value, Val}, MFA}) ->
   {Md, Formatted} = formatMfaMd(MFA),
   {[{reason, bad_return_value} | Md], ["bad return value: ", print_val(Val), " in ", Formatted]};
format_reason_md({{badrecord, Record}, [MFA | _]}) ->
   {Md, Formatted} = formatMfaMd(MFA),
   {[{reason, badrecord} | Md], ["bad record ", print_val(Record), " in ", Formatted]};
format_reason_md({{case_clause, Val}, [MFA | _]}) ->
   {Md, Formatted} = formatMfaMd(MFA),
   {[{reason, case_clause} | Md], ["no case clause matching ", print_val(Val), " in ", Formatted]};
format_reason_md({function_clause, [MFA | _]}) ->
   {Md, Formatted} = formatMfaMd(MFA),
   {[{reason, function_clause} | Md], ["no function clause matching ", Formatted]};
format_reason_md({if_clause, [MFA | _]}) ->
   {Md, Formatted} = formatMfaMd(MFA),
   {[{reason, if_clause} | Md], ["no true branch found while evaluating if expression in ", Formatted]};
format_reason_md({{try_clause, Val}, [MFA | _]}) ->
   {Md, Formatted} = formatMfaMd(MFA),
   {[{reason, try_clause} | Md], ["no try clause matching ", print_val(Val), " in ", Formatted]};
format_reason_md({badarith, [MFA | _]}) ->
   {Md, Formatted} = formatMfaMd(MFA),
   {[{reason, badarith} | Md], ["bad arithmetic expression in ", Formatted]};
format_reason_md({{badmatch, Val}, [MFA | _]}) ->
   {Md, Formatted} = formatMfaMd(MFA),
   {[{reason, badmatch} | Md], ["no match of right hand value ", print_val(Val), " in ", Formatted]};
format_reason_md({emfile, _Trace}) ->
   {[{reason, emfile}], "maximum number of file descriptors exhausted, check ulimit -n"};
format_reason_md({system_limit, [{M, F, _} | _] = Trace}) ->
   Limit =
      case {M, F} of
         {erlang, open_port} ->
            <<"maximum number of ports exceeded">>;
         {erlang, spawn} ->
            <<"maximum number of processes exceeded">>;
         {erlang, spawn_opt} ->
            <<"maximum number of processes exceeded">>;
         {erlang, list_to_atom} ->
            <<"tried to create an atom larger than 255, or maximum atom count exceeded">>;
         {ets, new} ->
            <<"maximum number of ETS tables exceeded">>;
         _ ->
            eFmt:formatBin(<<"~p">>, [Trace], [{charsLimit, 500}])
      end,
   {[{reason, system_limit}], ["system limit: ", Limit]};
format_reason_md({badarg, [MFA, MFA2 | _]}) ->
   case MFA of
      {_M, _F, A, _Props} when is_list(A) ->
         %% R15 line numbers
         {Md, Formatted} = formatMfaMd(MFA2),
         {_, Formatted2} = formatMfaMd(MFA),
         {[{reason, badarg} | Md],
            ["bad argument in call to ", Formatted2, " in ", Formatted]};
      {_M, _F, A} when is_list(A) ->
         {Md, Formatted} = formatMfaMd(MFA2),
         {_, Formatted2} = formatMfaMd(MFA),
         {[{reason, badarg} | Md],
            ["bad argument in call to ", Formatted2, " in ", Formatted]};
      _ ->
         %% seems to be generated by a bad call to a BIF
         {Md, Formatted} = formatMfaMd(MFA),
         {[{reason, badarg} | Md],
            ["bad argument in ", Formatted]}
   end;
format_reason_md({{badarg, Stack}, _}) ->
   format_reason_md({badarg, Stack});
format_reason_md({{badarity, {Fun, Args}}, [MFA | _]}) ->
   {arity, Arity} = lists:keyfind(arity, 1, erlang:fun_info(Fun)),
   {Md, Formatted} = formatMfaMd(MFA),
   {[{reason, badarity} | Md],
      [io_lib:format("fun called with wrong arity of ~w instead of ~w in ",
         [length(Args), Arity]), Formatted]};
format_reason_md({noproc, MFA}) ->
   {Md, Formatted} = formatMfaMd(MFA),
   {[{reason, noproc} | Md],
      ["no such process or port in call to ", Formatted]};
format_reason_md({{badfun, Term}, [MFA | _]}) ->
   {Md, Formatted} = formatMfaMd(MFA),
   {[{reason, badfun} | Md],
      ["bad function ", print_val(Term), " in ", Formatted]};
format_reason_md({Reason, [{M, F, A} | _]}) when is_atom(M), is_atom(F), is_integer(A) ->
   {Md, Formatted} = format_reason_md(Reason),
   {_, Formatted2} = formatMfaMd({M, F, A}),
   {Md, [Formatted, " in ", Formatted2]};
format_reason_md({Reason, [{M, F, A, Props} | _]}) when is_atom(M), is_atom(F), is_integer(A), is_list(Props) ->
   %% line numbers
   {Md, Formatted} = format_reason_md(Reason),
   {_, Formatted2} = formatMfaMd({M, F, A, Props}),
   {Md, [Formatted, " in ", Formatted2]};
format_reason_md(Reason) ->
   {Str, _} = rumTruncIo:print(Reason, 500),
   {[], Str}.

%% backwards compatability shim
format_mfa(MFA) ->
   element(2, formatMfaMd(MFA)).

-spec formatMfaMd(any()) -> {[{atom(), any()}], list()}.
formatMfaMd({M, F, A}) when is_list(A) ->
   ArgsStr = format_args(A, <<>>),
   {[{module, M}, {function, F}], eFtm:formatBin(<<"~w:~w(", ArgsStr/binary, ")">>, [M, F])};
formatMfaMd({M, F, A}) when is_integer(A) ->
   {[{module, M}, {function, F}], eFtm:formatBin(<<"~w:~w/~w">>, [M, F, A])};
formatMfaMd({M, F, A, Props}) when is_list(Props) ->
   case get_value(line, Props) of
      undefined ->
         formatMfaMd({M, F, A});
      Line ->
         {Md, Formatted} = formatMfaMd({M, F, A}),
         {[{line, Line} | Md], <<Formatted/binary, " line ", (integer_to_binary(Line))/binary>>}
   end;
formatMfaMd([{M, F, A} | _]) ->
   %% this kind of weird stacktrace can be generated by a uncaught throw in a gen_server
   formatMfaMd({M, F, A});
formatMfaMd([{M, F, A, Props} | _]) when is_list(Props) ->
   %% this kind of weird stacktrace can be generated by a uncaught throw in a gen_server
   %% TODO we might not always want to print the first MFA we see here, often it is more helpful
   %% to print a lower one, but it is hard to programatically decide.
   formatMfaMd({M, F, A, Props});
formatMfaMd(Other) ->
   {[], eFtm:formatBin(<<"~w">>, [Other])}.

format_args([], ArgsAcc) ->
   ArgsAcc;
format_args([H], ArgsAcc) ->
   Str = eFmt:formatBin(<<"~p">>, [H], [{charsLimit, 100}]),
   <<ArgsAcc/binary, Str/binary>>;
format_args([H | T], ArgsAcc) ->
   Str = eFmt:formatBin(<<"~p">>, [H], [{charsLimit, 100}]),
   format_args(T, <<ArgsAcc/binary, Str/binary, ",">>).

print_silly_list(L) when is_list(L) ->
   case rumStdlib:string_p(L) of
      true ->
         rumTruncIo:format("~s", [L], ?RumDefTruncation);
      _ ->
         print_silly_list(L, [], [])
   end;
print_silly_list(L) ->
   {Str, _} = rumTruncIo:print(L, ?RumDefTruncation),
   Str.

print_silly_list([], Fmt, Acc) ->
   rumTruncIo:format(string:join(lists:reverse(Fmt), ", "),
      lists:reverse(Acc), ?RumDefTruncation);
print_silly_list([{K, V} | T], Fmt, Acc) ->
   print_silly_list(T, ["~p: ~p" | Fmt], [V, K | Acc]);
print_silly_list([H | T], Fmt, Acc) ->
   print_silly_list(T, ["~p" | Fmt], [H | Acc]).

print_val(Val) ->
   {Str, _} = rumTruncIo:print(Val, 500),
   Str.


%% @doc Faster than proplists, but with the same API as long as you don't need to
%% handle bare atom keys
get_value(Key, Value) ->
   get_value(Key, Value, undefined).

get_value(Key, List, Default) ->
   case lists:keyfind(Key, 1, List) of
      false -> Default;
      {Key, Value} -> Value
   end.

supervisor_name({local, Name}) -> Name;
supervisor_name(Name) -> Name.

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

no_silent_hwm_drops_test_() ->
   {timeout, 10000,
      [
         fun() ->
            error_logger:tty(false),
            application:load(lager),
            application:set_env(lager, handlers, [{lager_test_backend, warning}]),
            application:set_env(lager, errLoggerRedirect, true),
            application:set_env(lager, errLoggerHwm, 5),
            application:set_env(lager, errLoggerFlushQueue, false),
            application:set_env(lager, suppress_supervisor_start_stop, true),
            application:set_env(lager, suppress_application_start_stop, true),
            application:unset_env(lager, crash_log),
            eRum:start(),
            try
               {_, _, MS} = os:timestamp(),
               timer:sleep((1000000 - MS) div 1000 + 1),
               % start close to the beginning of a new second
               [error_logger:error_msg("Foo ~p~n", [K]) || K <- lists:seq(1, 15)],
               wait_for_message("lager_error_logger_h dropped 10 messages in the last second that exceeded the limit of 5 messages/sec", 100, 50),
               % and once again
               [error_logger:error_msg("Foo1 ~p~n", [K]) || K <- lists:seq(1, 20)],
               wait_for_message("lager_error_logger_h dropped 15 messages in the last second that exceeded the limit of 5 messages/sec", 100, 50)
            after
               application:stop(lager),
               application:stop(goldrush),
               error_logger:tty(true)
            end
         end
      ]
   }.

shaper_does_not_forward_sup_progress_messages_to_info_level_backend_test_() ->
   {timeout, 10000,
      [fun() ->
         error_logger:tty(false),
         application:load(lager),
         application:set_env(lager, handlers, [{lager_test_backend, info}]),
         application:set_env(lager, errLoggerRedirect, true),
         application:set_env(lager, errLoggerHwm, 5),
         application:set_env(lager, suppress_supervisor_start_stop, false),
         application:set_env(lager, suppress_application_start_stop, false),
         application:unset_env(lager, crash_log),
         eRum:start(),
         try
            PidPlaceholder = self(),
            SupervisorMsg =
               [{supervisor, {PidPlaceholder, rabbit_connection_sup}},
                  {started,
                     [{pid, PidPlaceholder},
                        {name, helper_sup},
                        {mfargs,
                           {rabbit_connection_helper_sup, start_link, []}},
                        {restart_type, intrinsic},
                        {shutdown, infinity},
                        {child_type, supervisor}]}],
            ApplicationExit =
               [{application, error_logger_lager_h_test},
                  {exited, stopped},
                  {type, permanent}],

            error_logger:info_report("This is not a progress message"),
            error_logger:info_report(ApplicationExit),
            [error_logger:info_report(progress, SupervisorMsg) || _K <- lists:seq(0, 100)],
            error_logger:info_report("This is not a progress message 2"),

            % Note: this gets logged in slow environments:
            % Application lager started on node nonode@nohost
            wait_for_count(fun lager_test_backend:count/0, [3, 4], 100, 50),
            % Note: this debug msg gets ignored in slow environments:
            % Lager installed handler lager_test_backend into lager_event
            wait_for_count(fun lager_test_backend:count_ignored/0, [0, 1], 100, 50)
         after
            application:stop(lager),
            application:stop(goldrush),
            error_logger:tty(true)
         end
       end
      ]
   }.

supressed_messages_are_not_counted_for_hwm_test_() ->
   {timeout, 10000,
      [fun() ->
         error_logger:tty(false),
         application:load(lager),
         application:set_env(lager, handlers, [{lager_test_backend, debug}]),
         application:set_env(lager, errLoggerRedirect, true),
         application:set_env(lager, errLoggerHwm, 5),
         application:set_env(lager, suppress_supervisor_start_stop, true),
         application:set_env(lager, suppress_application_start_stop, true),
         application:unset_env(lager, crash_log),
         eRum:start(),
         try
            PidPlaceholder = self(),
            SupervisorMsg =
               [{supervisor, {PidPlaceholder, rabbit_connection_sup}},
                  {started,
                     [{pid, PidPlaceholder},
                        {name, helper_sup},
                        {mfargs,
                           {rabbit_connection_helper_sup, start_link, []}},
                        {restart_type, intrinsic},
                        {shutdown, infinity},
                        {child_type, supervisor}]}],
            ApplicationExit =
               [{application, error_logger_lager_h_test},
                  {exited, stopped},
                  {type, permanent}],

            lager_test_backend:flush(),
            error_logger:info_report("This is not a progress message"),
            [error_logger:info_report(ApplicationExit) || _K <- lists:seq(0, 100)],
            [error_logger:info_report(progress, SupervisorMsg) || _K <- lists:seq(0, 100)],
            error_logger:info_report("This is not a progress message 2"),

            wait_for_count(fun lager_test_backend:count/0, 2, 100, 50),
            wait_for_count(fun lager_test_backend:count_ignored/0, 0, 100, 50)
         after
            application:stop(lager),
            application:stop(goldrush),
            error_logger:tty(true)
         end
       end
      ]
   }.

wait_for_message(Expected, Tries, Sleep) ->
   maybe_find_expected_message(lager_test_backend:get_buffer(), Expected, Tries, Sleep).

maybe_find_expected_message(_Buffer, Expected, 0, _Sleep) ->
   throw({not_found, Expected});
maybe_find_expected_message([], Expected, Tries, Sleep) ->
   timer:sleep(Sleep),
   maybe_find_expected_message(lager_test_backend:get_buffer(), Expected, Tries - 1, Sleep);
maybe_find_expected_message([{_Severity, _Date, Msg, _Metadata} | T], Expected, Tries, Sleep) ->
   case lists:flatten(Msg) of
      Expected ->
         ok;
      _ ->
         maybe_find_expected_message(T, Expected, Tries, Sleep)
   end.

wait_for_count(Fun, _Expected, 0, _Sleep) ->
   Actual = Fun(),
   Msg = io_lib:format("wait_for_count: fun ~p final value: ~p~n", [Fun, Actual]),
   throw({failed, Msg});
wait_for_count(Fun, Expected, Tries, Sleep) when is_list(Expected) ->
   Actual = Fun(),
   case lists:member(Actual, Expected) of
      true ->
         ok;
      false ->
         timer:sleep(Sleep),
         wait_for_count(Fun, Expected, Tries - 1, Sleep)
   end;
wait_for_count(Fun, Expected, Tries, Sleep) ->
   case Fun() of
      Expected ->
         ok;
      _ ->
         timer:sleep(Sleep),
         wait_for_count(Fun, Expected, Tries - 1, Sleep)
   end.
-endif.