From f216f7d511909dfed6017964cd34df0d95b6aba6 Mon Sep 17 00:00:00 2001 From: GalaxyGorilla Date: Thu, 9 Jun 2016 14:05:11 +0200 Subject: [PATCH] Add server side peer information to logging The new lager tracing field `hello_request_peer` can have the following values: * `internal` for internal (pure Erlang) communication * an IP like `127.0.0.1` when HTTP is used * an identity string which is generated by ZeroMQ --- include/hello_log.hrl | 38 ++++++++++++++++++++------------------ src/hello_handler.erl | 26 +++++++++++++------------- src/hello_log.erl | 12 +++++++++++- test/hello_SUITE.erl | 12 ++++++++++-- 4 files changed, 54 insertions(+), 34 deletions(-) diff --git a/include/hello_log.hrl b/include/hello_log.hrl index e6493f6..5f640f3 100644 --- a/include/hello_log.hrl +++ b/include/hello_log.hrl @@ -9,48 +9,50 @@ lists:append([[{status_code, element(2, LogId)}, {message_id, element(1, LogId)}], Meta, ?DEFAULT_TRACES])). %% hello_handler specific log macros --define(REQ_TRACES(Mod, HandlerId, Request, RequestStatus, Response, LogId), - lists:append([?REQ_TRACES(Mod, HandlerId, Request, RequestStatus, LogId), [{hello_response, hello_log:format(Response)}]])). +-define(REQ_TRACES(Mod, HandlerId, Context, Request, RequestStatus, Response, LogId), + lists:append([?REQ_TRACES(Mod, HandlerId, Context, Request, RequestStatus, LogId), [{hello_response, hello_log:format(Response)}]])). --define(REQ_TRACES(Mod, HandlerId, Request, RequestStatus, LogId), +-define(REQ_TRACES(Mod, HandlerId, Context, Request, RequestStatus, LogId), ?DEFAULT_META([{hello_request, hello_log:format(Request)}, {hello_request_id, hello_log:get_id(Request)}, + {hello_request_peer, hello_log:format_context(peer, Context)}, {hello_request_method, hello_log:get_method(Request)}, {hello_request_status, RequestStatus}, {hello_service_id, HandlerId}, {hello_handler_callback, Mod}], LogId)). --define(LOG_REQUEST_async_reply(CallbackModule, HandlerId, Request, Response, LogId), - lager:debug(?REQ_TRACES(CallbackModule, HandlerId, Request, ok, Response, LogId), +-define(LOG_REQUEST_async_reply(CallbackModule, HandlerId, Context, Request, Response, LogId), + lager:debug(?REQ_TRACES(CallbackModule, HandlerId, Context, Request, ok, Response, LogId), "~p / ~p : received request", [CallbackModule, hello_log:get_method(Request)])). --define(LOG_REQUEST_request(CallbackModule, HandlerId, Request, Response, Time, LogId), - lager:debug(?REQ_TRACES(CallbackModule, HandlerId, Request, ok, Response, LogId), +-define(LOG_REQUEST_request(CallbackModule, HandlerId, Context, Request, Response, Time, LogId), + lager:debug(?REQ_TRACES(CallbackModule, HandlerId, Context, Request, ok, Response, LogId), "~p / ~p : received request [~w ms]", [CallbackModule, hello_log:get_method(Request), Time])). --define(LOG_REQUEST_request_stop(CallbackModule, HandlerId, Request, Response, Reason, Time, LogId), - lager:info(lists:append(?REQ_TRACES(CallbackModule, HandlerId, Request, ok, Response, LogId), [{hello_error_reason, Reason}]), +-define(LOG_REQUEST_request_stop(CallbackModule, HandlerId, Context, Request, Response, Reason, Time, LogId), + lager:info(lists:append(?REQ_TRACES(CallbackModule, HandlerId, Context, Request, ok, Response, LogId), [{hello_error_reason, Reason}]), "~p / ~p : received request [~w ms]", [CallbackModule, hello_log:get_method(Request), Time])). --define(LOG_REQUEST_request_no_reply(CallbackModule, HandlerId, Request, Time, LogId), - lager:debug(?REQ_TRACES(CallbackModule, HandlerId, Request, ok, LogId), +-define(LOG_REQUEST_request_no_reply(CallbackModule, HandlerId, Context, Request, Time, LogId), + lager:debug(?REQ_TRACES(CallbackModule, HandlerId, Context, Request, ok, LogId), "~p / ~p : received request [~w ms]", [CallbackModule, hello_log:get_method(Request), Time])). --define(LOG_REQUEST_request_stop_no_reply(CallbackModule, HandlerId, Request, Time, LogId), - lager:debug(?REQ_TRACES(CallbackModule, HandlerId, Request, ok, LogId), +-define(LOG_REQUEST_request_stop_no_reply(CallbackModule, HandlerId, Context, Request, Time, LogId), + lager:debug(?REQ_TRACES(CallbackModule, HandlerId, Context, Request, ok, LogId), "~p / ~p : received request [~w ms]", [CallbackModule, hello_log:get_method(Request), Time])). --define(LOG_REQUEST_request_stop_no_reply(CallbackModule, HandlerId, Request, Reason, Time, LogId), - lager:debug(lists:append(?REQ_TRACES(CallbackModule, HandlerId, Request, ok, LogId), [{hello_error_reason, Reason}]), +-define(LOG_REQUEST_request_stop_no_reply(CallbackModule, HandlerId, Context, Request, Reason, Time, LogId), + lager:debug(lists:append(?REQ_TRACES(CallbackModule, HandlerId, Context, Request, ok, LogId), [{hello_error_reason, Reason}]), "~p / ~p : received request [~w ms]", [CallbackModule, hello_log:get_method(Request), Time])). --define(LOG_REQUEST_bad_request(CallbackModule, HandlerId, Request, Reason, LogId), - lager:error(lists:append(?REQ_TRACES(CallbackModule, HandlerId, Request, error, LogId), [{hello_error_reason, Reason}]), +-define(LOG_REQUEST_bad_request(CallbackModule, HandlerId, Context, Request, Reason, LogId), + lager:error(lists:append(?REQ_TRACES(CallbackModule, HandlerId, Context, Request, error, LogId), [{hello_error_reason, Reason}]), "~p / ~p : received bad request", [CallbackModule, hello_log:get_method(Request)])). --define(LOG_WARNING_reason(CallbackModule, HandlerId, Msg, Args, Reason, LogId), +-define(LOG_WARNING_reason(CallbackModule, HandlerId, Context, Msg, Args, Reason, LogId), lager:error(?DEFAULT_META([{hello_handler_callback, CallbackModule}, {hello_error_reason, Reason}, + {hello_request_peer, hello_log:format_context(peer, Context)}, {hello_service_id, HandlerId}], LogId), Msg, Args)). diff --git a/src/hello_handler.erl b/src/hello_handler.erl index b7be071..d94a938 100644 --- a/src/hello_handler.erl +++ b/src/hello_handler.erl @@ -155,7 +155,7 @@ handle_cast({request, Request = #request{context = Context}}, Error:Reason -> send(Context, {error, {server_error, "handler error", undefined}}), hello_metrics:update_handler_request(error, MetricsInfo, 0), %% TODO: add timestamp - ?LOG_REQUEST_bad_request(Mod, Id, Request, {Error, Reason, erlang:get_stacktrace()}, ?LOGID24), + ?LOG_REQUEST_bad_request(Mod, Id, Context, Request, {Error, Reason, erlang:get_stacktrace()}, ?LOGID24), {stop, normal, State} end; handle_cast({set_idle_timeout, Timeout}, State = #state{timer = Timer}) -> @@ -165,11 +165,11 @@ handle_cast({async_reply, ReqContext, Result}, State = #state{id = Id, async_rep #context{req_ref = ReqRef} = ReqContext, case gb_trees:lookup(ReqRef, AsyncMap) of {value, Request} -> - ?LOG_REQUEST_async_reply(Mod, Id, Request, Result, ?LOGID25), + ?LOG_REQUEST_async_reply(Mod, Id, ReqContext, Request, Result, ?LOGID25), send(ReqContext, {ok, Result}), {noreply, State#state{async_reply_map = gb_trees:delete(ReqRef, AsyncMap)}}; none -> - ?LOG_WARNING_reason(Mod, Id, "~p : received unknown async reply", + ?LOG_WARNING_reason(Mod, Id, ReqContext, "~p : received unknown async reply", [Mod], {unknown_async_reply, {ReqRef, Result}}, ?LOGID26), {noreply, State} end. @@ -181,11 +181,11 @@ handle_call(_Call, _From, State) -> %% @hidden handle_info({?IDLE_TIMEOUT_MSG, TimerRef}, State = #state{timer = Timer, id = Id, mod = Mod}) when Timer#timer.idle_timeout_ref == TimerRef -> - ?LOG_WARNING_reason(Mod, Id, "~p : stopping due to idle timeout", [Mod], {error, idle_timeout}, ?LOGID27), + ?LOG_WARNING_reason(Mod, Id, undefined, "~p : stopping due to idle timeout", [Mod], {error, idle_timeout}, ?LOGID27), NewTimer = Timer#timer{stopped_because_idle = true}, {stop, normal, State#state{timer = NewTimer}}; handle_info({?IDLE_TIMEOUT_MSG, OtherRef}, State = #state{mod = Mod, id = Id}) -> - ?LOG_WARNING_reason(Mod, Id, "~p : received unknown idle timeout message", [Mod], + ?LOG_WARNING_reason(Mod, Id, undefined, "~p : received unknown idle timeout message", [Mod], {error, {unknown_timeout_message, OtherRef}}, ?LOGID28), {noreply, State}; handle_info({?INCOMING_MSG, Request = #request{context = Context}}, State0) -> @@ -230,39 +230,39 @@ do_request(Request = #request{context = Context}, TimeMS = Time / 1000, % in ms case Value of {reply, Response, NewHandlerState} -> - ?LOG_REQUEST_request(Mod, Id, Request, Response, TimeMS, ?LOGID29), + ?LOG_REQUEST_request(Mod, Id, Context1, Request, Response, TimeMS, ?LOGID29), send(Context1, Response), hello_metrics:update_handler_request(success, MetricsInfo, TimeMS), {noreply, State#state{state = NewHandlerState}}; {noreply, NewModState} -> - ?LOG_REQUEST_request_no_reply(Mod, Id, Request, TimeMS, ?LOGID30), + ?LOG_REQUEST_request_no_reply(Mod, Id, Context1, Request, TimeMS, ?LOGID30), hello_metrics:update_handler_request(success, MetricsInfo, TimeMS), {noreply, State#state{state = NewModState, async_reply_map = gb_trees:enter(ReqRef, Request, AsyncMap)}}; {stop, Reason, Response, NewModState} -> - ?LOG_REQUEST_request_stop(Mod, Id, Request, Response, Reason, TimeMS, ?LOGID31), + ?LOG_REQUEST_request_stop(Mod, Id, Context1, Request, Response, Reason, TimeMS, ?LOGID31), send(Context1, Response), hello_metrics:update_handler_request(success, MetricsInfo, TimeMS), {stop, Reason, State#state{state = NewModState}}; {stop, Reason, NewModState} -> - ?LOG_REQUEST_request_stop_no_reply(Mod, Id, Request, Reason, TimeMS, ?LOGID32), + ?LOG_REQUEST_request_stop_no_reply(Mod, Id, Context1, Request, Reason, TimeMS, ?LOGID32), hello_metrics:update_handler_request(success, MetricsInfo, TimeMS), {stop, Reason, State#state{mod = NewModState}}; {stop, NewModState} -> - ?LOG_REQUEST_request_stop_no_reply(Mod, Id, Request, TimeMS, ?LOGID33), + ?LOG_REQUEST_request_stop_no_reply(Mod, Id, Context1, Request, TimeMS, ?LOGID33), hello_metrics:update_handler_request(success, MetricsInfo, TimeMS), {stop, State#state{mod=NewModState}}; {ignore, NewModState} -> - ?LOG_REQUEST_request(Mod, Id, Request, ignore, TimeMS, ?LOGID29), + ?LOG_REQUEST_request(Mod, Id, Context1, Request, ignore, TimeMS, ?LOGID29), hello_metrics:update_handler_request(success, MetricsInfo, TimeMS), {noreply, State#state{state = NewModState}} end; {error, {_Code, _Message, _Data} = Reason} -> - ?LOG_REQUEST_bad_request(Mod, Id, Request, Reason, ?LOGID24), + ?LOG_REQUEST_bad_request(Mod, Id, Context1, Request, Reason, ?LOGID24), send(Context1, {error, Reason}), hello_metrics:update_handler_request(error, MetricsInfo, 0), {stop, normal, State}; _FalseAnswer -> - ?LOG_REQUEST_bad_request(Mod, Id, Request, _FalseAnswer, ?LOGID24), + ?LOG_REQUEST_bad_request(Mod, Id, Context1, Request, _FalseAnswer, ?LOGID24), send(Context1, {error, {server_error, "validation returned wrong error format", null}}), hello_metrics:update_handler_request(error, MetricsInfo, 0), {stop, normal, State} diff --git a/src/hello_log.erl b/src/hello_log.erl index 40f2441..84389a5 100644 --- a/src/hello_log.erl +++ b/src/hello_log.erl @@ -21,7 +21,7 @@ % @private -module(hello_log). --export([format/1, get_id/1, get_method/1]). +-export([format/1, format_context/2, get_id/1, get_method/1]). -include("hello.hrl"). @@ -48,6 +48,16 @@ format(ignore) -> ["ignored"]; format({ok, CallbackResponse}) -> stringify(CallbackResponse); format(Msg) -> stringify(Msg). +%% -- format parts of the request context +%% There are three possible types of 'peer': +%% 1. a reference when an internal 'service' is used +%% 2. a ZeroMQ peer identity (a binary) +%% 3. an IP with Port when HTTP is used +format_context(peer, #context{peer = Peer}) when is_reference(Peer) -> "internal"; +format_context(peer, #context{peer = Peer}) when is_binary(Peer) -> stringify(Peer); +format_context(peer, #context{peer = {IP, _Port}}) -> inet_parse:ntoa(IP); +format_context(_, _) -> "unavailable". + %% -- get internal hello request id get_id([ #request{id = Id} ]) -> stringify(Id); get_id([ #request{id = Id} | Requests]) -> stringify(Id) ++ ", " ++ get_id(Requests); diff --git a/test/hello_SUITE.erl b/test/hello_SUITE.erl index 757ebd0..63f11f9 100644 --- a/test/hello_SUITE.erl +++ b/test/hello_SUITE.erl @@ -3,6 +3,7 @@ -include_lib("common_test/include/ct.hrl"). -include("hello_test.hrl"). +-include("../include/hello.hrl"). -include("../include/jsonrpc_internal.hrl"). % --------------------------------------------------------------------- @@ -117,6 +118,12 @@ time_metrics(_Config) -> true = Uptime > 0, ok. +log_format(_Config) -> + "internal" = hello_log:format_context(peer, #context{peer = make_ref()}), + "127.0.0.1" = hello_log:format_context(peer, #context{peer = {{127, 0, 0, 1}, 8080}}), + "12345" = hello_log:format_context(peer, #context{peer = <<"12345">>}), + ok. + % --------------------------------------------------------------------- % -- common_test callbacks all() -> @@ -127,8 +134,9 @@ all() -> start_named_supervised, keep_alive, request_metrics, - time_metrics - ]. + time_metrics, + log_format + ]. init_per_suite(Config) -> hello:start(),