Canonical chain not updated during reorg if sync is in progress?

[nazar-pc]

I have a strange bug for which I only see one plausible explanation.

First of all a bit of logs (node was restarted):

2022-02-23 12:11:39 💤 Idle (0 peers), best: #505898 (0xaa90…5fea), finalized #0 (0x6ada…0d38), ⬇ 0.5kiB/s ⬆ 0.4kiB/s    
2022-02-23 12:11:44 💤 Idle (0 peers), best: #505898 (0xaa90…5fea), finalized #0 (0x6ada…0d38), ⬇ 0.1kiB/s ⬆ 90 B/s    
^C
apple@apples-MacBook-Air farmer-network % bash start-node.sh
2022-02-23 16:50:47 Subspace    
2022-02-23 16:50:47 ✌️  version 0.1.0-35cf6f5-x86_64-macos    
2022-02-23 16:50:47 ❤️  by Subspace Labs <https://subspace.network>, 2021-2022    
2022-02-23 16:50:47 📋 Chain specification: Subspace testnet    
2022-02-23 16:50:47 🏷  Node name: undefined-is-not-a-function    
2022-02-23 16:50:47 👤 Role: AUTHORITY    
2022-02-23 16:50:47 💾 Database: RocksDb at /Users/apple/Library/Application Support/subspace-node-x86_64-macos-11-snapshot-2022-jan-05/chains/subspace_test/db/full    
2022-02-23 16:50:47 ⛓  Native runtime: subspace-100 (subspace-1.tx1.au1)    
2022-02-23 16:50:55 Last archived block 505689    
2022-02-23 16:50:55 Archiving already produced blocks 505690..=505798    
2022-02-23 16:50:57 🏷  Local node identity is: 12D3KooWJBPe9vHbvLzB4roWxLwHgh1rxvgnFFGpidNAgHUjiQuN    
2022-02-23 16:51:14 🧑‍🌾 Starting Subspace Authorship worker    
2022-02-23 16:51:14 📦 Highest known block at #505898    
2022-02-23 16:51:14 〽️ Prometheus exporter started at 127.0.0.1:9615    
2022-02-23 16:51:14 Listening for new connections on 0.0.0.0:9944.    
2022-02-23 16:51:14 🔍 Discovered new external address for our node: /ip4/91.196.192.130/tcp/30333/p2p/12D3KooWJBPe9vHbvLzB4roWxLwHgh1rxvgnFFGpidNAgHUjiQuN    
2022-02-23 16:51:16 ♻️  Reorg on #505898,0xaa90…5fea to #505899,0x232b…40bd, common ancestor #505897,0xdebc…7db8    
2022-02-23 16:51:16 ✨ Imported #505899 (0x232b…40bd)    
2022-02-23 16:51:19 ⚙️  Syncing, target=#508777 (2 peers), best: #505940 (0x0799…1d85), finalized #0 (0x6ada…0d38), ⬇ 941.8kiB/s ⬆ 238.9kiB/s    
2022-02-23 16:51:24 ⚙️  Syncing 12.1 bps, target=#508777 (3 peers), best: #506001 (0x0baa…24d5), finalized #0 (0x6ada…0d38), ⬇ 1.1MiB/s ⬆ 1.4kiB/s    

As you can see, node was offline and after restart connected to network, started sync and had reorg of the [previously] best block.

I don't have detailed enough log to verify with 100% certainty, but I think the background process running in parallel to sync (triggered by block import actually) was requesting block 505898 by number and read non-canonical version of it (reorg didn't have effect yet).

Since blocks are read with lag of 100 blocks, so 505898 wasn't read until 505998 was imported, I have an impression that maybe canonical chain is not updated until sync is finished somehow.

Is it possible? Substrate implementation is quite complex so I didn't find exact place where canonical chain update happens yet.

Substrate is used from 5bd5b84 (in case there were relevant changes since).

[bkchr]

I'm confused, what is your problem? Or better, what is the bug?

[nazar-pc]

TL;DR: In BlockImport::import_block() I have an async call that tries to read block_number - 100block and I suspect that if this happens during sync process, it may read a block that doesn't belong to a canonical chain (if there was a reorg like in the log above).

The error/bug is that archived history (just block bodies) sometimes doesn't match what it should be after restart, but after node restart gets fixed. Above is the only plausible explanation I have for such an error.

[bkchr]

Okay. And you are sure that the canonical block is already imported when you are doing the request? And you are sure that the reorg already happened?

[nazar-pc]

Since it reads the block that is 100 blocks older than the tip and we never had such a deep fork, so I think it is fair to say yes to both, unless blocks are imported backwards, which I don't believe is a thing for normal operation (no warp sync).

[bkchr]

Yeah that is a good point. @arkpar any ideas?

[nazar-pc]

Friendly ping

[arkpar]

I don't think I understand the issue either. If the node ends up on a non-canonical block when you shut it down, it is normal to re-org right after the restart. At what exact point do you query for the block block_number - 100 and where does block_number come from?

[nazar-pc]

It is queried during block import right after block was imported, but before returning from the function, block_number is the block being imported

[nazar-pc]

Here is where it is called from: https://github.com/subspace/subspace/blob/9485bf440e70405218a33e6162d7f09eeb959431/crates/sc-consensus-subspace/src/lib.rs#L1176-L1181
And here is where block querying actually happens: https://github.com/subspace/subspace/blob/9485bf440e70405218a33e6162d7f09eeb959431/crates/sc-consensus-subspace/src/archiver.rs#L262-L265

[nazar-pc]

I believe https://substrate.stackexchange.com/a/1322/25 describes the root cause. Code in verifier was relying of some things happening during block import, which often is the case, but not guaranteed, resulting in rare obscure errors.