diff --git a/eth/downloader/downloader.go b/eth/downloader/downloader.go index 245f73e80da..45375bda9c5 100644 --- a/eth/downloader/downloader.go +++ b/eth/downloader/downloader.go @@ -76,6 +76,9 @@ var ( fsHeaderSafetyNet = 2048 // Number of headers to discard in case a chain violation is detected fsHeaderContCheck = 3 * time.Second // Time interval to check for header continuations during state download fsMinFullBlocks = 64 // Number of blocks to retrieve fully even in fast sync + + stalledSyncThreshold = 5 * time.Minute // Duration after which an unfinished sync round is reported as stalled + stalledSyncWarnInterval = time.Minute // Minimum interval between two stalled sync warnings ) var ( @@ -126,6 +129,8 @@ type Downloader struct { // Status synchroniseMock func(id string, hash common.Hash) error // Replacement for synchronise during testing synchronising int32 + syncStartTime int64 // Unix nanos at which the in-flight sync round started (0 if idle) + lastStallWarn int64 // Unix nanos at which the last stalled sync warning was emitted notified int32 committed int32 @@ -399,6 +404,32 @@ func (d *Downloader) Synchronise(id string, head common.Hash, td *big.Int, mode return err } +// warnIfSyncStalled reports a sync round that has been holding the +// synchronising flag for an unusually long time. Such a round silently rejects +// every subsequent attempt with errBusy, so without this the node can stop +// syncing indefinitely without emitting a single log line. +func (d *Downloader) warnIfSyncStalled(id string) { + started := atomic.LoadInt64(&d.syncStartTime) + if started == 0 { + // The running round is already tearing down, nothing to report. + return + } + now := time.Now().UnixNano() + elapsed := time.Duration(now - started) + if elapsed < stalledSyncThreshold { + return + } + last := atomic.LoadInt64(&d.lastStallWarn) + if last != 0 && time.Duration(now-last) < stalledSyncWarnInterval { + return + } + if !atomic.CompareAndSwapInt64(&d.lastStallWarn, last, now) { + // Another goroutine won the race and is emitting the warning. + return + } + log.Warn("Sync round has not finished, downloader may be stalled", "elapsed", common.PrettyDuration(elapsed), "peer", id) +} + // synchronise will select the peer and use it for synchronising. If an empty string is given // it will use the best peer possible and synchronize if its TD is higher than our own. If any of the // checks fail an error will be returned. This method is synchronous @@ -409,9 +440,14 @@ func (d *Downloader) synchronise(id string, hash common.Hash, td *big.Int, mode } // Make sure only one goroutine is ever allowed past this point at once if !atomic.CompareAndSwapInt32(&d.synchronising, 0, 1) { + d.warnIfSyncStalled(id) return errBusy } - defer atomic.StoreInt32(&d.synchronising, 0) + atomic.StoreInt64(&d.syncStartTime, time.Now().UnixNano()) + defer func() { + atomic.StoreInt64(&d.syncStartTime, 0) + atomic.StoreInt32(&d.synchronising, 0) + }() // Post a user notification of the sync (only once per session) if atomic.CompareAndSwapInt32(&d.notified, 0, 1) { diff --git a/eth/downloader/downloader_test.go b/eth/downloader/downloader_test.go index a5d770d9640..49789cdec91 100644 --- a/eth/downloader/downloader_test.go +++ b/eth/downloader/downloader_test.go @@ -2183,3 +2183,49 @@ func TestRequestTTL(t *testing.T) { t.Fatalf("ttlLimit (%v) is below rttMaxEstimate (%v)", ttlLimit, rttMaxEstimate) } } + +// TestSynchroniseStalledSyncWarning checks that a sync round which never +// releases the synchronising flag is reported, and that the report is +// rate limited. Without it a wedged round silently rejects every subsequent +// attempt with errBusy and the node stops syncing without any log line. +func TestSynchroniseStalledSyncWarning(t *testing.T) { + d := new(Downloader) + atomic.StoreInt32(&d.synchronising, 1) + + // A round that just started must not be reported yet. + atomic.StoreInt64(&d.syncStartTime, time.Now().UnixNano()) + if err := d.synchronise("peer", common.Hash{}, nil, FullSync); err != errBusy { + t.Fatalf("synchronise error mismatch: have %v, want %v", err, errBusy) + } + if warned := atomic.LoadInt64(&d.lastStallWarn); warned != 0 { + t.Fatalf("fresh sync round reported as stalled") + } + + // A round older than the threshold must be reported. + atomic.StoreInt64(&d.syncStartTime, time.Now().Add(-2*stalledSyncThreshold).UnixNano()) + if err := d.synchronise("peer", common.Hash{}, nil, FullSync); err != errBusy { + t.Fatalf("synchronise error mismatch: have %v, want %v", err, errBusy) + } + warned := atomic.LoadInt64(&d.lastStallWarn) + if warned == 0 { + t.Fatal("stalled sync round not reported") + } + + // Further attempts within the rate limit window must stay quiet. + if err := d.synchronise("peer", common.Hash{}, nil, FullSync); err != errBusy { + t.Fatalf("synchronise error mismatch: have %v, want %v", err, errBusy) + } + if again := atomic.LoadInt64(&d.lastStallWarn); again != warned { + t.Fatalf("stalled sync warning not rate limited: have %d, want %d", again, warned) + } + + // A round that is already tearing down must not be reported. + atomic.StoreInt64(&d.syncStartTime, 0) + atomic.StoreInt64(&d.lastStallWarn, 0) + if err := d.synchronise("peer", common.Hash{}, nil, FullSync); err != errBusy { + t.Fatalf("synchronise error mismatch: have %v, want %v", err, errBusy) + } + if warned := atomic.LoadInt64(&d.lastStallWarn); warned != 0 { + t.Fatalf("finishing sync round reported as stalled") + } +}