diff --git a/src/syn_backbone.erl b/src/syn_backbone.erl index dc5bdbe2..31e42ec9 100755 --- a/src/syn_backbone.erl +++ b/src/syn_backbone.erl @@ -46,6 +46,8 @@ %% includes -include("syn.hrl"). +-include_lib("kernel/include/logger.hrl"). + %% =================================================================== %% API %% =================================================================== @@ -110,15 +112,30 @@ init([]) -> {stop, Reason :: term(), Reply :: term(), State :: map()} | {stop, Reason :: term(), State :: map()}. handle_call({create_tables_for_scope, Scope}, _From, State) -> - error_logger:info_msg("SYN[~s] Creating tables for scope <~s>", [node(), Scope]), ensure_table_existence(set, syn_registry_by_name, Scope), ensure_table_existence(bag, syn_registry_by_pid, Scope), ensure_table_existence(ordered_set, syn_pg_by_name, Scope), ensure_table_existence(ordered_set, syn_pg_by_pid, Scope), + ?LOG_INFO(#{ + action => tables_created, + scope => Scope + }, + #{ + report_cb => fun syn_logger:scope/1, + domain => [syn, backbone] + }), {reply, ok, State}; handle_call(Request, From, State) -> - error_logger:warning_msg("SYN[~s] Received from ~p an unknown call message: ~p", [node(), From, Request]), + ?LOG_WARNING(#{ + kind => call, + from => From, + msg => Request + }, + #{ + report_cb => fun syn_logger:unknown_message/1, + domain => [syn, backbone] + }), {reply, undefined, State}. %% ---------------------------------------------------------------------------------------------------------- @@ -129,7 +146,14 @@ handle_call(Request, From, State) -> {noreply, State :: map(), Timeout :: non_neg_integer()} | {stop, Reason :: term(), State :: map()}. handle_cast(Msg, State) -> - error_logger:warning_msg("SYN[~s] Received an unknown cast message: ~p", [node(), Msg]), + ?LOG_WARNING(#{ + kind => cast, + msg => Msg + }, + #{ + report_cb => fun syn_logger:unknown_message/1, + domain => [syn, backbone] + }), {noreply, State}. %% ---------------------------------------------------------------------------------------------------------- @@ -140,7 +164,14 @@ handle_cast(Msg, State) -> {noreply, State :: map(), Timeout :: non_neg_integer()} | {stop, Reason :: term(), State :: map()}. handle_info(Info, State) -> - error_logger:warning_msg("SYN[~s] Received an unknown info message: ~p", [node(), Info]), + ?LOG_WARNING(#{ + kind => info, + msg => Info + }, + #{ + report_cb => fun syn_logger:unknown_message/1, + domain => [syn, backbone] + }), {noreply, State}. %% ---------------------------------------------------------------------------------------------------------- @@ -148,7 +179,13 @@ handle_info(Info, State) -> %% ---------------------------------------------------------------------------------------------------------- -spec terminate(Reason :: term(), State :: map()) -> terminated. terminate(Reason, _State) -> - error_logger:info_msg("SYN[~s] Terminating with reason: ~p", [node(), Reason]), + ?LOG_INFO(#{ + msg => {terminate, Reason} + }, + #{ + report_cb => fun syn_logger:terminate/1, + scope => [syn, backbone] + }), %% return terminated. diff --git a/src/syn_event_handler.erl b/src/syn_event_handler.erl index 833471de..6f6886bc 100644 --- a/src/syn_event_handler.erl +++ b/src/syn_event_handler.erl @@ -125,6 +125,8 @@ -module(syn_event_handler). +-include_lib("kernel/include/logger.hrl"). + %% API -export([ensure_event_handler_loaded/0]). -export([call_event_handler/2]). @@ -230,10 +232,16 @@ call_event_handler(CallbackMethod, Args) -> true -> try apply(CustomEventHandler, CallbackMethod, Args) catch Class:Reason:Stacktrace -> - error_logger:error_msg( - "SYN[~s] Error ~p:~p in custom handler ~p: ~p", - [node(), Class, Reason, CallbackMethod, Stacktrace] - ) + ?LOG_ERROR(#{ + class => Class, + reason => Reason, + mfa => {CustomEventHandler, CallbackMethod, Args}, + stacktrace => Stacktrace + }, + #{ + report_cb => fun syn_logger:callback_error/1, + domain => [syn, event_handler] + }) end; _ -> @@ -255,11 +263,18 @@ do_resolve_registry_conflict(Scope, Name, {Pid1, Meta1, Time1}, {Pid2, Meta2, Ti PidToKeep when is_pid(PidToKeep) -> {PidToKeep, false}; _ -> {undefined, false} - catch Class:Reason -> - error_logger:error_msg( - "SYN[~s] Error ~p in custom handler resolve_registry_conflict: ~p", - [node(), Class, Reason] - ), + catch Class:Reason:Stacktrace -> + ?LOG_ERROR(#{ + class => Class, + reason => Reason, + mfa => {CustomEventHandler, + resolve_registry_conflict, [Scope, Name, {Pid1, Meta1, Time1}, {Pid2, Meta2, Time2}]}, + stacktrace => Stacktrace + }, + #{ + report_cb => fun syn_logger:callback_error/1, + domain => [syn, event_handler] + }), {undefined, false} end; diff --git a/src/syn_gen_scope.erl b/src/syn_gen_scope.erl index 7c194a93..d5e34169 100644 --- a/src/syn_gen_scope.erl +++ b/src/syn_gen_scope.erl @@ -56,6 +56,8 @@ %% includes -include("syn.hrl"). +-include_lib("kernel/include/logger.hrl"). + %% callbacks -callback init(#state{}) -> {ok, HandlerState :: term()}. @@ -205,9 +207,13 @@ handle_info({'3.0', discover, RemoteScopePid}, #state{ nodes_map = NodesMap } = State) -> RemoteScopeNode = node(RemoteScopePid), - error_logger:info_msg("SYN[~s|~s<~s>] Received DISCOVER request from node ~s", - [node(), HandlerLogName, Scope, RemoteScopeNode] - ), + ?LOG_INFO(#{msg => discover, from => RemoteScopeNode}, + #{ + handler_name => HandlerLogName, + scope => Scope, + report_cb => fun syn_logger:?MODULE/1, + domain => [syn, gen_scope] + }), %% send local data to remote {ok, LocalData} = Handler:get_local_data(State), send_to_node(RemoteScopeNode, {'3.0', ack_sync, self(), LocalData}, State), @@ -230,9 +236,13 @@ handle_info({'3.0', ack_sync, RemoteScopePid, Data}, #state{ scope = Scope } = State) -> RemoteScopeNode = node(RemoteScopePid), - error_logger:info_msg("SYN[~s|~s<~s>] Received ACK SYNC (~w entries) from node ~s", - [node(), HandlerLogName, Scope, length(Data), RemoteScopeNode] - ), + ?LOG_INFO(#{msg => {ack_sync, Data}, from => RemoteScopeNode}, + #{ + handler_name => HandlerLogName, + scope => Scope, + report_cb => fun syn_logger:?MODULE/1, + domain => [syn, gen_scope] + }), %% save remote data Handler:save_remote_data(Data, State), %% is this a new node? @@ -261,9 +271,16 @@ handle_info({'DOWN', MRef, process, Pid, Reason}, #state{ RemoteNode = node(Pid), case maps:take(RemoteNode, NodesMap) of {Pid, NodesMap1} -> - error_logger:info_msg("SYN[~s|~s<~s>] Scope Process is DOWN on node ~s: ~p", - [node(), HandlerLogName, Scope, RemoteNode, Reason] - ), + ?LOG_INFO(#{ + msg => {down, Reason}, + from => RemoteNode + }, + #{ + handler_name => HandlerLogName, + scope => Scope, + report_cb => fun syn_logger:?MODULE/1, + domain => [syn, gen_scope] + }), Handler:purge_local_data_for_node(RemoteNode, State), {noreply, State#state{nodes_map = NodesMap1}}; @@ -280,9 +297,13 @@ handle_info({nodeup, RemoteNode}, #state{ handler_log_name = HandlerLogName, scope = Scope } = State) -> - error_logger:info_msg("SYN[~s|~s<~s>] Node ~s has joined the cluster, sending discover message", - [node(), HandlerLogName, Scope, RemoteNode] - ), + ?LOG_INFO(#{msg => nodeup, from => RemoteNode}, + #{ + handler_name => HandlerLogName, + scope => Scope, + report_cb => fun syn_logger:?MODULE/1, + domain => [syn, gen_scope] + }), send_to_node(RemoteNode, {'3.0', discover, self()}, State), {noreply, State}; @@ -301,7 +322,13 @@ handle_continue(after_init, #state{ scope = Scope, process_name = ProcessName } = State) -> - error_logger:info_msg("SYN[~s|~s<~s>] Discovering the cluster", [node(), HandlerLogName, Scope]), + ?LOG_INFO(#{msg => after_init}, + #{ + handler_name => HandlerLogName, + scope => Scope, + report_cb => fun syn_logger:?MODULE/1, + domain => [syn, gen_scope] + }), %% broadcasting is done in the scope process to avoid issues with ordering guarantees lists:foreach(fun(RemoteNode) -> {ProcessName, RemoteNode} ! {'3.0', discover, self()} @@ -313,7 +340,13 @@ handle_continue(after_init, #state{ %% ---------------------------------------------------------------------------------------------------------- -spec terminate(Reason :: (normal | shutdown | {shutdown, term()} | term()), #state{}) -> any(). terminate(Reason, #state{handler_log_name = HandlerLogName, scope = Scope}) -> - error_logger:info_msg("SYN[~s|~s<~s>] Terminating with reason: ~p", [node(), HandlerLogName, Scope, Reason]). + ?LOG_INFO(#{msg => {terminate, Reason}}, + #{ + handler_name => HandlerLogName, + scope => Scope, + report_cb => fun syn_logger:terminate/1, + domain => [syn, gen_scope] + }). %% ---------------------------------------------------------------------------------------------------------- %% Convert process state when code is changed. diff --git a/src/syn_logger.erl b/src/syn_logger.erl new file mode 100644 index 00000000..221d04e4 --- /dev/null +++ b/src/syn_logger.erl @@ -0,0 +1,54 @@ +-module(syn_logger). + +-export([syn_gen_scope/1, + terminate/1, + callback_error/1, + unknown_message/1, + scope/1, + conflict/1]). + +syn_gen_scope(#{msg := discover, from := From}) -> + {"Received DISCOVER request from node ~s", [From]}; +syn_gen_scope(#{msg := {ack_sync, Data}, from := From}) -> + {"Received ACK SYNC (~w entries) from node ~s", [length(Data), From]}; +syn_gen_scope(#{msg := {down, Reason}, from := From}) -> + {"Scope Process is DOWN on node node ~s: ~p", [From, Reason]}; +syn_gen_scope(#{msg := nodeup, from := From}) -> + {"Node ~s has joined the cluster, sending discover message", [From]}; +syn_gen_scope(#{msg := after_init}) -> + {"Discover the cluster", []}. + +terminate(#{msg := {terminate, Reason}}) -> + {"Terminating with reason: ~p", [Reason]}. + +callback_error(#{class := Class, + reason := Reason, + mfa := {_, Func, _}, + stacktrace := Stacktrace}) -> + {"Error ~p:~p in custom handler ~p: ~p", [Class, Reason, Func, Stacktrace]}; +callback_error(#{class := Class, + reason := Reason, + fa := {Func, _}, + stacktrace := Stacktrace}) -> + {"Error ~p:~p in custom handler ~p: ~p", [Class, Reason, Func, Stacktrace]}. + +unknown_message(#{kind := down, pid := Pid, reason := Reason}) -> + {"Received a DOWN message from and unknown process ~p with reason: ~p", + [Pid, Reason]}; +unknown_message(#{kind := call, from := From, msg := Msg}) -> + {"Received from ~p an unknown call message: ~p", [From, Msg]}; +unknown_message(#{kind := Kind, msg := Msg}) -> + {"Received an unknown ~p message: ~p", [Kind, Msg]}. + +scope(#{action := tables_created, new := Scope}) -> + {"Created tabled for scope <~s>", [Scope]}; +scope(#{action := added, new := Scope}) -> + {"Added node to scope <~s>", [Scope]}. + +conflict(#{name := Name, remote := Remote, local := Local, keep := {none, Pid}}) -> + {"Registry CONFLICT for name ~p: ~p vs ~p -> none chosen: ~p", + [Name, Remote, Local, Pid]}; +conflict(#{name := Name, remote := Remote, local := Local, keep := Keep} = Msg) -> + #{Keep := {Pid, _}} = Msg, + {"Registry CONFLICT for name ~p: ~p vs ~p -> keeping ~s: ~p", + [Name, Remote, Local, Keep, Pid]}. diff --git a/src/syn_pg.erl b/src/syn_pg.erl index 66b5a169..02e74cd2 100644 --- a/src/syn_pg.erl +++ b/src/syn_pg.erl @@ -69,6 +69,8 @@ %% includes -include("syn.hrl"). +-include_lib("kernel/include/logger.hrl"). + %% =================================================================== %% API %% =================================================================== @@ -364,10 +366,16 @@ handle_call({'3.0', join_or_update_on_node, RequesterNode, GroupName, Pid, MetaO do_join_on_node(GroupName, Pid, TableMeta, Meta, MRef, normal, RequesterNode, on_group_process_updated, State) catch Class:Reason:Stacktrace -> - error_logger:error_msg( - "SYN[~s] Error ~p:~p in pg update function: ~p", - [node(), Class, Reason, Stacktrace] - ), + ?LOG_ERROR(#{ + class => Class, + reason => Reason, + fa => {update, [TableMeta]}, + stacktrace => Stacktrace + }, + #{ + report_cb => fun syn_logger:callback_error/1, + domain => [syn, pg] + }), {reply, {raise, Class, Reason, Stacktrace}, State} end; @@ -407,9 +415,16 @@ handle_call({'3.0', leave_on_node, RequesterNode, GroupName, Pid}, _From, #state end; handle_call(Request, From, #state{scope = Scope} = State) -> - error_logger:warning_msg("SYN[~s|~s<~s>] Received from ~p an unknown call message: ~p", - [node(), ?MODULE_LOG_NAME, Scope, From, Request] - ), + ?LOG_WARNING(#{ + kind => call, + from => From, + msg => Request + }, + #{ + scope => Scope, + report_cb => fun syn_logger:unknown_message/1, + domain => [syn, pg] + }), {reply, undefined, State}. %% ---------------------------------------------------------------------------------------------------------- @@ -456,10 +471,16 @@ handle_info({'DOWN', _MRef, process, Pid, Reason}, #state{ } = State) -> case find_pg_entries_by_pid(Pid, TableByPid) of [] -> - error_logger:warning_msg( - "SYN[~s|~s<~s>] Received a DOWN message from an unknown process ~p with reason: ~p", - [node(), ?MODULE_LOG_NAME, Scope, Pid, Reason] - ); + ?LOG_WARNING(#{ + kind => down, + pid => Pid, + reason => Reason + }, + #{ + scope => Scope, + report_cb => fun syn_logger:unknown_message/1, + domain => [syn, pg] + }); Entries -> lists:foreach(fun({{_Pid, GroupName}, Meta, _, _, _}) -> @@ -475,7 +496,15 @@ handle_info({'DOWN', _MRef, process, Pid, Reason}, #state{ {noreply, State}; handle_info(Info, #state{scope = Scope} = State) -> - error_logger:warning_msg("SYN[~s|~s<~s>] Received an unknown info message: ~p", [node(), ?MODULE_LOG_NAME, Scope, Info]), + ?LOG_WARNING(#{ + kind => info, + msg => Info + }, + #{ + scope => Scope, + report_cb => fun syn_logger:unknown_message/1, + domain => [syn, pg] + }), {noreply, State}. %% ---------------------------------------------------------------------------------------------------------- diff --git a/src/syn_registry.erl b/src/syn_registry.erl index 774e750a..408b1a67 100755 --- a/src/syn_registry.erl +++ b/src/syn_registry.erl @@ -57,6 +57,8 @@ %% includes -include("syn.hrl"). +-include_lib("kernel/include/logger.hrl"). + %% =================================================================== %% API %% =================================================================== @@ -252,10 +254,16 @@ handle_call({'3.0', register_or_update_on_node, RequesterNode, Name, Pid, MetaOr do_register_on_node(Name, Pid, TableMeta, Meta, MRef, normal, RequesterNode, on_registry_process_updated, State) catch Class:Reason:Stacktrace -> - error_logger:error_msg( - "SYN[~s] Error ~p:~p in registry update function: ~p", - [node(), Class, Reason, Stacktrace] - ), + ?LOG_ERROR(#{ + class => Class, + reason => Reason, + fa => {registry_update, [Pid, TableMeta]}, + stacktrace => Stacktrace + }, + #{ + report_cb => fun syn_logger:callback_error/1, + domain => [syn, registry] + }), {reply, {raise, Class, Reason, Stacktrace}, State} end; @@ -302,9 +310,16 @@ handle_call({'3.0', unregister_on_node, RequesterNode, Name, Pid}, _From, #state end; handle_call(Request, From, #state{scope = Scope} = State) -> - error_logger:warning_msg("SYN[~s|~s<~s>] Received from ~p an unknown call message: ~p", - [node(), ?MODULE_LOG_NAME, Scope, From, Request] - ), + ?LOG_WARNING(#{ + kind => call, + from => From, + msg => Request + }, + #{ + scope => Scope, + report_cb => fun syn_logger:unknown_message/1, + domain => [syn, registry] + }), {reply, undefined, State}. %% ---------------------------------------------------------------------------------------------------------- @@ -350,10 +365,16 @@ handle_info({'DOWN', _MRef, process, Pid, Reason}, #state{ } = State) -> case find_registry_entries_by_pid(Pid, TableByPid) of [] -> - error_logger:warning_msg( - "SYN[~s|~s<~s>] Received a DOWN message from an unknown process ~p with reason: ~p", - [node(), ?MODULE_LOG_NAME, Scope, Pid, Reason] - ); + ?LOG_WARNING(#{ + kind => down, + pid => Pid, + reason => Reason + }, + #{ + scope => Scope, + report_cb => fun syn_logger:unknown_message/1, + domain => [syn, registry] + }); Entries -> lists:foreach(fun({_, Name, Meta, _, _, _}) -> @@ -369,7 +390,15 @@ handle_info({'DOWN', _MRef, process, Pid, Reason}, #state{ {noreply, State}; handle_info(Info, #state{scope = Scope} = State) -> - error_logger:warning_msg("SYN[~s|~s<~s>] Received an unknown info message: ~p", [node(), ?MODULE_LOG_NAME, Scope, Info]), + ?LOG_WARNING(#{ + kind => info, + msg => Info + }, + #{ + scope => Scope, + report_cb => fun syn_logger:unknown_message/1, + domain => [syn, registry] + }), {noreply, State}. %% ---------------------------------------------------------------------------------------------------------- @@ -667,9 +696,17 @@ resolve_conflict(Scope, Name, {Pid, Meta, Time}, {TablePid, TableMeta, TableTime case PidToKeep of Pid -> %% -> we keep the remote pid - error_logger:info_msg("SYN[~s|~s<~s>] Registry CONFLICT for name ~p: ~p vs ~p -> keeping remote: ~p", - [node(), ?MODULE_LOG_NAME, Scope, Name, {Pid, Meta}, {TablePid, TableMeta}, Pid] - ), + ?LOG_INFO(#{ + name => Name, + remote => {Pid, Meta}, + local => {TablePid, TableMeta}, + keep => remote + }, + #{ + scope => Scope, + report_cb => fun syn_logger:conflict/1, + domain => [syn, registry] + }), %% update locally, the incoming sync_register will update with the time coming from remote node update_local_table(Name, TablePid, {Pid, Meta, Time, undefined}, TableByName, TableByPid), %% kill @@ -683,9 +720,17 @@ resolve_conflict(Scope, Name, {Pid, Meta, Time}, {TablePid, TableMeta, TableTime TablePid -> %% -> we keep the local pid, remote pid will be killed by the other node in the conflict - error_logger:info_msg("SYN[~s|~s<~s>] Registry CONFLICT for name ~p: ~p vs ~p -> keeping local: ~p", - [node(), ?MODULE_LOG_NAME, Scope, Name, {Pid, Meta}, {TablePid, TableMeta}, TablePid] - ), + ?LOG_INFO(#{ + name => Name, + remote => {Pid, Meta}, + local => {TablePid, TableMeta}, + keep => local + }, + #{ + scope => Scope, + report_cb => fun syn_logger:conflict/1, + domain => [syn, registry] + }), %% overwrite with updated time ResolveTime = erlang:system_time(), add_to_local_table(Name, TablePid, TableMeta, ResolveTime, TableMRef, TableByName, TableByPid), @@ -693,9 +738,17 @@ resolve_conflict(Scope, Name, {Pid, Meta, Time}, {TablePid, TableMeta, TableTime syn_gen_scope:broadcast({'3.0', sync_register, Name, TablePid, TableMeta, ResolveTime, syn_conflict_resolution}, State); Invalid -> - error_logger:info_msg("SYN[~s|~s<~s>] Registry CONFLICT for name ~p: ~p vs ~p -> none chosen (got: ~p)", - [node(), ?MODULE_LOG_NAME, Scope, Name, {Pid, Meta}, {TablePid, TableMeta}, Invalid] - ), + ?LOG_INFO(#{ + name => Name, + remote => {Pid, Meta}, + local => {TablePid, TableMeta}, + keep => {none, Invalid} + }, + #{ + scope => Scope, + report_cb => fun syn_logger:conflict/1, + domain => [syn, registry] + }), %% remove maybe_demonitor(TablePid, TableByPid), remove_from_local_table(Name, TablePid, TableByName, TableByPid), diff --git a/src/syn_sup.erl b/src/syn_sup.erl index e70c39cf..02ccee27 100755 --- a/src/syn_sup.erl +++ b/src/syn_sup.erl @@ -37,6 +37,8 @@ %% includes -include("syn.hrl"). +-include_lib("kernel/include/logger.hrl"). + %% =================================================================== %% API %% =================================================================== @@ -50,7 +52,6 @@ node_scopes() -> -spec add_node_to_scope(Scope :: atom()) -> ok. add_node_to_scope(Scope) when is_atom(Scope) -> - error_logger:info_msg("SYN[~s] Adding node to scope <~s>", [node(), Scope]), Scopes0 = node_scopes(), case lists:member(Scope, Scopes0) of true -> @@ -64,6 +65,16 @@ add_node_to_scope(Scope) when is_atom(Scope) -> application:set_env(syn, scopes, Scopes), %% start child supervisor:start_child(?MODULE, child_spec(Scope)), + + ?LOG_INFO(#{ + action => added, + new => Scope, + prev => Scopes0 + }, + #{ + report_cb => fun syn_logger:scope/1, + domain => [syn] + }), ok end. diff --git a/test/syn_test_suite_helper.erl b/test/syn_test_suite_helper.erl index 45a13308..d3bb2007 100755 --- a/test/syn_test_suite_helper.erl +++ b/test/syn_test_suite_helper.erl @@ -40,7 +40,6 @@ -export([assert_received_messages/1]). -export([assert_empty_queue/0]). -export([assert_wait/2]). --export([send_error_logger_to_disk/0]). %% internal -export([process_main/0]). @@ -308,9 +307,6 @@ assert_wait(ExpectedResult, Fun, StartAt) -> end end. -send_error_logger_to_disk() -> - error_logger:logfile({open, atom_to_list(node())}). - %% =================================================================== %% Internal %% ===================================================================