PoS_EVM
/
woop
1
0
Fork 0
Code Issues Pull Requests Packages Projects Releases Wiki Activity

make consensus log verbose

Browse Source
pull/1970/head
chao 5 years ago
parent b7282a1ef3
commit 20feb3a2f7
2 changed files with 174 additions and 169 deletions
Show all changes Ignore whitespace when comparing lines Ignore changes in amount of whitespace Ignore changes in whitespace at EOL
Show Stats Download Patch File Download Diff File
  1. 239
      consensus/consensus_v2.go
  2. 104
      consensus/view_change.go

239
consensus/consensus_v2.go
Unescape View File

@ -19,7 +19,6 @@ import (
"github.com/harmony-one/harmony/internal/chain" "github.com/harmony-one/harmony/internal/chain"
nodeconfig "github.com/harmony-one/harmony/internal/configs/node" nodeconfig "github.com/harmony-one/harmony/internal/configs/node"
"github.com/harmony-one/harmony/internal/ctxerror" "github.com/harmony-one/harmony/internal/ctxerror"
"github.com/harmony-one/harmony/internal/utils"
"github.com/harmony-one/harmony/p2p/host" "github.com/harmony-one/harmony/p2p/host"
"github.com/harmony-one/harmony/shard" "github.com/harmony-one/harmony/shard"
"github.com/harmony-one/vdf/src/vdf_go" "github.com/harmony-one/vdf/src/vdf_go"
@ -50,7 +49,7 @@ func (consensus *Consensus) handleMessageUpdate(payload []byte) {
if msg.Type == msg_pb.MessageType_VIEWCHANGE || msg.Type == msg_pb.MessageType_NEWVIEW { if msg.Type == msg_pb.MessageType_VIEWCHANGE || msg.Type == msg_pb.MessageType_NEWVIEW {
if msg.GetViewchange() != nil && msg.GetViewchange().ShardId != consensus.ShardID { if msg.GetViewchange() != nil && msg.GetViewchange().ShardId != consensus.ShardID {
utils.Logger().Warn(). consensus.getLogger().Warn().
Uint32("myShardId", consensus.ShardID). Uint32("myShardId", consensus.ShardID).
Uint32("receivedShardId", msg.GetViewchange().ShardId). Uint32("receivedShardId", msg.GetViewchange().ShardId).
Msg("Received view change message from different shard") Msg("Received view change message from different shard")
@ -58,7 +57,7 @@ func (consensus *Consensus) handleMessageUpdate(payload []byte) {
} }
} else { } else {
if msg.GetConsensus() != nil && msg.GetConsensus().ShardId != consensus.ShardID { if msg.GetConsensus() != nil && msg.GetConsensus().ShardId != consensus.ShardID {
utils.Logger().Warn(). consensus.getLogger().Warn().
Uint32("myShardId", consensus.ShardID). Uint32("myShardId", consensus.ShardID).
Uint32("receivedShardId", msg.GetConsensus().ShardId). Uint32("receivedShardId", msg.GetConsensus().ShardId).
Msg("Received consensus message from different shard") Msg("Received consensus message from different shard")
@ -100,12 +99,12 @@ func (consensus *Consensus) announce(block *types.Block) {
// prepare message and broadcast to validators // prepare message and broadcast to validators
encodedBlock, err := rlp.EncodeToBytes(block) encodedBlock, err := rlp.EncodeToBytes(block)
if err != nil { if err != nil {
utils.Logger().Debug().Msg("[Announce] Failed encoding block") consensus.getLogger().Debug().Msg("[Announce] Failed encoding block")
return return
} }
encodedBlockHeader, err := rlp.EncodeToBytes(block.Header()) encodedBlockHeader, err := rlp.EncodeToBytes(block.Header())
if err != nil { if err != nil {
utils.Logger().Debug().Msg("[Announce] Failed encoding block header") consensus.getLogger().Debug().Msg("[Announce] Failed encoding block header")
return return
} }
@ -120,13 +119,13 @@ func (consensus *Consensus) announce(block *types.Block) {
_ = protobuf.Unmarshal(msgPayload, msg) _ = protobuf.Unmarshal(msgPayload, msg)
FPBTMsg, err := ParseFBFTMessage(msg) FPBTMsg, err := ParseFBFTMessage(msg)
if err != nil { if err != nil {
utils.Logger().Warn().Err(err).Msg("[Announce] Unable to parse FPBT message") consensus.getLogger().Warn().Err(err).Msg("[Announce] Unable to parse FPBT message")
return return
} }
// TODO(chao): review FPBT log data structure // TODO(chao): review FPBT log data structure
consensus.FBFTLog.AddMessage(FPBTMsg) consensus.FBFTLog.AddMessage(FPBTMsg)
utils.Logger().Debug(). consensus.getLogger().Debug().
Str("MsgBlockHash", FPBTMsg.BlockHash.Hex()). Str("MsgBlockHash", FPBTMsg.BlockHash.Hex()).
Uint64("MsgViewID", FPBTMsg.ViewID). Uint64("MsgViewID", FPBTMsg.ViewID).
Uint64("MsgBlockNum", FPBTMsg.BlockNum). Uint64("MsgBlockNum", FPBTMsg.BlockNum).
@ -138,7 +137,7 @@ func (consensus *Consensus) announce(block *types.Block) {
quorum.Prepare, consensus.PubKey, consensus.priKey.SignHash(consensus.blockHash[:]), quorum.Prepare, consensus.PubKey, consensus.priKey.SignHash(consensus.blockHash[:]),
) )
if err := consensus.prepareBitmap.SetKey(consensus.PubKey, true); err != nil { if err := consensus.prepareBitmap.SetKey(consensus.PubKey, true); err != nil {
utils.Logger().Warn().Err(err).Msg("[Announce] Leader prepareBitmap SetKey failed") consensus.getLogger().Warn().Err(err).Msg("[Announce] Leader prepareBitmap SetKey failed")
return return
} }
@ -147,19 +146,19 @@ func (consensus *Consensus) announce(block *types.Block) {
consensus.blockNum, msg_pb.MessageType_ANNOUNCE, []nodeconfig.GroupID{ consensus.blockNum, msg_pb.MessageType_ANNOUNCE, []nodeconfig.GroupID{
nodeconfig.NewGroupIDByShardID(nodeconfig.ShardID(consensus.ShardID)), nodeconfig.NewGroupIDByShardID(nodeconfig.ShardID(consensus.ShardID)),
}, host.ConstructP2pMessage(byte(17), msgToSend)); err != nil { }, host.ConstructP2pMessage(byte(17), msgToSend)); err != nil {
utils.Logger().Warn(). consensus.getLogger().Warn().
Str("groupID", string(nodeconfig.NewGroupIDByShardID( Str("groupID", string(nodeconfig.NewGroupIDByShardID(
nodeconfig.ShardID(consensus.ShardID), nodeconfig.ShardID(consensus.ShardID),
))). ))).
Msg("[Announce] Cannot send announce message") Msg("[Announce] Cannot send announce message")
} else { } else {
utils.Logger().Info(). consensus.getLogger().Info().
Str("blockHash", block.Hash().Hex()). Str("blockHash", block.Hash().Hex()).
Uint64("blockNum", block.NumberU64()). Uint64("blockNum", block.NumberU64()).
Msg("[Announce] Sent Announce Message!!") Msg("[Announce] Sent Announce Message!!")
} }
utils.Logger().Debug(). consensus.getLogger().Debug().
Str("From", consensus.phase.String()). Str("From", consensus.phase.String()).
Str("To", FBFTPrepare.String()). Str("To", FBFTPrepare.String()).
Msg("[Announce] Switching phase") Msg("[Announce] Switching phase")
@ -167,32 +166,32 @@ func (consensus *Consensus) announce(block *types.Block) {
} }
func (consensus *Consensus) onAnnounce(msg *msg_pb.Message) { func (consensus *Consensus) onAnnounce(msg *msg_pb.Message) {
utils.Logger().Debug().Msg("[OnAnnounce] Receive announce message") consensus.getLogger().Debug().Msg("[OnAnnounce] Receive announce message")
if consensus.IsLeader() && consensus.current.Mode() == Normal { if consensus.IsLeader() && consensus.current.Mode() == Normal {
return return
} }
senderKey, err := consensus.verifySenderKey(msg) senderKey, err := consensus.verifySenderKey(msg)
if err != nil { if err != nil {
utils.Logger().Error().Err(err).Msg("[OnAnnounce] VerifySenderKey failed") consensus.getLogger().Error().Err(err).Msg("[OnAnnounce] VerifySenderKey failed")
return return
} }
if !senderKey.IsEqual(consensus.LeaderPubKey) && if !senderKey.IsEqual(consensus.LeaderPubKey) &&
consensus.current.Mode() == Normal && !consensus.ignoreViewIDCheck { consensus.current.Mode() == Normal && !consensus.ignoreViewIDCheck {
utils.Logger().Warn(). consensus.getLogger().Warn().
Str("senderKey", senderKey.SerializeToHexStr()). Str("senderKey", senderKey.SerializeToHexStr()).
Str("leaderKey", consensus.LeaderPubKey.SerializeToHexStr()). Str("leaderKey", consensus.LeaderPubKey.SerializeToHexStr()).
Msg("[OnAnnounce] SenderKey does not match leader PubKey") Msg("[OnAnnounce] SenderKey does not match leader PubKey")
return return
} }
if err = verifyMessageSig(senderKey, msg); err != nil { if err = verifyMessageSig(senderKey, msg); err != nil {
utils.Logger().Error().Err(err).Msg("[OnAnnounce] Failed to verify leader signature") consensus.getLogger().Error().Err(err).Msg("[OnAnnounce] Failed to verify leader signature")
return return
} }
recvMsg, err := ParseFBFTMessage(msg) recvMsg, err := ParseFBFTMessage(msg)
if err != nil { if err != nil {
utils.Logger().Error(). consensus.getLogger().Error().
Err(err). Err(err).
Uint64("MsgBlockNum", recvMsg.BlockNum). Uint64("MsgBlockNum", recvMsg.BlockNum).
Msg("[OnAnnounce] Unparseable leader message") Msg("[OnAnnounce] Unparseable leader message")
@ -205,7 +204,7 @@ func (consensus *Consensus) onAnnounce(msg *msg_pb.Message) {
header := new(block.Header) header := new(block.Header)
err = rlp.DecodeBytes(encodedHeader, header) err = rlp.DecodeBytes(encodedHeader, header)
if err != nil { if err != nil {
utils.Logger().Warn(). consensus.getLogger().Warn().
Err(err). Err(err).
Uint64("MsgBlockNum", recvMsg.BlockNum). Uint64("MsgBlockNum", recvMsg.BlockNum).
Msg("[OnAnnounce] Unparseable block header data") Msg("[OnAnnounce] Unparseable block header data")
@ -213,7 +212,7 @@ func (consensus *Consensus) onAnnounce(msg *msg_pb.Message) {
} }
if recvMsg.BlockNum < consensus.blockNum || recvMsg.BlockNum != header.Number().Uint64() { if recvMsg.BlockNum < consensus.blockNum || recvMsg.BlockNum != header.Number().Uint64() {
utils.Logger().Debug(). consensus.getLogger().Debug().
Uint64("MsgBlockNum", recvMsg.BlockNum). Uint64("MsgBlockNum", recvMsg.BlockNum).
Uint64("hdrBlockNum", header.Number().Uint64()). Uint64("hdrBlockNum", header.Number().Uint64()).
Uint64("consensuBlockNum", consensus.blockNum). Uint64("consensuBlockNum", consensus.blockNum).
@ -222,7 +221,7 @@ func (consensus *Consensus) onAnnounce(msg *msg_pb.Message) {
} }
if consensus.current.Mode() == Normal { if consensus.current.Mode() == Normal {
if err = chain.Engine.VerifyHeader(consensus.ChainReader, header, true); err != nil { if err = chain.Engine.VerifyHeader(consensus.ChainReader, header, true); err != nil {
utils.Logger().Warn(). consensus.getLogger().Warn().
Err(err). Err(err).
Str("inChain", consensus.ChainReader.CurrentHeader().Number().String()). Str("inChain", consensus.ChainReader.CurrentHeader().Number().String()).
Str("MsgBlockNum", header.Number().String()). Str("MsgBlockNum", header.Number().String()).
@ -254,18 +253,24 @@ func (consensus *Consensus) onAnnounce(msg *msg_pb.Message) {
if len(logMsgs) > 0 { if len(logMsgs) > 0 {
if logMsgs[0].BlockHash != recvMsg.BlockHash && if logMsgs[0].BlockHash != recvMsg.BlockHash &&
logMsgs[0].SenderPubkey.IsEqual(recvMsg.SenderPubkey) { logMsgs[0].SenderPubkey.IsEqual(recvMsg.SenderPubkey) {
utils.Logger().Debug(). consensus.getLogger().Debug().
Str("leaderKey", consensus.LeaderPubKey.SerializeToHexStr()). Str("logMsgSenderKey", logMsgs[0].SenderPubkey.SerializeToHexStr()).
Str("logMsgBlockHash", logMsgs[0].BlockHash.Hex()).
Str("recvMsg.SenderPubkey", recvMsg.SenderPubkey.SerializeToHexStr()).
Uint64("recvMsg.BlockNum", recvMsg.BlockNum).
Uint64("recvMsg.ViewID", recvMsg.ViewID).
Str("recvMsgBlockHash", recvMsg.BlockHash.Hex()).
Str("LeaderKey", consensus.LeaderPubKey.SerializeToHexStr()).
Msg("[OnAnnounce] Leader is malicious") Msg("[OnAnnounce] Leader is malicious")
consensus.startViewChange(consensus.viewID + 1) consensus.startViewChange(consensus.viewID + 1)
} }
utils.Logger().Debug(). consensus.getLogger().Debug().
Str("leaderKey", consensus.LeaderPubKey.SerializeToHexStr()). Str("leaderKey", consensus.LeaderPubKey.SerializeToHexStr()).
Msg("[OnAnnounce] Announce message received again") Msg("[OnAnnounce] Announce message received again")
//return //return
} }
utils.Logger().Debug(). consensus.getLogger().Debug().
Uint64("MsgViewID", recvMsg.ViewID). Uint64("MsgViewID", recvMsg.ViewID).
Uint64("MsgBlockNum", recvMsg.BlockNum). Uint64("MsgBlockNum", recvMsg.BlockNum).
Msg("[OnAnnounce] Announce message Added") Msg("[OnAnnounce] Announce message Added")
@ -278,13 +283,13 @@ func (consensus *Consensus) onAnnounce(msg *msg_pb.Message) {
// we have already added message and block, skip check viewID and send prepare message if is in ViewChanging mode // we have already added message and block, skip check viewID and send prepare message if is in ViewChanging mode
if consensus.current.Mode() == ViewChanging { if consensus.current.Mode() == ViewChanging {
utils.Logger().Debug().Msg("[OnAnnounce] Still in ViewChanging Mode, Exiting !!") consensus.getLogger().Debug().Msg("[OnAnnounce] Still in ViewChanging Mode, Exiting !!")
return return
} }
if consensus.checkViewID(recvMsg) != nil { if consensus.checkViewID(recvMsg) != nil {
if consensus.current.Mode() == Normal { if consensus.current.Mode() == Normal {
utils.Logger().Debug(). consensus.getLogger().Debug().
Uint64("MsgViewID", recvMsg.ViewID). Uint64("MsgViewID", recvMsg.ViewID).
Uint64("MsgBlockNum", recvMsg.BlockNum). Uint64("MsgBlockNum", recvMsg.BlockNum).
Msg("[OnAnnounce] ViewID check failed") Msg("[OnAnnounce] ViewID check failed")
@ -303,13 +308,13 @@ func (consensus *Consensus) prepare() {
// TODO: this will not return immediatey, may block // TODO: this will not return immediatey, may block
if err := consensus.msgSender.SendWithoutRetry([]nodeconfig.GroupID{nodeconfig.NewGroupIDByShardID(nodeconfig.ShardID(consensus.ShardID))}, host.ConstructP2pMessage(byte(17), msgToSend)); err != nil { if err := consensus.msgSender.SendWithoutRetry([]nodeconfig.GroupID{nodeconfig.NewGroupIDByShardID(nodeconfig.ShardID(consensus.ShardID))}, host.ConstructP2pMessage(byte(17), msgToSend)); err != nil {
utils.Logger().Warn().Err(err).Msg("[OnAnnounce] Cannot send prepare message") consensus.getLogger().Warn().Err(err).Msg("[OnAnnounce] Cannot send prepare message")
} else { } else {
utils.Logger().Info(). consensus.getLogger().Info().
Str("blockHash", hex.EncodeToString(consensus.blockHash[:])). Str("blockHash", hex.EncodeToString(consensus.blockHash[:])).
Msg("[OnAnnounce] Sent Prepare Message!!") Msg("[OnAnnounce] Sent Prepare Message!!")
} }
utils.Logger().Debug(). consensus.getLogger().Debug().
Str("From", consensus.phase.String()). Str("From", consensus.phase.String()).
Str("To", FBFTPrepare.String()). Str("To", FBFTPrepare.String()).
Msg("[Announce] Switching Phase") Msg("[Announce] Switching Phase")
@ -324,22 +329,22 @@ func (consensus *Consensus) onPrepare(msg *msg_pb.Message) {
senderKey, err := consensus.verifySenderKey(msg) senderKey, err := consensus.verifySenderKey(msg)
if err != nil { if err != nil {
utils.Logger().Error().Err(err).Msg("[OnPrepare] VerifySenderKey failed") consensus.getLogger().Error().Err(err).Msg("[OnPrepare] VerifySenderKey failed")
return return
} }
if err = verifyMessageSig(senderKey, msg); err != nil { if err = verifyMessageSig(senderKey, msg); err != nil {
utils.Logger().Error().Err(err).Msg("[OnPrepare] Failed to verify sender's signature") consensus.getLogger().Error().Err(err).Msg("[OnPrepare] Failed to verify sender's signature")
return return
} }
recvMsg, err := ParseFBFTMessage(msg) recvMsg, err := ParseFBFTMessage(msg)
if err != nil { if err != nil {
utils.Logger().Error().Err(err).Msg("[OnPrepare] Unparseable validator message") consensus.getLogger().Error().Err(err).Msg("[OnPrepare] Unparseable validator message")
return return
} }
if recvMsg.ViewID != consensus.viewID || recvMsg.BlockNum != consensus.blockNum { if recvMsg.ViewID != consensus.viewID || recvMsg.BlockNum != consensus.blockNum {
utils.Logger().Debug(). consensus.getLogger().Debug().
Uint64("MsgViewID", recvMsg.ViewID). Uint64("MsgViewID", recvMsg.ViewID).
Uint64("MsgBlockNum", recvMsg.BlockNum). Uint64("MsgBlockNum", recvMsg.BlockNum).
Uint64("blockNum", consensus.blockNum). Uint64("blockNum", consensus.blockNum).
@ -350,7 +355,7 @@ func (consensus *Consensus) onPrepare(msg *msg_pb.Message) {
if !consensus.FBFTLog.HasMatchingViewAnnounce( if !consensus.FBFTLog.HasMatchingViewAnnounce(
consensus.blockNum, consensus.viewID, recvMsg.BlockHash, consensus.blockNum, consensus.viewID, recvMsg.BlockHash,
) { ) {
utils.Logger().Debug(). consensus.getLogger().Debug().
Uint64("MsgViewID", recvMsg.ViewID). Uint64("MsgViewID", recvMsg.ViewID).
Uint64("MsgBlockNum", recvMsg.BlockNum). Uint64("MsgBlockNum", recvMsg.BlockNum).
Uint64("blockNum", consensus.blockNum). Uint64("blockNum", consensus.blockNum).
@ -364,7 +369,7 @@ func (consensus *Consensus) onPrepare(msg *msg_pb.Message) {
consensus.mutex.Lock() consensus.mutex.Lock()
defer consensus.mutex.Unlock() defer consensus.mutex.Unlock()
logger := utils.Logger().With(). logger := consensus.getLogger().With().
Str("validatorPubKey", validatorPubKey.SerializeToHexStr()).Logger() Str("validatorPubKey", validatorPubKey.SerializeToHexStr()).Logger()
// proceed only when the message is not received before // proceed only when the message is not received before
@ -385,12 +390,12 @@ func (consensus *Consensus) onPrepare(msg *msg_pb.Message) {
var sign bls.Sign var sign bls.Sign
err = sign.Deserialize(prepareSig) err = sign.Deserialize(prepareSig)
if err != nil { if err != nil {
utils.Logger().Error().Err(err). consensus.getLogger().Error().Err(err).
Msg("[OnPrepare] Failed to deserialize bls signature") Msg("[OnPrepare] Failed to deserialize bls signature")
return return
} }
if !sign.VerifyHash(recvMsg.SenderPubkey, consensus.blockHash[:]) { if !sign.VerifyHash(recvMsg.SenderPubkey, consensus.blockHash[:]) {
utils.Logger().Error().Msg("[OnPrepare] Received invalid BLS signature") consensus.getLogger().Error().Msg("[OnPrepare] Received invalid BLS signature")
return return
} }
@ -401,7 +406,7 @@ func (consensus *Consensus) onPrepare(msg *msg_pb.Message) {
consensus.Decider.AddSignature(quorum.Prepare, validatorPubKey, &sign) consensus.Decider.AddSignature(quorum.Prepare, validatorPubKey, &sign)
// Set the bitmap indicating that this validator signed. // Set the bitmap indicating that this validator signed.
if err := prepareBitmap.SetKey(recvMsg.SenderPubkey, true); err != nil { if err := prepareBitmap.SetKey(recvMsg.SenderPubkey, true); err != nil {
utils.Logger().Warn().Err(err).Msg("[OnPrepare] prepareBitmap.SetKey failed") consensus.getLogger().Warn().Err(err).Msg("[OnPrepare] prepareBitmap.SetKey failed")
return return
} }
@ -419,7 +424,7 @@ func (consensus *Consensus) onPrepare(msg *msg_pb.Message) {
FBFTMsg, err := ParseFBFTMessage(msg) FBFTMsg, err := ParseFBFTMessage(msg)
if err != nil { if err != nil {
utils.Logger().Warn().Err(err).Msg("[OnPrepare] Unable to parse pbft message") consensus.getLogger().Warn().Err(err).Msg("[OnPrepare] Unable to parse pbft message")
return return
} }
@ -433,7 +438,7 @@ func (consensus *Consensus) onPrepare(msg *msg_pb.Message) {
) )
if err := consensus.commitBitmap.SetKey(consensus.PubKey, true); err != nil { if err := consensus.commitBitmap.SetKey(consensus.PubKey, true); err != nil {
utils.Logger().Debug().Msg("[OnPrepare] Leader commit bitmap set failed") consensus.getLogger().Debug().Msg("[OnPrepare] Leader commit bitmap set failed")
return return
} }
@ -444,9 +449,9 @@ func (consensus *Consensus) onPrepare(msg *msg_pb.Message) {
}, },
host.ConstructP2pMessage(byte(17), msgToSend), host.ConstructP2pMessage(byte(17), msgToSend),
); err != nil { ); err != nil {
utils.Logger().Warn().Msg("[OnPrepare] Cannot send prepared message") consensus.getLogger().Warn().Msg("[OnPrepare] Cannot send prepared message")
} else { } else {
utils.Logger().Debug(). consensus.getLogger().Debug().
Hex("blockHash", consensus.blockHash[:]). Hex("blockHash", consensus.blockHash[:]).
Uint64("blockNum", consensus.blockNum). Uint64("blockNum", consensus.blockNum).
Msg("[OnPrepare] Sent Prepared Message!!") Msg("[OnPrepare] Sent Prepared Message!!")
@ -455,7 +460,7 @@ func (consensus *Consensus) onPrepare(msg *msg_pb.Message) {
// Stop retry committed msg of last consensus // Stop retry committed msg of last consensus
consensus.msgSender.StopRetry(msg_pb.MessageType_COMMITTED) consensus.msgSender.StopRetry(msg_pb.MessageType_COMMITTED)
utils.Logger().Debug(). consensus.getLogger().Debug().
Str("From", consensus.phase.String()). Str("From", consensus.phase.String()).
Str("To", FBFTCommit.String()). Str("To", FBFTCommit.String()).
Msg("[OnPrepare] Switching phase") Msg("[OnPrepare] Switching phase")
@ -465,38 +470,38 @@ func (consensus *Consensus) onPrepare(msg *msg_pb.Message) {
} }
func (consensus *Consensus) onPrepared(msg *msg_pb.Message) { func (consensus *Consensus) onPrepared(msg *msg_pb.Message) {
utils.Logger().Debug().Msg("[OnPrepared] Received Prepared message") consensus.getLogger().Debug().Msg("[OnPrepared] Received Prepared message")
if consensus.IsLeader() && consensus.current.Mode() == Normal { if consensus.IsLeader() && consensus.current.Mode() == Normal {
return return
} }
senderKey, err := consensus.verifySenderKey(msg) senderKey, err := consensus.verifySenderKey(msg)
if err != nil { if err != nil {
utils.Logger().Debug().Err(err).Msg("[OnPrepared] VerifySenderKey failed") consensus.getLogger().Debug().Err(err).Msg("[OnPrepared] VerifySenderKey failed")
return return
} }
if !senderKey.IsEqual(consensus.LeaderPubKey) && if !senderKey.IsEqual(consensus.LeaderPubKey) &&
consensus.current.Mode() == Normal && !consensus.ignoreViewIDCheck { consensus.current.Mode() == Normal && !consensus.ignoreViewIDCheck {
utils.Logger().Warn().Msg("[OnPrepared] SenderKey not match leader PubKey") consensus.getLogger().Warn().Msg("[OnPrepared] SenderKey not match leader PubKey")
return return
} }
if err := verifyMessageSig(senderKey, msg); err != nil { if err := verifyMessageSig(senderKey, msg); err != nil {
utils.Logger().Debug().Err(err).Msg("[OnPrepared] Failed to verify sender's signature") consensus.getLogger().Debug().Err(err).Msg("[OnPrepared] Failed to verify sender's signature")
return return
} }
recvMsg, err := ParseFBFTMessage(msg) recvMsg, err := ParseFBFTMessage(msg)
if err != nil { if err != nil {
utils.Logger().Debug().Err(err).Msg("[OnPrepared] Unparseable validator message") consensus.getLogger().Debug().Err(err).Msg("[OnPrepared] Unparseable validator message")
return return
} }
utils.Logger().Info(). consensus.getLogger().Info().
Uint64("MsgBlockNum", recvMsg.BlockNum). Uint64("MsgBlockNum", recvMsg.BlockNum).
Uint64("MsgViewID", recvMsg.ViewID). Uint64("MsgViewID", recvMsg.ViewID).
Msg("[OnPrepared] Received prepared message") Msg("[OnPrepared] Received prepared message")
if recvMsg.BlockNum < consensus.blockNum { if recvMsg.BlockNum < consensus.blockNum {
utils.Logger().Debug().Uint64("MsgBlockNum", recvMsg.BlockNum).Msg("Old Block Received, ignoring!!") consensus.getLogger().Debug().Uint64("MsgBlockNum", recvMsg.BlockNum).Msg("Old Block Received, ignoring!!")
return return
} }
@ -504,12 +509,12 @@ func (consensus *Consensus) onPrepared(msg *msg_pb.Message) {
blockHash := recvMsg.BlockHash blockHash := recvMsg.BlockHash
aggSig, mask, err := consensus.ReadSignatureBitmapPayload(recvMsg.Payload, 0) aggSig, mask, err := consensus.ReadSignatureBitmapPayload(recvMsg.Payload, 0)
if err != nil { if err != nil {
utils.Logger().Error().Err(err).Msg("ReadSignatureBitmapPayload failed!!") consensus.getLogger().Error().Err(err).Msg("ReadSignatureBitmapPayload failed!!")
return return
} }
if !consensus.Decider.IsQuorumAchievedByMask(mask) { if !consensus.Decider.IsQuorumAchievedByMask(mask) {
utils.Logger().Warn(). consensus.getLogger().Warn().
Msgf("[OnPrepared] Quorum Not achieved") Msgf("[OnPrepared] Quorum Not achieved")
return return
} }
@ -517,7 +522,7 @@ func (consensus *Consensus) onPrepared(msg *msg_pb.Message) {
if !aggSig.VerifyHash(mask.AggregatePublic, blockHash[:]) { if !aggSig.VerifyHash(mask.AggregatePublic, blockHash[:]) {
myBlockHash := common.Hash{} myBlockHash := common.Hash{}
myBlockHash.SetBytes(consensus.blockHash[:]) myBlockHash.SetBytes(consensus.blockHash[:])
utils.Logger().Warn(). consensus.getLogger().Warn().
Uint64("MsgBlockNum", recvMsg.BlockNum). Uint64("MsgBlockNum", recvMsg.BlockNum).
Uint64("MsgViewID", recvMsg.ViewID). Uint64("MsgViewID", recvMsg.ViewID).
Msg("[OnPrepared] failed to verify multi signature for prepare phase") Msg("[OnPrepared] failed to verify multi signature for prepare phase")
@ -529,21 +534,21 @@ func (consensus *Consensus) onPrepared(msg *msg_pb.Message) {
var blockObj types.Block var blockObj types.Block
err = rlp.DecodeBytes(block, &blockObj) err = rlp.DecodeBytes(block, &blockObj)
if err != nil { if err != nil {
utils.Logger().Warn(). consensus.getLogger().Warn().
Err(err). Err(err).
Uint64("MsgBlockNum", recvMsg.BlockNum). Uint64("MsgBlockNum", recvMsg.BlockNum).
Msg("[OnPrepared] Unparseable block header data") Msg("[OnPrepared] Unparseable block header data")
return return
} }
if blockObj.NumberU64() != recvMsg.BlockNum || recvMsg.BlockNum < consensus.blockNum { if blockObj.NumberU64() != recvMsg.BlockNum || recvMsg.BlockNum < consensus.blockNum {
utils.Logger().Warn(). consensus.getLogger().Warn().
Uint64("MsgBlockNum", recvMsg.BlockNum). Uint64("MsgBlockNum", recvMsg.BlockNum).
Uint64("blockNum", blockObj.NumberU64()). Uint64("blockNum", blockObj.NumberU64()).
Msg("[OnPrepared] BlockNum not match") Msg("[OnPrepared] BlockNum not match")
return return
} }
if blockObj.Header().Hash() != recvMsg.BlockHash { if blockObj.Header().Hash() != recvMsg.BlockHash {
utils.Logger().Warn(). consensus.getLogger().Warn().
Uint64("MsgBlockNum", recvMsg.BlockNum). Uint64("MsgBlockNum", recvMsg.BlockNum).
Hex("MsgBlockHash", recvMsg.BlockHash[:]). Hex("MsgBlockHash", recvMsg.BlockHash[:]).
Str("blockObjHash", blockObj.Header().Hash().Hex()). Str("blockObjHash", blockObj.Header().Hash().Hex()).
@ -553,7 +558,7 @@ func (consensus *Consensus) onPrepared(msg *msg_pb.Message) {
if consensus.current.Mode() == Normal { if consensus.current.Mode() == Normal {
err := chain.Engine.VerifyHeader(consensus.ChainReader, blockObj.Header(), true) err := chain.Engine.VerifyHeader(consensus.ChainReader, blockObj.Header(), true)
if err != nil { if err != nil {
utils.Logger().Error(). consensus.getLogger().Error().
Err(err). Err(err).
Str("inChain", consensus.ChainReader.CurrentHeader().Number().String()). Str("inChain", consensus.ChainReader.CurrentHeader().Number().String()).
Str("MsgBlockNum", blockObj.Header().Number().String()). Str("MsgBlockNum", blockObj.Header().Number().String()).
@ -563,7 +568,7 @@ func (consensus *Consensus) onPrepared(msg *msg_pb.Message) {
if consensus.BlockVerifier == nil { if consensus.BlockVerifier == nil {
// do nothing // do nothing
} else if err := consensus.BlockVerifier(&blockObj); err != nil { } else if err := consensus.BlockVerifier(&blockObj); err != nil {
utils.Logger().Error().Err(err).Msg("[OnPrepared] Block verification failed") consensus.getLogger().Error().Err(err).Msg("[OnPrepared] Block verification failed")
return return
} }
} }
@ -571,7 +576,7 @@ func (consensus *Consensus) onPrepared(msg *msg_pb.Message) {
consensus.FBFTLog.AddBlock(&blockObj) consensus.FBFTLog.AddBlock(&blockObj)
recvMsg.Block = []byte{} // save memory space recvMsg.Block = []byte{} // save memory space
consensus.FBFTLog.AddMessage(recvMsg) consensus.FBFTLog.AddMessage(recvMsg)
utils.Logger().Debug(). consensus.getLogger().Debug().
Uint64("MsgViewID", recvMsg.ViewID). Uint64("MsgViewID", recvMsg.ViewID).
Uint64("MsgBlockNum", recvMsg.BlockNum). Uint64("MsgBlockNum", recvMsg.BlockNum).
Hex("blockHash", recvMsg.BlockHash[:]). Hex("blockHash", recvMsg.BlockHash[:]).
@ -582,13 +587,13 @@ func (consensus *Consensus) onPrepared(msg *msg_pb.Message) {
consensus.tryCatchup() consensus.tryCatchup()
if consensus.current.Mode() == ViewChanging { if consensus.current.Mode() == ViewChanging {
utils.Logger().Debug().Msg("[OnPrepared] Still in ViewChanging mode, Exiting!!") consensus.getLogger().Debug().Msg("[OnPrepared] Still in ViewChanging mode, Exiting!!")
return return
} }
if consensus.checkViewID(recvMsg) != nil { if consensus.checkViewID(recvMsg) != nil {
if consensus.current.Mode() == Normal { if consensus.current.Mode() == Normal {
utils.Logger().Debug(). consensus.getLogger().Debug().
Uint64("MsgViewID", recvMsg.ViewID). Uint64("MsgViewID", recvMsg.ViewID).
Uint64("MsgBlockNum", recvMsg.BlockNum). Uint64("MsgBlockNum", recvMsg.BlockNum).
Msg("[OnPrepared] ViewID check failed") Msg("[OnPrepared] ViewID check failed")
@ -596,7 +601,7 @@ func (consensus *Consensus) onPrepared(msg *msg_pb.Message) {
return return
} }
if recvMsg.BlockNum > consensus.blockNum { if recvMsg.BlockNum > consensus.blockNum {
utils.Logger().Debug(). consensus.getLogger().Debug().
Uint64("MsgBlockNum", recvMsg.BlockNum). Uint64("MsgBlockNum", recvMsg.BlockNum).
Uint64("blockNum", consensus.blockNum). Uint64("blockNum", consensus.blockNum).
Msg("[OnPrepared] Future Block Received, ignoring!!") Msg("[OnPrepared] Future Block Received, ignoring!!")
@ -631,15 +636,15 @@ func (consensus *Consensus) onPrepared(msg *msg_pb.Message) {
} }
if err := consensus.msgSender.SendWithoutRetry([]nodeconfig.GroupID{nodeconfig.NewGroupIDByShardID(nodeconfig.ShardID(consensus.ShardID))}, host.ConstructP2pMessage(byte(17), msgToSend)); err != nil { if err := consensus.msgSender.SendWithoutRetry([]nodeconfig.GroupID{nodeconfig.NewGroupIDByShardID(nodeconfig.ShardID(consensus.ShardID))}, host.ConstructP2pMessage(byte(17), msgToSend)); err != nil {
utils.Logger().Warn().Msg("[OnPrepared] Cannot send commit message!!") consensus.getLogger().Warn().Msg("[OnPrepared] Cannot send commit message!!")
} else { } else {
utils.Logger().Info(). consensus.getLogger().Info().
Uint64("blockNum", consensus.blockNum). Uint64("blockNum", consensus.blockNum).
Hex("blockHash", consensus.blockHash[:]). Hex("blockHash", consensus.blockHash[:]).
Msg("[OnPrepared] Sent Commit Message!!") Msg("[OnPrepared] Sent Commit Message!!")
} }
utils.Logger().Debug(). consensus.getLogger().Debug().
Str("From", consensus.phase.String()). Str("From", consensus.phase.String()).
Str("To", FBFTCommit.String()). Str("To", FBFTCommit.String()).
Msg("[OnPrepared] Switching phase") Msg("[OnPrepared] Switching phase")
@ -656,22 +661,22 @@ func (consensus *Consensus) onCommit(msg *msg_pb.Message) {
senderKey, err := consensus.verifySenderKey(msg) senderKey, err := consensus.verifySenderKey(msg)
if err != nil { if err != nil {
utils.Logger().Debug().Err(err).Msg("[OnCommit] VerifySenderKey Failed") consensus.getLogger().Debug().Err(err).Msg("[OnCommit] VerifySenderKey Failed")
return return
} }
if err = verifyMessageSig(senderKey, msg); err != nil { if err = verifyMessageSig(senderKey, msg); err != nil {
utils.Logger().Debug().Err(err).Msg("[OnCommit] Failed to verify sender's signature") consensus.getLogger().Debug().Err(err).Msg("[OnCommit] Failed to verify sender's signature")
return return
} }
recvMsg, err := ParseFBFTMessage(msg) recvMsg, err := ParseFBFTMessage(msg)
if err != nil { if err != nil {
utils.Logger().Debug().Err(err).Msg("[OnCommit] Parse pbft message failed") consensus.getLogger().Debug().Err(err).Msg("[OnCommit] Parse pbft message failed")
return return
} }
if recvMsg.ViewID != consensus.viewID || recvMsg.BlockNum != consensus.blockNum { if recvMsg.ViewID != consensus.viewID || recvMsg.BlockNum != consensus.blockNum {
utils.Logger().Debug(). consensus.getLogger().Debug().
Uint64("MsgViewID", recvMsg.ViewID). Uint64("MsgViewID", recvMsg.ViewID).
Uint64("MsgBlockNum", recvMsg.BlockNum). Uint64("MsgBlockNum", recvMsg.BlockNum).
Uint64("blockNum", consensus.blockNum). Uint64("blockNum", consensus.blockNum).
@ -681,7 +686,7 @@ func (consensus *Consensus) onCommit(msg *msg_pb.Message) {
} }
if !consensus.FBFTLog.HasMatchingAnnounce(consensus.blockNum, recvMsg.BlockHash) { if !consensus.FBFTLog.HasMatchingAnnounce(consensus.blockNum, recvMsg.BlockHash) {
utils.Logger().Debug(). consensus.getLogger().Debug().
Hex("MsgBlockHash", recvMsg.BlockHash[:]). Hex("MsgBlockHash", recvMsg.BlockHash[:]).
Uint64("MsgBlockNum", recvMsg.BlockNum). Uint64("MsgBlockNum", recvMsg.BlockNum).
Uint64("blockNum", consensus.blockNum). Uint64("blockNum", consensus.blockNum).
@ -690,7 +695,7 @@ func (consensus *Consensus) onCommit(msg *msg_pb.Message) {
} }
if !consensus.FBFTLog.HasMatchingPrepared(consensus.blockNum, recvMsg.BlockHash) { if !consensus.FBFTLog.HasMatchingPrepared(consensus.blockNum, recvMsg.BlockHash) {
utils.Logger().Debug(). consensus.getLogger().Debug().
Hex("blockHash", recvMsg.BlockHash[:]). Hex("blockHash", recvMsg.BlockHash[:]).
Uint64("blockNum", consensus.blockNum). Uint64("blockNum", consensus.blockNum).
Msg("[OnCommit] Cannot find matching prepared message") Msg("[OnCommit] Cannot find matching prepared message")
@ -702,7 +707,7 @@ func (consensus *Consensus) onCommit(msg *msg_pb.Message) {
consensus.mutex.Lock() consensus.mutex.Lock()
defer consensus.mutex.Unlock() defer consensus.mutex.Unlock()
logger := utils.Logger().With(). logger := consensus.getLogger().With().
Str("validatorPubKey", validatorPubKey.SerializeToHexStr()).Logger() Str("validatorPubKey", validatorPubKey.SerializeToHexStr()).Logger()
if !consensus.IsValidatorInCommittee(recvMsg.SenderPubkey) { if !consensus.IsValidatorInCommittee(recvMsg.SenderPubkey) {
logger.Error().Msg("[OnCommit] Invalid validator") logger.Error().Msg("[OnCommit] Invalid validator")
@ -744,7 +749,7 @@ func (consensus *Consensus) onCommit(msg *msg_pb.Message) {
consensus.Decider.AddSignature(quorum.Commit, validatorPubKey, &sign) consensus.Decider.AddSignature(quorum.Commit, validatorPubKey, &sign)
// Set the bitmap indicating that this validator signed. // Set the bitmap indicating that this validator signed.
if err := commitBitmap.SetKey(recvMsg.SenderPubkey, true); err != nil { if err := commitBitmap.SetKey(recvMsg.SenderPubkey, true); err != nil {
utils.Logger().Warn().Err(err).Msg("[OnCommit] commitBitmap.SetKey failed") consensus.getLogger().Warn().Err(err).Msg("[OnCommit] commitBitmap.SetKey failed")
return return
} }
@ -769,7 +774,7 @@ func (consensus *Consensus) onCommit(msg *msg_pb.Message) {
} }
func (consensus *Consensus) finalizeCommits() { func (consensus *Consensus) finalizeCommits() {
utils.Logger().Info(). consensus.getLogger().Info().
Int64("NumCommits", consensus.Decider.SignersCount(quorum.Commit)). Int64("NumCommits", consensus.Decider.SignersCount(quorum.Commit)).
Msg("[Finalizing] Finalizing Block") Msg("[Finalizing] Finalizing Block")
@ -784,7 +789,7 @@ func (consensus *Consensus) finalizeCommits() {
_ = protobuf.Unmarshal(msgPayload, msg) _ = protobuf.Unmarshal(msgPayload, msg)
pbftMsg, err := ParseFBFTMessage(msg) pbftMsg, err := ParseFBFTMessage(msg)
if err != nil { if err != nil {
utils.Logger().Warn().Err(err).Msg("[FinalizeCommits] Unable to parse pbft message") consensus.getLogger().Warn().Err(err).Msg("[FinalizeCommits] Unable to parse pbft message")
return return
} }
consensus.FBFTLog.AddMessage(pbftMsg) consensus.FBFTLog.AddMessage(pbftMsg)
@ -793,14 +798,14 @@ func (consensus *Consensus) finalizeCommits() {
curBlockHash := consensus.blockHash curBlockHash := consensus.blockHash
block := consensus.FBFTLog.GetBlockByHash(curBlockHash) block := consensus.FBFTLog.GetBlockByHash(curBlockHash)
if block == nil { if block == nil {
utils.Logger().Warn(). consensus.getLogger().Warn().
Str("blockHash", hex.EncodeToString(curBlockHash[:])). Str("blockHash", hex.EncodeToString(curBlockHash[:])).
Msg("[FinalizeCommits] Cannot find block by hash") Msg("[FinalizeCommits] Cannot find block by hash")
return return
} }
consensus.tryCatchup() consensus.tryCatchup()
if consensus.blockNum-beforeCatchupNum != 1 { if consensus.blockNum-beforeCatchupNum != 1 {
utils.Logger().Warn(). consensus.getLogger().Warn().
Uint64("beforeCatchupBlockNum", beforeCatchupNum). Uint64("beforeCatchupBlockNum", beforeCatchupNum).
Msg("[FinalizeCommits] Leader cannot provide the correct block for committed message") Msg("[FinalizeCommits] Leader cannot provide the correct block for committed message")
return return
@ -815,9 +820,9 @@ func (consensus *Consensus) finalizeCommits() {
nodeconfig.NewGroupIDByShardID(nodeconfig.ShardID(consensus.ShardID)), nodeconfig.NewGroupIDByShardID(nodeconfig.ShardID(consensus.ShardID)),
}, },
host.ConstructP2pMessage(byte(17), msgToSend)); err != nil { host.ConstructP2pMessage(byte(17), msgToSend)); err != nil {
utils.Logger().Warn().Err(err).Msg("[Finalizing] Cannot send committed message") consensus.getLogger().Warn().Err(err).Msg("[Finalizing] Cannot send committed message")
} else { } else {
utils.Logger().Info(). consensus.getLogger().Info().
Hex("blockHash", curBlockHash[:]). Hex("blockHash", curBlockHash[:]).
Uint64("blockNum", consensus.blockNum). Uint64("blockNum", consensus.blockNum).
Msg("[Finalizing] Sent Committed Message") Msg("[Finalizing] Sent Committed Message")
@ -833,13 +838,13 @@ func (consensus *Consensus) finalizeCommits() {
if consensus.consensusTimeout[timeoutBootstrap].IsActive() { if consensus.consensusTimeout[timeoutBootstrap].IsActive() {
consensus.consensusTimeout[timeoutBootstrap].Stop() consensus.consensusTimeout[timeoutBootstrap].Stop()
utils.Logger().Debug().Msg("[Finalizing] Start consensus timer; stop bootstrap timer only once") consensus.getLogger().Debug().Msg("[Finalizing] Start consensus timer; stop bootstrap timer only once")
} else { } else {
utils.Logger().Debug().Msg("[Finalizing] Start consensus timer") consensus.getLogger().Debug().Msg("[Finalizing] Start consensus timer")
} }
consensus.consensusTimeout[timeoutConsensus].Start() consensus.consensusTimeout[timeoutConsensus].Start()
utils.Logger().Info(). consensus.getLogger().Info().
Uint64("blockNum", block.NumberU64()). Uint64("blockNum", block.NumberU64()).
Uint64("epochNum", block.Epoch().Uint64()). Uint64("epochNum", block.Epoch().Uint64()).
Uint64("ViewId", block.Header().ViewID().Uint64()). Uint64("ViewId", block.Header().ViewID().Uint64()).
@ -853,7 +858,7 @@ func (consensus *Consensus) finalizeCommits() {
} }
func (consensus *Consensus) onCommitted(msg *msg_pb.Message) { func (consensus *Consensus) onCommitted(msg *msg_pb.Message) {
utils.Logger().Debug().Msg("[OnCommitted] Receive committed message") consensus.getLogger().Debug().Msg("[OnCommitted] Receive committed message")
if consensus.IsLeader() && consensus.current.Mode() == Normal { if consensus.IsLeader() && consensus.current.Mode() == Normal {
return return
@ -861,27 +866,27 @@ func (consensus *Consensus) onCommitted(msg *msg_pb.Message) {
senderKey, err := consensus.verifySenderKey(msg) senderKey, err := consensus.verifySenderKey(msg)
if err != nil { if err != nil {
utils.Logger().Warn().Err(err).Msg("[OnCommitted] verifySenderKey failed") consensus.getLogger().Warn().Err(err).Msg("[OnCommitted] verifySenderKey failed")
return return
} }
if !senderKey.IsEqual(consensus.LeaderPubKey) && if !senderKey.IsEqual(consensus.LeaderPubKey) &&
consensus.current.Mode() == Normal && !consensus.ignoreViewIDCheck { consensus.current.Mode() == Normal && !consensus.ignoreViewIDCheck {
utils.Logger().Warn().Msg("[OnCommitted] senderKey not match leader PubKey") consensus.getLogger().Warn().Msg("[OnCommitted] senderKey not match leader PubKey")
return return
} }
if err = verifyMessageSig(senderKey, msg); err != nil { if err = verifyMessageSig(senderKey, msg); err != nil {
utils.Logger().Warn().Err(err).Msg("[OnCommitted] Failed to verify sender's signature") consensus.getLogger().Warn().Err(err).Msg("[OnCommitted] Failed to verify sender's signature")
return return
} }
recvMsg, err := ParseFBFTMessage(msg) recvMsg, err := ParseFBFTMessage(msg)
if err != nil { if err != nil {
utils.Logger().Warn().Msg("[OnCommitted] unable to parse msg") consensus.getLogger().Warn().Msg("[OnCommitted] unable to parse msg")
return return
} }
if recvMsg.BlockNum < consensus.blockNum { if recvMsg.BlockNum < consensus.blockNum {
utils.Logger().Info(). consensus.getLogger().Info().
Uint64("MsgBlockNum", recvMsg.BlockNum). Uint64("MsgBlockNum", recvMsg.BlockNum).
Uint64("blockNum", consensus.blockNum). Uint64("blockNum", consensus.blockNum).
Msg("[OnCommitted] Received Old Blocks!!") Msg("[OnCommitted] Received Old Blocks!!")
@ -890,12 +895,12 @@ func (consensus *Consensus) onCommitted(msg *msg_pb.Message) {
aggSig, mask, err := consensus.ReadSignatureBitmapPayload(recvMsg.Payload, 0) aggSig, mask, err := consensus.ReadSignatureBitmapPayload(recvMsg.Payload, 0)
if err != nil { if err != nil {
utils.Logger().Error().Err(err).Msg("[OnCommitted] readSignatureBitmapPayload failed") consensus.getLogger().Error().Err(err).Msg("[OnCommitted] readSignatureBitmapPayload failed")
return return
} }
if !consensus.Decider.IsQuorumAchievedByMask(mask) { if !consensus.Decider.IsQuorumAchievedByMask(mask) {
utils.Logger().Warn(). consensus.getLogger().Warn().
Msgf("[OnCommitted] Quorum Not achieved") Msgf("[OnCommitted] Quorum Not achieved")
return return
} }
@ -904,7 +909,7 @@ func (consensus *Consensus) onCommitted(msg *msg_pb.Message) {
binary.LittleEndian.PutUint64(blockNumBytes, recvMsg.BlockNum) binary.LittleEndian.PutUint64(blockNumBytes, recvMsg.BlockNum)
commitPayload := append(blockNumBytes, recvMsg.BlockHash[:]...) commitPayload := append(blockNumBytes, recvMsg.BlockHash[:]...)
if !aggSig.VerifyHash(mask.AggregatePublic, commitPayload) { if !aggSig.VerifyHash(mask.AggregatePublic, commitPayload) {
utils.Logger().Error(). consensus.getLogger().Error().
Uint64("MsgBlockNum", recvMsg.BlockNum). Uint64("MsgBlockNum", recvMsg.BlockNum).
Msg("[OnCommitted] Failed to verify the multi signature for commit phase") Msg("[OnCommitted] Failed to verify the multi signature for commit phase")
return return
@ -912,7 +917,7 @@ func (consensus *Consensus) onCommitted(msg *msg_pb.Message) {
consensus.FBFTLog.AddMessage(recvMsg) consensus.FBFTLog.AddMessage(recvMsg)
consensus.ChainReader.WriteLastCommits(recvMsg.Payload) consensus.ChainReader.WriteLastCommits(recvMsg.Payload)
utils.Logger().Debug(). consensus.getLogger().Debug().
Uint64("MsgViewID", recvMsg.ViewID). Uint64("MsgViewID", recvMsg.ViewID).
Uint64("MsgBlockNum", recvMsg.BlockNum). Uint64("MsgBlockNum", recvMsg.BlockNum).
Msg("[OnCommitted] Committed message added") Msg("[OnCommitted] Committed message added")
@ -924,7 +929,7 @@ func (consensus *Consensus) onCommitted(msg *msg_pb.Message) {
consensus.commitBitmap = mask consensus.commitBitmap = mask
if recvMsg.BlockNum-consensus.blockNum > consensusBlockNumBuffer { if recvMsg.BlockNum-consensus.blockNum > consensusBlockNumBuffer {
utils.Logger().Debug().Uint64("MsgBlockNum", recvMsg.BlockNum).Msg("[OnCommitted] out of sync") consensus.getLogger().Debug().Uint64("MsgBlockNum", recvMsg.BlockNum).Msg("[OnCommitted] out of sync")
go func() { go func() {
select { select {
case consensus.blockNumLowChan <- struct{}{}: case consensus.blockNumLowChan <- struct{}{}:
@ -939,21 +944,21 @@ func (consensus *Consensus) onCommitted(msg *msg_pb.Message) {
} }
// if consensus.checkViewID(recvMsg) != nil { // if consensus.checkViewID(recvMsg) != nil {
// utils.Logger().Debug("viewID check failed", "viewID", recvMsg.ViewID, "myViewID", consensus.viewID) // consensus.getLogger().Debug("viewID check failed", "viewID", recvMsg.ViewID, "myViewID", consensus.viewID)
// return // return
// } // }
consensus.tryCatchup() consensus.tryCatchup()
if consensus.current.Mode() == ViewChanging { if consensus.current.Mode() == ViewChanging {
utils.Logger().Debug().Msg("[OnCommitted] Still in ViewChanging mode, Exiting!!") consensus.getLogger().Debug().Msg("[OnCommitted] Still in ViewChanging mode, Exiting!!")
return return
} }
if consensus.consensusTimeout[timeoutBootstrap].IsActive() { if consensus.consensusTimeout[timeoutBootstrap].IsActive() {
consensus.consensusTimeout[timeoutBootstrap].Stop() consensus.consensusTimeout[timeoutBootstrap].Stop()
utils.Logger().Debug().Msg("[OnCommitted] Start consensus timer; stop bootstrap timer only once") consensus.getLogger().Debug().Msg("[OnCommitted] Start consensus timer; stop bootstrap timer only once")
} else { } else {
utils.Logger().Debug().Msg("[OnCommitted] Start consensus timer") consensus.getLogger().Debug().Msg("[OnCommitted] Start consensus timer")
} }
consensus.consensusTimeout[timeoutConsensus].Start() consensus.consensusTimeout[timeoutConsensus].Start()
return return
@ -968,7 +973,7 @@ func (consensus *Consensus) LastCommitSig() ([]byte, []byte, error) {
if err != nil || len(lastCommits) < 96 { if err != nil || len(lastCommits) < 96 {
msgs := consensus.FBFTLog.GetMessagesByTypeSeq(msg_pb.MessageType_COMMITTED, consensus.blockNum-1) msgs := consensus.FBFTLog.GetMessagesByTypeSeq(msg_pb.MessageType_COMMITTED, consensus.blockNum-1)
if len(msgs) != 1 { if len(msgs) != 1 {
utils.Logger().Error(). consensus.getLogger().Error().
Int("numCommittedMsg", len(msgs)). Int("numCommittedMsg", len(msgs)).
Msg("GetLastCommitSig failed with wrong number of committed message") Msg("GetLastCommitSig failed with wrong number of committed message")
return nil, nil, ctxerror.New("GetLastCommitSig failed with wrong number of committed message", "numCommittedMsg", len(msgs)) return nil, nil, ctxerror.New("GetLastCommitSig failed with wrong number of committed message", "numCommittedMsg", len(msgs))
@ -988,7 +993,7 @@ func (consensus *Consensus) LastCommitSig() ([]byte, []byte, error) {
// try to catch up if fall behind // try to catch up if fall behind
func (consensus *Consensus) tryCatchup() { func (consensus *Consensus) tryCatchup() {
utils.Logger().Info().Msg("[TryCatchup] commit new blocks") consensus.getLogger().Info().Msg("[TryCatchup] commit new blocks")
// if consensus.phase != Commit && consensus.mode.Mode() == Normal { // if consensus.phase != Commit && consensus.mode.Mode() == Normal {
// return // return
// } // }
@ -999,11 +1004,11 @@ func (consensus *Consensus) tryCatchup() {
break break
} }
if len(msgs) > 1 { if len(msgs) > 1 {
utils.Logger().Error(). consensus.getLogger().Error().
Int("numMsgs", len(msgs)). Int("numMsgs", len(msgs)).
Msg("[TryCatchup] DANGER!!! we should only get one committed message for a given blockNum") Msg("[TryCatchup] DANGER!!! we should only get one committed message for a given blockNum")
} }
utils.Logger().Info().Msg("[TryCatchup] committed message found") consensus.getLogger().Info().Msg("[TryCatchup] committed message found")
block := consensus.FBFTLog.GetBlockByHash(msgs[0].BlockHash) block := consensus.FBFTLog.GetBlockByHash(msgs[0].BlockHash)
if block == nil { if block == nil {
@ -1013,22 +1018,22 @@ func (consensus *Consensus) tryCatchup() {
if consensus.BlockVerifier == nil { if consensus.BlockVerifier == nil {
// do nothing // do nothing
} else if err := consensus.BlockVerifier(block); err != nil { } else if err := consensus.BlockVerifier(block); err != nil {
utils.Logger().Info().Msg("[TryCatchup] block verification failed") consensus.getLogger().Info().Msg("[TryCatchup] block verification failed")
return return
} }
if block.ParentHash() != consensus.ChainReader.CurrentHeader().Hash() { if block.ParentHash() != consensus.ChainReader.CurrentHeader().Hash() {
utils.Logger().Debug().Msg("[TryCatchup] parent block hash not match") consensus.getLogger().Debug().Msg("[TryCatchup] parent block hash not match")
break break
} }
utils.Logger().Info().Msg("[TryCatchup] block found to commit") consensus.getLogger().Info().Msg("[TryCatchup] block found to commit")
preparedMsgs := consensus.FBFTLog.GetMessagesByTypeSeqHash(msg_pb.MessageType_PREPARED, msgs[0].BlockNum, msgs[0].BlockHash) preparedMsgs := consensus.FBFTLog.GetMessagesByTypeSeqHash(msg_pb.MessageType_PREPARED, msgs[0].BlockNum, msgs[0].BlockHash)
msg := consensus.FBFTLog.FindMessageByMaxViewID(preparedMsgs) msg := consensus.FBFTLog.FindMessageByMaxViewID(preparedMsgs)
if msg == nil { if msg == nil {
break break
} }
utils.Logger().Info().Msg("[TryCatchup] prepared message found to commit") consensus.getLogger().Info().Msg("[TryCatchup] prepared message found to commit")
// TODO(Chao): Explain the reasoning for these code // TODO(Chao): Explain the reasoning for these code
consensus.blockHash = [32]byte{} consensus.blockHash = [32]byte{}
@ -1036,14 +1041,14 @@ func (consensus *Consensus) tryCatchup() {
consensus.viewID = msgs[0].ViewID + 1 consensus.viewID = msgs[0].ViewID + 1
consensus.LeaderPubKey = msgs[0].SenderPubkey consensus.LeaderPubKey = msgs[0].SenderPubkey
utils.Logger().Info().Msg("[TryCatchup] Adding block to chain") consensus.getLogger().Info().Msg("[TryCatchup] Adding block to chain")
consensus.OnConsensusDone(block, msgs[0].Payload) consensus.OnConsensusDone(block, msgs[0].Payload)
consensus.ResetState() consensus.ResetState()
select { select {
case consensus.VerifiedNewBlock <- block: case consensus.VerifiedNewBlock <- block:
default: default:
utils.Logger().Info(). consensus.getLogger().Info().
Str("blockHash", block.Hash().String()). Str("blockHash", block.Hash().String()).
Msg("[TryCatchup] consensus verified block send to chan failed") Msg("[TryCatchup] consensus verified block send to chan failed")
continue continue
@ -1052,7 +1057,7 @@ func (consensus *Consensus) tryCatchup() {
break break
} }
if currentBlockNum < consensus.blockNum { if currentBlockNum < consensus.blockNum {
utils.Logger().Info(). consensus.getLogger().Info().
Uint64("From", currentBlockNum). Uint64("From", currentBlockNum).
Uint64("To", consensus.blockNum). Uint64("To", consensus.blockNum).
Msg("[TryCatchup] Caught up!") Msg("[TryCatchup] Caught up!")
@ -1075,23 +1080,23 @@ func (consensus *Consensus) Start(blockChannel chan *types.Block, stopChan chan
toStart := false toStart := false
isInitialLeader := consensus.IsLeader() isInitialLeader := consensus.IsLeader()
if isInitialLeader { if isInitialLeader {
utils.Logger().Info().Time("time", time.Now()).Msg("[ConsensusMainLoop] Waiting for consensus start") consensus.getLogger().Info().Time("time", time.Now()).Msg("[ConsensusMainLoop] Waiting for consensus start")
// send a signal to indicate it's ready to run consensus // send a signal to indicate it's ready to run consensus
// this signal is consumed by node object to create a new block and in turn trigger a new consensus on it // this signal is consumed by node object to create a new block and in turn trigger a new consensus on it
go func() { go func() {
<-startChannel <-startChannel
toStart = true toStart = true
utils.Logger().Info().Time("time", time.Now()).Msg("[ConsensusMainLoop] Send ReadySignal") consensus.getLogger().Info().Time("time", time.Now()).Msg("[ConsensusMainLoop] Send ReadySignal")
consensus.ReadySignal <- struct{}{} consensus.ReadySignal <- struct{}{}
}() }()
} }
utils.Logger().Info().Time("time", time.Now()).Msg("[ConsensusMainLoop] Consensus started") consensus.getLogger().Info().Time("time", time.Now()).Msg("[ConsensusMainLoop] Consensus started")
defer close(stoppedChan) defer close(stoppedChan)
ticker := time.NewTicker(3 * time.Second) ticker := time.NewTicker(3 * time.Second)
defer ticker.Stop() defer ticker.Stop()
consensus.consensusTimeout[timeoutBootstrap].Start() consensus.consensusTimeout[timeoutBootstrap].Start()
utils.Logger().Debug(). consensus.getLogger().Debug().
Uint64("viewID", consensus.viewID). Uint64("viewID", consensus.viewID).
Uint64("blockNum", consensus.blockNum). Uint64("blockNum", consensus.blockNum).
Msg("[ConsensusMainLoop] Start bootstrap timeout (only once)") Msg("[ConsensusMainLoop] Start bootstrap timeout (only once)")
@ -1112,11 +1117,11 @@ func (consensus *Consensus) Start(blockChannel chan *types.Block, stopChan chan
continue continue
} }
if k != timeoutViewChange { if k != timeoutViewChange {
utils.Logger().Debug().Msg("[ConsensusMainLoop] Ops Consensus Timeout!!!") consensus.getLogger().Debug().Msg("[ConsensusMainLoop] Ops Consensus Timeout!!!")
consensus.startViewChange(consensus.viewID + 1) consensus.startViewChange(consensus.viewID + 1)
break break
} else { } else {
utils.Logger().Debug().Msg("[ConsensusMainLoop] Ops View Change Timeout!!!") consensus.getLogger().Debug().Msg("[ConsensusMainLoop] Ops View Change Timeout!!!")
viewID := consensus.current.ViewID() viewID := consensus.current.ViewID()
consensus.startViewChange(viewID + 1) consensus.startViewChange(viewID + 1)
break break
@ -1127,12 +1132,12 @@ func (consensus *Consensus) Start(blockChannel chan *types.Block, stopChan chan
consensus.SetViewID(consensus.ChainReader.CurrentHeader().ViewID().Uint64() + 1) consensus.SetViewID(consensus.ChainReader.CurrentHeader().ViewID().Uint64() + 1)
mode := consensus.UpdateConsensusInformation() mode := consensus.UpdateConsensusInformation()
consensus.current.SetMode(mode) consensus.current.SetMode(mode)
utils.Logger().Info().Str("Mode", mode.String()).Msg("Node is in sync") consensus.getLogger().Info().Str("Mode", mode.String()).Msg("Node is in sync")
case <-consensus.syncNotReadyChan: case <-consensus.syncNotReadyChan:
consensus.SetBlockNum(consensus.ChainReader.CurrentHeader().Number().Uint64() + 1) consensus.SetBlockNum(consensus.ChainReader.CurrentHeader().Number().Uint64() + 1)
consensus.current.SetMode(Syncing) consensus.current.SetMode(Syncing)
utils.Logger().Info().Msg("Node is out of sync") consensus.getLogger().Info().Msg("Node is out of sync")
case newBlock := <-blockChannel: case newBlock := <-blockChannel:
// Debug code to trigger leader change. // Debug code to trigger leader change.
@ -1140,7 +1145,7 @@ func (consensus *Consensus) Start(blockChannel chan *types.Block, stopChan chan
// continue // continue
//} //}
utils.Logger().Info(). consensus.getLogger().Info().
Uint64("MsgBlockNum", newBlock.NumberU64()). Uint64("MsgBlockNum", newBlock.NumberU64()).
Msg("[ConsensusMainLoop] Received Proposed New Block!") Msg("[ConsensusMainLoop] Received Proposed New Block!")
@ -1223,7 +1228,7 @@ func (consensus *Consensus) Start(blockChannel chan *types.Block, stopChan chan
startTime = time.Now() startTime = time.Now()
consensus.msgSender.Reset(newBlock.NumberU64()) consensus.msgSender.Reset(newBlock.NumberU64())
utils.Logger().Debug(). consensus.getLogger().Debug().
Int("numTxs", len(newBlock.Transactions())). Int("numTxs", len(newBlock.Transactions())).
Time("startTime", startTime). Time("startTime", startTime).
Int64("publicKeys", consensus.Decider.ParticipantsCount()). Int64("publicKeys", consensus.Decider.ParticipantsCount()).

104
consensus/view_change.go
Unescape View File

@ -77,7 +77,7 @@ func (consensus *Consensus) switchPhase(desired FBFTPhase, override bool) {
func (consensus *Consensus) GetNextLeaderKey() *bls.PublicKey { func (consensus *Consensus) GetNextLeaderKey() *bls.PublicKey {
wasFound, next := consensus.Decider.NextAfter(consensus.LeaderPubKey) wasFound, next := consensus.Decider.NextAfter(consensus.LeaderPubKey)
if !wasFound { if !wasFound {
utils.Logger().Warn(). consensus.getLogger().Warn().
Str("key", consensus.LeaderPubKey.SerializeToHexStr()). Str("key", consensus.LeaderPubKey.SerializeToHexStr()).
Msg("GetNextLeaderKey: currentLeaderKey not found") Msg("GetNextLeaderKey: currentLeaderKey not found")
} }
@ -86,7 +86,7 @@ func (consensus *Consensus) GetNextLeaderKey() *bls.PublicKey {
// ResetViewChangeState reset the state for viewchange // ResetViewChangeState reset the state for viewchange
func (consensus *Consensus) ResetViewChangeState() { func (consensus *Consensus) ResetViewChangeState() {
utils.Logger().Debug(). consensus.getLogger().Debug().
Str("Phase", consensus.phase.String()). Str("Phase", consensus.phase.String()).
Msg("[ResetViewChangeState] Resetting view change state") Msg("[ResetViewChangeState] Resetting view change state")
consensus.current.SetMode(Normal) consensus.current.SetMode(Normal)
@ -124,7 +124,7 @@ func (consensus *Consensus) startViewChange(viewID uint64) {
diff := viewID - consensus.viewID diff := viewID - consensus.viewID
duration := time.Duration(int64(diff) * int64(viewChangeDuration)) duration := time.Duration(int64(diff) * int64(viewChangeDuration))
utils.Logger().Info(). consensus.getLogger().Info().
Uint64("ViewChangingID", viewID). Uint64("ViewChangingID", viewID).
Dur("timeoutDuration", duration). Dur("timeoutDuration", duration).
Str("NextLeader", consensus.LeaderPubKey.SerializeToHexStr()). Str("NextLeader", consensus.LeaderPubKey.SerializeToHexStr()).
@ -139,7 +139,7 @@ func (consensus *Consensus) startViewChange(viewID uint64) {
consensus.consensusTimeout[timeoutViewChange].SetDuration(duration) consensus.consensusTimeout[timeoutViewChange].SetDuration(duration)
consensus.consensusTimeout[timeoutViewChange].Start() consensus.consensusTimeout[timeoutViewChange].Start()
utils.Logger().Debug(). consensus.getLogger().Debug().
Uint64("ViewChangingID", consensus.current.ViewID()). Uint64("ViewChangingID", consensus.current.ViewID()).
Msg("[startViewChange] start view change timer") Msg("[startViewChange] start view change timer")
} }
@ -147,7 +147,7 @@ func (consensus *Consensus) startViewChange(viewID uint64) {
func (consensus *Consensus) onViewChange(msg *msg_pb.Message) { func (consensus *Consensus) onViewChange(msg *msg_pb.Message) {
recvMsg, err := ParseViewChangeMessage(msg) recvMsg, err := ParseViewChangeMessage(msg)
if err != nil { if err != nil {
utils.Logger().Warn().Msg("[onViewChange] Unable To Parse Viewchange Message") consensus.getLogger().Warn().Msg("[onViewChange] Unable To Parse Viewchange Message")
return return
} }
newLeaderKey := recvMsg.LeaderPubkey newLeaderKey := recvMsg.LeaderPubkey
@ -156,7 +156,7 @@ func (consensus *Consensus) onViewChange(msg *msg_pb.Message) {
} }
if consensus.Decider.IsQuorumAchieved(quorum.ViewChange) { if consensus.Decider.IsQuorumAchieved(quorum.ViewChange) {
utils.Logger().Debug(). consensus.getLogger().Debug().
Int64("have", consensus.Decider.SignersCount(quorum.ViewChange)). Int64("have", consensus.Decider.SignersCount(quorum.ViewChange)).
Int64("need", consensus.Decider.TwoThirdsSignersCount()). Int64("need", consensus.Decider.TwoThirdsSignersCount()).
Str("validatorPubKey", recvMsg.SenderPubkey.SerializeToHexStr()). Str("validatorPubKey", recvMsg.SenderPubkey.SerializeToHexStr()).
@ -166,21 +166,21 @@ func (consensus *Consensus) onViewChange(msg *msg_pb.Message) {
senderKey, err := consensus.verifyViewChangeSenderKey(msg) senderKey, err := consensus.verifyViewChangeSenderKey(msg)
if err != nil { if err != nil {
utils.Logger().Debug().Err(err).Msg("[onViewChange] VerifySenderKey Failed") consensus.getLogger().Debug().Err(err).Msg("[onViewChange] VerifySenderKey Failed")
return return
} }
// TODO: if difference is only one, new leader can still propose the same committed block to avoid another view change // TODO: if difference is only one, new leader can still propose the same committed block to avoid another view change
// TODO: new leader catchup without ignore view change message // TODO: new leader catchup without ignore view change message
if consensus.blockNum > recvMsg.BlockNum { if consensus.blockNum > recvMsg.BlockNum {
utils.Logger().Debug(). consensus.getLogger().Debug().
Uint64("MsgBlockNum", recvMsg.BlockNum). Uint64("MsgBlockNum", recvMsg.BlockNum).
Msg("[onViewChange] Message BlockNum Is Low") Msg("[onViewChange] Message BlockNum Is Low")
return return
} }
if consensus.blockNum < recvMsg.BlockNum { if consensus.blockNum < recvMsg.BlockNum {
utils.Logger().Warn(). consensus.getLogger().Warn().
Uint64("MsgBlockNum", recvMsg.BlockNum). Uint64("MsgBlockNum", recvMsg.BlockNum).
Msg("[onViewChange] New Leader Has Lower Blocknum") Msg("[onViewChange] New Leader Has Lower Blocknum")
return return
@ -188,14 +188,14 @@ func (consensus *Consensus) onViewChange(msg *msg_pb.Message) {
if consensus.current.Mode() == ViewChanging && if consensus.current.Mode() == ViewChanging &&
consensus.current.ViewID() > recvMsg.ViewID { consensus.current.ViewID() > recvMsg.ViewID {
utils.Logger().Warn(). consensus.getLogger().Warn().
Uint64("MyViewChangingID", consensus.current.ViewID()). Uint64("MyViewChangingID", consensus.current.ViewID()).
Uint64("MsgViewChangingID", recvMsg.ViewID). Uint64("MsgViewChangingID", recvMsg.ViewID).
Msg("[onViewChange] ViewChanging ID Is Low") Msg("[onViewChange] ViewChanging ID Is Low")
return return
} }
if err = verifyMessageSig(senderKey, msg); err != nil { if err = verifyMessageSig(senderKey, msg); err != nil {
utils.Logger().Debug().Err(err).Msg("[onViewChange] Failed To Verify Sender's Signature") consensus.getLogger().Debug().Err(err).Msg("[onViewChange] Failed To Verify Sender's Signature")
return return
} }
@ -213,11 +213,11 @@ func (consensus *Consensus) onViewChange(msg *msg_pb.Message) {
) )
preparedMsg := consensus.FBFTLog.FindMessageByMaxViewID(preparedMsgs) preparedMsg := consensus.FBFTLog.FindMessageByMaxViewID(preparedMsgs)
if preparedMsg == nil { if preparedMsg == nil {
utils.Logger().Debug().Msg("[onViewChange] add my M2(NIL) type messaage") consensus.getLogger().Debug().Msg("[onViewChange] add my M2(NIL) type messaage")
consensus.nilSigs[consensus.PubKey.SerializeToHexStr()] = consensus.priKey.SignHash(NIL) consensus.nilSigs[consensus.PubKey.SerializeToHexStr()] = consensus.priKey.SignHash(NIL)
consensus.nilBitmap.SetKey(consensus.PubKey, true) consensus.nilBitmap.SetKey(consensus.PubKey, true)
} else { } else {
utils.Logger().Debug().Msg("[onViewChange] add my M1 type messaage") consensus.getLogger().Debug().Msg("[onViewChange] add my M1 type messaage")
msgToSign := append(preparedMsg.BlockHash[:], preparedMsg.Payload...) msgToSign := append(preparedMsg.BlockHash[:], preparedMsg.Payload...)
consensus.bhpSigs[consensus.PubKey.SerializeToHexStr()] = consensus.priKey.SignHash(msgToSign) consensus.bhpSigs[consensus.PubKey.SerializeToHexStr()] = consensus.priKey.SignHash(msgToSign)
consensus.bhpBitmap.SetKey(consensus.PubKey, true) consensus.bhpBitmap.SetKey(consensus.PubKey, true)
@ -238,18 +238,18 @@ func (consensus *Consensus) onViewChange(msg *msg_pb.Message) {
if len(recvMsg.Payload) == 0 { if len(recvMsg.Payload) == 0 {
_, ok := consensus.nilSigs[senderKey.SerializeToHexStr()] _, ok := consensus.nilSigs[senderKey.SerializeToHexStr()]
if ok { if ok {
utils.Logger().Debug(). consensus.getLogger().Debug().
Str("validatorPubKey", senderKey.SerializeToHexStr()). Str("validatorPubKey", senderKey.SerializeToHexStr()).
Msg("[onViewChange] Already Received M2 message from validator") Msg("[onViewChange] Already Received M2 message from validator")
return return
} }
if !recvMsg.ViewchangeSig.VerifyHash(senderKey, NIL) { if !recvMsg.ViewchangeSig.VerifyHash(senderKey, NIL) {
utils.Logger().Warn().Msg("[onViewChange] Failed To Verify Signature For M2 Type Viewchange Message") consensus.getLogger().Warn().Msg("[onViewChange] Failed To Verify Signature For M2 Type Viewchange Message")
return return
} }
utils.Logger().Debug(). consensus.getLogger().Debug().
Str("validatorPubKey", senderKey.SerializeToHexStr()). Str("validatorPubKey", senderKey.SerializeToHexStr()).
Msg("[onViewChange] Add M2 (NIL) type message") Msg("[onViewChange] Add M2 (NIL) type message")
consensus.nilSigs[senderKey.SerializeToHexStr()] = recvMsg.ViewchangeSig consensus.nilSigs[senderKey.SerializeToHexStr()] = recvMsg.ViewchangeSig
@ -257,20 +257,20 @@ func (consensus *Consensus) onViewChange(msg *msg_pb.Message) {
} else { // m1 type message } else { // m1 type message
_, ok := consensus.bhpSigs[senderKey.SerializeToHexStr()] _, ok := consensus.bhpSigs[senderKey.SerializeToHexStr()]
if ok { if ok {
utils.Logger().Debug(). consensus.getLogger().Debug().
Str("validatorPubKey", senderKey.SerializeToHexStr()). Str("validatorPubKey", senderKey.SerializeToHexStr()).
Msg("[onViewChange] Already Received M1 Message From the Validator") Msg("[onViewChange] Already Received M1 Message From the Validator")
return return
} }
if !recvMsg.ViewchangeSig.VerifyHash(recvMsg.SenderPubkey, recvMsg.Payload) { if !recvMsg.ViewchangeSig.VerifyHash(recvMsg.SenderPubkey, recvMsg.Payload) {
utils.Logger().Warn().Msg("[onViewChange] Failed to Verify Signature for M1 Type Viewchange Message") consensus.getLogger().Warn().Msg("[onViewChange] Failed to Verify Signature for M1 Type Viewchange Message")
return return
} }
// first time receive m1 type message, need verify validity of prepared message // first time receive m1 type message, need verify validity of prepared message
if len(consensus.m1Payload) == 0 || !bytes.Equal(consensus.m1Payload, recvMsg.Payload) { if len(consensus.m1Payload) == 0 || !bytes.Equal(consensus.m1Payload, recvMsg.Payload) {
if len(recvMsg.Payload) <= 32 { if len(recvMsg.Payload) <= 32 {
utils.Logger().Debug(). consensus.getLogger().Debug().
Int("len", len(recvMsg.Payload)). Int("len", len(recvMsg.Payload)).
Msg("[onViewChange] M1 RecvMsg Payload Not Enough Length") Msg("[onViewChange] M1 RecvMsg Payload Not Enough Length")
return return
@ -278,19 +278,19 @@ func (consensus *Consensus) onViewChange(msg *msg_pb.Message) {
blockHash := recvMsg.Payload[:32] blockHash := recvMsg.Payload[:32]
aggSig, mask, err := consensus.ReadSignatureBitmapPayload(recvMsg.Payload, 32) aggSig, mask, err := consensus.ReadSignatureBitmapPayload(recvMsg.Payload, 32)
if err != nil { if err != nil {
utils.Logger().Error().Err(err).Msg("[onViewChange] M1 RecvMsg Payload Read Error") consensus.getLogger().Error().Err(err).Msg("[onViewChange] M1 RecvMsg Payload Read Error")
return return
} }
if !consensus.Decider.IsQuorumAchievedByMask(mask) { if !consensus.Decider.IsQuorumAchievedByMask(mask) {
utils.Logger().Warn(). consensus.getLogger().Warn().
Msgf("[onViewChange] Quorum Not achieved") Msgf("[onViewChange] Quorum Not achieved")
return return
} }
// Verify the multi-sig for prepare phase // Verify the multi-sig for prepare phase
if !aggSig.VerifyHash(mask.AggregatePublic, blockHash[:]) { if !aggSig.VerifyHash(mask.AggregatePublic, blockHash[:]) {
utils.Logger().Warn(). consensus.getLogger().Warn().
Hex("blockHash", blockHash). Hex("blockHash", blockHash).
Msg("[onViewChange] failed to verify multi signature for m1 prepared payload") Msg("[onViewChange] failed to verify multi signature for m1 prepared payload")
return return
@ -310,11 +310,11 @@ func (consensus *Consensus) onViewChange(msg *msg_pb.Message) {
preparedMsg.Payload = make([]byte, len(recvMsg.Payload)-32) preparedMsg.Payload = make([]byte, len(recvMsg.Payload)-32)
copy(preparedMsg.Payload[:], recvMsg.Payload[32:]) copy(preparedMsg.Payload[:], recvMsg.Payload[32:])
preparedMsg.SenderPubkey = consensus.PubKey preparedMsg.SenderPubkey = consensus.PubKey
utils.Logger().Info().Msg("[onViewChange] New Leader Prepared Message Added") consensus.getLogger().Info().Msg("[onViewChange] New Leader Prepared Message Added")
consensus.FBFTLog.AddMessage(&preparedMsg) consensus.FBFTLog.AddMessage(&preparedMsg)
} }
} }
utils.Logger().Debug(). consensus.getLogger().Debug().
Str("validatorPubKey", senderKey.SerializeToHexStr()). Str("validatorPubKey", senderKey.SerializeToHexStr()).
Msg("[onViewChange] Add M1 (prepared) type message") Msg("[onViewChange] Add M1 (prepared) type message")
consensus.bhpSigs[senderKey.SerializeToHexStr()] = recvMsg.ViewchangeSig consensus.bhpSigs[senderKey.SerializeToHexStr()] = recvMsg.ViewchangeSig
@ -324,7 +324,7 @@ func (consensus *Consensus) onViewChange(msg *msg_pb.Message) {
// check and add viewID (m3 type) message signature // check and add viewID (m3 type) message signature
sig := consensus.Decider.ReadSignature(quorum.ViewChange, senderKey) sig := consensus.Decider.ReadSignature(quorum.ViewChange, senderKey)
if sig != nil { if sig != nil {
utils.Logger().Debug(). consensus.getLogger().Debug().
Str("validatorPubKey", senderKey.SerializeToHexStr()). Str("validatorPubKey", senderKey.SerializeToHexStr()).
Msg("[onViewChange] Already Received M3(ViewID) message from the validator") Msg("[onViewChange] Already Received M3(ViewID) message from the validator")
return return
@ -332,18 +332,18 @@ func (consensus *Consensus) onViewChange(msg *msg_pb.Message) {
viewIDHash := make([]byte, 8) viewIDHash := make([]byte, 8)
binary.LittleEndian.PutUint64(viewIDHash, recvMsg.ViewID) binary.LittleEndian.PutUint64(viewIDHash, recvMsg.ViewID)
if !recvMsg.ViewidSig.VerifyHash(recvMsg.SenderPubkey, viewIDHash) { if !recvMsg.ViewidSig.VerifyHash(recvMsg.SenderPubkey, viewIDHash) {
utils.Logger().Warn(). consensus.getLogger().Warn().
Uint64("MsgViewID", recvMsg.ViewID). Uint64("MsgViewID", recvMsg.ViewID).
Msg("[onViewChange] Failed to Verify M3 Message Signature") Msg("[onViewChange] Failed to Verify M3 Message Signature")
return return
} }
utils.Logger().Debug(). consensus.getLogger().Debug().
Str("validatorPubKey", senderKey.SerializeToHexStr()). Str("validatorPubKey", senderKey.SerializeToHexStr()).
Msg("[onViewChange] Add M3 (ViewID) type message") Msg("[onViewChange] Add M3 (ViewID) type message")
consensus.Decider.AddSignature(quorum.ViewChange, senderKey, recvMsg.ViewidSig) consensus.Decider.AddSignature(quorum.ViewChange, senderKey, recvMsg.ViewidSig)
// Set the bitmap indicating that this validator signed. // Set the bitmap indicating that this validator signed.
consensus.viewIDBitmap.SetKey(recvMsg.SenderPubkey, true) consensus.viewIDBitmap.SetKey(recvMsg.SenderPubkey, true)
utils.Logger().Debug(). consensus.getLogger().Debug().
Int64("numSigs", consensus.Decider.SignersCount(quorum.ViewChange)). Int64("numSigs", consensus.Decider.SignersCount(quorum.ViewChange)).
Int64("needed", consensus.Decider.TwoThirdsSignersCount()). Int64("needed", consensus.Decider.TwoThirdsSignersCount()).
Msg("[onViewChange]") Msg("[onViewChange]")
@ -359,7 +359,7 @@ func (consensus *Consensus) onViewChange(msg *msg_pb.Message) {
consensus.ReadySignal <- struct{}{} consensus.ReadySignal <- struct{}{}
}() }()
} else { } else {
utils.Logger().Debug(). consensus.getLogger().Debug().
Str("From", consensus.phase.String()). Str("From", consensus.phase.String()).
Str("To", FBFTCommit.String()). Str("To", FBFTCommit.String()).
Msg("[OnViewChange] Switching phase") Msg("[OnViewChange] Switching phase")
@ -368,7 +368,7 @@ func (consensus *Consensus) onViewChange(msg *msg_pb.Message) {
aggSig, mask, err := consensus.ReadSignatureBitmapPayload(recvMsg.Payload, 32) aggSig, mask, err := consensus.ReadSignatureBitmapPayload(recvMsg.Payload, 32)
if err != nil { if err != nil {
utils.Logger().Error().Err(err). consensus.getLogger().Error().Err(err).
Msg("[onViewChange] ReadSignatureBitmapPayload Fail") Msg("[onViewChange] ReadSignatureBitmapPayload Fail")
return return
} }
@ -384,7 +384,7 @@ func (consensus *Consensus) onViewChange(msg *msg_pb.Message) {
) )
if err = consensus.commitBitmap.SetKey(consensus.PubKey, true); err != nil { if err = consensus.commitBitmap.SetKey(consensus.PubKey, true); err != nil {
utils.Logger().Debug(). consensus.getLogger().Debug().
Msg("[OnViewChange] New Leader commit bitmap set failed") Msg("[OnViewChange] New Leader commit bitmap set failed")
return return
} }
@ -393,7 +393,7 @@ func (consensus *Consensus) onViewChange(msg *msg_pb.Message) {
consensus.current.SetViewID(recvMsg.ViewID) consensus.current.SetViewID(recvMsg.ViewID)
msgToSend := consensus.constructNewViewMessage() msgToSend := consensus.constructNewViewMessage()
utils.Logger().Warn(). consensus.getLogger().Warn().
Int("payloadSize", len(consensus.m1Payload)). Int("payloadSize", len(consensus.m1Payload)).
Hex("M1Payload", consensus.m1Payload). Hex("M1Payload", consensus.m1Payload).
Msg("[onViewChange] Sent NewView Message") Msg("[onViewChange] Sent NewView Message")
@ -403,10 +403,10 @@ func (consensus *Consensus) onViewChange(msg *msg_pb.Message) {
consensus.ResetViewChangeState() consensus.ResetViewChangeState()
consensus.consensusTimeout[timeoutViewChange].Stop() consensus.consensusTimeout[timeoutViewChange].Stop()
consensus.consensusTimeout[timeoutConsensus].Start() consensus.consensusTimeout[timeoutConsensus].Start()
utils.Logger().Debug(). consensus.getLogger().Debug().
Uint64("viewChangingID", consensus.current.ViewID()). Uint64("viewChangingID", consensus.current.ViewID()).
Msg("[onViewChange] New Leader Start Consensus Timer and Stop View Change Timer") Msg("[onViewChange] New Leader Start Consensus Timer and Stop View Change Timer")
utils.Logger().Debug(). consensus.getLogger().Debug().
Str("myKey", consensus.PubKey.SerializeToHexStr()). Str("myKey", consensus.PubKey.SerializeToHexStr()).
Uint64("viewID", consensus.viewID). Uint64("viewID", consensus.viewID).
Uint64("block", consensus.blockNum). Uint64("block", consensus.blockNum).
@ -416,27 +416,27 @@ func (consensus *Consensus) onViewChange(msg *msg_pb.Message) {
// TODO: move to consensus_leader.go later // TODO: move to consensus_leader.go later
func (consensus *Consensus) onNewView(msg *msg_pb.Message) { func (consensus *Consensus) onNewView(msg *msg_pb.Message) {
utils.Logger().Debug().Msg("[onNewView] Received NewView Message") consensus.getLogger().Debug().Msg("[onNewView] Received NewView Message")
senderKey, err := consensus.verifyViewChangeSenderKey(msg) senderKey, err := consensus.verifyViewChangeSenderKey(msg)
if err != nil { if err != nil {
utils.Logger().Warn().Err(err).Msg("[onNewView] VerifySenderKey Failed") consensus.getLogger().Warn().Err(err).Msg("[onNewView] VerifySenderKey Failed")
return return
} }
recvMsg, err := consensus.ParseNewViewMessage(msg) recvMsg, err := consensus.ParseNewViewMessage(msg)
if err != nil { if err != nil {
utils.Logger().Warn().Err(err).Msg("[onNewView] Unable to Parse NewView Message") consensus.getLogger().Warn().Err(err).Msg("[onNewView] Unable to Parse NewView Message")
return return
} }
if err = verifyMessageSig(senderKey, msg); err != nil { if err = verifyMessageSig(senderKey, msg); err != nil {
utils.Logger().Error().Err(err).Msg("[onNewView] Failed to Verify New Leader's Signature") consensus.getLogger().Error().Err(err).Msg("[onNewView] Failed to Verify New Leader's Signature")
return return
} }
consensus.vcLock.Lock() consensus.vcLock.Lock()
defer consensus.vcLock.Unlock() defer consensus.vcLock.Unlock()
if recvMsg.M3AggSig == nil || recvMsg.M3Bitmap == nil { if recvMsg.M3AggSig == nil || recvMsg.M3Bitmap == nil {
utils.Logger().Error().Msg("[onNewView] M3AggSig or M3Bitmap is nil") consensus.getLogger().Error().Msg("[onNewView] M3AggSig or M3Bitmap is nil")
return return
} }
m3Sig := recvMsg.M3AggSig m3Sig := recvMsg.M3AggSig
@ -446,13 +446,13 @@ func (consensus *Consensus) onNewView(msg *msg_pb.Message) {
binary.LittleEndian.PutUint64(viewIDBytes, recvMsg.ViewID) binary.LittleEndian.PutUint64(viewIDBytes, recvMsg.ViewID)
if !consensus.Decider.IsQuorumAchievedByMask(m3Mask) { if !consensus.Decider.IsQuorumAchievedByMask(m3Mask) {
utils.Logger().Warn(). consensus.getLogger().Warn().
Msgf("[onNewView] Quorum Not achieved") Msgf("[onNewView] Quorum Not achieved")
return return
} }
if !m3Sig.VerifyHash(m3Mask.AggregatePublic, viewIDBytes) { if !m3Sig.VerifyHash(m3Mask.AggregatePublic, viewIDBytes) {
utils.Logger().Warn(). consensus.getLogger().Warn().
Str("m3Sig", m3Sig.SerializeToHexStr()). Str("m3Sig", m3Sig.SerializeToHexStr()).
Hex("m3Mask", m3Mask.Bitmap). Hex("m3Mask", m3Mask.Bitmap).
Uint64("MsgViewID", recvMsg.ViewID). Uint64("MsgViewID", recvMsg.ViewID).
@ -462,10 +462,10 @@ func (consensus *Consensus) onNewView(msg *msg_pb.Message) {
m2Mask := recvMsg.M2Bitmap m2Mask := recvMsg.M2Bitmap
if recvMsg.M2AggSig != nil { if recvMsg.M2AggSig != nil {
utils.Logger().Debug().Msg("[onNewView] M2AggSig (NIL) is Not Empty") consensus.getLogger().Debug().Msg("[onNewView] M2AggSig (NIL) is Not Empty")
m2Sig := recvMsg.M2AggSig m2Sig := recvMsg.M2AggSig
if !m2Sig.VerifyHash(m2Mask.AggregatePublic, NIL) { if !m2Sig.VerifyHash(m2Mask.AggregatePublic, NIL) {
utils.Logger().Warn(). consensus.getLogger().Warn().
Msg("[onNewView] Unable to Verify Aggregated Signature of M2 (NIL) payload") Msg("[onNewView] Unable to Verify Aggregated Signature of M2 (NIL) payload")
return return
} }
@ -476,7 +476,7 @@ func (consensus *Consensus) onNewView(msg *msg_pb.Message) {
(m2Mask != nil && m2Mask.Bitmap != nil && (m2Mask != nil && m2Mask.Bitmap != nil &&
utils.CountOneBits(m3Mask.Bitmap) > utils.CountOneBits(m2Mask.Bitmap)) { utils.CountOneBits(m3Mask.Bitmap) > utils.CountOneBits(m2Mask.Bitmap)) {
if len(recvMsg.Payload) <= 32 { if len(recvMsg.Payload) <= 32 {
utils.Logger().Debug(). consensus.getLogger().Debug().
Msg("[onNewView] M1 (prepared) Type Payload Not Have Enough Length") Msg("[onNewView] M1 (prepared) Type Payload Not Have Enough Length")
return return
} }
@ -484,12 +484,12 @@ func (consensus *Consensus) onNewView(msg *msg_pb.Message) {
blockHash := recvMsg.Payload[:32] blockHash := recvMsg.Payload[:32]
aggSig, mask, err := consensus.ReadSignatureBitmapPayload(recvMsg.Payload, 32) aggSig, mask, err := consensus.ReadSignatureBitmapPayload(recvMsg.Payload, 32)
if err != nil { if err != nil {
utils.Logger().Error().Err(err). consensus.getLogger().Error().Err(err).
Msg("[onNewView] ReadSignatureBitmapPayload Failed") Msg("[onNewView] ReadSignatureBitmapPayload Failed")
return return
} }
if !aggSig.VerifyHash(mask.AggregatePublic, blockHash) { if !aggSig.VerifyHash(mask.AggregatePublic, blockHash) {
utils.Logger().Warn(). consensus.getLogger().Warn().
Msg("[onNewView] Failed to Verify Signature for M1 (prepare) message") Msg("[onNewView] Failed to Verify Signature for M1 (prepare) message")
return return
} }
@ -518,7 +518,7 @@ func (consensus *Consensus) onNewView(msg *msg_pb.Message) {
// change view and leaderKey to keep in sync with network // change view and leaderKey to keep in sync with network
if consensus.blockNum != recvMsg.BlockNum { if consensus.blockNum != recvMsg.BlockNum {
utils.Logger().Debug(). consensus.getLogger().Debug().
Str("newLeaderKey", consensus.LeaderPubKey.SerializeToHexStr()). Str("newLeaderKey", consensus.LeaderPubKey.SerializeToHexStr()).
Uint64("MsgBlockNum", recvMsg.BlockNum). Uint64("MsgBlockNum", recvMsg.BlockNum).
Msg("[onNewView] New Leader Changed") Msg("[onNewView] New Leader Changed")
@ -534,21 +534,21 @@ func (consensus *Consensus) onNewView(msg *msg_pb.Message) {
commitPayload := append(blockNumHash, consensus.blockHash[:]...) commitPayload := append(blockNumHash, consensus.blockHash[:]...)
msgToSend := consensus.constructCommitMessage(commitPayload) msgToSend := consensus.constructCommitMessage(commitPayload)
utils.Logger().Info().Msg("onNewView === commit") consensus.getLogger().Info().Msg("onNewView === commit")
consensus.host.SendMessageToGroups([]nodeconfig.GroupID{nodeconfig.NewGroupIDByShardID(nodeconfig.ShardID(consensus.ShardID))}, host.ConstructP2pMessage(byte(17), msgToSend)) consensus.host.SendMessageToGroups([]nodeconfig.GroupID{nodeconfig.NewGroupIDByShardID(nodeconfig.ShardID(consensus.ShardID))}, host.ConstructP2pMessage(byte(17), msgToSend))
utils.Logger().Debug(). consensus.getLogger().Debug().
Str("From", consensus.phase.String()). Str("From", consensus.phase.String()).
Str("To", FBFTCommit.String()). Str("To", FBFTCommit.String()).
Msg("[OnViewChange] Switching phase") Msg("[OnViewChange] Switching phase")
consensus.switchPhase(FBFTCommit, true) consensus.switchPhase(FBFTCommit, true)
} else { } else {
consensus.ResetState() consensus.ResetState()
utils.Logger().Info().Msg("onNewView === announce") consensus.getLogger().Info().Msg("onNewView === announce")
} }
utils.Logger().Debug(). consensus.getLogger().Debug().
Str("newLeaderKey", consensus.LeaderPubKey.SerializeToHexStr()). Str("newLeaderKey", consensus.LeaderPubKey.SerializeToHexStr()).
Msg("new leader changed") Msg("new leader changed")
utils.Logger().Debug(). consensus.getLogger().Debug().
Msg("validator start consensus timer and stop view change timer") Msg("validator start consensus timer and stop view change timer")
consensus.consensusTimeout[timeoutConsensus].Start() consensus.consensusTimeout[timeoutConsensus].Start()
consensus.consensusTimeout[timeoutViewChange].Stop() consensus.consensusTimeout[timeoutViewChange].Stop()

Write Preview
Loading…
Cancel
Save