From 002ecae789c26f38e8686c2f158e18f8aaf22ef2 Mon Sep 17 00:00:00 2001 From: Pavel Kalinnikov Date: Fri, 9 Feb 2024 12:35:53 +0000 Subject: [PATCH] rafttest: improve message formatting Print one entry per line, and indent entries appropriately. Print and indent snapshots in a separate line too. Signed-off-by: Pavel Kalinnikov --- testdata/async_storage_writes.txt | 181 ++++++++++++++---- .../async_storage_writes_append_aba_race.txt | 67 +++++-- testdata/campaign_learner_must_vote.txt | 10 +- testdata/confchange_v1_add_single.txt | 6 +- testdata/confchange_v2_add_double_auto.txt | 12 +- .../confchange_v2_add_double_implicit.txt | 6 +- testdata/confchange_v2_add_single_auto.txt | 6 +- .../confchange_v2_add_single_explicit.txt | 6 +- testdata/confchange_v2_replace_leader.txt | 6 +- testdata/probe_and_replicate.txt | 82 +++++++- testdata/snapshot_succeed_via_app_resp.txt | 6 +- .../snapshot_succeed_via_app_resp_behind.txt | 12 +- util.go | 30 +-- 13 files changed, 329 insertions(+), 101 deletions(-) diff --git a/testdata/async_storage_writes.txt b/testdata/async_storage_writes.txt index 52f37092..02e59e5a 100644 --- a/testdata/async_storage_writes.txt +++ b/testdata/async_storage_writes.txt @@ -29,7 +29,9 @@ stabilize Messages: 1->2 MsgVote Term:1 Log:1/10 1->3 MsgVote Term:1 Log:1/10 - 1->AppendThread MsgStorageAppend Term:1 Log:0/0 Commit:10 Vote:1 Responses:[1->1 MsgVoteResp Term:1 Log:0/0] + 1->AppendThread MsgStorageAppend Term:1 Log:0/0 Commit:10 Vote:1 Responses:[ + 1->1 MsgVoteResp Term:1 Log:0/0 + ] > 2 receiving messages 1->2 MsgVote Term:1 Log:1/10 INFO 2 [term: 0] received a MsgVote message with higher term from 1 [term: 1] @@ -49,12 +51,16 @@ stabilize Ready MustSync=true: HardState Term:1 Vote:1 Commit:10 Messages: - 2->AppendThread MsgStorageAppend Term:1 Log:0/0 Commit:10 Vote:1 Responses:[2->1 MsgVoteResp Term:1 Log:0/0] + 2->AppendThread MsgStorageAppend Term:1 Log:0/0 Commit:10 Vote:1 Responses:[ + 2->1 MsgVoteResp Term:1 Log:0/0 + ] > 3 handling Ready Ready MustSync=true: HardState Term:1 Vote:1 Commit:10 Messages: - 3->AppendThread MsgStorageAppend Term:1 Log:0/0 Commit:10 Vote:1 Responses:[3->1 MsgVoteResp Term:1 Log:0/0] + 3->AppendThread MsgStorageAppend Term:1 Log:0/0 Commit:10 Vote:1 Responses:[ + 3->1 MsgVoteResp Term:1 Log:0/0 + ] > 1 receiving messages 1->1 MsgVoteResp Term:1 Log:0/0 INFO 1 received MsgVoteResp from 1 at term 1 @@ -83,7 +89,10 @@ stabilize Messages: 1->2 MsgApp Term:1 Log:1/10 Commit:10 Entries:[1/11 EntryNormal ""] 1->3 MsgApp Term:1 Log:1/10 Commit:10 Entries:[1/11 EntryNormal ""] - 1->AppendThread MsgStorageAppend Term:0 Log:0/0 Entries:[1/11 EntryNormal ""] Responses:[1->1 MsgAppResp Term:1 Log:0/11, AppendThread->1 MsgStorageAppendResp Term:1 Log:1/11] + 1->AppendThread MsgStorageAppend Term:0 Log:0/0 Entries:[1/11 EntryNormal ""] Responses:[ + 1->1 MsgAppResp Term:1 Log:0/11 + AppendThread->1 MsgStorageAppendResp Term:1 Log:1/11 + ] > 2 receiving messages 1->2 MsgApp Term:1 Log:1/10 Commit:10 Entries:[1/11 EntryNormal ""] > 3 receiving messages @@ -100,14 +109,20 @@ stabilize Entries: 1/11 EntryNormal "" Messages: - 2->AppendThread MsgStorageAppend Term:0 Log:0/0 Entries:[1/11 EntryNormal ""] Responses:[2->1 MsgAppResp Term:1 Log:0/11, AppendThread->2 MsgStorageAppendResp Term:1 Log:1/11] + 2->AppendThread MsgStorageAppend Term:0 Log:0/0 Entries:[1/11 EntryNormal ""] Responses:[ + 2->1 MsgAppResp Term:1 Log:0/11 + AppendThread->2 MsgStorageAppendResp Term:1 Log:1/11 + ] > 3 handling Ready Ready MustSync=true: Lead:1 State:StateFollower Entries: 1/11 EntryNormal "" Messages: - 3->AppendThread MsgStorageAppend Term:0 Log:0/0 Entries:[1/11 EntryNormal ""] Responses:[3->1 MsgAppResp Term:1 Log:0/11, AppendThread->3 MsgStorageAppendResp Term:1 Log:1/11] + 3->AppendThread MsgStorageAppend Term:0 Log:0/0 Entries:[1/11 EntryNormal ""] Responses:[ + 3->1 MsgAppResp Term:1 Log:0/11 + AppendThread->3 MsgStorageAppendResp Term:1 Log:1/11 + ] > 1 receiving messages 1->1 MsgAppResp Term:1 Log:0/11 AppendThread->1 MsgStorageAppendResp Term:1 Log:1/11 @@ -139,7 +154,9 @@ stabilize 1->2 MsgApp Term:1 Log:1/11 Commit:11 1->3 MsgApp Term:1 Log:1/11 Commit:11 1->AppendThread MsgStorageAppend Term:1 Log:0/0 Commit:11 Vote:1 - 1->ApplyThread MsgStorageApply Term:0 Log:0/0 Entries:[1/11 EntryNormal ""] Responses:[ApplyThread->1 MsgStorageApplyResp Term:0 Log:0/0 Entries:[1/11 EntryNormal ""]] + 1->ApplyThread MsgStorageApply Term:0 Log:0/0 Entries:[1/11 EntryNormal ""] Responses:[ + ApplyThread->1 MsgStorageApplyResp Term:0 Log:0/0 Entries:[1/11 EntryNormal ""] + ] > 2 receiving messages 1->2 MsgApp Term:1 Log:1/11 Commit:11 > 3 receiving messages @@ -159,16 +176,24 @@ stabilize CommittedEntries: 1/11 EntryNormal "" Messages: - 2->AppendThread MsgStorageAppend Term:1 Log:0/0 Commit:11 Vote:1 Responses:[2->1 MsgAppResp Term:1 Log:0/11] - 2->ApplyThread MsgStorageApply Term:0 Log:0/0 Entries:[1/11 EntryNormal ""] Responses:[ApplyThread->2 MsgStorageApplyResp Term:0 Log:0/0 Entries:[1/11 EntryNormal ""]] + 2->AppendThread MsgStorageAppend Term:1 Log:0/0 Commit:11 Vote:1 Responses:[ + 2->1 MsgAppResp Term:1 Log:0/11 + ] + 2->ApplyThread MsgStorageApply Term:0 Log:0/0 Entries:[1/11 EntryNormal ""] Responses:[ + ApplyThread->2 MsgStorageApplyResp Term:0 Log:0/0 Entries:[1/11 EntryNormal ""] + ] > 3 handling Ready Ready MustSync=false: HardState Term:1 Vote:1 Commit:11 CommittedEntries: 1/11 EntryNormal "" Messages: - 3->AppendThread MsgStorageAppend Term:1 Log:0/0 Commit:11 Vote:1 Responses:[3->1 MsgAppResp Term:1 Log:0/11] - 3->ApplyThread MsgStorageApply Term:0 Log:0/0 Entries:[1/11 EntryNormal ""] Responses:[ApplyThread->3 MsgStorageApplyResp Term:0 Log:0/0 Entries:[1/11 EntryNormal ""]] + 3->AppendThread MsgStorageAppend Term:1 Log:0/0 Commit:11 Vote:1 Responses:[ + 3->1 MsgAppResp Term:1 Log:0/11 + ] + 3->ApplyThread MsgStorageApply Term:0 Log:0/0 Entries:[1/11 EntryNormal ""] Responses:[ + ApplyThread->3 MsgStorageApplyResp Term:0 Log:0/0 Entries:[1/11 EntryNormal ""] + ] > 1 receiving messages ApplyThread->1 MsgStorageApplyResp Term:0 Log:0/0 Entries:[1/11 EntryNormal ""] > 2 processing append thread @@ -212,7 +237,10 @@ process-ready 1 2 3 Messages: 1->2 MsgApp Term:1 Log:1/11 Commit:11 Entries:[1/12 EntryNormal "prop_1"] 1->3 MsgApp Term:1 Log:1/11 Commit:11 Entries:[1/12 EntryNormal "prop_1"] - 1->AppendThread MsgStorageAppend Term:0 Log:0/0 Entries:[1/12 EntryNormal "prop_1"] Responses:[1->1 MsgAppResp Term:1 Log:0/12, AppendThread->1 MsgStorageAppendResp Term:1 Log:1/12] + 1->AppendThread MsgStorageAppend Term:0 Log:0/0 Entries:[1/12 EntryNormal "prop_1"] Responses:[ + 1->1 MsgAppResp Term:1 Log:0/12 + AppendThread->1 MsgStorageAppendResp Term:1 Log:1/12 + ] > 2 handling Ready > 3 handling Ready @@ -232,13 +260,19 @@ process-ready 1 2 3 Entries: 1/12 EntryNormal "prop_1" Messages: - 2->AppendThread MsgStorageAppend Term:0 Log:0/0 Entries:[1/12 EntryNormal "prop_1"] Responses:[2->1 MsgAppResp Term:1 Log:0/12, AppendThread->2 MsgStorageAppendResp Term:1 Log:1/12] + 2->AppendThread MsgStorageAppend Term:0 Log:0/0 Entries:[1/12 EntryNormal "prop_1"] Responses:[ + 2->1 MsgAppResp Term:1 Log:0/12 + AppendThread->2 MsgStorageAppendResp Term:1 Log:1/12 + ] > 3 handling Ready Ready MustSync=true: Entries: 1/12 EntryNormal "prop_1" Messages: - 3->AppendThread MsgStorageAppend Term:0 Log:0/0 Entries:[1/12 EntryNormal "prop_1"] Responses:[3->1 MsgAppResp Term:1 Log:0/12, AppendThread->3 MsgStorageAppendResp Term:1 Log:1/12] + 3->AppendThread MsgStorageAppend Term:0 Log:0/0 Entries:[1/12 EntryNormal "prop_1"] Responses:[ + 3->1 MsgAppResp Term:1 Log:0/12 + AppendThread->3 MsgStorageAppendResp Term:1 Log:1/12 + ] propose 1 prop_2 ---- @@ -253,7 +287,10 @@ process-ready 1 2 3 Messages: 1->2 MsgApp Term:1 Log:1/12 Commit:11 Entries:[1/13 EntryNormal "prop_2"] 1->3 MsgApp Term:1 Log:1/12 Commit:11 Entries:[1/13 EntryNormal "prop_2"] - 1->AppendThread MsgStorageAppend Term:0 Log:0/0 Entries:[1/13 EntryNormal "prop_2"] Responses:[1->1 MsgAppResp Term:1 Log:0/13, AppendThread->1 MsgStorageAppendResp Term:1 Log:1/13] + 1->AppendThread MsgStorageAppend Term:0 Log:0/0 Entries:[1/13 EntryNormal "prop_2"] Responses:[ + 1->1 MsgAppResp Term:1 Log:0/13 + AppendThread->1 MsgStorageAppendResp Term:1 Log:1/13 + ] > 2 handling Ready > 3 handling Ready @@ -273,13 +310,19 @@ process-ready 1 2 3 Entries: 1/13 EntryNormal "prop_2" Messages: - 2->AppendThread MsgStorageAppend Term:0 Log:0/0 Entries:[1/13 EntryNormal "prop_2"] Responses:[2->1 MsgAppResp Term:1 Log:0/13, AppendThread->2 MsgStorageAppendResp Term:1 Log:1/13] + 2->AppendThread MsgStorageAppend Term:0 Log:0/0 Entries:[1/13 EntryNormal "prop_2"] Responses:[ + 2->1 MsgAppResp Term:1 Log:0/13 + AppendThread->2 MsgStorageAppendResp Term:1 Log:1/13 + ] > 3 handling Ready Ready MustSync=true: Entries: 1/13 EntryNormal "prop_2" Messages: - 3->AppendThread MsgStorageAppend Term:0 Log:0/0 Entries:[1/13 EntryNormal "prop_2"] Responses:[3->1 MsgAppResp Term:1 Log:0/13, AppendThread->3 MsgStorageAppendResp Term:1 Log:1/13] + 3->AppendThread MsgStorageAppend Term:0 Log:0/0 Entries:[1/13 EntryNormal "prop_2"] Responses:[ + 3->1 MsgAppResp Term:1 Log:0/13 + AppendThread->3 MsgStorageAppendResp Term:1 Log:1/13 + ] process-append-thread 1 2 3 ---- @@ -329,8 +372,13 @@ process-ready 1 2 3 1->3 MsgApp Term:1 Log:1/13 Commit:12 1->2 MsgApp Term:1 Log:1/13 Commit:12 Entries:[1/14 EntryNormal "prop_3"] 1->3 MsgApp Term:1 Log:1/13 Commit:12 Entries:[1/14 EntryNormal "prop_3"] - 1->AppendThread MsgStorageAppend Term:1 Log:0/0 Commit:12 Vote:1 Entries:[1/14 EntryNormal "prop_3"] Responses:[1->1 MsgAppResp Term:1 Log:0/14, AppendThread->1 MsgStorageAppendResp Term:1 Log:1/14] - 1->ApplyThread MsgStorageApply Term:0 Log:0/0 Entries:[1/12 EntryNormal "prop_1"] Responses:[ApplyThread->1 MsgStorageApplyResp Term:0 Log:0/0 Entries:[1/12 EntryNormal "prop_1"]] + 1->AppendThread MsgStorageAppend Term:1 Log:0/0 Commit:12 Vote:1 Entries:[1/14 EntryNormal "prop_3"] Responses:[ + 1->1 MsgAppResp Term:1 Log:0/14 + AppendThread->1 MsgStorageAppendResp Term:1 Log:1/14 + ] + 1->ApplyThread MsgStorageApply Term:0 Log:0/0 Entries:[1/12 EntryNormal "prop_1"] Responses:[ + ApplyThread->1 MsgStorageApplyResp Term:0 Log:0/0 Entries:[1/12 EntryNormal "prop_1"] + ] > 2 handling Ready > 3 handling Ready @@ -355,8 +403,14 @@ process-ready 1 2 3 CommittedEntries: 1/12 EntryNormal "prop_1" Messages: - 2->AppendThread MsgStorageAppend Term:1 Log:0/0 Commit:12 Vote:1 Entries:[1/14 EntryNormal "prop_3"] Responses:[2->1 MsgAppResp Term:1 Log:0/13, 2->1 MsgAppResp Term:1 Log:0/14, AppendThread->2 MsgStorageAppendResp Term:1 Log:1/14] - 2->ApplyThread MsgStorageApply Term:0 Log:0/0 Entries:[1/12 EntryNormal "prop_1"] Responses:[ApplyThread->2 MsgStorageApplyResp Term:0 Log:0/0 Entries:[1/12 EntryNormal "prop_1"]] + 2->AppendThread MsgStorageAppend Term:1 Log:0/0 Commit:12 Vote:1 Entries:[1/14 EntryNormal "prop_3"] Responses:[ + 2->1 MsgAppResp Term:1 Log:0/13 + 2->1 MsgAppResp Term:1 Log:0/14 + AppendThread->2 MsgStorageAppendResp Term:1 Log:1/14 + ] + 2->ApplyThread MsgStorageApply Term:0 Log:0/0 Entries:[1/12 EntryNormal "prop_1"] Responses:[ + ApplyThread->2 MsgStorageApplyResp Term:0 Log:0/0 Entries:[1/12 EntryNormal "prop_1"] + ] > 3 handling Ready Ready MustSync=true: HardState Term:1 Vote:1 Commit:12 @@ -365,8 +419,14 @@ process-ready 1 2 3 CommittedEntries: 1/12 EntryNormal "prop_1" Messages: - 3->AppendThread MsgStorageAppend Term:1 Log:0/0 Commit:12 Vote:1 Entries:[1/14 EntryNormal "prop_3"] Responses:[3->1 MsgAppResp Term:1 Log:0/13, 3->1 MsgAppResp Term:1 Log:0/14, AppendThread->3 MsgStorageAppendResp Term:1 Log:1/14] - 3->ApplyThread MsgStorageApply Term:0 Log:0/0 Entries:[1/12 EntryNormal "prop_1"] Responses:[ApplyThread->3 MsgStorageApplyResp Term:0 Log:0/0 Entries:[1/12 EntryNormal "prop_1"]] + 3->AppendThread MsgStorageAppend Term:1 Log:0/0 Commit:12 Vote:1 Entries:[1/14 EntryNormal "prop_3"] Responses:[ + 3->1 MsgAppResp Term:1 Log:0/13 + 3->1 MsgAppResp Term:1 Log:0/14 + AppendThread->3 MsgStorageAppendResp Term:1 Log:1/14 + ] + 3->ApplyThread MsgStorageApply Term:0 Log:0/0 Entries:[1/12 EntryNormal "prop_1"] Responses:[ + ApplyThread->3 MsgStorageApplyResp Term:0 Log:0/0 Entries:[1/12 EntryNormal "prop_1"] + ] process-append-thread 1 2 3 ---- @@ -416,8 +476,13 @@ process-ready 1 2 3 1->3 MsgApp Term:1 Log:1/14 Commit:13 1->2 MsgApp Term:1 Log:1/14 Commit:13 Entries:[1/15 EntryNormal "prop_4"] 1->3 MsgApp Term:1 Log:1/14 Commit:13 Entries:[1/15 EntryNormal "prop_4"] - 1->AppendThread MsgStorageAppend Term:1 Log:0/0 Commit:13 Vote:1 Entries:[1/15 EntryNormal "prop_4"] Responses:[1->1 MsgAppResp Term:1 Log:0/15, AppendThread->1 MsgStorageAppendResp Term:1 Log:1/15] - 1->ApplyThread MsgStorageApply Term:0 Log:0/0 Entries:[1/13 EntryNormal "prop_2"] Responses:[ApplyThread->1 MsgStorageApplyResp Term:0 Log:0/0 Entries:[1/13 EntryNormal "prop_2"]] + 1->AppendThread MsgStorageAppend Term:1 Log:0/0 Commit:13 Vote:1 Entries:[1/15 EntryNormal "prop_4"] Responses:[ + 1->1 MsgAppResp Term:1 Log:0/15 + AppendThread->1 MsgStorageAppendResp Term:1 Log:1/15 + ] + 1->ApplyThread MsgStorageApply Term:0 Log:0/0 Entries:[1/13 EntryNormal "prop_2"] Responses:[ + ApplyThread->1 MsgStorageApplyResp Term:0 Log:0/0 Entries:[1/13 EntryNormal "prop_2"] + ] > 2 handling Ready > 3 handling Ready @@ -442,8 +507,14 @@ process-ready 1 2 3 CommittedEntries: 1/13 EntryNormal "prop_2" Messages: - 2->AppendThread MsgStorageAppend Term:1 Log:0/0 Commit:13 Vote:1 Entries:[1/15 EntryNormal "prop_4"] Responses:[2->1 MsgAppResp Term:1 Log:0/14, 2->1 MsgAppResp Term:1 Log:0/15, AppendThread->2 MsgStorageAppendResp Term:1 Log:1/15] - 2->ApplyThread MsgStorageApply Term:0 Log:0/0 Entries:[1/13 EntryNormal "prop_2"] Responses:[ApplyThread->2 MsgStorageApplyResp Term:0 Log:0/0 Entries:[1/13 EntryNormal "prop_2"]] + 2->AppendThread MsgStorageAppend Term:1 Log:0/0 Commit:13 Vote:1 Entries:[1/15 EntryNormal "prop_4"] Responses:[ + 2->1 MsgAppResp Term:1 Log:0/14 + 2->1 MsgAppResp Term:1 Log:0/15 + AppendThread->2 MsgStorageAppendResp Term:1 Log:1/15 + ] + 2->ApplyThread MsgStorageApply Term:0 Log:0/0 Entries:[1/13 EntryNormal "prop_2"] Responses:[ + ApplyThread->2 MsgStorageApplyResp Term:0 Log:0/0 Entries:[1/13 EntryNormal "prop_2"] + ] > 3 handling Ready Ready MustSync=true: HardState Term:1 Vote:1 Commit:13 @@ -452,8 +523,14 @@ process-ready 1 2 3 CommittedEntries: 1/13 EntryNormal "prop_2" Messages: - 3->AppendThread MsgStorageAppend Term:1 Log:0/0 Commit:13 Vote:1 Entries:[1/15 EntryNormal "prop_4"] Responses:[3->1 MsgAppResp Term:1 Log:0/14, 3->1 MsgAppResp Term:1 Log:0/15, AppendThread->3 MsgStorageAppendResp Term:1 Log:1/15] - 3->ApplyThread MsgStorageApply Term:0 Log:0/0 Entries:[1/13 EntryNormal "prop_2"] Responses:[ApplyThread->3 MsgStorageApplyResp Term:0 Log:0/0 Entries:[1/13 EntryNormal "prop_2"]] + 3->AppendThread MsgStorageAppend Term:1 Log:0/0 Commit:13 Vote:1 Entries:[1/15 EntryNormal "prop_4"] Responses:[ + 3->1 MsgAppResp Term:1 Log:0/14 + 3->1 MsgAppResp Term:1 Log:0/15 + AppendThread->3 MsgStorageAppendResp Term:1 Log:1/15 + ] + 3->ApplyThread MsgStorageApply Term:0 Log:0/0 Entries:[1/13 EntryNormal "prop_2"] Responses:[ + ApplyThread->3 MsgStorageApplyResp Term:0 Log:0/0 Entries:[1/13 EntryNormal "prop_2"] + ] process-append-thread 1 2 3 ---- @@ -520,8 +597,12 @@ process-ready 1 2 3 Messages: 1->2 MsgApp Term:1 Log:1/15 Commit:14 1->3 MsgApp Term:1 Log:1/15 Commit:14 - 1->AppendThread MsgStorageAppend Term:1 Log:0/0 Commit:14 Vote:1 Responses:[AppendThread->1 MsgStorageAppendResp Term:1 Log:1/15] - 1->ApplyThread MsgStorageApply Term:0 Log:0/0 Entries:[1/14 EntryNormal "prop_3"] Responses:[ApplyThread->1 MsgStorageApplyResp Term:0 Log:0/0 Entries:[1/14 EntryNormal "prop_3"]] + 1->AppendThread MsgStorageAppend Term:1 Log:0/0 Commit:14 Vote:1 Responses:[ + AppendThread->1 MsgStorageAppendResp Term:1 Log:1/15 + ] + 1->ApplyThread MsgStorageApply Term:0 Log:0/0 Entries:[1/14 EntryNormal "prop_3"] Responses:[ + ApplyThread->1 MsgStorageApplyResp Term:0 Log:0/0 Entries:[1/14 EntryNormal "prop_3"] + ] > 2 handling Ready > 3 handling Ready @@ -542,16 +623,26 @@ process-ready 1 2 3 CommittedEntries: 1/14 EntryNormal "prop_3" Messages: - 2->AppendThread MsgStorageAppend Term:1 Log:0/0 Commit:14 Vote:1 Responses:[2->1 MsgAppResp Term:1 Log:0/15, AppendThread->2 MsgStorageAppendResp Term:1 Log:1/15] - 2->ApplyThread MsgStorageApply Term:0 Log:0/0 Entries:[1/14 EntryNormal "prop_3"] Responses:[ApplyThread->2 MsgStorageApplyResp Term:0 Log:0/0 Entries:[1/14 EntryNormal "prop_3"]] + 2->AppendThread MsgStorageAppend Term:1 Log:0/0 Commit:14 Vote:1 Responses:[ + 2->1 MsgAppResp Term:1 Log:0/15 + AppendThread->2 MsgStorageAppendResp Term:1 Log:1/15 + ] + 2->ApplyThread MsgStorageApply Term:0 Log:0/0 Entries:[1/14 EntryNormal "prop_3"] Responses:[ + ApplyThread->2 MsgStorageApplyResp Term:0 Log:0/0 Entries:[1/14 EntryNormal "prop_3"] + ] > 3 handling Ready Ready MustSync=false: HardState Term:1 Vote:1 Commit:14 CommittedEntries: 1/14 EntryNormal "prop_3" Messages: - 3->AppendThread MsgStorageAppend Term:1 Log:0/0 Commit:14 Vote:1 Responses:[3->1 MsgAppResp Term:1 Log:0/15, AppendThread->3 MsgStorageAppendResp Term:1 Log:1/15] - 3->ApplyThread MsgStorageApply Term:0 Log:0/0 Entries:[1/14 EntryNormal "prop_3"] Responses:[ApplyThread->3 MsgStorageApplyResp Term:0 Log:0/0 Entries:[1/14 EntryNormal "prop_3"]] + 3->AppendThread MsgStorageAppend Term:1 Log:0/0 Commit:14 Vote:1 Responses:[ + 3->1 MsgAppResp Term:1 Log:0/15 + AppendThread->3 MsgStorageAppendResp Term:1 Log:1/15 + ] + 3->ApplyThread MsgStorageApply Term:0 Log:0/0 Entries:[1/14 EntryNormal "prop_3"] Responses:[ + ApplyThread->3 MsgStorageApplyResp Term:0 Log:0/0 Entries:[1/14 EntryNormal "prop_3"] + ] process-append-thread 1 2 3 ---- @@ -619,7 +710,9 @@ process-ready 1 2 3 1->2 MsgApp Term:1 Log:1/15 Commit:15 1->3 MsgApp Term:1 Log:1/15 Commit:15 1->AppendThread MsgStorageAppend Term:1 Log:0/0 Commit:15 Vote:1 - 1->ApplyThread MsgStorageApply Term:0 Log:0/0 Entries:[1/15 EntryNormal "prop_4"] Responses:[ApplyThread->1 MsgStorageApplyResp Term:0 Log:0/0 Entries:[1/15 EntryNormal "prop_4"]] + 1->ApplyThread MsgStorageApply Term:0 Log:0/0 Entries:[1/15 EntryNormal "prop_4"] Responses:[ + ApplyThread->1 MsgStorageApplyResp Term:0 Log:0/0 Entries:[1/15 EntryNormal "prop_4"] + ] > 2 handling Ready > 3 handling Ready @@ -640,16 +733,24 @@ process-ready 1 2 3 CommittedEntries: 1/15 EntryNormal "prop_4" Messages: - 2->AppendThread MsgStorageAppend Term:1 Log:0/0 Commit:15 Vote:1 Responses:[2->1 MsgAppResp Term:1 Log:0/15] - 2->ApplyThread MsgStorageApply Term:0 Log:0/0 Entries:[1/15 EntryNormal "prop_4"] Responses:[ApplyThread->2 MsgStorageApplyResp Term:0 Log:0/0 Entries:[1/15 EntryNormal "prop_4"]] + 2->AppendThread MsgStorageAppend Term:1 Log:0/0 Commit:15 Vote:1 Responses:[ + 2->1 MsgAppResp Term:1 Log:0/15 + ] + 2->ApplyThread MsgStorageApply Term:0 Log:0/0 Entries:[1/15 EntryNormal "prop_4"] Responses:[ + ApplyThread->2 MsgStorageApplyResp Term:0 Log:0/0 Entries:[1/15 EntryNormal "prop_4"] + ] > 3 handling Ready Ready MustSync=false: HardState Term:1 Vote:1 Commit:15 CommittedEntries: 1/15 EntryNormal "prop_4" Messages: - 3->AppendThread MsgStorageAppend Term:1 Log:0/0 Commit:15 Vote:1 Responses:[3->1 MsgAppResp Term:1 Log:0/15] - 3->ApplyThread MsgStorageApply Term:0 Log:0/0 Entries:[1/15 EntryNormal "prop_4"] Responses:[ApplyThread->3 MsgStorageApplyResp Term:0 Log:0/0 Entries:[1/15 EntryNormal "prop_4"]] + 3->AppendThread MsgStorageAppend Term:1 Log:0/0 Commit:15 Vote:1 Responses:[ + 3->1 MsgAppResp Term:1 Log:0/15 + ] + 3->ApplyThread MsgStorageApply Term:0 Log:0/0 Entries:[1/15 EntryNormal "prop_4"] Responses:[ + ApplyThread->3 MsgStorageApplyResp Term:0 Log:0/0 Entries:[1/15 EntryNormal "prop_4"] + ] process-append-thread 2 3 ---- diff --git a/testdata/async_storage_writes_append_aba_race.txt b/testdata/async_storage_writes_append_aba_race.txt index 4b68330f..83964fe7 100644 --- a/testdata/async_storage_writes_append_aba_race.txt +++ b/testdata/async_storage_writes_append_aba_race.txt @@ -42,7 +42,10 @@ Messages: 2->5 MsgApp Term:1 Log:1/11 Commit:11 Entries:[1/12 EntryNormal "init_prop"] 2->6 MsgApp Term:1 Log:1/11 Commit:11 Entries:[1/12 EntryNormal "init_prop"] 2->7 MsgApp Term:1 Log:1/11 Commit:11 Entries:[1/12 EntryNormal "init_prop"] -2->AppendThread MsgStorageAppend Term:0 Log:0/0 Entries:[1/12 EntryNormal "init_prop"] Responses:[2->2 MsgAppResp Term:1 Log:0/12, AppendThread->2 MsgStorageAppendResp Term:1 Log:1/12] +2->AppendThread MsgStorageAppend Term:0 Log:0/0 Entries:[1/12 EntryNormal "init_prop"] Responses:[ + 2->2 MsgAppResp Term:1 Log:0/12 + AppendThread->2 MsgStorageAppendResp Term:1 Log:1/12 +] deliver-msgs 1 drop=(3,4,5,6,7) ---- @@ -61,7 +64,10 @@ Ready MustSync=true: Entries: 1/12 EntryNormal "init_prop" Messages: -1->AppendThread MsgStorageAppend Term:0 Log:0/0 Entries:[1/12 EntryNormal "init_prop"] Responses:[1->2 MsgAppResp Term:1 Log:0/12, AppendThread->1 MsgStorageAppendResp Term:1 Log:1/12] +1->AppendThread MsgStorageAppend Term:0 Log:0/0 Entries:[1/12 EntryNormal "init_prop"] Responses:[ + 1->2 MsgAppResp Term:1 Log:0/12 + AppendThread->1 MsgStorageAppendResp Term:1 Log:1/12 +] # Step 4: node 3 becomes the leader after getting a vote from nodes 4, 5, and 6. @@ -88,7 +94,9 @@ Messages: 3->5 MsgVote Term:2 Log:1/11 3->6 MsgVote Term:2 Log:1/11 3->7 MsgVote Term:2 Log:1/11 -3->AppendThread MsgStorageAppend Term:2 Log:0/0 Commit:11 Vote:3 Responses:[3->3 MsgVoteResp Term:2 Log:0/0] +3->AppendThread MsgStorageAppend Term:2 Log:0/0 Commit:11 Vote:3 Responses:[ + 3->3 MsgVoteResp Term:2 Log:0/0 +] deliver-msgs 4 5 6 ---- @@ -112,19 +120,25 @@ process-ready 4 5 6 Lead:0 State:StateFollower HardState Term:2 Vote:3 Commit:11 Messages: - 4->AppendThread MsgStorageAppend Term:2 Log:0/0 Commit:11 Vote:3 Responses:[4->3 MsgVoteResp Term:2 Log:0/0] + 4->AppendThread MsgStorageAppend Term:2 Log:0/0 Commit:11 Vote:3 Responses:[ + 4->3 MsgVoteResp Term:2 Log:0/0 + ] > 5 handling Ready Ready MustSync=true: Lead:0 State:StateFollower HardState Term:2 Vote:3 Commit:11 Messages: - 5->AppendThread MsgStorageAppend Term:2 Log:0/0 Commit:11 Vote:3 Responses:[5->3 MsgVoteResp Term:2 Log:0/0] + 5->AppendThread MsgStorageAppend Term:2 Log:0/0 Commit:11 Vote:3 Responses:[ + 5->3 MsgVoteResp Term:2 Log:0/0 + ] > 6 handling Ready Ready MustSync=true: Lead:0 State:StateFollower HardState Term:2 Vote:3 Commit:11 Messages: - 6->AppendThread MsgStorageAppend Term:2 Log:0/0 Commit:11 Vote:3 Responses:[6->3 MsgVoteResp Term:2 Log:0/0] + 6->AppendThread MsgStorageAppend Term:2 Log:0/0 Commit:11 Vote:3 Responses:[ + 6->3 MsgVoteResp Term:2 Log:0/0 + ] process-append-thread 3 4 5 6 ---- @@ -183,7 +197,10 @@ Messages: 3->5 MsgApp Term:2 Log:1/11 Commit:11 Entries:[2/12 EntryNormal ""] 3->6 MsgApp Term:2 Log:1/11 Commit:11 Entries:[2/12 EntryNormal ""] 3->7 MsgApp Term:2 Log:1/11 Commit:11 Entries:[2/12 EntryNormal ""] -3->AppendThread MsgStorageAppend Term:0 Log:0/0 Entries:[2/12 EntryNormal ""] Responses:[3->3 MsgAppResp Term:2 Log:0/12, AppendThread->3 MsgStorageAppendResp Term:2 Log:2/12] +3->AppendThread MsgStorageAppend Term:0 Log:0/0 Entries:[2/12 EntryNormal ""] Responses:[ + 3->3 MsgAppResp Term:2 Log:0/12 + AppendThread->3 MsgStorageAppendResp Term:2 Log:2/12 +] deliver-msgs 1 drop=(2,4,5,6,7) ---- @@ -210,7 +227,11 @@ HardState Term:2 Commit:11 Entries: 2/12 EntryNormal "" Messages: -1->AppendThread MsgStorageAppend Term:2 Log:0/0 Commit:11 Entries:[2/12 EntryNormal ""] Responses:[1->3 MsgVoteResp Term:2 Log:0/0 Rejected (Hint: 0), 1->3 MsgAppResp Term:2 Log:0/12, AppendThread->1 MsgStorageAppendResp Term:2 Log:2/12] +1->AppendThread MsgStorageAppend Term:2 Log:0/0 Commit:11 Entries:[2/12 EntryNormal ""] Responses:[ + 1->3 MsgVoteResp Term:2 Log:0/0 Rejected (Hint: 0) + 1->3 MsgAppResp Term:2 Log:0/12 + AppendThread->1 MsgStorageAppendResp Term:2 Log:2/12 +] # Step 6: node 3 crashes and node 4 becomes leader getting the vote from 5, 6, and 7. @@ -237,7 +258,9 @@ Messages: 4->5 MsgVote Term:3 Log:1/11 4->6 MsgVote Term:3 Log:1/11 4->7 MsgVote Term:3 Log:1/11 -4->AppendThread MsgStorageAppend Term:3 Log:0/0 Commit:11 Vote:4 Responses:[4->4 MsgVoteResp Term:3 Log:0/0] +4->AppendThread MsgStorageAppend Term:3 Log:0/0 Commit:11 Vote:4 Responses:[ + 4->4 MsgVoteResp Term:3 Log:0/0 +] deliver-msgs 5 6 7 ---- @@ -260,18 +283,24 @@ process-ready 5 6 7 Ready MustSync=true: HardState Term:3 Vote:4 Commit:11 Messages: - 5->AppendThread MsgStorageAppend Term:3 Log:0/0 Commit:11 Vote:4 Responses:[5->4 MsgVoteResp Term:3 Log:0/0] + 5->AppendThread MsgStorageAppend Term:3 Log:0/0 Commit:11 Vote:4 Responses:[ + 5->4 MsgVoteResp Term:3 Log:0/0 + ] > 6 handling Ready Ready MustSync=true: HardState Term:3 Vote:4 Commit:11 Messages: - 6->AppendThread MsgStorageAppend Term:3 Log:0/0 Commit:11 Vote:4 Responses:[6->4 MsgVoteResp Term:3 Log:0/0] + 6->AppendThread MsgStorageAppend Term:3 Log:0/0 Commit:11 Vote:4 Responses:[ + 6->4 MsgVoteResp Term:3 Log:0/0 + ] > 7 handling Ready Ready MustSync=true: Lead:0 State:StateFollower HardState Term:3 Vote:4 Commit:11 Messages: - 7->AppendThread MsgStorageAppend Term:3 Log:0/0 Commit:11 Vote:4 Responses:[7->4 MsgVoteResp Term:3 Log:0/0] + 7->AppendThread MsgStorageAppend Term:3 Log:0/0 Commit:11 Vote:4 Responses:[ + 7->4 MsgVoteResp Term:3 Log:0/0 + ] process-append-thread 4 5 6 7 ---- @@ -325,7 +354,10 @@ Messages: 4->5 MsgApp Term:3 Log:1/11 Commit:11 Entries:[3/12 EntryNormal ""] 4->6 MsgApp Term:3 Log:1/11 Commit:11 Entries:[3/12 EntryNormal ""] 4->7 MsgApp Term:3 Log:1/11 Commit:11 Entries:[3/12 EntryNormal ""] -4->AppendThread MsgStorageAppend Term:0 Log:0/0 Entries:[3/12 EntryNormal ""] Responses:[4->4 MsgAppResp Term:3 Log:0/12, AppendThread->4 MsgStorageAppendResp Term:3 Log:3/12] +4->AppendThread MsgStorageAppend Term:0 Log:0/0 Entries:[3/12 EntryNormal ""] Responses:[ + 4->4 MsgAppResp Term:3 Log:0/12 + AppendThread->4 MsgStorageAppendResp Term:3 Log:3/12 +] # Step 7: before the new entries reach node 1, it hears of the term change # through a heartbeat and persists the new term. Node 1 then receives these @@ -366,7 +398,9 @@ Lead:4 State:StateFollower HardState Term:3 Commit:11 Messages: 1->4 MsgHeartbeatResp Term:3 Log:0/0 -1->AppendThread MsgStorageAppend Term:3 Log:0/0 Commit:11 Responses:[AppendThread->1 MsgStorageAppendResp Term:3 Log:2/12] +1->AppendThread MsgStorageAppend Term:3 Log:0/0 Commit:11 Responses:[ + AppendThread->1 MsgStorageAppendResp Term:3 Log:2/12 +] deliver-msgs 4 ---- @@ -390,7 +424,10 @@ Ready MustSync=true: Entries: 3/12 EntryNormal "" Messages: -1->AppendThread MsgStorageAppend Term:0 Log:0/0 Entries:[3/12 EntryNormal ""] Responses:[1->4 MsgAppResp Term:3 Log:0/12, AppendThread->1 MsgStorageAppendResp Term:3 Log:3/12] +1->AppendThread MsgStorageAppend Term:0 Log:0/0 Entries:[3/12 EntryNormal ""] Responses:[ + 1->4 MsgAppResp Term:3 Log:0/12 + AppendThread->1 MsgStorageAppendResp Term:3 Log:3/12 +] # Step 8: The asynchronous log appends from the first Ready complete and the # MsgStorageAppendResp is returned to the raft node state machine. A decision diff --git a/testdata/campaign_learner_must_vote.txt b/testdata/campaign_learner_must_vote.txt index 85617df3..d05de374 100644 --- a/testdata/campaign_learner_must_vote.txt +++ b/testdata/campaign_learner_must_vote.txt @@ -117,9 +117,15 @@ stabilize 2 3 > 2 handling Ready Ready MustSync=false: Messages: - 2->3 MsgApp Term:2 Log:1/3 Commit:4 Entries:[1/4 EntryConfChangeV2 v3, 2/5 EntryNormal ""] + 2->3 MsgApp Term:2 Log:1/3 Commit:4 Entries:[ + 1/4 EntryConfChangeV2 v3 + 2/5 EntryNormal "" + ] > 3 receiving messages - 2->3 MsgApp Term:2 Log:1/3 Commit:4 Entries:[1/4 EntryConfChangeV2 v3, 2/5 EntryNormal ""] + 2->3 MsgApp Term:2 Log:1/3 Commit:4 Entries:[ + 1/4 EntryConfChangeV2 v3 + 2/5 EntryNormal "" + ] > 3 handling Ready Ready MustSync=true: HardState Term:2 Vote:2 Commit:4 diff --git a/testdata/confchange_v1_add_single.txt b/testdata/confchange_v1_add_single.txt index 0419d28d..e54a183f 100644 --- a/testdata/confchange_v1_add_single.txt +++ b/testdata/confchange_v1_add_single.txt @@ -76,9 +76,11 @@ stabilize > 1 handling Ready Ready MustSync=false: Messages: - 1->2 MsgSnap Term:1 Log:0/0 Snapshot: Index:4 Term:1 ConfState:Voters:[1 2] VotersOutgoing:[] Learners:[] LearnersNext:[] AutoLeave:false + 1->2 MsgSnap Term:1 Log:0/0 + Snapshot: Index:4 Term:1 ConfState:Voters:[1 2] VotersOutgoing:[] Learners:[] LearnersNext:[] AutoLeave:false > 2 receiving messages - 1->2 MsgSnap Term:1 Log:0/0 Snapshot: Index:4 Term:1 ConfState:Voters:[1 2] VotersOutgoing:[] Learners:[] LearnersNext:[] AutoLeave:false + 1->2 MsgSnap Term:1 Log:0/0 + Snapshot: Index:4 Term:1 ConfState:Voters:[1 2] VotersOutgoing:[] Learners:[] LearnersNext:[] AutoLeave:false INFO log [committed=0, applied=0, applying=0, unstable.offset=1, unstable.offsetInProgress=1, len(unstable.Entries)=0] starts to restore snapshot [index: 4, term: 1] INFO 2 switched to configuration voters=(1 2) INFO 2 [commit: 4, lastindex: 4, lastterm: 1] restored snapshot [index: 4, term: 1] diff --git a/testdata/confchange_v2_add_double_auto.txt b/testdata/confchange_v2_add_double_auto.txt index 5cf4f24c..bf1dfcbe 100644 --- a/testdata/confchange_v2_add_double_auto.txt +++ b/testdata/confchange_v2_add_double_auto.txt @@ -99,9 +99,11 @@ stabilize 1 2 > 1 handling Ready Ready MustSync=false: Messages: - 1->2 MsgSnap Term:1 Log:0/0 Snapshot: Index:4 Term:1 ConfState:Voters:[1 2 3] VotersOutgoing:[1] Learners:[] LearnersNext:[] AutoLeave:true + 1->2 MsgSnap Term:1 Log:0/0 + Snapshot: Index:4 Term:1 ConfState:Voters:[1 2 3] VotersOutgoing:[1] Learners:[] LearnersNext:[] AutoLeave:true > 2 receiving messages - 1->2 MsgSnap Term:1 Log:0/0 Snapshot: Index:4 Term:1 ConfState:Voters:[1 2 3] VotersOutgoing:[1] Learners:[] LearnersNext:[] AutoLeave:true + 1->2 MsgSnap Term:1 Log:0/0 + Snapshot: Index:4 Term:1 ConfState:Voters:[1 2 3] VotersOutgoing:[1] Learners:[] LearnersNext:[] AutoLeave:true INFO log [committed=0, applied=0, applying=0, unstable.offset=1, unstable.offsetInProgress=1, len(unstable.Entries)=0] starts to restore snapshot [index: 4, term: 1] INFO 2 switched to configuration voters=(1 2 3)&&(1) autoleave INFO 2 [commit: 4, lastindex: 4, lastterm: 1] restored snapshot [index: 4, term: 1] @@ -173,9 +175,11 @@ stabilize 1 3 > 1 handling Ready Ready MustSync=false: Messages: - 1->3 MsgSnap Term:1 Log:0/0 Snapshot: Index:5 Term:1 ConfState:Voters:[1 2 3] VotersOutgoing:[] Learners:[] LearnersNext:[] AutoLeave:false + 1->3 MsgSnap Term:1 Log:0/0 + Snapshot: Index:5 Term:1 ConfState:Voters:[1 2 3] VotersOutgoing:[] Learners:[] LearnersNext:[] AutoLeave:false > 3 receiving messages - 1->3 MsgSnap Term:1 Log:0/0 Snapshot: Index:5 Term:1 ConfState:Voters:[1 2 3] VotersOutgoing:[] Learners:[] LearnersNext:[] AutoLeave:false + 1->3 MsgSnap Term:1 Log:0/0 + Snapshot: Index:5 Term:1 ConfState:Voters:[1 2 3] VotersOutgoing:[] Learners:[] LearnersNext:[] AutoLeave:false INFO log [committed=0, applied=0, applying=0, unstable.offset=1, unstable.offsetInProgress=1, len(unstable.Entries)=0] starts to restore snapshot [index: 5, term: 1] INFO 3 switched to configuration voters=(1 2 3) INFO 3 [commit: 5, lastindex: 5, lastterm: 1] restored snapshot [index: 5, term: 1] diff --git a/testdata/confchange_v2_add_double_implicit.txt b/testdata/confchange_v2_add_double_implicit.txt index 81b3f0de..536d66b8 100644 --- a/testdata/confchange_v2_add_double_implicit.txt +++ b/testdata/confchange_v2_add_double_implicit.txt @@ -82,9 +82,11 @@ stabilize 1 2 > 1 handling Ready Ready MustSync=false: Messages: - 1->2 MsgSnap Term:1 Log:0/0 Snapshot: Index:4 Term:1 ConfState:Voters:[1 2] VotersOutgoing:[1] Learners:[] LearnersNext:[] AutoLeave:true + 1->2 MsgSnap Term:1 Log:0/0 + Snapshot: Index:4 Term:1 ConfState:Voters:[1 2] VotersOutgoing:[1] Learners:[] LearnersNext:[] AutoLeave:true > 2 receiving messages - 1->2 MsgSnap Term:1 Log:0/0 Snapshot: Index:4 Term:1 ConfState:Voters:[1 2] VotersOutgoing:[1] Learners:[] LearnersNext:[] AutoLeave:true + 1->2 MsgSnap Term:1 Log:0/0 + Snapshot: Index:4 Term:1 ConfState:Voters:[1 2] VotersOutgoing:[1] Learners:[] LearnersNext:[] AutoLeave:true INFO log [committed=0, applied=0, applying=0, unstable.offset=1, unstable.offsetInProgress=1, len(unstable.Entries)=0] starts to restore snapshot [index: 4, term: 1] INFO 2 switched to configuration voters=(1 2)&&(1) autoleave INFO 2 [commit: 4, lastindex: 4, lastterm: 1] restored snapshot [index: 4, term: 1] diff --git a/testdata/confchange_v2_add_single_auto.txt b/testdata/confchange_v2_add_single_auto.txt index fe127bf5..1c487da8 100644 --- a/testdata/confchange_v2_add_single_auto.txt +++ b/testdata/confchange_v2_add_single_auto.txt @@ -77,9 +77,11 @@ stabilize > 1 handling Ready Ready MustSync=false: Messages: - 1->2 MsgSnap Term:1 Log:0/0 Snapshot: Index:4 Term:1 ConfState:Voters:[1 2] VotersOutgoing:[] Learners:[] LearnersNext:[] AutoLeave:false + 1->2 MsgSnap Term:1 Log:0/0 + Snapshot: Index:4 Term:1 ConfState:Voters:[1 2] VotersOutgoing:[] Learners:[] LearnersNext:[] AutoLeave:false > 2 receiving messages - 1->2 MsgSnap Term:1 Log:0/0 Snapshot: Index:4 Term:1 ConfState:Voters:[1 2] VotersOutgoing:[] Learners:[] LearnersNext:[] AutoLeave:false + 1->2 MsgSnap Term:1 Log:0/0 + Snapshot: Index:4 Term:1 ConfState:Voters:[1 2] VotersOutgoing:[] Learners:[] LearnersNext:[] AutoLeave:false INFO log [committed=0, applied=0, applying=0, unstable.offset=1, unstable.offsetInProgress=1, len(unstable.Entries)=0] starts to restore snapshot [index: 4, term: 1] INFO 2 switched to configuration voters=(1 2) INFO 2 [commit: 4, lastindex: 4, lastterm: 1] restored snapshot [index: 4, term: 1] diff --git a/testdata/confchange_v2_add_single_explicit.txt b/testdata/confchange_v2_add_single_explicit.txt index c51900f0..123cd17a 100644 --- a/testdata/confchange_v2_add_single_explicit.txt +++ b/testdata/confchange_v2_add_single_explicit.txt @@ -77,9 +77,11 @@ stabilize 1 2 > 1 handling Ready Ready MustSync=false: Messages: - 1->2 MsgSnap Term:1 Log:0/0 Snapshot: Index:4 Term:1 ConfState:Voters:[1 2] VotersOutgoing:[1] Learners:[] LearnersNext:[] AutoLeave:false + 1->2 MsgSnap Term:1 Log:0/0 + Snapshot: Index:4 Term:1 ConfState:Voters:[1 2] VotersOutgoing:[1] Learners:[] LearnersNext:[] AutoLeave:false > 2 receiving messages - 1->2 MsgSnap Term:1 Log:0/0 Snapshot: Index:4 Term:1 ConfState:Voters:[1 2] VotersOutgoing:[1] Learners:[] LearnersNext:[] AutoLeave:false + 1->2 MsgSnap Term:1 Log:0/0 + Snapshot: Index:4 Term:1 ConfState:Voters:[1 2] VotersOutgoing:[1] Learners:[] LearnersNext:[] AutoLeave:false INFO log [committed=0, applied=0, applying=0, unstable.offset=1, unstable.offsetInProgress=1, len(unstable.Entries)=0] starts to restore snapshot [index: 4, term: 1] INFO 2 switched to configuration voters=(1 2)&&(1) INFO 2 [commit: 4, lastindex: 4, lastterm: 1] restored snapshot [index: 4, term: 1] diff --git a/testdata/confchange_v2_replace_leader.txt b/testdata/confchange_v2_replace_leader.txt index dfb09505..ae43ce21 100644 --- a/testdata/confchange_v2_replace_leader.txt +++ b/testdata/confchange_v2_replace_leader.txt @@ -126,9 +126,11 @@ stabilize > 1 handling Ready Ready MustSync=false: Messages: - 1->4 MsgSnap Term:1 Log:0/0 Snapshot: Index:4 Term:1 ConfState:Voters:[2 3 4] VotersOutgoing:[1 2 3] Learners:[] LearnersNext:[] AutoLeave:false + 1->4 MsgSnap Term:1 Log:0/0 + Snapshot: Index:4 Term:1 ConfState:Voters:[2 3 4] VotersOutgoing:[1 2 3] Learners:[] LearnersNext:[] AutoLeave:false > 4 receiving messages - 1->4 MsgSnap Term:1 Log:0/0 Snapshot: Index:4 Term:1 ConfState:Voters:[2 3 4] VotersOutgoing:[1 2 3] Learners:[] LearnersNext:[] AutoLeave:false + 1->4 MsgSnap Term:1 Log:0/0 + Snapshot: Index:4 Term:1 ConfState:Voters:[2 3 4] VotersOutgoing:[1 2 3] Learners:[] LearnersNext:[] AutoLeave:false INFO log [committed=0, applied=0, applying=0, unstable.offset=1, unstable.offsetInProgress=1, len(unstable.Entries)=0] starts to restore snapshot [index: 4, term: 1] INFO 4 switched to configuration voters=(2 3 4)&&(1 2 3) INFO 4 [commit: 4, lastindex: 4, lastterm: 1] restored snapshot [index: 4, term: 1] diff --git a/testdata/probe_and_replicate.txt b/testdata/probe_and_replicate.txt index d5829704..c4100e97 100644 --- a/testdata/probe_and_replicate.txt +++ b/testdata/probe_and_replicate.txt @@ -495,9 +495,15 @@ stabilize 1 2 > 1 handling Ready Ready MustSync=false: Messages: - 1->2 MsgApp Term:8 Log:6/19 Commit:18 Entries:[6/20 EntryNormal "prop_6_20", 8/21 EntryNormal ""] + 1->2 MsgApp Term:8 Log:6/19 Commit:18 Entries:[ + 6/20 EntryNormal "prop_6_20" + 8/21 EntryNormal "" + ] > 2 receiving messages - 1->2 MsgApp Term:8 Log:6/19 Commit:18 Entries:[6/20 EntryNormal "prop_6_20", 8/21 EntryNormal ""] + 1->2 MsgApp Term:8 Log:6/19 Commit:18 Entries:[ + 6/20 EntryNormal "prop_6_20" + 8/21 EntryNormal "" + ] > 2 handling Ready Ready MustSync=true: Entries: @@ -534,9 +540,25 @@ stabilize 1 3 > 1 handling Ready Ready MustSync=false: Messages: - 1->3 MsgApp Term:8 Log:4/14 Commit:18 Entries:[4/15 EntryNormal "prop_4_15", 5/16 EntryNormal "", 5/17 EntryNormal "prop_5_17", 6/18 EntryNormal "", 6/19 EntryNormal "prop_6_19", 6/20 EntryNormal "prop_6_20", 8/21 EntryNormal ""] + 1->3 MsgApp Term:8 Log:4/14 Commit:18 Entries:[ + 4/15 EntryNormal "prop_4_15" + 5/16 EntryNormal "" + 5/17 EntryNormal "prop_5_17" + 6/18 EntryNormal "" + 6/19 EntryNormal "prop_6_19" + 6/20 EntryNormal "prop_6_20" + 8/21 EntryNormal "" + ] > 3 receiving messages - 1->3 MsgApp Term:8 Log:4/14 Commit:18 Entries:[4/15 EntryNormal "prop_4_15", 5/16 EntryNormal "", 5/17 EntryNormal "prop_5_17", 6/18 EntryNormal "", 6/19 EntryNormal "prop_6_19", 6/20 EntryNormal "prop_6_20", 8/21 EntryNormal ""] + 1->3 MsgApp Term:8 Log:4/14 Commit:18 Entries:[ + 4/15 EntryNormal "prop_4_15" + 5/16 EntryNormal "" + 5/17 EntryNormal "prop_5_17" + 6/18 EntryNormal "" + 6/19 EntryNormal "prop_6_19" + 6/20 EntryNormal "prop_6_20" + 8/21 EntryNormal "" + ] > 3 handling Ready Ready MustSync=true: HardState Term:8 Vote:1 Commit:18 @@ -624,9 +646,17 @@ stabilize 1 5 > 1 handling Ready Ready MustSync=false: Messages: - 1->5 MsgApp Term:8 Log:6/18 Commit:21 Entries:[6/19 EntryNormal "prop_6_19", 6/20 EntryNormal "prop_6_20", 8/21 EntryNormal ""] + 1->5 MsgApp Term:8 Log:6/18 Commit:21 Entries:[ + 6/19 EntryNormal "prop_6_19" + 6/20 EntryNormal "prop_6_20" + 8/21 EntryNormal "" + ] > 5 receiving messages - 1->5 MsgApp Term:8 Log:6/18 Commit:21 Entries:[6/19 EntryNormal "prop_6_19", 6/20 EntryNormal "prop_6_20", 8/21 EntryNormal ""] + 1->5 MsgApp Term:8 Log:6/18 Commit:21 Entries:[ + 6/19 EntryNormal "prop_6_19" + 6/20 EntryNormal "prop_6_20" + 8/21 EntryNormal "" + ] INFO found conflict at index 19 [existing term: 7, conflicting term: 6] INFO replace the unstable entries from index 19 > 5 handling Ready @@ -671,9 +701,23 @@ stabilize 1 6 > 1 handling Ready Ready MustSync=false: Messages: - 1->6 MsgApp Term:8 Log:4/15 Commit:21 Entries:[5/16 EntryNormal "", 5/17 EntryNormal "prop_5_17", 6/18 EntryNormal "", 6/19 EntryNormal "prop_6_19", 6/20 EntryNormal "prop_6_20", 8/21 EntryNormal ""] + 1->6 MsgApp Term:8 Log:4/15 Commit:21 Entries:[ + 5/16 EntryNormal "" + 5/17 EntryNormal "prop_5_17" + 6/18 EntryNormal "" + 6/19 EntryNormal "prop_6_19" + 6/20 EntryNormal "prop_6_20" + 8/21 EntryNormal "" + ] > 6 receiving messages - 1->6 MsgApp Term:8 Log:4/15 Commit:21 Entries:[5/16 EntryNormal "", 5/17 EntryNormal "prop_5_17", 6/18 EntryNormal "", 6/19 EntryNormal "prop_6_19", 6/20 EntryNormal "prop_6_20", 8/21 EntryNormal ""] + 1->6 MsgApp Term:8 Log:4/15 Commit:21 Entries:[ + 5/16 EntryNormal "" + 5/17 EntryNormal "prop_5_17" + 6/18 EntryNormal "" + 6/19 EntryNormal "prop_6_19" + 6/20 EntryNormal "prop_6_20" + 8/21 EntryNormal "" + ] INFO found conflict at index 16 [existing term: 4, conflicting term: 5] INFO replace the unstable entries from index 16 > 6 handling Ready @@ -724,9 +768,27 @@ stabilize 1 7 > 1 handling Ready Ready MustSync=false: Messages: - 1->7 MsgApp Term:8 Log:1/13 Commit:21 Entries:[4/14 EntryNormal "", 4/15 EntryNormal "prop_4_15", 5/16 EntryNormal "", 5/17 EntryNormal "prop_5_17", 6/18 EntryNormal "", 6/19 EntryNormal "prop_6_19", 6/20 EntryNormal "prop_6_20", 8/21 EntryNormal ""] + 1->7 MsgApp Term:8 Log:1/13 Commit:21 Entries:[ + 4/14 EntryNormal "" + 4/15 EntryNormal "prop_4_15" + 5/16 EntryNormal "" + 5/17 EntryNormal "prop_5_17" + 6/18 EntryNormal "" + 6/19 EntryNormal "prop_6_19" + 6/20 EntryNormal "prop_6_20" + 8/21 EntryNormal "" + ] > 7 receiving messages - 1->7 MsgApp Term:8 Log:1/13 Commit:21 Entries:[4/14 EntryNormal "", 4/15 EntryNormal "prop_4_15", 5/16 EntryNormal "", 5/17 EntryNormal "prop_5_17", 6/18 EntryNormal "", 6/19 EntryNormal "prop_6_19", 6/20 EntryNormal "prop_6_20", 8/21 EntryNormal ""] + 1->7 MsgApp Term:8 Log:1/13 Commit:21 Entries:[ + 4/14 EntryNormal "" + 4/15 EntryNormal "prop_4_15" + 5/16 EntryNormal "" + 5/17 EntryNormal "prop_5_17" + 6/18 EntryNormal "" + 6/19 EntryNormal "prop_6_19" + 6/20 EntryNormal "prop_6_20" + 8/21 EntryNormal "" + ] INFO found conflict at index 14 [existing term: 2, conflicting term: 4] INFO replace the unstable entries from index 14 > 7 handling Ready diff --git a/testdata/snapshot_succeed_via_app_resp.txt b/testdata/snapshot_succeed_via_app_resp.txt index 80ed3646..5c4b0c61 100644 --- a/testdata/snapshot_succeed_via_app_resp.txt +++ b/testdata/snapshot_succeed_via_app_resp.txt @@ -91,7 +91,8 @@ stabilize 1 > 1 handling Ready Ready MustSync=false: Messages: - 1->3 MsgSnap Term:1 Log:0/0 Snapshot: Index:11 Term:1 ConfState:Voters:[1 2 3] VotersOutgoing:[] Learners:[] LearnersNext:[] AutoLeave:false + 1->3 MsgSnap Term:1 Log:0/0 + Snapshot: Index:11 Term:1 ConfState:Voters:[1 2 3] VotersOutgoing:[] Learners:[] LearnersNext:[] AutoLeave:false status 1 ---- @@ -106,7 +107,8 @@ status 1 stabilize 3 ---- > 3 receiving messages - 1->3 MsgSnap Term:1 Log:0/0 Snapshot: Index:11 Term:1 ConfState:Voters:[1 2 3] VotersOutgoing:[] Learners:[] LearnersNext:[] AutoLeave:false + 1->3 MsgSnap Term:1 Log:0/0 + Snapshot: Index:11 Term:1 ConfState:Voters:[1 2 3] VotersOutgoing:[] Learners:[] LearnersNext:[] AutoLeave:false INFO log [committed=0, applied=0, applying=0, unstable.offset=1, unstable.offsetInProgress=1, len(unstable.Entries)=0] starts to restore snapshot [index: 11, term: 1] INFO 3 switched to configuration voters=(1 2 3) INFO 3 [commit: 11, lastindex: 11, lastterm: 1] restored snapshot [index: 11, term: 1] diff --git a/testdata/snapshot_succeed_via_app_resp_behind.txt b/testdata/snapshot_succeed_via_app_resp_behind.txt index 09496982..b0f5883b 100644 --- a/testdata/snapshot_succeed_via_app_resp_behind.txt +++ b/testdata/snapshot_succeed_via_app_resp_behind.txt @@ -60,7 +60,8 @@ log is empty: first index=6, last index=5 # does not move 3 to StateSnapshot. send-snapshot 1 3 ---- -1->3 MsgSnap Term:1 Log:0/0 Snapshot: Index:11 Term:1 ConfState:Voters:[1 2 3] VotersOutgoing:[] Learners:[] LearnersNext:[] AutoLeave:false +1->3 MsgSnap Term:1 Log:0/0 + Snapshot: Index:11 Term:1 ConfState:Voters:[1 2 3] VotersOutgoing:[] Learners:[] LearnersNext:[] AutoLeave:false # Propose and commit an additional entry, which makes the leader's # last index 12, beyond the snapshot it sent at index 11. @@ -106,7 +107,8 @@ Messages: # 3 receives and applies the snapshot, but doesn't respond with MsgAppResp yet. deliver-msgs 3 ---- -1->3 MsgSnap Term:1 Log:0/0 Snapshot: Index:11 Term:1 ConfState:Voters:[1 2 3] VotersOutgoing:[] Learners:[] LearnersNext:[] AutoLeave:false +1->3 MsgSnap Term:1 Log:0/0 + Snapshot: Index:11 Term:1 ConfState:Voters:[1 2 3] VotersOutgoing:[] Learners:[] LearnersNext:[] AutoLeave:false INFO log [committed=5, applied=5, applying=5, unstable.offset=6, unstable.offsetInProgress=6, len(unstable.Entries)=0] starts to restore snapshot [index: 11, term: 1] INFO 3 switched to configuration voters=(1 2 3) INFO 3 [commit: 11, lastindex: 11, lastterm: 1] restored snapshot [index: 11, term: 1] @@ -126,12 +128,14 @@ stabilize 1 > 1 handling Ready Ready MustSync=false: Messages: - 1->3 MsgSnap Term:1 Log:0/0 Snapshot: Index:12 Term:1 ConfState:Voters:[1 2 3] VotersOutgoing:[] Learners:[] LearnersNext:[] AutoLeave:false + 1->3 MsgSnap Term:1 Log:0/0 + Snapshot: Index:12 Term:1 ConfState:Voters:[1 2 3] VotersOutgoing:[] Learners:[] LearnersNext:[] AutoLeave:false # Drop the extra MsgSnap(index=12) that 1 just sent, to keep the test tidy. deliver-msgs drop=(3) ---- -dropped: 1->3 MsgSnap Term:1 Log:0/0 Snapshot: Index:12 Term:1 ConfState:Voters:[1 2 3] VotersOutgoing:[] Learners:[] LearnersNext:[] AutoLeave:false +dropped: 1->3 MsgSnap Term:1 Log:0/0 + Snapshot: Index:12 Term:1 ConfState:Voters:[1 2 3] VotersOutgoing:[] Learners:[] LearnersNext:[] AutoLeave:false # 3 sends the affirmative MsgAppResp that resulted from applying the snapshot # at index 11. diff --git a/util.go b/util.go index c475a104..8f781788 100644 --- a/util.go +++ b/util.go @@ -148,8 +148,12 @@ type EntryFormatter func([]byte) string // DescribeMessage returns a concise human-readable description of a // Message for debugging. func DescribeMessage(m pb.Message, f EntryFormatter) string { + return describeMessageWithIndent("", m, f) +} + +func describeMessageWithIndent(indent string, m pb.Message, f EntryFormatter) string { var buf bytes.Buffer - fmt.Fprintf(&buf, "%s->%s %v Term:%d Log:%d/%d", + fmt.Fprintf(&buf, "%s%s->%s %v Term:%d Log:%d/%d", indent, describeTarget(m.From), describeTarget(m.To), m.Type, m.Term, m.LogTerm, m.Index) if m.Reject { fmt.Fprintf(&buf, " Rejected (Hint: %d)", m.RejectHint) @@ -160,28 +164,26 @@ func DescribeMessage(m pb.Message, f EntryFormatter) string { if m.Vote != 0 { fmt.Fprintf(&buf, " Vote:%d", m.Vote) } - if len(m.Entries) > 0 { + if ln := len(m.Entries); ln == 1 { + fmt.Fprintf(&buf, " Entries:[%s]", DescribeEntry(m.Entries[0], f)) + } else if ln > 1 { fmt.Fprint(&buf, " Entries:[") - for i, e := range m.Entries { - if i != 0 { - buf.WriteString(", ") - } + for _, e := range m.Entries { + fmt.Fprintf(&buf, "\n%s ", indent) buf.WriteString(DescribeEntry(e, f)) } - fmt.Fprint(&buf, "]") + fmt.Fprintf(&buf, "\n%s]", indent) } if s := m.Snapshot; s != nil && !IsEmptySnap(*s) { - fmt.Fprintf(&buf, " Snapshot: %s", DescribeSnapshot(*s)) + fmt.Fprintf(&buf, "\n%s Snapshot: %s", indent, DescribeSnapshot(*s)) } if len(m.Responses) > 0 { fmt.Fprintf(&buf, " Responses:[") - for i, m := range m.Responses { - if i != 0 { - buf.WriteString(", ") - } - buf.WriteString(DescribeMessage(m, f)) + for _, m := range m.Responses { + buf.WriteString("\n") + buf.WriteString(describeMessageWithIndent(indent+" ", m, f)) } - fmt.Fprintf(&buf, "]") + fmt.Fprintf(&buf, "\n%s]", indent) } return buf.String() }