blsync error "beacon syncer reorging"

[s1na]

System information

Geth version: geth version 1.14.4-unstable-a6751d6f-20240603
CL client & version: e.g. blsync
OS & Version:Linux

Expected behaviour

I had a mainnet node that was initially synced via lighthouse. However at some point I stopped lighthouse and started geth with blsync integrated. I expect to see no errors in the logs.

Actual behaviour

At first it synced a couple dozen blocks that it was behind. Then it started logging some errors. Interestingly it is still syncing and the tip is really going forward. Just that there are also these errors all the time in the logs.

INFO [06-03|13:50:28.283] Imported new chain segment               number=19,984,403 hash=99af49..4e9289 blocks=45 txs=7177 mgas=674.201 elapsed=8.228s mgasps=81.932 age=3d19h30m snapdiffs=6.20MiB triediffs=172.16MiB triedirty=200.59MiB
INFO [06-03|13:50:36.363] Imported new chain segment               number=19,984,452 hash=f53c95..1a7d76 blocks=49 txs=8011 mgas=736.620 elapsed=8.080s mgasps=91.163 age=3d19h20m snapdiffs=8.01MiB triediffs=172.04MiB triedirty=208.75MiB
WARN [06-03|13:50:37.536] Ignoring payload with missing parent     number=20,011,702 hash=007928..e5ad28 parent=d69996..f81378 reason="beacon syncer reorging"
INFO [06-03|13:50:37.536] Successful NewPayload                    number=20,011,702 hash=007928..e5ad28 status=SYNCING
INFO [06-03|13:50:37.536] Forkchoice requested sync to new head    number=20,011,702 hash=007928..e5ad28 finalized=unknown
WARN [06-03|13:50:37.536] Served engine_forkchoiceUpdatedV3        reqid=106 duration="189.275µs" err="beacon syncer reorging"
ERROR[06-03|13:50:37.536] Failed ForkchoiceUpdated                 head=007928..e5ad28 error="beacon syncer reorging"
INFO [06-03|13:50:44.368] Imported new chain segment               number=19,984,498 hash=9a7c92..3f24c0 blocks=46 txs=8136 mgas=731.290 elapsed=8.005s mgasps=91.352 age=3d19h11m snapdiffs=5.63MiB triediffs=170.99MiB triedirty=216.50MiB
WARN [06-03|13:50:49.638] Ignoring payload with missing parent     number=20,011,703 hash=7a2550..c7d8d9 parent=007928..e5ad28 reason="beacon syncer reorging"
INFO [06-03|13:50:49.638] Successful NewPayload                    number=20,011,703 hash=7a2550..c7d8d9 status=SYNCING
INFO [06-03|13:50:49.638] Forkchoice requested sync to new head    number=20,011,703 hash=7a2550..c7d8d9 finalized=unknown
WARN [06-03|13:50:49.638] Served engine_forkchoiceUpdatedV3        reqid=108 duration="231.53µs"  err="beacon syncer reorging"
ERROR[06-03|13:50:49.638] Failed ForkchoiceUpdated                 head=7a2550..c7d8d9 error="beacon syncer reorging"
INFO [06-03|13:50:52.452] Imported new chain segment               number=19,984,547 hash=865688..8e3a6c blocks=49 txs=7962 mgas=687.650 elapsed=8.084s mgasps=85.063 age=3d19h1m  snapdiffs=7.50MiB triediffs=174.39MiB triedirty=224.36MiB
INFO [06-03|13:51:00.553] Imported new chain segment               number=19,984,593 hash=266036..e84dc9 blocks=46 txs=7261 mgas=668.814 elapsed=8.100s mgasps=82.561 age=3d18h52m snapdiffs=5.31MiB triediffs=175.81MiB triedirty=232.08MiB
WARN [06-03|13:51:01.934] Ignoring payload with missing parent     number=20,011,704 hash=6dc10d..907dc9 parent=7a2550..c7d8d9 reason="beacon syncer reorging"
INFO [06-03|13:51:01.934] Successful NewPayload                    number=20,011,704 hash=6dc10d..907dc9 status=SYNCING
INFO [06-03|13:51:01.935] Forkchoice requested sync to new head    number=20,011,704 hash=6dc10d..907dc9 finalized=unknown
WARN [06-03|13:51:01.935] Served engine_forkchoiceUpdatedV3        reqid=110 duration="185.387µs" err="beacon syncer reorging"
ERROR[06-03|13:51:01.935] Failed ForkchoiceUpdated                 head=6dc10d..907dc9 error="beacon syncer reorging"
INFO [06-03|13:51:08.636] Imported new chain segment               number=19,984,637 hash=4166a4..996d9d blocks=44 txs=7696 mgas=649.101 elapsed=8.082s mgasps=80.305 age=3d18h43m snapdiffs=7.19MiB triediffs=187.84MiB triedirty=239.17MiB

[s1na]

Those warnings and errors were happening every slot. However once sync reached the tip of the chain they stopped. These are the logs from around that time:

WARN [06-03|15:23:18.103] Ignoring payload with missing parent     number=20,012,163 hash=662e90..bb0e2b parent=14c405..952324 reason="beacon syncer reorging"
INFO [06-03|15:23:18.104] Successful NewPayload                    number=20,012,163 hash=662e90..bb0e2b status=SYNCING
INFO [06-03|15:23:18.105] Forkchoice requested sync to new head    number=20,012,163 hash=662e90..bb0e2b finalized=20,012,078
WARN [06-03|15:23:18.105] Served engine_forkchoiceUpdatedV3        reqid=1020 duration="504.625µs" err="beacon syncer reorging"
ERROR[06-03|15:23:18.105] Failed ForkchoiceUpdated                 head=662e90..bb0e2b error="beacon syncer reorging"
INFO [06-03|15:23:21.823] Imported new chain segment               number=20,011,979 hash=e111f7..f09fe0 blocks=49 txs=8611 mgas=759.519 elapsed=8.056s    mgasps=94.270  age=37m10s    snapdiffs=9.49MiB triediffs=195.38MiB triedir
ty=214.44MiB
INFO [06-03|15:23:26.823] Imported new chain segment               number=20,012,009 hash=67895c..cef72d blocks=30 txs=5284 mgas=491.582 elapsed=5.000s    mgasps=98.315  age=31m15s    snapdiffs=6.71MiB triediffs=192.60MiB triedir
ty=220.75MiB
INFO [06-03|15:23:26.922] Syncing beacon headers                   downloaded=33493 left=0          eta=0s
WARN [06-03|15:23:29.894] Ignoring payload with missing parent     number=20,012,164 hash=c0ad84..1991e4 parent=662e90..bb0e2b reason="chain gapped, head: 20012097, newHead: 20012164"
INFO [06-03|15:23:29.894] Successful NewPayload                    number=20,012,164 hash=c0ad84..1991e4 status=SYNCING
INFO [06-03|15:23:29.894] Forkchoice requested sync to new head    number=20,012,164 hash=c0ad84..1991e4 finalized=20,012,078
INFO [06-03|15:23:29.896] Restarting sync cycle                    reason="chain gapped, head: 20012097, newHead: 20012164"
INFO [06-03|15:23:29.896] Successful ForkchoiceUpdated             head=c0ad84..1991e4 status=SYNCING
ERROR[06-03|15:23:29.939] Cleaning spurious beacon sync leftovers  stale_head_1=20,012,097 stale_tail_1=20,012,010 stale_next_1=67895c..cef72d
INFO [06-03|15:23:29.941] Syncing beacon headers                   downloaded=33647 left=0          eta=0s
INFO [06-03|15:23:42.392] Imported new chain segment               number=20,012,037 hash=21b74b..9853f2 blocks=28 txs=4488 mgas=399.914 elapsed=6.245s    mgasps=64.029  age=25m55s    snapdiffs=7.82MiB triediffs=188.93MiB triedir
ty=20.13MiB
INFO [06-03|15:23:46.021] Successful NewPayload                    number=20,012,165 hash=b7cd6d..62d8ab status=SYNCING
INFO [06-03|15:23:46.021] Forkchoice requested sync to new head    number=20,012,165 hash=b7cd6d..62d8ab finalized=20,012,078
INFO [06-03|15:23:46.022] Successful ForkchoiceUpdated             head=b7cd6d..62d8ab status=SYNCING
INFO [06-03|15:23:50.577] Imported new chain segment               number=20,012,080 hash=4affc7..c12505 blocks=43 txs=7267 mgas=618.927 elapsed=8.180s    mgasps=75.655  age=17m27s    snapdiffs=5.54MiB triediffs=185.93MiB triedir
ty=38.96MiB
INFO [06-03|15:23:54.940] Successful NewPayload                    number=20,012,166 hash=32d856..544b97 status=SYNCING
INFO [06-03|15:23:54.940] Forkchoice requested sync to new head    number=20,012,166 hash=32d856..544b97 finalized=20,012,078
INFO [06-03|15:23:54.941] Successful ForkchoiceUpdated             head=32d856..544b97 status=SYNCING
INFO [06-03|15:23:58.581] Imported new chain segment               number=20,012,126 hash=832512..64cd56 blocks=46 txs=7548 mgas=685.168 elapsed=8.004s    mgasps=85.602  age=8m23s     snapdiffs=7.40MiB triediffs=184.79MiB triedir
ty=54.68MiB
INFO [06-03|15:24:05.682] Imported new chain segment               number=20,012,164 hash=c0ad84..1991e4 blocks=38 txs=6940 mgas=569.949 elapsed=7.100s    mgasps=80.267  snapdiffs=8.96MiB triediffs=188.07MiB triedirty=4.77MiB
INFO [06-03|15:24:09.834] Successful NewPayload                    number=20,012,167 hash=410354..9ecbc1 status=SYNCING
INFO [06-03|15:24:09.834] Forkchoice requested sync to new head    number=20,012,167 hash=410354..9ecbc1 finalized=20,012,078
INFO [06-03|15:24:09.835] Successful ForkchoiceUpdated             head=410354..9ecbc1 status=SYNCING
INFO [06-03|15:24:10.491] Imported new chain segment               number=20,012,167 hash=410354..9ecbc1 blocks=3  txs=712  mgas=45.328  elapsed=457.691ms mgasps=99.036  snapdiffs=9.08MiB triediffs=188.45MiB triedirty=6.70MiB   i
gnored=1

I do observe these every once in a while:

INFO [06-03|15:31:55.776] Imported new potential chain segment     number=20,012,205 hash=0893b5..065696 blocks=1  txs=73   mgas=3.177   elapsed=50.979ms    mgasps=62.319  snapdiffs=6.56MiB triediffs=188.02MiB triedirty=27.13MiB
INFO [06-03|15:31:55.776] Successful NewPayload                    number=20,012,205 hash=0893b5..065696 status=VALID
INFO [06-03|15:31:55.778] Chain head was updated                   number=20,012,205 hash=0893b5..065696 root=757b2e..67e68d elapsed=1.114467ms
INFO [06-03|15:31:55.966] Successful ForkchoiceUpdated             head=0893b5..065696 status=VALID
WARN [06-03|15:32:05.724] Beacon API request failed                type=sync.ReqBeaconBlock reqid=565  err="Get \"https://www.lightclientdata.org/eth/v2/beacon/blocks/0xc1d3692bd7c11de64d2ef4bf898d05bcad8b6030e8ed6b9c2e19aeb13e2a
0041\": context deadline exceeded (Client.Timeout exceeded while awaiting headers)"
WARN [06-03|15:32:31.482] Ignoring payload with missing parent     number=20,012,207 hash=92ec6b..8d7a4b parent=e7285c..feb80b reason="chain gapped, head: 20012167, newHead: 20012207"
INFO [06-03|15:32:31.482] Successful NewPayload                    number=20,012,207 hash=92ec6b..8d7a4b status=SYNCING
INFO [06-03|15:32:31.482] Forkchoice requested sync to new head    number=20,012,207 hash=92ec6b..8d7a4b finalized=20,012,142
INFO [06-03|15:32:31.483] Restarting sync cycle                    reason="chain gapped, head: 20012167, newHead: 20012207"
INFO [06-03|15:32:31.483] Successful ForkchoiceUpdated             head=92ec6b..8d7a4b status=SYNCING
INFO [06-03|15:32:31.606] Syncing beacon headers                   downloaded=33648 left=0          eta=0s
ERROR[06-03|15:32:31.606] Failed to clean stale beacon headers     err="filled header below beacon header tail: 20012167 < 20012206"
WARN [06-03|15:32:31.655] Retrieved pivot header from local        number=20,012,143 hash=fa94b4..500ee4 latest=20,012,207 oldest=20,012,206

[zsfelfoldi]

This is not a bug, it's a feature :) The error string "beacon syncer reorging" comes from eth/downloader and has nothing to do with the beacon light client. It just means that the EL block coming from the CL source has no parent in the current EL chain. This is normally happening until geth syncs up missing blocks from the devp2p network.
Once the local EL chain is synced, this can still happen sometimes if the CL (in this case blsync) misses a block. This is what happened in the last log where a CL block retrieval has timed out and block 20,012,206 was not delivered to geth, therefore the next one was injected with no parent so geth had to go back to sync mode. Blsync could fetch the missing blocks, actually it was implemented at a certain point but then we decided to not complicate blsync with this because geth should be able to fill the gaps anyway.

[fjl]

Let's just wait until this happens again and then investigate @s1na

[s1na]

My sepolia light node has stopped finalizing after a while:

> eth.getBlock('latest').number - eth.getBlock('finalized').number
42385

For context, I did a fresh sync and everything was working fine. Fast forward few days later, I see these warning in the logs every slot:

WARN [06-23|10:52:25.046] Ignoring payload with missing parent     number=6,168,642 hash=39b8f1..bc7c35 parent=c5aaa1..3696b9 reason="chain gapped, head: 6168637, newHead: 6168642"
INFO [06-23|10:52:25.046] Successful NewPayload                    number=6,168,642 hash=39b8f1..bc7c35 status=SYNCING
INFO [06-23|10:52:25.046] Forkchoice requested sync to new head    number=6,168,642 hash=39b8f1..bc7c35 finalized=unknown
INFO [06-23|10:52:25.046] Restarting sync cycle                    reason="chain gapped, head: 6168637, newHead: 6168642"
INFO [06-23|10:52:25.046] Successful ForkchoiceUpdated             head=39b8f1..bc7c35 status=SYNCING
INFO [06-23|10:52:25.078] Syncing beacon headers                   downloaded=34974 left=0 eta=0s
WARN [06-23|10:52:25.079] Retrieved pivot header from local        number=6,168,578 hash=527403..71cb46 latest=6,168,642 oldest=6,168,638
INFO [06-23|10:52:25.919] Imported new chain segment               number=6,168,642 hash=39b8f1..bc7c35 blocks=5  txs=416  mgas=64.204  elapsed=806.007ms mgasps=79.657  age=1m13s           snapdiffs=5.08MiB triediffs=96.94MiB  triedirty=48.85MiB

WARN [06-23|10:53:25.162] Ignoring payload with missing parent     number=6,168,648 hash=9d6205..f8c416 parent=927825..a205ef reason="chain gapped, head: 6168642, newHead: 6168648"
INFO [06-23|10:53:25.162] Successful NewPayload                    number=6,168,648 hash=9d6205..f8c416 status=SYNCING
INFO [06-23|10:53:25.162] Forkchoice requested sync to new head    number=6,168,648 hash=9d6205..f8c416 finalized=unknown
INFO [06-23|10:53:25.163] Restarting sync cycle                    reason="chain gapped, head: 6168642, newHead: 6168648"
INFO [06-23|10:53:25.163] Successful ForkchoiceUpdated             head=9d6205..f8c416 status=SYNCING
INFO [06-23|10:53:25.195] Syncing beacon headers                   downloaded=34979 left=0 eta=0s
WARN [06-23|10:53:25.196] Retrieved pivot header from local        number=6,168,584 hash=519997..47a694 latest=6,168,648 oldest=6,168,643
INFO [06-23|10:53:26.144] Imported new chain segment               number=6,168,648 hash=9d6205..f8c416 blocks=6  txs=524  mgas=112.875 elapsed=909.325ms mgasps=124.130 age=1m2s

It looks similar to the issue above so posted it here.