From 7846fcdb0d00af53991c1b3dcd0b829b891771bb Mon Sep 17 00:00:00 2001 From: "Jose E. Cribeiro Aneiros" Date: Mon, 7 Oct 2024 13:22:13 +0200 Subject: [PATCH] feat(#36): Adds telemetry events closes #36 --- rebar.config | 6 +- src/erf.app.src | 3 + src/erf_http_server/erf_http_server_elli.erl | 88 +++++++++++++++++- src/erf_telemetry.erl | 96 ++++++++++++++++++++ 4 files changed, 187 insertions(+), 6 deletions(-) create mode 100644 src/erf_telemetry.erl diff --git a/rebar.config b/rebar.config index 659a6c7..49bd5e9 100644 --- a/rebar.config +++ b/rebar.config @@ -88,12 +88,14 @@ {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_router.erl" + "src/erf_router.erl", + "src/erf_telemetry.erl" ]} ]}. diff --git a/src/erf.app.src b/src/erf.app.src index af7ed84..373f03d 100644 --- a/src/erf.app.src +++ b/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, []} ]}. diff --git a/src/erf_http_server/erf_http_server_elli.erl b/src/erf_http_server/erf_http_server_elli.erl index f356081..6140ecb 100644 --- a/src/erf_http_server/erf_http_server_elli.erl +++ b/src/erf_http_server/erf_http_server_elli.erl @@ -78,21 +78,30 @@ 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(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(Request), Exception, Stacktrace @@ -100,7 +109,7 @@ handle_event(request_exit, [Request, Exception, Stacktrace], [Name]) -> 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), + resp_duration => duration(Timings, user), + req_body_length => size(Sizes, request_body), + resp_body_length => size(Sizes, response_body) + }, + Req = preprocess(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(RawReq), + ExceptionData = #{ + stacktrace => list_to_binary(io_lib:format("~p", [Stacktrace])), + error => 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(RawReq), + ExceptionData = #{ + error => 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(), @@ -207,3 +270,20 @@ 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. diff --git a/src/erf_telemetry.erl b/src/erf_telemetry.erl new file mode 100644 index 0000000..8be130b --- /dev/null +++ b/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 + +%% erf'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(), + resp_duration := integer(), + req_body_length => integer(), + resp_body_length => 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) + ); + _ -> + 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, #{}) + ); + _ -> + ok + end. + +%%%----------------------------------------------------------------------------- +%%% INTERNAL FUNCTIONS +%%%----------------------------------------------------------------------------- +metadata(Ref, Req, {RespStatus, RespHeaders, _Body}, RawMetadata) -> + RawMetadata#{ + req => Req, + resp_headers => RespHeaders, + resp_status => RespStatus, + ref => Ref + }. + +metric({request_complete, _}) -> + [erf, request, stop]; +metric({chunk_complete, _}) -> + [erf, request, stop]; +metric({request_exception, _}) -> + [erf, request, fail].