[FAB-4330] Orderer panic on restart

On restart, the orderer is failing to properly re-initialize the config
sequence number, which causes it to inappropriately flag new non-config
blocks as config blocks.

On second restart, the incorrect last config index causes the orderer to
attempt to treat a normal transaction as a config transaction.  The
error checking recognizes this as a fatal error and panics.

This CR moves the initialization out of the "new channel" path, and into
the common path shared by both startup and restart.

It also enhances the log messages to make detection of this sort of
scenario easier.

Change-Id: I0d730eb5180f21ee6913bc8633ff540128bc6899
Signed-off-by: Jason Yellick <[email protected]>

Author: Jason Yellick

orderer/multichain/chainsupport.go

@@ -122,16 +122,28 @@ func newChainSupport(
 		signer:          signer,
 	}
 
+	cs.lastConfigSeq = cs.Sequence()
+
 	var err error
 
 	lastBlock := ledger.GetBlock(cs.Reader(), cs.Reader().Height()-1)
+
+	// If this is the genesis block, the lastconfig field may be empty, and, the last config is necessary 0
+	// so no need to initialize lastConfig
+	if lastBlock.Header.Number != 0 {
+		cs.lastConfig, err = utils.GetLastConfigIndexFromBlock(lastBlock)
+		if err != nil {
+			logger.Fatalf("[channel: %s] Error extracting last config block from block metadata: %s", cs.ChainID(), err)
+		}
+	}
+
 	metadata, err := utils.GetMetadataFromBlock(lastBlock, cb.BlockMetadataIndex_ORDERER)
 	// Assuming a block created with cb.NewBlock(), this should not
 	// error even if the orderer metadata is an empty byte slice
 	if err != nil {
 		logger.Fatalf("[channel: %s] Error extracting orderer metadata: %s", cs.ChainID(), err)
 	}
-	logger.Debugf("[channel: %s] Retrieved metadata for tip of chain (block #%d): %+v", cs.ChainID(), cs.Reader().Height()-1, metadata)
+	logger.Debugf("[channel: %s] Retrieved metadata for tip of chain (blockNumber=%d, lastConfig=%d, lastConfigSeq=%d): %+v", cs.ChainID(), lastBlock.Header.Number, cs.lastConfig, cs.lastConfigSeq, metadata)
 
 	cs.chain, err = consenter.HandleChain(cs, metadata)
 	if err != nil {
@@ -222,6 +234,7 @@ func (cs *chainSupport) addBlockSignature(block *cb.Block) {
 func (cs *chainSupport) addLastConfigSignature(block *cb.Block) {
 	configSeq := cs.Sequence()
 	if configSeq > cs.lastConfigSeq {
+		logger.Debugf("[channel: %s] Detected lastConfigSeq transitioning from %d to %d, setting lastConfig from %d to %d", cs.ChainID(), cs.lastConfigSeq, configSeq, cs.lastConfig, block.Header.Number)
 		cs.lastConfig = block.Header.Number
 		cs.lastConfigSeq = configSeq
 	}

orderer/multichain/manager.go

@@ -187,11 +187,6 @@ func (ml *multiLedger) newChain(configtx *cb.Envelope) {
 
 	logger.Infof("Created and starting new chain %s", chainID)
 
-	cs.lastConfigSeq = cs.Sequence()
-	// The sequence number on the genesis block of the system channel will be 0.
-	// The sequence number on the genesis block of every non-system channel will be 1.
-	logger.Debugf("[channel: %s] Last config set to %d", chainID, cs.lastConfigSeq)
-
 	newChains[string(chainID)] = cs
 	cs.start()
 

orderer/multichain/manager_test.go

@@ -471,6 +471,15 @@ func TestNewChain(t *testing.T) {
 	case <-time.After(time.Second):
 		t.Fatalf("Block 1 not produced after timeout on new chain")
 	}
+
+	testRestartedChainSupport(t, chainSupport, consenters, expectedLastConfigSeq)
+}
+
+func testRestartedChainSupport(t *testing.T, cs ChainSupport, consenters map[string]Consenter, expectedLastConfigSeq uint64) {
+	ccs, ok := cs.(*chainSupport)
+	assert.True(t, ok, "Casting error")
+	rcs := newChainSupport(ccs.filters, ccs.ledgerResources, consenters, mockCrypto())
+	assert.Equal(t, expectedLastConfigSeq, rcs.lastConfigSeq, "On restart, incorrect lastConfigSeq")
 }
 
 func testLastConfigBlockNumber(t *testing.T, block *cb.Block, expectedBlockNumber uint64) {