fix sbft backlog processing

sbft backlog needs to be processed on every phase transition. Otherwise,
messages put in the backlog may be as good as lost, in case, e.g., a
pre-prepare is received after corresponding prepare/commit/checkpoint msgs.

This is demonstrated by the new test TestMsgReordering (which would so far
fail) in simplebft_test.go.

Change-Id: I4b38a922e5d565c8e7a92a66f3e125fd30e8715f
Signed-off-by: Marko Vukolic <mvu@zurich.ibm.com>

orderer/sbft/simplebft/commit.go

@@ -23,6 +23,7 @@ func (s *SBFT) maybeSendCommit() {
 		return
 	}
 	s.sendCommit()
+	s.processBacklog()
 }
 
 func (s *SBFT) sendCommit() {

orderer/sbft/simplebft/execute.go

@@ -26,4 +26,5 @@ func (s *SBFT) maybeExecute() {
 	s.sys.Persist("execute", &s.cur.subject)
 
 	s.sendCheckpoint()
+	s.processBacklog()
 }

orderer/sbft/simplebft/preprepare.go

@@ -99,6 +99,7 @@ func (s *SBFT) handleCheckedPreprepare(pp *Preprepare) {
 	s.acceptPreprepare(pp)
 	if !s.isPrimary() {
 		s.sendPrepare()
+		s.processBacklog()
 	}
 
 	s.maybeSendCommit()

orderer/sbft/simplebft/simplebft_test.go

@@ -29,8 +29,8 @@ var testLog = logging.MustGetLogger("test")
 
 func init() {
 	logging.SetLevel(logging.NOTICE, "")
-	// logging.SetLevel(logging.DEBUG, "test")
-	// logging.SetLevel(logging.DEBUG, "sbft")
+	//logging.SetLevel(logging.DEBUG, "test")
+	//logging.SetLevel(logging.DEBUG, "sbft")
 }
 
 func connectAll(sys *testSystem) {
@@ -259,6 +259,58 @@ func TestViewChange(t *testing.T) {
 	}
 }
 
+func TestMsgReordering(t *testing.T) {
+	N := uint64(4)
+	sys := newTestSystem(N)
+	var repls []*SBFT
+	var adapters []*testSystemAdapter
+	for i := uint64(0); i < N; i++ {
+		a := sys.NewAdapter(i)
+		s, err := New(i, &Config{N: N, F: 1, BatchDurationNsec: 2000000000, BatchSizeBytes: 1, RequestTimeoutNsec: 20000000000}, a)
+		if err != nil {
+			t.Fatal(err)
+		}
+		repls = append(repls, s)
+		adapters = append(adapters, a)
+	}
+
+	var preprep *testMsgEvent
+
+	// forcing pre-prepare from primary 0 to reach replica 1 after some delay
+	// effectivelly delivering pre-prepare instead of checkpoint
+	sys.filterFn = func(e testElem) (testElem, bool) {
+		if msg, ok := e.ev.(*testMsgEvent); ok {
+			if msg.src == 0 && msg.dst == 1 {
+				c := msg.msg.GetPreprepare()
+				if c != nil && c.Seq.View == 0 {
+					preprep = msg   //memorizing pre-prepare
+					return e, false // but dropping it
+				}
+				d := msg.msg.GetCheckpoint()
+				if d != nil {
+					msg.msg = &Msg{&Msg_Preprepare{preprep.msg.GetPreprepare()}}
+					return e, true //and delivering it
+				}
+				return e, false //droping other msgs from 0 to 1
+			}
+		}
+		return e, true
+	}
+
+	connectAll(sys)
+	r1 := []byte{1, 2, 3}
+	repls[0].Request(r1)
+	sys.Run()
+	for _, a := range adapters {
+		if len(a.batches) != 1 {
+			t.Fatal("expected execution of 1 batch")
+		}
+		if !reflect.DeepEqual([][]byte{r1}, a.batches[0].Payloads) {
+			t.Error("wrong request executed (1)")
+		}
+	}
+}
+
 func TestViewChangeWithRetransmission(t *testing.T) {
 	N := uint64(4)
 	sys := newTestSystem(N)