From 0058430352420a8c0dc053900f108e7086f52fad Mon Sep 17 00:00:00 2001 From: Anders Svensson Date: Thu, 22 May 2014 11:01:45 +0200 Subject: Replace traffic-related log reports with no-op function calls The former were a little over-enthusiastic and could cause a node to be logged to death if a peer Diameter node was sufficiently ill-willed. The function calls are to diameter_lib:log/4, the arguments of which identify the happening in question, and which does nothing but provide a function to trace on. Many existing log calls have been shrunk. The only remaining traffic-related report (hopefully) is that resulting from {answer_errors, report} config, and this has been slimmed. --- lib/diameter/src/base/diameter_codec.erl | 31 +++++++------- lib/diameter/src/base/diameter_lib.erl | 56 +++++++++++++++++++++++-- lib/diameter/src/base/diameter_peer_fsm.erl | 65 ++++++++++------------------- lib/diameter/src/base/diameter_service.erl | 48 ++++++++++++++------- lib/diameter/src/base/diameter_traffic.erl | 51 +++++++++++----------- lib/diameter/src/base/diameter_watchdog.erl | 5 ++- 6 files changed, 151 insertions(+), 105 deletions(-) (limited to 'lib/diameter/src/base') diff --git a/lib/diameter/src/base/diameter_codec.erl b/lib/diameter/src/base/diameter_codec.erl index 9db3552286..84139d7f5e 100644 --- a/lib/diameter/src/base/diameter_codec.erl +++ b/lib/diameter/src/base/diameter_codec.erl @@ -70,18 +70,15 @@ encode(Mod, #diameter_packet{} = Pkt) -> try e(Mod, Pkt) catch - exit: {_, _, #diameter_header{}} = T -> + exit: {Reason, Stack, #diameter_header{} = H} = T -> %% Exit with a header in the reason to let the caller %% count encode errors. - X = {?MODULE, encode, T}, - diameter_lib:error_report(X, {?MODULE, encode, [Mod, Pkt]}), - exit(X); + ?LOG(encode_error, {Reason, Stack, H}), + exit({?MODULE, encode, T}); error: Reason -> - %% Be verbose since a crash report may be truncated and - %% encode errors are self-inflicted. - X = {?MODULE, encode, {Reason, ?STACK}}, - diameter_lib:error_report(X, {?MODULE, encode, [Mod, Pkt]}), - exit(X) + T = {Reason, diameter_lib:get_stacktrace()}, + ?LOG(encode_error, T), + exit({?MODULE, encode, T}) end; encode(Mod, Msg) -> @@ -115,7 +112,7 @@ e(_, #diameter_packet{msg = [#diameter_header{} = Hdr | As]} = Pkt) -> Avps/binary>>} catch error: Reason -> - exit({Reason, ?STACK, Hdr}) + exit({Reason, diameter_lib:get_stacktrace(), Hdr}) end; e(Mod, #diameter_packet{header = Hdr0, msg = Msg} = Pkt) -> @@ -147,7 +144,7 @@ e(Mod, #diameter_packet{header = Hdr0, msg = Msg} = Pkt) -> Avps/binary>>} catch error: Reason -> - exit({Reason, ?STACK, Hdr}) + exit({Reason, diameter_lib:get_stacktrace(), Hdr}) end. %% make_flags/2 @@ -278,23 +275,23 @@ decode(Id, Mod, Bin) decode(Id, Mod, #diameter_packet{header = decode_header(Bin), bin = Bin}). decode_avps(MsgName, Mod, Pkt, {E, Avps}) -> - ?LOG(invalid, Pkt#diameter_packet.bin), + ?LOG(invalid_avp_length, Pkt#diameter_packet.header), #diameter_packet{errors = Failed} = P = decode_avps(MsgName, Mod, Pkt, Avps), P#diameter_packet{errors = [E | Failed]}; -decode_avps('', Mod, Pkt, Avps) -> %% unknown message ... - ?LOG(unknown, {Mod, Pkt#diameter_packet.header}), +decode_avps('', _, Pkt, Avps) -> %% unknown message ... + ?LOG(unknown_message, Pkt#diameter_packet.header), Pkt#diameter_packet{avps = lists:reverse(Avps), errors = [3001]}; %% DIAMETER_COMMAND_UNSUPPORTED %% msg = undefined identifies this case. decode_avps(MsgName, Mod, Pkt, Avps) -> %% ... or not - {Rec, As, Failed} = Mod:decode_avps(MsgName, Avps), - ?LOGC([] /= Failed, failed, {Mod, Failed}), + {Rec, As, Errors} = Mod:decode_avps(MsgName, Avps), + ?LOGC([] /= Errors, decode_errors, Pkt#diameter_packet.header), Pkt#diameter_packet{msg = Rec, - errors = Failed, + errors = Errors, avps = As}. %%% --------------------------------------------------------------------------- diff --git a/lib/diameter/src/base/diameter_lib.erl b/lib/diameter/src/base/diameter_lib.erl index 44d81e2778..5b3a2063f8 100644 --- a/lib/diameter/src/base/diameter_lib.erl +++ b/lib/diameter/src/base/diameter_lib.erl @@ -1,7 +1,7 @@ %% %% %CopyrightBegin% %% -%% Copyright Ericsson AB 2010-2013. All Rights Reserved. +%% Copyright Ericsson AB 2010-2014. All Rights Reserved. %% %% The contents of this file are subject to the Erlang Public License, %% Version 1.1, (the "License"); you may not use this file except in @@ -25,12 +25,30 @@ now_diff/1, time/1, eval/1, + eval_name/1, + get_stacktrace/0, ipaddr/1, spawn_opts/2, wait/1, fold_tuple/3, log/4]). +%% --------------------------------------------------------------------------- +%% # get_stacktrace/0 +%% --------------------------------------------------------------------------- + +%% Return a stacktrace with a leading, potentially large, argument +%% list replaced by an arity. Trace on stacktrace/0 to see the +%% original. + +get_stacktrace() -> + stacktrace(erlang:get_stacktrace()). + +stacktrace([{M,F,A,L} | T]) when is_list(A) -> + [{M, F, length(A), L} | T]; +stacktrace(L) -> + L. + %% --------------------------------------------------------------------------- %% # info_report/2 %% --------------------------------------------------------------------------- @@ -60,9 +78,17 @@ warning_report(Reason, T) -> report(fun error_logger:warning_report/1, Reason, T). report(Fun, Reason, T) -> - Fun([{why, Reason}, {who, self()}, {what, T}]), + Fun(io_lib:format("diameter: ~" ++ fmt(Reason) ++ "~n ~p~n", + [Reason, T])), false. +fmt(T) -> + if is_list(T) -> + "s"; + true -> + "p" + end. + %% --------------------------------------------------------------------------- %% # now_diff/1 %% --------------------------------------------------------------------------- @@ -129,8 +155,8 @@ eval({M,F,A}) -> eval([{M,F,A} | X]) -> apply(M, F, X ++ A); -eval([[F|A] | X]) -> - eval([F | X ++ A]); +eval([[F|X] | A]) -> + eval([F | A ++ X]); eval([F|A]) -> apply(F,A); @@ -141,6 +167,28 @@ eval({F}) -> eval(F) -> F(). +%% --------------------------------------------------------------------------- +%% eval_name/1 +%% --------------------------------------------------------------------------- + +eval_name({M,F,A}) -> + {M, F, length(A)}; + +eval_name([{M,F,A} | X]) -> + {M, F, length(A) + length(X)}; + +eval_name([[F|A] | X]) -> + eval_name([F | X ++ A]); + +eval_name([F|_]) -> + F; + +eval_name({F}) -> + eval_name(F); + +eval_name(F) -> + F. + %% --------------------------------------------------------------------------- %% # ipaddr/1 %% diff --git a/lib/diameter/src/base/diameter_peer_fsm.erl b/lib/diameter/src/base/diameter_peer_fsm.erl index 4b97fa96b3..e9b6a263c9 100644 --- a/lib/diameter/src/base/diameter_peer_fsm.erl +++ b/lib/diameter/src/base/diameter_peer_fsm.erl @@ -283,7 +283,7 @@ handle_info(T, #state{} = State) -> ok -> {noreply, State}; #state{state = X} = S -> - ?LOGC(X =/= State#state.state, transition, X), + ?LOGC(X /= State#state.state, transition, X), {noreply, S}; {stop, Reason} -> ?LOG(stop, Reason), @@ -295,13 +295,9 @@ handle_info(T, #state{} = State) -> exit: {diameter_codec, encode, T} = Reason -> incr_error(send, T), ?LOG(stop, Reason), - %% diameter_codec:encode/2 emits an error report. Only - %% indicate the probable reason here. - diameter_lib:info_report(probable_configuration_error, - insufficient_capabilities), {stop, {shutdown, Reason}, State}; {?MODULE, Tag, Reason} -> - ?LOG(Tag, {Reason, T}), + ?LOG(stop, Tag), {stop, {shutdown, Reason}, State} end. %% The form of the throw caught here is historical. It's @@ -477,12 +473,12 @@ send_CER(#state{state = {'Wait-Conn-Ack', Tmo}, orelse close({already_connected, Remote, LCaps}), CER = build_CER(S), - ?LOG(send, 'CER'), #diameter_packet{header = #diameter_header{end_to_end_id = Eid, hop_by_hop_id = Hid}} = Pkt = encode(CER, Dict), send(TPid, Pkt), + ?LOG(send, 'CER'), start_timer(Tmo, S#state{state = {'Wait-CEA', Hid, Eid}}). %% Register ourselves as connecting to the remote endpoint in @@ -554,26 +550,18 @@ recv(#diameter_header{length = Len} recv(#diameter_header{} = H, #diameter_packet{bin = Bin}, - #state{length_errors = E} - = S) -> - invalid(E, - invalid_message_length, - recv, - [size(Bin), bit_size(Bin) rem 8, H, S]); + #state{length_errors = E}) -> + T = {size(Bin), bit_size(Bin) rem 8, H}, + invalid(E, message_length_mismatch, T); -recv(false, Pkt, #state{length_errors = E} = S) -> - invalid(E, truncated_header, recv, [Pkt, S]). +recv(false, #diameter_packet{bin = Bin}, #state{length_errors = E}) -> + invalid(E, truncated_header, Bin). %% Note that counters here only count discarded messages. -invalid(E, Reason, F, A) -> +invalid(E, Reason, T) -> diameter_stats:incr(Reason), - abort(E, Reason, F, A). - -abort(exit, Reason, F, A) -> - diameter_lib:warning_report(Reason, {?MODULE, F, A}), - throw({?MODULE, abort, Reason}); - -abort(_, _, _, _) -> + E == exit andalso close({Reason, T}), + ?LOG(Reason, T), ok. msg_id({_,_,_} = T, _) -> @@ -674,8 +662,12 @@ send_answer(Type, ReqPkt, #state{transport = TPid, dictionary = Dict} = S) -> incr_rc(send, AnsPkt, Dict), send(TPid, AnsPkt), + ?LOG(send, ans(Type)), eval(PostF, S). +ans('CER') -> 'CEA'; +ans('DPR') -> 'DPA'. + eval([F|A], S) -> apply(F, A ++ [S]); eval(ok, S) -> @@ -897,9 +889,7 @@ handle_CEA(#diameter_packet{bin = Bin} %% connection with the peer. try - is_integer(RC) - orelse ?THROW(no_result_code), - ?IS_SUCCESS(RC) + is_integer(RC) andalso ?IS_SUCCESS(RC) orelse ?THROW(RC), [] == SApps andalso ?THROW(no_common_application), @@ -1015,19 +1005,13 @@ capz(#diameter_caps{} = L, #diameter_caps{} = R) -> tl(tuple_to_list(R)))]). %% close/1 +%% +%% A good function to trace on in case of problems with capabilities +%% exchange. close(Reason) -> - report(Reason), throw({?MODULE, close, Reason}). -%% Could possibly log more here. -report({M, _, _, _, _} = T) - when M == 'CER'; - M == 'CEA' -> - diameter_lib:error_report(failure, T); -report(_) -> - ok. - %% dpr/2 %% %% The RFC isn't clear on whether DPR should be send in a non-Open @@ -1061,7 +1045,7 @@ dpr(_Reason, _S) -> %% process and contact it. (eg. diameter:service_info/2) dpr([CB|Rest], [Reason | _] = Args, S) -> - try diameter_lib:eval([CB | Args]) of + case diameter_lib:eval([CB | Args]) of {dpr, Opts} when is_list(Opts) -> send_dpr(Reason, Opts, S); dpr -> @@ -1071,14 +1055,7 @@ dpr([CB|Rest], [Reason | _] = Args, S) -> ignore -> dpr(Rest, Args, S); T -> - No = {disconnect_cb, T}, - diameter_lib:error_report(invalid, No), - {stop, No} - catch - E:R -> - No = {disconnect_cb, E, R, ?STACK}, - diameter_lib:error_report(failure, No), - {stop, No} + ?ERROR({disconnect_cb, CB, Args, T}) end; dpr([], [Reason | _], S) -> diff --git a/lib/diameter/src/base/diameter_service.erl b/lib/diameter/src/base/diameter_service.erl index 0dc3eb7123..b7cd311e02 100644 --- a/lib/diameter/src/base/diameter_service.erl +++ b/lib/diameter/src/base/diameter_service.erl @@ -731,14 +731,27 @@ remotes(F) -> L when is_list(L) -> L; T -> - diameter_lib:error_report({invalid_return, T}, F), + ?LOG(invalid_return, {F,T}), + error_report(invalid_return, share_peers, F), [] catch E:R -> - diameter_lib:error_report({failure, {E, R, ?STACK}}, F), + ?LOG(failure, {E, R, F, diameter_lib:get_stacktrace()}), + error_report(failure, share_peers, F), [] end. +%% error_report/3 + +error_report(T, What, F) -> + Reason = io_lib:format("~s from ~p callback", [reason(T), What]), + diameter_lib:error_report(Reason, diameter_lib:eval_name(F)). + +reason(invalid_return) -> + "invalid return"; +reason(failure) -> + "failure". + %% --------------------------------------------------------------------------- %% # start/3 %% --------------------------------------------------------------------------- @@ -1038,8 +1051,11 @@ peer_cb(App, F, A) -> true catch E:R -> - diameter_lib:error_report({failure, {E, R, ?STACK}}, - {App, F, A}), + %% Don't include arguments since a #diameter_caps{} strings + %% from the peer, which could be anything (especially, large). + [Mod|X] = App#diameter_app.module, + ?LOG(failure, {E, R, Mod, F, diameter_lib:get_stacktrace()}), + error_report(failure, F, {Mod, F, A ++ X}), false end. @@ -1262,13 +1278,14 @@ cm([#diameter_app{alias = Alias} = App], Req, From, Svc) -> mod_state(Alias, ModS), {T, RC}; T -> - diameter_lib:error_report({invalid, T}, - {App, handle_call, Args}), + ModX = App#diameter_app.module, + ?LOG(invalid_return, {ModX, handle_call, Args, T}), invalid catch E: Reason -> - diameter_lib:error_report({failure, {E, Reason, ?STACK}}, - {App, handle_call, Args}), + ModX = App#diameter_app.module, + Stack = diameter_lib:get_stacktrace(), + ?LOG(failure, {E, Reason, ModX, handle_call, Stack}), failure end; @@ -1426,13 +1443,16 @@ pick_peer(Local, T; %% Accept returned state in the immutable {false = No, S} -> %% case as long it isn't changed. No; - T -> - diameter_lib:error_report({invalid, T, App}, - {App, pick_peer, Args}) + T when M -> + ModX = App#diameter_app.module, + ?LOG(invalid_return, {ModX, pick_peer, T}), + false catch - E: Reason -> - diameter_lib:error_report({failure, {E, Reason, ?STACK}}, - {App, pick_peer, Args}) + E: Reason when M -> + ModX = App#diameter_app.module, + Stack = diameter_lib:get_stacktrace(), + ?LOG(failure, {E, Reason, ModX, pick_peer, Stack}), + false end. %% peers/4 diff --git a/lib/diameter/src/base/diameter_traffic.erl b/lib/diameter/src/base/diameter_traffic.erl index f2ac745053..7c680f96b5 100644 --- a/lib/diameter/src/base/diameter_traffic.erl +++ b/lib/diameter/src/base/diameter_traffic.erl @@ -48,6 +48,8 @@ -include_lib("diameter/include/diameter.hrl"). -include("diameter_internal.hrl"). +-define(LOGX(Reason, T), begin ?LOG(Reason, T), x({Reason, T}) end). + -define(RELAY, ?DIAMETER_DICT_RELAY). -define(BASE, ?DIAMETER_DICT_COMMON). %% Note: the RFC 3588 dictionary @@ -154,9 +156,8 @@ incr_rc(Dir, Pkt, TPid, Dict0) -> try incr_rc(Dir, Pkt, Dict0, TPid, Dict0) catch - exit: {invalid_error_bit = E, _} -> - E; - exit: no_result_code = E -> + exit: {E,_} when E == no_result_code; + E == invalid_error_bit -> E end. @@ -234,7 +235,7 @@ spawn_request(TPid, Pkt, Dict0, Opts, RecvData) -> spawn_opt(fun() -> recv_request(TPid, Pkt, Dict0, RecvData) end, Opts) catch error: system_limit = E -> %% discard - ?LOG({error, E}, now()) + ?LOG(error, E) end. %% --------------------------------------------------------------------------- @@ -336,23 +337,25 @@ rc(N) -> %% This error is returned when a request is received with an invalid %% message length. -errors(_, #diameter_packet{header = #diameter_header{length = Len}, +errors(_, #diameter_packet{header = #diameter_header{length = Len} = H, bin = Bin, errors = Es} = Pkt) when Len < 20; 0 /= Len rem 4; 8*Len /= bit_size(Bin) -> + ?LOG(invalid_message_length, {H, bit_size(Bin)}), Pkt#diameter_packet{errors = [5015 | Es]}; %% DIAMETER_UNSUPPORTED_VERSION 5011 %% This error is returned when a request was received, whose version %% number is unsupported. -errors(_, #diameter_packet{header = #diameter_header{version = V}, +errors(_, #diameter_packet{header = #diameter_header{version = V} = H, errors = Es} = Pkt) when V /= ?DIAMETER_VERSION -> + ?LOG(unsupported_version, H), Pkt#diameter_packet{errors = [5011 | Es]}; %% DIAMETER_COMMAND_UNSUPPORTED 3001 @@ -360,12 +363,13 @@ errors(_, #diameter_packet{header = #diameter_header{version = V}, %% recognize or support. This MUST be used when a Diameter node %% receives an experimental command that it does not understand. -errors(Id, #diameter_packet{header = #diameter_header{is_proxiable = P}, +errors(Id, #diameter_packet{header = #diameter_header{is_proxiable = P} = H, msg = M, errors = Es} = Pkt) when ?APP_ID_RELAY /= Id, undefined == M; %% don't know the command ?APP_ID_RELAY == Id, not P -> %% command isn't proxiable + ?LOG(command_unsupported, H), Pkt#diameter_packet{errors = [3001 | Es]}; %% DIAMETER_INVALID_HDR_BITS 3008 @@ -374,9 +378,11 @@ errors(Id, #diameter_packet{header = #diameter_header{is_proxiable = P}, %% inconsistent with the command code's definition. errors(_, #diameter_packet{header = #diameter_header{is_request = true, - is_error = true}, + is_error = true} + = H, errors = Es} = Pkt) -> + ?LOG(invalid_hdr_bits, H), Pkt#diameter_packet{errors = [3008 | Es]}; %% Green. @@ -532,7 +538,6 @@ answer_message(RC, origin_realm = {OR,_}}, Dict0, Pkt) -> - ?LOG({error, RC}, Pkt), {Dict0, answer_message(OH, OR, RC, Dict0, Pkt)}. %% resend/7 @@ -1042,12 +1047,12 @@ incr_rc(Dir, Pkt, Dict, TPid, Dict0) -> %% Exit on a missing result code. T = rc_counter(Dict, Msg), - T == false andalso x(no_result_code, answer, [Dir, Pkt]), + T == false andalso ?LOGX(no_result_code, {Dict, Dir, Hdr}), {Ctr, RC} = T, %% Or on an inappropriate value. is_result(RC, E, Dict0) - orelse x({invalid_error_bit, RC}, answer, [Dir, Pkt]), + orelse ?LOGX(invalid_error_bit, {Dict, Dir, Hdr, RC}), incr(TPid, {Id, Dir, Ctr}). @@ -1112,13 +1117,6 @@ int(N) int(_) -> undefined. --spec x(any(), atom(), list()) -> no_return(). - -%% Warn and exit request process on errors in an incoming answer. -x(Reason, F, A) -> - diameter_lib:warning_report(Reason, {?MODULE, F, A}), - x(Reason). - x(T) -> exit(T). @@ -1430,7 +1428,7 @@ handle_A(Pkt, SvcName, Dict, Dict0, App, #request{transport = TPid} = Req) -> of _ -> answer(Pkt, SvcName, App, Req) catch - exit: no_result_code -> + exit: {no_result_code, _} -> %% RFC 6733 requires one of Result-Code or %% Experimental-Result, but the decode will have detected %% a missing AVP. If both are optional in the dictionary @@ -1462,11 +1460,16 @@ a(#diameter_packet{errors = Es} callback == AE -> cb(ModX, handle_answer, [Pkt, msg(P), SvcName, {TPid, Caps}]); -a(Pkt, SvcName, _, report, Req) -> - x(errors, handle_answer, [SvcName, Req, Pkt]); +a(Pkt, SvcName, _, AE, _) -> + a(Pkt#diameter_packet.header, SvcName, AE). + +a(Hdr, SvcName, report) -> + MFA = {?MODULE, handle_answer, [SvcName, Hdr]}, + diameter_lib:warning_report(errors, MFA), + a(Hdr, SvcName, discard); -a(Pkt, SvcName, _, discard, Req) -> - x({errors, handle_answer, [SvcName, Req, Pkt]}). +a(Hdr, SvcName, discard) -> + x({answer_errors, {SvcName, Hdr}}). %% Note that we don't check that the application id in the answer's %% header is what we expect. (TODO: Does the rfc says anything about @@ -1652,7 +1655,7 @@ resend_request(Pkt0, packet = Pkt0, caps = Caps}, - ?LOG(retransmission, Req), + ?LOG(retransmission, Pkt#diameter_packet.header), TRef = send_request(TPid, Pkt, Req, SvcName, Tmo), {TRef, Req}. diff --git a/lib/diameter/src/base/diameter_watchdog.erl b/lib/diameter/src/base/diameter_watchdog.erl index dbfe087659..5e27778432 100644 --- a/lib/diameter/src/base/diameter_watchdog.erl +++ b/lib/diameter/src/base/diameter_watchdog.erl @@ -219,7 +219,6 @@ dict0(_, _, Acc) -> Acc. config_error(T) -> - diameter_lib:error_report(configuration_error, T), exit({shutdown, {configuration_error, T}}). %% handle_call/3 @@ -268,7 +267,7 @@ event(Msg, TPid = tpid(F,T), E = {[TPid | data(Msg, TPid, From, To)], From, To}, send(Pid, {watchdog, self(), E}), - ?LOG(transition, {self(), E}). + ?LOG(transition, {From, To}). data(Msg, TPid, reopen, okay) -> {recv, TPid, 'DWA', _Pkt} = Msg, %% assert @@ -562,6 +561,7 @@ recv(Name, Pkt, S) -> rcv('DWR', Pkt, #watchdog{transport = TPid, dictionary = Dict0}) -> + ?LOG(recv, 'DWR'), DPkt = diameter_codec:decode(Dict0, Pkt), diameter_traffic:incr_error(recv, DPkt, TPid), EPkt = encode(dwa, Dict0, Pkt), @@ -572,6 +572,7 @@ rcv('DWR', Pkt, #watchdog{transport = TPid, rcv('DWA', Pkt, #watchdog{transport = TPid, dictionary = Dict0}) -> + ?LOG(recv, 'DWA'), diameter_traffic:incr_rc(recv, diameter_codec:decode(Dict0, Pkt), TPid, -- cgit v1.2.3