wip

src/eradius_client.erl

@@ -73,8 +73,6 @@ send_request(ServerRef, ServerName, Req, Opts) when not is_list(ServerName) ->
 do_send_request(_ServerRef, [], _Tried, _Req, _Opts) ->
     {error, no_active_servers};
 do_send_request(ServerRef, Peers, Tried, Req0, Opts0) ->
-    TS1 = erlang:monotonic_time(),
-
     case eradius_client_mngr:wanna_send(ServerRef, Peers, Tried) of
         {ok, {Socket, ReqId, ServerName, Server, ReqInfo}} ->
             #{secret := Secret} = Server,
@@ -89,23 +87,18 @@ do_send_request(ServerRef, Peers, Tried, Req0, Opts0) ->
             {Response, Req} =
                 send_request_loop(
                   Socket, ReqId, Req2#{req_id => ReqId, secret => Secret}, Opts),
-            proceed_response(ServerRef, [ServerName | Tried], Req, Response, ServerName, TS1, Opts);
+            proceed_response(ServerRef, [ServerName | Tried], Req, Response, ServerName, Opts);
 
         {error, _} = Error ->
             maybe_failover(ServerRef, Tried, Req0, Error, Opts0)
     end.
 
-proceed_response(_ServerRef, _Tried, Req, {ok, Resp0}, _ServerName, TS1, _Opts) ->
-    Resp = eradius_req:record_metric(
-             reply, #{request => Req,
-                      duration => erlang:monotonic_time() - TS1}, Resp0),
+proceed_response(_ServerRef, _Tried, Req, {ok, Resp0}, _ServerName, _Opts) ->
+    Resp = eradius_req:record_metric(reply, #{request => Req}, Resp0),
     {{ok, Resp}, Req};
 
-proceed_response(ServerRef, Tried, Req0, {error, Error} = Response, ServerName, TS1, Opts) ->
-    Req = eradius_req:record_metric(
-            discard, #{reason => Error,
-                       request => Req0,
-                       duration => erlang:monotonic_time() - TS1}, Req0),
+proceed_response(ServerRef, Tried, Req0, {error, Error} = Response, ServerName, Opts) ->
+    Req = eradius_req:record_metric(discard, #{reason => Error, request => Req0}, Req0),
     eradius_client_mngr:request_failed(ServerRef, ServerName),
     maybe_failover(ServerRef, Tried, Req, Response, Opts).
 

src/eradius_metrics_prometheus.erl

@@ -18,6 +18,8 @@
 -define(CONFIG, #{histogram_buckets => ?DEFAULT_BUCKETS,
                   client_metrics => true,
                   server_metrics => true}).
+-define(TS_CLIENT_KEY, '_prometheus_metrics_client_ts').
+-define(TS_SERVER_KEY, '_prometheus_metrics_server_ts').
 
 %%%=========================================================================
 %%% Setup
@@ -315,13 +317,13 @@ client_metrics_callback(Event, MetaData,
         request ->
             client_request_metrics(MetaData, Labels, Req);
         retransmission ->
-            prometheus_counter:inc(eradius_client_retransmissions_total, Labels, 1);
+            prometheus_counter:inc(eradius_client_retransmissions_total, Labels, 1),
+            Req;
         reply ->
             client_reply_metrics(MetaData, Labels, Req);
         _ ->
-            ok
-    end,
-    Req;
+            Req
+    end;
 client_metrics_callback(Event, MetaData, Req) ->
     ?LOG(error, "BROKEN Client-Metric:~nEvent: ~p~nMetaData: ~p~nReq: ~p~n",
          [Event, MetaData, Req]),
@@ -344,9 +346,36 @@ client_request_metrics(_MetaData, Labels, #{cmd := Cmd} = Req) ->
             %% WTF? how can a client generate a request with an unknown type?
             %% should probably be _response_, keep it for compatibility
             prometheus_counter:inc(eradius_client_unknown_type_request_total, Labels, 1)
-    end.
+    end,
+    Req#{?TS_CLIENT_KEY => erlang:monotonic_time()}.
+
+client_request_duration(#{request := #{cmd := ReqCmd}}, Labels,
+                        #{?TS_CLIENT_KEY := TS} = Req) ->
+    Duration = erlang:monotonic_time() - TS,
+    prometheus_histogram:observe(
+      eradius_request_duration_milliseconds, Labels, Duration),
+
+    case ReqCmd of
+        request ->
+            prometheus_histogram:observe(
+              eradius_client_access_request_duration_milliseconds, Labels, Duration);
+        accreq ->
+            AcctStatusType = acct_status_type(Req),
+            prometheus_histogram:observe(
+              eradius_client_accounting_request_duration_milliseconds,
+              Labels ++ [AcctStatusType], Duration);
+        coareq ->
+            prometheus_histogram:observe(
+              eradius_client_coa_request_duration_milliseconds, Labels, Duration);
+        discreq ->
+            prometheus_histogram:observe(
+              eradius_client_disconnect_request_duration_milliseconds, Labels, Duration);
+        _ ->
+            ok
+    end,
+    Req.
 
-client_reply_metrics(_MetaData, Labels,
+client_reply_metrics(MetaData, Labels,
                      #{cmd := Cmd, server_addr := {ServerIP, ServerPort}} = Req) ->
     prometheus_boolean:set(eradius_server_status, [ServerIP, ServerPort], true),
     case Cmd of
@@ -371,7 +400,8 @@ client_reply_metrics(_MetaData, Labels,
         _ ->
             %% should probably be _response_, keep it for compatibility
             prometheus_counter:inc(eradius_client_unknown_type_request_total, Labels, 1)
-    end.
+    end,
+    client_request_duration(MetaData, Labels, Req).
 
 -spec server_metrics_callback(Event :: eradius_req:metrics_event(),
                               MetaData :: term(),
@@ -389,17 +419,17 @@ server_metrics_callback(Event, MetaData,
             server_request_metrics(MetaData, Labels, Req);
         retransmission ->
             prometheus_counter:inc(eradius_requests_total, Labels, 1),
-            prometheus_counter:inc(eradius_retransmissions_total, Labels, 1);
+            prometheus_counter:inc(eradius_retransmissions_total, Labels, 1),
+            Req;
         discard ->
             server_discard_metrics(MetaData, Labels, Req);
         reply ->
             server_reply_metrics(MetaData, Labels, Req);
         _ ->
             ?LOG(error, "Unexpected Server-Metric:~nEvent: ~p~nMetaData: ~p~nReq: ~p~n",
                  [Event, MetaData, Req]),
-            ok
-    end,
-    Req;
+            Req
+    end;
 server_metrics_callback(invalid_request, #{server := Server} = _MetaData, _) ->
     prometheus_counter:inc(eradius_invalid_requests_total, [Server], 1),
     ok;
@@ -424,7 +454,8 @@ server_request_metrics(_MetaData, Labels, #{cmd := Cmd} = Req) ->
             prometheus_counter:inc(eradius_disconnect_requests_total, Labels, 1);
         _ ->
             prometheus_counter:inc(eradius_unknown_type_request_total, Labels, 1)
-    end.
+    end,
+    Req#{?TS_SERVER_KEY => erlang:monotonic_time()}.
 
 server_discard_metrics(MetaData, Labels, Req) ->
     prometheus_gauge:inc(eradius_pending_requests_total, Labels, -1),
@@ -443,9 +474,36 @@ server_discard_metrics(MetaData, Labels, Req) ->
             ?LOG(error, "Unexpected Server-Metric:~nEvent: ~p~nMetaData: ~p~nReq: ~p~n",
                  [discard, MetaData, Req]),
             ok
-    end.
+    end,
+    Req.
+
+server_request_duration(#{request := #{cmd := ReqCmd}}, Labels,
+                        #{?TS_SERVER_KEY := TS} = Req) ->
+    Duration = erlang:monotonic_time() - TS,
+    prometheus_histogram:observe(
+      eradius_request_duration_milliseconds, Labels, Duration),
 
-server_reply_metrics(_MetaData, Labels, #{cmd := Cmd} = Req) ->
+    case ReqCmd of
+        request ->
+            prometheus_histogram:observe(
+              eradius_access_request_duration_milliseconds, Labels, Duration);
+        accreq ->
+            AcctStatusType = acct_status_type(Req),
+            prometheus_histogram:observe(
+              eradius_accounting_request_duration_milliseconds,
+              Labels ++ [AcctStatusType], Duration);
+        coareq ->
+            prometheus_histogram:observe(
+              eradius_coa_request_duration_milliseconds, Labels, Duration);
+        discreq ->
+            prometheus_histogram:observe(
+              eradius_disconnect_request_duration_milliseconds, Labels, Duration);
+        _ ->
+            ok
+    end,
+    Req.
+
+server_reply_metrics(MetaData, Labels, #{cmd := Cmd} = Req) ->
     prometheus_counter:inc(eradius_replies_total, Labels, 1),
     prometheus_gauge:inc(eradius_pending_requests_total, Labels, -1),
     case Cmd of
@@ -469,8 +527,8 @@ server_reply_metrics(_MetaData, Labels, #{cmd := Cmd} = Req) ->
             prometheus_counter:inc(eradius_disconnect_nacks_total, Labels, 1);
         _ ->
             ok
-    end.
-
+    end,
+    server_request_duration(MetaData, Labels, Req).
 
 acct_status_type(#{attrs := Attrs}) when is_list(Attrs) ->
     acct_status_type_list(Attrs);

src/eradius_server.erl

@@ -187,8 +187,7 @@ handle_info({udp, Socket, FromIP, FromPortNo, <<Header:20/bytes, Body/binary>>},
     NAS = maps:get(FromIP, Clients),
     <<_, ReqId:8, _/binary>> = Header,
     Req0 = eradius_req:request(Header, Body, NAS, MetricsCallback),
-    Req1 = Req0#{arrival_time => erlang:monotonic_time(),
-                 socket => Socket,
+    Req1 = Req0#{socket => Socket,
                  server => ServerName,
                  server_addr => Server,
                  client_addr => {FromIP, FromPortNo}},
@@ -254,7 +253,7 @@ code_change(_OldVsn, State, _Extra) -> {ok, State}.
 %% @private
 -spec do_radius(pid(), handler(), term(), eradius_req:req()) -> any().
 do_radius(ServerPid, {HandlerMod, HandlerArg}, ReqKey,
-          #{arrival_time := _TS1, server := Server, client_addr := Client} = Req0) ->
+          #{server := Server, client_addr := Client} = Req0) ->
     case apply_handler_mod(HandlerMod, HandlerArg, Req0) of
         {reply, Packet, Resp0, Req} ->
             ?LOG(debug, "~s From: ~s INF: Sending response for request ~0p",