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]>
etcd-io · Feb 9, 2024 · 1258bde · 1258bde
1 parent 5963780
commit 1258bde
Show file tree

Hide file tree

Showing 25 changed files with 1,207 additions and 361 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
@@ -36,22 +36,51 @@ Ready MustSync=true:
 Entries:
 1/12 EntryNormal "init_prop"
 Messages:
-2->1 MsgApp Term:1 Log:1/11 Commit:11 Entries:[1/12 EntryNormal "init_prop"]
-2->3 MsgApp Term:1 Log:1/11 Commit:11 Entries:[1/12 EntryNormal "init_prop"]
-2->4 MsgApp Term:1 Log:1/11 Commit:11 Entries:[1/12 EntryNormal "init_prop"]
-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->1 MsgApp Term:1 Log:1/11 Commit:11 Entries: [
+  1/12 EntryNormal "init_prop"
+]
+2->3 MsgApp Term:1 Log:1/11 Commit:11 Entries: [
+  1/12 EntryNormal "init_prop"
+]
+2->4 MsgApp Term:1 Log:1/11 Commit:11 Entries: [
+  1/12 EntryNormal "init_prop"
+]
+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
+]
 
 deliver-msgs 1 drop=(3,4,5,6,7)
 ----
-2->1 MsgApp Term:1 Log:1/11 Commit:11 Entries:[1/12 EntryNormal "init_prop"]
-dropped: 2->3 MsgApp Term:1 Log:1/11 Commit:11 Entries:[1/12 EntryNormal "init_prop"]
-dropped: 2->4 MsgApp Term:1 Log:1/11 Commit:11 Entries:[1/12 EntryNormal "init_prop"]
-dropped: 2->5 MsgApp Term:1 Log:1/11 Commit:11 Entries:[1/12 EntryNormal "init_prop"]
-dropped: 2->6 MsgApp Term:1 Log:1/11 Commit:11 Entries:[1/12 EntryNormal "init_prop"]
-dropped: 2->7 MsgApp Term:1 Log:1/11 Commit:11 Entries:[1/12 EntryNormal "init_prop"]
+2->1 MsgApp Term:1 Log:1/11 Commit:11 Entries: [
+  1/12 EntryNormal "init_prop"
+]
+dropped: 2->3 MsgApp Term:1 Log:1/11 Commit:11 Entries: [
+  1/12 EntryNormal "init_prop"
+]
+dropped: 2->4 MsgApp Term:1 Log:1/11 Commit:11 Entries: [
+  1/12 EntryNormal "init_prop"
+]
+dropped: 2->5 MsgApp Term:1 Log:1/11 Commit:11 Entries: [
+  1/12 EntryNormal "init_prop"
+]
+dropped: 2->6 MsgApp Term:1 Log:1/11 Commit:11 Entries: [
+  1/12 EntryNormal "init_prop"
+]
+dropped: 2->7 MsgApp Term:1 Log:1/11 Commit:11 Entries: [
+  1/12 EntryNormal "init_prop"
+]
 
 # Step 3: node 1 gets the Ready and the entries are appended asynchronously.
 
@@ -61,7 +90,12 @@ 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 +122,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 +148,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
 ----
@@ -177,30 +219,59 @@ Lead:3 State:StateLeader
 Entries:
 2/12 EntryNormal ""
 Messages:
-3->1 MsgApp Term:2 Log:1/11 Commit:11 Entries:[2/12 EntryNormal ""]
-3->2 MsgApp Term:2 Log:1/11 Commit:11 Entries:[2/12 EntryNormal ""]
-3->4 MsgApp Term:2 Log:1/11 Commit:11 Entries:[2/12 EntryNormal ""]
-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->1 MsgApp Term:2 Log:1/11 Commit:11 Entries: [
+  2/12 EntryNormal ""
+]
+3->2 MsgApp Term:2 Log:1/11 Commit:11 Entries: [
+  2/12 EntryNormal ""
+]
+3->4 MsgApp Term:2 Log:1/11 Commit:11 Entries: [
+  2/12 EntryNormal ""
+]
+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
+]
 
 deliver-msgs 1 drop=(2,4,5,6,7)
 ----
 3->1 MsgVote Term:2 Log:1/11
 INFO 1 [term: 1] received a MsgVote message with higher term from 3 [term: 2]
 INFO 1 became follower at term 2
 INFO 1 [logterm: 1, index: 12, vote: 0] rejected MsgVote from 3 [logterm: 1, index: 11] at term 2
-3->1 MsgApp Term:2 Log:1/11 Commit:11 Entries:[2/12 EntryNormal ""]
+3->1 MsgApp Term:2 Log:1/11 Commit:11 Entries: [
+  2/12 EntryNormal ""
+]
 INFO found conflict at index 12 [existing term: 1, conflicting term: 2]
 INFO replace the unstable entries from index 12
 dropped: 3->2 MsgVote Term:2 Log:1/11
-dropped: 3->2 MsgApp Term:2 Log:1/11 Commit:11 Entries:[2/12 EntryNormal ""]
-dropped: 3->4 MsgApp Term:2 Log:1/11 Commit:11 Entries:[2/12 EntryNormal ""]
-dropped: 3->5 MsgApp Term:2 Log:1/11 Commit:11 Entries:[2/12 EntryNormal ""]
-dropped: 3->6 MsgApp Term:2 Log:1/11 Commit:11 Entries:[2/12 EntryNormal ""]
+dropped: 3->2 MsgApp Term:2 Log:1/11 Commit:11 Entries: [
+  2/12 EntryNormal ""
+]
+dropped: 3->4 MsgApp Term:2 Log:1/11 Commit:11 Entries: [
+  2/12 EntryNormal ""
+]
+dropped: 3->5 MsgApp Term:2 Log:1/11 Commit:11 Entries: [
+  2/12 EntryNormal ""
+]
+dropped: 3->6 MsgApp Term:2 Log:1/11 Commit:11 Entries: [
+  2/12 EntryNormal ""
+]
 dropped: 3->7 MsgVote Term:2 Log:1/11
-dropped: 3->7 MsgApp Term:2 Log:1/11 Commit:11 Entries:[2/12 EntryNormal ""]
+dropped: 3->7 MsgApp Term:2 Log:1/11 Commit:11 Entries: [
+  2/12 EntryNormal ""
+]
 
 process-ready 1
 ----
@@ -210,7 +281,13 @@ 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 +314,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 +339,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
 ----
@@ -319,13 +404,30 @@ Lead:4 State:StateLeader
 Entries:
 3/12 EntryNormal ""
 Messages:
-4->1 MsgApp Term:3 Log:1/11 Commit:11 Entries:[3/12 EntryNormal ""]
-4->2 MsgApp Term:3 Log:1/11 Commit:11 Entries:[3/12 EntryNormal ""]
-4->3 MsgApp Term:3 Log:1/11 Commit:11 Entries:[3/12 EntryNormal ""]
-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->1 MsgApp Term:3 Log:1/11 Commit:11 Entries: [
+  3/12 EntryNormal ""
+]
+4->2 MsgApp Term:3 Log:1/11 Commit:11 Entries: [
+  3/12 EntryNormal ""
+]
+4->3 MsgApp Term:3 Log:1/11 Commit:11 Entries: [
+  3/12 EntryNormal ""
+]
+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
+]
 
 # 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
@@ -336,7 +438,9 @@ Messages:
 deliver-msgs drop=1
 ----
 dropped: 4->1 MsgVote Term:3 Log:1/11
-dropped: 4->1 MsgApp Term:3 Log:1/11 Commit:11 Entries:[3/12 EntryNormal ""]
+dropped: 4->1 MsgApp Term:3 Log:1/11 Commit:11 Entries: [
+  3/12 EntryNormal ""
+]
 
 tick-heartbeat 4
 ----
@@ -366,7 +470,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
 ----
@@ -376,11 +482,15 @@ process-ready 4
 ----
 Ready MustSync=false:
 Messages:
-4->1 MsgApp Term:3 Log:1/11 Commit:11 Entries:[3/12 EntryNormal ""]
+4->1 MsgApp Term:3 Log:1/11 Commit:11 Entries: [
+  3/12 EntryNormal ""
+]
 
 deliver-msgs 1
 ----
-4->1 MsgApp Term:3 Log:1/11 Commit:11 Entries:[3/12 EntryNormal ""]
+4->1 MsgApp Term:3 Log:1/11 Commit:11 Entries: [
+  3/12 EntryNormal ""
+]
 INFO found conflict at index 12 [existing term: 2, conflicting term: 3]
 INFO replace the unstable entries from index 12
 
@@ -390,7 +500,12 @@ 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
@@ -403,7 +518,9 @@ raft-log 1
 process-append-thread 1
 ----
 Processing:
-1->AppendThread MsgStorageAppend Term:0 Log:0/0 Entries:[1/12 EntryNormal "init_prop"]
+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
@@ -429,7 +546,9 @@ INFO 1 [term: 3] ignored entry appends from a MsgStorageAppendResp message with
 process-append-thread 1
 ----
 Processing:
-1->AppendThread MsgStorageAppend Term:2 Log:0/0 Commit:11 Entries:[2/12 EntryNormal ""]
+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
@@ -465,7 +584,9 @@ INFO entry at (index,term)=(12,2) mismatched with entry at (12,3) in unstable lo
 process-append-thread 1
 ----
 Processing:
-1->AppendThread MsgStorageAppend Term:0 Log:0/0 Entries:[3/12 EntryNormal ""]
+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

diff --git a/testdata/campaign.txt b/testdata/campaign.txt
@@ -64,12 +64,20 @@ stabilize
   Entries:
   1/3 EntryNormal ""
   Messages:
-  1->2 MsgApp Term:1 Log:1/2 Commit:2 Entries:[1/3 EntryNormal ""]
-  1->3 MsgApp Term:1 Log:1/2 Commit:2 Entries:[1/3 EntryNormal ""]
+  1->2 MsgApp Term:1 Log:1/2 Commit:2 Entries: [
+    1/3 EntryNormal ""
+  ]
+  1->3 MsgApp Term:1 Log:1/2 Commit:2 Entries: [
+    1/3 EntryNormal ""
+  ]
 > 2 receiving messages
-  1->2 MsgApp Term:1 Log:1/2 Commit:2 Entries:[1/3 EntryNormal ""]
+  1->2 MsgApp Term:1 Log:1/2 Commit:2 Entries: [
+    1/3 EntryNormal ""
+  ]
 > 3 receiving messages
-  1->3 MsgApp Term:1 Log:1/2 Commit:2 Entries:[1/3 EntryNormal ""]
+  1->3 MsgApp Term:1 Log:1/2 Commit:2 Entries: [
+    1/3 EntryNormal ""
+  ]
 > 2 handling Ready
   Ready MustSync=true:
   Lead:1 State:StateFollower