fix: request headers when a node falsely reports itself synchronized

core/process/constants.go

@@ -36,9 +36,6 @@ const MaxSyncWithErrorsAllowed = 10
 // SlotModulusTrigger defines a slot modulus on which a trigger for an action will be released
 const SlotModulusTrigger = 5
 
-// SlotModulusTriggerWhenSyncIsStuck defines a slot modulus on which a trigger for an action when sync is stuck will be released
-const SlotModulusTriggerWhenSyncIsStuck = 20
-
 // MinForkSlot represents the minimum fork slot set by a notarized header received
 const MinForkSlot = uint64(0)
 

core/process/headerCheck/headerSignatureVerify.go

@@ -1,6 +1,7 @@
 package headerCheck
 
 import (
+	"errors"
 	"math/bits"
 
 	logger "github.com/klever-io/klever-go-logger"
@@ -113,6 +114,7 @@ func (hsv *HeaderSigVerifier) VerifySignature(header data.HeaderHandler) error {
 		epoch,
 	)
 	if err != nil {
+		logIfEpochConfigMissing(err, header, epoch, "signature")
 		return err
 	}
 
@@ -293,9 +295,42 @@ func (hsv *HeaderSigVerifier) getLeader(header data.HeaderHandler) (crypto.Publi
 
 	headerConsensusGroup, err := hsv.nodesCoordinator.ComputeConsensusGroup(prevRandSeed, header.GetSlot(), epoch)
 	if err != nil {
+		logIfEpochConfigMissing(err, header, epoch, "leader")
 		return nil, err
 	}
 
 	leaderPubKeyValidator := headerConsensusGroup[0]
 	return hsv.keyGen.PublicKeyFromByteArray(leaderPubKeyValidator.PubKey())
 }
+
+// logIfEpochConfigMissing emits a dedicated line when a header is rejected only
+// because the consensus configuration for its epoch has not been built yet. That
+// configuration is created when the epoch-start block is committed, so between an
+// epoch boundary and that commit every new-epoch header fails here, on gossip, on
+// self-requested headers and on the consensus topic alike (issue #90).
+//
+// Kept at debug level on purpose: an unauthenticated peer can trigger this path
+// with a header carrying an arbitrary future epoch, so a louder level would be a
+// cheap log-flood lever. Enable process/headerCheck:DEBUG to measure how many
+// slots the window actually spans. The header hash is deliberately absent for the
+// same reason: it is not computed yet at this point, and computing one here would
+// put a marshal plus a hash on a path an unauthenticated peer can drive.
+//
+// lookupEpoch is the epoch whose configuration was actually missing, which is not
+// the header's own epoch for an epoch-start header: both callers verify those
+// against the previous epoch. Both values are logged so the line cannot send an
+// operator looking for the wrong configuration.
+func logIfEpochConfigMissing(err error, header data.HeaderHandler, lookupEpoch uint32, stage string) {
+	if !errors.Is(err, sharding.ErrEpochNodesConfigDoesNotExist) {
+		return
+	}
+
+	log.Debug("header rejected, epoch consensus config not built yet",
+		"stage", stage,
+		"missing config for epoch", lookupEpoch,
+		"header epoch", header.GetEpoch(),
+		"nonce", header.GetNonce(),
+		"slot", header.GetSlot(),
+		"is epoch start", header.GetIsEpochStart(),
+	)
+}

core/process/headerCheck/headerSignatureVerify_test.go

@@ -3,8 +3,10 @@ package headerCheck_test
 import (
 	"bytes"
 	"errors"
+	"fmt"
 	"testing"
 
+	logger "github.com/klever-io/klever-go-logger"
 	"github.com/klever-io/klever-go/common"
 	cMock "github.com/klever-io/klever-go/common/mock"
 	"github.com/klever-io/klever-go/core/process"
@@ -726,3 +728,149 @@ func TestHeaderSigVerifier_VerifySignatureOkWhenFallbackThresholdCouldBeApplied(
 	require.Nil(t, err)
 	require.True(t, wasCalled)
 }
+
+// epochConfigLogFormatter keeps everything except the epoch-config rejection line
+// out of the observer buffer, so unrelated log output from other tests in this
+// package cannot make the assertions below flaky. Same idiom as
+// core/process/transactionLog/printTxLogProcessor_test.go.
+type epochConfigLogFormatter struct {
+	logger.PlainFormatter
+}
+
+func (f *epochConfigLogFormatter) Output(line logger.LogLineHandler) []byte {
+	if line.GetMessage() != "header rejected, epoch consensus config not built yet" {
+		return nil
+	}
+
+	return f.PlainFormatter.Output(line)
+}
+
+// The epoch consensus configuration is only built when the epoch-start block is
+// committed, so between an epoch boundary and that commit every new-epoch header
+// is rejected here (issue #90).
+//
+// Two things must hold. The sentinel has to reach the caller intact, because the
+// worker's blacklist suppression keys off it (core/consensus/slot/worker.go) and
+// a header rejected only for this reason is early rather than invalid. And the
+// rejection has to be observable, because counting the slots it spans is how the
+// window's real duration gets measured.
+//
+// Not parallel: it mutates the global log level and observer list.
+func TestHeaderSigVerifier_EpochNodesConfigMissingIsSurfacedIntact(t *testing.T) {
+	const missingEpoch = uint32(7)
+
+	previousPattern := logger.GetLogLevelPattern()
+	require.Nil(t, logger.SetLogLevel("*:DEBUG"))
+
+	buff := &bytes.Buffer{}
+	require.Nil(t, logger.AddLogObserver(buff, &epochConfigLogFormatter{}))
+
+	t.Cleanup(func() {
+		require.Nil(t, logger.RemoveLogObserver(buff))
+		require.Nil(t, logger.SetLogLevel(previousPattern))
+	})
+
+	newArgsRejectingEpochConfig := func() *headerCheck.ArgsHeaderSigVerifier {
+		args := createHeaderSigVerifierArgs()
+		args.NodesCoordinator = &cMock.NodesCoordinatorMock{
+			ComputeValidatorsGroupCalled: func(_ []byte, _ uint64, epoch uint32) ([]sharding.Validator, error) {
+				// Same wrapping the real coordinator applies, so the test also
+				// pins that errors.Is survives it.
+				return nil, fmt.Errorf("%w epoch=%v", sharding.ErrEpochNodesConfigDoesNotExist, epoch)
+			},
+		}
+
+		return args
+	}
+
+	t.Run("leader lookup path", func(t *testing.T) {
+		hdrSigVerifier, err := headerCheck.NewHeaderSigVerifier(newArgsRejectingEpochConfig())
+		require.Nil(t, err)
+
+		header := &block.Block{Header: &block.BlockHeader{Epoch: missingEpoch, Nonce: 42, Slot: 43}}
+
+		err = hdrSigVerifier.VerifyRandSeed(header)
+
+		require.True(t, errors.Is(err, sharding.ErrEpochNodesConfigDoesNotExist), "got %v", err)
+		require.Contains(t, buff.String(), "leader")
+	})
+
+	t.Run("signature path", func(t *testing.T) {
+		hdrSigVerifier, err := headerCheck.NewHeaderSigVerifier(newArgsRejectingEpochConfig())
+		require.Nil(t, err)
+
+		header := &block.Block{
+			Header:        &block.BlockHeader{Epoch: missingEpoch, Nonce: 42, Slot: 43},
+			PubKeysBitmap: []byte("1"),
+		}
+
+		err = hdrSigVerifier.VerifySignature(header)
+
+		require.True(t, errors.Is(err, sharding.ErrEpochNodesConfigDoesNotExist), "got %v", err)
+		require.Contains(t, buff.String(), "signature")
+	})
+
+	// A single emitted line must carry the fields an operator needs to count how
+	// many slots the window spans. Asserting on one line rather than on the
+	// accumulated buffer is what makes this meaningful: over the concatenation of
+	// several lines the field assertions would still pass with a field missing
+	// from one of them.
+	t.Run("a single emitted line carries epoch, nonce and slot", func(t *testing.T) {
+		buff.Reset()
+
+		hdrSigVerifier, err := headerCheck.NewHeaderSigVerifier(newArgsRejectingEpochConfig())
+		require.Nil(t, err)
+
+		header := &block.Block{Header: &block.BlockHeader{Epoch: missingEpoch, Nonce: 42, Slot: 43}}
+
+		err = hdrSigVerifier.VerifyRandSeed(header)
+		require.True(t, errors.Is(err, sharding.ErrEpochNodesConfigDoesNotExist), "got %v", err)
+
+		output := buff.String()
+		require.Contains(t, output, "missing config for epoch = 7")
+		require.Contains(t, output, "header epoch = 7")
+		require.Contains(t, output, "nonce = 42")
+		require.Contains(t, output, "slot = 43")
+	})
+
+	// For an epoch-start header both callers verify against the previous epoch,
+	// so the line must name that epoch as the missing one. Reporting the header's
+	// own epoch would send an operator looking for the wrong configuration.
+	t.Run("epoch-start header names the previous epoch as the missing one", func(t *testing.T) {
+		buff.Reset()
+
+		hdrSigVerifier, err := headerCheck.NewHeaderSigVerifier(newArgsRejectingEpochConfig())
+		require.Nil(t, err)
+
+		header := &block.Block{
+			Header: &block.BlockHeader{Epoch: missingEpoch, Nonce: 42, Slot: 43, IsEpochStart: true},
+		}
+
+		err = hdrSigVerifier.VerifyRandSeed(header)
+		require.True(t, errors.Is(err, sharding.ErrEpochNodesConfigDoesNotExist), "got %v", err)
+
+		require.Contains(t, buff.String(), "missing config for epoch = 6")
+		require.Contains(t, buff.String(), "header epoch = 7")
+	})
+
+	// A different error must leave the diagnostic silent, otherwise the line stops
+	// meaning "the epoch window is open".
+	t.Run("stays silent for an unrelated error", func(t *testing.T) {
+		buff.Reset()
+
+		args := createHeaderSigVerifierArgs()
+		args.NodesCoordinator = &cMock.NodesCoordinatorMock{
+			ComputeValidatorsGroupCalled: func(_ []byte, _ uint64, _ uint32) ([]sharding.Validator, error) {
+				return nil, errors.New("some other failure")
+			},
+		}
+
+		hdrSigVerifier, err := headerCheck.NewHeaderSigVerifier(args)
+		require.Nil(t, err)
+
+		err = hdrSigVerifier.VerifyRandSeed(&block.Block{Header: &block.BlockHeader{}})
+		require.NotNil(t, err)
+
+		require.Empty(t, buff.String())
+	})
+}

core/process/sync/baseForkDetector.go

@@ -4,6 +4,7 @@ import (
 	"bytes"
 	"math"
 	"sync"
+	"sync/atomic"
 	"time"
 
 	"github.com/klever-io/klever-go/core/consensus"
@@ -52,6 +53,10 @@ type baseForkDetector struct {
 	genesisSlot        uint64
 	maxForkHeaderEpoch uint32
 	tmpStuck           time.Time
+	// lastCheckpointAheadWarnSlot throttles the checkpoint-ahead warning to once
+	// per slot; CheckFork can run on every sync-loop iteration while the node is
+	// not synchronized.
+	lastCheckpointAheadWarnSlot atomic.Int64
 }
 
 // SetRollBackNonce sets the nonce where the chain should roll back
@@ -604,7 +609,20 @@ func (bfd *baseForkDetector) isConsensusStuck() bool {
 		return false
 	}
 
-	slotsDifference := tools.SafeI64ToU64(bfd.slotManager.Index()) - bfd.lastCheckpoint().slot
+	currentSlot := tools.SafeI64ToU64(bfd.slotManager.Index())
+	lastCheckpointSlot := bfd.lastCheckpoint().slot
+	slotsDifference, err := tools.SafeSubUint64(currentSlot, lastCheckpointSlot)
+	if err != nil {
+		// The last checkpoint is ahead of our own slot index, so no slots have
+		// elapsed since it. Subtracting would wrap around on uint64 and report an
+		// enormous lag, which clears the threshold below and forces a rollback of
+		// a block that was just committed. checkBlockBasicValidity deliberately
+		// accepts headers one slot ahead of the local index, so a node whose clock
+		// trails its peers can reach this state without any peer misbehaving.
+		bfd.warnOnceCheckpointAheadOfSlotIndex(currentSlot, lastCheckpointSlot)
+		return false
+	}
+
 	if slotsDifference <= process.MaxSlotsWithoutCommittedBlock {
 		return false
 	}
@@ -616,6 +634,31 @@ func (bfd *baseForkDetector) isConsensusStuck() bool {
 	return true
 }
 
+// warnOnceCheckpointAheadOfSlotIndex surfaces the clock-trails-tip state. While
+// it lasts, the node is otherwise silent: incoming headers are dropped below the
+// default log level because their slot exceeds the local index, the
+// bootstrapper's slot lag reads zero so its stall warning cannot fire, and the
+// node keeps reporting NsSynchronized. After an NTP step-back or a VM resume
+// this can hold for a long time, so this line is the only operator-visible
+// signal. Throttled to once per slot because CheckFork runs on every sync-loop
+// iteration while the node is not synchronized.
+//
+// The format does happen under mutNodeState, since CheckFork's only production
+// caller holds it. That is accepted here, unlike for the stall warning that was
+// moved out of that lock: the throttle caps this at one format per slot, and
+// the state has no out-of-lock observer to move it to.
+func (bfd *baseForkDetector) warnOnceCheckpointAheadOfSlotIndex(currentSlot uint64, checkpointSlot uint64) {
+	slotIndex := bfd.slotManager.Index()
+	if bfd.lastCheckpointAheadWarnSlot.Swap(slotIndex) == slotIndex {
+		return
+	}
+
+	log.Warn("last checkpoint is ahead of the local slot index, node clock appears to trail the network",
+		"local slot index", currentSlot,
+		"checkpoint slot", checkpointSlot,
+		"checkpoint nonce", bfd.lastCheckpoint().nonce)
+}
+
 func (bfd *baseForkDetector) isSyncing() bool {
 	// noncesDifference is used for comparison, allow the difference to be negative
 	noncesDifference := tools.SafeU64ToI64(bfd.ProbableHighestNonce()) - tools.SafeU64ToI64(bfd.lastCheckpoint().nonce)