Browse Source

Improve log display.

Roberto Ostinelli 3 years ago
parent
commit
d86f804d73
7 changed files with 59 additions and 44 deletions
  1. 2 1
      src/syn.hrl
  2. 5 5
      src/syn_backbone.erl
  3. 2 2
      src/syn_event_handler.erl
  4. 22 18
      src/syn_gen_scope.erl
  5. 10 5
      src/syn_pg.erl
  6. 16 11
      src/syn_registry.erl
  7. 2 2
      src/syn_sup.erl

+ 2 - 1
src/syn.hrl

@@ -70,7 +70,8 @@
 %% records
 -record(state, {
     handler = undefined :: undefined | module(),
-    handler_state = undefined :: term(),
+    handler_state :: term(),
+    handler_log_name :: atom(),
     scope = undefined :: atom(),
     process_name :: atom(),
     nodes_map = #{} :: #{node() => pid()},

+ 5 - 5
src/syn_backbone.erl

@@ -105,7 +105,7 @@ 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'", [?MODULE, Scope]),
+    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),
@@ -113,7 +113,7 @@ handle_call({create_tables_for_scope, Scope}, _From, State) ->
     {reply, ok, State};
 
 handle_call(Request, From, State) ->
-    error_logger:warning_msg("SYN[~s] Received from ~p an unknown call message: ~p", [?MODULE, From, Request]),
+    error_logger:warning_msg("SYN[~s] Received from ~p an unknown call message: ~p", [node(), From, Request]),
     {reply, undefined, State}.
 
 %% ----------------------------------------------------------------------------------------------------------
@@ -124,7 +124,7 @@ 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", [?MODULE, Msg]),
+    error_logger:warning_msg("SYN[~s] Received an unknown cast message: ~p", [node(), Msg]),
     {noreply, State}.
 
 %% ----------------------------------------------------------------------------------------------------------
@@ -135,7 +135,7 @@ 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", [?MODULE, Info]),
+    error_logger:warning_msg("SYN[~s] Received an unknown info message: ~p", [node(), Info]),
     {noreply, State}.
 
 %% ----------------------------------------------------------------------------------------------------------
@@ -143,7 +143,7 @@ handle_info(Info, State) ->
 %% ----------------------------------------------------------------------------------------------------------
 -spec terminate(Reason :: term(), State :: map()) -> terminated.
 terminate(Reason, _State) ->
-    error_logger:info_msg("SYN[~s] Terminating with reason: ~p", [?MODULE, Reason]),
+    error_logger:info_msg("SYN[~s] Terminating with reason: ~p", [node(), Reason]),
     %% return
     terminated.
 

+ 2 - 2
src/syn_event_handler.erl

@@ -224,7 +224,7 @@ call_event_handler(CallbackMethod, Args) ->
             catch Class:Reason:Stacktrace ->
                 error_logger:error_msg(
                     "SYN[~s] Error ~p:~p in custom handler ~p: ~p",
-                    [?MODULE, Class, Reason, CallbackMethod, Stacktrace]
+                    [node(), Class, Reason, CallbackMethod, Stacktrace]
                 )
             end;
 
@@ -249,7 +249,7 @@ do_resolve_registry_conflict(Scope, Name, {Pid1, Meta1, Time1}, {Pid2, Meta2, Ti
             catch Class:Reason ->
                 error_logger:error_msg(
                     "SYN[~s] Error ~p in custom handler resolve_registry_conflict: ~p",
-                    [?MODULE, Class, Reason]
+                    [node(), Class, Reason]
                 ),
                 {undefined, false}
             end;

+ 22 - 18
src/syn_gen_scope.erl

@@ -29,7 +29,7 @@
 
 %% API
 -export([
-    start_link/2,
+    start_link/3,
     subcluster_nodes/2,
     call/3, call/4
 ]).
@@ -78,9 +78,9 @@
 %% ===================================================================
 %% API
 %% ===================================================================
--spec start_link(Handler :: module(), Scope :: atom()) ->
+-spec start_link(Handler :: module(), HandlerLogName :: atom(), Scope :: atom()) ->
     {ok, Pid :: pid()} | {error, {already_started, Pid :: pid()}} | {error, Reason :: term()}.
-start_link(Handler, Scope) when is_atom(Scope) ->
+start_link(Handler, HandlerLogName, Scope) when is_atom(Scope) ->
     %% build name
     HandlerBin = list_to_binary(atom_to_list(Handler)),
     ScopeBin = list_to_binary(atom_to_list(Scope)),
@@ -88,7 +88,7 @@ start_link(Handler, Scope) when is_atom(Scope) ->
     %% save to lookup table
     syn_backbone:save_process_name({Handler, Scope}, ProcessName),
     %% create process
-    gen_server:start_link({local, ProcessName}, ?MODULE, [Handler, Scope, ProcessName], []).
+    gen_server:start_link({local, ProcessName}, ?MODULE, [Handler, HandlerLogName, Scope, ProcessName], []).
 
 -spec subcluster_nodes(Handler :: module(), Scope :: atom()) -> [node()].
 subcluster_nodes(Handler, Scope) ->
@@ -138,7 +138,7 @@ send_to_node(RemoteNode, Message, #state{process_name = ProcessName}) ->
     {ok, #state{}} |
     {ok, #state{}, timeout() | hibernate | {continue, term()}} |
     {stop, Reason :: term()} | ignore.
-init([Handler, Scope, ProcessName]) ->
+init([Handler, HandlerLogName, Scope, ProcessName]) ->
     %% monitor nodes
     ok = net_kernel:monitor_nodes(true),
     %% start multicast process
@@ -150,6 +150,7 @@ init([Handler, Scope, ProcessName]) ->
     %% build state
     State = #state{
         handler = Handler,
+        handler_log_name = HandlerLogName,
         scope = Scope,
         process_name = ProcessName,
         multicast_pid = MulticastPid,
@@ -199,12 +200,13 @@ handle_cast(Msg, #state{handler = Handler} = State) ->
     {stop, Reason :: term(), #state{}}.
 handle_info({'3.0', discover, RemoteScopePid}, #state{
     handler = Handler,
+    handler_log_name = HandlerLogName,
     scope = Scope,
     nodes_map = NodesMap
 } = State) ->
     RemoteScopeNode = node(RemoteScopePid),
-    error_logger:info_msg("SYN[~s<~s>] Received DISCOVER request from node '~s'",
-        [Handler, Scope, RemoteScopeNode]
+    error_logger:info_msg("SYN[~s|~s<~s>] Received DISCOVER request from node ~s",
+        [node(), HandlerLogName, Scope, RemoteScopeNode]
     ),
     %% send local data to remote
     {ok, LocalData} = Handler:get_local_data(State),
@@ -223,12 +225,13 @@ handle_info({'3.0', discover, RemoteScopePid}, #state{
 
 handle_info({'3.0', ack_sync, RemoteScopePid, Data}, #state{
     handler = Handler,
+    handler_log_name = HandlerLogName,
     nodes_map = NodesMap,
     scope = Scope
 } = State) ->
     RemoteScopeNode = node(RemoteScopePid),
-    error_logger:info_msg("SYN[~s<~s>] Received ACK SYNC (~w entries) from node '~s'",
-        [Handler, Scope, length(Data), RemoteScopeNode]
+    error_logger:info_msg("SYN[~s|~s<~s>] Received ACK SYNC (~w entries) from node ~s",
+        [node(), HandlerLogName, Scope, length(Data), RemoteScopeNode]
     ),
     %% save remote data
     Handler:save_remote_data(Data, State),
@@ -250,6 +253,7 @@ handle_info({'3.0', ack_sync, RemoteScopePid, Data}, #state{
 
 handle_info({'DOWN', MRef, process, Pid, Reason}, #state{
     handler = Handler,
+    handler_log_name = HandlerLogName,
     scope = Scope,
     nodes_map = NodesMap
 } = State) when node(Pid) =/= node() ->
@@ -257,8 +261,8 @@ 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>] Scope Process is DOWN on node '~s': ~p",
-                [Handler, Scope, RemoteNode, Reason]
+            error_logger:info_msg("SYN[~s|~s<~s>] Scope Process is DOWN on node ~s: ~p",
+                [node(), HandlerLogName, Scope, RemoteNode, Reason]
             ),
             Handler:purge_local_data_for_node(RemoteNode, State),
             {noreply, State#state{nodes_map = NodesMap1}};
@@ -273,11 +277,11 @@ handle_info({nodedown, _Node}, State) ->
     {noreply, State};
 
 handle_info({nodeup, RemoteNode}, #state{
-    handler = Handler,
+    handler_log_name = HandlerLogName,
     scope = Scope
 } = State) ->
-    error_logger:info_msg("SYN[~s<~s>] Node '~s' has joined the cluster, sending discover message",
-        [Handler, Scope, RemoteNode]
+    error_logger:info_msg("SYN[~s|~s<~s>] Node ~s has joined the cluster, sending discover message",
+        [node(), HandlerLogName, Scope, RemoteNode]
     ),
     send_to_node(RemoteNode, {'3.0', discover, self()}, State),
     {noreply, State};
@@ -293,11 +297,11 @@ handle_info(Info, #state{handler = Handler} = State) ->
     {noreply, #state{}, timeout() | hibernate | {continue, term()}} |
     {stop, Reason :: term(), #state{}}.
 handle_continue(after_init, #state{
-    handler = Handler,
+    handler_log_name = HandlerLogName,
     scope = Scope,
     process_name = ProcessName
 } = State) ->
-    error_logger:info_msg("SYN[~s<~s>] Discovering the cluster", [Handler, Scope]),
+    error_logger:info_msg("SYN[~s|~s<~s>] Discovering the cluster", [node(), HandlerLogName, Scope]),
     %% broadcasting is done in the scope process to avoid issues with ordering guarantees
     lists:foreach(fun(RemoteNode) ->
         {ProcessName, RemoteNode} ! {'3.0', discover, self()}
@@ -308,8 +312,8 @@ handle_continue(after_init, #state{
 %% Terminate
 %% ----------------------------------------------------------------------------------------------------------
 -spec terminate(Reason :: (normal | shutdown | {shutdown, term()} | term()), #state{}) -> any().
-terminate(Reason, #state{handler = Handler, scope = Scope}) ->
-    error_logger:info_msg("SYN[~s<~s>] ~s terminating with reason: ~p", [Handler, Scope, Handler, Reason]).
+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]).
 
 %% ----------------------------------------------------------------------------------------------------------
 %% Convert process state when code is changed.

+ 10 - 5
src/syn_pg.erl

@@ -55,6 +55,9 @@
 %% internal
 -export([multi_call_and_receive/5]).
 
+%% macros
+-define(MODULE_LOG_NAME, pg).
+
 %% tests
 -ifdef(TEST).
 -export([add_to_local_table/7]).
@@ -69,7 +72,7 @@
 -spec start_link(Scope :: atom()) ->
     {ok, Pid :: pid()} | {error, {already_started, Pid :: pid()}} | {error, Reason :: term()}.
 start_link(Scope) when is_atom(Scope) ->
-    syn_gen_scope:start_link(?MODULE, Scope).
+    syn_gen_scope:start_link(?MODULE, ?MODULE_LOG_NAME, Scope).
 
 -spec subcluster_nodes(Scope :: atom()) -> [node()].
 subcluster_nodes(Scope) ->
@@ -312,7 +315,9 @@ 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>] Received from ~p an unknown call message: ~p", [?MODULE, Scope, From, Request]),
+    error_logger:warning_msg("SYN[~s|~s<~s>] Received from ~p an unknown call message: ~p",
+        [node(), ?MODULE_LOG_NAME, Scope, From, Request]
+    ),
     {reply, undefined, State}.
 
 %% ----------------------------------------------------------------------------------------------------------
@@ -360,8 +365,8 @@ handle_info({'DOWN', _MRef, process, Pid, Reason}, #state{
     case find_pg_entries_by_pid(Pid, TableByPid) of
         [] ->
             error_logger:warning_msg(
-                "SYN[~s<~s>] Received a DOWN message from an unknown process ~p with reason: ~p",
-                [?MODULE, Scope, Pid, Reason]
+                "SYN[~s|~s<~s>] Received a DOWN message from an unknown process ~p with reason: ~p",
+                [node(), ?MODULE_LOG_NAME, Scope, Pid, Reason]
             );
 
         Entries ->
@@ -378,7 +383,7 @@ handle_info({'DOWN', _MRef, process, Pid, Reason}, #state{
     {noreply, State};
 
 handle_info(Info, #state{scope = Scope} = State) ->
-    error_logger:warning_msg("SYN[~s<~s>] Received an unknown info message: ~p", [?MODULE, Scope, Info]),
+    error_logger:warning_msg("SYN[~s|~s<~s>] Received an unknown info message: ~p", [node(), ?MODULE_LOG_NAME, Scope, Info]),
     {noreply, State}.
 
 %% ----------------------------------------------------------------------------------------------------------

+ 16 - 11
src/syn_registry.erl

@@ -45,6 +45,9 @@
     purge_local_data_for_node/2
 ]).
 
+%% macros
+-define(MODULE_LOG_NAME, registry).
+
 %% tests
 -ifdef(TEST).
 -export([add_to_local_table/7, remove_from_local_table/4]).
@@ -59,7 +62,7 @@
 -spec start_link(Scope :: atom()) ->
     {ok, Pid :: pid()} | {error, {already_started, Pid :: pid()}} | {error, Reason :: term()}.
 start_link(Scope) when is_atom(Scope) ->
-    syn_gen_scope:start_link(?MODULE, Scope).
+    syn_gen_scope:start_link(?MODULE, ?MODULE_LOG_NAME, Scope).
 
 -spec subcluster_nodes(Scope :: atom()) -> [node()].
 subcluster_nodes(Scope) ->
@@ -232,7 +235,9 @@ 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>] Received from ~p an unknown call message: ~p", [?MODULE, Scope, From, Request]),
+    error_logger:warning_msg("SYN[~s|~s<~s>] Received from ~p an unknown call message: ~p",
+        [node(), ?MODULE_LOG_NAME, Scope, From, Request]
+    ),
     {reply, undefined, State}.
 
 %% ----------------------------------------------------------------------------------------------------------
@@ -279,8 +284,8 @@ handle_info({'DOWN', _MRef, process, Pid, Reason}, #state{
     case find_registry_entries_by_pid(Pid, TableByPid) of
         [] ->
             error_logger:warning_msg(
-                "SYN[~s<~s>] Received a DOWN message from an unknown process ~p with reason: ~p",
-                [?MODULE, Scope, Pid, Reason]
+                "SYN[~s|~s<~s>] Received a DOWN message from an unknown process ~p with reason: ~p",
+                [node(), ?MODULE_LOG_NAME, Scope, Pid, Reason]
             );
 
         Entries ->
@@ -297,7 +302,7 @@ handle_info({'DOWN', _MRef, process, Pid, Reason}, #state{
     {noreply, State};
 
 handle_info(Info, #state{scope = Scope} = State) ->
-    error_logger:warning_msg("SYN[~s<~s>] Received an unknown info message: ~p", [?MODULE, Scope, Info]),
+    error_logger:warning_msg("SYN[~s|~s<~s>] Received an unknown info message: ~p", [node(), ?MODULE_LOG_NAME, Scope, Info]),
     {noreply, State}.
 
 %% ----------------------------------------------------------------------------------------------------------
@@ -590,8 +595,8 @@ 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>] Registry CONFLICT for name ~p: ~p vs ~p -> keeping remote: ~p",
-                [?MODULE, Scope, Name, Pid, TablePid, 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]
             ),
             %% 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),
@@ -606,8 +611,8 @@ 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>] Registry CONFLICT for name ~p: ~p vs ~p -> keeping local: ~p",
-                [?MODULE, Scope, Name, Pid, TablePid, TablePid]
+            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]
             ),
             %% overwrite with updated time
             ResolveTime = erlang:system_time(),
@@ -616,8 +621,8 @@ 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>] Registry CONFLICT for name ~p: ~p vs ~p -> none chosen (got: ~p)",
-                [?MODULE, Scope, Name, Pid, TablePid, 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]
             ),
             %% remove
             maybe_demonitor(TablePid, TableByPid),

+ 2 - 2
src/syn_sup.erl

@@ -31,7 +31,7 @@
 -export([start_link/0]).
 -export([node_scopes/0, add_node_to_scope/1]).
 
-%% Supervisor callbacks
+%% supervisor callbacks
 -export([init/1]).
 
 %% includes
@@ -54,7 +54,7 @@ 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", [Scope]),
+    error_logger:info_msg("SYN[~s] Adding node to scope <~s>", [node(), Scope]),
     Scopes0 = application:get_env(syn, scopes, []),
     case lists:member(Scope, Scopes0) of
         true ->