[log] clean up logging

* change logs to lebel debug that where intendet for debugging only,
  but where not using the debug level
* remove obsolete debug logs
* clarify some non-debug logs

src/ergw_aaa_diameter_srv.erl

@@ -180,7 +180,7 @@ call(App, Request, #{function := Function} = Config, CallOpts) ->
 		encode ->
 		    ?LOG(critical, "failed to encode DIAMETER requests: ~0p", [Request]);
 		Other ->
-		    ?LOG(notice, "non-critical diameter API: ~p", [Other])
+		    ?LOG(notice, "non-critical diameter API return: ~p", [Other])
 	    end,
 	    SI = diameter:service_info(Function, applications),
 	    handle_plain_error(Result, Request, Function, App, CallOpts, SI);
@@ -264,8 +264,8 @@ handle_cast(stop, State) ->
 
 handle_info({'DOWN', MRef, _Type, Pid, Info}, #state{peers = Peers0} = State)
   when is_map_key(MRef, Peers0) ->
-    ?LOG(alert, "got down for pending request ~0p (~p) with ~p",
-	 [maps:get(MRef, Peers0), Pid, Info]),
+    ?LOG(alert, "Diameter request process terminated unexpected with ~0tp (req: ~0tp, pid: ~0p)",
+	 [Info, maps:get(MRef, Peers0), Pid]),
 
     {_, _, PeerRef, Caps} = maps:get(MRef, Peers0),
     {Result, Peers} = release_peer(PeerRef, Caps, maps:without([Pid, MRef], Peers0)),
@@ -285,7 +285,8 @@ handle_info({'DOWN', MRef, _Type, Pid, _Info}, State) ->
     {noreply, State};
 
 handle_info(Info, State) ->
-    ?LOG(warning, "handle_info: ~p", [Info]),
+    ?LOG(alert, "unexpected info message, something important might have been missed: ~p",
+         [Info]),
     {noreply, State}.
 
 terminate(_Reason, _State) ->
@@ -389,11 +390,13 @@ start_request_h(SvcName, {PeerRef,  #diameter_caps{origin_host = {_, OH}} = Caps
 	  capacity    = Cap,
 	  tokens      = Tokens} = Peer,
     if Cnt >= Cap ->
-	    ?LOG(debug, "peer ~0p over capacity (~p > ~p)", [OH, Cnt, Cap]),
-	    {{discard, rate_limit}, Peers0#{OH => inc_stats(no_tokens, Peer)}};
-       Tokens == 0 ->
-	    ?LOG(debug, "peer ~0p over rate", [OH]),
+	    ?LOG(notice,
+		 "Diameter peer ~0p traffic is over the configured outstanding request capacity (~p > ~p)",
+		 [OH, Cnt, Cap]),
 	    {{discard, rate_limit}, Peers0#{OH => inc_stats(no_capacity, Peer)}};
+       Tokens == 0 ->
+	    ?LOG(notice, "Diameter peer ~0p traffic is over the configured rate", [OH]),
+	    {{discard, rate_limit}, Peers0#{OH => inc_stats(no_tokens, Peer)}};
        true ->
 	    ?LOG(debug, "outstanding inc: ~p", [Cnt + 1]),
 	    Peers1 =

src/ergw_aaa_gx.erl

@@ -164,14 +164,14 @@ handle_response(_Promise, _Msg, Session, Events, _Opts, State) ->
 %%===================================================================
 
 %% peer_up/3
-peer_up(_SvcName, _Peer, State) ->
-    ?LOG(debug, "peer_up: ~p~n", [_Peer]),
+peer_up(_SvcName, {_, #diameter_caps{origin_host = {OH, _}}}, State) ->
+    ?LOG(info, "Diameter peer FSM for ~p changed to state UP", [OH]),
     State.
 
 %% peer_down/3
-peer_down(SvcName, Peer, State) ->
+peer_down(SvcName, {_, #diameter_caps{origin_host = {OH, _}}} = Peer, State) ->
     ergw_aaa_diameter_srv:peer_down(?MODULE, SvcName, Peer),
-    ?LOG(debug, "peer_down: ~p~n", [Peer]),
+    ?LOG(info, "Diameter peer FSM for ~p changed to state DOWN", [OH]),
     State.
 
 %% pick_peer/5
@@ -218,9 +218,11 @@ prepare_retransmit(_Pkt, _SvcName, _Peer, _CallOpts) ->
 
 %% handle_answer/5
 handle_answer(#diameter_packet{msg = Msg, errors = Errors},
-	      _Request, SvcName, Peer, _CallOpts)
-  when length(Errors) /= 0 ->
-    ?LOG(error, "~p: decode of answer from ~p failed, errors ~p", [SvcName, Peer, Errors]),
+	      _Request, SvcName, {_, #diameter_caps{origin_host = {OH, _}}} = Peer, _CallOpts)
+   when length(Errors) /= 0 ->
+    %% the exact content of Errors is a bit unclear, dumping them is best we can do
+    ?LOG(error, "~0tp: decode of Diameter answer ~0tp from ~0tp failed, errors ~0tp",
+         [SvcName, Msg, OH, Errors]),
     ok = ergw_aaa_diameter_srv:finish_request(SvcName, Peer),
     case Msg of
 	[_ | #{'Result-Code' := RC}] -> {error, RC};	%% try to handle gracefully
@@ -303,7 +305,6 @@ handle_cca({error, Code} = Result, Session, Events, _Opts, State)
   when is_integer(Code) ->
     {Result, Session, [{stop, {?API, peer_reject}} | Events], State#state{state = stopped}};
 handle_cca({error, Reason} = Result, Session, Events, _Opts, State) ->
-    ?LOG(error, "CCA Result: ~p", [Result]),
     {Result, Session, [{stop, {?API, Reason}} | Events], State#state{state = stopped}}.
 
 %% handle_cca/7
@@ -625,10 +626,8 @@ to_session(Procedure, SessEvs, Avps) ->
 to_session(_, 'Usage-Monitoring-Information', Value, SessEv) ->
     lists:foldl(fun umi_to_session/2, SessEv, Value);
 to_session(_, 'Charging-Rule-Install', V, {Session, Events}) ->
-    [?LOG(info, "CRI: ~p", [R]) || R <- V],
     {Session, [{pcc, install, V} | Events]};
 to_session(_, 'Charging-Rule-Remove', V, {Session, Events}) ->
-    [?LOG(info, "CRI: ~p", [R]) || R <- V],
     {Session, [{pcc, remove, V} | Events]};
 to_session(_, _, _, SessEv) ->
     SessEv.

src/ergw_aaa_nasreq.erl

@@ -105,7 +105,7 @@ initialize_service(_ServiceId, #{function := Function, accounting := AcctModel})
 			   {dictionary, ?DIAMETER_DICT_NASREQ},
 			   {module, ?MODULE}]
 			  | Appl]},
-    ?LOG(debug, "Registering NASREQ service: ~p", [{Function, SvcOpts}]),
+    ?LOG(info, "Registering NASREQ service: ~p", [{Function, SvcOpts}]),
     ergw_aaa_diameter_srv:register_service(Function, SvcOpts),
     {ok, []}.
 
@@ -150,7 +150,6 @@ invoke(_Service, interim, Session, Events, Opts, #state{state = started} = State
 invoke(_Service, Procedure, Session, Events, Opts,
        #state{state = started, authorized = Authorized} = State0)
   when Procedure =:= stop; Procedure =:= terminate ->
-    ?LOG(debug, "Session ~s: ~p", [Procedure, Session]),
     State1 = inc_record_number(State0#state{state = stopped}),
     RecType = ?'DIAMETER_SGI_ACCOUNTING-RECORD-TYPE_STOP_RECORD',
     App = acct_app_alias(Opts),
@@ -209,14 +208,14 @@ handle_response('STR', Msg, Session, Events, Opts, State) ->
 %%===================================================================
 
 %% peer_up/3
-peer_up(_SvcName, _Peer, State) ->
-    ?LOG(debug, "peer_up: ~p~n", [_Peer]),
+peer_up(_SvcName, {_, #diameter_caps{origin_host = {OH, _}}}, State) ->
+    ?LOG(info, "Diameter peer FSM for ~p changed to state UP", [OH]),
     State.
 
 %% peer_down/3
-peer_down(SvcName, Peer, State) ->
+peer_down(SvcName, {_, #diameter_caps{origin_host = {OH, _}}} = Peer, State) ->
     ergw_aaa_diameter_srv:peer_down(?MODULE, SvcName, Peer),
-    ?LOG(debug, "peer_down: ~p~n", [Peer]),
+    ?LOG(info, "Diameter peer FSM for ~p changed to state DOWN", [OH]),
     State.
 
 %% pick_peer/5
@@ -275,9 +274,11 @@ prepare_retransmit(_Pkt, _SvcName, _Peer, _CallOpts) ->
 
 %% handle_answer/5
 handle_answer(#diameter_packet{msg = Msg, errors = Errors},
-	      _Request, SvcName, Peer, _CallOpts)
+	      _Request, SvcName, {_, #diameter_caps{origin_host = {OH, _}}} = Peer, _CallOpts)
   when length(Errors) /= 0 ->
-    ?LOG(error, "~p: decode of answer ~p from ~p failed, errors ~p", [SvcName, Msg, Peer, Errors]),
+    %% the exact content of Errors is a bit unclear, dumping them is best we can do
+    ?LOG(error, "~0tp: decode of Diameter answer ~0tp from ~0tp failed, errors ~0tp",
+         [SvcName, Msg, OH, Errors]),
     ok = ergw_aaa_diameter_srv:finish_request(SvcName, Peer),
     case Msg of
 	[_ | #{'Result-Code' := RC}] -> {error, RC};	%% try to handle gracefully
@@ -299,8 +300,10 @@ handle_error(Reason, _Request, SvcName, Peer, CallOpts) ->
 handle_request(#diameter_packet{msg = [Command | Avps]}, _SvcName, Peer)
   when Command =:= 'ASR'; Command =:= 'RAR' ->
     handle_common_request(Command, Avps, Peer);
-handle_request(_Packet, _SvcName, _Peer) ->
-    erlang:error({unexpected, ?MODULE, ?LINE}).
+handle_request(Packet, SvcName, {_, #diameter_caps{origin_host = {OH, _}}}) ->
+    ?LOG(error, "~0tp: unsupported Diameter request from peer ~p, raw request ~0tp",
+		[SvcName, OH, Packet]),
+    {answer_message, 3001}.  %% DIAMETER_COMMAND_UNSUPPORTED
 
 %%%===================================================================
 %%% Options Validation
@@ -619,7 +622,7 @@ handle_common_request(Command, #{'Session-Id' := SessionId} = Avps, {_PeerRef, C
 		    'Session-Id' => SessionId},
     ReplyCode = diameter_reply_code(Command),
     ReplyAvps = diameter_reply_avps(Result, ReplyAvps2),
-    ?LOG(error, "~p reply Avps: ~p", [Command, ReplyAvps]),
+    ?LOG(debug, "~p reply Avps: ~p", [Command, ReplyAvps]),
     {reply, [ReplyCode | ReplyAvps]}.
 
 filter_reply_avps('RAR', Avps) ->

src/ergw_aaa_radius.erl

@@ -213,7 +213,8 @@ validate_host(Opt, Host)
 	{ok, #hostent{h_addr_list = [IP | _]}} ->
 	    IP;
 	_ ->
-	    ?LOG(error, "can't resolve remote RADIUS server name '~s'", [Host]),
+	    ?LOG(emergency, "unable to resolve remote RADIUS server name '~s' to IPv4 address",
+		 [Host]),
 	    erlang:error(badarg, [Opt, Host])
     end;
 validate_host(_Opt, {_,_,_,_} = IP) ->
@@ -810,26 +811,26 @@ to_session_opts({#attribute{name = "X_" ++ Name} = Attr, Value}, SOpts) ->
 to_session_opts({#attribute{name = Name} = Attr, Value}, SOpts) ->
     to_session_opts(Attr, catch (list_to_existing_atom(Name)), Value, SOpts);
 to_session_opts({Attr, Value}, SOpts) ->
-    ?LOG(debug, "unhandled undecoded reply AVP: ~0p: ~0p", [Attr, Value]),
+    ?LOG(warning, "unsupported, undecoded AVP in reply: ~0tp: ~0tp", [Attr, Value]),
     SOpts.
 
 %% Service-Type = Framed-User
 to_session_opts(_Attr, 'Service-Type', 2, SOpts) ->
     SOpts#{'Service-Type' => 'Framed-User'};
 
-to_session_opts(_Attr, 'Service-Type', Value, _SOpts) ->
-    ?LOG(debug, "unexpected Value in Service-Type: ~p", [Value]),
-    throw(?AAA_ERR(?FATAL));
+to_session_opts(_Attr, 'Service-Type', Value, SOpts) ->
+    ?LOG(warning, "unsupported value for RADIUS Service-Type in reply: ~p", [Value]),
+    SOpts;
 
 %% Framed-Protocol = PPP
 to_session_opts(_Attr, 'Framed-Protocol', 1, SOpts) ->
     SOpts#{'Framed-Protocol' => 'PPP'};
 %% Framed-Protocol = GPRS-PDP-Context
 to_session_opts(_Attr, 'Framed-Protocol', 7, SOpts) ->
     SOpts#{'Framed-Protocol' => 'GPRS-PDP-Context'};
-to_session_opts(_Attr, 'Framed-Protocol', Value, _SOpts) ->
-    ?LOG(debug, "unexpected Value in Framed-Protocol: ~p", [Value]),
-    throw(?AAA_ERR(?FATAL));
+to_session_opts(_Attr, 'Framed-Protocol', Value, SOpts) ->
+    ?LOG(warning, "unsupported value for RADIUS Framed-Protocol in reply: ~p", [Value]),
+    SOpts;
 
 %% Alc-Primary-Dns
 to_session_opts(_Attr, 'Alc-Primary-DNS', DNS, SOpts) ->

src/ergw_aaa_radius_handler.erl

@@ -37,9 +37,9 @@ radius_request(#radius_request{cmd = discreq, attrs = Attrs} = Req, _NasProp, _A
         end,
     {reply, Req#radius_request{cmd = Cmd}};
 
-radius_request(#radius_request{} = Request, _NasProp, _Args) ->
-    ?LOG(warning, "Unhandled radius request: ~p", [Request]),
-    {reply, Request}.
+radius_request(#radius_request{}, _NasProp, _Args) ->
+    %% unsupported requests, eradius_server will logs the `noreply` as an error, no need to duplicate that
+    noreply.
 
 to_session_id(HexSessionId) ->
     H = fun(N) when N < 58  -> N - 48;

src/ergw_aaa_rf.erl

@@ -190,14 +190,14 @@ handle_response(_Promise, _Msg, Session, Events, _Opts, State) ->
 %%===================================================================
 
 %% peer_up/3
-peer_up(_SvcName, _Peer, State) ->
-    ?LOG(debug, "peer_up: ~p~n", [_Peer]),
+peer_up(_SvcName, {_, #diameter_caps{origin_host = {OH, _}}}, State) ->
+    ?LOG(info, "Diameter peer FSM for ~p changed to state UP", [OH]),
     State.
 
 %% peer_down/3
-peer_down(SvcName, Peer, State) ->
+peer_down(SvcName, {_, #diameter_caps{origin_host = {OH, _}}} = Peer, State) ->
     ergw_aaa_diameter_srv:peer_down(?MODULE, SvcName, Peer),
-    ?LOG(debug, "peer_down: ~p~n", [Peer]),
+    ?LOG(info, "Diameter peer FSM for ~p changed to state DOWN", [OH]),
     State.
 
 %% pick_peer/5
@@ -231,9 +231,11 @@ prepare_retransmit(_Pkt, _SvcName, _Peer, _CallOpts) ->
 
 %% handle_answer/5
 handle_answer(#diameter_packet{msg = Msg, errors = Errors},
-	      _Request, SvcName, Peer, _CallOpts)
+	      _Request, SvcName, {_, #diameter_caps{origin_host = {OH, _}}} = Peer, _CallOpts)
   when length(Errors) /= 0 ->
-    ?LOG(error, "~p: decode of answer from ~p failed, errors ~p", [SvcName, Peer, Errors]),
+    %% the exact content of Errors is a bit unclear, dumping them is best we can do
+    ?LOG(error, "~0tp: decode of Diameter answer ~0tp from ~0tp failed, errors ~0tp",
+         [SvcName, Msg, OH, Errors]),
     ok = ergw_aaa_diameter_srv:finish_request(SvcName, Peer),
     case Msg of
 	[_ | #{'Result-Code' := RC}] -> {error, RC};	%% try to handle gracefully

src/ergw_aaa_ro.erl

@@ -190,14 +190,14 @@ handle_response(_Promise, _Msg, Session, Events, _Opts, State) ->
 %%===================================================================
 
 %% peer_up/3
-peer_up(_SvcName, _Peer, State) ->
-    ?LOG(debug, "peer_up: ~p~n", [_Peer]),
+peer_up(_SvcName, {_, #diameter_caps{origin_host = {OH, _}}}, State) ->
+    ?LOG(info, "Diameter peer FSM for ~p changed to state UP", [OH]),
     State.
 
 %% peer_down/3
-peer_down(SvcName, Peer, State) ->
+peer_down(SvcName, {_, #diameter_caps{origin_host = {OH, _}}} = Peer, State) ->
     ergw_aaa_diameter_srv:peer_down(?MODULE, SvcName, Peer),
-    ?LOG(debug, "peer_down: ~p~n", [Peer]),
+    ?LOG(info, "Diameter peer FSM for ~p changed to state DOWN", [OH]),
     State.
 
 %% pick_peer/5
@@ -232,9 +232,11 @@ prepare_retransmit(_Pkt, _SvcName, _Peer, _CallOpts) ->
 
 %% handle_answer/5
 handle_answer(#diameter_packet{msg = Msg, errors = Errors},
-	      _Request, SvcName, Peer, CallOpts)
+	      _Request, SvcName, {_, #diameter_caps{origin_host = {OH, _}}} = Peer, CallOpts)
   when length(Errors) /= 0 ->
-    ?LOG(error, "~p: decode of answer from ~p failed, errors ~p", [SvcName, Peer, Errors]),
+    %% the exact content of Errors is a bit unclear, dumping them is best we can do
+    ?LOG(error, "~0tp: decode of Diameter answer ~0tp from ~0tp failed, errors ~0tp",
+         [SvcName, Msg, OH, Errors]),
     ok = ergw_aaa_diameter_srv:finish_request(SvcName, Peer),
     Code =
 	case Msg of
@@ -276,9 +278,9 @@ maybe_retry(Reason, SvcName, Peer, CallOpts) ->
 handle_request(#diameter_packet{msg = [Command | Avps]}, _SvcName, Peer)
   when Command =:= 'ASR'; Command =:= 'RAR' ->
     handle_common_request(Command, Avps, Peer);
-handle_request(_Packet, _SvcName, {_PeerRef, _Caps} = _Peer) ->
-    ?LOG(error, "~p:handle_request(~p, ~p, ~p)",
-		[?MODULE, _Packet, _SvcName, _Caps]),
+handle_request(Packet, SvcName, {_, #diameter_caps{origin_host = {OH, _}}}) ->
+    ?LOG(error, "~0tp: unsupported Diameter request from peer ~p, raw request ~0tp",
+		[SvcName, OH, Packet]),
     {answer_message, 3001}.  %% DIAMETER_COMMAND_UNSUPPORTED
 
 %%%===================================================================
@@ -359,7 +361,6 @@ handle_cca({error, Code} = Result, Session, Events, _Opts, State)
   when is_integer(Code) ->
     {Result, Session, [{stop, {?API, peer_reject}} | Events], State#state{state = stopped}};
 handle_cca({error, Reason} = Result, Session, Events, _Opts, State) ->
-    ?LOG(error, "CCA Result: ~p", [Result]),
     {Result, Session, [{stop, {?API, Reason}} | Events], State#state{state = stopped}}.
 
 handle_common_request(Command, #{'Session-Id' := SessionId} = Avps, {_PeerRef, Caps}) ->
@@ -768,11 +769,9 @@ request_credits(Session, MSCC) ->
     Credits = maps:get(credits, Session, #{}),
     maps:fold(
       fun(RatingGroup, empty, Request) ->
-	      ?LOG(warning, "Ro Charging Key: ~p", [RatingGroup]),
 	      RSU = [{'Requested-Service-Unit', #{}}],
 	      merge_mscc(RatingGroup, RSU, Request);
-	 (RatingGroup, _, Request) ->
-	      ?LOG(error, "unknown Ro Rating Group: ~p", [RatingGroup]),
+	 (_, _, Request) ->
 	      Request
       end, MSCC, Credits).
 

src/ergw_aaa_session.erl

@@ -311,12 +311,13 @@ handle_event(info, {'$reply', Promise, Handler, Msg, Opts} = _Info,
     update_session(SessOut, EvsOut, Data),
     {keep_state, Data};
 
-handle_event(Type, Event, _State, _Data) ->
-    ?LOG(warning, "unhandled event ~p:~p", [Type, Event]),
+handle_event(info, Info, State, _) ->
+    ?LOG(alert, "unexpected info message in state ~p, something important might have been missed: ~p",
+         [State, Info]),
     keep_state_and_data.
 
 terminate(Reason, Data) ->
-    ?LOG(error, "ctld Session terminating with state ~p with reason ~p", [Data, Reason]),
+    ?LOG(debug, "terminating with state ~p with reason ~p", [Data, Reason]),
     ok.
 
 code_change(_OldVsn, Data, _Extra) ->

src/ergw_aaa_static.erl

@@ -107,7 +107,8 @@ handle_response({API, _}, #{'Result-Code' := Code}, Session, Events, State) ->
 handle_response(Procedure, #{'Result-Code' := Code}, Session, Events, State) ->
     {{fail, Code}, Session, [{stop, {Procedure, peer_reject}} | Events], State};
 handle_response(_Procedure, Response, Session, Events, State) ->
-    ?LOG(error, "Response: ~p", [Response]),
+    ?LOG(alert, "unexpected Diameter response, something important might have been missed: ~p",
+         [Response]),
     {Response, Session, Events, State}.
 
 get_state_atom(_) ->

test/diameter_Gy_SUITE.erl

@@ -142,6 +142,9 @@ all() ->
      terminate].
 
 init_per_suite(Config0) ->
+    %% the overhead of logging interfers with the rate limit tests
+    logger:set_primary_config(level, none),
+
     Config = [{handler_under_test, ?HUT} | Config0],
 
     application:load(ergw_aaa),

test/diameter_Rf_SUITE.erl

@@ -94,6 +94,9 @@ all() ->
     ].
 
 init_per_suite(Config0) ->
+    %% the overhead of logging interfers with the rate limit tests
+    logger:set_primary_config(level, none),
+
     Config = [{handler_under_test, ?HUT} | Config0],
 
     application:load(ergw_aaa),

test/diameter_test_server.erl

@@ -249,7 +249,6 @@ handle_request(#diameter_packet{msg = ['ACR' | Msg]}, _SvcName, {_, Caps}, _Extr
 	    #{'Session-Id' := Id,
 	      'Accounting-Record-Type' := Type,
 	      'Accounting-Record-Number' := Number} = Msg,
-	    ct:pal("Received msg: ~p", [Msg]),
 	    ACA =  #{'Session-Id' => Id,
 		     'Result-Code' => 2001,
 		     'Origin-Host' => OH,