[consensus] add more logs in case of errors

Makefile

@@ -49,7 +49,9 @@ pb: pb_rawapi pb_ibft pb_synccommittee
 
 SOL_FILES := $(wildcard nil/contracts/solidity/tests/*.sol nil/contracts/solidity/*.sol)
 BIN_FILES := $(patsubst nil/contracts/solidity/%.sol, contracts/compiled/%.bin, $(SOL_FILES))
-CHECK_LOCKS_DIRECTORIES := ./nil/internal/network ./nil/internal/network/connection_manager
+CHECK_LOCKS_DIRECTORIES := ./nil/internal/network \
+                           ./nil/internal/network/connection_manager \
+                           ./nil/internal/collate
 # TODO: Uncomment the line below when all checks have passed to run checklocks across all directories
 # CHECK_LOCKS_DIRECTORIES := $(shell find ./nil -type f -name "*.go" | xargs -I {} dirname {} | sort -u)
 

nil/internal/collate/errors/errors.go

@@ -0,0 +1,9 @@
+package errors
+
+import "errors"
+
+var (
+	ErrOldBlock     = errors.New("received old block")
+	ErrOutOfOrder   = errors.New("received block is out of order")
+	ErrHashMismatch = errors.New("block hash mismatch")
+)

nil/internal/collate/syncer.go

@@ -11,6 +11,7 @@ import (
 	"github.com/NilFoundation/nil/nil/common/assert"
 	"github.com/NilFoundation/nil/nil/common/check"
 	"github.com/NilFoundation/nil/nil/common/logging"
+	cerrors "github.com/NilFoundation/nil/nil/internal/collate/errors"
 	"github.com/NilFoundation/nil/nil/internal/db"
 	"github.com/NilFoundation/nil/nil/internal/execution"
 	"github.com/NilFoundation/nil/nil/internal/network"
@@ -239,10 +240,10 @@ func (s *Syncer) processTopicTransaction(ctx context.Context, data []byte) (bool
 
 	if err := s.saveBlock(ctx, b); err != nil {
 		switch {
-		case errors.Is(err, errOutOfOrder):
+		case errors.Is(err, cerrors.ErrOutOfOrder):
 			// todo: queue the block for later processing
 			return false, nil
-		case errors.Is(err, errOldBlock):
+		case errors.Is(err, cerrors.ErrOldBlock):
 			return false, nil
 		default:
 			return false, err
@@ -265,7 +266,7 @@ func (s *Syncer) fetchBlocks(ctx context.Context) {
 		for block := range blocksCh {
 			count++
 			if err := s.saveBlock(ctx, block); err != nil {
-				if errors.Is(err, errOldBlock) {
+				if errors.Is(err, cerrors.ErrOldBlock) {
 					continue
 				}
 				s.logger.Error().

nil/internal/collate/validator.go

@@ -12,6 +12,7 @@ import (
 	"github.com/NilFoundation/nil/nil/common"
 	"github.com/NilFoundation/nil/nil/common/check"
 	"github.com/NilFoundation/nil/nil/common/logging"
+	cerrors "github.com/NilFoundation/nil/nil/internal/collate/errors"
 	"github.com/NilFoundation/nil/nil/internal/config"
 	"github.com/NilFoundation/nil/nil/internal/db"
 	"github.com/NilFoundation/nil/nil/internal/execution"
@@ -20,12 +21,6 @@ import (
 	"github.com/NilFoundation/nil/nil/internal/types"
 )
 
-var (
-	errOldBlock     = errors.New("received old block")
-	errOutOfOrder   = errors.New("received block is out of order")
-	errHashMismatch = errors.New("block hash mismatch")
-)
-
 type invalidSignatureError struct {
 	inner error
 }
@@ -40,20 +35,20 @@ func newErrInvalidSignature(inner error) invalidSignatureError {
 
 type Validator struct {
 	params             *Params
-	mainShardValidator *Validator
+	mainShardValidator *Validator // +checklocksignore: thread safe
 
 	txFabric       db.DB
 	pool           TxnPool
-	networkManager *network.Manager
-	blockVerifier  *signer.BlockVerifier
+	networkManager *network.Manager      // +checklocksignore: thread safe
+	blockVerifier  *signer.BlockVerifier // +checklocksignore: thread safe
 
 	mutex         sync.RWMutex
-	lastBlock     *types.Block
-	lastBlockHash common.Hash
+	lastBlock     *types.Block // +checklocks:mutex
+	lastBlockHash common.Hash  // +checklocks:mutex
 
 	subsMutex sync.Mutex
-	subsId    uint64
-	subs      map[uint64]chan types.BlockNumber
+	subsId    uint64                            // +checklocks:subsMutex
+	subs      map[uint64]chan types.BlockNumber // +checklocks:subsMutex
 
 	logger logging.Logger
 }
@@ -75,6 +70,7 @@ func NewValidator(
 	}
 }
 
+// +checklocksread:s.mutex
 func (s *Validator) getLastBlockUnlocked(ctx context.Context) (*types.Block, common.Hash, error) {
 	if s.lastBlock != nil {
 		return s.lastBlock, s.lastBlockHash, nil
@@ -144,14 +140,14 @@ func (s *Validator) VerifyProposal(ctx context.Context, proposal *execution.Prop
 		return nil, err
 	}
 
-	// No lock since it accesses last block/hash only inside "locked" GetLastBlock function
-	prevBlock, prevBlockHash, err := s.GetLastBlock(ctx)
-	if err != nil {
+	// No lock since below we use only locked functions and only in read mode
+	if err := s.validateProposal(ctx, p); err != nil {
 		return nil, err
 	}
 
-	if prevBlockHash != proposal.PrevBlockHash {
-		return nil, fmt.Errorf("%w: expected %x, got %x", errHashMismatch, prevBlockHash, proposal.PrevBlockHash)
+	prevBlock, _, err := s.GetLastBlock(ctx)
+	if err != nil {
+		return nil, err
 	}
 
 	s.params.ExecutionMode = execution.ModeVerify
@@ -179,6 +175,7 @@ func (s *Validator) InsertProposal(
 	return s.insertProposalUnlocked(ctx, proposal, params)
 }
 
+// +checklocks:s.mutex
 func (s *Validator) insertProposalUnlocked(
 	ctx context.Context,
 	proposal *execution.ProposalSSZ,
@@ -220,6 +217,7 @@ func (s *Validator) insertProposalUnlocked(
 	})
 }
 
+// +checklocks:s.mutex
 func (s *Validator) onBlockCommitUnlocked(
 	ctx context.Context, res *execution.BlockGenerationResult, proposal *execution.Proposal,
 ) {
@@ -272,6 +270,7 @@ func (s *Validator) validateRepliedBlock(
 	return nil
 }
 
+// +checklocksread:s.mutex
 func (s *Validator) validateProposalUnlocked(ctx context.Context, proposal *execution.Proposal) error {
 	lastBlock, lastBlockHash, err := s.getLastBlockUnlocked(ctx)
 	if err != nil {
@@ -281,17 +280,17 @@ func (s *Validator) validateProposalUnlocked(ctx context.Context, proposal *exec
 	blockId := proposal.PrevBlockId + 1
 	if blockId <= lastBlock.Id {
 		s.logger.Trace().
-			Err(errOldBlock).
+			Err(cerrors.ErrOldBlock).
 			Stringer(logging.FieldBlockNumber, blockId).
 			Send()
-		return errOldBlock
+		return cerrors.ErrOldBlock
 	}
 
 	if blockId != lastBlock.Id+1 {
 		s.logger.Debug().
 			Stringer(logging.FieldBlockNumber, blockId).
 			Msgf("Received block %d is out of order with the last block %d", blockId, lastBlock.Id)
-		return errOutOfOrder
+		return cerrors.ErrOutOfOrder
 	}
 
 	if lastBlockHash != proposal.PrevBlockHash {
@@ -303,18 +302,25 @@ func (s *Validator) validateProposalUnlocked(ctx context.Context, proposal *exec
 			Stringer("lastHash", lastBlockHash).
 			Stringer("expectedLastHash", proposal.PrevBlockHash).
 			Msgf("Previous block hash mismatch: expected %x, got %x", lastBlockHash, proposal.PrevBlockHash)
-		return errHashMismatch
+		return cerrors.ErrHashMismatch
 	}
 
 	return nil
 }
 
+func (s *Validator) validateProposal(ctx context.Context, proposal *execution.Proposal) error {
+	s.mutex.RLock()
+	defer s.mutex.RUnlock()
+	return s.validateProposalUnlocked(ctx, proposal)
+}
+
 func (s *Validator) ReplayBlock(ctx context.Context, block *types.BlockWithExtractedData) error {
 	s.mutex.Lock()
 	defer s.mutex.Unlock()
 	return s.replayBlockUnlocked(ctx, block)
 }
 
+// +checklocks:s.mutex
 func (s *Validator) replayBlockUnlocked(ctx context.Context, block *types.BlockWithExtractedData) error {
 	blockHash := block.Block.Hash(s.params.ShardId)
 	s.logger.Trace().
@@ -370,7 +376,7 @@ func (s *Validator) replayBlockUnlocked(ctx context.Context, block *types.BlockW
 	}
 
 	if err := s.validateProposalUnlocked(ctx, proposal); err != nil {
-		if errors.Is(err, errHashMismatch) {
+		if errors.Is(err, cerrors.ErrHashMismatch) {
 			return returnErrorOrPanic(err)
 		}
 		return err
@@ -405,6 +411,7 @@ func (s *Validator) replayBlockUnlocked(ctx context.Context, block *types.BlockW
 	return nil
 }
 
+// +checklocks:s.mutex
 func (s *Validator) setLastBlockUnlocked(block *types.Block, hash common.Hash) {
 	s.lastBlock = block
 	s.lastBlockHash = hash
@@ -447,6 +454,7 @@ func (s *Validator) checkBlock(ctx context.Context, expectedHash common.Hash) (b
 	return s.checkBlockUnlocked(ctx, expectedHash)
 }
 
+// +checklocksread:s.mutex
 func (s *Validator) checkBlockUnlocked(ctx context.Context, expectedHash common.Hash) (bool, error) {
 	_, hash, err := s.getLastBlockUnlocked(ctx)
 	if err != nil {

nil/internal/consensus/ibft/ibft.go

@@ -2,6 +2,7 @@ package ibft
 
 import (
 	"context"
+	"errors"
 	"math/big"
 	"slices"
 
@@ -10,6 +11,7 @@ import (
 	"github.com/NilFoundation/nil/nil/go-ibft/core"
 	"github.com/NilFoundation/nil/nil/go-ibft/messages"
 	protoIBFT "github.com/NilFoundation/nil/nil/go-ibft/messages/proto"
+	cerrors "github.com/NilFoundation/nil/nil/internal/collate/errors"
 	"github.com/NilFoundation/nil/nil/internal/config"
 	"github.com/NilFoundation/nil/nil/internal/crypto/bls"
 	"github.com/NilFoundation/nil/nil/internal/db"
@@ -180,7 +182,11 @@ func (i *backendIBFT) InsertProposal(proposal *protoIBFT.Proposal, committedSeal
 		ProposerIndex: proposerIndex,
 		Signature:     sig,
 	}); err != nil {
-		logger.Error().Err(err).Msg("Failed to insert proposal")
+		event := i.logger.Error()
+		if errors.Is(err, cerrors.ErrOldBlock) {
+			event = i.logger.Debug()
+		}
+		event.Err(err).Msg("Failed to insert proposal")
 	}
 }
 

nil/internal/consensus/ibft/verifier.go

@@ -2,20 +2,35 @@ package ibft
 
 import (
 	"bytes"
+	"errors"
 
 	"github.com/NilFoundation/nil/nil/common/logging"
 	"github.com/NilFoundation/nil/nil/go-ibft/messages"
 	protoIBFT "github.com/NilFoundation/nil/nil/go-ibft/messages/proto"
+	cerrors "github.com/NilFoundation/nil/nil/internal/collate/errors"
 	"github.com/NilFoundation/nil/nil/internal/config"
 )
 
 func (i *backendIBFT) IsValidProposal(rawProposal []byte) bool {
 	proposal, err := i.unmarshalProposal(rawProposal)
 	if err != nil {
+		i.logger.Error().
+			Err(err).
+			Uint64(logging.FieldHeight, uint64(proposal.PrevBlockId)+1).
+			Msg("Failed to unmarshal proposal")
 		return false
 	}
 
 	_, err = i.validator.VerifyProposal(i.ctx, proposal)
+	if err != nil {
+		event := i.logger.Error()
+		if errors.Is(err, cerrors.ErrOldBlock) {
+			event = i.logger.Debug()
+		}
+		event.Err(err).
+			Uint64(logging.FieldHeight, uint64(proposal.PrevBlockId)+1).
+			Msg("Proposal is invalid")
+	}
 	return err == nil
 }
 
@@ -114,6 +129,15 @@ func (i *backendIBFT) IsValidProposalHash(proposal *protoIBFT.Proposal, hash []b
 
 	block, err := i.validator.VerifyProposal(i.ctx, prop)
 	if err != nil {
+		event := i.logger.Error()
+		if errors.Is(err, cerrors.ErrOldBlock) {
+			event = i.logger.Debug()
+		}
+
+		event.Err(err).
+			Uint64(logging.FieldRound, proposal.Round).
+			Uint64(logging.FieldHeight, uint64(prop.PrevBlockId)+1).
+			Msg("Failed to verify proposal")
 		return false
 	}