Вы не можете выбрать более 25 тем
Темы должны начинаться с буквы или цифры, могут содержать дефисы(-) и должны содержать не более 35 символов.
426 строки
17 KiB
426 строки
17 KiB
%% Copyright (c) 2011-2012 Basho Technologies, Inc. All Rights Reserved.
|
|
%%
|
|
%% 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 A error_logger backend for redirecting events into lager.
|
|
%% Error messages and crash logs are also optionally written to a crash log.
|
|
|
|
%% @see lager_crash_log
|
|
|
|
%% @private
|
|
|
|
-module(error_logger_lager_h).
|
|
|
|
-include("lager.hrl").
|
|
|
|
-behaviour(gen_event).
|
|
|
|
-export([set_high_water/1]).
|
|
-export([init/1, handle_call/2, handle_event/2, handle_info/2, terminate/2,
|
|
code_change/3]).
|
|
|
|
-export([format_reason/1]).
|
|
|
|
-record(state, {
|
|
%% how many messages per second we try to deliver
|
|
hwm = undefined :: 'undefined' | pos_integer(),
|
|
%% how many messages we've received this second
|
|
mps = 0 :: non_neg_integer(),
|
|
%% the current second
|
|
lasttime = os:timestamp() :: erlang:timestamp(),
|
|
%% count of dropped messages this second
|
|
dropped = 0 :: non_neg_integer()
|
|
}).
|
|
|
|
-define(LOGMSG(Level, Pid, Msg),
|
|
case ?SHOULD_LOG(Level) of
|
|
true ->
|
|
_ =lager:log(Level, Pid, Msg),
|
|
ok;
|
|
_ -> ok
|
|
end).
|
|
|
|
-define(LOGFMT(Level, Pid, Fmt, Args),
|
|
case ?SHOULD_LOG(Level) of
|
|
true ->
|
|
_ = lager:log(Level, Pid, Fmt, Args),
|
|
ok;
|
|
_ -> ok
|
|
end).
|
|
|
|
-ifdef(TEST).
|
|
-compile(export_all).
|
|
%% Make CRASH synchronous when testing, to avoid timing headaches
|
|
-define(CRASH_LOG(Event),
|
|
catch(gen_server:call(lager_crash_log, {log, Event}))).
|
|
-else.
|
|
-define(CRASH_LOG(Event),
|
|
gen_server:cast(lager_crash_log, {log, Event})).
|
|
-endif.
|
|
|
|
set_high_water(N) ->
|
|
gen_event:call(error_logger, ?MODULE, {set_high_water, N}, infinity).
|
|
|
|
-spec init(any()) -> {ok, #state{}}.
|
|
init([HighWaterMark]) ->
|
|
{ok, #state{hwm=HighWaterMark}}.
|
|
|
|
handle_call({set_high_water, N}, State) ->
|
|
{ok, ok, State#state{hwm = N}};
|
|
handle_call(_Request, State) ->
|
|
{ok, unknown_call, State}.
|
|
|
|
handle_event(Event, State) ->
|
|
case check_hwm(State) of
|
|
{true, NewState} ->
|
|
log_event(Event, NewState);
|
|
{false, NewState} ->
|
|
{ok, NewState}
|
|
end.
|
|
|
|
handle_info(_Info, State) ->
|
|
{ok, State}.
|
|
|
|
terminate(_Reason, _State) ->
|
|
ok.
|
|
|
|
code_change(_OldVsn, State, _Extra) ->
|
|
{ok, State}.
|
|
|
|
%% internal functions
|
|
|
|
check_hwm(State = #state{hwm = undefined}) ->
|
|
{true, State};
|
|
check_hwm(State = #state{mps = Mps, hwm = Hwm}) when Mps < Hwm ->
|
|
%% haven't hit high water mark yet, just log it
|
|
{true, State#state{mps=Mps+1}};
|
|
check_hwm(State = #state{hwm = Hwm, lasttime = Last, dropped = Drop}) ->
|
|
%% are we still in the same second?
|
|
{M, S, _} = Now = os:timestamp(),
|
|
case Last of
|
|
{M, S, _} ->
|
|
%% still in same second, but have exceeded the high water mark
|
|
NewDrops = discard_messages(Now, 0),
|
|
{false, State#state{dropped=Drop+NewDrops}};
|
|
_ ->
|
|
%% different second, reset all counters and allow it
|
|
case Drop > 0 of
|
|
true ->
|
|
?LOGFMT(warning, self(), "lager_error_logger_h dropped ~p messages in the last second that exceeded the limit of ~p messages/sec",
|
|
[Drop, Hwm]);
|
|
false ->
|
|
ok
|
|
end,
|
|
{true, State#state{dropped = 0, mps=1, lasttime = Now}}
|
|
end.
|
|
|
|
discard_messages(Second, Count) ->
|
|
{M, S, _} = os:timestamp(),
|
|
case Second of
|
|
{M, S, _} ->
|
|
receive
|
|
_Msg ->
|
|
discard_messages(Second, Count+1)
|
|
after 0 ->
|
|
Count
|
|
end;
|
|
_ ->
|
|
Count
|
|
end.
|
|
|
|
log_event(Event, State) ->
|
|
case Event of
|
|
{error, _GL, {Pid, Fmt, Args}} ->
|
|
case Fmt of
|
|
"** Generic server "++_ ->
|
|
%% gen_server terminate
|
|
[Name, _Msg, _State, Reason] = Args,
|
|
?CRASH_LOG(Event),
|
|
?LOGFMT(error, Pid, "gen_server ~w terminated with reason: ~s",
|
|
[Name, format_reason(Reason)]);
|
|
"** State machine "++_ ->
|
|
%% gen_fsm terminate
|
|
[Name, _Msg, StateName, _StateData, Reason] = Args,
|
|
?CRASH_LOG(Event),
|
|
?LOGFMT(error, Pid, "gen_fsm ~w in state ~w terminated with reason: ~s",
|
|
[Name, StateName, format_reason(Reason)]);
|
|
"** gen_event handler"++_ ->
|
|
%% gen_event handler terminate
|
|
[ID, Name, _Msg, _State, Reason] = Args,
|
|
?CRASH_LOG(Event),
|
|
?LOGFMT(error, Pid, "gen_event ~w installed in ~w terminated with reason: ~s",
|
|
[ID, Name, format_reason(Reason)]);
|
|
"** 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(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),
|
|
?LOGFMT(error, Pid,
|
|
"Cowboy handler ~p terminated in ~p:~p/~p with reason: ~s",
|
|
[Module, Module, Function, Arity, format_reason({Reason, StackTrace})])
|
|
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,
|
|
?LOGFMT(error, Pid, "Webmachine error at path ~p : ~s", [Path, format_reason(StackTrace)]);
|
|
_ ->
|
|
?CRASH_LOG(Event),
|
|
?LOGMSG(error, Pid, lager:safe_format(Fmt, Args, ?DEFAULT_TRUNCATION))
|
|
end;
|
|
{error_report, _GL, {Pid, std_error, D}} ->
|
|
?CRASH_LOG(Event),
|
|
?LOGMSG(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),
|
|
?LOGFMT(error, Pid,
|
|
"Supervisor ~w had child ~s exit with reason ~s in context ~w",
|
|
[supervisor_name(Name), Offender, format_reason(Reason), Ctx]);
|
|
_ ->
|
|
?LOGMSG(error, Pid, "SUPERVISOR REPORT " ++ print_silly_list(D))
|
|
end;
|
|
{error_report, _GL, {Pid, crash_report, [Self, Neighbours]}} ->
|
|
?CRASH_LOG(Event),
|
|
?LOGMSG(error, Pid, "CRASH REPORT " ++ format_crash_report(Self, Neighbours));
|
|
{warning_msg, _GL, {Pid, Fmt, Args}} ->
|
|
?LOGMSG(warning, Pid, lager:safe_format(Fmt, Args, ?DEFAULT_TRUNCATION));
|
|
{warning_report, _GL, {Pid, std_warning, Report}} ->
|
|
?LOGMSG(warning, Pid, print_silly_list(Report));
|
|
{info_msg, _GL, {Pid, Fmt, Args}} ->
|
|
?LOGMSG(info, Pid, lager:safe_format(Fmt, Args, ?DEFAULT_TRUNCATION));
|
|
{info_report, _GL, {Pid, std_info, D}} when is_list(D) ->
|
|
Details = lists:sort(D),
|
|
case Details of
|
|
[{application, App}, {exited, Reason}, {type, _Type}] ->
|
|
?LOGFMT(info, Pid, "Application ~w exited with reason: ~s",
|
|
[App, format_reason(Reason)]);
|
|
_ ->
|
|
?LOGMSG(info, Pid, print_silly_list(D))
|
|
end;
|
|
{info_report, _GL, {Pid, std_info, D}} ->
|
|
?LOGFMT(info, Pid, "~w", [D]);
|
|
{info_report, _GL, {P, progress, D}} ->
|
|
Details = lists:sort(D),
|
|
case Details of
|
|
[{application, App}, {started_at, Node}] ->
|
|
?LOGFMT(info, P, "Application ~w started on node ~w",
|
|
[App, Node]);
|
|
[{started, Started}, {supervisor, Name}] ->
|
|
MFA = format_mfa(proplists:get_value(mfargs, Started)),
|
|
Pid = proplists:get_value(pid, Started),
|
|
?LOGFMT(debug, P, "Supervisor ~w started ~s at pid ~w",
|
|
[supervisor_name(Name), MFA, Pid]);
|
|
_ ->
|
|
?LOGMSG(info, P, "PROGRESS REPORT " ++ print_silly_list(D))
|
|
end;
|
|
_ ->
|
|
?LOGFMT(warning, self(), "Unexpected error_logger event ~w", [Event])
|
|
end,
|
|
{ok, State}.
|
|
|
|
format_crash_report(Report, Neighbours) ->
|
|
Name = case proplists:get_value(registered_name, Report, []) of
|
|
[] ->
|
|
%% process_info(Pid, registered_name) returns [] for unregistered processes
|
|
proplists:get_value(pid, Report);
|
|
Atom -> Atom
|
|
end,
|
|
{Class, Reason, Trace} = proplists:get_value(error_info, Report),
|
|
ReasonStr = format_reason({Reason, Trace}),
|
|
Type = case Class of
|
|
exit -> "exited";
|
|
_ -> "crashed"
|
|
end,
|
|
io_lib:format("Process ~w with ~w neighbours ~s with reason: ~s",
|
|
[Name, length(Neighbours), Type, ReasonStr]).
|
|
|
|
format_offender(Off) ->
|
|
case proplists:get_value(mfargs, Off) of
|
|
undefined ->
|
|
%% supervisor_bridge
|
|
io_lib:format("at module ~w at ~w",
|
|
[proplists:get_value(mod, Off), proplists:get_value(pid, Off)]);
|
|
MFArgs ->
|
|
%% regular supervisor
|
|
MFA = format_mfa(MFArgs),
|
|
Name = proplists:get_value(name, Off),
|
|
io_lib:format("~p started with ~s at ~w",
|
|
[Name, MFA, proplists:get_value(pid, Off)])
|
|
end.
|
|
|
|
format_reason({'function not exported', [{M, F, A},MFA|_]}) ->
|
|
["call to undefined function ", format_mfa({M, F, length(A)}),
|
|
" from ", format_mfa(MFA)];
|
|
format_reason({'function not exported', [{M, F, A, _Props},MFA|_]}) ->
|
|
%% R15 line numbers
|
|
["call to undefined function ", format_mfa({M, F, length(A)}),
|
|
" from ", format_mfa(MFA)];
|
|
format_reason({undef, [MFA|_]}) ->
|
|
["call to undefined function ", format_mfa(MFA)];
|
|
format_reason({bad_return, {_MFA, {'EXIT', Reason}}}) ->
|
|
format_reason(Reason);
|
|
format_reason({bad_return, {MFA, Val}}) ->
|
|
["bad return value ", print_val(Val), " from ", format_mfa(MFA)];
|
|
format_reason({bad_return_value, Val}) ->
|
|
["bad return value: ", print_val(Val)];
|
|
format_reason({{bad_return_value, Val}, MFA}) ->
|
|
["bad return value: ", print_val(Val), " in ", format_mfa(MFA)];
|
|
format_reason({{badrecord, Record}, [MFA|_]}) ->
|
|
["bad record ", print_val(Record), " in ", format_mfa(MFA)];
|
|
format_reason({{case_clause, Val}, [MFA|_]}) ->
|
|
["no case clause matching ", print_val(Val), " in ", format_mfa(MFA)];
|
|
format_reason({function_clause, [MFA|_]}) ->
|
|
["no function clause matching ", format_mfa(MFA)];
|
|
format_reason({if_clause, [MFA|_]}) ->
|
|
["no true branch found while evaluating if expression in ", format_mfa(MFA)];
|
|
format_reason({{try_clause, Val}, [MFA|_]}) ->
|
|
["no try clause matching ", print_val(Val), " in ", format_mfa(MFA)];
|
|
format_reason({badarith, [MFA|_]}) ->
|
|
["bad arithmetic expression in ", format_mfa(MFA)];
|
|
format_reason({{badmatch, Val}, [MFA|_]}) ->
|
|
["no match of right hand value ", print_val(Val), " in ", format_mfa(MFA)];
|
|
format_reason({emfile, _Trace}) ->
|
|
"maximum number of file descriptors exhausted, check ulimit -n";
|
|
format_reason({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";
|
|
_ ->
|
|
{Str, _} = lager_trunc_io:print(Trace, 500),
|
|
Str
|
|
end,
|
|
["system limit: ", Limit];
|
|
format_reason({badarg, [MFA,MFA2|_]}) ->
|
|
case MFA of
|
|
{_M, _F, A, _Props} when is_list(A) ->
|
|
%% R15 line numbers
|
|
["bad argument in call to ", format_mfa(MFA), " in ", format_mfa(MFA2)];
|
|
{_M, _F, A} when is_list(A) ->
|
|
["bad argument in call to ", format_mfa(MFA), " in ", format_mfa(MFA2)];
|
|
_ ->
|
|
%% seems to be generated by a bad call to a BIF
|
|
["bad argument in ", format_mfa(MFA)]
|
|
end;
|
|
format_reason({{badarity, {Fun, Args}}, [MFA|_]}) ->
|
|
{arity, Arity} = lists:keyfind(arity, 1, erlang:fun_info(Fun)),
|
|
[io_lib:format("fun called with wrong arity of ~w instead of ~w in ",
|
|
[length(Args), Arity]), format_mfa(MFA)];
|
|
format_reason({noproc, MFA}) ->
|
|
["no such process or port in call to ", format_mfa(MFA)];
|
|
format_reason({{badfun, Term}, [MFA|_]}) ->
|
|
["bad function ", print_val(Term), " in ", format_mfa(MFA)];
|
|
format_reason({Reason, [{M, F, A}|_]}) when is_atom(M), is_atom(F), is_integer(A) ->
|
|
[format_reason(Reason), " in ", format_mfa({M, F, A})];
|
|
format_reason({Reason, [{M, F, A, Props}|_]}) when is_atom(M), is_atom(F), is_integer(A), is_list(Props) ->
|
|
%% line numbers
|
|
[format_reason(Reason), " in ", format_mfa({M, F, A, Props})];
|
|
format_reason(Reason) ->
|
|
{Str, _} = lager_trunc_io:print(Reason, 500),
|
|
Str.
|
|
|
|
format_mfa({M, F, A}) when is_list(A) ->
|
|
{FmtStr, Args} = format_args(A, [], []),
|
|
io_lib:format("~w:~w("++FmtStr++")", [M, F | Args]);
|
|
format_mfa({M, F, A}) when is_integer(A) ->
|
|
io_lib:format("~w:~w/~w", [M, F, A]);
|
|
format_mfa({M, F, A, Props}) when is_list(Props) ->
|
|
case proplists:get_value(line, Props) of
|
|
undefined ->
|
|
format_mfa({M, F, A});
|
|
Line ->
|
|
[format_mfa({M, F, A}), io_lib:format(" line ~w", [Line])]
|
|
end;
|
|
format_mfa([{M, F, A}, _]) ->
|
|
%% this kind of weird stacktrace can be generated by a uncaught throw in a gen_server
|
|
format_mfa({M, F, A});
|
|
format_mfa([{M, F, A, Props}, _]) when is_list(Props) ->
|
|
%% this kind of weird stacktrace can be generated by a uncaught throw in a gen_server
|
|
format_mfa({M, F, A, Props});
|
|
format_mfa(Other) ->
|
|
io_lib:format("~w", [Other]).
|
|
|
|
format_args([], FmtAcc, ArgsAcc) ->
|
|
{string:join(lists:reverse(FmtAcc), ", "), lists:reverse(ArgsAcc)};
|
|
format_args([H|T], FmtAcc, ArgsAcc) ->
|
|
{Str, _} = lager_trunc_io:print(H, 100),
|
|
format_args(T, ["~s"|FmtAcc], [Str|ArgsAcc]).
|
|
|
|
print_silly_list(L) when is_list(L) ->
|
|
case lager_stdlib:string_p(L) of
|
|
true ->
|
|
lager_trunc_io:format("~s", [L], ?DEFAULT_TRUNCATION);
|
|
_ ->
|
|
print_silly_list(L, [], [])
|
|
end;
|
|
print_silly_list(L) ->
|
|
{Str, _} = lager_trunc_io:print(L, ?DEFAULT_TRUNCATION),
|
|
Str.
|
|
|
|
print_silly_list([], Fmt, Acc) ->
|
|
lager_trunc_io:format(string:join(lists:reverse(Fmt), ", "),
|
|
lists:reverse(Acc), ?DEFAULT_TRUNCATION);
|
|
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, _} = lager_trunc_io:print(Val, 500),
|
|
Str.
|
|
|
|
supervisor_name({local, Name}) -> Name;
|
|
supervisor_name(Name) -> Name.
|
|
-ifdef(TEST).
|
|
|
|
%% Not intended to be a fully paranoid EUnit test....
|
|
|
|
t0() ->
|
|
application:stop(lager),
|
|
application:stop(sasl),
|
|
lager:start(),
|
|
set_high_water(5),
|
|
[error_logger:warning_msg("Foo ~p!", [X]) || X <- lists:seq(1,10)],
|
|
timer:sleep(1000),
|
|
[error_logger:warning_msg("Bar ~p!", [X]) || X <- lists:seq(1,10)],
|
|
timer:sleep(1000),
|
|
error_logger:warning_msg("Baz!"),
|
|
ok.
|
|
|
|
-endif. % TEST
|