From 833b40e56666d92147e479b3111d528bf90f4f69 Mon Sep 17 00:00:00 2001 From: GalaxyGorilla Date: Thu, 3 Sep 2015 16:28:33 +0200 Subject: [PATCH] This commit aims to enhance the logging in hello regarding aspects: - introduction to status codes and message ids - human readable log messages - log level is configured to info or debugfor every log - documentation of log messages with status codes - more logs in hello client - introduction of several tracing possibilities - more meta fields for journald - no functional changes should be included --- README.md | 29 +-- doc/logging.md | 234 +++++++++++++++++++++++++ include/hello_log.hrl | 109 +++++++----- include/hello_log_ids.hrl | 90 ++++++++++ src/hello_client.erl | 179 ++++++++++++++----- src/hello_handler.erl | 55 +++--- src/hello_log.erl | 46 ++++- src/hello_metrics.erl | 2 +- src/hello_registry.erl | 18 +- src/hello_router.erl | 8 +- src/hello_service.erl | 3 +- src/hello_supervisor.erl | 10 +- src/protocols/hello_proto_jsonrpc.erl | 10 +- src/transports/hello_http_client.erl | 17 +- src/transports/hello_http_listener.erl | 12 +- src/transports/hello_zmq_client.erl | 13 +- src/transports/hello_zmq_listener.erl | 24 ++- test/jsonrpc_SUITE.erl | 4 +- 18 files changed, 684 insertions(+), 179 deletions(-) create mode 100644 doc/logging.md create mode 100644 include/hello_log_ids.hrl diff --git a/README.md b/README.md index 111874d..2d45bcd 100644 --- a/README.md +++ b/README.md @@ -100,42 +100,29 @@ You can start client with keep alive support: # Logging -Hello log request and responses through lager on level INFO. Lager metadata fields -'hello_request' and 'hello_handler' are set to support tracing. -'hello_request' is set to 'api' for normal request and to 'error' for undecoded (bad) -requests. 'hello_handler' is set to the name of the handler module. -'class' is set to 'hello' for tracing all hello logs. 'hello_method' if set for method tracing. +Hello logs with lager on level 'debug' and 'info'. There is a strong tracing support, e.g. +traces like {class, hello}, {hello_request_method, some_method} or {hello_request_status, ok | error} +are available (see hello_log.hrl for more). To write all bad request to a file use: {lager, [ {handlers, [ - {lager_file_backend, [{file, "bad_request.log"}, {level, none}]} + {lager_file_backend, [{file, "bad_request.log"}, {level, info}]} ]}, {traces, [ - {{lager_file_backend, "bad_request.log"}, [{hello_request, error}], info} + {{lager_file_backend, "bad_request.log"}, [{hello_request_status, error}], info} ]} ]} -To write all requests for a module hello_stateful_handler_example to a file use: +To write all requests for a module hello_handler_example to a file use: {lager, [ {handlers, [ - {lager_file_backend, [{file, "hello_stateful_handler_example.log"}, {level, none}]} + {lager_file_backend, [{file, "hello_handler_example.log"}, {level, none}]} ]}, {traces, [ - {{lager_file_backend, "hello_stateful_handler_example.log"}, [{hello_handler, hello_handler_example}], info} - ]} - ]} - -To write all requests for a method `Test.try` to a file use: - - {lager, [ - {handlers, [ - {lager_file_backend, [{file, "hello_stateful_handler_example.log"}, {level, none}]} - ]}, - {traces, [ - {{lager_file_backend, "hello_stateful_handler_example.log"}, [{hello_method, <<"Test.try">>}], info} + {{lager_file_backend, "hello_handler_example.log"}, [{hello_handler_callback, hello_handler_example}], info} ]} ]} diff --git a/doc/logging.md b/doc/logging.md new file mode 100644 index 0000000..4604e8e --- /dev/null +++ b/doc/logging.md @@ -0,0 +1,234 @@ +### Logging in hello + +##### This document describes the status codes used in hello. Status codes should be seen in logging as a 4-digit number prepended to the actual log message. The first digit is aligned to http status codes (e.g. 2 is 'ok', 4 for client error, 5 for server errors and similar for other digits) while the following last digits define the statement more precisely. + +| Logging Class | ID | +|-------------------------------------------|-----| +| Initialization (app) | 00* | +| Initialization (client) | 10* | +| Initialization (server) | 11* | +| Message passing (client) | 20* | +| Message passing (server) | 21* | +| Message creation and parsing (client) | 30* | +| Message creation and parsing (server) | 31* | +| Routing (server only) | 40* | +| Metrics | 50* | +| Registry | 60* | + +#### 4200 + +* ___Messages___: + * [ec504cee59b245c0861b78ccd936b856] Request from hello client @CLIENT@ on method(s) @METHOD@ failed with reason @REASON@. + * [cb4c75e200f74a279ca3373e37eb7f81] Hello client @CLIENT@ attempted to send binary request on method(s) @METHOD@ but failed with reason @REASON@. +* ___Explanation___: Hello client attempted to send a request but failed due to issues with encoding or transport specific reasons. +* ___Level___: info + +#### 4300 + +* ___Messages___: + * [d7a051ed5dab4b50afa67ca5fadd6077] Creation of request from hello client @Client@ failed for a call with reason @REASON@. + * [b68c94425c1f40aca74ef33e13eccbfc] Hello client @CLIENT@ attempted to encode request on method(s) @METHOD@ but failed with reason @REASON@. +* ___Explanation___: Hello client attempted to create a request but failed due to protocol specific reasons. +* ___Level___: info + +#### 4301 + +* ___Messages___: + * [c2763c7aba514282a48a87dee13e7738] Hello client @CLIENT@ failed to decode response with reason @REASON@. +* ___Explanation___: Hello client attempted to decode a response but failed due to issues with the protocol specific creation process. +* ___Level___: info + +#### 2302 + +* ___Messages___: + * [d77a63a5b17c4f0499fc9360083aa7a1] Hello client @CLIENT@ attempted to encode request on method(s) @METHOD@ but ignored sending request. +* ___Explanation___: Hello client attempted to encode or decode a response but ignored further processing. +* ___Level___: debug + + +#### 2100 + +* ___Messages___: + * [ff6a6c3ae0734a65b2845c39d223b249] Initializing hello client @CLIENT@ on @URL@ ... + * [b31ad32a76a94d78b866b2e168f9f7d3] Hello client @CLIENT@ initialized successfully. + * [c2ba31819c384d76966d6bdb0cf02250] Hello client @CLIENT@ initialized successfully with keep alive. +* ___Explanation___: Hello client initializing process. Protocol and transport state are initialized. +* ___Level___: debug + +#### 4100 + +* ___Messages___: + * [bd8b9bc7d0ef48a98f6286c779781985] Hello client @CLIENT@ is unable to initialize protocol because of reason @REASON@. + * [a55b446c103646b2a84543a907c13378] Hello client @CLIENT@ unable to initialize transport because of reason @REASON@. +* ___Explanation___: Hello client protocol or transport handler returned an error reason @REASON@. +* ___Level___: info + +#### 2200 + +* ___Messages___: + * [e9f0397b5b814c3abd55f3a474815f6c] Hello client @CLIENT@ received notification. + * [f819220efa73409fa896aaafc0c21d30] Hello client @CLIENT@ received single response. + * [a953af5734984f39b1c26a3541a1f48f] Hello client @CLIENT@ received batch response. + * [bfde238fb72f420996cb52eaeda474df] Hello client @CLIENT@ sent request on method(s) @METHOD@. +* ___Explanation___: The client sent or received a response on a request. +* ___Level___: debug + +#### 2201 + +* ___Messages___: + * [bc9ed80e61cb441c952422c649a3ff3e] Hello client @CLIENT@ received internal message. + * [d330d615c9a84f9dadd4a327fa3ac2fe] Hello client @CLIENT@ sent PING request. Pinging server again in @TIME@ milliseconds. + * [ef4efe6bb336491990b99cc1113adb85] Hello client @CLIENT@ received PONG response. Pinging server again in @TIME@ milliseconds. +* ___Explanation___: The client sent or received a message for e.g. informational purposes. This does affect functionality of the client, e.g. keep alive mechanisms or similar. +* ___Level___: debug + +#### 2202 + +* ___Messages___: + * [d406dffdf263429eac4e64b7c52f7276] Hello client @CLIENT@ received error notification from transport handler with reason @REASON@. + * [a887733cce7949f5a1d041441ccdfdfc] Hello client @CLIENT@ ignored decoding binary response. + * [e61cd5d46b344504aad275c1f4831f90] Hello client @CLIENT@ got response for non-existing request id @ID@. +* ___Explanation___: The client sent or received a message for e.g. informational purposes. This does not affect functionality of the client. +* ___Level___: debug + +#### 2203 + +* ___Messages___: + * [e6fa0b7a7ffb45f29a359eca6776b369] Hello ZeroMQ client attempted to establish connection to @URL@ returning @RESULT@. +* ___Explanation___: The client transport initlializes a connection. +* ___Level___: debug + +#### 4201 + +* ___Messages___: + * [d3cbc27eb6ab43f2b2dfc9114c122054] Hello http client received an error after executing a request to @URL@ with reason @REASON@. + * [cd035f8d88aa45cca84b67a4227c8cd6] Error in hello client @CLIENT@: There is no PONG answer on PING for @TIME@ msec. Connection will be reestablished. +* ___Explanation___: The client sent or received an error message for e.g. informational purposes. This has no impact on the functionality of the client. +* ___Level___: info + +#### 5210 + +* ___Messages___: + * [e2f93d4effd2479fa7a6291b2c9da1dd] Hello handler with callback @CALLBACK@ and service id @ID@ dismissed bad request on method(s) @METHOD@. +* ___Explanation___: Hello handler attempted to handle an invalid request possibly triggering to stop the handler, e.g. validation procedures noticed an invalid method name or similar. +* ___Level___: info + +#### 2210 + +* ___Messages___: + * [fc965b4e012648578c379fe0faae3461] Hello handler with callback @CALLBACK@ and service id @ID@ answered async request on method(s) @METHOD@. + * [c457bf8eb8574927bb1285bc32c18aff] Hello handler with callback @CALLBACK@ and service id @ID@ answered synced request on method(s) @METHOD@ in @TIME@ ms. +* ___Explanation___: Hello handler successfully proceeded a request. +* ___Level___: debug + +#### 2212 + +* ___Messages___: + * [a7237645a763489591c1559b7ec586b8] Hello handler with callback module @CALLBACK@ and service id @ID@ got unknown async reply. + * [b9ab6b39134542fdbf0fabd7a88e8a19] Hello handler with callback module @CALLBACK@ and service id @ID@ received unknown idle timeout message. + * [da812da4d818443a872767687edd47f3] Hello handler with callback @CALLBACK@ and service id @ID@ received async request on method(s) @METHOD@ in @TIME@ ms. + * [b3543661a8b2472984874c9c7325fa81] Hello handler with callback @CALLBACK@ and service id @ID@ answered synced request on method(s) @METHOD@ and stopped with reason @REASON@ in @TIME@ ms. + * [aeb8bd41d1ed47048e6ea6056cade3ac] Hello handler with callback @CALLBACK@ and service id @ID@ received async request on method(s) @METHOD@ and stopped with reason @REASON@ in @TIME@ ms. + * [aee0c58903824a139d1b1df028c223d6] Hello Handler with callback @CALLBACK@ and service id @ID@ received async request on method(s) @METHOD@ and stopped with reason normal in @TIME@ ms. +* ___Explanation___: Hello handler noticed difficulties in proceeding a request. This has no impact in the functionality of the handler (besides intended stop mechanisms). +* ___Level___: debug + +#### 4101 + +* ___Messages___: + * [a95801c548ad4f508f315334ff79f199] Hello http client invoked with invalid options. Terminated with reason @REASON@. +* ___Explanation___: Hello client transport could't be initialized. +* ___Level___: info + +#### 2400 + +* ___Messages___: + * [c68287edeaac43fe96f49161eb8f44ba] Handler for service @NAME@ and identifier @ID@ not found. Starting handler. + * [d3496f96a1154dad96e5ec469dda164b] Found handler @HANDLER@ for service @NAME@ and identifier @ID@. + * [cfe782643a4e49a581a94c2ae146e683] Hello router resolved namespace @NAMESPACE@ to hello handler @HANDLER@. + * [eab6276590fc4d84996662f4c13a271a] Hello http client: DNS discovery service resolved path @PATH@ to host @IP@. + * [d80498ec152342eba94827f005123d27] Hello ZeroMQ client: DNS discovery service resolved path @PATH@ to host @IP@. + * [af5e3e79776642e4851709b58e7ea790] DNS discovery service registered app @APP@ with name @NAME@ on port @PORT@. +* ___Explanation___: Hello router successfully attempts to find a handler for a request. +* ___Level___: debug + +#### 2402 + +* ___Messages___: + * [a48b0a9d2aaa477494fade8ace87f20f] Hello https client received message @MSG@ from DNS discovery service. + * [eafe96b96fb447c59ba19d8452ee16f8] Hello ZeroMQ client ignored message @MSG@ from DNS discovery service. + * [e849ee8a79b2435394e81b51894a617c] Hello ZeroMQ listener ignored message @MSG@ from DNS discovery service. + * [a3fcdc9a486247d1af5ea679d0f724e9] Hello registry received message @MSG@ from DNS service discovery. +* ___Explanation___: Some module ignored a message from the DNS-DS. +* ___Level___: debug + +#### 5400 + +* ___Messages___: + * [aee45db4a0a4465687588331edc8bde4] Hello router couldn't find service for a key @KEY@. Request is dismissed. + * [eda0efbe7f6d490490e00ae4055629d2] Hello service @NAME@ not found. +* ___Explanation___: Hello handler can't resolve a lookup and will return method_not_found. +* ___Level___: info + +#### 5211 + +* ___Messages___: + * [aabd551dcc334fe093954d19b4dcc445] Hello handler with callback module @CALLBACK@ and service id @ID@ is going to stop due to idle timeout. + * [cb26c528ecb2474db3078ca1156ba7ba] Hello http listener received an error while streaming the response body. + * [dea8dfd8818e432bb61a64ca88e35a9e] Hello ZeroMQ listener received bad message @MSG@ from @PID@. +* ___Explanation___: Hello handler transport noticed problems handling a request or sending back a response. +* ___Level___: info + +#### 5213 + +* ___Messages___: + * [c0ea6cda30b64f10be3db0ee5fdc22d1] Hello ZeroMQ listener was unable to bind on @URL@ because of reason @REASON@. +* ___Explanation___: Hello handler transport noticed problems in the initializing process. +* ___Level___: info + +#### 5500 + +* ___Messages___: + * [adcfa613af3d40538bddb1e5fd178139] Hello metrics received unknown subscription type @TYPE@. + * [b5886b31a45d422bb02422aaf072797b] Hello registry received unknown key @KEY@ for register metric. +* ___Explanation___: Hello metrics noticed problems in processing metric information. +* ___Level___: debug + +#### 5600 + +* ___Messages___: + * [bb0ea6d2b9c74a78afa724889ceee0b5] Hello registry received @EXIT@ signal from monitored process @PID@ with reason @REASON@. + * [da5cd3be4435462dafff47b1bbc34a62] Hello registry received @EXIT@ signal from monitored process @PID@ with reason @REASON@. Going to clean up associated processes @PIDS@. + * [ab5f921ed6e7488293241dc27eaf102e] Hello registry attempted to register process @PID@ with key @KEY@, but process is not alive. +* ___Explanation___: Hello registry noticed problems in registering or monitoring processes. +* ___Level___: info + +#### 2600 + +* ___Messages___: + * [bd8ad7e2a04940e8bc4fd7417d2907aa] Hello registry is going to register process @PID@ with key @KEY@ and data @DATA@. +* ___Explanation___: Hello registry registering process. +* ___Level___: debug + +#### 4000 + +* ___Messages___: + * [a3b473cec1c841d0ada3232fafe8d081] Hello supervisor got invalid list @LIST@ of roles. + * [be1432aa9c074facae66b9d6786de2e5] Hello supervisor got invalid role @ROLE@. +* ___Explanation___: Problems in hello application initialization. +* ___Level___: info + +#### 4102 + +* ___Messages___: + * [ab65930009164e7fb6419b615b4ae4b5] Hello client invoked with invalid JSONRPC version @VERSION@. +* ___Explanation___: Problems in client protocol initialization. +* ___Level___: info + +#### 4310 + +* ___Messages___: + * [bd81f08a8fc94502bcbd07975e952016] Hello proto unable to decode binary request with error @ERROR@. + * [c796ed5e01f0455fb09c42e0f04198c1] Hello proto attempted to decode invalid notification object. +* ___Explanation___: Problems in decoding binary requests. +* ___Level___: info diff --git a/include/hello_log.hrl b/include/hello_log.hrl index 97df89f..d507483 100644 --- a/include/hello_log.hrl +++ b/include/hello_log.hrl @@ -2,53 +2,70 @@ -define(HELLO_LOG, 1). -include("hello.hrl"). +-include("hello_log_ids.hrl"). -define(DEFAULT_TRACES, [{class, hello}]). --define(REQ_TRACES(Mod, Method), [{class, hello}, {hello_request, api}, {hello_handler, Mod}, {hello_method, Method}]). --define(BAD_TRACES(Mod, Method), [{class, hello}, {hello_request, error}, {hello_handler, Mod}, {hello_method, Method}]). - --define(LOG_REQUEST_async_reply(CallbackModule, HandlerPid, Request, Response), - lager:info(?REQ_TRACES(CallbackModule, Request#request.method), - "async reply on ~w. ~s - ~s", - [HandlerPid, hello_log:fmt_request(Request), hello_log:fmt_response(Response)])). - --define(LOG_REQUEST_request(CallbackModule, HandlerPid, Request, Response, Time), - lager:info(?REQ_TRACES(CallbackModule, Request#request.method), - "request on ~w. ~s - ~s (~w ms)", - [HandlerPid, hello_log:fmt_request(Request), hello_log:fmt_response(Response), Time])). - --define(LOG_REQUEST_request_stop(CallbackModule, HandlerPid, Request, Response, Reason, Time), - lager:info(?REQ_TRACES(CallbackModule, Request#request.method), - "request on ~w. ~s - ~s (stopped with reason ~w) (~w ms)", - [HandlerPid, hello_log:fmt_request(Request), hello_log:fmt_response(Response), Reason, Time])). - --define(LOG_REQUEST_request_no_reply(CallbackModule, HandlerPid, Request, Time), - lager:info(?REQ_TRACES(CallbackModule, Request#request.method), - "request on ~w. ~s - noreply (~w ms)", - [HandlerPid, hello_log:fmt_request(Request), Time])). - --define(LOG_REQUEST_request_stop_no_reply(CallbackModule, HandlerPid, Request, Time), - lager:info(?REQ_TRACES(CallbackModule, Request#request.method), - "request on ~w. ~s (stopped with reason normal) (~w ms)", - [HandlerPid, hello_log:fmt_request(Request), Time])). - --define(LOG_REQUEST_request_stop_no_reply(CallbackModule, HandlerPid, Request, Reason, Time), - lager:info(?REQ_TRACES(CallbackModule, Request#request.method), - "request on ~w. ~s (stopped with reason ~w) (~w ms)", - [HandlerPid, hello_log:fmt_request(Request), Reason, Time])). - --define(LOG_REQUEST_bad_request(CallbackModule, HandlerPid, Request, Reason), - lager:error(?BAD_TRACES(CallbackModule, Request#request.method), - "bad request on ~w. ~s - ~w", - [HandlerPid, hello_log:fmt_request(Request), Reason])). - --define(LOG_DEBUG(Msg, Args), lager:debug(?DEFAULT_TRACES, Msg, Args)). --define(LOG_INFO(Msg, Args), lager:info(?DEFAULT_TRACES, Msg, Args)). --define(LOG_NOTICE(Msg, Args), lager:notice(?DEFAULT_TRACES, Msg, Args)). --define(LOG_WARNING(Msg, Args), lager:warning(?DEFAULT_TRACES, Msg, Args)). --define(LOG_ERROR(Msg, Args), lager:error(?DEFAULT_TRACES, Msg, Args)). --define(LOG_CRITICAL(Msg, Args), lager:critical(?DEFAULT_TRACES, Msg, Args)). --define(LOG_ALERT(Msg, Args), lager:alert(?DEFAULT_TRACES, Msg, Args)). --define(LOG_EMERGENCY(Msg, Args), lager:emergency(?DEFAULT_TRACES, Msg, Args)). +-define(DEFAULT_META(Meta, LogId), + 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, Request, RequestStatus, LogId), + ?DEFAULT_META([{hello_request, hello_log:format(Request)}, + {hello_request_id, hello_log:get_id(Request)}, + {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), + "Hello handler with callback '~p' and service id '~p' answered async request on method(s) '~p'.", + [CallbackModule, HandlerId, 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), + "Hello handler with callback '~p' and service id '~p' answered synced request on method(s) '~p' in '~w' ms.", + [CallbackModule, HandlerId, 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}]), + "Hello handler with callback '~p' and service id '~p' answered synced request on method(s) '~p' and stopped in '~w' ms.", + [CallbackModule, HandlerId, 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), + "Hello handler with callback '~p' and service id '~p' received async request on method(s) '~p' in ~w ms.", + [CallbackModule, HandlerId, 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), + "Hello Handler with callback '~p' and service id '~p' received async request on method(s) '~p' and stopped with reason normal in '~w' ms.", + [CallbackModule, HandlerId, 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}]), + "Hello handler with callback '~p' and service id '~p' received async request on method(s) '~p' and stopped in '~w' ms.", + [CallbackModule, HandlerId, hello_log:get_method(Request), Time])). + +-define(LOG_REQUEST_bad_request(CallbackModule, HandlerId, Request, Reason, LogId), + lager:info(lists:append(?REQ_TRACES(CallbackModule, HandlerId, Request, error, LogId), [{hello_error_reason, Reason}]), + "Hello handler with callback '~p' and service id '~p' dismissed bad request on method(s) '~p'.", + [CallbackModule, HandlerId, hello_log:get_method(Request)])). + +-define(LOG_WARNING_reason(CallbackModule, HandlerId, Msg, Args, Reason, LogId), + lager:info(?DEFAULT_META([{hello_handler_callback, CallbackModule}, {hello_error_reason, Reason}, + {hello_service_id, HandlerId}], LogId), Msg, Args)). + +-define(LOG_DEBUG(Msg, Args, Meta, LogId), lager:debug(?DEFAULT_META(Meta, LogId), Msg, Args)). +-define(LOG_INFO(Msg, Args, Meta, LogId), lager:info(?DEFAULT_META(Meta, LogId), Msg, Args)). +-define(LOG_NOTICE(Msg, Args, Meta, LogId), lager:notice(?DEFAULT_META(Meta, LogId), Msg, Args)). +-define(LOG_WARNING(Msg, Args, Meta, LogId), lager:warning(?DEFAULT_META(Meta, LogId), Msg, Args)). +-define(LOG_ERROR(Msg, Args, Meta, LogId), lager:error(?DEFAULT_META(Meta, LogId), Msg, Args)). +-define(LOG_CRITICAL(Msg, Args, Meta, LogId), lager:critical(?DEFAULT_META(Meta, LogId), Msg, Args)). +-define(LOG_ALERT(Msg, Args, Meta, LogId), lager:alert(?DEFAULT_META(Meta, LogId), Msg, Args)). +-define(LOG_EMERGENCY(Msg, Args, Meta, LogId), lager:emergency(?DEFAULT_META(Meta, LogId), Msg, Args)). -endif. diff --git a/include/hello_log_ids.hrl b/include/hello_log_ids.hrl new file mode 100644 index 0000000..608290a --- /dev/null +++ b/include/hello_log_ids.hrl @@ -0,0 +1,90 @@ +-define(LOGID99, {ffffffffffffffffffffffffffffffff, 9999}). %placeholder + +%% since erlang atoms are quoted if they begin with a number +%% we just take UUIDs which begin with a letter. Hence we have +%% no quoting in journald (like other message IDs). + +%MESSAGE IDs and STATUS CODEs for hello_client +-define(LOGID00, {ec504cee59b245c0861b78ccd936b856, 4200}). +-define(LOGID01, {d7a051ed5dab4b50afa67ca5fadd6077, 4300}). +-define(LOGID02, {ff6a6c3ae0734a65b2845c39d223b249, 2100}). +-define(LOGID03, {bd8b9bc7d0ef48a98f6286c779781985, 4100}). +-define(LOGID04, {a55b446c103646b2a84543a907c13378, 4100}). +-define(LOGID05, {b31ad32a76a94d78b866b2e168f9f7d3, 2100}). +-define(LOGID06, {c2ba31819c384d76966d6bdb0cf02250, 2100}). +-define(LOGID07, {d406dffdf263429eac4e64b7c52f7276, 2202}). +-define(LOGID08, {e9f0397b5b814c3abd55f3a474815f6c, 2200}). +-define(LOGID09, {f819220efa73409fa896aaafc0c21d30, 2200}). +-define(LOGID10, {a953af5734984f39b1c26a3541a1f48f, 2200}). +-define(LOGID11, {c2763c7aba514282a48a87dee13e7738, 4301}). +-define(LOGID12, {a887733cce7949f5a1d041441ccdfdfc, 2202}). +-define(LOGID13, {bc9ed80e61cb441c952422c649a3ff3e, 2201}). +-define(LOGID14, {bfde238fb72f420996cb52eaeda474df, 2200}). +-define(LOGID15, {cb4c75e200f74a279ca3373e37eb7f81, 4200}). +-define(LOGID16, {b68c94425c1f40aca74ef33e13eccbfc, 4300}). +-define(LOGID17, {d77a63a5b17c4f0499fc9360083aa7a1, 2302}). +-define(LOGID18, {ef4efe6bb336491990b99cc1113adb85, 2201}). +-define(LOGID19, {e61cd5d46b344504aad275c1f4831f90, 2202}). +-define(LOGID20, {cd035f8d88aa45cca84b67a4227c8cd6, 4201}). +-define(LOGID21, {d330d615c9a84f9dadd4a327fa3ac2fe, 2201}). + +%MESSAGE IDs and SATUS CODEs for hello_handler +-define(LOGID22, {c68287edeaac43fe96f49161eb8f44ba, 2400}). +-define(LOGID23, {d3496f96a1154dad96e5ec469dda164b, 2400}). +-define(LOGID24, {e2f93d4effd2479fa7a6291b2c9da1dd, 5210}). +-define(LOGID25, {fc965b4e012648578c379fe0faae3461, 2210}). +-define(LOGID26, {a7237645a763489591c1559b7ec586b8, 2212}). +-define(LOGID27, {aabd551dcc334fe093954d19b4dcc445, 5211}). +-define(LOGID28, {b9ab6b39134542fdbf0fabd7a88e8a19, 2212}). +-define(LOGID29, {c457bf8eb8574927bb1285bc32c18aff, 2210}). +-define(LOGID30, {da812da4d818443a872767687edd47f3, 2212}). +-define(LOGID31, {b3543661a8b2472984874c9c7325fa81, 2212}). +-define(LOGID32, {aeb8bd41d1ed47048e6ea6056cade3ac, 2212}). +-define(LOGID33, {aee0c58903824a139d1b1df028c223d6, 2212}). + +%MESSAGE IDs and SATUS CODEs for hello_router +-define(LOGID37, {aee45db4a0a4465687588331edc8bde4, 5400}). +-define(LOGID38, {cfe782643a4e49a581a94c2ae146e683, 2400}). + +%MESSAGE IDs and SATUS CODEs for hello_http_client +-define(LOGID39, {a95801c548ad4f508f315334ff79f199, 4101}). +-define(LOGID40, {eab6276590fc4d84996662f4c13a271a, 2400}). +-define(LOGID41, {a48b0a9d2aaa477494fade8ace87f20f, 2402}). +-define(LOGID42, {d3cbc27eb6ab43f2b2dfc9114c122054, 4201}). + +%MESSAGE IDs and SATUS CODEs for hello_zmq_client +-define(LOGID43, {d80498ec152342eba94827f005123d27, 2400}). +-define(LOGID44, {e6fa0b7a7ffb45f29a359eca6776b369, 2203}). +-define(LOGID45, {eafe96b96fb447c59ba19d8452ee16f8, 2402}). + +%MESSAGE IDs and SATUS CODEs for hello_htp_listener +-define(LOGID46, {cb26c528ecb2474db3078ca1156ba7ba, 5211}). + +%MESSAGE IDs and SATUS CODEs for hello_zmq_listener +-define(LOGID47, {c0ea6cda30b64f10be3db0ee5fdc22d1, 5213}). +-define(LOGID48, {dea8dfd8818e432bb61a64ca88e35a9e, 5211}). +-define(LOGID49, {e849ee8a79b2435394e81b51894a617c, 2402}). + +%MESSAGE IDs and SATUS CODEs for hello_metrics +-define(LOGID50, {adcfa613af3d40538bddb1e5fd178139, 5500}). + +%MESSAGE IDs and SATUS CODEs for hello_registry +-define(LOGID51, {bb0ea6d2b9c74a78afa724889ceee0b5, 5600}). +-define(LOGID52, {da5cd3be4435462dafff47b1bbc34a62, 5600}). +-define(LOGID53, {a3fcdc9a486247d1af5ea679d0f724e9, 2402}). +-define(LOGID54, {bd8ad7e2a04940e8bc4fd7417d2907aa, 2600}). +-define(LOGID55, {ab5f921ed6e7488293241dc27eaf102e, 5600}). +-define(LOGID56, {b5886b31a45d422bb02422aaf072797b, 5500}). +-define(LOGID57, {af5e3e79776642e4851709b58e7ea790, 2400}). + +%MESSAGE IDs and SATUS CODEs for hello_service +-define(LOGID58, {eda0efbe7f6d490490e00ae4055629d2, 5400}). + +%MESSAGE IDs and SATUS CODEs for hello_supervisor +-define(LOGID59, {a3b473cec1c841d0ada3232fafe8d081, 4000}). +-define(LOGID60, {be1432aa9c074facae66b9d6786de2e5, 4000}). + +%MESSAGE IDs and SATUS CODEs for hello_proto_jsonrpc +-define(LOGID61, {ab65930009164e7fb6419b615b4ae4b5, 4102}). +-define(LOGID62, {bd81f08a8fc94502bcbd07975e952016, 4310}). +-define(LOGID63, {c796ed5e01f0455fb09c42e0f04198c1, 4310}). diff --git a/src/hello_client.erl b/src/hello_client.erl index 0dea42b..59a8d9f 100644 --- a/src/hello_client.erl +++ b/src/hello_client.erl @@ -31,10 +31,13 @@ %% for tests -export([handle_internal/2]). +-export([gen_meta_fields/1]). -include("hello.hrl"). -include("hello_log.hrl"). -include_lib("ex_uri/include/ex_uri.hrl"). + +-define(HELLO_CLIENT_DEFAULT_META(ClientId, Url), [{hello_client, ClientId}, {hello_transport_url, Url}]). -define(DEFAULT_TIMEOUT, application:get_env(hello, client_timeout, 10000)). -type client_name() :: {local, atom()} | {global, atom()} | {via, atom(), term()}. @@ -72,7 +75,7 @@ start_link(URI, {TransportOpts, ProtocolOpts, ClientOpts}) -> % @deprecated start_link(Name, URI, {TransportOpts, ProtocolOpts, ClientOpts}) -> - gen_server:start_link(Name, ?MODULE, {URI, TransportOpts, ProtocolOpts, ClientOpts}, []). + gen_server:start_link(Name, ?MODULE, {URI, TransportOpts, ProtocolOpts, ClientOpts ++ [{name, Name}]}, []). -spec start_link(URI :: string(), trans_opts(), protocol_opts(), client_opts()) -> start_result(). start_link(URI, TransportOpts, ProtocolOpts, ClientOpts) -> @@ -80,7 +83,7 @@ start_link(URI, TransportOpts, ProtocolOpts, ClientOpts) -> -spec start_link(client_name(), URI :: string(), trans_opts(), protocol_opts(), client_opts()) -> start_result(). start_link(Name, URI, TransportOpts, ProtocolOpts, ClientOpts) -> - gen_server:start_link(Name, ?MODULE, {URI, TransportOpts, ProtocolOpts, ClientOpts}, []). + gen_server:start_link(Name, ?MODULE, {URI, TransportOpts, ProtocolOpts, ClientOpts ++ [{name, Name}]}, []). %% API to start with hello supervisor -spec start_supervised(URI :: string(), trans_opts(), protocol_opts(), client_opts()) -> @@ -91,7 +94,7 @@ start_supervised(URI, TransportOpts, ProtocolOpts, ClientOpts) -> -spec start_supervised(atom(), URI :: string(), trans_opts(), protocol_opts(), client_opts()) -> {ok, pid()}. start_supervised(Name, URI, TransportOpts, ProtocolOpts, ClientOpts) -> - hello_client_sup:start_named_client(Name, URI, {TransportOpts, ProtocolOpts, ClientOpts}). + hello_client_sup:start_named_client(Name, URI, {TransportOpts, ProtocolOpts, ClientOpts ++ [{name, {Name}}]}). -spec stop_supervised(client_name()) -> ok | {error, Reason :: term()}. stop_supervised(Client) -> @@ -119,6 +122,7 @@ timeout_call(Client, Call, Timeout) -> %% ---------------------------------------------------------------------------------------------------- %% -- gen_server callbacks -record(client_state, { + id :: term(), uri_rec :: #ex_uri{}, transport_opts :: term(), transport_mod :: module(), @@ -149,7 +153,8 @@ init({URI, TransportOpts, ProtocolOpts, ClientOpts}) -> end. %% @hidden -handle_call({call, Call}, From, State = #client_state{protocol_mod = ProtocolMod, protocol_state = ProtocolState}) -> +handle_call({call, Call}, From, State = #client_state{protocol_mod = ProtocolMod, + protocol_state = ProtocolState, id = ClientId}) -> case hello_proto:build_request(Call, ProtocolMod, ProtocolState) of {ok, Request, NewProtocolState} -> State1 = State#client_state{protocol_state = NewProtocolState}, @@ -157,12 +162,15 @@ handle_call({call, Call}, From, State = #client_state{protocol_mod = ProtocolMod {ok, State2} -> {noreply, State2}; {ok, Reply, State2} -> {reply, Reply, State2}; {error, Reason, State2} -> - ?LOG_ERROR("unsuccessful send request: ~p, reason: ~p", [Request, Reason]), + ?LOG_INFO("Request from hello client '~p' on method(s) '~p' failed with reason '~p'.", + [ClientId, hello_log:get_method(Request), Reason], gen_meta_fields(Request, State2), ?LOGID00), {reply, Reason, State2} end; {error, Reason, NewProtocolState} -> - ?LOG_ERROR("unsuccessful build request for call: ~p, reason: ~p", [Call, Reason]), - {reply, Reason, State#client_state{protocol_state = NewProtocolState}} + NewState = State#client_state{protocol_state = NewProtocolState}, + ?LOG_INFO("Creation of request from hello client '~p' failed for a call with reason '~p'.", + [ClientId, Reason], gen_meta_fields(Call, NewState), ?LOGID01), + {reply, Reason, NewState} end; handle_call(terminate, _From, State) -> {stop, normal, ok, State}. @@ -174,17 +182,20 @@ handle_info(?PING, State = #client_state{waiting_for_pong = true, keep_alive_int uri_rec = URIRec, transport_mod = TransportModule, transport_opts = TransportOpts, protocol_opts = ProtocolOpts, transport_state = TransportState, client_opts = ClientOpts, - last_pong = LastPong}) -> - ?LOG_ERROR("There is no PONG answer on PING for ~p msec. Connection will be reestablished.", - [last_pong(LastPong, KeepAliveInterval)]), + last_pong = LastPong, id = ClientId}) -> + ?LOG_INFO("Error in hello client '~p': There is no PONG answer on PING for '~p' msec. Connection will be reestablished.", + [ClientId, last_pong(LastPong, KeepAliveInterval)], gen_meta_fields(State), ?LOGID20), TransportModule:terminate_transport(lost_connection, TransportState), case init_transport(TransportModule, URIRec, TransportOpts, ProtocolOpts, ClientOpts, State) of {ok, NewState} -> {noreply, NewState}; {stop, Reason} -> {stop, Reason, State} end; handle_info(?PING, State = #client_state{transport_mod=TransportModule, transport_state=TransportState, - keep_alive_interval = KeepAliveInterval, keep_alive_ref = TimerRef}) -> + keep_alive_interval = KeepAliveInterval, + keep_alive_ref = TimerRef, id = ClientId}) -> {ok, NewTransportState} = TransportModule:send_request(?PING, ?INTERNAL_SIGNATURE, TransportState), + ?LOG_DEBUG("Hello client '~p' sent PING request. Pinging server again in '~p' milliseconds.", + [ClientId, KeepAliveInterval], gen_meta_fields(State), ?LOGID21), timer:cancel(TimerRef), {ok, NewTimerRef} = timer:send_after(KeepAliveInterval, self(), ?PING), {noreply, State#client_state{transport_state = NewTransportState, keep_alive_ref = NewTimerRef, @@ -220,6 +231,10 @@ init_transport(TransportModule, URIRec, TransportOpts, ProtocolOpts, ClientOpts) end. init_transport(TransportModule, URIRec, TransportOpts, ProtocolOpts, ClientOpts, State0) -> + ClientId = get_client_id(ClientOpts), + Url = ex_uri:encode(URIRec), + ?LOG_INFO("Initializing hello client '~p' on '~p' ...", [ClientId, Url], + ?HELLO_CLIENT_DEFAULT_META(ClientId, Url), ?LOGID02), case TransportModule:init_transport(URIRec, TransportOpts) of {ok, TransportState} -> NotificationSink = proplists:get_value(notification_sink, ProtocolOpts, undefined), @@ -237,62 +252,107 @@ init_transport(TransportModule, URIRec, TransportOpts, ProtocolOpts, ClientOpts, notification_sink = NotificationSink, waiting_for_pong = false}, evaluate_client_options(ClientOpts, State); - {error, Reason} -> {stop, Reason} + {error, Reason} -> + ?LOG_INFO("Hello client '~p' is unable to initialize protocol because of reason '~p'.", + [ClientId, Reason], ?HELLO_CLIENT_DEFAULT_META(ClientId, Url), ?LOGID03), + {stop, Reason} end; - {error, Reason} -> {stop, Reason} + {error, Reason} -> + ?LOG_INFO("Hello client '~p' unable to initialize transport because of reason '~p'.", + [ClientId, Reason], ?HELLO_CLIENT_DEFAULT_META(ClientId, Url), ?LOGID04), + {stop, Reason} end. evaluate_client_options(ClientOpts, State0) -> State = State0#client_state{client_opts = ClientOpts}, KeepAliveInterval = proplists:get_value(keep_alive_interval, ClientOpts, -1), + ClientId = get_client_id(ClientOpts), if KeepAliveInterval =< 0 -> - {ok, State#client_state{keep_alive_interval = -1}}; + State1 = State#client_state{keep_alive_interval = -1, id = ClientId}, + ?LOG_DEBUG("Hello client '~p' initialized successfully.", [ClientId], + gen_meta_fields(State1), ?LOGID05), + {ok, State1}; KeepAliveInterval > 0 -> {ok, TimerRef} = timer:send_after(KeepAliveInterval, self(), ?PING), - {ok, State#client_state{keep_alive_interval = KeepAliveInterval, keep_alive_ref = TimerRef}} + State1 = State#client_state{keep_alive_interval = KeepAliveInterval, keep_alive_ref = TimerRef, id = ClientId}, + ?LOG_DEBUG("Hello client '~p' initialized successfully with keep alive.", + [ClientId], gen_meta_fields(State1), ?LOGID06), + {ok, State1} end. -incoming_message({error, _Reason, NewTransportState}, State) -> %%will be logged later +get_client_id(ClientOpts) -> + ClientName = proplists:get_value(name, ClientOpts, {self()}), + element(tuple_size(ClientName), ClientName). + +incoming_message({error, Reason, NewTransportState}, State = #client_state{id = ClientId}) -> %%will be logged later + ?LOG_DEBUG("Hello client '~p' received error notification from transport handler with reason '~p'.", + [ClientId, Reason], gen_meta_fields(State), ?LOGID07), {noreply, State#client_state{transport_state = NewTransportState}}; -incoming_message({ok, Signature, BinResponse, NewTransportState}, - State = #client_state{async_request_map = AsyncMap, protocol_mod = ProtocolMod, protocol_opts = ProtocolOpts}) -> +incoming_message({ok, Signature, BinResponse, NewTransportState}, + State = #client_state{async_request_map = AsyncMap, + protocol_mod = ProtocolMod, + protocol_opts = ProtocolOpts, + id = ClientId}) -> case hello_proto:decode(ProtocolMod, ProtocolOpts, Signature, BinResponse, response) of {ok, #response{id = null, response = Response}} -> + ?LOG_DEBUG("Hello client '~p' received notification.", [ClientId], + gen_meta_fields(Response, State), ?LOGID08), notification(Response, State), {noreply, State#client_state{transport_state = NewTransportState}}; {ok, Response = #response{}} -> - NewAsyncMap = request_reply(Response, AsyncMap), - {noreply, State#client_state{transport_state = NewTransportState, async_request_map = NewAsyncMap}}; + ?LOG_DEBUG("Hello client '~p' received single response.", [ClientId], + gen_meta_fields(Response, State), ?LOGID09), + request_reply(Response, AsyncMap, State); {ok, Responses = [{ok, #response{}} | _]} -> - NotificationRespopses = [R || {_, #response{id = null} = R} <- Responses], - NotificationRespopses /= [] andalso notification([R || #response{response = R} <- NotificationRespopses], State), - Responses1 = [R || {_, R} <- Responses] -- NotificationRespopses, - NewAsyncMap = request_reply(Responses1, AsyncMap), - {noreply, State#client_state{transport_state = NewTransportState, async_request_map = NewAsyncMap}}; - {error, _Reason} -> + Responses1 = [R || {_, R} <- Responses], + ?LOG_DEBUG("Hello client '~p' received batch response.", [ClientId], + gen_meta_fields(Responses1, State), ?LOGID10), + NotificationResponses = [R || {_, #response{id = null} = R} <- Responses], + NotificationResponses /= [] andalso notification([R || #response{response = R} <- NotificationResponses], State), + Responses2 = Responses1 -- NotificationResponses, + request_reply(Responses2, AsyncMap, State#client_state{transport_state = NewTransportState}); + {error, Reason} -> + ?LOG_INFO("Hello client '~p' failed to decode response with reason '~p'.", [ClientId, Reason], + gen_meta_fields(BinResponse, State), ?LOGID11), {noreply, State#client_state{transport_state = NewTransportState}}; ignore -> + ?LOG_DEBUG("Hello client '~p' ignored decoding binary response.", [ClientId], + gen_meta_fields(BinResponse, State), ?LOGID12), {noreply, State#client_state{transport_state = NewTransportState}}; {internal, Message} -> + ?LOG_DEBUG("Hello client '~p' received internal message.", [ClientId], + gen_meta_fields(Message, State), ?LOGID13), {ok, State1} = ?MODULE:handle_internal(Message, State), {noreply, State1} end. -outgoing_message(Request, From, State = #client_state{protocol_mod = ProtocolMod, protocol_opts = ProtocolOpts, - transport_mod = TransportModule, transport_state = TransportState, - async_request_map = AsyncMap}) -> +outgoing_message(Request, From, State = #client_state{protocol_mod = ProtocolMod, + protocol_opts = ProtocolOpts, + transport_mod = TransportModule, + transport_state = TransportState, + async_request_map = AsyncMap, id = ClientId}) -> case hello_proto:encode(ProtocolMod, ProtocolOpts, Request) of {ok, BinRequest} -> Signature = hello_proto:signature(ProtocolMod, ProtocolOpts), case TransportModule:send_request(BinRequest, Signature, TransportState) of {ok, NewTransportState} -> + ?LOG_DEBUG("Hello client '~p' sent request on method(s) '~p'.", [ClientId, hello_log:get_method(Request)], + gen_meta_fields(Request, State), ?LOGID14), maybe_noreply(NewTransportState, Request, From, AsyncMap, State); {error, Reason, NewTransportState} -> + ?LOG_INFO("Hello client '~p' attempted to send binary request on method(s) '~p' but failed with reason '~p'.", + [ClientId, hello_log:get_method(Request), Reason], gen_meta_fields(BinRequest, State), ?LOGID15), {error, Reason, State#client_state{transport_state = NewTransportState}} end; - {error, Reason, State} -> {error, Reason, State}; - ignore -> {ok, State} + {error, Reason, State} -> + ?LOG_INFO("Hello client '~p' attempted to encode request on method '~p' but failed with reason '~p'.", + [ClientId, hello_log:get_method(Request), Reason], gen_meta_fields(Request, State), ?LOGID16), + {error, Reason, State}; + ignore -> + ?LOG_DEBUG("Hello client '~p' attempted to encode request on method '~p' but ignored sending request.", + [ClientId, hello_log:get_method(Request), Request], gen_meta_fields(Request, State), ?LOGID17), + {ok, State} end. update_map(Requests, From, AsyncMap0) when is_list(Requests) -> @@ -302,7 +362,9 @@ update_map(Requests, From, AsyncMap0) when is_list(Requests) -> update_map(#request{id = undefined}, _From, AsyncMap) -> AsyncMap; update_map(#request{id = RequestId} = Request, From, AsyncMap) -> gb_trees:enter(RequestId, {From, Request}, AsyncMap). -handle_internal(?PONG, State = #client_state{keep_alive_interval = KeepAliveInterval, keep_alive_ref = TimerRef}) -> +handle_internal(?PONG, State = #client_state{keep_alive_interval = KeepAliveInterval, keep_alive_ref = TimerRef, id = ClientId}) -> + ?LOG_DEBUG("Hello client '~p' received PONG response. Pinging server again in '~p' milliseconds.", + [ClientId, KeepAliveInterval], gen_meta_fields(?PONG, State), ?LOGID18), timer:cancel(TimerRef), {ok, NewTimerRef} = timer:send_after(KeepAliveInterval, self(), ?PING), {ok, State#client_state{keep_alive_ref = NewTimerRef, waiting_for_pong = false, last_pong = os:timestamp()}}; @@ -334,15 +396,25 @@ notification(Response, _State = #client_state{notification_sink = NotificationSi ignore end. -request_reply(#response{} = Response, AsyncMap) -> - request_reply([Response], AsyncMap, []); -request_reply(Responses, AsyncMap) -> - request_reply(Responses, AsyncMap, []). +request_reply(Response, AsyncMap, State) -> + case request_reply1(Response, AsyncMap) of + {ok, NewAsyncMap} -> + {noreply, State#client_state{async_request_map = NewAsyncMap}}; + {not_found, RequestId, NewAsyncMap} -> + ?LOG_INFO("Hello client '~p' got response for non-existing request id '~p'.", + [RequestId], gen_meta_fields(Response, State), ?LOGID19), + {noreply, State#client_state{async_request_map = NewAsyncMap}} + end. + +request_reply1(#response{} = Response, AsyncMap) -> + request_reply1([Response], AsyncMap, []); +request_reply1(Responses, AsyncMap) -> + request_reply1(Responses, AsyncMap, []). -request_reply([], AsyncMap, [{CallRef, Response}]) -> +request_reply1([], AsyncMap, [{CallRef, Response}]) -> gen_server:reply(CallRef, {ok, Response}), - AsyncMap; -request_reply([], AsyncMap, Responses) -> + {ok, AsyncMap}; +request_reply1([], AsyncMap, Responses) -> Refs = proplists:get_keys(Responses), lists:map(fun(CallRef) -> NewAcc = lists:filtermap(fun({Ref, Response}) when Ref =:= CallRef -> @@ -350,16 +422,35 @@ request_reply([], AsyncMap, Responses) -> (_) -> false end, lists:reverse(Responses)), gen_server:reply(CallRef, {ok, NewAcc}) end, Refs), - AsyncMap; -request_reply([#response{id = RequestId, response = Response} | Tail], AsyncMap, Responses) -> + {ok, AsyncMap}; +request_reply1([#response{id = RequestId, response = Response} | Tail], AsyncMap, Responses) -> case gb_trees:lookup(RequestId, AsyncMap) of {value, {CallRef, _Request}} -> NewAsyncMap = gb_trees:delete(RequestId, AsyncMap), - request_reply(Tail, NewAsyncMap, [{CallRef, Response} | Responses]); + request_reply1(Tail, NewAsyncMap, [{CallRef, Response} | Responses]); none -> - ?LOG_WARNING("get not existing request_id ~p", [RequestId]), - AsyncMap + {not_found, RequestId, AsyncMap} end. +gen_meta_fields(Requests = [ #request{} | _ ], State) -> + lists:append(gen_meta_fields(State), [{hello_request, hello_log:format(Requests)}, + {hello_request_method, hello_log:get_method(Requests)}, + {hello_request_id, hello_log:get_id(Requests)}]); +gen_meta_fields(Request = #request{}, State) -> + lists:append(gen_meta_fields(State), [{hello_request, hello_log:format(Request)}, + {hello_request_method, hello_log:get_method(Request)}, + {hello_request_id, hello_log:get_id(Request)}]); +gen_meta_fields(Responses = [ #response{} | _ ], State) -> + lists:append(gen_meta_fields(State), [{hello_response, hello_log:format(Responses)}, + {hello_request_id, hello_log:get_id(Responses)}]); +gen_meta_fields(Response = #response{}, State) -> + lists:append(gen_meta_fields(State), [{hello_response, hello_log:format(Response)}, + {hello_request_id, hello_log:get_id(Response)}]); +gen_meta_fields(Msg, State) -> + lists:append(gen_meta_fields(State), [{hello_message, Msg}]). + +gen_meta_fields(#client_state{transport_mod = TransportModule, transport_state = TransportState, id = ClientId}) -> + lists:append([{hello_client_id, ClientId}], TransportModule:gen_meta_fields(TransportState)). + last_pong(undefined, Interval) -> Interval; last_pong(Start, _) -> timer:now_diff(os:timestamp(), Start) / 1000. diff --git a/src/hello_handler.erl b/src/hello_handler.erl index aa2d59a..94a5587 100644 --- a/src/hello_handler.erl +++ b/src/hello_handler.erl @@ -48,6 +48,7 @@ %% ---------------------------------------------------------------------------------------------------- %% -- internal records -record(state, { + id :: term(), mod :: module(), state :: term(), context :: #context{}, @@ -81,11 +82,12 @@ get_handler(Name, Identifier, HandlerMod, HandlerArgs) -> case hello_registry:lookup({handler, Name, Identifier}) of {error, not_found} -> - ?LOG_DEBUG("Hadler for service ~p and identifier ~p not found, " - "it will have been started", [Name, Identifier]), + ?LOG_DEBUG("Handler for service ~p and identifier ~p not found. Starting handler.", + [Name, Identifier], [], ?LOGID22), start_handler(Identifier, HandlerMod, HandlerArgs); {ok, _, Handler} -> - ?LOG_DEBUG("Found hadler ~p for service ~p and identifier ~p", [Handler, Name, Identifier]), + ?LOG_DEBUG("Found handler ~p for service ~p and identifier ~p.", + [Handler, Name, Identifier], [], ?LOGID23), Handler end. @@ -127,35 +129,37 @@ reply(ReqContext = #context{handler_pid = HandlerPid}, Result) -> %% @hidden init({Identifier, HandlerMod, HandlerArgs}) -> case HandlerMod:init(Identifier, HandlerArgs) of - Result when is_tuple(Result) and (element(1, Result) == ok) -> - setelement(2, Result, #state{mod = HandlerMod, state = element(2, Result), async_reply_map = gb_trees:empty()}); + {ok, Handlerstate} -> + {ok, #state{mod = HandlerMod, state = Handlerstate, + async_reply_map = gb_trees:empty(), id = Identifier}}; Other -> Other end. %% @hidden -handle_cast({request, Request = #request{context = Context}}, State = #state{mod = Mod, state = _HandlerState}) -> +handle_cast({request, Request = #request{context = Context}}, + State = #state{mod = Mod, state = _HandlerState, id = Id}) -> % TODO: fix logging, request should be loged with answer. If no answer, should be logged, no answer try do_request(Request, State) catch Error:Reason -> send(Context, {error, {server_error, "handler error", undefined}}), - ?LOG_REQUEST_bad_request(Mod, self(), Request, {Error, Reason, erlang:get_stacktrace()}), + ?LOG_REQUEST_bad_request(Mod, Id, Request, {Error, Reason, erlang:get_stacktrace()}, ?LOGID24), {stop, normal, State} end; handle_cast({set_idle_timeout, Timeout}, State = #state{timer = Timer}) -> NewTimer = Timer#timer{idle_timeout = Timeout}, {noreply, reset_idle_timeout(State#state{timer = NewTimer})}; -handle_cast({async_reply, ReqContext, Result}, State = #state{async_reply_map = AsyncMap, mod = Mod}) -> +handle_cast({async_reply, ReqContext, Result}, State = #state{id = Id, async_reply_map = AsyncMap, mod = Mod}) -> #context{req_ref = ReqRef} = ReqContext, case gb_trees:lookup(ReqRef, AsyncMap) of {value, Request} -> - ?LOG_REQUEST_async_reply(Mod, self(), Request, {ok, Result}), + ?LOG_REQUEST_async_reply(Mod, Id, Request, Result, ?LOGID25), send(ReqContext, {ok, Result}), {noreply, State#state{async_reply_map = gb_trees:delete(ReqRef, AsyncMap)}}; none -> - error_logger:warning_report([{hello_handler, State#state.mod}, - {unknown_async_reply, ReqRef, Result}]), + ?LOG_WARNING_reason(Mod, Id, "Hello handler with callback module '~p' and service id '~p' got unknown async reply.", + [Mod, Id], {unknown_async_reply, {ReqRef, Result}}, ?LOGID26), {noreply, State} end. @@ -164,11 +168,15 @@ handle_call(_Call, _From, State) -> {reply, {error, unknown_call}, State}. %% @hidden -handle_info({?IDLE_TIMEOUT_MSG, TimerRef}, State = #state{timer = Timer}) when Timer#timer.idle_timeout_ref == TimerRef -> +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, "Hello handler with callback module '~p' and service id '~p' is going to stop due to idle timeout.", + [Mod, Id], {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}) -> - error_logger:warning_report([{hello_handler, Mod}, {unknown_timeout_msg, OtherRef}]), +handle_info({?IDLE_TIMEOUT_MSG, OtherRef}, State = #state{mod = Mod, id = Id}) -> + ?LOG_WARNING_reason(Mod, Id, "Hello handler with callback module '~p' and service id '~p' received unknown idle timeout message.", + [Mod, Id], {error, {unknown_timeout_message, OtherRef}}, ?LOGID28), {noreply, State}; handle_info({?INCOMING_MSG, Request = #request{context = Context}}, State0) -> State = reset_idle_timeout(State0), @@ -200,7 +208,8 @@ code_change(_FromVsn, _ToVsn, State) -> %% -------------------------------------------------------------------------------- %% -- internal functions %% @hidden -do_request(Request = #request{context = Context}, State = #state{async_reply_map = AsyncMap, mod = Mod, state = HandlerState}) -> +do_request(Request = #request{context = Context}, + State = #state{async_reply_map = AsyncMap, mod = Mod, state = HandlerState, id = Id}) -> ReqRef = make_ref(), HandlerPid = self(), Context1 = Context#context{req_ref = ReqRef, handler_pid = HandlerPid}, @@ -211,32 +220,32 @@ do_request(Request = #request{context = Context}, State = #state{async_reply_map hello_metrics:handle_request_time(TimeMS), case Value of {reply, Response, NewHandlerState} -> - ?LOG_REQUEST_request(Mod, HandlerPid, Request, Response, TimeMS), + ?LOG_REQUEST_request(Mod, Id, Request, Response, TimeMS, ?LOGID29), send(Context1, Response), {noreply, State#state{state = NewHandlerState}}; {noreply, NewModState} -> - ?LOG_REQUEST_request_no_reply(Mod, HandlerPid, Request, TimeMS), + ?LOG_REQUEST_request_no_reply(Mod, Id, Request, TimeMS, ?LOGID30), {noreply, State#state{state = NewModState, async_reply_map = gb_trees:enter(ReqRef, Request, AsyncMap)}}; {stop, Reason, Response, NewModState} -> - ?LOG_REQUEST_request_stop(Mod, HandlerPid, Request, Response, Reason, TimeMS), + ?LOG_REQUEST_request_stop(Mod, Id, Request, Response, Reason, TimeMS, ?LOGID31), send(Context1, Response), {stop, Reason, State#state{state = NewModState}}; {stop, Reason, NewModState} -> - ?LOG_REQUEST_request_stop_no_reply(Mod, HandlerPid, Request, Reason, TimeMS), + ?LOG_REQUEST_request_stop_no_reply(Mod, Id, Request, Reason, TimeMS, ?LOGID32), {stop, Reason, State#state{mod = NewModState}}; {stop, NewModState} -> - ?LOG_REQUEST_request_stop_no_reply(Mod, HandlerPid, Request, TimeMS), + ?LOG_REQUEST_request_stop_no_reply(Mod, Id, Request, TimeMS, ?LOGID33), {stop, State#state{mod=NewModState}}; {ignore, NewModState} -> - ?LOG_REQUEST_request(Mod, HandlerPid, Request, ignore, TimeMS), + ?LOG_REQUEST_request(Mod, Id, Request, ignore, TimeMS, ?LOGID29), {noreply, State#state{state = NewModState}} end; {error, {_Code, _Message, _Data} = Reason} -> - ?LOG_REQUEST_bad_request(Mod, HandlerPid, Request, Reason), + ?LOG_REQUEST_bad_request(Mod, Id, Request, Reason, ?LOGID24), send(Context1, {error, Reason}), {stop, normal, State}; _FalseAnswer -> - ?LOG_REQUEST_bad_request(Mod, HandlerPid, Request, _FalseAnswer), + ?LOG_REQUEST_bad_request(Mod, Id, Request, _FalseAnswer, ?LOGID24), send(Context1, {error, {server_error, "validation returned wrong error format", null}}), {stop, normal, State} end. diff --git a/src/hello_log.erl b/src/hello_log.erl index 8a2b1a5..20bd7aa 100644 --- a/src/hello_log.erl +++ b/src/hello_log.erl @@ -21,14 +21,48 @@ % @private -module(hello_log). --export([fmt_response/1, fmt_request/1]). +-export([format/1, get_id/1, get_method/1]). -include("hello.hrl"). %% -------------------------------------------------------------------------------- -%% -- Formaters -fmt_request(#request{method = Method, args = Params}) -> - <<"method: ", (hello_json:encode(Method))/binary, ", params: ", (hello_json:encode(Params))/binary>>. +%% -- Formaters for messages -fmt_response(ignore) -> ["ignored"]; -fmt_response(Result) -> io_lib:format("~4096p", [Result]). +%% -- request formatting +format([ Request = #request{} ]) -> + "[ " ++ format(Request) ++ " ]"; +format([ Request = #request{} | Requests]) -> + "[ " ++ format(Request) ++ " ], " ++ format(Requests); +format(#request{id = ID, method = Method, args = Args}) -> + lists:append(["ID: ", stringify(ID), "; METHOD: ", stringify(Method), + "; ARGS: ", stringify(Args)]); + +%% -- response formatting; first for record responses, then for arbitrary data blobs +format([ Response = #response{} ]) -> + "[ " ++ format(Response) ++ " ]"; +format([ Response = #response{} | Responses]) -> + "[ " ++ format(Response) ++ " ], " ++ format(Responses); +format(#response{id = ID, response = CallbackResponse}) -> + lists:append(["ID: ", stringify(ID), "; RESPONSE: ", stringify(CallbackResponse)]); +format(ignore) -> ["ignored"]; +format({ok, CallbackResponse}) -> stringify(CallbackResponse); +format(Msg) -> stringify(Msg). + +%% -- get internal hello request id +get_id([ #request{id = Id} ]) -> stringify(Id); +get_id([ #request{id = Id} | Requests]) -> stringify(Id) ++ ", " ++ get_id(Requests); +get_id(#request{id = Id}) -> stringify(Id); +get_id([ #response{id = Id} ]) -> stringify(Id); +get_id([ #response{id = Id} | Responses]) -> stringify(Id) ++ ", " ++ get_id(Responses); +get_id(#response{id = Id}) -> stringify(Id). + +%% -- get request method +get_method([ #request{method = Method} ]) -> + stringify(Method); +get_method([ #request{method = Method} | Requests]) -> + stringify(Method) ++ ", " ++ get_method(Requests); +get_method(#request{method = Method}) -> + stringify(Method). + +stringify(Term) -> + lists:flatten(io_lib:format("~p", [Term])). diff --git a/src/hello_metrics.erl b/src/hello_metrics.erl index f9abfbf..aba62f0 100644 --- a/src/hello_metrics.erl +++ b/src/hello_metrics.erl @@ -104,7 +104,7 @@ subscriptions(listener) -> [{[hello, listeners], value, ?DEFAULT_INTERVAL}]; subscriptions(client) -> [{[hello, clients], value, ?DEFAULT_INTERVAL}]; subscriptions(Type) -> - ?LOG_WARNING("unknown subscription type ~p", [Type]), []. + ?LOG_DEBUG("Hello metrics received unknown subscription type '~p'.", [Type], [], ?LOGID50), []. % @private diff --git a/src/hello_registry.erl b/src/hello_registry.erl index d4d2845..9996e18 100644 --- a/src/hello_registry.erl +++ b/src/hello_registry.erl @@ -116,15 +116,17 @@ handle_call(_Call, _From, State) -> {reply, {error, unknown_call}, State}. handle_info({'EXIT', From, Reason}, Table) -> - ?LOG_WARNING("~p: exit with reason ~p", [From, Reason]), + ?LOG_INFO("Hello registry received 'EXIT' signal from monitored process '~p' with reason '~p'.", [From, Reason], + [{hello_error_reason, {process_exit, Reason}}], ?LOGID51), {noreply, Table}; handle_info({'DOWN', _MRef, process, Pid, Reason}, Table) -> Objects = ets:match(Table, {'$1', Pid, '_', '_'}), - ?LOG_WARNING("~p: down ~p with reason ~p", [Pid, Objects, Reason]), + ?LOG_INFO("Hello registry received 'DOWN' signal from monitored process '~p' with reason '~p'. Going to clean up associated processes '~p'.", + [Pid, Reason, Objects], [{hello_error_reason, {process_down, Objects, Reason}}], ?LOGID52), spawn(fun() -> [down(Object)|| Object <- Objects] end), {noreply, Table}; handle_info({dnssd, _Ref, Msg}, State) -> - ?LOG_DEBUG("dnssd Msg: ~p", [Msg]), + ?LOG_DEBUG("Hello registry received message '~p' from DNS service discovery.", [Msg], [], ?LOGID53), {noreply, State}; handle_info(_InfoMsg, State) -> {noreply, State}. @@ -147,10 +149,11 @@ register(Key, Pid, Data, Table) -> true -> update_metric(Key, 1), is_pid(Pid) andalso monitor_(Table, Pid), - ?LOG_DEBUG("Register ~p for pid ~p with data: ~p", [Key, Pid, Data]), + ?LOG_DEBUG("Hello registry is going to register process '~p' with key '~p' and data '~p'.", [Pid, Key, Data], [], ?LOGID54), bind(Key, Pid, Data, Table); false -> - ?LOG_ERROR("Tried to register ~p for pid ~p, but pid not alive", [Key, Pid]), + ?LOG_INFO("Hello registry attempted to register process '~p' with key '~p', but process is not alive.", [Pid, Key], + [{hello_error_reason, {error, pid_not_alive}}], ?LOGID55), {error, pid_not_alive} end. @@ -173,11 +176,10 @@ down([Key]) -> hello_registry:unregister(Key). update_metric({binding, _}, Value) -> hello_metrics:binding(Value); update_metric({service, _}, Value) -> hello_metrics:service(Value); update_metric({listener, _}, Value) -> hello_metrics:listener(Value); -update_metric(Key, _) -> - ?LOG_INFO("unknown key ~p for register_metric", [Key]). +update_metric(Key, _) -> ?LOG_DEBUG("Hello registry received unknown key '~p' for register metric.", [Key], [], ?LOGID56). do_dnss_register(App, Name, Port) -> - ?LOG_INFO("dnss register ~p/~p on port ~p", [App, Name, Port]), + ?LOG_DEBUG("DNS discovery service registered app '~p' with name '~p' on port '~p'.", [App, Name, Port], [], ?LOGID57), case dnssd:register(Name, <<"_", App/binary, "._tcp">>, Port) of {ok, Ref} -> Ref; _ -> ok diff --git a/src/hello_router.erl b/src/hello_router.erl index 4b47f1d..2d20024 100644 --- a/src/hello_router.erl +++ b/src/hello_router.erl @@ -7,10 +7,14 @@ route(_Context = #context{session_id = Id}, Request = #request{method = Method}, Namespace = get_namespace(Method), case hello_binding:lookup(ExURI, Namespace) of {error, not_found} -> - ?LOG_WARNING("Route couldn't find a service for a key ~s not found", [Namespace]), + ?LOG_INFO("Hello router couldn't find service for a key ~s. Request is dismissed.", [Namespace], + [ {hello_request, hello_log:format(Request)}, + {hello_error_response, {error, not_found, Namespace}}], + ?LOGID37), {error, method_not_found}; {ok, _, Name} -> - ?LOG_DEBUG("Request ~p in namespace ~p will have been routed to ~p", [Request, Namespace, Name]), + ?LOG_DEBUG("Hello router resolved namespace '~p' to hello handler '~p'.", [Namespace, Name], + [{hello_request, hello_log:format(Request)}], ?LOGID38), {ok, Name, Id} end. diff --git a/src/hello_service.erl b/src/hello_service.erl index 4197759..39bcace 100644 --- a/src/hello_service.erl +++ b/src/hello_service.erl @@ -27,7 +27,8 @@ call(Name, Identifier, Request) -> Handler = hello_handler:get_handler(Name, Identifier, HandlerMod, HandlerArgs), hello_handler:process(Handler, Request); {error, not_found} -> - ?LOG_WARNING("Service ~s not found", [Name]), + ?LOG_INFO("Hello service ~s not found.", [Name], + [{hello_error_response, {error, method_not_found}}], ?LOGID58), {error, method_not_found} end. diff --git a/src/hello_supervisor.erl b/src/hello_supervisor.erl index 27d8d2e..71cfa0b 100644 --- a/src/hello_supervisor.erl +++ b/src/hello_supervisor.erl @@ -24,6 +24,9 @@ -export([start_link/0]). -export([init/1]). +-include("hello.hrl"). +-include("hello_log.hrl"). + -define(SERVER, hello_supervisor). start_link() -> @@ -43,12 +46,15 @@ get_roles() -> {ok, Role} when is_list(Role) -> Exess = lists:subtract(Role, [client, server]), if - length(Exess) > 0 -> error_logger:warning_report([{roles, ignored}, Exess]); + length(Exess) > 0 -> + ?LOG_INFO("Hello supervisor got invalid list '~p' of roles.", [Role], + [{hello_error_reason, invalid_roles}], ?LOGID59); true -> ok end, lists:subtract(Role, Exess); {ok, Role} -> - error_logger:warning_report([{application, hello}, {roles, invalid}, Role]), + ?LOG_INFO("Hello supervisor got invalid role '~p'.", [Role], + [{hello_error_reason, invalid_roles}], ?LOGID60), [client, server]; undefined -> [client, server] diff --git a/src/protocols/hello_proto_jsonrpc.erl b/src/protocols/hello_proto_jsonrpc.erl index e4ca317..47218c4 100644 --- a/src/protocols/hello_proto_jsonrpc.erl +++ b/src/protocols/hello_proto_jsonrpc.erl @@ -43,7 +43,7 @@ init_client(Proplist) -> true -> {ok, #jsonrpc_info{ reqid = 0, version = JsonRPCVersion} }; _ -> - ?LOG_ERROR("Unsupported JSONRPC version ~p", [JsonRPCVersion]), + ?LOG_INFO("Hello client invoked with invalid JSONRPC version '~p'.", [JsonRPCVersion], [], ?LOGID61), {error, invalid_json_version} end. @@ -75,7 +75,8 @@ decode(Binary, _Opts, Type) -> end catch Error:Reason -> - ?LOG_ERROR("Error ~p Reason ~p ~p~n", [Error, Reason, erlang:get_stacktrace()]), + ?LOG_INFO("Hello proto unable to decode binary request with error '~p'.", [Error], + [{hello_error_reason, {Error, Reason, erlang:get_stacktrace()}}], ?LOGID62), {error, #error{code = parse_error}} end. @@ -125,7 +126,8 @@ decode_single(Object, Type) -> decode_single(Type, Object, Info) catch throw:{_Invalid, #jsonrpc_info{reqid = null}, _Reason} -> %% just a notification, no need to tell anyone - ?LOG_ERROR("get invalid notification: ~p", [Object]), + ?LOG_INFO("Hello proto attempted to decode invalid notification object.", [], + [{hello_error_reason, {invalid_notification, Object}}], ?LOGID63), ignore; throw:{invalid, Info1, Reason} -> %% an invalid response, this should never happen Error = build_error(#error{code = invalid(Type), message = Reason}), @@ -140,7 +142,7 @@ decode_single(request, #{<<"method">> := Method} = Object, #jsonrpc_info{reqid = Obj = #{} when JsonRPC > ?JSONRPC_1 -> Obj; _ -> throw({invalid, Info, <<"\"params\" must be array or object">>}) end, - Request = #request{method = Method, type=type(ReqId), args = Params, proto_data = Info}, + Request = #request{method = Method, type=type(ReqId), args = Params, proto_data = Info, id = ReqId}, {ok, Request}; decode_single(request, #{<<"method">> := _Method} = _Object, Info) -> throw({invalid, Info, <<"\"method\" must be a string">>}); diff --git a/src/transports/hello_http_client.erl b/src/transports/hello_http_client.erl index b8b5b12..ac9ad45 100644 --- a/src/transports/hello_http_client.erl +++ b/src/transports/hello_http_client.erl @@ -24,6 +24,7 @@ -behaviour(hello_client). -export([init_transport/2, send_request/3, terminate_transport/2, handle_info/2]). -export([http_send/4]). +-export([gen_meta_fields/1]). -include_lib("ex_uri/include/ex_uri.hrl"). -include("hello.hrl"). @@ -46,7 +47,8 @@ init_transport(URL, Options) -> http_connect_url(URL), {ok, #http_state{url = ex_uri:encode(URL), scheme = URL#ex_uri.scheme, path = URL#ex_uri.path, options = ValOpts}}; {error, Reason} -> - ?LOG_ERROR("Invalid options for init http client, reason: ~p", [Reason]), + ?LOG_INFO("Hello http client invoked with invalid options. Terminated with reason '~p'.", [Reason], + [{hello_error_reason, {error, Reason, Options}}], ?LOGID39), {error, Reason} end. @@ -60,10 +62,12 @@ terminate_transport(_Reason, _State) -> ok. handle_info({dnssd, _Ref, {resolve,{Host, Port, _Txt}}}, State = #http_state{scheme = Scheme, path = Path}) -> - ?LOG_INFO("dnssd Service: ~p:~w", [Host, Port]), + ?LOG_INFO("Hello http client: DNS discovery service resolved path '~p' to host '~p:~w'.", [Path, Host, Port], + gen_meta_fields(State), ?LOGID40), {noreply, State#http_state{url = build_url(Scheme, Host, Path, Port)}}; handle_info({dnssd, _Ref, Msg}, State) -> - ?LOG_INFO("dnssd Msg: ~p", [Msg]), + ?LOG_INFO("Hello https client received message '~p' from DNS discovery service.", [Msg], + gen_meta_fields(State), ?LOGID41), {noreply, State}. build_url(Scheme, Host, Path, Port) -> @@ -107,8 +111,8 @@ http_send(Client, Request, Signarute, State = #http_state{url = URL, options = O Client ! {?INCOMING_MSG, {error, HttpCode, State}}, exit(normal); {error, Reason} -> - ?LOG_ERROR("error during ibrowse:send_req to, url: ~p, headers: ~p, request: ~p, reason: ~p", - [URL, Headers, Request, Reason]), + ?LOG_INFO("Hello http client received an error after executing a request to '~p' with reason '~p'.", [URL, Reason], + lists:append(gen_meta_fields(State), [{hello_error_reason, {{request, Request}, {error, Reason}}}]), ?LOGID42), Client ! {?INCOMING_MSG, {error, Reason, State}}, exit(normal) end. @@ -148,3 +152,6 @@ http_connect_url(#ex_uri{authority = #ex_uri_authority{host = Host}, path = [$/| ok; http_connect_url(URI) -> URI. + +gen_meta_fields(#http_state{url = URL, path = Path}) -> + [{hello_transport, http}, {hello_transport_url, URL}, {hello_transport_path, Path}]. diff --git a/src/transports/hello_http_listener.erl b/src/transports/hello_http_listener.erl index 7857dcb..940828a 100644 --- a/src/transports/hello_http_listener.erl +++ b/src/transports/hello_http_listener.erl @@ -32,14 +32,15 @@ -include_lib("ex_uri/include/ex_uri.hrl"). -record(http_listener_state, { - url :: #ex_uri{} + url :: #ex_uri{}, + encoded_url :: string() }). %% -------------------------------------------------------------------------------- %% -- hello_binding callbacks listener_specification(ExUriUrl, ListenerOpts) -> % cowboy dispatch - State = #http_listener_state{ url = ExUriUrl }, + State = #http_listener_state{ url = ExUriUrl, encoded_url = ex_uri:encode(ExUriUrl) }, Dispatch = cowboy_router:compile([{'_', [{'_', ?MODULE, [State]}]}]), %% Copied from cowboy.erl because it doesn't provide an API that %% allows supervising the listener from the calling application yet. @@ -103,7 +104,9 @@ http_chunked_loop(Req, State) -> case cowboy_req:chunk(BinResp, Req) of ok -> http_chunked_loop(Req, State); R -> - ?LOG_ERROR("cowboy_req:chunk result ~p during send ~p to ~p", [R, BinResp, Req]), + ?LOG_INFO("Hello http listener received an error while streaming the response body.", [], + lists:append([{hello_error_reason, {{request, Req}, {response, BinResp}, {error, R}}}], + gen_meta_fields(State)), ?LOGID46), {ok, Req, State} end end. @@ -177,3 +180,6 @@ extract_ip_and_host(#ex_uri{authority = #ex_uri_authority{host = Host}}) -> {Address, Host} end end. + +gen_meta_fields(#http_listener_state{encoded_url = EncUrl}) -> + [{hello_transport, http}, {hello_transport_url, EncUrl}]. \ No newline at end of file diff --git a/src/transports/hello_zmq_client.erl b/src/transports/hello_zmq_client.erl index 99d9977..adec48c 100644 --- a/src/transports/hello_zmq_client.erl +++ b/src/transports/hello_zmq_client.erl @@ -23,6 +23,7 @@ -behaviour(hello_client). -export([init_transport/2, send_request/3, terminate_transport/2, handle_info/2]). +-export([gen_meta_fields/1]). -include_lib("ex_uri/include/ex_uri.hrl"). -include("hello.hrl"). @@ -54,13 +55,16 @@ terminate_transport(_Reason, #zmq_state{socket = Socket}) -> handle_info({'EXIT', _, normal}, State) -> {noreply, State}; handle_info({dnssd, _Ref, {resolve,{Host, Port, _Txt}}}, State = #zmq_state{uri = URI, socket = Socket}) -> - ?LOG_INFO("dnssd Service: ~p:~w", [Host, Port]), + ?LOG_INFO("Hello ZeroMQ client: DNS discovery service resolved path '~p' to host '~p:~w'.", [URI, Host, Port], + gen_meta_fields(State), ?LOGID43), Protocol = zmq_protocol(URI), R = ezmq:connect(Socket, tcp, clean_host(Host), Port, [Protocol]), - ?LOG_INFO("ezmq:connect: ~p", [R]), + ?LOG_INFO("Hello ZeroMQ client attempted to establish connection to '~p' returning '~p'", [URI, R], + gen_meta_fields(State), ?LOGID44), {noreply, State}; handle_info({dnssd, _Ref, Msg}, State) -> - ?LOG_INFO("dnssd Msg: ~p", [Msg]), + ?LOG_INFO("Hello ZeroMQ client ignored message '~p' from DNS discovery service.", [Msg], + gen_meta_fields(State), ?LOGID45), {noreply, State}; handle_info({zmq, _Socket, [Signature, Msg]}, State) -> %% recieve on req socket {?INCOMING_MSG, {ok, Signature, Msg, State}}; @@ -109,3 +113,6 @@ clean_host(Host) -> Host end, binary_to_list(CleanedHost). + +gen_meta_fields(#zmq_state{uri = Uri}) -> + [{hello_transport, zmtp}, {hello_transport_url, ex_uri:encode(Uri)}]. diff --git a/src/transports/hello_zmq_listener.erl b/src/transports/hello_zmq_listener.erl index 2dac4bf..ebfedd6 100644 --- a/src/transports/hello_zmq_listener.erl +++ b/src/transports/hello_zmq_listener.erl @@ -55,10 +55,11 @@ port(_ExUriUrl, ListenerId) -> %% -------------------------------------------------------------------------------- %% -- gen_server callbacks -record(state, { - url :: #ex_uri{}, - lastmsg_peer :: binary(), - encode_info :: binary(), - socket :: ezmq:socket() + url :: #ex_uri{}, + encoded_url :: string(), + lastmsg_peer :: binary(), + encode_info :: binary(), + socket :: ezmq:socket() }). start_link(URL) -> @@ -67,12 +68,14 @@ start_link(URL) -> init(URL) -> process_flag(trap_exit, true), {ok, Socket} = ezmq:socket([{type, router}, {active, true}]), + EncUrl = ex_uri:encode(URL), case ezmq_bind_url(Socket, URL) of ok -> - State = #state{socket = Socket, url = URL}, + State = #state{socket = Socket, url = URL, encoded_url = EncUrl}, {ok, State}; {error, Error} -> - ?LOG_ERROR("ezmq_bind_url error: ~p", [Error]), + ?LOG_INFO("Hello ZeroMQ listener was unable to bind on '~p' because of reason '~p'.", [URL, Error], + [{hello_transport, zmtp}, {hello_transport_url, EncUrl}], ?LOGID47), {stop, Error} end. @@ -88,7 +91,8 @@ handle_info({zmq, Socket, {Peer, [Signature, Msg]}}, State = #state{url = URL, s {noreply, State}; handle_info({zmq, _Socket, {Peer, Msg}}, State) -> - ?LOG_ERROR("received bad message: ~p from ~p", [Msg, Peer]), + ?LOG_INFO("Hello ZeroMQ listener received bad message '~p' from '~p'.", [Msg, Peer], + gen_meta_fields(State), ?LOGID48), {noreply, State}; handle_info({hello_msg, _Handler, Peer, Signature, Message}, State = #state{socket = Socket}) -> @@ -100,7 +104,8 @@ handle_info({hello_closed, _HandlerPid, _Peer}, State) -> handle_info({'EXIT', _Reason}, State) -> {noreply, State}; handle_info({dnssd, _Ref, Msg}, State) -> - ?LOG_INFO("dnssd Msg: ~p", [Msg]), + ?LOG_DEBUG("Hello ZeroMQ listener ignored message '~p' from DNS discovery service.", [Msg], + gen_meta_fields(State), ?LOGID49), {noreply, State}. terminate(_Reason, State) -> @@ -145,3 +150,6 @@ ezmq_ip(inet6, Host) -> _ -> inet:parse_ipv6_address(Host) end. + +gen_meta_fields(#state{encoded_url = EncUrl}) -> + [{hello_transport, zmtp}, {hello_transport_url, EncUrl}]. \ No newline at end of file diff --git a/test/jsonrpc_SUITE.erl b/test/jsonrpc_SUITE.erl index 59d06ec..af5722a 100644 --- a/test/jsonrpc_SUITE.erl +++ b/test/jsonrpc_SUITE.erl @@ -10,9 +10,9 @@ % -- test cases call_service(_Config) -> {Req1, [Args1], _} = ?REQ11, - {ok, Args1} = hello:call_service(atom_to_binary(handler1:name(), latin1), {Req1, [Args1]}), + {ok, Args1} = hello:call_service(atom_to_binary(handler1:name(), latin1), handler1:name(), {Req1, [Args1]}), {Req2, [Args2], _} = ?REQ21, - {ok, Args2} = hello:call_service(atom_to_binary(handler2:name(), latin1), {Req2, [Args2]}). + {ok, Args2} = hello:call_service(atom_to_binary(handler2:name(), latin1), handler2:name(), {Req2, [Args2]}). simple_one_shot(_Config) ->