rafttest: print Ready before processing it

It was confusing to see the effects of the Ready (i.e. log messages)
printed before the Ready itself.

raft/rafttest/interaction_env_handler_process_ready.go

@@ -32,6 +32,7 @@ func (env *InteractionEnv) ProcessReady(idx int) error {
 	// TODO(tbg): Allow simulating crashes here.
 	rn, s := env.Nodes[idx].RawNode, env.Nodes[idx].Storage
 	rd := rn.Ready()
+	env.Output.WriteString(raft.DescribeReady(rd, defaultEntryFormatter))
 	// TODO(tbg): the order of operations here is not necessarily safe. See:
 	// https://github.com/etcd-io/etcd/pull/10861
 	if !raft.IsEmptyHardState(rd.HardState) {
@@ -89,6 +90,5 @@ func (env *InteractionEnv) ProcessReady(idx int) error {
 		env.Messages = append(env.Messages, msg)
 	}
 	rn.Advance(rd)
-	env.Output.WriteString(raft.DescribeReady(rd, defaultEntryFormatter))
 	return nil
 }

raft/testdata/campaign_learner_must_vote.txt

@@ -120,7 +120,6 @@ stabilize 2 3
 > 3 receiving messages
   2->3 MsgApp Term:2 Log:1/3 Commit:4 Entries:[1/4 EntryConfChangeV2 v3, 2/5 EntryNormal ""]
 > 3 handling Ready
-  INFO 3 switched to configuration voters=(1 2 3)
   Ready MustSync=true:
   HardState Term:2 Vote:2 Commit:4
   Entries:
@@ -130,6 +129,7 @@ stabilize 2 3
   1/4 EntryConfChangeV2 v3
   Messages:
   3->2 MsgAppResp Term:2 Log:0/5
+  INFO 3 switched to configuration voters=(1 2 3)
 > 2 receiving messages
   3->2 MsgAppResp Term:2 Log:0/5
 > 2 handling Ready

raft/testdata/confchange_v1_add_single.txt

@@ -33,7 +33,6 @@ INFO newRaft 2 [peers: [], term: 0, commit: 0, applied: 0, lastindex: 0, lastter
 stabilize
 ----
 > 1 handling Ready
-  INFO 1 switched to configuration voters=(1 2)
   Ready MustSync=true:
   Lead:1 State:StateLeader
   HardState Term:1 Vote:1 Commit:4
@@ -43,6 +42,7 @@ stabilize
   CommittedEntries:
   1/3 EntryNormal ""
   1/4 EntryConfChange v2
+  INFO 1 switched to configuration voters=(1 2)
 > 1 handling Ready
   Ready MustSync=false:
   Messages:

raft/testdata/confchange_v1_remove_leader.txt

@@ -83,7 +83,6 @@ stabilize 1
   2->1 MsgAppResp Term:1 Log:0/4
   2->1 MsgAppResp Term:1 Log:0/5
 > 1 handling Ready
-  INFO 1 switched to configuration voters=(2 3)
   Ready MustSync=false:
   HardState Term:1 Vote:1 Commit:5
   CommittedEntries:
@@ -94,6 +93,7 @@ stabilize 1
   1->3 MsgApp Term:1 Log:1/6 Commit:4
   1->2 MsgApp Term:1 Log:1/6 Commit:5
   1->3 MsgApp Term:1 Log:1/6 Commit:5
+  INFO 1 switched to configuration voters=(2 3)
 
 # n2 responds, n3 doesn't yet. Quorum for 'bar' should not be reached...
 stabilize 2
@@ -103,7 +103,6 @@ stabilize 2
   1->2 MsgApp Term:1 Log:1/6 Commit:4
   1->2 MsgApp Term:1 Log:1/6 Commit:5
 > 2 handling Ready
-  INFO 2 switched to configuration voters=(2 3)
   Ready MustSync=true:
   HardState Term:1 Vote:1 Commit:5
   Entries:
@@ -115,6 +114,7 @@ stabilize 2
   2->1 MsgAppResp Term:1 Log:0/6
   2->1 MsgAppResp Term:1 Log:0/6
   2->1 MsgAppResp Term:1 Log:0/6
+  INFO 2 switched to configuration voters=(2 3)
 
 # ... which thankfully is what we see on the leader.
 stabilize 1
@@ -134,7 +134,6 @@ stabilize
   1->3 MsgApp Term:1 Log:1/6 Commit:4
   1->3 MsgApp Term:1 Log:1/6 Commit:5
 > 3 handling Ready
-  INFO 3 switched to configuration voters=(2 3)
   Ready MustSync=true:
   HardState Term:1 Vote:1 Commit:5
   Entries:
@@ -150,6 +149,7 @@ stabilize
   3->1 MsgAppResp Term:1 Log:0/6
   3->1 MsgAppResp Term:1 Log:0/6
   3->1 MsgAppResp Term:1 Log:0/6
+  INFO 3 switched to configuration voters=(2 3)
 > 1 receiving messages
   3->1 MsgAppResp Term:1 Log:0/4
   3->1 MsgAppResp Term:1 Log:0/5

raft/testdata/confchange_v2_add_double_auto.txt

@@ -38,8 +38,6 @@ INFO newRaft 3 [peers: [], term: 0, commit: 0, applied: 0, lastindex: 0, lastter
 # once.
 process-ready 1
 ----
-INFO 1 switched to configuration voters=(1 2 3)&&(1) autoleave
-INFO initiating automatic transition out of joint configuration voters=(1 2 3)&&(1) autoleave
 Ready MustSync=true:
 Lead:1 State:StateLeader
 HardState Term:1 Vote:1 Commit:4
@@ -49,6 +47,8 @@ Entries:
 CommittedEntries:
 1/3 EntryNormal ""
 1/4 EntryConfChangeV2 v2 v3
+INFO 1 switched to configuration voters=(1 2 3)&&(1) autoleave
+INFO initiating automatic transition out of joint configuration voters=(1 2 3)&&(1) autoleave
 
 # n1 immediately probes n2 and n3.
 stabilize 1
@@ -119,23 +119,23 @@ stabilize 1 2
 > 1 receiving messages
   2->1 MsgAppResp Term:1 Log:0/5
 > 1 handling Ready
-  INFO 1 switched to configuration voters=(1 2 3)
   Ready MustSync=false:
   HardState Term:1 Vote:1 Commit:5
   CommittedEntries:
   1/5 EntryConfChangeV2
   Messages:
   1->2 MsgApp Term:1 Log:1/5 Commit:5
+  INFO 1 switched to configuration voters=(1 2 3)
 > 2 receiving messages
   1->2 MsgApp Term:1 Log:1/5 Commit:5
 > 2 handling Ready
-  INFO 2 switched to configuration voters=(1 2 3)
   Ready MustSync=false:
   HardState Term:1 Commit:5
   CommittedEntries:
   1/5 EntryConfChangeV2
   Messages:
   2->1 MsgAppResp Term:1 Log:0/5
+  INFO 2 switched to configuration voters=(1 2 3)
 > 1 receiving messages
   2->1 MsgAppResp Term:1 Log:0/5
 

raft/testdata/confchange_v2_add_double_implicit.txt

@@ -36,8 +36,6 @@ INFO newRaft 2 [peers: [], term: 0, commit: 0, applied: 0, lastindex: 0, lastter
 stabilize 1 2
 ----
 > 1 handling Ready
-  INFO 1 switched to configuration voters=(1 2)&&(1) autoleave
-  INFO initiating automatic transition out of joint configuration voters=(1 2)&&(1) autoleave
   Ready MustSync=true:
   Lead:1 State:StateLeader
   HardState Term:1 Vote:1 Commit:4
@@ -47,6 +45,8 @@ stabilize 1 2
   CommittedEntries:
   1/3 EntryNormal ""
   1/4 EntryConfChangeV2 v2
+  INFO 1 switched to configuration voters=(1 2)&&(1) autoleave
+  INFO initiating automatic transition out of joint configuration voters=(1 2)&&(1) autoleave
 > 1 handling Ready
   Ready MustSync=true:
   Entries:
@@ -104,22 +104,22 @@ stabilize 1 2
 > 1 receiving messages
   2->1 MsgAppResp Term:1 Log:0/5
 > 1 handling Ready
-  INFO 1 switched to configuration voters=(1 2)
   Ready MustSync=false:
   HardState Term:1 Vote:1 Commit:5
   CommittedEntries:
   1/5 EntryConfChangeV2
   Messages:
   1->2 MsgApp Term:1 Log:1/5 Commit:5
+  INFO 1 switched to configuration voters=(1 2)
 > 2 receiving messages
   1->2 MsgApp Term:1 Log:1/5 Commit:5
 > 2 handling Ready
-  INFO 2 switched to configuration voters=(1 2)
   Ready MustSync=false:
   HardState Term:1 Commit:5
   CommittedEntries:
   1/5 EntryConfChangeV2
   Messages:
   2->1 MsgAppResp Term:1 Log:0/5
+  INFO 2 switched to configuration voters=(1 2)
 > 1 receiving messages
   2->1 MsgAppResp Term:1 Log:0/5

raft/testdata/confchange_v2_add_single_auto.txt

@@ -34,7 +34,6 @@ INFO newRaft 2 [peers: [], term: 0, commit: 0, applied: 0, lastindex: 0, lastter
 stabilize
 ----
 > 1 handling Ready
-  INFO 1 switched to configuration voters=(1 2)
   Ready MustSync=true:
   Lead:1 State:StateLeader
   HardState Term:1 Vote:1 Commit:4
@@ -44,6 +43,7 @@ stabilize
   CommittedEntries:
   1/3 EntryNormal ""
   1/4 EntryConfChangeV2 v2
+  INFO 1 switched to configuration voters=(1 2)
 > 1 handling Ready
   Ready MustSync=false:
   Messages:
@@ -136,8 +136,6 @@ stabilize
   2->1 MsgAppResp Term:1 Log:0/5
   2->1 MsgAppResp Term:1 Log:0/6
 > 1 handling Ready
-  INFO 1 switched to configuration voters=(1 2 3 4 5)&&(1 2) autoleave
-  INFO initiating automatic transition out of joint configuration voters=(1 2 3 4 5)&&(1 2) autoleave
   Ready MustSync=false:
   HardState Term:1 Vote:1 Commit:6
   CommittedEntries:
@@ -146,6 +144,8 @@ stabilize
   Messages:
   1->2 MsgApp Term:1 Log:1/6 Commit:5
   1->2 MsgApp Term:1 Log:1/6 Commit:6
+  INFO 1 switched to configuration voters=(1 2 3 4 5)&&(1 2) autoleave
+  INFO initiating automatic transition out of joint configuration voters=(1 2 3 4 5)&&(1 2) autoleave
 > 2 receiving messages
   1->2 MsgApp Term:1 Log:1/6 Commit:5
   1->2 MsgApp Term:1 Log:1/6 Commit:6
@@ -158,7 +158,6 @@ stabilize
   1->4 MsgApp Term:1 Log:1/5 Commit:6 Entries:[1/6 EntryNormal ""]
   1->5 MsgApp Term:1 Log:1/5 Commit:6 Entries:[1/6 EntryNormal ""]
 > 2 handling Ready
-  INFO 2 switched to configuration voters=(1 2 3 4 5)&&(1 2) autoleave
   Ready MustSync=false:
   HardState Term:1 Commit:6
   CommittedEntries:
@@ -167,6 +166,7 @@ stabilize
   Messages:
   2->1 MsgAppResp Term:1 Log:0/6
   2->1 MsgAppResp Term:1 Log:0/6
+  INFO 2 switched to configuration voters=(1 2 3 4 5)&&(1 2) autoleave
 > 1 receiving messages
   2->1 MsgAppResp Term:1 Log:0/6
   2->1 MsgAppResp Term:1 Log:0/6

raft/testdata/confchange_v2_add_single_explicit.txt

@@ -34,7 +34,6 @@ INFO newRaft 2 [peers: [], term: 0, commit: 0, applied: 0, lastindex: 0, lastter
 stabilize 1 2
 ----
 > 1 handling Ready
-  INFO 1 switched to configuration voters=(1 2)&&(1)
   Ready MustSync=true:
   Lead:1 State:StateLeader
   HardState Term:1 Vote:1 Commit:4
@@ -44,6 +43,7 @@ stabilize 1 2
   CommittedEntries:
   1/3 EntryNormal ""
   1/4 EntryConfChangeV2 v2
+  INFO 1 switched to configuration voters=(1 2)&&(1)
 > 1 handling Ready
   Ready MustSync=false:
   Messages:
@@ -136,7 +136,6 @@ stabilize
   2->1 MsgAppResp Term:1 Log:0/5
   2->1 MsgAppResp Term:1 Log:0/6
 > 1 handling Ready
-  INFO 1 switched to configuration voters=(1 2)
   Ready MustSync=false:
   HardState Term:1 Vote:1 Commit:6
   CommittedEntries:
@@ -145,11 +144,11 @@ stabilize
   Messages:
   1->2 MsgApp Term:1 Log:1/6 Commit:5
   1->2 MsgApp Term:1 Log:1/6 Commit:6
+  INFO 1 switched to configuration voters=(1 2)
 > 2 receiving messages
   1->2 MsgApp Term:1 Log:1/6 Commit:5
   1->2 MsgApp Term:1 Log:1/6 Commit:6
 > 2 handling Ready
-  INFO 2 switched to configuration voters=(1 2)
   Ready MustSync=false:
   HardState Term:1 Commit:6
   CommittedEntries:
@@ -158,6 +157,7 @@ stabilize
   Messages:
   2->1 MsgAppResp Term:1 Log:0/6
   2->1 MsgAppResp Term:1 Log:0/6
+  INFO 2 switched to configuration voters=(1 2)
 > 1 receiving messages
   2->1 MsgAppResp Term:1 Log:0/6
   2->1 MsgAppResp Term:1 Log:0/6