Geth produced a block without transactions in mainnet

[joaocenoura]

System information

Geth version: v1.10.23
CL client & version: teku/v22.11.0
OS & Version: Linux
Commit hash : N/A

Context

Our setup in mainnet is a Teku CL + MEV boost (single relay) + Geth EL. We've experienced mev-boost failures which made Teku to use Geth as fallback block builder. During a 7 day period, Geth was used as a fallback block builder 124 times, of which it produced 4 blocks without transactions.

Expected behaviour

Geth should always produce blocks with transactions.

Actual behaviour

Geth produced ~3% of blocks without transactions

Steps to reproduce the behaviour

We're not able to reproduce this issue consistently on mainnet. From our sample, ~3% percent of the blocks were affected during normal operation of our nodes.

Backtrace

There were no errors or warning in Geth that could help troubleshoot the root cause of this issue. We only saw in Teku:

2022-12-12 06:28:51.001 INFO  - Slot Event  *** Slot: 5333542, Block: 257eff64f8de68d9102de90f3a820bffa8180dea33d5de6ae0dbe737f668d403, Justified: 166672, Finalized: 166671, Peers: 100
2022-12-12 06:28:39.001 INFO  - Slot Event  *** Slot: 5333541, Block: 14ea43cce448b280c3765ad8370c2f07c7b00424ad164e11696d021258cdb0ca, Justified: 166672, Finalized: 166671, Peers: 100
2022-12-12 06:28:27.000 INFO  - Slot Event  *** Slot: 5333540, Block: 9dc64b6e664cab7c526d2988207f22a7498323a4e26f2ee53ac0c7d350eb75b3, Justified: 166672, Finalized: 166671, Peers: 100
2022-12-12 06:28:15.001 INFO  - Slot Event  *** Slot: 5333539, Block: ec4a33c9f8f9212d425f650659f66d3f60d0dd40a9a9c1f97585b21495b67fbc, Justified: 166672, Finalized: 166671, Peers: 100
2022-12-12 06:28:03.071 INFO  - Slot Event  *** Slot: 5333538, Block: 068a54bcd6a8c05b9b5ae568bce6f39dcd0afafd3235f2741bcc2afd6c050014, Justified: 166672, Finalized: 166671, Peers: 101
2022-12-12 06:27:51.000 INFO  - Slot Event  *** Slot: 5333537, Block: 947f8b8356b7a455de621568e59489d24ed42fb55874b8da454cde3a433f6271, Justified: 166672, Finalized: 166671, Peers: 100
2022-12-12 06:27:39.001 INFO  - Slot Event  *** Slot: 5333536, Block: 7860622b5e7a027f335d7d8903c95974ea04ef7891ad328bce365ff72ce0440b, Justified: 166672, Finalized: 166671, Peers: 101
2022-12-12 06:27:36.957 INFO  - Falling back to locally produced execution payload (Block Number 16166836, Block Hash = 0x74273878c39a508cf6f8eb5db3525c011c65ee7d6857e5433c83f021f203cf88, Fallback Reason = validator_not_registered)
2022-12-12 06:27:36.699 INFO  - Sync committee performance: epoch 166672, <redacted>
2022-12-12 06:27:36.699 INFO  - Attestation performance: epoch 166671, <redacted>
2022-12-12 06:27:35.001 INFO  - Epoch Event *** Epoch: 166673, Justified checkpoint: 166672, Finalized checkpoint: 166671, Finalized root: 2fd661a3dcbdbddb041d1409093ff8ebe83da2764f432ca092af74aca02064d7
2022-12-12 06:27:27.000 INFO  - Slot Event  *** Slot: 5333535, Block: 3609c35e5dd616ddb03cdffbfbfba4cd1981ee3421cb2b9e4336c43eb7940f5f, Justified: 166671, Finalized: 166670, Peers: 100
2022-12-12 06:27:15.000 INFO  - Slot Event  *** Slot: 5333534, Block: ab2c9c141d102589502e8f8bbb1a5deeefc1f5a048cf399bc95a8cc1b54f7f05, Justified: 166671, Finalized: 166670, Peers: 100
2022-12-12 06:27:03.001 INFO  - Slot Event  *** Slot: 5333533, Block: d22074a32946e03ae9ef19dace47bb14c09d3b54f83c3a9ea4d48cb2c494ddcc, Justified: 166671, Finalized: 166670, Peers: 100

And in Geth:

INFO [12-12|06:28:11.696] Unindexed transactions                   blocks=1    txs=317     tail=13,816,840 elapsed=3.732ms
INFO [12-12|06:28:11.692] Chain head was updated                   number=16,166,839 hash=a2949a..252590 root=7e02b0..91af93 elapsed="520.503µs"
INFO [12-12|06:28:11.562] Imported new potential chain segment     blocks=1    txs=13      mgas=3.625   elapsed=41.097ms     mgasps=88.194   number=16,166,839 hash=a2949a..252590 dirty=1020.16MiB
INFO [12-12|06:28:00.585] Unindexed transactions                   blocks=1    txs=24      tail=13,816,839 elapsed="464.303µs"
INFO [12-12|06:28:00.584] Chain head was updated                   number=16,166,838 hash=1a74a1..7accc7 root=089974..af0250 elapsed=8.548253ms
INFO [12-12|06:28:00.567] Imported new potential chain segment     blocks=1    txs=201     mgas=29.209  elapsed=1.001s       mgasps=29.172   number=16,166,838 hash=1a74a1..7accc7 dirty=1021.93MiB
INFO [12-12|06:27:48.046] Unindexed transactions                   blocks=1    txs=53      tail=13,816,838 elapsed="923.105µs"
INFO [12-12|06:27:48.045] Chain head was updated                   number=16,166,837 hash=3f8f41..2cffe8 root=aff1f3..4b8d5c elapsed=2.606915ms
INFO [12-12|06:27:48.027] Imported new potential chain segment     blocks=1    txs=109     mgas=29.999  elapsed=142.018ms    mgasps=211.232  number=16,166,837 hash=3f8f41..2cffe8 dirty=1023.30MiB
INFO [12-12|06:27:37.117] Unindexed transactions                   blocks=1    txs=50      tail=13,816,837 elapsed=1.050ms
INFO [12-12|06:27:37.115] Chain head was updated                   number=16,166,836 hash=742738..03cf88 root=4e0a52..3e12d3 elapsed="100.901µs"
INFO [12-12|06:27:36.965] Imported new potential chain segment     blocks=1    txs=0       mgas=0.000   elapsed=10.297ms     mgasps=0.000    number=16,166,836 hash=742738..03cf88 dirty=1021.78MiB
INFO [12-12|06:27:24.427] Unindexed transactions                   blocks=1    txs=336     tail=13,816,836 elapsed=4.530ms
INFO [12-12|06:27:24.423] Chain head was updated                   number=16,166,835 hash=c5fb9e..1153cc root=4e0a52..3e12d3 elapsed=5.477731ms
INFO [12-12|06:27:24.408] Imported new potential chain segment     blocks=1    txs=106     mgas=15.415  elapsed=448.053ms    mgasps=34.405   number=16,166,835 hash=c5fb9e..1153cc dirty=1022.58MiB
INFO [12-12|06:27:11.996] Unindexed transactions                   blocks=1    txs=129     tail=13,816,835 elapsed=1.755ms
INFO [12-12|06:27:11.994] Chain head was updated                   number=16,166,834 hash=45985e..f7a64b root=01bb95..d53e68 elapsed=3.171018ms
INFO [12-12|06:27:11.983] Imported new potential chain segment     blocks=1    txs=113     mgas=10.523  elapsed=110.206ms    mgasps=95.480   number=16,166,834 hash=45985e..f7a64b dirty=1022.19MiB

We're using default settings for logging. Unfortunately there's no warnings or errors in CL or EL. The only relevant line in CL is:

2022-12-12 06:27:36.957 INFO  - Falling back to locally produced execution payload (Block Number 16166836, Block Hash = 0x74273878c39a508cf6f8eb5db3525c011c65ee7d6857e5433c83f021f203cf88, Fallback Reason = validator_not_registered)

and from EL we're just seeing it importing the produced block w/out transactions:

INFO [12-12|06:27:36.965] Imported new potential chain segment     blocks=1    txs=0       mgas=0.000   elapsed=10.297ms     mgasps=0.000    number=16,166,836 hash=742738..03cf88 dirty=1021.78MiB

Final note

We've mitigated this issue by adding more relays which should improve mev-boost resilience and decrease the probability of fallback to Geth's block production. However we're just hiding a real issue here and, because of that, it would be valuable to understand under what circumstances Geth provides a block without transactions in mainnet.
Would also be worth knowing if is there any logging we could enable specifically for block production or any other flag that could improve block production process.

[holiman]

Geth version: v1.10.23

Use latest master, a.k.a unstable for prebuilt binaries or latest on docker. We shipped some improvements to block building, which have not made it into stable release yet, it seems.

[holiman]

More specifically: #25836

[joaocenoura]

many thanks for the fast reply @holiman. Any ETA for it to hit stable? Would you know if there's any logging improvements related to block production we could enable? Many thanks for your work 🙌

[holiman]

I don't know the ETA for it to hit stable. We won't ship 1.11 for a while yet, so the question is if we will include it in a backport release any time soon.... We'll discusss it, we haven't scheduled it yet.

[ricardolyn]

@holiman is there a plan to add logs when a block is produced by Geth or provided to the beacon? Thanks