Open s1na opened 3 weeks ago
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
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.
Let's just wait until this happens again and then investigate @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.
System information
Geth version:
geth version 1.14.4-unstable-a6751d6f-20240603
CL client & version: e.g. blsync OS & Version:LinuxExpected 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.