5

We are trying to use warp sync for our substrate chain but it doesn't seem to advance past the genesis block.

Normal sync works fine. We purge the chain state and then run the node using:

chainflip-node --chain $CHAINSPEC_JSON --base-path $BASE_PATH --node-key-file $NODE_KEY_FILE --validator --sync warp

Our node has minimal changes compared to the stock node in the substrate repo as of tag monthly-2022-12 (except for the runtime of course).

When we run warp it says it's downloading and importing, but the best and finalized blocks never advance past #0.

Some log output:

2023-01-20 14:52:56 〽️ Prometheus exporter started at 127.0.0.1:9615 2023-01-20 14:52:56 creating instance on iface 46.101.217.18 2023-01-20 14:52:56 creating instance on iface 10.19.0.6 2023-01-20 14:52:56 creating instance on iface 10.114.0.3 2023-01-20 14:52:56 🔍 Discovered new external address for our node: /ip4/46.101.217.18/tcp/30333/ws/p2p/12D3KooWSADnCvB4suununbHcHR2nzo4qFjr6CuynsPhDhrGbAAz 2023-01-20 14:53:01 ⏩ Warping, Downloading state, 9.34 Mib (17 peers), best: #0 (0x2d00…c9b3), finalized #0 (0x2d00…c9b3), ⬇ 2.1MiB/s ⬆ 19.6kiB/s 2023-01-20 14:53:06 ⏩ Warping, Downloading state, 14.53 Mib (29 peers), best: #0 (0x2d00…c9b3), finalized #0 (0x2d00…c9b3), ⬇ 1.0MiB/s ⬆ 76.8kiB/s 2023-01-20 14:53:11 ⏩ Warping, Downloading state, 14.53 Mib (40 peers), best: #0 (0x2d00…c9b3), finalized #0 (0x2d00…c9b3), ⬇ 63.5kiB/s ⬆ 15.3kiB/s 2023-01-20 14:53:16 ⏩ Warping, Downloading state, 18.64 Mib (44 peers), best: #0 (0x2d00…c9b3), finalized #0 (0x2d00…c9b3), ⬇ 834.9kiB/s ⬆ 6.7kiB/s 2023-01-20 14:53:21 ⏩ Warping, Downloading state, 18.64 Mib (50 peers), best: #0 (0x2d00…c9b3), finalized #0 (0x2d00…c9b3), ⬇ 13.0kiB/s ⬆ 8.0kiB/s 2023-01-20 14:53:26 ⏩ Warping, Downloading state, 23.35 Mib (50 peers), best: #0 (0x2d00…c9b3), finalized #0 (0x2d00…c9b3), ⬇ 390.8kiB/s ⬆ 2.6kiB/s 2023-01-20 14:53:31 ⏩ Warping, Downloading state, 23.35 Mib (50 peers), best: #0 (0x2d00…c9b3), finalized #0 (0x2d00…c9b3), ⬇ 7.2kiB/s ⬆ 2.4kiB/s 2023-01-20 14:53:36 ⏩ Warping, Downloading state, 23.35 Mib (50 peers), best: #0 (0x2d00…c9b3), finalized #0 (0x2d00…c9b3), ⬇ 12.2kiB/s ⬆ 6.8kiB/s 2023-01-20 14:53:41 ⏩ Warping, Downloading state, 23.35 Mib (50 peers), best: #0 (0x2d00…c9b3), finalized #0 (0x2d00…c9b3), ⬇ 206.2kiB/s ⬆ 1.6kiB/s 2023-01-20 14:53:46 ⏩ Warping, Downloading state, 23.35 Mib (49 peers), best: #0 (0x2d00…c9b3), finalized #0 (0x2d00…c9b3), ⬇ 13.0kiB/s ⬆ 2.0kiB/s 2023-01-20 14:53:51 ⏩ Warping, Downloading state, 23.35 Mib (49 peers), best: #0 (0x2d00…c9b3), finalized #0 (0x2d00…c9b3), ⬇ 17.8kiB/s ⬆ 7.4kiB/s 2023-01-20 14:53:56 ⏩ Warping, Downloading state, 28.26 Mib (43 peers), best: #0 (0x2d00…c9b3), finalized #0 (0x2d00…c9b3), ⬇ 629.5kiB/s ⬆ 9.9kiB/s 2023-01-20 14:54:01 ⏩ Warping, Downloading state, 30.46 Mib (44 peers), best: #0 (0x2d00…c9b3), finalized #0 (0x2d00…c9b3), ⬇ 540.4kiB/s ⬆ 5.4kiB/s 2023-01-20 14:54:06 ⏩ Warping, Importing state, 33.06 Mib (45 peers), best: #0 (0x2d00…c9b3), finalized #0 (0x2d00…c9b3), ⬇ 484.4kiB/s ⬆ 1.4kiB/s 2023-01-20 14:54:11 ⏩ Warping, Importing state, 33.06 Mib (45 peers), best: #0 (0x2d00…c9b3), finalized #0 (0x2d00…c9b3), ⬇ 39.1kiB/s ⬆ 0.5kiB/s 2023-01-20 14:54:16 ⏩ Warping, Importing state, 33.06 Mib (45 peers), best: #0 (0x2d00…c9b3), finalized #0 (0x2d00…c9b3), ⬇ 12.2kiB/s ⬆ 1.0kiB/s 2023-01-20 14:54:21 ⏩ Warping, Importing state, 33.06 Mib (45 peers), best: #0 (0x2d00…c9b3), finalized #0 (0x2d00…c9b3), ⬇ 5.8kiB/s ⬆ 0.8kiB/s 2023-01-20 14:54:26 ⏩ Warping, Importing state, 33.06 Mib (45 peers), best: #0 (0x2d00…c9b3), finalized #0 (0x2d00…c9b3), ⬇ 126.7kiB/s ⬆ 1.5kiB/s

25 minutes later, it's still on block #0:

2023-01-20 15:19:16 ⏩ Warping, Importing state, 33.06 Mib (50 peers), best: #0 (0x2d00…c9b3), finalized #0 (0x2d00…c9b3), ⬇ 181.5kiB/s ⬆ 0.7kiB/s 2023-01-20 15:19:21 ⏩ Warping, Importing state, 33.06 Mib (50 peers), best: #0 (0x2d00…c9b3), finalized #0 (0x2d00…c9b3), ⬇ 158.7kiB/s ⬆ 2.0kiB/s 2023-01-20 15:19:26 ⏩ Warping, Importing state, 33.06 Mib (50 peers), best: #0 (0x2d00…c9b3), finalized #0 (0x2d00…c9b3), ⬇ 44.2kiB/s ⬆ 1.3kiB/s 2023-01-20 15:19:31 ⏩ Warping, Importing state, 33.06 Mib (50 peers), best: #0 (0x2d00…c9b3), finalized #0 (0x2d00…c9b3), ⬇ 244.2kiB/s ⬆ 1.0kiB/s 2023-01-20 15:19:36 ⏩ Warping, Importing state, 33.06 Mib (50 peers), best: #0 (0x2d00…c9b3), finalized #0 (0x2d00…c9b3), ⬇ 57.0kiB/s ⬆ 1.2kiB/s 2023-01-20 15:19:41 ⏩ Warping, Importing state, 33.06 Mib (50 peers), best: #0 (0x2d00…c9b3), finalized #0 (0x2d00…c9b3), ⬇ 30.6kiB/s ⬆ 1.2kiB/s 2023-01-20 15:19:46 ⏩ Warping, Importing state, 33.06 Mib (50 peers), best: #0 (0x2d00…c9b3), finalized #0 (0x2d00…c9b3), ⬇ 19.3kiB/s ⬆ 1.0kiB/s

We use Aura and Grandpa.

I also ran with RUST_LOG='sync=trace'. I'll spare you the full logs...

Occasionally I saw this:

2023-01-20 14:41:58.695 DEBUG tokio-runtime-worker sync: Peer is on different chain (our genesis: 0x2d00…c9b3 theirs: 0x6f02…cab6) 2023-01-20 14:41:58.695 DEBUG tokio-runtime-worker sync: 12D3KooWEcre1PPy9AHQEzQ7sUMMQ89wRYPZGcifq5ZvQqAfxZ6A disconnected

Seems odd (and I'd be interested to know how this is possible), but the majority of peers connect without issue.

Lots of this:

2023-01-20 14:41:54.538 DEBUG tokio-runtime-worker sync: Pre-validating received block announcement 0xa23910c301900d417cdd8e7d0fc6056270223521e8050cff30628183f9ccafe9 with number 1032320 from 12D3KooWE7S7Ls49gwzxnVAzztMdVdcCqXRfLKN6mysykJWKpNqi 2023-01-20 14:41:54.538 TRACE tokio-runtime-worker sync: Finished block announce validation: from PeerId("12D3KooWE7S7Ls49gwzxnVAzztMdVdcCqXRfLKN6mysykJWKpNqi"): AnnouncementSummary { block_hash: 0xa23910c301900d417cdd8e7d0fc6056270223521e8050cff30628183f9ccafe9, number: 1032320, parent_hash: 0x91c242079e6d54a715f9d4706430e81d57eb6c067046ad02a5484bef1e341b92, state: Some(Best) }. local_best=true

So we are able to download the block announcements (block number and hash are correct).

Also some messages like this:

2023-01-20 14:41:50.379 DEBUG tokio-runtime-worker sync: Importing state data from 12D3KooWJEBw5VqdeC3ip7cm1Zo7ixC1PFtsQ6x5qmQ6aCpURzQ3 with 0 keys, 2007109 proof nodes. 2023-01-20 14:41:50.379 DEBUG tokio-runtime-worker sync: Importing state from 2007109 trie nodes 2023-01-20 14:41:50.521 DEBUG tokio-runtime-worker sync: Imported with 33552 keys 2023-01-20 14:41:50.527 TRACE tokio-runtime-worker sync: New StateRequest for 12D3KooWJEBw5VqdeC3ip7cm1Zo7ixC1PFtsQ6x5qmQ6aCpURzQ3: StateRequest { block: [188, 20, 58, 132, 189, 8, 180, 145, 196, 168, 147, 12, 124, 117, 228, 249, 196, 34, 61, 196, 72, 82, 111, 70, 101, 208, 171, 103, 218, 51, 40, 166], start: [[182, 247, 33, 64, 30, 125, 40, 166, 3, 51, 77, 136, 21, 254, 161, 104, 78, 201, 123, 137, 48, 209, 197, 27, 110, 226, 101, 7, 251, 108, 174, 192, 7, 3, 127, 217, 87, 213, 36, 230, 19, 1, 0, 0]], no_proof: false }

However no ERROR or WARN messages.

Any advice on how to debug this would be welcome.

Improve this question

1 Answer 1

Reset to default
2

Ensure that you never have done any forced set changes for your chain because the finalization was stuck. AURA also didn't worked with warp syncing until two weeks ago.

Improve this answer
3
  • Thanks for the quick answer! > AURA also didn't worked with warp syncing until two weeks ago. This sounds like the most likely problem, will look into it. Commented Jan 20, 2023 at 16:07
  • So - cherry-picking the above-mentioned PR allows the state import to proceed, however now I have another issue: 💔 Error importing block 0xd8..62: consensus error: Import failed: Import failed: Incomplete block import pipeline.. I've accepted the above answer and will investigate further - might raise another question... Commented Jan 23, 2023 at 13:18
  • Issue raised github.com/paritytech/substrate/issues/13220 Commented Jan 23, 2023 at 15:16

Start asking to get answers

Find the answer to your question by asking.

Ask question

Explore related questions

See similar questions with these tags.