search

erigontech / erigon

Ethereum implementation on the efficiency frontier https://erigon.gitbook.io
GNU Lesser General Public License v3.0
3.16k stars 1.14k forks source link

Erigon mainnet sync seems always 1-2 blocks behind #8448

Open michelescippa opened 1 year ago

michelescippa commented 1 year ago

erigon version 2.49.2-stable-a8ae8a03 Ubuntu 22.04.3 LTS

After sync finished, it seems always downloading blocks through EngineBlockDownloader and chase the latest block.

Erigon log:

[INFO] [10-12|10:33:34.165] [snapshots] Dumping txs block num=17564397 alloc=2.7GB sys=5.8GB [INFO] [10-12|10:33:36.073] [NewPayload] Handling new payload height=18333765 hash=0x71e1eeba24038db4765ac2fae2ccf31ba662247665da69d3367b2d8c69de31b1 [INFO] [10-12|10:33:36.073] [EngineBlockDownloader] Downloading PoS headers... height=unknown hash=0x5419534ba8f73e8f413211560bec6d7eada746ee39cc5852644e67e973754970 requestId=0 [INFO] [10-12|10:33:36.509] [EngineBlockDownloader] Processed highest=18333764 [INFO] [10-12|10:33:36.509] Beginning downloaded blocks insertion [INFO] [10-12|10:33:36.584] [EngineBlockDownloader] Finished downloading blocks from=18333763 to=18333764 [INFO] [10-12|10:33:40.587] [EngineBlockDownloader] blocks verification successful [INFO] [10-12|10:33:48.519] [NewPayload] Handling new payload height=18333766 hash=0x51e6622dcdd61c965b4dceb8c11ea7b92f1dad6d8b3128d0533588f19a29d7df [INFO] [10-12|10:33:52.336] [4/12 Execution] Completed on block=18333766 [INFO] [10-12|10:33:54.245] [snapshots] Dumping txs block num=17564886 alloc=3.6GB sys=5.8GB [INFO] [10-12|10:33:56.131] RPC Daemon notified of new headers from=18333763 to=18333766 hash=0x51e6622dcdd61c965b4dceb8c11ea7b92f1dad6d8b3128d0533588f19a29d7df header sending=26.924µs log sending=276ns [INFO] [10-12|10:33:56.131] head updated hash=0x51e6622dcdd61c965b4dceb8c11ea7b92f1dad6d8b3128d0533588f19a29d7df number=18333766

Lighthouse log:

Oct 12 10:38:53.001 INFO Synced                                  slot: 7523592, block: 0x0226…8294, epoch: 235112, finalized_epoch: 235110, finalized_root: 0x9da4…1f6c, exec_hash: 0x4aa9…33e0 (unverified), peers: 11, service: slot_notifier
Oct 12 10:39:01.648 INFO New block received                      root: 0x2f06e1671a7ad347661632d516597974503759d9a1acd4116892735501a4d4c0, slot: 7523593
Oct 12 10:39:05.000 INFO Synced                                  slot: 7523593, block: 0x2f06…d4c0, epoch: 235112, finalized_epoch: 235110, finalized_root: 0x9da4…1f6c, exec_hash: 0x383d…1c6f (verified), peers: 11, service: slot_notifier
Oct 12 10:39:11.945 INFO New block received                      root: 0x310bcd3265cfc67a778d608202677f595730171cc388de5b0759d5e0959315da, slot: 7523594
Oct 12 10:39:17.001 WARN Head is optimistic                      execution_block_hash: 0x7def775257da0e99aaf43612d29377e5b0ba5677639ec9cf44e46df9202037a7, info: chain not fully verified, block and attestation production disabled until execution engine syncs, service: slot_notifier
Oct 12 10:39:17.001 INFO Synced                                  slot: 7523594, block: 0x310b…15da, epoch: 235112, finalized_epoch: 235110, finalized_root: 0x9da4…1f6c, exec_hash: 0x7def…37a7 (unverified), peers: 11, service: slot_notifier
Oct 12 10:39:24.877 INFO New block received                      root: 0x71fed49b0fae53cf871e93dfa89a031c0c7d527a691655d9d1446d94ea036a7d, slot: 7523595
Oct 12 10:39:29.000 WARN Head is optimistic                      execution_block_hash: 0x80247cdb8376230327632d0ed1029f1694f60a93e245018470ce6f843c38d459, info: chain not fully verified, block and attestation production disabled until execution engine syncs, service: slot_notifier
Oct 12 10:39:29.000 INFO Synced                                  slot: 7523595, block: 0x71fe…6a7d, epoch: 235112, finalized_epoch: 235110, finalized_root: 0x9da4…1f6c, exec_hash: 0x8024…d459 (unverified), peers: 10, service: slot_notifier
RatanRSur commented 1 year ago

I think I'm seeing something similar on 2.52. erigon:

Oct 12 07:35:54 pillow erigon[3238747]: [INFO] [10-12|07:35:54.960] [NewPayload] Handling new payload        height=18334072 hash=0x5dd01d036ac4feb22823b10c3b3db9a94c10e6f30c3e543278ebdbc62607741e
Oct 12 07:36:00 pillow erigon[3238747]: [INFO] [10-12|07:36:00.943] [NewPayload] Handling new payload        height=18334075 hash=0x7072d945c24fbec186c64053084c492f8ea99b9fa3c13cee5c55a266a5152cbd
Oct 12 07:36:00 pillow erigon[3238747]: [INFO] [10-12|07:36:00.943] [EngineBlockDownloader] Downloading PoS headers... height=unknown hash=0xb03f19c06792554cf25c21909d302fe11c53456abbe3c434eecc37ab44a7aab4 requestId=0
Oct 12 07:36:04 pillow erigon[3238747]: [INFO] [10-12|07:36:04.165] [EngineBlockDownloader] Processed        highest=18334074
Oct 12 07:36:04 pillow erigon[3238747]: [INFO] [10-12|07:36:04.165] Beginning downloaded blocks insertion
Oct 12 07:36:04 pillow erigon[3238747]: [INFO] [10-12|07:36:04.169] [EngineBlockDownloader] Finished downloading blocks from=18334072 to=18334074
Oct 12 07:36:04 pillow erigon[3238747]: [INFO] [10-12|07:36:04.181] [EngineBlockDownloader] block verification skipped
Oct 12 07:36:13 pillow erigon[3238747]: [INFO] [10-12|07:36:13.401] [NewPayload] Handling new payload        height=18334076 hash=0xc461c1608d9c33302350bf05a11441fae543f7ac4d285800d23aa6dcf5d9ede6
Oct 12 07:36:24 pillow erigon[3238747]: [INFO] [10-12|07:36:24.258] [NewPayload] Handling new payload        height=18334077 hash=0xe390eed133176c079822479597b8a312fe6de9ca94ea553fe3ee19d51fd1bb1a
Oct 12 07:36:36 pillow erigon[3238747]: [INFO] [10-12|07:36:36.928] [NewPayload] Handling new payload        height=18334078 hash=0x02b1d3c7dc28d57ef9051fcbaa6c3b11f13e18d14988c12f61d2ae6d504fe196
Oct 12 07:36:47 pillow erigon[3238747]: [INFO] [10-12|07:36:47.950] [NewPayload] Handling new payload        height=18334079 hash=0xc463185e8372c43c577a2e04159da7aa768efc4d8c67e4378338a4f994fae23d
Oct 12 07:37:00 pillow erigon[3238747]: [INFO] [10-12|07:37:00.620] [NewPayload] Handling new payload        height=18334080 hash=0xc9b877472d46e9d5b6256c981c83de3029a3970a2eb1e1e20f22f7da856fb96e
Oct 12 07:37:12 pillow erigon[3238747]: [INFO] [10-12|07:37:12.478] [NewPayload] Handling new payload        height=18334081 hash=0xbf2f826774b4d0d4cdede106e863b578522d456787f500353032af5cb94d2a40
Oct 12 07:37:23 pillow erigon[3238747]: [INFO] [10-12|07:37:23.868] [NewPayload] Handling new payload        height=18334082 hash=0x4424ea0fda294bc512eb8638c5bff1f451d76ceeaa933f2e8fb345f6d623e24f
Oct 12 07:37:36 pillow erigon[3238747]: [INFO] [10-12|07:37:36.948] [NewPayload] Handling new payload        height=18334083 hash=0x7f11febc14e6457d3b79ac7f4cedfa424e6fa08f54736729d9eff6d358cd38cc
Oct 12 07:37:48 pillow erigon[3238747]: [INFO] [10-12|07:37:48.363] [NewPayload] Handling new payload        height=18334084 hash=0x49914cbf07234f9c7a73f3dca4eed2d8550b51301364a6766d7235ea178b4693
Oct 12 07:38:02 pillow erigon[3238747]: [INFO] [10-12|07:38:02.309] [NewPayload] Handling new payload        height=18334085 hash=0xb03722990daea5202a9b791e7b60d2935dd3d246a68307d343589185334d7c7e
Oct 12 07:38:12 pillow erigon[3238747]: [INFO] [10-12|07:38:12.120] [NewPayload] Handling new payload        height=18334086 hash=0x7f8dc88dba59afd3e608fedbfff310de277184a56ad389b56d6bc6b03629d7c3
Oct 12 07:38:24 pillow erigon[3238747]: [INFO] [10-12|07:38:24.207] [NewPayload] Handling new payload        height=18334087 hash=0x49f65ca8498442179330246b3cd7d5059f382212e827e80dcb3b33fc24715562
Oct 12 07:38:35 pillow erigon[3238747]: [INFO] [10-12|07:38:35.864] [NewPayload] Handling new payload        height=18334088 hash=0x30e73d43a4e01c3c77a48f0b4b4d1860feb8c131319c38ac13ca32830242b44d
Oct 12 07:38:49 pillow erigon[3238747]: [INFO] [10-12|07:38:49.862] [NewPayload] Handling new payload        height=18334089 hash=0xd4d186f298fe2aef183bfbff0f21d17d9cd8c4dad989a79319c2fc1e755d7727
Oct 12 07:38:50 pillow erigon[3238747]: [INFO] [10-12|07:38:50.927] [p2p] GoodPeers                          eth68=3 eth67=2
Oct 12 07:38:51 pillow erigon[3238747]: [INFO] [10-12|07:38:51.842] [txpool] stat                            pending=2022 baseFee=0 queued=1662 alloc=4.5GB sys=5.4GB
Oct 12 07:39:00 pillow erigon[3238747]: [INFO] [10-12|07:39:00.346] [NewPayload] Handling new payload        height=18334090 hash=0xb0ff3031438e1059cf3158fb5b28cbdbac677a429b4c8b3bec9ca71b21a4f8bb
Oct 12 07:39:12 pillow erigon[3238747]: [INFO] [10-12|07:39:12.824] [NewPayload] Handling new payload        height=18334091 hash=0x8e91588b71b4e91cb8fc3885550ec47513994b134d15ee6142535a535148d4b3
Oct 12 07:39:24 pillow erigon[3238747]: [INFO] [10-12|07:39:24.646] [NewPayload] Handling new payload        height=18334092 hash=0xf4445eb10203f7e989bc84c1fbd80618e08f4f592564474888853f13d0ea85e3
Oct 12 07:39:37 pillow erigon[3238747]: [INFO] [10-12|07:39:37.820] [NewPayload] Handling new payload        height=18334093 hash=0xe2d289d674e7ebed5b445c46c9a3a31618184a84b244fb24397ce2790c0ddb78
Oct 12 07:39:48 pillow erigon[3238747]: [INFO] [10-12|07:39:48.697] [NewPayload] Handling new payload        height=18334094 hash=0x64ea8897036873c595f3464931973c989352ea61134ac65f407324752517d10e
Oct 12 07:39:59 pillow erigon[3238747]: [INFO] [10-12|07:39:59.641] [NewPayload] Handling new payload        height=18334095 hash=0xc7347a3710be56bf88cf483f2e525b5705007909c369696123ddc56619c52e41
Oct 12 07:40:12 pillow erigon[3238747]: [INFO] [10-12|07:40:12.180] [NewPayload] Handling new payload        height=18334096 hash=0x3b7f31744909fdce464d5568ba281915c5cdb9d39e73ba44ec5bf56832bc74fb
Oct 12 07:40:24 pillow erigon[3238747]: [INFO] [10-12|07:40:24.773] [NewPayload] Handling new payload        height=18334097 hash=0x3d6f086161dfd8ff36271b1d659252e66d90a8766ae24fcd9fb3167d65a498ed
Oct 12 07:40:36 pillow erigon[3238747]: [INFO] [10-12|07:40:36.776] [NewPayload] Handling new payload        height=18334098 hash=0xad45d0075ac7025cc05d1d4f8adb283ca392eeb3e26d5db2f0af3d004de81353
Oct 12 07:40:48 pillow erigon[3238747]: [INFO] [10-12|07:40:48.265] [NewPayload] Handling new payload        height=18334099 hash=0x1cad6868845f3781a9431eb062710492956efbecb67db0464e69a7a85bf38c9a
Oct 12 07:41:01 pillow erigon[3238747]: [INFO] [10-12|07:41:01.027] [NewPayload] Handling new payload        height=18334100 hash=0xd35fcaf627077bd14269f6586b3b225be853a2799c90b835f30d54a509f91803
Oct 12 07:41:13 pillow erigon[3238747]: [INFO] [10-12|07:41:13.099] [NewPayload] Handling new payload        height=18334101 hash=0x674a850d8c37592beb67beb4cdf85bdb07f4ae75e96344ba09e0723d4d49694a

teku:


Oct 12 07:37:59 pillow teku[3236771]: 07:37:59.072 INFO  - Syncing     *** Target slot: 7523888, Head slot: 7523887, Waiting for execution layer sync, Connected peers: 31
Oct 12 07:38:11 pillow teku[3236771]: 07:38:11.067 INFO  - Syncing     *** Target slot: 7523889, Head slot: 7523888, Waiting for execution layer sync, Connected peers: 31
Oct 12 07:38:23 pillow teku[3236771]: 07:38:23.066 INFO  - Syncing     *** Target slot: 7523890, Head slot: 7523889, Waiting for execution layer sync, Connected peers: 29
Oct 12 07:38:35 pillow teku[3236771]: 07:38:35.061 INFO  - Syncing     *** Target slot: 7523891, Head slot: 7523890, Waiting for execution layer sync, Connected peers: 32
Oct 12 07:38:47 pillow teku[3236771]: 07:38:47.075 INFO  - Syncing     *** Target slot: 7523892, Head slot: 7523891, Waiting for execution layer sync, Connected peers: 29
Oct 12 07:38:59 pillow teku[3236771]: 07:38:59.071 INFO  - Syncing     *** Target slot: 7523893, Head slot: 7523892, Waiting for execution layer sync, Connected peers: 27
Oct 12 07:39:11 pillow teku[3236771]: 07:39:11.096 INFO  - Syncing     *** Target slot: 7523894, Head slot: 7523893, Waiting for execution layer sync, Connected peers: 33
Oct 12 07:39:23 pillow teku[3236771]: 07:39:23.068 INFO  - Syncing     *** Target slot: 7523895, Head slot: 7523894, Waiting for execution layer sync, Connected peers: 32
Oct 12 07:39:35 pillow teku[3236771]: 07:39:35.067 INFO  - Syncing     *** Target slot: 7523896, Head slot: 7523895, Waiting for execution layer sync, Connected peers: 32
Oct 12 07:39:47 pillow teku[3236771]: 07:39:47.069 INFO  - Syncing     *** Target slot: 7523897, Head slot: 7523896, Waiting for execution layer sync, Connected peers: 32
Oct 12 07:39:59 pillow teku[3236771]: 07:39:59.062 INFO  - Syncing     *** Target slot: 7523898, Head slot: 7523897, Waiting for execution layer sync, Connected peers: 29
Oct 12 07:40:11 pillow teku[3236771]: 07:40:11.068 INFO  - Syncing     *** Target slot: 7523899, Head slot: 7523898, Waiting for execution layer sync, Connected peers: 37
Oct 12 07:40:23 pillow teku[3236771]: 07:40:23.071 INFO  - Syncing     *** Target slot: 7523900, Head slot: 7523899, Waiting for execution layer sync, Connected peers: 35

The sync should be complete since it's at the chain head.

RatanRSur commented 1 year ago

@michelescippa did you manage to figure out what was going on here? I'm still seeing this

RatanRSur commented 1 year ago

Enabled debug logs to give some more info on why it might be stuck syncing even though it's at head.

Screenshot 2023-10-23 at 5 34 56 PM
jhvst commented 9 months ago

Seeing the same on erigon 2.55.0 and 2.57.0. The node maintains sync for maybe 5-10 minutes before deciding to download single blocks using the EngineBlockDownloader, which is also the point the chain becomes optimistic. The node might catch the tip again and then work fine for another 5-10 minutes before becoming optimistic again.

Any update on possible fix would be welcome!

jhvst commented 9 months ago

This was in fact slow backend disk (RAID0 on two 100k/30k IOPS disks was not enough). Switching from btrfs to LVM xfs fixed this issue.