NethermindEth
Reprocessing in logs when missing slot on beaconchain.
Description I've noticed a strange correlation between missing slot on beacon chain and our processing. Whenever the missing slot occurs (like here: https://beaconcha.in/slot/8675152) for some reason we are reprocessing blocks and we have one block always processed twice but with different hash:
20 Mar 2024 10:11:15.065
Synced chain Head to 19474940 (0xfd0962...720273)
20 Mar 2024 10:11:15.042
Received ForkChoice: Head: 19474940 (0xfd0962...720273), Safe: 19474891 (0x53752b...01a619), Finalized: 19474859 (0xca119e...09177f)
20 Mar 2024 10:11:13.800
- Block throughput 37.56 MGas/s | 590.80 t/s | 2.20 Blk/s | recv 0 | proc 0
20 Mar 2024 10:11:13.800
- Block 17.04 MGas | 268 txs | calls 683 ( 41) | sload 2,410 | sstore 916 | create 0
20 Mar 2024 10:11:13.800
Processed 19474940 | 453.62 ms | slot 8,981 ms | Gas gwei: 36.46 .. 38.30 (37.94) .. 92.03
20 Mar 2024 10:11:13.330
Received new block: 19474940 (0xfd0962...720273)
20 Mar 2024 10:11:05.758
Synced chain Head to 19474939 (0x2a8a09...33713f)
20 Mar 2024 10:11:05.751
Received ForkChoice: Head: 19474939 (0x2a8a09...33713f), Safe: 19474891 (0x53752b...01a619), Finalized: 19474859 (0xca119e...09177f)
20 Mar 2024 10:11:04.819
- Block throughput 17.36 MGas/s | 295.81 t/s | 2.89 Blk/s | recv 0 | proc 0
20 Mar 2024 10:11:04.819
- Blocks 5 29.99 MGas | 511 txs | calls 1,157 ( 23) | sload 4,893 | sstore 1,774 | create 0
20 Mar 2024 10:11:04.819
Processed 19474935... 19474939 | 1,727.44 ms | slot 12,330 ms | Gas gwei: 32.41 .. 32.76 (36.52) .. 1,149.51
20 Mar 2024 10:11:03.066
Received new block: 19474939 (0x2a8a09...33713f)
20 Mar 2024 10:10:52.489
- Block throughput 133.10 MGas/s | 2537.99 t/s | -17.75 Blk/s | recv 0 | proc 0
20 Mar 2024 10:10:52.489
- Block 30.00 MGas | 572 txs | calls 906 ( 51) | sload 4,150 | sstore 1,455 | create 1
20 Mar 2024 10:10:52.489
Processed 19474934 | 225.38 ms | slot 14,879 ms | Gas gwei: 34.11 .. 34.11 (37.34) .. 95.00
20 Mar 2024 10:10:52.224
Received new block: 19474934 (0x6260cc...66524a)
20 Mar 2024 10:10:37.857
Synced chain Head to 19474938 (0x86867b...2d6da2)
20 Mar 2024 10:10:37.857
Received ForkChoice: Head: 19474938 (0x86867b...2d6da2), Safe: 19474891 (0x53752b...01a619), Finalized: 19474859 (0xca119e...09177f)
20 Mar 2024 10:10:37.611
- Block throughput 59.01 MGas/s | 1195.18 t/s | 4.60 Blk/s | recv 0 | proc 0
20 Mar 2024 10:10:37.611
- Block 12.84 MGas | 260 txs | calls 440 ( 6) | sload 1,862 | sstore 680 | create 0
20 Mar 2024 10:10:37.611
Processed 19474938 | 217.54 ms | slot 11,308 ms | Gas gwei: 33.01 .. 33.01 (35.38) .. 134.16
20 Mar 2024 10:10:37.385
Received new block: 19474938 (0x86867b...2d6da2)
20 Mar 2024 10:10:26.745
Synced chain Head to 19474937 (0x136262...074e08)
20 Mar 2024 10:10:26.743
Received ForkChoice: Head: 19474937 (0x136262...074e08), Safe: 19474891 (0x53752b...01a619), Finalized: 19474859 (0xca119e...09177f)
20 Mar 2024 10:10:26.302
- Block throughput 16.57 MGas/s | 306.62 t/s | 1.18 Blk/s | recv 0 | proc 0
20 Mar 2024 10:10:26.302
- Block 13.99 MGas | 259 txs | calls 472 ( 13) | sload 2,471 | sstore 837 | create 0
20 Mar 2024 10:10:26.302
Processed 19474937 | 844.68 ms | slot 12,876 ms | Gas gwei: 33.28 .. 33.28 (35.97) .. 203.70
20 Mar 2024 10:10:25.446
Received new block: 19474937 (0x136262...074e08)
There is a log Received new block: 19474934 (0x6260cc...66524a) but when I check this block on chain it has different hash:
https://beaconcha.in/block/19474934 - 0x9114a81dfcd800f181cf50243fbcc8a6df16ad5647462a39c54136aa30c50e84
We have multiple reports that for some reason validators are losing head vote when previous slot was missing - maybe this is related? or maybe it is just a logging issue.
Good catch @kamilchodola
This looks like a bug on our side. We processed a few blocks, we didn't have to though. We could process only the latest block, but block 19474934 caused that we did Processed 19474935... 19474939 and because of it is 5 blocks it took more time 1,727.44 ms so we missed head vote.
There is misleading log statement here caused by: https://github.com/NethermindEth/nethermind/blob/c2529a99a33fc78e61bffa62f3c045c280f582cb/src/Nethermind/Nethermind.Consensus/Processing/ProcessingStats.cs#L106
This will calculate an incorrect amount of processed blocks, if a block gets processed out of order.
@ak88 So at the end is this a real issue or just logging issue? I recall users were complaining about lost attestations when this occur so wondering what is the problem in there