Runtime error Timestamp slot must match CurrentSlot while producing block

[EclesioMeloJunior]

Describe the bug

• While running gossamer as Bob and two other substrate nodes as Alice and Charlie, respectively I notice that the gossamer node throw several of the following error:

2022-06-30T14:39:16-04:00 CRIT target=runtime message=panicked at 'Timestamp slot must match `CurrentSlot`', /Users/eclesiojunior/.cargo/git/checkouts/substrate-7e08433d4c370a21/563f482/frame/babe/src/lib.rs:845:9	imports.go:L139:ext_logging_log_version_1	pkg=runtime module=go-wasmer
2022-06-30T14:39:16-04:00 WARN failed to handle slot 414153514: cannot build inherents: Failed to call the `BlockBuilder_apply_extrinsic` exported function.	epoch_handler.go:L125	pkg=babe

I noticed that running gossamer as Alice (babe-lead: true) and two other substrate nodes as Bob and Charlie this error rarely appears.

Obs: In fact gossamer waits for the first block to be produced to initiate the epoch and set up the slots.

[EclesioMeloJunior]

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

[EclesioMeloJunior]

The error was caused by a slight difference between the timestamp defined when the epoch starts and the timestamp inserted in the inherent when the block is built, there is a table below that describes the timestamp when the slot number was defined and the timestamp when the block is built in the slot.

slot number	timestamp defined	timestamp on block inherent
414248299	1656993196	1656993196009
414248302	1656993208	1656993208006
414248305	1656993220	1656993220001
414248307	1656993228	1656993228000
414248309	1656993236	1656993236004
414248310	1656993240	1656993240004
414248313	1656993252	1656993252001
414248314	1656993256	1656993255998

For almost all slots the timestamp defined in the epoch start and the timestamp stored in the block inherent in the build process are compatible but on slot 414248314 the error panicked at Timestamp slot must match CurrentSlot occurs and we can see that the timestamp defined was 1656993256 (Tuesday, July 5, 2022 3:54:16 AM), and the timestamp stored on block inherent in the build process is 1656993255998 (Tuesday, July 5, 2022 3:54:15.998 AM) meaning we are milliseconds before the intended timestamp for the current slot.

We should guarantee that we only build a block right after the start timestamp for the current slot is reached

[qdm12]

For the record, this is due to the timer triggering before the target slot startTime. The time received from the timer channel is sometimes behind the start time, and calling time.Now() will give a time before startTime quite often.

Note sure if this is an OS or kernel or Go issue, but we ended up just adding an if check with an extra sleep if it happens.