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 <[email protected]>
pav-kv · Feb 9, 2024 · 8c5f2f1 · 8c5f2f1
1 parent 5963780
commit 8c5f2f1
Show file tree

Hide file tree

Showing 13 changed files with 329 additions and 101 deletions.
diff --git a/testdata/async_storage_writes.txt b/testdata/async_storage_writes.txt
diff --git 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
@@ -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
@@ -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
@@ -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
@@ -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
@@ -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
@@ -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
@@ -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]