refactor and improve log (#92)

* refactor and improve log

* fix conflict and test

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{}) {

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
 }

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
 }

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)

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))
 

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)

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)

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 {

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
 	}
 

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)
 					}
 				}
 			}