From ecfd0e355b66412d7cd92813189d6a57a2d697c0 Mon Sep 17 00:00:00 2001 From: Jerry Date: Fri, 2 Jan 2026 12:14:26 -0800 Subject: [PATCH 1/2] consensus/bor: ensure late blocks have sufficient build time MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit When a parent block is sealed late (actual seal time exceeds its timestamp), the next block had insufficient time to include transactions, resulting in empty blocks. Problem: - Parent block timestamp: T=2s, sealed at T=4s (2s late) - Next block gets timestamp: parent + period = 4s - Current time: 4s - Build time available: 0s → empty block Solution: Set header.Time = now + blockPeriod when scheduled time has passed, giving blocks full build time regardless of parent seal latency. --- consensus/bor/bor.go | 8 +- consensus/bor/bor_test.go | 93 ++++++++++++++++--- tests/bor/bor_test.go | 182 ++++++++++++++++++++++++++++++++++++++ tests/bor/helper.go | 11 +-- 4 files changed, 277 insertions(+), 17 deletions(-) diff --git a/consensus/bor/bor.go b/consensus/bor/bor.go index 7f4e4829b1..751f6f0163 100644 --- a/consensus/bor/bor.go +++ b/consensus/bor/bor.go @@ -1041,9 +1041,13 @@ func (c *Bor) Prepare(chain consensus.ChainHeaderReader, header *types.Header) e now := time.Now() if header.Time < uint64(now.Unix()) { - header.Time = uint64(now.Unix()) + additionalBlockTime := time.Duration(c.config.CalculatePeriod(number)) * time.Second + if c.blockTime > 0 { + additionalBlockTime = c.blockTime + } + header.Time = uint64(now.Add(additionalBlockTime).Unix()) if c.blockTime > 0 && c.config.IsRio(header.Number) { - header.ActualTime = now + header.ActualTime = now.Add(additionalBlockTime) } } diff --git a/consensus/bor/bor_test.go b/consensus/bor/bor_test.go index eec1e70b00..ba1de9c16e 100644 --- a/consensus/bor/bor_test.go +++ b/consensus/bor/bor_test.go @@ -743,7 +743,7 @@ func TestCustomBlockTimeClampsToNowAlsoUpdatesActualTime(t *testing.T) { addr1 := common.HexToAddress("0x1") // Force parent time far in the past so that after adding blockTime, header.Time is still < now - // and the "clamp to now" block triggers. + // and the "clamp to now + blockTime" block triggers. pastParentTime := time.Now().Add(-10 * time.Minute).Unix() sp := &fakeSpanner{vals: []*valset.Validator{{Address: addr1, VotingPower: 1}}} @@ -771,18 +771,27 @@ func TestCustomBlockTimeClampsToNowAlsoUpdatesActualTime(t *testing.T) { require.NoError(t, err) - // Validate the clamp happened: header.Time should be "now-ish", not the past-derived time. - require.GreaterOrEqual(t, int64(header.Time), before.Unix(), "header.Time should be clamped up to now") - require.LessOrEqual(t, int64(header.Time), after.Unix()+1, "header.Time should be close to now") + // With the late block fix, header.Time should be "now + blockTime", not just "now" + // This gives the block builder sufficient time to include transactions + expectedMinTime := before.Add(b.blockTime).Unix() + expectedMaxTime := after.Add(b.blockTime).Unix() + 1 // +1 for timing tolerance + + require.GreaterOrEqual(t, int64(header.Time), expectedMinTime, + "header.Time should be at least now + blockTime to provide build time") + require.LessOrEqual(t, int64(header.Time), expectedMaxTime, + "header.Time should be approximately now + blockTime") // Critical regression assertion: - // When custom blockTime is enabled for Rio, clamping header.Time to now must also set ActualTime = now. + // When custom blockTime is enabled for Rio, clamping header.Time must also set ActualTime = now + blockTime. require.False(t, header.ActualTime.IsZero(), "ActualTime should be set when blockTime > 0 and Rio is enabled") - require.GreaterOrEqual(t, header.ActualTime.Unix(), before.Unix(), "ActualTime should be updated to now when clamping occurs") - require.LessOrEqual(t, header.ActualTime.Unix(), after.Unix()+1, "ActualTime should be close to now when clamping occurs") - - // Optional: since clamping sets both from the same `now`, they should match on Unix seconds. - require.Equal(t, int64(header.Time), header.ActualTime.Unix(), "header.Time and ActualTime should align after clamping") + require.GreaterOrEqual(t, header.ActualTime.Unix(), expectedMinTime, + "ActualTime should be at least now + blockTime when clamping occurs") + require.LessOrEqual(t, header.ActualTime.Unix(), expectedMaxTime, + "ActualTime should be approximately now + blockTime when clamping occurs") + + // Since clamping sets both from the same calculation, they should match on Unix seconds. + require.Equal(t, int64(header.Time), header.ActualTime.Unix(), + "header.Time and ActualTime should align after clamping") } func TestVerifySealRejectsOversizedDifficulty(t *testing.T) { @@ -869,3 +878,67 @@ func TestVerifySealRejectsOversizedDifficulty(t *testing.T) { diffErr.Actual, uint64(math.MaxUint64)) } } + +// TestLateBlockTimestampFix verifies that late blocks get sufficient build time +// by setting header.Time = now + blockPeriod instead of just clamping to now. +func TestLateBlockTimestampFix(t *testing.T) { + t.Parallel() + + addr1 := common.HexToAddress("0x1") + borCfg := ¶ms.BorConfig{ + Sprint: map[string]uint64{"0": 64}, + Period: map[string]uint64{"0": 2}, + } + + t.Run("late parent gets future timestamp", func(t *testing.T) { + sp := &fakeSpanner{vals: []*valset.Validator{{Address: addr1, VotingPower: 1}}} + oldParentTime := time.Now().Add(-4 * time.Second).Unix() + chain, b := newChainAndBorForTest(t, sp, borCfg, true, addr1, uint64(oldParentTime)) + + header := &types.Header{Number: big.NewInt(1), ParentHash: chain.HeaderChain().GetHeaderByNumber(0).Hash()} + + before := time.Now() + require.NoError(t, b.Prepare(chain.HeaderChain(), header)) + + // Should give full 2s build time from now, not from parent + expectedMin := before.Add(2 * time.Second).Unix() + require.GreaterOrEqual(t, int64(header.Time), expectedMin) + }) + + t.Run("on-time parent uses normal calculation", func(t *testing.T) { + sp := &fakeSpanner{vals: []*valset.Validator{{Address: addr1, VotingPower: 1}}} + recentParentTime := time.Now().Unix() + chain, b := newChainAndBorForTest(t, sp, borCfg, true, addr1, uint64(recentParentTime)) + + header := &types.Header{Number: big.NewInt(1), ParentHash: chain.HeaderChain().GetHeaderByNumber(0).Hash()} + + require.NoError(t, b.Prepare(chain.HeaderChain(), header)) + + // Should use parent.Time + period + genesis := chain.HeaderChain().GetHeaderByNumber(0) + require.GreaterOrEqual(t, header.Time, genesis.Time+borCfg.Period["0"]) + }) + + t.Run("custom blockTime with Rio", func(t *testing.T) { + sp := &fakeSpanner{vals: []*valset.Validator{{Address: addr1, VotingPower: 1}}} + rioCfg := ¶ms.BorConfig{ + Sprint: map[string]uint64{"0": 64}, + Period: map[string]uint64{"0": 2}, + RioBlock: big.NewInt(0), + } + + oldParentTime := time.Now().Add(-4 * time.Second).Unix() + chain, b := newChainAndBorForTest(t, sp, rioCfg, true, addr1, uint64(oldParentTime)) + b.blockTime = 3 * time.Second + + header := &types.Header{Number: big.NewInt(1), ParentHash: chain.HeaderChain().GetHeaderByNumber(0).Hash()} + + before := time.Now() + require.NoError(t, b.Prepare(chain.HeaderChain(), header)) + + expectedMin := before.Add(3 * time.Second).Unix() + require.GreaterOrEqual(t, int64(header.Time), expectedMin) + require.False(t, header.ActualTime.IsZero()) + require.GreaterOrEqual(t, header.ActualTime.Unix(), expectedMin) + }) +} diff --git a/tests/bor/bor_test.go b/tests/bor/bor_test.go index e15049c309..537b96a430 100644 --- a/tests/bor/bor_test.go +++ b/tests/bor/bor_test.go @@ -2065,3 +2065,185 @@ func TestCustomBlockTimeMining(t *testing.T) { require.LessOrEqual(t, blocksMinedCount, maxExpectedBlocks, fmt.Sprintf("Too many blocks mined. Expected at most %d, got %d", maxExpectedBlocks, blocksMinedCount)) } + +// TestLateBlockNotEmpty tests that when a parent block is sealed late, +// blocks still have sufficient time to include transactions. +// This verifies the fix for empty blocks caused by late parent blocks. +func TestLateBlockNotEmpty(t *testing.T) { + t.Parallel() + log.SetDefault(log.NewLogger(log.NewTerminalHandlerWithLevel(os.Stderr, log.LevelInfo, true))) + fdlimit.Raise(2048) + + faucets := make([]*ecdsa.PrivateKey, 128) + for i := 0; i < len(faucets); i++ { + faucets[i], _ = crypto.GenerateKey() + } + + genesis := InitGenesis(t, faucets, "./testdata/genesis_2val.json", 16) + genesis.Config.Bor.Period = map[string]uint64{"0": 2} + genesis.Config.Bor.Sprint = map[string]uint64{"0": 16} + genesis.Config.Bor.RioBlock = big.NewInt(0) + + // Start a single miner node + stack, ethBackend, err := InitMiner(genesis, keys[0], true) + require.NoError(t, err) + defer stack.Close() + + for stack.Server().NodeInfo().Ports.Listener == 0 { + time.Sleep(250 * time.Millisecond) + } + + // Start mining + err = ethBackend.StartMining() + require.NoError(t, err) + + // Wait for initial blocks + log.Info("Waiting for initial blocks...") + for { + time.Sleep(500 * time.Millisecond) + if ethBackend.BlockChain().CurrentBlock().Number.Uint64() >= 3 { + break + } + } + + // Stop mining and wait for it to fully stop + ethBackend.StopMining() + time.Sleep(500 * time.Millisecond) + + // Capture parent block + parentBlock := ethBackend.BlockChain().CurrentBlock() + parentNumber := parentBlock.Number.Uint64() + parentTime := parentBlock.Time + + log.Info("Parent block", "number", parentNumber, "time", parentTime) + + // Add transactions BEFORE waiting (they should be in pool when we resume) + txpool := ethBackend.TxPool() + senderKey := pkey1 + senderAddr := crypto.PubkeyToAddress(senderKey.PublicKey) + recipientAddr := crypto.PubkeyToAddress(pkey2.PublicKey) + nonce := txpool.Nonce(senderAddr) + signer := types.LatestSignerForChainID(genesis.Config.ChainID) + + // Start goroutine to continuously add transactions + stopTxs := make(chan struct{}) + txNonce := nonce + go func() { + ticker := time.NewTicker(100 * time.Millisecond) + defer ticker.Stop() + for { + select { + case <-stopTxs: + return + case <-ticker.C: + // Add 5 transactions every 100ms + for i := 0; i < 5; i++ { + tx := types.NewTransaction( + txNonce, + recipientAddr, + big.NewInt(1000), + 21000, + big.NewInt(30000000000), + nil, + ) + signedTx, _ := types.SignTx(tx, signer, senderKey) + if txpool.Add([]*types.Transaction{signedTx}, true)[0] == nil { + txNonce++ + } + } + } + } + }() + defer close(stopTxs) + + // Wait a bit for initial transactions to be added + time.Sleep(300 * time.Millisecond) + + pending, queued := txpool.Stats() + log.Info("Txpool after initial txs", "pending", pending, "queued", queued) + require.Greater(t, pending, 0, "Expected transactions in pending") + + // Wait for parent to become older than block period (simulates late parent) + blockPeriod := time.Duration(genesis.Config.Bor.Period["0"]) * time.Second + + // Wait until parent age > blockPeriod (not just equal) + var parentAge int64 + for { + parentBlock = ethBackend.BlockChain().CurrentBlock() + parentNumber = parentBlock.Number.Uint64() + parentTime = parentBlock.Time + parentAge = time.Now().Unix() - int64(parentTime) + + if parentAge > int64(blockPeriod.Seconds()) { + log.Info("Parent is now late", "number", parentNumber, "age", parentAge, "blockPeriod", blockPeriod.Seconds()) + break + } + + time.Sleep(100 * time.Millisecond) + } + + // Resume mining + err = ethBackend.StartMining() + require.NoError(t, err) + + // Wait for blocks to be mined and check that they ALL contain transactions + log.Info("Waiting for blocks after resume...") + blocksToCheck := uint64(3) + maxWait := 10 * time.Second + deadline := time.Now().Add(maxWait) + allBlocksChecked := false + + var currentNumber uint64 + for time.Now().Before(deadline) { + time.Sleep(500 * time.Millisecond) + currentNumber = ethBackend.BlockChain().CurrentBlock().Number.Uint64() + + if currentNumber >= parentNumber+blocksToCheck { + allBlocksChecked = true + break + } + } + + require.True(t, allBlocksChecked, "Expected %d blocks to be mined", blocksToCheck) + + // Verify ALL blocks after parent contain transactions + totalTxsInBlocks := 0 + actualNow := time.Now().Unix() + parentAge = actualNow - int64(parentTime) // Update parent age for error messages + + for i := uint64(1); i <= blocksToCheck; i++ { + block := ethBackend.BlockChain().GetBlockByNumber(parentNumber + i) + require.NotNil(t, block) + txCount := len(block.Transactions()) + totalTxsInBlocks += txCount + + // Calculate expected build time + expectedMinTime := int64(parentTime) + int64(blockPeriod.Seconds()) + actualBuildTime := int64(block.Time()) - actualNow + timeFromParent := int64(block.Time()) - int64(parentTime) + + log.Info("Block check", + "number", block.Number().Uint64(), + "txCount", txCount, + "blockTime", block.Time(), + "actualNow", actualNow, + "buildTime", actualBuildTime, + "timeFromParent", timeFromParent, + "expectedMin", expectedMinTime) + + // KEY ASSERTION: With the fix, ALL blocks should contain transactions + // when there are pending transactions in the pool + require.Greater(t, txCount, 0, + "Block %d is empty! With late block fix, all blocks should include "+ + "transactions when txpool has pending txs. Parent age was %d seconds. "+ + "Block time: %d, Now: %d, Build time available: %d seconds.", + block.Number().Uint64(), parentAge, block.Time(), actualNow, actualBuildTime) + } + + log.Info("SUCCESS: All blocks after late parent contain transactions", + "blocksChecked", blocksToCheck, + "totalTxs", totalTxsInBlocks, + "parentAge", parentAge) + + ethBackend.StopMining() +} diff --git a/tests/bor/helper.go b/tests/bor/helper.go index 4da21a166c..925b13351e 100644 --- a/tests/bor/helper.go +++ b/tests/bor/helper.go @@ -607,11 +607,12 @@ func InitMinerWithBlockTime(genesis *core.Genesis, privKey *ecdsa.PrivateKey, wi TxPool: legacypool.DefaultConfig, GPO: ethconfig.Defaults.GPO, Miner: miner.Config{ - Etherbase: crypto.PubkeyToAddress(privKey.PublicKey), - GasCeil: genesis.GasLimit * 11 / 10, - GasPrice: big.NewInt(1), - Recommit: time.Second, - BlockTime: blockTime, + Etherbase: crypto.PubkeyToAddress(privKey.PublicKey), + GasCeil: genesis.GasLimit * 11 / 10, + GasPrice: big.NewInt(1), + Recommit: time.Second, + BlockTime: blockTime, + CommitInterruptFlag: true, }, WithoutHeimdall: withoutHeimdall, }) From e5772882b929b46557501b9c5596f371abea5abf Mon Sep 17 00:00:00 2001 From: Jerry Date: Mon, 12 Jan 2026 11:54:34 -0800 Subject: [PATCH 2/2] Address comment --- consensus/bor/bor_test.go | 3 +++ 1 file changed, 3 insertions(+) diff --git a/consensus/bor/bor_test.go b/consensus/bor/bor_test.go index ba1de9c16e..72c9a768db 100644 --- a/consensus/bor/bor_test.go +++ b/consensus/bor/bor_test.go @@ -903,6 +903,9 @@ func TestLateBlockTimestampFix(t *testing.T) { // Should give full 2s build time from now, not from parent expectedMin := before.Add(2 * time.Second).Unix() require.GreaterOrEqual(t, int64(header.Time), expectedMin) + // Add upper bound check to ensure timestamp is within reasonable range (allow 100ms execution time) + expectedMax := before.Add(2*time.Second + 100*time.Millisecond).Unix() + require.LessOrEqual(t, int64(header.Time), expectedMax) }) t.Run("on-time parent uses normal calculation", func(t *testing.T) {