diff --git a/consensus/XDPoS/engines/engine_v2/engine.go b/consensus/XDPoS/engines/engine_v2/engine.go index 0906da00e3..8b46776652 100644 --- a/consensus/XDPoS/engines/engine_v2/engine.go +++ b/consensus/XDPoS/engines/engine_v2/engine.go @@ -446,7 +446,7 @@ func (x *XDPoS_v2) IsAuthorisedAddress(chain consensus.ChainReader, header *type } } - log.Warn("Not authorised address", "Address", address.Hex(), "Hash", header.Hash().Hex()) + log.Warn("Not authorised address", "Address", address.Hex(), "Hash", header.Hash().Hex(), "round", round) for index, mn := range masterNodes { log.Warn("Master node list item", "mn", mn.Hex(), "index", index) } @@ -466,7 +466,7 @@ func (x *XDPoS_v2) GetSnapshot(chain consensus.ChainReader, header *types.Header func (x *XDPoS_v2) UpdateMasternodes(chain consensus.ChainReader, header *types.Header, ms []utils.Masternode) error { number := header.Number.Uint64() - log.Trace("take snapshot", "number", number, "hash", header.Hash()) + log.Trace("[UpdateMasternodes]") masterNodes := []common.Address{} for _, m := range ms { @@ -475,6 +475,7 @@ func (x *XDPoS_v2) UpdateMasternodes(chain consensus.ChainReader, header *types. x.lock.RLock() snap := newSnapshot(number, header.Hash(), masterNodes) + log.Trace("[UpdateMasternodes] take snapshot", "number", number, "hash", header.Hash()) x.lock.RUnlock() err := storeSnapshot(snap, x.db) @@ -484,11 +485,10 @@ func (x *XDPoS_v2) UpdateMasternodes(chain consensus.ChainReader, header *types. } x.snapshots.Add(snap.Hash, snap) - nm := []string{} - for _, n := range ms { - nm = append(nm, n.Address.String()) + log.Info("[UpdateMasternodes] New set of masternodes has been updated to snapshot", "number", snap.Number, "hash", snap.Hash) + for i, n := range ms { + log.Info("masternode", "index", i, "address", n.Address.String()) } - log.Info("New set of masternodes has been updated to snapshot", "number", snap.Number, "hash", snap.Hash, "new masternodes", nm) return nil } @@ -506,7 +506,9 @@ func (x *XDPoS_v2) VerifyHeaders(chain consensus.ChainReader, headers []*types.H go func() { for i, header := range headers { err := x.verifyHeader(chain, header, headers[:i], fullVerifies[i]) - log.Warn("[VerifyHeaders] Fail to verify header", "fullVerify", fullVerifies[i], "blockNum", header.Number, "blockHash", header.Hash(), "error", err) + if err != nil { + log.Warn("[VerifyHeaders] Fail to verify header", "fullVerify", fullVerifies[i], "blockNum", header.Number, "blockHash", header.Hash(), "error", err) + } select { case <-abort: return @@ -530,18 +532,18 @@ func (x *XDPoS_v2) VerifySyncInfoMessage(chain consensus.ChainReader, syncInfo * */ if (x.highestQuorumCert.ProposedBlockInfo.Round >= syncInfo.HighestQuorumCert.ProposedBlockInfo.Round) && (x.highestTimeoutCert.Round >= syncInfo.HighestTimeoutCert.Round) { - log.Warn("[VerifySyncInfoMessage] Round from incoming syncInfo message is no longer qualified", "Highest QC Round", x.highestQuorumCert.ProposedBlockInfo.Round, "Incoming SyncInfo QC Round", syncInfo.HighestQuorumCert.ProposedBlockInfo.Round, "highestTimeoutCert Round", x.highestTimeoutCert.Round, "Incoming syncInfo TC Round", syncInfo.HighestTimeoutCert.Round) + log.Debug("[VerifySyncInfoMessage] Round from incoming syncInfo message is no longer qualified", "Highest QC Round", x.highestQuorumCert.ProposedBlockInfo.Round, "Incoming SyncInfo QC Round", syncInfo.HighestQuorumCert.ProposedBlockInfo.Round, "highestTimeoutCert Round", x.highestTimeoutCert.Round, "Incoming syncInfo TC Round", syncInfo.HighestTimeoutCert.Round) return false, nil } err := x.verifyQC(chain, syncInfo.HighestQuorumCert, nil) if err != nil { - log.Warn("SyncInfo message verification failed due to QC", "error", err) + log.Warn("[VerifySyncInfoMessage] SyncInfo message verification failed due to QC", "error", err) return false, err } err = x.verifyTC(chain, syncInfo.HighestTimeoutCert) if err != nil { - log.Warn("SyncInfo message verification failed due to TC", "error", err) + log.Warn("[VerifySyncInfoMessage] SyncInfo message verification failed due to TC", "error", err) return false, err } return true, nil @@ -849,11 +851,7 @@ func (x *XDPoS_v2) processQC(blockChainReader consensus.ChainReader, incomingQuo } // 4. Set new round if incomingQuorumCert.ProposedBlockInfo.Round >= x.currentRound { - err := x.setNewRound(blockChainReader, incomingQuorumCert.ProposedBlockInfo.Round+1) - if err != nil { - log.Error("[processQC] Fail to setNewRound", "new round to set", incomingQuorumCert.ProposedBlockInfo.Round+1) - return err - } + x.setNewRound(blockChainReader, incomingQuorumCert.ProposedBlockInfo.Round+1) } log.Trace("[ProcessQC][After]", "HighQC", x.highestQuorumCert) return nil @@ -864,14 +862,13 @@ func (x *XDPoS_v2) processQC(blockChainReader consensus.ChainReader, incomingQuo 2. Reset timer 3. Reset vote and timeout Pools */ -func (x *XDPoS_v2) setNewRound(blockChainReader consensus.ChainReader, round types.Round) error { +func (x *XDPoS_v2) setNewRound(blockChainReader consensus.ChainReader, round types.Round) { + log.Info("[setNewRound] new round and reset pools and workers", "round", round) x.currentRound = round x.timeoutCount = 0 - //TODO: tell miner now it's a new round and start mine if it's leader x.timeoutWorker.Reset(blockChainReader) //TODO: vote pools x.timeoutPool.Clear() - return nil } func (x *XDPoS_v2) broadcastToBftChannel(msg interface{}) { diff --git a/consensus/XDPoS/engines/engine_v2/epochSwitch.go b/consensus/XDPoS/engines/engine_v2/epochSwitch.go index e3787c42ff..1adaa34649 100644 --- a/consensus/XDPoS/engines/engine_v2/epochSwitch.go +++ b/consensus/XDPoS/engines/engine_v2/epochSwitch.go @@ -32,13 +32,13 @@ func (x *XDPoS_v2) getPreviousEpochSwitchInfoByHash(chain consensus.ChainReader, func (x *XDPoS_v2) getEpochSwitchInfo(chain consensus.ChainReader, header *types.Header, hash common.Hash) (*types.EpochSwitchInfo, error) { e, ok := x.epochSwitches.Get(hash) if ok { - log.Debug("[getEpochSwitchInfo] cache hit", "hash", hash.Hex()) epochSwitchInfo := e.(*types.EpochSwitchInfo) + log.Debug("[getEpochSwitchInfo] cache hit", "number", epochSwitchInfo.EpochSwitchBlockInfo.Number, "hash", hash.Hex()) return epochSwitchInfo, nil } h := header if h == nil { - log.Debug("[getEpochSwitchInfo] header missing, get header", "hash", hash.Hex()) + log.Debug("[getEpochSwitchInfo] header doesn't provide, get header by hash", "hash", hash.Hex()) h = chain.GetHeaderByHash(hash) if h == nil { log.Warn("[getEpochSwitchInfo] can not find header from db", "hash", hash.Hex()) @@ -135,6 +135,6 @@ func (x *XDPoS_v2) IsEpochSwitch(header *types.Header) (bool, uint64, error) { log.Info("[IsEpochSwitch] true, parent equals V2.SwitchBlock", "round", round, "number", header.Number.Uint64(), "hash", header.Hash()) return true, epochNum, nil } - log.Info("[IsEpochSwitch]", "parent round", parentRound, "round", round, "number", header.Number.Uint64(), "hash", header.Hash()) + log.Info("[IsEpochSwitch]", "is", parentRound < epochStartRound, "parentRound", parentRound, "round", round, "number", header.Number.Uint64(), "epochNum", epochNum, "hash", header.Hash()) return parentRound < epochStartRound, epochNum, nil } diff --git a/consensus/XDPoS/engines/engine_v2/timeout.go b/consensus/XDPoS/engines/engine_v2/timeout.go index ece20cfe23..f0aaafa31c 100644 --- a/consensus/XDPoS/engines/engine_v2/timeout.go +++ b/consensus/XDPoS/engines/engine_v2/timeout.go @@ -25,7 +25,7 @@ func (x *XDPoS_v2) timeoutHandler(blockChainReader consensus.ChainReader, timeou } // Collect timeout, generate TC isThresholdReached, numberOfTimeoutsInPool, pooledTimeouts := x.timeoutPool.Add(timeout) - log.Info("[timeoutHandler] collect timeout", "number", numberOfTimeoutsInPool) + log.Debug("[timeoutHandler] collect timeout", "number", numberOfTimeoutsInPool) // Threshold reached if isThresholdReached { @@ -140,10 +140,8 @@ func (x *XDPoS_v2) processTC(blockChainReader consensus.ChainReader, timeoutCert x.highestTimeoutCert = timeoutCert } if timeoutCert.Round >= x.currentRound { - err := x.setNewRound(blockChainReader, timeoutCert.Round+1) - if err != nil { - return err - } + x.setNewRound(blockChainReader, timeoutCert.Round+1) + } return nil } diff --git a/consensus/XDPoS/engines/engine_v2/verifyHeader.go b/consensus/XDPoS/engines/engine_v2/verifyHeader.go index 535221aea3..c4207b90a1 100644 --- a/consensus/XDPoS/engines/engine_v2/verifyHeader.go +++ b/consensus/XDPoS/engines/engine_v2/verifyHeader.go @@ -164,6 +164,12 @@ func (x *XDPoS_v2) verifyHeader(chain consensus.ChainReader, header *types.Heade // Verify the header validators address is legit by checking against its snapshot masternode list minutes the penalty list, we also ensure the order matches func (x *XDPoS_v2) isValidatorsLegit(chain consensus.ChainReader, header *types.Header, penalties []common.Address) (bool, error) { + + if header.Number.Cmp(x.config.V2.SwitchBlock) == 0 { + log.Info("[isValidatorsLegit] examing last v1 block") + return true, nil + } + snap, err := x.getSnapshot(chain, header.Number.Uint64(), false) if err != nil { log.Error("[isValidatorsLegit] Error while trying to get snapshot", "BlockNumber", header.Number.Int64(), "Hash", header.Hash().Hex(), "error", err) diff --git a/consensus/XDPoS/engines/engine_v2/vote.go b/consensus/XDPoS/engines/engine_v2/vote.go index eaf3034567..f044b32329 100644 --- a/consensus/XDPoS/engines/engine_v2/vote.go +++ b/consensus/XDPoS/engines/engine_v2/vote.go @@ -66,7 +66,7 @@ func (x *XDPoS_v2) voteHandler(chain consensus.ChainReader, voteMsg *types.Vote) // Collect vote thresholdReached, numberOfVotesInPool, pooledVotes := x.votePool.Add(voteMsg) - log.Info("[voteHandler] collect votes", "number", numberOfVotesInPool) + log.Debug("[voteHandler] collect votes", "number", numberOfVotesInPool) if thresholdReached { log.Info(fmt.Sprintf("[voteHandler] Vote pool threashold reached: %v, number of items in the pool: %v", thresholdReached, numberOfVotesInPool)) diff --git a/consensus/tests/engine_v2_tests/vote_test.go b/consensus/tests/engine_v2_tests/vote_test.go index d135b5d20c..77b43c3804 100644 --- a/consensus/tests/engine_v2_tests/vote_test.go +++ b/consensus/tests/engine_v2_tests/vote_test.go @@ -514,23 +514,23 @@ func TestVoteMsgMissingSnapshot(t *testing.T) { blockchain, _, currentBlock, signer, signFn, _ := PrepareXDCTestBlockChainForV2Engine(t, 915, params.TestXDPoSMockChainConfig, nil) engineV2 := blockchain.Engine().(*XDPoS.XDPoS).EngineV2 - blockInfo := &utils.BlockInfo{ + blockInfo := &types.BlockInfo{ Hash: currentBlock.Hash(), - Round: utils.Round(14), + Round: types.Round(14), Number: big.NewInt(915), } - voteForSign := &utils.VoteForSign{ + voteForSign := &types.VoteForSign{ ProposedBlockInfo: blockInfo, GapNumber: 450, } - signHash, _ := signFn(accounts.Account{Address: signer}, utils.VoteSigHash(voteForSign).Bytes()) - voteMsg := &utils.Vote{ + signHash, _ := signFn(accounts.Account{Address: signer}, types.VoteSigHash(voteForSign).Bytes()) + voteMsg := &types.Vote{ ProposedBlockInfo: blockInfo, Signature: signHash, GapNumber: 1350, // missing 1350 snapshot } - engineV2.SetNewRoundFaker(blockchain, utils.Round(14), false) + engineV2.SetNewRoundFaker(blockchain, types.Round(14), false) verified, err := engineV2.VerifyVoteMessage(blockchain, voteMsg) assert.False(t, verified) assert.NotNil(t, err) diff --git a/eth/bft/bft_handler.go b/eth/bft/bft_handler.go index 61c73ab03c..c4271b4b22 100644 --- a/eth/bft/bft_handler.go +++ b/eth/bft/bft_handler.go @@ -79,7 +79,7 @@ func (b *Bfter) Vote(vote *types.Vote) error { err = b.consensus.voteHandler(b.blockChainReader, vote) if err != nil { if _, ok := err.(*utils.ErrIncomingMessageRoundTooFarFromCurrentRound); ok { - log.Warn("vote round not equal", "error", err, "vote", vote.Hash()) + log.Debug("vote round not equal", "error", err, "vote", vote.Hash()) return err } log.Error("handle BFT Vote", "error", err) @@ -103,7 +103,7 @@ func (b *Bfter) Timeout(timeout *types.Timeout) error { err = b.consensus.timeoutHandler(b.blockChainReader, timeout) if err != nil { if _, ok := err.(*utils.ErrIncomingMessageRoundNotEqualCurrentRound); ok { - log.Warn("timeout round not equal", "error", err) + log.Debug("timeout round not equal", "error", err) return err } log.Error("handle BFT Timeout", "error", err) diff --git a/eth/fetcher/fetcher.go b/eth/fetcher/fetcher.go index 7b8389bf41..ea970ecfaf 100644 --- a/eth/fetcher/fetcher.go +++ b/eth/fetcher/fetcher.go @@ -729,9 +729,8 @@ func (f *Fetcher) insert(peer string, block *types.Block) { } err = f.handleProposedBlock(block.Header()) if err != nil { - log.Error("[insert] Unable to handle new proposed block", "err", err, "number", block.Number(), "hash", block.Hash()) + log.Warn("[insert] Unable to handle new proposed block", "err", err, "number", block.Number(), "hash", block.Hash()) } - // TODO: (XIN-101) Add propose block handler // If import succeeded, broadcast the block propAnnounceOutTimer.UpdateSince(block.ReceivedAt) if !fastBroadCast { diff --git a/eth/hooks/engine_v2_hooks.go b/eth/hooks/engine_v2_hooks.go index 689a4e13fa..e13dc1661c 100644 --- a/eth/hooks/engine_v2_hooks.go +++ b/eth/hooks/engine_v2_hooks.go @@ -19,50 +19,49 @@ import ( func AttachConsensusV2Hooks(adaptor *XDPoS.XDPoS, bc *core.BlockChain, chainConfig *params.ChainConfig) { // Hook scans for bad masternodes and decide to penalty them - adaptor.EngineV2.HookPenalty = func(chain consensus.ChainReader, number *big.Int, parentHash common.Hash, candidates []common.Address) ([]common.Address, error) { + adaptor.EngineV2.HookPenalty = func(chain consensus.ChainReader, number *big.Int, currentHash common.Hash, candidates []common.Address) ([]common.Address, error) { start := time.Now() listBlockHash := make([]common.Hash, chain.Config().XDPoS.Epoch) // get list block hash & stats total created block statMiners := make(map[common.Address]int) - listBlockHash[0] = parentHash + listBlockHash[0] = currentHash parentNumber := number.Uint64() - 1 - pHash := parentHash + parentHash := currentHash for i := uint64(1); ; i++ { - parentHeader := chain.GetHeader(pHash, parentNumber) - b, _, err := adaptor.EngineV2.IsEpochSwitch(parentHeader) + parentHeader := chain.GetHeader(parentHash, parentNumber) + isEpochSwitch, _, err := adaptor.EngineV2.IsEpochSwitch(parentHeader) if err != nil { - log.Error("[HookPenalty]", "err", err) + log.Error("[HookPenalty] isEpochSwitch", "err", err) return []common.Address{}, err } - if b { + if isEpochSwitch { break } miner := parentHeader.Coinbase // we can directly use coinbase, since it's verified (Verification is a TODO) - value, exist := statMiners[miner] + _, exist := statMiners[miner] if exist { - value = value + 1 + statMiners[miner]++ } else { - value = 1 + statMiners[miner] = 1 } - statMiners[miner] = value - pHash = parentHeader.ParentHash + parentHash = parentHeader.ParentHash + listBlockHash[i] = parentHash parentNumber-- - listBlockHash[i] = pHash } // add list not miner to penalties - preMasternodes := adaptor.EngineV2.GetMasternodesByHash(chain, parentHash) + preMasternodes := adaptor.EngineV2.GetMasternodesByHash(chain, currentHash) penalties := []common.Address{} for miner, total := range statMiners { if total < common.MinimunMinerBlockPerEpoch { - log.Debug("Find a node not enough requirement create block", "addr", miner.Hex(), "total", total) + log.Info("[HookPenalty] Find a node does not create enough block", "addr", miner.Hex(), "total", total, "require", common.MinimunMinerBlockPerEpoch) penalties = append(penalties, miner) } } for _, addr := range preMasternodes { if _, exist := statMiners[addr]; !exist { - log.Debug("Find a node don't create block", "addr", addr.Hex()) + log.Info("[HookPenalty] Find a node do not create any block", "addr", addr.Hex()) penalties = append(penalties, addr) } } @@ -72,10 +71,11 @@ func AttachConsensusV2Hooks(adaptor *XDPoS.XDPoS, bc *core.BlockChain, chainConf comebackHeight := (common.LimitPenaltyEpochV2+1)*chain.Config().XDPoS.Epoch + chain.Config().XDPoS.V2.SwitchBlock.Uint64() penComebacks := []common.Address{} if number.Uint64() > comebackHeight { - pens := adaptor.EngineV2.GetPreviousPenaltyByHash(chain, parentHash, common.LimitPenaltyEpochV2) + pens := adaptor.EngineV2.GetPreviousPenaltyByHash(chain, currentHash, common.LimitPenaltyEpochV2) for _, p := range pens { for _, addr := range candidates { if p == addr { + log.Info("[HookPenalty] get previous penalty node and add into comeback list", "addr", addr) penComebacks = append(penComebacks, p) break } @@ -123,7 +123,6 @@ func AttachConsensusV2Hooks(adaptor *XDPoS.XDPoS, bc *core.BlockChain, chainConf } } - log.Debug("Time Calculated HookPenaltyV2 ", "block", number, "pen comeback nodes", len(penComebacks), "not enough miner", len(penalties), "time", common.PrettyDuration(time.Since(start))) for _, comeback := range penComebacks { ok := true for _, p := range penalties { @@ -136,6 +135,11 @@ func AttachConsensusV2Hooks(adaptor *XDPoS.XDPoS, bc *core.BlockChain, chainConf penalties = append(penalties, comeback) } } + + for i, p := range penalties { + log.Info("[HookPenalty] Final penalty list", "index", i, "addr", p) + } + log.Info("[HookPenalty] Time Calculated HookPenaltyV2 ", "block", number, "time", common.PrettyDuration(time.Since(start))) return penalties, nil } diff --git a/miner/worker.go b/miner/worker.go index 5a0a72a2fa..299f9a9aa0 100644 --- a/miner/worker.go +++ b/miner/worker.go @@ -414,7 +414,7 @@ func (self *worker) wait() { c := self.engine.(*XDPoS.XDPoS) err = c.HandleProposedBlock(self.chain, block.Header()) if err != nil { - log.Error("[wait] Unable to handle new proposed block", "err", err, "number", block.Number(), "hash", block.Hash()) + log.Warn("[wait] Unable to handle new proposed block", "err", err, "number", block.Number(), "hash", block.Hash()) } authorized := c.IsAuthorisedAddress(self.chain, block.Header(), self.coinbase) @@ -435,7 +435,7 @@ func (self *worker) wait() { // Send tx sign to smart contract blockSigners. if block.NumberU64()%common.MergeSignRange == 0 || !self.config.IsTIP2019(block.Number()) { if err := contracts.CreateTransactionSign(self.config, self.eth.TxPool(), self.eth.AccountManager(), block, self.chainDb, self.coinbase); err != nil { - log.Error("Fail to create tx sign for signer", "error", "err") + log.Error("Fail to create tx sign for signer", "error", err) } } }