Sync Issue 2

[n13]

Here's my analysis of this log. This is a completely different failure mode from the previous logs -- and it confirms your hypothesis.

Timeline:

Time	Event	Block	Rate
17:52:48	Fresh sync starts from genesis, 1 peer (Qmbct)	#21	-
17:52 - 17:53:57	Fast sync through small blocks	#335	3-8 bps
17:54:02	Hits large tx-flood blocks	#338	0.3-0.7 bps
17:56:17	Through the fat region, speeds up	#417	1.9-9.8 bps
18:01:43	Stalls completely at a huge block	#1558	0.0 bps
18:02:02	First Network(Timeout) - peer disconnected	#1558	stuck
18:03:03	Backoff clears, new request sent	#1558	stuck
18:03:23	Second Network(Timeout) (20s later)	#1558	stuck
18:04:23	Third disconnect	#1558	stuck
18:04:26	"Potential long-range attack" (stale mined block)	#1558	-
18:04 - 18:10	~6 minutes dead: 0 peers, 0 progress	#1558	-
18:10:11	Qmbct reconnects, Refused in 77ms	#1558	-
18:10:24	QmQ4A connects, crawls at ~1 block/5 seconds	#1559	~0.1 bps
18:11:26	QmQ4A Network(Timeout) too	#1562	stuck
18:11 onwards	Endless Refused/Timeout cycle across all peers	#1562	0
20:26:42	User kills node - still stuck at #1562, 0 peers	#1562	dead

The node sat stuck for over 2 hours and never recovered.

Root cause -- confirmed: large block + 20s timeout:

The proof is in the download bandwidth numbers. While stuck at #1558:

18:01:48 -- 0.0 bps, download 87.8 kiB/s
18:01:53 -- 0.0 bps, download 200.2 kiB/s
18:01:58 -- 0.0 bps, download 172.7 kiB/s
18:02:02 -- Network(Timeout)

Data IS flowing (100-200 kiB/s) but the block doesn't finish importing. The block request times out at 20 seconds. At 200 kiB/s, the max transferable in 20 seconds is ~4 MB, but the block is likely larger (the tx-flood blocks had 538 extrinsics and hit the 5 MiB block weight limit). The peer is also bandwidth-constrained serving its own traffic.

When QmQ4A finally manages to serve block #1559 (took ~5s), that block barely made it. But subsequent blocks are equally large, and the timeouts resume.

This is NOT the same as the previous fork-loop problem. This node:

• Never forked (it's syncing from genesis)
• Never mined on its own chain (the "Potential long-range attack" at 18:04:26 was a stale block proposal from before the sync stall)
• Has zero transaction propagation overhead

The sole problem is: the sync/2 request-response protocol's 20-second timeout is too short for large blocks over a bandwidth-limited link. One timeout triggers the disconnect-backoff cascade, and the node never recovers because the same large block blocks it every time.

Full log:
log9.txt

[n13]

Grok fix sounds reasonable

1. SAME_REQUEST fatal ban code path (in sc-network-sync-0.54.0/src/block_request_handler.rs)

The exact path is BlockRequestHandler::handle_request (called from the process_requests async loop on every incoming sync/2 request via the request_receiver):

• Decode protobuf BlockRequest → compute from_block_id, max_blocks (capped at MAX_BLOCKS_IN_RESPONSE = 128), direction, attributes, support_multiple_justifications.
• Build SeenRequestsKey<B> (includes peer, from (Hash or Number), max_blocks, direction, attributes, support_multiple_justifications; Hash impl hashes the peer + params but not the full request body size).
• match self.seen_requests.get(&key) (LruMap):
  • Some(Fulfilled(ref mut requests)) → increment count; if > MAX_NUMBER_OF_SAME_REQUESTS_PER_PEER (which is 2), set reputation_change = Some(rep::SAME_REQUEST) (fatal i32::MIN for non-small_request; small=only HEADER|JUSTIFICATION).
  • None → insert(key.clone(), First).
• If no reputation change or small request: call get_block_response(...) (walks headers + bodies/indexed bodies, respects MAX_BODY_BYTES = 8MiB, returns BlockResponse).
• After serving (if response had data): update LRU entry from First → Fulfilled(1).
• Send OutgoingResponse with the reputation_changes (triggers peer ban in peerset/peer_store.rs if <= BANNED_THRESHOLD).

seen_requests is initialized in BlockRequestHandler::new (capacity num_peer_hint * 2 via ByLength, lives for the entire SyncingEngine/BlockRequestHandler lifetime). It is never cleared. This matches Log 1 exactly: ancestor search converges on the same fork-point hash → identical key on reconnect → count exceeds 2 → fatal ban within ~70ms for all 3 peers (lines 697-711 in log8.txt).

2. 20s timeout → permanent sync stall (in sc-network-sync-0.54.0/src/engine.rs + strategy/chain_sync.rs)

Request timeout is set in generate_protocol_config (Duration::from_secs(20) on the RequestResponseProtocolConfig).

Timeout handling (engine.rs:1018 in process_response_event for ResponseEvent):

• RequestFailure::Network(OutboundFailure::Timeout) → report_peer(..., rep::TIMEOUT) (-1<<10 = -1024) + disconnect_peer.
• Similar for Refused, Io, etc. (all disconnect + penalize).
• oneshot::Canceled also disconnects.

In chain_sync.rs:

• on_generic_response routes block responses to on_block_response (or drops on decode errors).
• On disconnect during in-flight request: DisconnectedPeers::on_disconnect_during_request (in strategy/disconnected_peers.rs) tracks it (60s base backoff via DISCONNECTED_PEER_BACKOFF_SECONDS, exponential with num_disconnects; after MAX_NUM_DISCONNECTS=3 → fatal REPUTATION_REPORT ban).
• is_peer_available checks backoff timer; on_sync_peer_disconnected removes peer from strategy.peers and pending_responses.
• Peer state (e.g. PeerSyncState::DownloadingNew or AncestorSearch) is reset on reconnect; ancestor search or peer_block_request may re-issue the exact same large block range.
• No per-block retry queue or "slow peer / smaller request" fallback for the stalled block. Large stress-test blocks (~500KB–4+MB with 500+ extrinsics) exceed the 20s window → repeated Timeout/Refused/backoff cycle across peers (Log 9: stalls at #1558–1562, 0 peers for ~6min then endless loop for 2+ hours; lines 1905-1918, 2219-2223, 14000+).

The sync rate drops to 0 because the gap-filling request for that specific historical block never completes, peers are repeatedly penalized/disconnected, and DisconnectedPeers + reputation decay (1/200 per second, ~69s for i32::MIN to unban) prevent quick recovery.

3. Minimal fixes to prevent both failure modes

These are the smallest, targeted changes (DRY, no new code where upstream already has the levers; keep existing constants/behavior for small requests):

• SAME_REQUEST: In block_request_handler.rs (and symmetrically in state_request_handler.rs), change const MAX_NUMBER_OF_SAME_REQUESTS_PER_PEER: usize = 2; → 5 (or 10). This tolerates legitimate re-requests after reconnects/ancestor convergence without altering the LRU key or adding clearing logic.
• Timeout: In block_request_handler.rs:94, change Duration::from_secs(20) → Duration::from_secs(60) (or 120). Matches the disconnected-peer backoff scale and gives headroom for large PoW blocks under tx load.
• (Optional one-liner in peer_store.rs if needed: tweak BANNED_THRESHOLD or INVERSE_DECREMENT for faster unban, but the above two prevent the triggers.)

These stop the fatal ban cycle (Log 1) and the timeout/backoff death spiral (Log 2) while preserving all anti-spam intent. No other changes needed—the rest of get_block_response, on_block_response, DisconnectedPeers, and PoW mining continue unchanged. The node stays synced/mining under stress.

The logs and upstream code confirm this is the precise root cause (large blocks + fork-point re-requests + hardcoded small constants). Happy to implement the patches or test them!

[n13]

Here is the full trace and analysis.

---

1. SAME_REQUEST Fatal Ban -- Code Path Trace

The entire mechanism lives in sc-network-sync-0.54.0/src/block_request_handler.rs. Here's the exact flow:

Constants:

const MAX_NUMBER_OF_SAME_REQUESTS_PER_PEER: usize = 2;

mod rep {
	use sc_network::ReputationChange as Rep;
	pub const SAME_REQUEST: Rep = Rep::new_fatal("Same block request multiple times");
	pub const SAME_SMALL_REQUEST: Rep =
		Rep::new(-(1 << 10), "same small block request multiple times");
}

Step 1 -- Key construction. Every incoming block request is decoded into a SeenRequestsKey keyed on (peer, from_block_id, max_blocks, direction, attributes, support_multiple_justifications):

		let key = SeenRequestsKey {
			peer: *peer,
			max_blocks,
			direction,
			from: from_block_id,
			attributes,
			support_multiple_justifications,
		};

Step 2 -- LRU check. The handler checks seen_requests (an LRU map that persists for the handler's entire lifetime):

		match self.seen_requests.get(&key) {
			Some(SeenRequestsValue::First) => {},
			Some(SeenRequestsValue::Fulfilled(ref mut requests)) => {
				*requests = requests.saturating_add(1);
				if *requests > MAX_NUMBER_OF_SAME_REQUESTS_PER_PEER {
					reputation_change = Some(if small_request {
						rep::SAME_SMALL_REQUEST
					} else {
						rep::SAME_REQUEST
					});
				}
			},
			None => {
				self.seen_requests.insert(key.clone(), SeenRequestsValue::First);
			},
		}

Step 3 -- Promotion to Fulfilled. After successfully serving blocks, the entry is promoted from First to Fulfilled(1):

				if let Some(value) = self.seen_requests.get(&key) {
					if let SeenRequestsValue::First = value {
						*value = SeenRequestsValue::Fulfilled(1);
					}
				}

Step 4 -- Non-small requests get empty response + fatal reputation. When reputation_change.is_some() && !small_request, the handler refuses to serve blocks and sends back Err(()):

		let maybe_block_response = if reputation_change.is_none() || small_request {
			// ... serve blocks ...
			Some(block_response)
		} else {
			None
		};

The OutgoingResponse carries the fatal reputation_changes which the network layer applies to the peer store.

The trigger sequence from log8.txt:

1. 15:44:17.832 -- Peer QmQ4A requests BlockId::Hash(0x8b5d...), 128 blocks descending (body+header+justification). First time: reputation_change: None. Served 41 blocks, 4.5MB. Entry set to Fulfilled(1).
2. 15:44:31.669 -- Same peer makes the exact same request (same hash, same params). Counter becomes Fulfilled(3) which exceeds MAX_NUMBER_OF_SAME_REQUESTS_PER_PEER=2. Triggers SAME_REQUEST with value i32::MIN = -2147483648.
3. 15:44:31.669 -- PeerStore::report_peer receives i32::MIN. BANNED_THRESHOLD = 71 * (i32::MIN / 100) = -1,524,713,267. Since -2147483648 < -1524713267, peer is immediately banned. All protocols disconnect.

The ban lifts after ~69 seconds (per INVERSE_DECREMENT = 200 decay), but the peer's ancestor search converges to the same fork-point hash and re-issues the identical request, which the still-warm LRU instantly re-bans.

---

2. Timeout Handling -- Why 20s Causes Permanent Stall

The timeout is hardcoded in the protocol config:

		Duration::from_secs(20),

When a timeout fires, engine.rs handles it in process_response_event:

				RequestFailure::Network(OutboundFailure::Timeout) => {
					self.network_service.report_peer(peer_id, rep::TIMEOUT);
					self.network_service
						.disconnect_peer(peer_id, self.block_announce_protocol_name.clone());
				},

Where rep::TIMEOUT = -(1 << 10) = -1024. The peer is disconnected.

Critically, the strategy never receives a "request failed" callback. The engine does not call strategy.on_generic_response for failures. Instead, the disconnect triggers on_sync_peer_disconnected which calls strategy.remove_peer:

	fn remove_peer(&mut self, peer_id: &PeerId) {
		self.blocks.clear_peer_download(peer_id);
		// ...
		if let Some(state) = self.peers.remove(peer_id) {
			if !state.state.is_available() {
				if let Some(bad_peer) =
					self.disconnected_peers.on_disconnect_during_request(*peer_id)
				{
					self.actions.push(SyncingAction::DropPeer(bad_peer));
				}
			}
		}
		// ...
	}

Since the peer was in DownloadingNew state (not available), DisconnectedPeers tracks it. The backoff is num_disconnects * 60 seconds:

const DISCONNECTED_PEER_BACKOFF_SECONDS: u64 = 60;

The death spiral for log9.txt:

Time	Event
18:01:41	Block #1558 imported. Next block (#1559) is ~500KB+ with 538 extrinsics.
18:01:41	Request starts for the next range. Block too large to transfer in 20s.
18:02:02	Timeout fires (20s). Peer reported (-1024), disconnected. DisconnectedPeers records disconnect #1.
18:02:03	Peer reconnects via libp2p. add_peer_inner starts ancestor search.
18:02:03	is_peer_available returns false -- 60s backoff active. Peer sits idle.
18:03:03	Backoff expires. Request retried. Same large block, same timeout.
18:03:23	Timeout #2. DisconnectedPeers records disconnect #2 (backoff now 120s).
18:05:23	Backoff expires. Timeout #3. MAX_NUM_DISCONNECTS=3 hit. Fatal ban via REPUTATION_REPORT.
18:05:23 → ~18:06:32	69-second ban decay. 0 peers. Node is stuck at #1558.
18:06:32+	Same cycle restarts with any reconnecting peer.

The node crawled to #1562 (3 blocks from a second peer QmQ4A that managed to squeeze through) and then remained permanently stuck for over 2 hours until killed at 20:26.

Why retry doesn't help: Every reconnection restarts the ancestor search from scratch. Even once the ancestor search completes and the same large block range is requested, the 20-second timeout fires again because the block physically cannot be transferred in time. The DisconnectedPeers mechanism then escalates backoff (60s → 120s → fatal ban), making recovery progressively slower until it becomes effectively permanent.

---

3. Minimal Fixes

Both failures stem from upstream sc-network-sync constants that assume small blocks. Since the crate is pulled as sc-network-sync = "0.54.0" (not a local fork), you'll need to fork or patch the crate.

Fix A: Request Timeout (addresses both logs)

In block_request_handler.rs line 94, increase the timeout from 20s to something appropriate for your chain's max block size. For 8MB max body at even modest transfer rates (1 MB/s), 120 seconds is generous:

Duration::from_secs(120),

This directly fixes log9 (large-block sync stall) and reduces the compounding effect in log8 (tx-heavy blocks timing out during the isolation window).

Fix B: SAME_REQUEST (addresses log8 specifically)

The LRU has no TTL -- an entry from the first request persists for the handler's lifetime. Two options, in order of preference:

Option B1 -- Increase tolerance. Change MAX_NUMBER_OF_SAME_REQUESTS_PER_PEER from 2 to something like 10. This allows the legitimate reconnect-and-re-request cycle several rounds before triggering the ban. Minimal diff, one constant change.

Option B2 -- Clear on reconnect. Remove the peer's entries from seen_requests when the peer disconnects. This requires passing the peer ID down to clear matching keys, which is a slightly larger change but eliminates the root cause: a post-ban-reconnect producing a request the LRU already remembers.

Fix C: Timeout reputation (defense in depth)

In engine.rs rep::TIMEOUT, the -1024 penalty is relatively mild per-event, but DisconnectedPeers treats any disconnect-during-request as evidence of misbehavior with exponential backoff. For honest-but-slow peers on a chain with large blocks, you could:

1. Increase DISCONNECTED_PEER_BACKOFF_SECONDS from 60 to a lower value (e.g., 10-15s), or
2. Not count timeout disconnects as "disconnect during request" in DisconnectedPeers (requires distinguishing timeout from other failure modes in the disconnect path)

Recommended Minimal Patch

The single highest-impact fix is increasing the request timeout (Fix A). It directly breaks the stall loop in log9, and prevents the timeout-compounding in log8. Combined with Fix B1 (increasing MAX_NUMBER_OF_SAME_REQUESTS_PER_PEER), both failure modes are resolved with changes to just two constants in block_request_handler.rs.