ChainSafe
Gossamer Authors a Block in the First Slot Even if Substrate Has Already Done So
Copied from https://github.com/ChainSafe/gossamer/issues/2634#issuecomment-1174497612
Running two nodes: one substrate node with the following log flags: -lsc_basic_authorship::basic_authorship=trace,sc_basic_authorship::basic_authorship=debug,babe=trace,babe=debug I and a gossamer node without --babe-lead flag I noticed the following behavior:
After the Gossamer bob node connects to substrate alice it is possible to see that Alice successfully claimed the slot number 414245627 to produce the block number 1:
2022-07-04 20:54:59.369 INFO tokio-runtime-worker substrate: 💤 Idle (0 peers), best: #0 (0x831b…cbd5), finalized #0 (0x831b…cbd5), ⬇ 0 ⬆ 0
2022-07-04 20:55:00.019 DEBUG tokio-runtime-worker babe: Skipping proposal slot. Waiting for the network.
2022-07-04 20:55:04.006 DEBUG tokio-runtime-worker babe: Attempting to claim slot 414245626
2022-07-04 20:55:04.374 INFO tokio-runtime-worker substrate: 💤 Idle (1 peers), best: #0 (0x831b…cbd5), finalized #0 (0x831b…cbd5), ⬇ 0.5kiB/s ⬆ 0.5kiB/s
2022-07-04 20:55:08.004 DEBUG tokio-runtime-worker babe: Attempting to claim slot 414245627
2022-07-04 20:55:08.007 DEBUG tokio-runtime-worker babe: Claimed slot 414245627
2022-07-04 20:55:08.007 DEBUG tokio-runtime-worker babe: Starting authorship at slot 414245627; timestamp = 1656982508001
2022-07-04 20:55:08.007 INFO tokio-runtime-worker sc_basic_authorship::basic_authorship: 🙌 Starting consensus session on top of parent 0x831bc7b7435742990d86fb32940b26af8e0f3d273aa712e673e553ce3a3bcbd5
2022-07-04 20:55:08.024 DEBUG tokio-runtime-worker sc_basic_authorship::basic_authorship: Attempting to push transactions from the pool.
2022-07-04 20:55:08.024 DEBUG tokio-runtime-worker sc_basic_authorship::basic_authorship: Pool status: PoolStatus { ready: 0, ready_bytes: 0, future: 0, future_bytes: 0 }
2022-07-04 20:55:08.030 INFO tokio-runtime-worker sc_basic_authorship::basic_authorship: 🎁 Prepared block for proposing at 1 (5 ms) [hash: 0xa77bef4c1ebb7782b2607ae60b205ec5c1f5999d3f42cf0fcdec406562abfdca; parent_hash: 0x831b…cbd5; extrinsics (1): [0xafee…a8ae]]
2022-07-04 20:55:08.033 INFO tokio-runtime-worker babe: 🔖 Pre-sealed block for proposal at 1. Hash now 0x72558fc82d6df3aee34548b710f0ea2d9cc59a190e348222039a08e59705bcb3, previously 0xa77bef4c1ebb7782b2607ae60b205ec5c1f5999d3f42cf0fcdec406562abfdca.
2022-07-04 20:55:08.033 INFO tokio-runtime-worker babe: 👶 New epoch 0 launching at block 0x7255…bcb3 (block slot 414245627 >= start slot 414245627).
On the gossamer side when it connects with the substrate it is possible to see gossamer syncing block number one and setting the first slot as 414245627
2022-07-04T20:55:05-04:00 INFO 🚣 currently syncing, 1 peers connected, target block number 4294967295, 0.00 average blocks/second, 0.00 overall average, finalised block number 0 with hash 0x831bc7b7435742990d86fb32940b26af8e0f3d273aa712e673e553ce3a3bcbd5 chain_sync.go:L385 pkg=sync
2022-07-04T20:55:08-04:00 DBUG syncing block 1, setting first slot as 414245627 verify.go:L152 pkg=babe
After that gossamer starts the epoch 0 and set up all the slots:
2022-07-04T20:55:08-04:00 INFO initiating epoch 0 with start slot 414245627 epoch.go:L59 pkg=babe
2022-07-04T20:55:08-04:00 DBUG epoch 0: claimed secondary vrf slot 414245627 epoch.go:L239 pkg=babe
2022-07-04T20:55:08-04:00 DBUG epoch 0: claimed secondary vrf slot 414245631 epoch.go:L239 pkg=babe
2022-07-04T20:55:08-04:00 DBUG epoch 0: claimed secondary vrf slot 414245633 epoch.go:L239 pkg=babe
2022-07-04T20:55:08-04:00 DBUG epoch 0: claimed secondary vrf slot 414245642 epoch.go:L239 pkg=babe
2022-07-04T20:55:08-04:00 DBUG epoch 0: claimed primary slot 414245649 epoch.go:L217 pkg=babe
2022-07-04T20:55:08-04:00 DBUG epoch 0: claimed primary slot 414245650 epoch.go:L217 pkg=babe
2022-07-04T20:55:08-04:00 DBUG epoch 0: claimed secondary vrf slot 414245651 epoch.go:L239 pkg=babe
2022-07-04T20:55:08-04:00 DBUG epoch 0: claimed primary slot 414245657 epoch.go:L217 pkg=babe
2022-07-04T20:55:08-04:00 DBUG epoch 0: claimed secondary vrf slot 414245658 epoch.go:L239 pkg=babe
2022-07-04T20:55:08-04:00 DBUG epoch 0: claimed secondary vrf slot 414245661 epoch.go:L239 pkg=babe
2022-07-04T20:55:08-04:00 DBUG epoch 0: claimed secondary vrf slot 414245664 epoch.go:L239 pkg=babe
2022-07-04T20:55:08-04:00 DBUG epoch 0: claimed secondary vrf slot 414245665 epoch.go:L239 pkg=babe
2022-07-04T20:55:08-04:00 DBUG epoch 0: claimed secondary vrf slot 414245668 epoch.go:L239 pkg=babe
2022-07-04T20:55:08-04:00 DBUG authoring in 13 slots in epoch 0 epoch_handler.go:L109 pkg=babe
And right after setting up the slots gossamer logs the line that says wait for the next authoring slot number 414245627 in order to produce a block in it, which did not make any sense as this specific slot already contains a block that gossamer knows about it. After logging the line, gossamer built block number 2 and then logs the line that says waiting for next authoring slot 414245631 which is the slot right after the slot 414245627
2022-07-04T20:55:08-04:00 DBUG waiting for next authoring slot 414245627 epoch_handler.go:L112 pkg=babe
2022-07-04T20:55:10-04:00 INFO built block 2 with hash 0x33bd95c34026e87c719f2f25457053ca43b389e53887843d59e7bbf32502506e, state root 0x14dfe22c12afa89b5a8e7e2d94a4449d9cdbe9ffa9b75401f210884c5944b27e, epoch 0 and slot 414245627 babe.go:L541 pkg=babe
2022-07-04T20:55:10-04:00 DBUG waiting for next authoring slot 414245631 epoch_handler.go:L112 pkg=babe
At the same time in the substrate node, after the substrate produces block 1 and starts epoch 0 it disconnects from gossamer, but gossamer keeps producing blocks
2022-07-04 20:55:08.033 INFO tokio-runtime-worker babe: 👶 New epoch 0 launching at block 0x7255…bcb3 (block slot 414245627 >= start slot 414245627).
2022-07-04 20:55:08.033 INFO tokio-runtime-worker babe: 👶 Next epoch starts at slot 414245672
2022-07-04 20:55:08.034 INFO tokio-runtime-worker substrate: ✨ Imported #1 (0x7255…bcb3)
2022-07-04 20:55:09.378 INFO tokio-runtime-worker substrate: 💤 Idle (1 peers), best: #1 (0x7255…bcb3), finalized #0 (0x831b…cbd5), ⬇ 0.1kiB/s ⬆ 0.3kiB/s
2022-07-04 20:55:12.000 DEBUG tokio-runtime-worker babe: Skipping proposal slot. Waiting for the network.
2022-07-04 20:55:14.383 INFO tokio-runtime-worker substrate: 💤 Idle (0 peers), best: #1 (0x7255…bcb3), finalized #0 (0x831b…cbd5), ⬇ 0.4kiB/s ⬆ 0.2kiB/s
2022-07-04 20:55:16.004 DEBUG tokio-runtime-worker babe: No block for 1 slots. Applying exponential lenience, total proposing duration: 4000ms
currently syncing, 1 peers connected, target block number 4294967295, block number is 1, but it is printing 4294967295. This looks problematic
which did not make any sense as this specific slot already contains a block that gossamer knows about it.
Multiple authors can claim the same slot. So, this is acceptable. We can author a block in the slot even if we know someone else has authored a block (let's call this block B) in that slot. It will create a fork, which will get resolved later. But it is not acceptable to author blocks on top of B, since that would create non-increasing slots in the chain.