ChainSafe / ChainSafe/gossamer
Gossamer Authors a Block in the First Slot Even if Substrate Has Already Done So
- Dominant language
- Go
- Stars
- 454
- Forks
- 144
- PR merge metrics
- No merged PRs in 30d
Description
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
```
Contributor guide
Assessment
This issue has not been assessed yet.