From 6fb53c74fe07d16d6ca9816b5b32ce774b91304a Mon Sep 17 00:00:00 2001
From: Javier Garea <javigarea@gmail.com>
Date: Thu, 10 Oct 2024 08:32:03 +0200
Subject: [PATCH] feat: add request start event (#83)

---
 src/erf_http_server/erf_http_server_elli.erl | 26 ++++++++++++++---
 src/erf_telemetry.erl                        | 30 +++++++++++++-------
 2 files changed, 41 insertions(+), 15 deletions(-)

diff --git a/src/erf_http_server/erf_http_server_elli.erl b/src/erf_http_server/erf_http_server_elli.erl
index a25e15e..3ed75ab 100644
--- a/src/erf_http_server/erf_http_server_elli.erl
+++ b/src/erf_http_server/erf_http_server_elli.erl
@@ -17,6 +17,7 @@
 
 %%% BEHAVIOURS
 -behaviour(erf_http_server).
+-behaviour(elli_handler).
 
 %%% INCLUDE FILES
 -include_lib("kernel/include/logger.hrl").
@@ -28,6 +29,7 @@
 
 %%% ELLI HANDLER EXPORTS
 -export([
+    init/2,
     handle/2,
     handle_event/3
 ]).
@@ -67,6 +69,19 @@ start_link(Name, Conf, ExtraConf) ->
 %%%-----------------------------------------------------------------------------
 %%% ELLI HANDLER EXPORTS
 %%%-----------------------------------------------------------------------------
+-spec init(InitialRequest, CallbackArgs) -> Result when
+    InitialRequest :: elli:req(),
+    CallbackArgs :: [Name :: atom()],
+    Result :: {ok, Behaviour :: standard}.
+init(Req, [Name]) ->
+    erf_telemetry:event(
+        {request_start, #{monotonic_time => erlang:monotonic_time()}}, 
+        Name, 
+        preprocess(Name, Req), 
+        undefined
+    ),
+    {ok, standard}.
+
 -spec handle(InitialRequest, CallbackArgs) -> Result when
     InitialRequest :: elli:req(),
     CallbackArgs :: [Name :: atom()],
@@ -87,7 +102,7 @@ handle(ElliRequest, [Name]) ->
 handle_event(request_complete, Args, CallbackArgs) ->
     handle_full_response(request_complete, Args, CallbackArgs);
 handle_event(chunk_complete, Args, CallbackArgs) ->
-    handle_full_response(chunk_complete, Args, CallbackArgs);
+    handle_full_response(request_complete, Args, CallbackArgs);
 handle_event(invalid_return, [Request, Unexpected], CallbackArgs) ->
     handle_exception(Request, Unexpected, CallbackArgs);
 handle_event(request_throw, [Request, Exception, Stacktrace], [Name]) ->
@@ -172,6 +187,7 @@ duration(StartKey, EndKey, Timings) ->
 handle_full_response(Event, [RawReq, StatusCode, Hs, Body, {Timings, Sizes}], [Name]) ->
     Metrics = #{
         duration => duration(Timings, request),
+        monotonic_time => erlang:monotonic_time(),
         req_body_duration => duration(Timings, req_body),
         req_body_length => size(Sizes, request_body), 
         resp_body_length => size(Sizes, response_body),
@@ -187,14 +203,16 @@ handle_full_response(Event, [RawReq, StatusCode, Hs, Body, {Timings, Sizes}], [N
 handle_exception(RawReq, [Exception, Stacktrace], [Name]) ->
     Req = preprocess(Name, RawReq),
     ExceptionData = #{
-        stacktrace => erlang:list_to_binary(io_lib:format("~p", [Stacktrace])),
-        error => erlang:list_to_binary(io_lib:format("~p", [Exception]))
+        error => erlang:list_to_binary(io_lib:format("~p", [Exception])),
+        monotonic_time => erlang:monotonic_time(),
+        stacktrace => erlang:list_to_binary(io_lib:format("~p", [Stacktrace]))
     },
     erf_telemetry:event({request_exception, ExceptionData}, Name, Req, {500, [], undefined});
 handle_exception(RawReq, Unexpected, [Name]) ->
     Req = preprocess(Name, RawReq),
     ExceptionData = #{
-        error => erlang:list_to_binary(io_lib:format("~p", [Unexpected]))
+        error => erlang:list_to_binary(io_lib:format("~p", [Unexpected])),
+        monotonic_time => erlang:monotonic_time()
     },
     erf_telemetry:event({request_exception, ExceptionData}, Name, Req, {500, [], undefined}).
 
diff --git a/src/erf_telemetry.erl b/src/erf_telemetry.erl
index e462d3c..0ce9499 100644
--- a/src/erf_telemetry.erl
+++ b/src/erf_telemetry.erl
@@ -22,17 +22,19 @@
 
 %%% TYPES
 -type event() ::
-    {request_complete, req_measurements()}
-    | {chunk_complete, req_measurements()}
+    {request_start, #{monotonic_time := monotonic_time()}}
+    | {request_complete, req_measurements()}
     | {request_exception, exception_data()}.
 
 -type exception_data() :: #{
     error := binary(),
+    monotonic_time := monotonic_time(),
     stacktrace => binary()
 }.
-
+-type monotonic_time() :: integer().
 -type req_measurements() :: #{
     duration := integer(),
+    monotonic_time := monotonic_time(),
     req_body_duration => integer(),
     req_body_length => integer(),
     resp_body_length => integer(),
@@ -43,6 +45,7 @@
 -export_type([
     event/0,
     exception_data/0,
+    monotonic_time/0,
     req_measurements/0
 ]).
 
@@ -53,7 +56,7 @@
     Event :: event(),
     Name :: atom(),
     Req :: erf:request(),
-    Resp :: erf:response().
+    Resp :: undefined | erf:response().
 event({request_exception, ExceptionData} = Event, Name, Req, Resp) ->
     case code:is_loaded(telemetry) of
         {file, _TelemetryBeam} ->
@@ -80,17 +83,22 @@ event({_EventName, Measurements} = Event, Name, Req, Resp) ->
 %%%-----------------------------------------------------------------------------
 %%% INTERNAL FUNCTIONS
 %%%-----------------------------------------------------------------------------
+metadata(Name, Req, undefined, RawMetadata) ->
+    RawMetadata#{
+        name => Name,
+        req => Req
+    };
 metadata(Name, Req, {RespStatus, RespHeaders, _Body}, RawMetadata) ->
     RawMetadata#{
+        name => Name,
         req => Req,
         resp_headers => RespHeaders,
-        resp_status => RespStatus,
-        name => Name
+        resp_status => RespStatus
     }.
 
-metric({request_complete, _}) ->
-    [erf, request, stop];
-metric({chunk_complete, _}) ->
+metric({request_complete, _Measurements}) ->
     [erf, request, stop];
-metric({request_exception, _}) ->
-    [erf, request, fail].
+metric({request_exception, _ExceptionData}) ->
+    [erf, request, fail];
+metric({request_start, _Measurements}) ->
+    [erf, request, start].