From 0a5307f97d3afe9cfcbc0aeea60888d924564365 Mon Sep 17 00:00:00 2001 From: Karl Nilsson Date: Wed, 15 Jan 2025 14:58:37 +0000 Subject: [PATCH] Improve some multi line log messages. Also one assertion added. --- src/ra.erl | 8 ++++---- src/ra_log.erl | 2 +- src/ra_server.erl | 26 ++++++++++++++------------ src/ra_server_sup_sup.erl | 6 +++--- src/ra_system_recover.erl | 2 +- test/ra_server_SUITE.erl | 3 +-- 6 files changed, 24 insertions(+), 23 deletions(-) diff --git a/src/ra.erl b/src/ra.erl index d0534491..7296c720 100644 --- a/src/ra.erl +++ b/src/ra.erl @@ -444,7 +444,7 @@ start_cluster(System, [#{cluster_name := ClusterName} | _] = ServerConfigs, end, ServerConfigs), case Started of [] -> - ?ERR("ra: failed to form a new cluster ~w.~n " + ?ERR("ra: failed to form a new cluster ~w. " "No servers were successfully started.", [ClusterName]), {error, cluster_not_formed}; @@ -460,15 +460,15 @@ start_cluster(System, [#{cluster_name := ClusterName} | _] = ServerConfigs, case members(TriggeredId, length(ServerConfigs) * Timeout) of {ok, _, Leader} -> - ?INFO("ra: started cluster ~ts with ~b servers~n" - "~b servers failed to start: ~w~nLeader: ~w", + ?INFO("ra: started cluster ~ts with ~b servers. " + "~b servers failed to start: ~w. Leader: ~w", [ClusterName, length(ServerConfigs), length(NotStarted), NotStartedIds, Leader]), % we have a functioning cluster {ok, StartedIds, NotStartedIds}; Err -> - ?WARN("ra: failed to form new cluster ~w.~n " + ?WARN("ra: failed to form new cluster ~w. " "Error: ~w", [ClusterName, Err]), _ = [force_delete_server(System, N) || N <- StartedIds], % we do not have a functioning cluster diff --git a/src/ra_log.erl b/src/ra_log.erl index 983b5d64..5d8711d3 100644 --- a/src/ra_log.erl +++ b/src/ra_log.erl @@ -1109,7 +1109,7 @@ delete_everything(#?MODULE{cfg = #cfg{uid = UId, catch _:_ = Err -> ?WARN("ra_log:delete_everything/1 failed to delete " - "directory ~ts~n Error: ~p", [Dir, Err]) + "directory ~ts. Error: ~p", [Dir, Err]) end, ok. diff --git a/src/ra_server.erl b/src/ra_server.erl index 44312d18..028092ec 100644 --- a/src/ra_server.erl +++ b/src/ra_server.erl @@ -6,6 +6,7 @@ %% @hidden -module(ra_server). +-include_lib("stdlib/include/assert.hrl"). -include("ra.hrl"). -include("ra_server.hrl"). @@ -1160,6 +1161,7 @@ handle_follower(#append_entries_rpc{term = Term, State00 = #{cfg := #cfg{log_id = LogId, id = Id} = Cfg, log := Log00, + commit_index := CommitIndex, current_term := CurTerm}) when Term >= CurTerm -> ok = incr_counter(Cfg, ?C_RA_SRV_AER_RECEIVED_FOLLOWER, 1), @@ -1175,13 +1177,14 @@ handle_follower(#append_entries_rpc{term = Term, case Entries of [] -> ok = incr_counter(Cfg, ?C_RA_SRV_AER_RECEIVED_FOLLOWER_EMPTY, 1), - LastIdx = ra_log:last_index_term(Log1), + {LastIdx, _} = ra_log:last_index_term(Log1), Log2 = case Entries0 of - [] when element(1, LastIdx) > PLIdx -> + [] when LastIdx > PLIdx -> %% if no entries were sent we need to reset %% last index to match the leader - ?DEBUG("~ts: resetting last index to ~b", - [LogId, PLIdx]), + ?DEBUG("~ts: resetting last index to ~b from ~b in term ~b", + [LogId, PLIdx, LastIdx, Term]), + ?assertNot(PLIdx =< CommitIndex), {ok, L} = ra_log:set_last_index(PLIdx, Log1), L; _ -> @@ -1218,7 +1221,6 @@ handle_follower(#append_entries_rpc{term = Term, %% alternative where the WAL writes the last index, term %% it wrote for each UID into an ETS table and query %% this. - % Log = ra_log:reset_to_last_known_written(Log1), Log = Log1, {await_condition, State1#{log => Log, @@ -1249,7 +1251,7 @@ handle_follower(#append_entries_rpc{term = Term, %% NB: this is the commit index before update LastApplied = maps:get(last_applied, State00), ?INFO("~ts: term mismatch - follower had entry at ~b with term ~b " - "but not with term ~b~n" + "but not with term ~b. " "Asking leader ~w to resend from ~b", [LogId, PLIdx, OtherTerm, PLTerm, LeaderId, LastApplied + 1]), % This situation arises when a minority leader replicates entries @@ -1346,7 +1348,7 @@ handle_follower(#request_vote_rpc{term = Term, candidate_id = Cand, LastIdxTerm = last_idx_term(State1), case is_candidate_log_up_to_date(LLIdx, LLTerm, LastIdxTerm) of true -> - ?INFO("~ts: granting vote for ~w with last indexterm ~w" + ?INFO("~ts: granting vote for ~w with last {index, term} ~w" " for term ~b previous term was ~b", [LogId, Cand, {LLIdx, LLTerm}, Term, CurTerm]), Reply = #request_vote_result{term = Term, vote_granted = true}, @@ -1354,8 +1356,8 @@ handle_follower(#request_vote_rpc{term = Term, candidate_id = Cand, {follower, State, [{reply, Reply}]}; false -> ?INFO("~ts: declining vote for ~w for term ~b," - " candidate last log index term was: ~w~n" - " last log entry idxterm seen was: ~w", + " candidate last log {index, term} was: ~w " + " last log entry {index, term} is: ~w", [LogId, Cand, Term, {LLIdx, LLTerm}, {LastIdxTerm}]), Reply = #request_vote_result{term = Term, vote_granted = false}, {follower, update_term(Term, State1), [{reply, Reply}]} @@ -2399,7 +2401,7 @@ process_pre_vote(FsmState, #pre_vote_rpc{term = Term, candidate_id = Cand, TheirMacVer =< OurMacVer) -> ?DEBUG("~ts: granting pre-vote for ~w" " machine version (their:ours:effective) ~b:~b:~b" - " with last indexterm ~w" + " with last {index, term} ~w" " for term ~b previous term ~b", [log_id(State0), Cand, TheirMacVer, OurMacVer, EffMacVer, {LLIdx, LLTerm}, Term, CurTerm]), @@ -2413,8 +2415,8 @@ process_pre_vote(FsmState, #pre_vote_rpc{term = Term, candidate_id = Cand, start_election_timeout]}; false -> ?DEBUG("~ts: declining pre-vote for ~w for term ~b," - " candidate last log index term was: ~w~n" - "Last log entry idxterm seen was: ~w", + " candidate last log {index, term} was: ~w " + "last log entry {index, term} seen is: ~w", [log_id(State0), Cand, Term, {LLIdx, LLTerm}, LastIdxTerm]), case FsmState of follower -> diff --git a/src/ra_server_sup_sup.erl b/src/ra_server_sup_sup.erl index 4659c63c..dcfc964e 100644 --- a/src/ra_server_sup_sup.erl +++ b/src/ra_server_sup_sup.erl @@ -171,7 +171,7 @@ delete_server_rpc(System, RaName) -> #{data_dir := _SysDir, names := #{log_meta := Meta, server_sup := SrvSup} = Names} -> - ?INFO("Deleting server ~w and its data directory.~n", + ?INFO("Deleting server ~w and its data directory.", [RaName]), %% TODO: better handle and report errors %% UId could be `undefined' here @@ -201,7 +201,7 @@ delete_data_directory(Directory) -> ok catch _:_ = Err -> - ?WARN("ra: delete_server/1 failed to delete directory ~ts~n" + ?WARN("ra: delete_server/1 failed to delete directory ~ts. " "Error: ~p", [Directory, Err]), error end @@ -218,7 +218,7 @@ delete_data_directory(Directory) -> remove_all(System) when is_atom(System) -> #{names := #{server_sup := Sup}} = ra_system:fetch(System), _ = [begin - ?DEBUG("ra: terminating child ~w in system ~ts~n", [Pid, System]), + ?DEBUG("ra: terminating child ~w in system ~ts", [Pid, System]), supervisor:terminate_child(Sup, Pid) end || {_, Pid, _, _} <- supervisor:which_children(Sup)], diff --git a/src/ra_system_recover.erl b/src/ra_system_recover.erl index b6ad5214..c31ceaf0 100644 --- a/src/ra_system_recover.erl +++ b/src/ra_system_recover.erl @@ -59,7 +59,7 @@ init([System]) -> ok -> ok catch C:E:S -> - ?ERROR("~s: ~s encountered during server recovery ~p~n " + ?ERROR("~s: ~s encountered during server recovery ~p. " "stack ~p", [?MODULE, C, E, S]), ok diff --git a/test/ra_server_SUITE.erl b/test/ra_server_SUITE.erl index a4663e31..f62d7dbd 100644 --- a/test/ra_server_SUITE.erl +++ b/test/ra_server_SUITE.erl @@ -533,7 +533,7 @@ follower_aer_5(_Config) -> %% next index Init = empty_state(3, n2), AER1 = #append_entries_rpc{term = 1, leader_id = N1, prev_log_index = 0, - prev_log_term = 0, leader_commit = 10, + prev_log_term = 0, leader_commit = 2, entries = [ entry(1, 1, one), entry(2, 1, two), @@ -555,7 +555,6 @@ follower_aer_5(_Config) -> ?assertMatch(#append_entries_reply{next_index = 4, last_term = 1, last_index = 3}, M), - % ct:pal("Effects ~p~n State: ~p", [Effects, State1]), ok.