eth, consensus: refactor whitelisting related logs and improve error handling

consensus/bor/heimdall.go

@@ -17,8 +17,8 @@ type IHeimdallClient interface {
 	FetchCheckpointCount(ctx context.Context) (int64, error)
 	FetchMilestone(ctx context.Context) (*milestone.Milestone, error)
 	FetchMilestoneCount(ctx context.Context) (int64, error)
-	FetchNoAckMilestone(ctx context.Context, milestoneID string) error //Fetch the bool value whether milestone corresponding to the given id failed in the Heimdall
-	FetchLastNoAckMilestone(ctx context.Context) (string, error)       //Fetch latest failed milestone id
-	FetchMilestoneID(ctx context.Context, milestoneID string) error    //Fetch the bool value whether milestone corresponding to the given id is in process in Heimdall
+	FetchNoAckMilestone(ctx context.Context, milestoneID string) error // Fetch the bool value whether milestone corresponding to the given id failed in the Heimdall
+	FetchLastNoAckMilestone(ctx context.Context) (string, error)       // Fetch latest failed milestone id
+	FetchMilestoneID(ctx context.Context, milestoneID string) error    // Fetch the bool value whether milestone corresponding to the given id is in process in Heimdall
 	Close()
 }

consensus/bor/heimdallapp/milestone.go

@@ -14,60 +14,61 @@ import (
 )
 
 func (h *HeimdallAppClient) FetchMilestoneCount(_ context.Context) (int64, error) {
-	log.Info("Fetching milestone count")
+	log.Debug("Fetching milestone count")
 
 	res := h.hApp.CheckpointKeeper.GetMilestoneCount(h.NewContext())
 
-	log.Info("Fetched Milestone Count")
+	log.Debug("Fetched Milestone Count", "res", int64(res))
 
 	return int64(res), nil
 }
 
 func (h *HeimdallAppClient) FetchMilestone(_ context.Context) (*milestone.Milestone, error) {
-	log.Info("Fetching Latest Milestone")
+	log.Debug("Fetching Latest Milestone")
 
 	res, err := h.hApp.CheckpointKeeper.GetLastMilestone(h.NewContext())
 	if err != nil {
 		return nil, err
 	}
 
-	log.Info("Fetched Latest Milestone")
+	milestone := toBorMilestone(res)
+	log.Debug("Fetched Latest Milestone", "milestone", milestone)
 
-	return toBorMilestone(res), nil
+	return milestone, nil
 }
 
 func (h *HeimdallAppClient) FetchNoAckMilestone(_ context.Context, milestoneID string) error {
-	log.Info("Fetching No Ack Milestone By MilestoneID", "MilestoneID", milestoneID)
+	log.Debug("Fetching No Ack Milestone By MilestoneID", "MilestoneID", milestoneID)
 
 	res := h.hApp.CheckpointKeeper.GetNoAckMilestone(h.NewContext(), milestoneID)
 	if res {
 		log.Info("Fetched No Ack By MilestoneID", "MilestoneID", milestoneID)
 		return nil
 	}
 
-	return fmt.Errorf("Still No Ack Milestone exist corresponding to MilestoneId:%v", milestoneID)
+	return fmt.Errorf("still no-ack milestone exist corresponding to milestoneID: %v", milestoneID)
 }
 
 func (h *HeimdallAppClient) FetchLastNoAckMilestone(_ context.Context) (string, error) {
-	log.Info("Fetching Latest No Ack Milestone ID")
+	log.Debug("Fetching Latest No Ack Milestone ID")
 
 	res := h.hApp.CheckpointKeeper.GetLastNoAckMilestone(h.NewContext())
 
-	log.Info("Fetched Latest No Ack Milestone ID")
+	log.Debug("Fetched Latest No Ack Milestone ID", "res", res)
 
 	return res, nil
 }
 
 func (h *HeimdallAppClient) FetchMilestoneID(_ context.Context, milestoneID string) error {
-	log.Info("Fetching Milestone ID ", "MilestoneID", milestoneID)
+	log.Debug("Fetching Milestone ID ", "MilestoneID", milestoneID)
 
 	res := chTypes.GetMilestoneID()
 
 	if res == milestoneID {
 		return nil
 	}
 
-	return fmt.Errorf("Milestone corresponding to Milestone ID:%v doesn't exist in Heimdall", milestoneID)
+	return fmt.Errorf("milestone corresponding to milestoneID: %v doesn't exist in heimdall", milestoneID)
 }
 
 func toBorMilestone(hdMilestone *hmTypes.Milestone) *milestone.Milestone {

consensus/bor/heimdallgrpc/milestone.go

@@ -5,6 +5,7 @@ import (
 	"fmt"
 	"math/big"
 
+	"github.com/ethereum/go-ethereum/consensus/bor/heimdall"
 	"github.com/ethereum/go-ethereum/consensus/bor/heimdall/milestone"
 	"github.com/ethereum/go-ethereum/log"
 
@@ -48,14 +49,14 @@ func (h *HeimdallGRPCClient) FetchMilestone(ctx context.Context) (*milestone.Mil
 }
 
 func (h *HeimdallGRPCClient) FetchLastNoAckMilestone(ctx context.Context) (string, error) {
-	log.Info("Fetching latest no ack milestone Id")
+	log.Debug("Fetching latest no ack milestone Id")
 
 	res, err := h.client.FetchLastNoAckMilestone(ctx, nil)
 	if err != nil {
 		return "", err
 	}
 
-	log.Info("Fetched last no-ack milestone")
+	log.Debug("Fetched last no-ack milestone", "res", res.Result.Result)
 
 	return res.Result.Result, nil
 }
@@ -65,18 +66,18 @@ func (h *HeimdallGRPCClient) FetchNoAckMilestone(ctx context.Context, milestoneI
 		MilestoneID: milestoneID,
 	}
 
-	log.Info("Fetching no ack milestone", "milestoneaID", milestoneID)
+	log.Debug("Fetching no ack milestone", "milestoneID", milestoneID)
 
 	res, err := h.client.FetchNoAckMilestone(ctx, req)
 	if err != nil {
 		return err
 	}
 
 	if !res.Result.Result {
-		return fmt.Errorf("Not in rejected list: milestoneID %q", milestoneID)
+		return fmt.Errorf("%w: milestoneID %q", heimdall.ErrNotInRejectedList, milestoneID)
 	}
 
-	log.Info("Fetched no ack milestone", "milestoneaID", milestoneID)
+	log.Debug("Fetched no ack milestone", "milestoneID", milestoneID)
 
 	return nil
 }
@@ -86,18 +87,18 @@ func (h *HeimdallGRPCClient) FetchMilestoneID(ctx context.Context, milestoneID s
 		MilestoneID: milestoneID,
 	}
 
-	log.Info("Fetching milestone id", "milestoneID", milestoneID)
+	log.Debug("Fetching milestone id", "milestoneID", milestoneID)
 
 	res, err := h.client.FetchMilestoneID(ctx, req)
 	if err != nil {
 		return err
 	}
 
 	if !res.Result.Result {
-		return fmt.Errorf("This milestoneID %q does not exist", milestoneID)
+		return fmt.Errorf("%w: milestoneID %q", heimdall.ErrNotInMilestoneList, milestoneID)
 	}
 
-	log.Info("Fetched milestone id", "milestoneID", milestoneID)
+	log.Debug("Fetched milestone id", "milestoneID", milestoneID)
 
 	return nil
 }

core/blockchain_test.go

@@ -4500,10 +4500,12 @@ func TestTxIndexer(t *testing.T) {
 	}
 	verify := func(db ethdb.Database, expTail uint64) {
 		tail := rawdb.ReadTxIndexTail(db)
+		//nolint:staticcheck
 		if tail == nil {
 			t.Fatal("Failed to write tx index tail")
 		}
 
+		//nolint:staticcheck
 		if *tail != expTail {
 			t.Fatalf("Unexpected tx index tail, want %v, got %d", expTail, *tail)
 		}

eth/backend.go

@@ -695,30 +695,24 @@ func retryHeimdallHandler(fn heimdallHandler, tickerDuration time.Duration, time
 		return
 	}
 
-	// first run for fetching milestones
+	// first run
 	firstCtx, cancel := context.WithTimeout(context.Background(), timeout)
-	err = fn(firstCtx, ethHandler, bor)
+	_ = fn(firstCtx, ethHandler, bor)
 
 	cancel()
 
-	if err != nil {
-		log.Warn(fmt.Sprintf("unable to start the %s service - first run", fnName), "err", err)
-	}
-
 	ticker := time.NewTicker(tickerDuration)
 	defer ticker.Stop()
 
 	for {
 		select {
 		case <-ticker.C:
 			ctx, cancel := context.WithTimeout(context.Background(), timeout)
-			err := fn(ctx, ethHandler, bor)
 
-			cancel()
+			// Skip any error reporting here as it's handled in respective functions
+			_ = fn(ctx, ethHandler, bor)
 
-			if err != nil {
-				log.Warn(fmt.Sprintf("unable to handle %s", fnName), "err", err)
-			}
+			cancel()
 		case <-closeCh:
 			return
 		}
@@ -754,7 +748,7 @@ func (s *Ethereum) handleMilestone(ctx context.Context, ethHandler *ethHandler,
 	// If the current chain head is behind the received milestone, add it to the future milestone
 	// list. Also, the hash mismatch (end block hash) error will lead to rewind so also
 	// add that milestone to the future milestone list.
-	if errors.Is(err, errMissingBlocks) || errors.Is(err, errHashMismatch) {
+	if errors.Is(err, errChainOutOfSync) || errors.Is(err, errHashMismatch) {
 		ethHandler.downloader.ProcessFutureMilestone(num, hash)
 	}
 

eth/bor_checkpoint_verifier.go

@@ -12,12 +12,16 @@ import (
 )
 
 var (
-	// errMissingBlocks is returned when we don't have the blocks locally, yet.
-	errMissingBlocks = errors.New("missing blocks")
+	// errMissingCurrentBlock is returned when we don't have the current block
+	// present locally.
+	errMissingCurrentBlock = errors.New("current block missing")
 
-	// errRootHash is returned when we aren't able to calculate the root hash
-	// locally for a range of blocks.
-	errRootHash = errors.New("failed to get local root hash")
+	// errChainOutOfSync is returned when we're trying to process a future
+	// checkpoint/milestone and we haven't reached at that number yet.
+	errChainOutOfSync = errors.New("chain out of sync")
+
+	// errRootHash is returned when the root hash calculation for a range of blocks fails.
+	errRootHash = errors.New("root hash calculation failed")
 
 	// errHashMismatch is returned when the local hash doesn't match
 	// with the hash of checkpoint/milestone. It is the root hash of blocks
@@ -30,10 +34,7 @@ var (
 	// errEndBlock is returned when we're unable to fetch a block locally.
 	errTipConfirmationBlock = errors.New("failed to get tip confirmation block")
 
-	// errBlockNumberConversion is returned when we get err in parsing hexautil block number
-	errBlockNumberConversion = errors.New("failed to parse the block number")
-
-	//Metrics for collecting the rewindLength
+	// rewindLengthMeter for collecting info about the length of chain rewinded
 	rewindLengthMeter = metrics.NewRegisteredMeter("chain/autorewind/length", nil)
 )
 
@@ -57,14 +58,14 @@ func borVerify(ctx context.Context, eth *Ethereum, handler *ethHandler, start ui
 	currentBlock := eth.BlockChain().CurrentBlock()
 	if currentBlock == nil {
 		log.Debug(fmt.Sprintf("Failed to fetch current block from blockchain while verifying incoming %s", str))
-		return hash, errMissingBlocks
+		return hash, errMissingCurrentBlock
 	}
 
 	head := currentBlock.Number.Uint64()
 
 	if head < end {
 		log.Debug(fmt.Sprintf("Current head block behind incoming %s block", str), "head", head, "end block", end)
-		return hash, errMissingBlocks
+		return hash, errChainOutOfSync
 	}
 
 	var localHash string
@@ -77,23 +78,22 @@ func borVerify(ctx context.Context, eth *Ethereum, handler *ethHandler, start ui
 		localHash, err = handler.ethAPI.GetRootHash(ctx, start, end)
 
 		if err != nil {
-			log.Debug("Failed to get root hash of given block range while whitelisting checkpoint", "start", start, "end", end, "err", err)
-			return hash, errRootHash
+			log.Debug("Failed to calculate root hash of given block range while whitelisting checkpoint", "start", start, "end", end, "err", err)
+			return hash, fmt.Errorf("%w: %v", errRootHash, err)
 		}
 	} else {
 		// in case of milestone(isCheckpoint==false) get the hash of endBlock
 		block, err := handler.ethAPI.GetBlockByNumber(ctx, rpc.BlockNumber(end), false)
 		if err != nil {
 			log.Debug("Failed to get end block hash while whitelisting milestone", "number", end, "err", err)
-			return hash, errEndBlock
+			return hash, fmt.Errorf("%w: %v", errEndBlock, err)
 		}
 
 		localHash = fmt.Sprintf("%v", block["hash"])[2:]
 	}
 
 	//nolint
 	if localHash != hash {
-
 		if isCheckpoint {
 			log.Warn("Root hash mismatch while whitelisting checkpoint", "expected", localHash, "got", hash)
 		} else {
@@ -124,9 +124,9 @@ func borVerify(ctx context.Context, eth *Ethereum, handler *ethHandler, start ui
 		}
 
 		if isCheckpoint {
-			log.Warn("Rewinding chain due to checkpoint root hash mismatch", "number", rewindTo)
+			log.Info("Rewinding chain due to checkpoint root hash mismatch", "number", rewindTo)
 		} else {
-			log.Warn("Rewinding chain due to milestone endblock hash mismatch", "number", rewindTo)
+			log.Info("Rewinding chain due to milestone endblock hash mismatch", "number", rewindTo)
 		}
 
 		rewindBack(eth, head, rewindTo)
@@ -138,7 +138,7 @@ func borVerify(ctx context.Context, eth *Ethereum, handler *ethHandler, start ui
 	block, err := handler.ethAPI.GetBlockByNumber(ctx, rpc.BlockNumber(end), false)
 	if err != nil {
 		log.Debug("Failed to get end block hash while whitelisting", "err", err)
-		return hash, errEndBlock
+		return hash, fmt.Errorf("%w: %v", errEndBlock, err)
 	}
 
 	hash = fmt.Sprintf("%v", block["hash"])
@@ -170,5 +170,4 @@ func rewind(eth *Ethereum, head uint64, rewindTo uint64) {
 	} else {
 		rewindLengthMeter.Mark(int64(head - rewindTo))
 	}
-
 }

eth/downloader/whitelist/finality.go

@@ -18,6 +18,7 @@ type finality[T rawdb.BlockFinality[T]] struct {
 	Number   uint64      // Number , populated by reaching out to heimdall
 	interval uint64      // Interval, until which we can allow importing
 	doExist  bool
+	name     string // Name of the service (checkpoint or milestone)
 }
 
 type finalityService interface {
@@ -43,21 +44,33 @@ func (f *finality[T]) IsValidPeer(fetchHeadersByNumber func(number uint64, amoun
 	return isValidPeer(fetchHeadersByNumber, doExist, number, hash)
 }
 
-// IsValidChain checks the validity of chain by comparing it
-// against the local checkpoint entry
-// todo: need changes
+// IsValidChain checks the validity of chain by comparing it against the local
+// whitelisted entry of checkpoint/milestone.
 func (f *finality[T]) IsValidChain(currentHeader *types.Header, chain []*types.Header) (bool, error) {
 	// Return if we've received empty chain
 	if len(chain) == 0 {
 		return false, nil
 	}
 
-	res, err := isValidChain(currentHeader, chain, f.doExist, f.Number, f.Hash)
+	return isValidChain(currentHeader, chain, f.doExist, f.Number, f.Hash)
+}
 
-	return res, err
+// reportWhitelist logs the block number and hash if a new and unique entry is being inserted
+// and it doesn't log for duplicate/redundant entries.
+func (f *finality[T]) reportWhitelist(block uint64, hash common.Hash) {
+	msg := fmt.Sprintf("Whitelisting new %s from heimdall", f.name)
+	if !f.doExist {
+		log.Info(msg, "block", block, "hash", hash)
+	} else {
+		if f.Number != block && f.Hash != hash {
+			log.Info(msg, "block", block, "hash", hash)
+		}
+	}
 }
 
 func (f *finality[T]) Process(block uint64, hash common.Hash) {
+	f.reportWhitelist(block, hash)
+
 	f.doExist = true
 	f.Hash = hash
 	f.Number = block

eth/downloader/whitelist/service.go

@@ -60,6 +60,7 @@ func NewService(db ethdb.Database) *Service {
 				Hash:     checkpointHash,
 				interval: 256,
 				db:       db,
+				name:     "checkpoint",
 			},
 		},
 
@@ -70,6 +71,7 @@ func NewService(db ethdb.Database) *Service {
 				Hash:     milestoneHash,
 				interval: 256,
 				db:       db,
+				name:     "milestone",
 			},
 
 			Locked:                locked,