Reduced block production timeout

consensus/construct.go

@@ -97,21 +97,63 @@ func (consensus *Consensus) construct(
 	case msg_pb.MessageType_PREPARE:
 		needMsgSig = false
 		sig := bls_core.Sign{}
+		signedCount := 0
 		for _, priKey := range priKeys {
 			if s := priKey.Pri.SignHash(consensusMsg.BlockHash); s != nil {
 				sig.Add(s)
+				signedCount++
+			} else {
+				consensus.getLogger().Warn().
+					Str("phase", p.String()).
+					Str("pubKey", priKey.Pub.Bytes.Hex()).
+					Uint64("blockNum", consensusMsg.BlockNum).
+					Uint64("viewID", consensusMsg.ViewId).
+					Hex("blockHash", consensusMsg.BlockHash).
+					Msg("[construct] BLS signing returned nil")
 			}
 		}
 		consensusMsg.Payload = sig.Serialize()
+		consensus.getLogger().Info().
+			Str("phase", p.String()).
+			Int("keysProvided", len(priKeys)).
+			Int("signedCount", signedCount).
+			Int("payloadLen", len(consensusMsg.Payload)).
+			Uint64("blockNum", consensusMsg.BlockNum).
+			Uint64("viewID", consensusMsg.ViewId).
+			Hex("blockHash", consensusMsg.BlockHash).
+			Msg("[construct] Constructed validator consensus signature")
 	case msg_pb.MessageType_COMMIT:
 		needMsgSig = false
 		sig := bls_core.Sign{}
+		signedCount := 0
 		for _, priKey := range priKeys {
 			if s := priKey.Pri.SignHash(payloadForSign); s != nil {
 				sig.Add(s)
+				signedCount++
+			} else {
+				consensus.getLogger().Warn().
+					Str("phase", p.String()).
+					Str("pubKey", priKey.Pub.Bytes.Hex()).
+					Uint64("blockNum", consensusMsg.BlockNum).
+					Uint64("viewID", consensusMsg.ViewId).
+					Hex("blockHash", consensusMsg.BlockHash).
+					Int("commitPayloadLen", len(payloadForSign)).
+					Hex("commitPayload", payloadForSign).
+					Msg("[construct] BLS signing returned nil")
 			}
 		}
 		consensusMsg.Payload = sig.Serialize()
+		consensus.getLogger().Info().
+			Str("phase", p.String()).
+			Int("keysProvided", len(priKeys)).
+			Int("signedCount", signedCount).
+			Int("payloadLen", len(consensusMsg.Payload)).
+			Uint64("blockNum", consensusMsg.BlockNum).
+			Uint64("viewID", consensusMsg.ViewId).
+			Hex("blockHash", consensusMsg.BlockHash).
+			Int("commitPayloadLen", len(payloadForSign)).
+			Hex("commitPayload", payloadForSign).
+			Msg("[construct] Constructed validator consensus signature")
 	case msg_pb.MessageType_PREPARED:
 		consensusMsg.Block = consensus.current.block
 		consensusMsg.Payload = consensus.constructQuorumSigAndBitmap(quorum.Prepare)

consensus/leader.go

@@ -221,6 +221,11 @@ func (consensus *Consensus) onPrepare(recvMsg *FBFTMessage) {
 func (consensus *Consensus) onCommit(recvMsg *FBFTMessage) {
 	//// Read - Start
 	if !consensus.isRightBlockNumAndViewID(recvMsg) {
+		consensus.getLogger().Warn().
+			Uint64("msgBlockNum", recvMsg.BlockNum).
+			Uint64("msgViewID", recvMsg.ViewID).
+			Str("msgBlockHash", recvMsg.BlockHash.Hex()).
+			Msg("[OnCommit] ignoring commit with mismatched block number or view ID")
 		return
 	}
 	// proceed only when the message is not received before
@@ -255,7 +260,11 @@ func (consensus *Consensus) onCommit(recvMsg *FBFTMessage) {
 	logger.Debug().Msg("[OnCommit] Received new commit message")
 	var sign bls_core.Sign
 	if err := sign.Deserialize(recvMsg.Payload); err != nil {
-		logger.Debug().Msg("[OnCommit] Failed to deserialize bls signature")
+		logger.Warn().
+			Err(err).
+			Int("payloadLen", len(recvMsg.Payload)).
+			Hex("payload", recvMsg.Payload).
+			Msg("[OnCommit] Failed to deserialize bls signature")
 		return
 	}
 
@@ -274,6 +283,11 @@ func (consensus *Consensus) onCommit(recvMsg *FBFTMessage) {
 	logger = logger.With().
 		Uint64("MsgViewID", recvMsg.ViewID).
 		Uint64("MsgBlockNum", recvMsg.BlockNum).
+		Uint64("blockNum", blockObj.NumberU64()).
+		Uint64("blockViewID", blockObj.Header().ViewID().Uint64()).
+		Str("blockHash", blockObj.Hash().Hex()).
+		Int("commitPayloadLen", len(commitPayload)).
+		Hex("commitPayload", commitPayload).
 		Logger()
 
 	signerPubKey := &bls_core.PublicKey{}
@@ -285,9 +299,17 @@ func (consensus *Consensus) onCommit(recvMsg *FBFTMessage) {
 		}
 	}
 	if !sign.VerifyHash(signerPubKey, commitPayload) {
-		logger.Error().Msg("[OnCommit] Cannot verify commit message")
+		logger.Error().
+			Str("signerPubKey", signerPubKey.SerializeToHexStr()).
+			Int("signatureLen", len(recvMsg.Payload)).
+			Hex("signature", recvMsg.Payload).
+			Msg("[OnCommit] Cannot verify commit message")
 		return
 	}
+	logger.Info().
+		Int("signersInMessage", len(recvMsg.SenderPubkeys)).
+		Str("signerPubKey", signerPubKey.SerializeToHexStr()).
+		Msg("[OnCommit] verified commit signature")
 
 	//// Write - Start
 	// Check for potential double signing
@@ -303,6 +325,7 @@ func (consensus *Consensus) onCommit(recvMsg *FBFTMessage) {
 		&sign, recvMsg.BlockHash,
 		recvMsg.BlockNum, recvMsg.ViewID,
 	); err != nil {
+		logger.Warn().Err(err).Msg("[OnCommit] submit vote commit failed")
 		return
 	}
 	// Set the bitmap indicating that this validator signed.
@@ -311,6 +334,11 @@ func (consensus *Consensus) onCommit(recvMsg *FBFTMessage) {
 			Msg("[OnCommit] commitBitmap.SetKey failed")
 		return
 	}
+	logger.Info().
+		Int64("numReceivedBefore", signerCount).
+		Int64("numReceivedAfter", consensus.decider().SignersCount(quorum.Commit)).
+		Bool("quorumWasMet", quorumWasMet).
+		Msg("[OnCommit] accepted commit vote")
 	//// Write - End
 
 	//// Read - Start
@@ -337,6 +365,24 @@ func (consensus *Consensus) onCommit(recvMsg *FBFTMessage) {
 		if maxWaitTime > waitTime {
 			waitTime = maxWaitTime
 		}
+		epoch := consensus.Blockchain().CurrentBlock().Epoch()
+		finalCommitNoWait := consensus.Blockchain().Config().IsFinalCommitNoWait(epoch)
+		oneSecondBlock := consensus.Blockchain().Config().IsOneSecond(epoch)
+		if finalCommitNoWait {
+			waitTime = 0
+		}
+		if oneSecondBlock {
+			waitTime = time.Until(consensus.NextBlockDue) - 200*time.Millisecond
+			if waitTime < 0 {
+				waitTime = 0
+			}
+		}
+		logger.Info().
+			Str("maxWaitTime", maxWaitTime.String()).
+			Str("waitTime", waitTime.String()).
+			Bool("finalCommitNoWait", finalCommitNoWait).
+			Bool("oneSecondBlock", oneSecondBlock).
+			Msg("[OnCommit] calculated final commit grace period")
 		go consensus.finalCommit(waitTime, viewID, consensus.isLeader())
 
 		consensus.msgSender.StopRetry(msg_pb.MessageType_PREPARED)

consensus/validator.go

@@ -178,6 +178,14 @@ func (consensus *Consensus) sendCommitMessages(blockObj *types.Block) {
 	// Sign commit signature on the received block and construct the p2p messages
 	commitPayload := signature.ConstructCommitPayload(consensus.Blockchain().Config(),
 		blockObj.Epoch(), blockObj.Hash(), blockObj.NumberU64(), blockObj.Header().ViewID().Uint64())
+	consensus.getLogger().Info().
+		Uint64("blockNum", blockObj.NumberU64()).
+		Uint64("viewID", blockObj.Header().ViewID().Uint64()).
+		Str("blockHash", blockObj.Hash().Hex()).
+		Int("commitPayloadLen", len(commitPayload)).
+		Hex("commitPayload", commitPayload).
+		Int("keys", len(priKeys)).
+		Msg("[sendCommitMessages] signing commit payload")
 
 	p2pMsgs := consensus.constructP2pMessages(msg_pb.MessageType_COMMIT, commitPayload, priKeys)
 
@@ -187,6 +195,7 @@ func (consensus *Consensus) sendCommitMessages(blockObj *types.Block) {
 		consensus.getLogger().Info().
 			Uint64("blockNum", consensus.BlockNum()).
 			Hex("blockHash", consensus.current.blockHash[:]).
+			Int("messages", len(p2pMsgs)).
 			Msg("[sendCommitMessages] Sent Commit Message!!")
 	}
 }
@@ -416,15 +425,29 @@ func (consensus *Consensus) getPriKeysInCommittee() ([]*bls.PrivateKeyWrapper, e
 	priKeys := []*bls.PrivateKeyWrapper{}
 	for i, key := range consensus.priKey {
 		if !consensus.isValidatorInCommittee(key.Pub.Bytes) {
+			consensus.getLogger().Debug().
+				Str("pubKey", key.Pub.Bytes.Hex()).
+				Msg("[getPriKeysInCommittee] local BLS key is not in committee")
 			continue
 		}
 		priKeys = append(priKeys, &consensus.priKey[i])
 	}
+	consensus.getLogger().Info().
+		Int("localKeys", len(consensus.priKey)).
+		Int("committeeKeys", len(priKeys)).
+		Msg("[getPriKeysInCommittee] selected local committee keys")
 	return priKeys, nil
 }
 
 func (consensus *Consensus) constructP2pMessages(msgType msg_pb.MessageType, payloadForSign []byte, priKeys []*bls.PrivateKeyWrapper) []*NetworkMessage {
 	p2pMsgs := []*NetworkMessage{}
+	consensus.getLogger().Info().
+		Str("messageType", msgType.String()).
+		Bool("aggregateSig", consensus.AggregateSig).
+		Int("keys", len(priKeys)).
+		Int("payloadForSignLen", len(payloadForSign)).
+		Hex("payloadForSign", payloadForSign).
+		Msg("[constructP2pMessages] constructing consensus p2p messages")
 	if consensus.AggregateSig {
 		networkMessage, err := consensus.construct(msgType, payloadForSign, priKeys)
 		if err != nil {
@@ -452,6 +475,10 @@ func (consensus *Consensus) constructP2pMessages(msgType msg_pb.MessageType, pay
 			p2pMsgs = append(p2pMsgs, networkMessage)
 		}
 	}
+	consensus.getLogger().Info().
+		Str("messageType", msgType.String()).
+		Int("messages", len(p2pMsgs)).
+		Msg("[constructP2pMessages] constructed consensus p2p messages")
 	return p2pMsgs
 }
 
@@ -461,12 +488,21 @@ func (consensus *Consensus) broadcastConsensusP2pMessages(p2pMsgs []*NetworkMess
 	for _, p2pMsg := range p2pMsgs {
 		// TODO: this will not return immediately, may block
 		if consensus.current.Mode() != Listening {
+			consensus.getLogger().Info().
+				Str("messageType", p2pMsg.MessageType.String()).
+				Int("messageBytes", len(p2pMsg.Bytes)).
+				Str("groupID", groupID[0].String()).
+				Msg("[broadcastConsensusP2pMessages] sending consensus message")
 			if err := consensus.msgSender.SendWithoutRetry(
 				groupID,
 				p2p.ConstructMessage(p2pMsg.Bytes),
 			); err != nil {
 				return err
 			}
+		} else {
+			consensus.getLogger().Warn().
+				Str("messageType", p2pMsg.MessageType.String()).
+				Msg("[broadcastConsensusP2pMessages] not sending consensus message in Listening mode")
 		}
 	}
 	return nil

internal/params/config.go

@@ -272,6 +272,7 @@ var (
 		EIP8024Epoch:                          big.NewInt(49685),
 		EIP6780Epoch:                          big.NewInt(49810),
 		PragueEpoch:                           EpochTBD,
+		FinalCommitNoWaitEpoch:                big.NewInt(50200),
 	}
 
 	// StressnetChainConfig contains the chain parameters for the Stress test network.
@@ -453,6 +454,7 @@ var (
 		big.NewInt(0),                      // TimestampValidationEpoch
 		big.NewInt(0),                      // PragueEpoch
 		big.NewInt(0),                      // EIP8024Epoch
+		EpochTBD,                           // FinalCommitNoWaitEpoch
 	}
 
 	// TestChainConfig ...
@@ -515,6 +517,7 @@ var (
 		big.NewInt(0),        // TimestampValidationEpoch
 		big.NewInt(0),        // PragueEpoch
 		big.NewInt(0),        // EIP8024Epoch
+		EpochTBD,             // FinalCommitNoWaitEpoch
 	}
 
 	// TestRules ...
@@ -726,6 +729,10 @@ type ChainConfig struct {
 	PragueEpoch *big.Int `json:"prague-epoch,omitempty"`
 	// EIP8024Epoch is the first epoch to support EIP-8024 (DUPN, SWAPN, EXCHANGE opcodes)
 	EIP8024Epoch *big.Int `json:"eip8024-epoch,omitempty"`
+
+	// FinalCommitNoWaitEpoch is the first epoch where the final commit is
+	// triggered immediately without waiting (zero wait time).
+	FinalCommitNoWaitEpoch *big.Int `json:"final-commit-no-wait-epoch,omitempty"`
 }
 
 // String implements the fmt.Stringer interface.
@@ -1038,6 +1045,10 @@ func (c *ChainConfig) IsLeaderRotationV2Epoch(epoch *big.Int) bool {
 	return isForked(c.LeaderRotationV2Epoch, epoch)
 }
 
+func (c *ChainConfig) IsFinalCommitNoWait(epoch *big.Int) bool {
+	return isForked(c.FinalCommitNoWaitEpoch, epoch)
+}
+
 // IsFeeCollectEpoch determines whether Txn Fees will be collected into the community-managed account.
 func (c *ChainConfig) IsFeeCollectEpoch(epoch *big.Int) bool {
 	return isForked(c.FeeCollectEpoch, epoch)