diff --git a/consensus/construct.go b/consensus/construct.go index dab4026918..720335dd2b 100644 --- a/consensus/construct.go +++ b/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) diff --git a/consensus/leader.go b/consensus/leader.go index af7e39a0d7..994c6e9b8f 100644 --- a/consensus/leader.go +++ b/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) diff --git a/consensus/validator.go b/consensus/validator.go index 874edb0ef8..242a9da415 100644 --- a/consensus/validator.go +++ b/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 diff --git a/internal/params/config.go b/internal/params/config.go index b98f43b834..acfdf02307 100644 --- a/internal/params/config.go +++ b/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)