fix(eth): log sync status each cycle while node is behind network

The sync status logger only fired while the downloader was inside a bulk
historical sync. Once the node is caught up, new blocks are followed
through the block fetcher / BFT announcements, so Synchronising() stays
false and the warn log appeared only once or never over hours of normal
operation instead of every 10 minutes.

The logger now reports whenever the node is behind the best peer's head,
covering both the downloader and the announcement-driven catch-up paths.

Author: gzliudan

eth/sync.go

@@ -205,24 +205,40 @@ func (pm *ProtocolManager) syncStatusLogger() {
 	for {
 		select {
 		case <-ticker.C:
-			if pm.downloader.Synchronising() {
-				progress := pm.downloader.Progress()
-				log.Warn("Block synchronisation in progress",
-					"starting", progress.StartingBlock,
-					"current", progress.CurrentBlock,
-					"highest", progress.HighestBlock,
-					"pulledStates", progress.PulledStates,
-					"knownStates", progress.KnownStates,
-					"peers", pm.peers.Len(),
-				)
-			}
+			pm.reportSyncStatus()
 
 		case <-pm.quitSync:
 			return
 		}
 	}
 }
 
+// reportSyncStatus emits a warn-level log whenever the node is behind the best
+// peer's head. Gating on the downloader alone is not enough: once the bulk
+// historical sync finishes, new blocks are fetched through the block fetcher /
+// BFT announcements, so `downloader.Synchronising()` stays false even while the
+// node is still catching up.
+func (pm *ProtocolManager) reportSyncStatus() {
+	peer := pm.peers.BestPeer()
+	if peer == nil {
+		return
+	}
+	current := pm.blockchain.CurrentBlock()
+	_, pTd := peer.Head()
+	if pTd.Cmp(pm.blockchain.GetTd(current.Hash(), current.Number.Uint64())) <= 0 {
+		return // We are at or ahead of the best peer, nothing left to sync
+	}
+	progress := pm.downloader.Progress()
+	log.Warn("Block synchronisation in progress",
+		"starting", progress.StartingBlock,
+		"current", progress.CurrentBlock,
+		"highest", progress.HighestBlock,
+		"pulledStates", progress.PulledStates,
+		"knownStates", progress.KnownStates,
+		"peers", pm.peers.Len(),
+	)
+}
+
 // synchronise tries to sync up our local block chain with a remote peer.
 func (pm *ProtocolManager) synchronise(peer *peer) {
 	// Short circuit if no peers are available

eth/sync_test.go

@@ -17,11 +17,15 @@
 package eth
 
 import (
+	"bytes"
+	"math/big"
+	"strings"
 	"sync/atomic"
 	"testing"
 	"time"
 
 	"github.com/XinFinOrg/XDPoSChain/eth/downloader"
+	"github.com/XinFinOrg/XDPoSChain/log"
 	"github.com/XinFinOrg/XDPoSChain/p2p"
 	"github.com/XinFinOrg/XDPoSChain/p2p/enode"
 )
@@ -31,6 +35,66 @@ func TestFastSyncDisabling100(t *testing.T) { testFastSyncDisabling(t, xdc100) }
 func TestFastSyncDisabling164(t *testing.T) { testFastSyncDisabling(t, xdc164) }
 func TestFastSyncDisabling165(t *testing.T) { testFastSyncDisabling(t, xdc165) }
 
+// Tests that the periodic sync status logger reports progress whenever the node
+// is behind the best peer's head, even when the downloader is idle (i.e. the
+// node is following new blocks through the block fetcher / BFT announcements).
+func TestSyncStatusLogger(t *testing.T) {
+	pm, _ := newTestProtocolManagerMust(t, downloader.FullSync, 0, nil, nil)
+	defer pm.Stop()
+
+	// Capture the warn-level logs emitted by the sync status logger.
+	var logBuf bytes.Buffer
+	prevLog := log.Root()
+	glog := log.NewGlogHandler(log.NewTerminalHandlerWithLevel(&logBuf, log.LevelTrace, false))
+	glog.Verbosity(log.LevelTrace)
+	log.SetDefault(log.NewLogger(glog))
+	defer log.SetDefault(prevLog)
+
+	// Register a peer that we can move ahead of / behind our own chain head.
+	app, net := p2p.MsgPipe()
+	defer app.Close()
+	peer := pm.newPeer(xdc100, p2p.NewPeer(enode.ID{1}, "sync-status-peer", nil), net, pm.txpool.Get)
+	if err := pm.peers.Register(peer); err != nil {
+		t.Fatalf("failed to register peer: %v", err)
+	}
+	defer pm.peers.Unregister(peer.id)
+
+	current := pm.blockchain.CurrentBlock()
+	localTD := pm.blockchain.GetTd(current.Hash(), current.Number.Uint64())
+
+	// setHead moves the peer's advertised head to the given total difficulty.
+	// The handshake (which normally initialises these fields) is skipped here,
+	// so set the peer's head state directly.
+	setHead := func(td *big.Int) {
+		peer.lock.Lock()
+		defer peer.lock.Unlock()
+		peer.head = current.Hash()
+		peer.td = new(big.Int).Set(td)
+	}
+
+	// A peer ahead of us must trigger a sync status report...
+	setHead(new(big.Int).Add(localTD, big.NewInt(1)))
+	pm.reportSyncStatus()
+	if got := strings.Count(logBuf.String(), "Block synchronisation in progress"); got != 1 {
+		t.Fatalf("expected a sync status log when behind the best peer, got %d, log: %q", got, logBuf.String())
+	}
+	// ...while a peer at or behind us must not.
+	logBuf.Reset()
+	setHead(localTD)
+	pm.reportSyncStatus()
+	if got := strings.Count(logBuf.String(), "Block synchronisation in progress"); got != 0 {
+		t.Fatalf("expected no sync status log when at the best peer's head, got %d, log: %q", got, logBuf.String())
+	}
+	// The progress fields must be populated with the local chain state.
+	logBuf.Reset()
+	setHead(new(big.Int).Add(localTD, big.NewInt(1)))
+	pm.reportSyncStatus()
+	logLine := logBuf.String()
+	if !strings.Contains(logLine, "current=") || !strings.Contains(logLine, "peers=1") {
+		t.Fatalf("expected populated progress fields, got %q", logLine)
+	}
+}
+
 // Tests that fast sync gets disabled as soon as a real block is successfully
 // imported into the blockchain.
 func testFastSyncDisabling(t *testing.T, protocol int) {