feat(#36): Adds telemetry events

rebar.config

@@ -88,13 +88,15 @@
     {erf_http_server_elli, handle, 2},
     {erf_http_server_elli, handle_event, 3},
     {erf_router, handle, 2},
-    {erf_static, mime_type, 1}
+    {erf_static, mime_type, 1},
+    erf_telemetry
 ]}.
 
 {gradualizer_opts, [
     %% TODO: address
     {exclude, [
         "src/erf.erl",
-        "src/erf_router.erl"
+        "src/erf_router.erl",
+        "src/erf_telemetry.erl"
     ]}
 ]}.

src/erf.app.src

@@ -3,5 +3,8 @@
     {vsn, "0.1.2"},
     {registered, []},
     {applications, [kernel, stdlib, compiler, syntax_tools, elli, ndto, njson]},
+    {optional_applications, [
+        telemetry
+    ]},
     {env, []}
 ]}.

src/erf_http_server/erf_http_server_elli.erl

@@ -78,29 +78,38 @@ handle(ElliRequest, [Name]) ->
     ErfResponse = erf_router:handle(Name, ErfRequest),
     postprocess(ErfRequest, ErfResponse).
 
--spec handle_event(Event, Data, CallbackArgs) -> ok when
-    Event :: atom(),
-    Data :: term(),
+-spec handle_event(Event, Args, CallbackArgs) -> ok when
+    Event :: elli_handler:event(),
+    Args :: term(),
     CallbackArgs :: [Name :: atom()].
 %% @doc Handles an elli event.
 %% @private
+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_event(invalid_return, [Request, Unexpected], CallbackArgs) ->
+    handle_exception(Request, Unexpected, CallbackArgs);
 handle_event(request_throw, [Request, Exception, Stacktrace], [Name]) ->
+    handle_exception(Request, [Exception, Stacktrace], [Name]),
     {ok, LogLevel} = erf_conf:log_level(Name),
     ?LOG(LogLevel, "[erf] Request ~p threw exception ~p:~n~p", [Request, Exception, Stacktrace]);
 handle_event(request_error, [Request, Exception, Stacktrace], [Name]) ->
+    handle_exception(Request, [Exception, Stacktrace], [Name]),
     {ok, LogLevel} = erf_conf:log_level(Name),
     ?LOG(LogLevel, "[erf] Request ~p errored with exception ~p.~nStacktrace:~n~p", [
         preprocess(Name, Request), Exception, Stacktrace
     ]);
 handle_event(request_exit, [Request, Exception, Stacktrace], [Name]) ->
+    handle_exception(Request, [Exception, Stacktrace], [Name]),
     {ok, LogLevel} = erf_conf:log_level(Name),
     ?LOG(LogLevel, "[erf] Request ~p exited with exception ~p.~nStacktrace:~n~p", [
         preprocess(Name, Request), Exception, Stacktrace
     ]);
 handle_event(file_error, [ErrorReason], [Name]) ->
     {ok, LogLevel} = erf_conf:log_level(Name),
     ?LOG(LogLevel, "[erf] Returning file errored with reason: ~p", [ErrorReason]);
-handle_event(_Event, _Data, _CallbackArgs) ->
+handle_event(_Event, _Args, _CallbackArgs) ->
     % TODO: take better advantage of the event system
     ok.
 
@@ -135,6 +144,60 @@ build_elli_conf(Name, HTTPServerConf, ExtraElliConf) ->
         ]
     ).
 
+-spec duration(Timings, Key) -> Result when
+    Timings :: list(),
+    Key :: atom(),
+    Result :: integer().
+duration(Timings, request) ->
+    duration(request_start, request_end, Timings);
+duration(Timings, req_body) ->
+    duration(body_start, body_end, Timings);
+duration(Timings, user) ->
+    duration(user_start, user_end, Timings).
+
+-spec duration(StartKey, EndKey, Timings) -> Result when
+    StartKey :: atom(),
+    EndKey :: atom(),
+    Timings :: list(),
+    Result :: integer().
+duration(StartKey, EndKey, Timings) ->
+    Start = proplists:get_value(StartKey, Timings),
+    End   = proplists:get_value(EndKey, Timings),
+    End - Start.
+
+-spec handle_full_response(Event, Args, Config) -> ok when
+    Event :: elli_handler:event(),
+    Args :: elli_handler:callback_args(),
+    Config :: [Name :: atom()].
+handle_full_response(Event, [RawReq, StatusCode, Hs, Body, {Timings, Sizes}], [Name]) ->
+    Metrics = #{
+        duration => duration(Timings, request),
+        req_body_duration => duration(Timings, req_body),
+        req_body_length => size(Sizes, request_body), 
+        resp_body_length => size(Sizes, response_body),
+        resp_duration => duration(Timings, user)
+    },
+    Req = preprocess(Name, RawReq),
+    erf_telemetry:event({Event, Metrics}, Name, Req, {StatusCode, Hs, Body}).
+
+-spec handle_exception(RawReq, Args, Config) -> ok when
+    RawReq :: elli:req(),
+    Args :: term(),
+    Config :: [Name :: atom()].
+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]))
+    },
+    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]))
+    },
+    erf_telemetry:event({request_exception, ExceptionData}, Name, Req, {500, [], undefined}).
+
 -spec postprocess(Request, Response) -> Resp when
     Request :: erf:request(),
     Response :: erf:response(),
@@ -161,8 +224,7 @@ postprocess(_Request, {Status, RawHeaders, RawBody}) ->
     Request :: erf:request().
 preprocess(Name, Req) ->
     Scheme = elli_request:scheme(Req),
-    Host = elli_request:host(Req),
-    Port = elli_request:port(Req),
+    {Host, Port} = host_port(Req),
     Path = elli_request:path(Req),
     Method = preprocess_method(elli_request:method(Req)),
     QueryParameters = elli_request:get_args_decoded(Req),
@@ -217,3 +279,37 @@ preprocess_method('TRACE') ->
     trace;
 preprocess_method(<<"CONNECT">>) ->
     connect.
+
+-spec size(Sizes, Key) -> Result when
+    Sizes :: list(),
+    Key :: atom(),
+    Result :: integer().
+size(Sizes, request_body) ->
+    proplists:get_value(req_body, Sizes);
+size(Sizes, response_body) ->
+    case proplists:get_value(chunks, Sizes) of
+        undefined ->
+        case proplists:get_value(file, Sizes) of
+            undefined ->
+                proplists:get_value(resp_body, Sizes);
+            FileSize -> 
+                FileSize
+        end;
+        ChunksSize -> ChunksSize
+    end.
+
+host_port(Req) ->
+    case {elli_request:host(Req), elli_request:port(Req)} of
+        {undefined, Port} ->
+            HostHeader = proplists:get_value(<<"host">>, elli_request:headers(Req), <<"">>),
+            case string:split(HostHeader, <<":">>) of
+                [RawHost, RawPort] ->
+                    {RawHost, erlang:binary_to_integer(RawPort)};
+                [RawHost] ->
+                    {RawHost, Port};
+                _Error ->
+                    {undefined, Port}
+            end;
+        {Host, Port} ->
+            {Host, Port}
+    end.

src/erf_telemetry.erl

@@ -0,0 +1,96 @@
+%%% Copyright 2024 Nomasystems, S.L. http://www.nomasystems.com
+%%
+%% Licensed under the Apache License, Version 2.0 (the "License");
+%% you may not use this file except in compliance with the License.
+%% You may obtain a copy of the License at
+%%
+%%     http://www.apache.org/licenses/LICENSE-2.0
+%%
+%% Unless required by applicable law or agreed to in writing, software
+%% distributed under the License is distributed on an "AS IS" BASIS,
+%% WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+%% See the License for the specific language governing permissions and
+%% limitations under the License
+
+%% <code>erf</code>'s telemetry module.
+-module(erf_telemetry).
+
+%%% EXTERNAL EXPORTS
+-export([
+    event/4
+]).
+
+%%% TYPES
+-type event() ::
+    {request_complete, req_measurements()}
+    | {chunk_complete, req_measurements()}
+    | {request_exception, exception_data()}.
+
+-type exception_data() :: #{
+    error := binary(),
+    stacktrace => binary()
+}.
+
+-type req_measurements() :: #{
+    duration := integer(),
+    req_body_duration => integer(),
+    req_body_length => integer(),
+    resp_body_length => integer(),
+    resp_duration := integer()
+}.
+
+%%% TYPE EXPORTS
+-export_type([
+    event/0,
+    exception_data/0,
+    req_measurements/0
+]).
+
+%%%-----------------------------------------------------------------------------
+%%% EXTERNAL EXPORTS
+%%%-----------------------------------------------------------------------------
+-spec event(Event, Name, Req, Resp) -> ok when
+    Event :: event(),
+    Name :: atom(),
+    Req :: erf:request(),
+    Resp :: erf:response().
+event({request_exception, ExceptionData} = Event, Name, Req, Resp) ->
+    case code:is_loaded(telemetry) of
+        {file, _TelemetryBeam} ->
+            telemetry:execute(
+                metric(Event),
+                [],
+                metadata(Name, Req, Resp, ExceptionData)
+            );
+        _Error ->
+            ok
+    end;
+event({_EventName, Measurements} = Event, Name, Req, Resp) ->
+    case code:is_loaded(telemetry) of
+        {file, _TelemetryBeam} ->
+            telemetry:execute(
+                metric(Event),
+                Measurements,
+                metadata(Name, Req, Resp, #{})
+            );
+        _Error ->
+            ok
+    end.
+
+%%%-----------------------------------------------------------------------------
+%%% INTERNAL FUNCTIONS
+%%%-----------------------------------------------------------------------------
+metadata(Name, Req, {RespStatus, RespHeaders, _Body}, RawMetadata) ->
+    RawMetadata#{
+        req => Req,
+        resp_headers => RespHeaders,
+        resp_status => RespStatus,
+        name => Name
+    }.
+
+metric({request_complete, _}) ->
+    [erf, request, stop];
+metric({chunk_complete, _}) ->
+    [erf, request, stop];
+metric({request_exception, _}) ->
+    [erf, request, fail].