eth/downloader: separate state sync from queue (#14460)

* eth/downloader: separate state sync from queue

Scheduling of state node downloads hogged the downloader queue lock when
new requests were scheduled. This caused timeouts for other requests.
With this change, state sync is fully independent of all other downloads
and doesn't involve the queue at all.

State sync is started and checked on in processContent. This is slightly
awkward because processContent doesn't have a select loop. Instead, the
queue is closed by an auxiliary goroutine when state sync fails. We
tried several alternatives to this but settled on the current approach
because it's the least amount of change overall.

Handling of the pivot block has changed slightly: the queue previously
prevented import of pivot block receipts before the state of the pivot
block was available. In this commit, the receipt will be imported before
the state. This causes an annoyance where the pivot block is committed
as fast block head even when state downloads fail. Stay tuned for more
updates in this area ;)

* eth/downloader: remove cancelTimeout channel

* eth/downloader: retry state requests on timeout

* eth/downloader: improve comment

* eth/downloader: mark peers idle when state sync is done

* eth/downloader: move pivot block splitting to processContent

This change also ensures that pivot block receipts aren't imported
before the pivot block itself.

* eth/downloader: limit state node retries

* eth/downloader: improve state node error handling and retry check

* eth/downloader: remove maxStateNodeRetries

It fails the sync too much.

* eth/downloader: remove last use of cancelCh in statesync.go

Fixes TestDeliverHeadersHang*Fast and (hopefully)
the weird cancellation behaviour at the end of fast sync.

* eth/downloader: fix leak in runStateSync

* eth/downloader: don't run processFullSyncContent in LightSync mode

* eth/downloader: improve comments

* eth/downloader: fix vet, megacheck

* eth/downloader: remove unrequested tasks anyway

* eth/downloader, trie: various polishes around duplicate items

This commit explicitly tracks duplicate and unexpected state
delieveries done against a trie Sync structure, also adding
there to import info logs.

The commit moves the db batch used to commit trie changes one
level deeper so its flushed after every node insertion. This
is needed to avoid a lot of duplicate retrievals caused by
inconsistencies between Sync internals and database. A better
approach is to track not-yet-written states in trie.Sync and
flush on commit, but I'm focuing on correctness first now.

The commit fixes a regression around pivot block fail count.
The counter previously was reset to 1 if and only if a sync
cycle progressed (inserted at least 1 entry to the database).
The current code reset it already if a node was delivered,
which is not stong enough, because unless it ends up written
to disk, an attacker can just loop and attack ad infinitum.

The commit also fixes a regression around state deliveries
and timeouts. The old downloader tracked if a delivery is
stale (none of the deliveries were requestedt), in which
case it didn't mark the node idle and did not send further
requests, since it signals a past timeout. The current code
did mark it idle even on stale deliveries, which eventually
caused two requests to be in flight at the same time, making
the deliveries always stale and mass duplicating retrievals
between multiple peers.

* eth/downloader: fix state request leak

This commit fixes the hang seen sometimes while doing the state
sync. The cause of the hang was a rare combination of events:
request state data from peer, peer drops and reconnects almost
immediately. This caused a new download task to be assigned to
the peer, overwriting the old one still waiting for a timeout,
which in turned leaked the requests out, never to be retried.
The fix is to ensure that a task assignment moves any pending
one back into the retry queue.

The commit also fixes a regression with peer dropping due to
stalls. The current code considered a peer stalling if they
timed out delivering 1 item. However, the downloader never
requests only one, the minimum is 2 (attempt to fine tune
estimated latency/bandwidth). The fix is simply to drop if
a timeout is detected at 2 items.

Apart from the above bugfixes, the commit contains some code
polishes I made while debugging the hang.

* core, eth, trie: support batched trie sync db writes

* trie: rename SyncMemCache to syncMemBatch

core/state/sync.go

@@ -59,10 +59,16 @@ func (s *StateSync) Missing(max int) []common.Hash {
 }
 
 // Process injects a batch of retrieved trie nodes data, returning if something
-// was committed to the database and also the index of an entry if processing of
+// was committed to the memcache and also the index of an entry if processing of
 // it failed.
-func (s *StateSync) Process(list []trie.SyncResult, dbw trie.DatabaseWriter) (bool, int, error) {
-	return (*trie.TrieSync)(s).Process(list, dbw)
+func (s *StateSync) Process(list []trie.SyncResult) (bool, int, error) {
+	return (*trie.TrieSync)(s).Process(list)
+}
+
+// Commit flushes the data stored in the internal memcache out to persistent
+// storage, returning th enumber of items written and any occurred error.
+func (s *StateSync) Commit(dbw trie.DatabaseWriter) (int, error) {
+	return (*trie.TrieSync)(s).Commit(dbw)
 }
 
 // Pending returns the number of state entries currently pending for download.

core/state/sync_test.go

@@ -138,9 +138,12 @@ func testIterativeStateSync(t *testing.T, batch int) {
 			}
 			results[i] = trie.SyncResult{Hash: hash, Data: data}
 		}
-		if _, index, err := sched.Process(results, dstDb); err != nil {
+		if _, index, err := sched.Process(results); err != nil {
 			t.Fatalf("failed to process result #%d: %v", index, err)
 		}
+		if index, err := sched.Commit(dstDb); err != nil {
+			t.Fatalf("failed to commit data #%d: %v", index, err)
+		}
 		queue = append(queue[:0], sched.Missing(batch)...)
 	}
 	// Cross check that the two states are in sync
@@ -168,9 +171,12 @@ func TestIterativeDelayedStateSync(t *testing.T) {
 			}
 			results[i] = trie.SyncResult{Hash: hash, Data: data}
 		}
-		if _, index, err := sched.Process(results, dstDb); err != nil {
+		if _, index, err := sched.Process(results); err != nil {
 			t.Fatalf("failed to process result #%d: %v", index, err)
 		}
+		if index, err := sched.Commit(dstDb); err != nil {
+			t.Fatalf("failed to commit data #%d: %v", index, err)
+		}
 		queue = append(queue[len(results):], sched.Missing(0)...)
 	}
 	// Cross check that the two states are in sync
@@ -206,9 +212,12 @@ func testIterativeRandomStateSync(t *testing.T, batch int) {
 			results = append(results, trie.SyncResult{Hash: hash, Data: data})
 		}
 		// Feed the retrieved results back and queue new tasks
-		if _, index, err := sched.Process(results, dstDb); err != nil {
+		if _, index, err := sched.Process(results); err != nil {
 			t.Fatalf("failed to process result #%d: %v", index, err)
 		}
+		if index, err := sched.Commit(dstDb); err != nil {
+			t.Fatalf("failed to commit data #%d: %v", index, err)
+		}
 		queue = make(map[common.Hash]struct{})
 		for _, hash := range sched.Missing(batch) {
 			queue[hash] = struct{}{}
@@ -249,9 +258,12 @@ func TestIterativeRandomDelayedStateSync(t *testing.T) {
 			}
 		}
 		// Feed the retrieved results back and queue new tasks
-		if _, index, err := sched.Process(results, dstDb); err != nil {
+		if _, index, err := sched.Process(results); err != nil {
 			t.Fatalf("failed to process result #%d: %v", index, err)
 		}
+		if index, err := sched.Commit(dstDb); err != nil {
+			t.Fatalf("failed to commit data #%d: %v", index, err)
+		}
 		for _, hash := range sched.Missing(0) {
 			queue[hash] = struct{}{}
 		}
@@ -283,9 +295,12 @@ func TestIncompleteStateSync(t *testing.T) {
 			results[i] = trie.SyncResult{Hash: hash, Data: data}
 		}
 		// Process each of the state nodes
-		if _, index, err := sched.Process(results, dstDb); err != nil {
+		if _, index, err := sched.Process(results); err != nil {
 			t.Fatalf("failed to process result #%d: %v", index, err)
 		}
+		if index, err := sched.Commit(dstDb); err != nil {
+			t.Fatalf("failed to commit data #%d: %v", index, err)
+		}
 		for _, result := range results {
 			added = append(added, result.Hash)
 		}

eth/downloader/metrics.go

@@ -38,8 +38,6 @@ var (
 	receiptDropMeter    = metrics.NewMeter("eth/downloader/receipts/drop")
 	receiptTimeoutMeter = metrics.NewMeter("eth/downloader/receipts/timeout")
 
-	stateInMeter      = metrics.NewMeter("eth/downloader/states/in")
-	stateReqTimer     = metrics.NewTimer("eth/downloader/states/req")
-	stateDropMeter    = metrics.NewMeter("eth/downloader/states/drop")
-	stateTimeoutMeter = metrics.NewMeter("eth/downloader/states/timeout")
+	stateInMeter   = metrics.NewMeter("eth/downloader/states/in")
+	stateDropMeter = metrics.NewMeter("eth/downloader/states/drop")
 )

eth/downloader/peer.go

@@ -30,6 +30,7 @@ import (
 	"time"
 
 	"github.com/ethereum/go-ethereum/common"
+	"github.com/ethereum/go-ethereum/event"
 	"github.com/ethereum/go-ethereum/log"
 )
 
@@ -195,7 +196,7 @@ func (p *peer) FetchReceipts(request *fetchRequest) error {
 }
 
 // FetchNodeData sends a node state data retrieval request to the remote peer.
-func (p *peer) FetchNodeData(request *fetchRequest) error {
+func (p *peer) FetchNodeData(hashes []common.Hash) error {
 	// Sanity check the protocol version
 	if p.version < 63 {
 		panic(fmt.Sprintf("node data fetch [eth/63+] requested on eth/%d", p.version))
@@ -205,14 +206,7 @@ func (p *peer) FetchNodeData(request *fetchRequest) error {
 		return errAlreadyFetching
 	}
 	p.stateStarted = time.Now()
-
-	// Convert the hash set to a retrievable slice
-	hashes := make([]common.Hash, 0, len(request.Hashes))
-	for hash := range request.Hashes {
-		hashes = append(hashes, hash)
-	}
 	go p.getNodeData(hashes)
-
 	return nil
 }
 
@@ -343,8 +337,9 @@ func (p *peer) Lacks(hash common.Hash) bool {
 // peerSet represents the collection of active peer participating in the chain
 // download procedure.
 type peerSet struct {
-	peers map[string]*peer
-	lock  sync.RWMutex
+	peers       map[string]*peer
+	newPeerFeed event.Feed
+	lock        sync.RWMutex
 }
 
 // newPeerSet creates a new peer set top track the active download sources.
@@ -354,6 +349,10 @@ func newPeerSet() *peerSet {
 	}
 }
 
+func (ps *peerSet) SubscribeNewPeers(ch chan<- *peer) event.Subscription {
+	return ps.newPeerFeed.Subscribe(ch)
+}
+
 // Reset iterates over the current peer set, and resets each of the known peers
 // to prepare for a next batch of block retrieval.
 func (ps *peerSet) Reset() {
@@ -377,9 +376,8 @@ func (ps *peerSet) Register(p *peer) error {
 
 	// Register the new peer with some meaningful defaults
 	ps.lock.Lock()
-	defer ps.lock.Unlock()
-
 	if _, ok := ps.peers[p.id]; ok {
+		ps.lock.Unlock()
 		return errAlreadyRegistered
 	}
 	if len(ps.peers) > 0 {
@@ -399,6 +397,9 @@ func (ps *peerSet) Register(p *peer) error {
 		p.stateThroughput /= float64(len(ps.peers))
 	}
 	ps.peers[p.id] = p
+	ps.lock.Unlock()
+
+	ps.newPeerFeed.Send(p)
 	return nil
 }
 

trie/sync.go

@@ -28,6 +28,10 @@ import (
 // node it did not request.
 var ErrNotRequested = errors.New("not requested")
 
+// ErrAlreadyProcessed is returned by the trie sync when it's requested to process a
+// node it already processed previously.
+var ErrAlreadyProcessed = errors.New("already processed")
+
 // request represents a scheduled or already in-flight state retrieval request.
 type request struct {
 	hash common.Hash // Hash of the node data content to retrieve
@@ -48,6 +52,21 @@ type SyncResult struct {
 	Data []byte      // Data content of the retrieved node
 }
 
+// syncMemBatch is an in-memory buffer of successfully downloaded but not yet
+// persisted data items.
+type syncMemBatch struct {
+	batch map[common.Hash][]byte // In-memory membatch of recently ocmpleted items
+	order []common.Hash          // Order of completion to prevent out-of-order data loss
+}
+
+// newSyncMemBatch allocates a new memory-buffer for not-yet persisted trie nodes.
+func newSyncMemBatch() *syncMemBatch {
+	return &syncMemBatch{
+		batch: make(map[common.Hash][]byte),
+		order: make([]common.Hash, 0, 256),
+	}
+}
+
 // TrieSyncLeafCallback is a callback type invoked when a trie sync reaches a
 // leaf node. It's used by state syncing to check if the leaf node requires some
 // further data syncing.
@@ -57,7 +76,8 @@ type TrieSyncLeafCallback func(leaf []byte, parent common.Hash) error
 // unknown trie hashes to retrieve, accepts node data associated with said hashes
 // and reconstructs the trie step by step until all is done.
 type TrieSync struct {
-	database DatabaseReader
+	database DatabaseReader           // Persistent database to check for existing entries
+	membatch *syncMemBatch            // Memory buffer to avoid frequest database writes
 	requests map[common.Hash]*request // Pending requests pertaining to a key hash
 	queue    *prque.Prque             // Priority queue with the pending requests
 }
@@ -66,6 +86,7 @@ type TrieSync struct {
 func NewTrieSync(root common.Hash, database DatabaseReader, callback TrieSyncLeafCallback) *TrieSync {
 	ts := &TrieSync{
 		database: database,
+		membatch: newSyncMemBatch(),
 		requests: make(map[common.Hash]*request),
 		queue:    prque.New(),
 	}
@@ -79,6 +100,9 @@ func (s *TrieSync) AddSubTrie(root common.Hash, depth int, parent common.Hash, c
 	if root == emptyRoot {
 		return
 	}
+	if _, ok := s.membatch.batch[root]; ok {
+		return
+	}
 	key := root.Bytes()
 	blob, _ := s.database.Get(key)
 	if local, err := decodeNode(key, blob, 0); local != nil && err == nil {
@@ -111,6 +135,9 @@ func (s *TrieSync) AddRawEntry(hash common.Hash, depth int, parent common.Hash)
 	if hash == emptyState {
 		return
 	}
+	if _, ok := s.membatch.batch[hash]; ok {
+		return
+	}
 	if blob, _ := s.database.Get(hash.Bytes()); blob != nil {
 		return
 	}
@@ -144,7 +171,7 @@ func (s *TrieSync) Missing(max int) []common.Hash {
 // Process injects a batch of retrieved trie nodes data, returning if something
 // was committed to the database and also the index of an entry if processing of
 // it failed.
-func (s *TrieSync) Process(results []SyncResult, dbw DatabaseWriter) (bool, int, error) {
+func (s *TrieSync) Process(results []SyncResult) (bool, int, error) {
 	committed := false
 
 	for i, item := range results {
@@ -153,10 +180,13 @@ func (s *TrieSync) Process(results []SyncResult, dbw DatabaseWriter) (bool, int,
 		if request == nil {
 			return committed, i, ErrNotRequested
 		}
+		if request.data != nil {
+			return committed, i, ErrAlreadyProcessed
+		}
 		// If the item is a raw entry request, commit directly
 		if request.raw {
 			request.data = item.Data
-			s.commit(request, dbw)
+			s.commit(request)
 			committed = true
 			continue
 		}
@@ -173,7 +203,7 @@ func (s *TrieSync) Process(results []SyncResult, dbw DatabaseWriter) (bool, int,
 			return committed, i, err
 		}
 		if len(requests) == 0 && request.deps == 0 {
-			s.commit(request, dbw)
+			s.commit(request)
 			committed = true
 			continue
 		}
@@ -185,6 +215,22 @@ func (s *TrieSync) Process(results []SyncResult, dbw DatabaseWriter) (bool, int,
 	return committed, 0, nil
 }
 
+// Commit flushes the data stored in the internal membatch out to persistent
+// storage, returning th enumber of items written and any occurred error.
+func (s *TrieSync) Commit(dbw DatabaseWriter) (int, error) {
+	// Dump the membatch into a database dbw
+	for i, key := range s.membatch.order {
+		if err := dbw.Put(key[:], s.membatch.batch[key]); err != nil {
+			return i, err
+		}
+	}
+	written := len(s.membatch.order)
+
+	// Drop the membatch data and return
+	s.membatch = newSyncMemBatch()
+	return written, nil
+}
+
 // Pending returns the number of state entries currently pending for download.
 func (s *TrieSync) Pending() int {
 	return len(s.requests)
@@ -246,13 +292,17 @@ func (s *TrieSync) children(req *request, object node) ([]*request, error) {
 		// If the child references another node, resolve or schedule
 		if node, ok := (child.node).(hashNode); ok {
 			// Try to resolve the node from the local database
+			hash := common.BytesToHash(node)
+			if _, ok := s.membatch.batch[hash]; ok {
+				continue
+			}
 			blob, _ := s.database.Get(node)
 			if local, err := decodeNode(node[:], blob, 0); local != nil && err == nil {
 				continue
 			}
 			// Locally unknown node, schedule for retrieval
 			requests = append(requests, &request{
-				hash:     common.BytesToHash(node),
+				hash:     hash,
 				parents:  []*request{req},
 				depth:    child.depth,
 				callback: req.callback,
@@ -262,21 +312,21 @@ func (s *TrieSync) children(req *request, object node) ([]*request, error) {
 	return requests, nil
 }
 
-// commit finalizes a retrieval request and stores it into the database. If any
+// commit finalizes a retrieval request and stores it into the membatch. If any
 // of the referencing parent requests complete due to this commit, they are also
 // committed themselves.
-func (s *TrieSync) commit(req *request, dbw DatabaseWriter) (err error) {
-	// Write the node content to disk
-	if err := dbw.Put(req.hash[:], req.data); err != nil {
-		return err
-	}
+func (s *TrieSync) commit(req *request) (err error) {
+	// Write the node content to the membatch
+	s.membatch.batch[req.hash] = req.data
+	s.membatch.order = append(s.membatch.order, req.hash)
+
 	delete(s.requests, req.hash)
 
 	// Check all parents for completion
 	for _, parent := range req.parents {
 		parent.deps--
 		if parent.deps == 0 {
-			if err := s.commit(parent, dbw); err != nil {
+			if err := s.commit(parent); err != nil {
 				return err
 			}
 		}

trie/sync_test.go

@@ -122,9 +122,12 @@ func testIterativeTrieSync(t *testing.T, batch int) {
 			}
 			results[i] = SyncResult{hash, data}
 		}
-		if _, index, err := sched.Process(results, dstDb); err != nil {
+		if _, index, err := sched.Process(results); err != nil {
 			t.Fatalf("failed to process result #%d: %v", index, err)
 		}
+		if index, err := sched.Commit(dstDb); err != nil {
+			t.Fatalf("failed to commit data #%d: %v", index, err)
+		}
 		queue = append(queue[:0], sched.Missing(batch)...)
 	}
 	// Cross check that the two tries are in sync
@@ -152,9 +155,12 @@ func TestIterativeDelayedTrieSync(t *testing.T) {
 			}
 			results[i] = SyncResult{hash, data}
 		}
-		if _, index, err := sched.Process(results, dstDb); err != nil {
+		if _, index, err := sched.Process(results); err != nil {
 			t.Fatalf("failed to process result #%d: %v", index, err)
 		}
+		if index, err := sched.Commit(dstDb); err != nil {
+			t.Fatalf("failed to commit data #%d: %v", index, err)
+		}
 		queue = append(queue[len(results):], sched.Missing(10000)...)
 	}
 	// Cross check that the two tries are in sync
@@ -190,9 +196,12 @@ func testIterativeRandomTrieSync(t *testing.T, batch int) {
 			results = append(results, SyncResult{hash, data})
 		}
 		// Feed the retrieved results back and queue new tasks
-		if _, index, err := sched.Process(results, dstDb); err != nil {
+		if _, index, err := sched.Process(results); err != nil {
 			t.Fatalf("failed to process result #%d: %v", index, err)
 		}
+		if index, err := sched.Commit(dstDb); err != nil {
+			t.Fatalf("failed to commit data #%d: %v", index, err)
+		}
 		queue = make(map[common.Hash]struct{})
 		for _, hash := range sched.Missing(batch) {
 			queue[hash] = struct{}{}
@@ -231,9 +240,12 @@ func TestIterativeRandomDelayedTrieSync(t *testing.T) {
 			}
 		}
 		// Feed the retrieved results back and queue new tasks
-		if _, index, err := sched.Process(results, dstDb); err != nil {
+		if _, index, err := sched.Process(results); err != nil {
 			t.Fatalf("failed to process result #%d: %v", index, err)
 		}
+		if index, err := sched.Commit(dstDb); err != nil {
+			t.Fatalf("failed to commit data #%d: %v", index, err)
+		}
 		for _, result := range results {
 			delete(queue, result.Hash)
 		}
@@ -272,9 +284,12 @@ func TestDuplicateAvoidanceTrieSync(t *testing.T) {
 
 			results[i] = SyncResult{hash, data}
 		}
-		if _, index, err := sched.Process(results, dstDb); err != nil {
+		if _, index, err := sched.Process(results); err != nil {
 			t.Fatalf("failed to process result #%d: %v", index, err)
 		}
+		if index, err := sched.Commit(dstDb); err != nil {
+			t.Fatalf("failed to commit data #%d: %v", index, err)
+		}
 		queue = append(queue[:0], sched.Missing(0)...)
 	}
 	// Cross check that the two tries are in sync
@@ -304,9 +319,12 @@ func TestIncompleteTrieSync(t *testing.T) {
 			results[i] = SyncResult{hash, data}
 		}
 		// Process each of the trie nodes
-		if _, index, err := sched.Process(results, dstDb); err != nil {
+		if _, index, err := sched.Process(results); err != nil {
 			t.Fatalf("failed to process result #%d: %v", index, err)
 		}
+		if index, err := sched.Commit(dstDb); err != nil {
+			t.Fatalf("failed to commit data #%d: %v", index, err)
+		}
 		for _, result := range results {
 			added = append(added, result.Hash)
 		}