Node can't sync with the network

[nazar-pc]

Is there an existing issue?

• I have searched the existing issues

Experiencing problems? Have you tried our Stack Exchange first?

• This is not a support question.

Description of bug

We have discovered with somewhat recent Susbtrate (319a7bd) nodes sometimes fail to keep up with the network and even after restart they are unable to sync.

We have some heavy blocks on the network and we decreased block response size in our Substrate fork (autonomys/substrate@7fceb6c), but all blocks are strictly smaller than this lower limit anyway, so that is not an issue.

Here is logs of a node that was previously unable to sync with -l sync=trace:
dariia-node-log.txt

I can see that it tries to download blocks backwards, but stops before reaching correctly identified common ancestor block 9715.

Steps to reproduce

Requires "broken" state of the node (that I have access to) in order to reliably reproduce the issue.

[nazar-pc]

Clarification: it does seem to download all the blocks after all and even tries to import them (multiple times), but fails to find parent block that according to logs it seems to receive without issues.

This happens over and over again:

2023-08-04 15:20:30.261 TRACE tokio-runtime-worker sync::import-queue: [Consensus] Scheduling 984 blocks for import
2023-08-04 15:20:30.261 TRACE tokio-runtime-worker sync::import-queue: [Consensus] Starting import of 984 blocks  (9719..10702)
2023-08-04 15:20:30.261 TRACE tokio-runtime-worker sync::import-queue: [Consensus] Header 0x2339…7b90 has 4 logs
2023-08-04 15:20:30.261 DEBUG tokio-runtime-worker sync::import-queue: [Consensus] Block with unknown parent 9719: 0x2339e5a4f3f81345855649305a789b1c8956504b5b6e657d1d0385aeb0457b90, parent: 0xa7150f5889ee194ea2fb4ce45d22df11658afc4f278da9dbb3c68dfb586efdaf
2023-08-04 15:20:30.268 TRACE tokio-runtime-worker sync: [Consensus] Imported 0 of 984

Explorer (currently live) for this version of the network: https://polkadot.js.org/apps/?rpc=wss%3A%2F%2Frpc.devnet.subspace.network%2Fws#/explorer

[nazar-pc]

Parent is block 9718, which also happens to be the best block number the node is at, but from a different fork. Basically node stopped at non-canonical block and can't get back onto canonical chain. The common ancestor is just 3 blocks deep and not finalized.

[altonen]

Yeah I agree, that is probably the core issue. If you do a sync from genesis with a clean DB does it work then?

Could possibly be related to this paritytech/substrate#12830

[nazar-pc]

Yeah I agree, that is probably the core issue. If you do a sync from genesis with a clean DB does it work then?

Yes, just synced a fresh node from genesis successfully. There are also multiple nodes that were live all the time and work fine, but logs are from one of the two nodes so far that got stuck at different heights.

Could possibly be related to this paritytech/substrate#12830

Yes, I also saw similar logs in paritytech/substrate#13295 which might be related/have a similar root cause.

[altonen]

@dmitry-markin

Before you continue with the sync refactoring, could you take a look at this problem?

[nazar-pc]

Hey folks, how high is it on your priority list?
I'll have to look into this myself if it is not resolved in next few days, it happens surprisingly often on our chain for some reason.
Just want to manage expectations on our end better, I understand you might have more pressing things to work on.

[altonen]

@dmitry-markin is looking into it, I'll give it a go as well if there is no definite answer soonish but there are other quite high priority tasks in the pipeline as well.

Did bisect reveal paritytech/substrate@319a7bd to be the offending commit because it sounds a little suspicious? If this started failing for you recently, have you had a chance to bisect the history of Subspace, in case there is a commit in your history that triggers this behavior in Substrate?

How easy is this to reproduce? Just running a Subspace node with default settings will do?

[nazar-pc]

It happens eventually, likely related to restarts (at least once happened on node that working fine prior to restart), not yet sure how to trigger it reliably, but it does happen quite often given tiny size of this test network. We have been doing many major changes lately, so bisecting will be trickier than to debug directly with local Substrate fork.

I have uploaded zip archive with broken node using which I was generating above logs: https://nextcloud.mokrynskyi.com/s/qCoWgZ6Td49xwHf

Should be 100% reproducible with above database and https://github.com/subspace/subspace/releases/tag/snapshot-2023-aug-07 when running like this:

subspace-node --base-path xyz --chain devnet --execution wasm --validator --blocks-pruning 256 --state-pruning archive --sync-from-dsn false

It is already at a certain height and will never move any higher than that, it is stuck. Above release uses our Substrate fork at https://github.com/subspace/substrate/tree/subspace-v5, --sync-from-dsn false should disable most of relevant customizations we did to it.

[dmitry-markin]

To share my findings so far — I was able to reproduce in tests what looks quite similar to the problem described in paritytech/substrate#12830. If it's the underlying issue, we now should at least have an easy way to reproduce and debug it.

[dmitry-markin]

P.S. Here is the failing test if you want to look into: paritytech/substrate#14735.

[dmitry-markin]

It's not completely clear yet, but may be what's happening is a weird combination of syncing logic and peer disconnection due to reputation system. At least with your subspace snapshot/database it looks like this (copying only the relevant lines):

1. A remote peer found to have a different fork with common block 9715 and is requested to provide 64 blocks:

2023-08-09 17:17:12.774 TRACE tokio-runtime-worker sync: [Consensus] BlockResponse 0 from 12D3KooWSrQ1Qq4TKbAw1ZeSUwUc84SH32GgCag1JrUJLvpYsvoN with 1 blocks  (9715)    
2023-08-09 17:17:12.774 TRACE tokio-runtime-worker sync: [Consensus] Got ancestry block paritytech/substrate#9715 (0xdce2…a1ea) from peer 12D3KooWSrQ1Qq4TKbAw1ZeSUwUc84SH32GgCag1JrUJLvpYsvoN    
2023-08-09 17:17:12.774 TRACE tokio-runtime-worker sync: [Consensus] Ancestry search complete. Ours=0x9aaa…a206 (9718), Theirs=0xf914…1cf2 (52738), Common=Some(0xdce23caa41389cefbc0883ac3d2f060bda389d89c4b6e6eb0558984bcdc0a1ea) (9715)    
2023-08-09 17:17:12.858 TRACE tokio-runtime-worker sync: [Consensus] New block request for 12D3KooWSrQ1Qq4TKbAw1ZeSUwUc84SH32GgCag1JrUJLvpYsvoN, (best:52738, common:9715) BlockRequest { id: 0, fields: HEADER | BODY | JUSTIFICATION, from: Number(9779), direction: Descending, max: Some(64) }

2. All the blocks probably do not fit into one response, so lesser amount is downloaded in chunks:

2023-08-09 17:17:13.426 TRACE tokio-runtime-worker sync: [Consensus] BlockResponse 0 from 12D3KooWSrQ1Qq4TKbAw1ZeSUwUc84SH32GgCag1JrUJLvpYsvoN with 39 blocks  (9779..9741)
2023-08-09 17:17:13.434 TRACE tokio-runtime-worker sync: [Consensus] New block request for 12D3KooWSrQ1Qq4TKbAw1ZeSUwUc84SH32GgCag1JrUJLvpYsvoN, (best:52738, common:9715) BlockRequest { id: 0, fields: HEADER | BODY | JUSTIFICATION, from: Number(9740), direction: Descending, max: Some(25) }
2023-08-09 17:17:14.398 TRACE tokio-runtime-worker sync: [Consensus] BlockResponse 0 from 12D3KooWSrQ1Qq4TKbAw1ZeSUwUc84SH32GgCag1JrUJLvpYsvoN with 1 blocks  (9740)
2023-08-09 17:17:14.419 TRACE tokio-runtime-worker sync: [Consensus] New block request for 12D3KooWSrQ1Qq4TKbAw1ZeSUwUc84SH32GgCag1JrUJLvpYsvoN, (best:52738, common:9715) BlockRequest { id: 0, fields: HEADER | BODY | JUSTIFICATION, from: Number(9739), direction: Descending, max: Some(24) }
2023-08-09 17:17:14.826 TRACE tokio-runtime-worker sync: [Consensus] BlockResponse 0 from 12D3KooWSrQ1Qq4TKbAw1ZeSUwUc84SH32GgCag1JrUJLvpYsvoN with 1 blocks  (9739)
...
2023-08-09 17:17:24.260 TRACE tokio-runtime-worker sync: [Consensus] New block request for 12D3KooWSrQ1Qq4TKbAw1ZeSUwUc84SH32GgCag1JrUJLvpYsvoN, (best:52738, common:9715) BlockRequest { id: 0, fields: HEADER | BODY | JUSTIFICATION, from: Number(9728), direction: Descending, max: Some(13) }
2023-08-09 17:17:25.208 TRACE tokio-runtime-worker sync: [Consensus] BlockResponse 0 from 12D3KooWSrQ1Qq4TKbAw1ZeSUwUc84SH32GgCag1JrUJLvpYsvoN with 2 blocks  (9728..9727)
2023-08-09 17:17:25.424 TRACE tokio-runtime-worker sync: [Consensus] New block request for 12D3KooWSrQ1Qq4TKbAw1ZeSUwUc84SH32GgCag1JrUJLvpYsvoN, (best:52738, common:9715) BlockRequest { id: 0, fields: HEADER | BODY | JUSTIFICATION, from: Number(9726), direction: Descending, max: Some(11) }

3. At this point due to the remote peer also requesting blocks from us, the reputation system decides to disconnect it:

2023-08-09 17:17:25.889 DEBUG tokio-runtime-worker sync: [Consensus] Handling block request from 12D3KooWSrQ1Qq4TKbAw1ZeSUwUc84SH32GgCag1JrUJLvpYsvoN: Starting at `BlockId::Hash(0x9aaa72d9718d997c6894cf3e62c1e48620e3f14db7ad2cc25807814f9285a206)` with maximum blocks of `128`, reputation_change: `Some(ReputationChange { value: -2147483648, reason: "Same block request multiple times" })`, small_request `false`, direction `Descending` and attributes `HEADER | BODY | JUSTIFICATION`.    
2023-08-09 17:17:25.889 DEBUG tokio-runtime-worker sync: [Consensus] Sending result of block request from 12D3KooWSrQ1Qq4TKbAw1ZeSUwUc84SH32GgCag1JrUJLvpYsvoN starting at `BlockId::Hash(0x9aaa72d9718d997c6894cf3e62c1e48620e3f14db7ad2cc25807814f9285a206)`: blocks: None, data: None    
2023-08-09 17:17:25.889 DEBUG tokio-runtime-worker sync: [Consensus] Handled block request from 12D3KooWSrQ1Qq4TKbAw1ZeSUwUc84SH32GgCag1JrUJLvpYsvoN.    
2023-08-09 17:17:25.890  WARN tokio-runtime-worker peerset: [Consensus] Ignoring request to disconnect reserved peer 12D3KooWSrQ1Qq4TKbAw1ZeSUwUc84SH32GgCag1JrUJLvpYsvoN from SetId(2).    
2023-08-09 17:17:25.890 DEBUG tokio-runtime-worker sync: [Consensus] 12D3KooWSrQ1Qq4TKbAw1ZeSUwUc84SH32GgCag1JrUJLvpYsvoN disconnected

And we never finish filling the gap.

What I also find quite annoying is that the block chunks are requested by block number and not by block hash — while this should not cause issues with downloading of a canonical chain, it can interfere with downloading forks.

Also, it looks like the issue is not directly related to paritytech/substrate#12830, because in that case the problem was connected with inability to fill fork gaps > 128 blocks with one request, and in our case we have multiple successful "gap" requests.

What I would try doing next is disabling "Same block request multiple times" reputation punishment to see if it cuts the tie.

@nazar-pc By the way, how do you patch subspace to build against local substrate source? I tried naive patching with diener but hit the issue of building against multiple version of substrate crates.

[nazar-pc]

@dmitry-markin diener is what I use as well, just need to update Cargo.toml and replace https://github.com/paritytech/substrate with https://github.com/subspace/substrate.

[dmitry-markin]

It turned out the trick was to patch both https://github.com/paritytech/substrate & https://github.com/subspace/substrate. Most likely I was sidetracked by this other issue reported in the previous comment as other peers are not disconnected and could fulfill block requests.

It looks like the block download continues normally in a descending manner towards block 9715 at one block per response. Unfortunately, as soon as the client downloads block 9719, the sync state machine decides it's ready to import blocks (as it already has 9718), and tries to import all downloaded blocks. Unfortunately, they are on a different fork so the import fails, the blocks are discarded, and the process is restarted.

So, IMO, the problem is that block import is triggered by block number (incorrectly, as the parent is different) instead of the block hash with respect to the parent hash. At the same time the block download request is seemingly correct, just the block import is triggered too soonish before all the blocks in the range are downloaded. What likely makes the issue manifest here is that the blocks are big in this part of the chain and only fit one block per response, so the range is not fulfilled completely via one response.

[nazar-pc]

Yep, that sounds exactly the way I expected it to be

[dmitry-markin]

We clearly have issues with forks downloading. Here is the original range request:

2023-08-11 14:44:54.028 TRACE tokio-runtime-worker sync: [Consensus] Ancestry search complete. Ours=0x9aaa…a206 (9718), Theirs=0x4e1e…4c9b (66055), Common=Some(0xdce23caa41389cefbc0883ac3d2f060bda389d89c4b6e6eb0558984bcdc0a1ea) (9715)    
2023-08-11 14:44:54.041 TRACE tokio-runtime-worker sync: [Consensus] New block request for 12D3KooW9rBrhvZuc8C7ff3sD3sdu9crpZ6hiYDtU2RedWddfjQi, (best:66055, common:9715) BlockRequest { id: 0, fields: HEADER | BODY | JUSTIFICATION, from: Number(9779), direction: Descending, max: Some(64) }

There is no message "Added fork target" in between, because the condition
https://github.com/paritytech/substrate/blob/aedfdc977b28a4029ec658dff960a86220f7622b/client/network/sync/src/lib.rs#L912-L913
is false. And even if it was true, the "fork" download would fail due to paritytech/substrate#12830 because the "fork" is longer than 128 blocks.

And due to the logic of downloading of the canonical chain, block import is triggered (as I wrote in the previous message) before we actually have all the blocks from the range.

@nazar-pc I will look into the issue more today, but I'm afraid there is no quick fix available. Unfortunately, I'm not available next week, so we'll either need to postpone the fix, or I'll need to ask you too look into it.