Merge pull request #219 from travelping/CENNSO-2033/change-logging

[CENNSO-2033] rework logging

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);
@@ -250,8 +250,8 @@ handle_call({start_request, SvcName, Peer, RPid}, _From, #state{peers = Peers0}
     {reply, Reply, State#state{peers = Peers}};
 
 handle_call({finish_request, SvcName, Peer, RPid}, _From, #state{peers = Peers0} = State) ->
-    {Reply, Peers} = finish_request_h(SvcName, Peer, RPid, Peers0),
-    {reply, Reply, State#state{peers = Peers}};
+    Peers = finish_request_h(SvcName, Peer, RPid, Peers0),
+    {reply, ok, State#state{peers = Peers}};
 
 handle_call(peers_info, _, #state{peers = Peers} = State) ->
     {reply, Peers, State}.
@@ -264,19 +264,11 @@ 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)),
-    case Result of
-	{error, Error} ->
-	    ?LOG(critical, "release peer failed with ~0p", [Error]),
-	    ct:fail("release peer failed with ~0p", [Error]),
-	    ok;
-	ok ->
-	    ok
-    end,
+    Peers = release_peer(PeerRef, Caps, maps:without([Pid, MRef], Peers0)),
     ets:match_delete(?MODULE, {{'_', Pid}, MRef}),
     {noreply, State#state{peers = Peers}};
 
@@ -285,7 +277,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 +382,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 =
@@ -415,9 +410,10 @@ release_peer_oh(#diameter_caps{origin_host = {_, OH}}, Peers) ->
     case Peer of
 	#peer{outstanding = Cnt} when Cnt > 0 ->
 	    ?LOG(debug, "outstanding dec #1: ~p", [Cnt - 1]),
-	    {ok, Peers#{OH => Peer#peer{outstanding = Cnt - 1}}};
+	    Peers#{OH => Peer#peer{outstanding = Cnt - 1}};
 	_ ->
-	    {{error, underflow}, Peers#{OH => Peer}}
+	    ?LOG(emergency, "reference counting underflow for Diameter peer ~0tp", [OH]),
+	    Peers#{OH => Peer}
     end.
 
 release_peer(PeerRef, Caps, Peers) ->

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).