search

erigontech / erigon

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

Client RPC failed to retrieve ForkChoiceUpdate response, err: unknown ancestor #12594

Open exodus-justinz opened 4 days ago

exodus-justinz commented 4 days ago

System information

Erigon version: ./erigon --version erigon version 2.60.9-501a53b7 OS & Version: Linux

Commit hash: https://github.com/erigontech/erigon/commit/501a53b7aa51a89bbcefc6a50eb44317b4a5a888

Erigon Command (with flags/config):

Consensus Layer:

Consensus Layer Command (with flags/config):

--nat=extip:x.x.x.x --identity=xxxxxx --ethash.dagdir=/home/eth/data/erigon-ethash --torrent.download.slots=10000 --http.corsdomain=* --torrent.download.rate=3000mb --gpo.percentile=65 --txpool.nolocals=true --http.api=admin,eth,net,web3,debug,engine,erigon --rpc.batch.limit=3000 --txpool.disable=true --http.addr=0.0.0.0 --internalcl=true --datadir=/home/eth/data/eth --ws --rpc.batch.concurrency=100 --http.vhosts=*

Chain/Network: Ethereum/Mainnet

Expected behaviour

Erigon syncs normally

Actual behaviour

Erigon starts up with the following logs, but the RPC port won't open

[WARN] [11-04|02:35:52.099] [1/12 Snapshots] Some blocks are not in snapshots and not in db max_in_snapshots=19799999 min_in_db=19900000
[INFO] [11-04|02:35:52.099] [snapshots:download] Stat                blocks=19800k indices=19800k alloc=4.5GB sys=6.5GB
[INFO] [11-04|02:36:43.784] Static peers                             len=0
[INFO] [11-04|02:36:43.786] [Sentinel] Sentinel started              app=caplin enr=enr:-Ly4QEzPv8w4FnGq4Z88Nhx6VMJUek-u1VppoSrm6k_jCsU9QeJPdCnhP7Hs6GCHtPms38kmOAUko_yRpFd0xz43h9sBh2F0dG5ldHOIAAAAAAAAAACEZXRoMpBqlaGpBAAAAAAAAAAAAAAAgmlkgnY0gmlwhH8AAAGJc2VjcDI1NmsxoQMMNdr0E1NNllVhxS2i9PQTR4o4MrcXjMNVlKwoew9zX4hzeW5jbmV0cwCDdGNwgg-hg3VkcIIPoA
[INFO] [11-04|02:36:43.787] Started Ethereum 2.0 Gossip Service      app=caplin
[INFO] [11-04|02:36:43.884] [Gossip] Subscribed to topic             topic=/eth2/6a95a1a9/attester_slashing/ssz_snappy
[INFO] [11-04|02:36:43.885] [Gossip] Subscribed to topic             topic=/eth2/6a95a1a9/blob_sidecar_3/ssz_snappy
[INFO] [11-04|02:36:43.885] [Gossip] Subscribed to topic             topic=/eth2/6a95a1a9/blob_sidecar_4/ssz_snappy
[INFO] [11-04|02:36:43.885] [Gossip] Subscribed to topic             topic=/eth2/6a95a1a9/proposer_slashing/ssz_snappy
[INFO] [11-04|02:36:43.885] [Gossip] Subscribed to topic             topic=/eth2/6a95a1a9/blob_sidecar_5/ssz_snappy
[INFO] [11-04|02:36:43.885] [Gossip] Subscribed to topic             topic=/eth2/6a95a1a9/beacon_block/ssz_snappy
[INFO] [11-04|02:36:43.885] [Gossip] Subscribed to topic             topic=/eth2/6a95a1a9/blob_sidecar_0/ssz_snappy
[INFO] [11-04|02:36:43.885] [Gossip] Subscribed to topic             topic=/eth2/6a95a1a9/beacon_aggregate_and_proof/ssz_snappy
[INFO] [11-04|02:36:43.885] [Gossip] Subscribed to topic             topic=/eth2/6a95a1a9/blob_sidecar_1/ssz_snappy
[INFO] [11-04|02:36:43.885] [Gossip] Subscribed to topic             topic=/eth2/6a95a1a9/blob_sidecar_2/ssz_snappy
[INFO] [11-04|02:36:43.885] [Gossip] Subscribed to topic             topic=/eth2/6a95a1a9/sync_committee_contribution_and_proof/ssz_snappy
[INFO] [11-04|02:36:43.885] [Gossip] Subscribed to topic             topic=/eth2/6a95a1a9/bls_to_execution_change/ssz_snappy
mdbx_meta_unsteady:9961 wipe txn #4, meta 2
[INFO] [11-04|02:37:03.497] [Caplin] starting clstages loop          app=caplin
[INFO] [11-04|02:37:03.498] Starting downloading History             app=caplin stage=DownloadHistoricalBlocks from=10321888
[INFO] [11-04|02:37:06.935] Missing blocks download finished (note: this does not mean that the history is complete, only that the missing blocks need for sync have been downloaded) app=caplin stage=DownloadHistoricalBlocks
[INFO] [11-04|02:37:08.503] Ready to insert history, waiting for sync cycle to finish app=caplin stage=DownloadHistoricalBlocks
[INFO] [11-04|02:37:08.507] [Caplin] Forward Sync                    app=caplin stage=ForwardSync from=10321888 to=10321983
[INFO] [11-04|02:37:41.351] [Caplin] Forward Sync                    app=caplin stage=ForwardSync progress=10321940 distance-from-chain-tip=8m36s estimated-time-remaining=24s
[INFO] [11-04|02:37:43.788] P2P                                      app=caplin peers=25
[WARN] [11-04|02:38:14.660] [engine] CurrentHeader                   err="ethereumExecutionModule.CurrentHeader: no current header yet - probabably node not synced yet"
[WARN] [11-04|02:38:14.666] [engine] CurrentHeader                   err="ethereumExecutionModule.CurrentHeader: no current header yet - probabably node not synced yet"
[WARN] [11-04|02:38:14.671] [engine] CurrentHeader                   err="ethereumExecutionModule.CurrentHeader: no current header yet - probabably node not synced yet"
[WARN] [11-04|02:38:14.675] [engine] CurrentHeader                   err="ethereumExecutionModule.CurrentHeader: no current header yet - probabably node not synced yet"
[WARN] [11-04|02:38:14.681] [engine] CurrentHeader                   err="ethereumExecutionModule.CurrentHeader: no current header yet - probabably node not synced yet"
[WARN] [11-04|02:38:14.685] [engine] CurrentHeader                   err="ethereumExecutionModule.CurrentHeader: no current header yet - probabably node not synced yet"
[WARN] [11-04|02:38:14.689] [engine] CurrentHeader                   err="ethereumExecutionModule.CurrentHeader: no current header yet - probabably node not synced yet"
[WARN] [11-04|02:38:25.790] [engine] CurrentHeader                   err="ethereumExecutionModule.CurrentHeader: no current header yet - probabably node not synced yet"
[WARN] [11-04|02:38:25.955] [engine] CurrentHeader                   err="ethereumExecutionModule.CurrentHeader: no current header yet - probabably node not synced yet"
[WARN] [11-04|02:38:25.963] [engine] CurrentHeader                   err="ethereumExecutionModule.CurrentHeader: no current header yet - probabably node not synced yet"
[WARN] [11-04|02:38:31.548] [engine] CurrentHeader                   err="ethereumExecutionModule.CurrentHeader: no current header yet - probabably node not synced yet"
[WARN] [11-04|02:38:36.829] [engine] CurrentHeader                   err="ethereumExecutionModule.CurrentHeader: no current header yet - probabably node not synced yet"
[INFO] [11-04|02:38:37.154] [p2p] GoodPeers                          eth68=2
[WARN] [11-04|02:38:37.613] Could not set forkchoice                 app=caplin stage=ForkChoice err="execution Client RPC failed to retrieve ForkChoiceUpdate response, err: unknown ancestor"
[WARN] [11-04|02:38:37.613] error executing clstage                  app=caplin stage=ForkChoice err="execution Client RPC failed to retrieve ForkChoiceUpdate response, err: unknown ancestor"
[INFO] [11-04|02:38:37.739] [mem] memory stats                       Rss=11.6GB Size=0B Pss=11.6GB SharedClean=2.8MB SharedDirty=0B PrivateClean=727.8MB PrivateDirty=10.9GB Referenced=11.6GB Anonymous=10.9GB Swap=0B alloc=6.0GB sys=11.0GB
[INFO] [11-04|02:38:43.788] P2P                                      app=caplin peers=49
[WARN] [11-04|02:38:50.845] [engine] CurrentHeader                   err="ethereumExecutionModule.CurrentHeader: no current header yet - probabably node not synced yet"
[WARN] [11-04|02:38:54.917] Could not set forkchoice                 app=caplin stage=ForkChoice err="execution Client RPC failed to retrieve ForkChoiceUpdate response, err: unknown ancestor"

And eventually it would loop with

[WARN] [11-04|02:44:26.761] Could not set forkchoice                 app=caplin stage=ForkChoice err="execution Client RPC failed to retrieve ForkChoiceUpdate response, err: unknown ancestor"
[WARN] [11-04|02:44:26.761] error executing clstage                  app=caplin stage=ForkChoice err="execution Client RPC failed to retrieve ForkChoiceUpdate response, err: unknown ancestor"
[WARN] [11-04|02:44:36.593] [engine] CurrentHeader                   err="ethereumExecutionModule.CurrentHeader: no current header yet - probabably node not synced yet"

Steps to reproduce the behaviour

Backtrace

[backtrace]
AskAlexSharov commented 4 days ago

Some blocks are not in snapshots and not in db max_in_snapshots=19799999 min_in_db=19900000 try integration stage_headers --reset

exodus-justinz commented 2 days ago

Some blocks are not in snapshots and not in db max_in_snapshots=19799999 min_in_db=19900000 try integration stage_headers --reset

we stopped erigon and run this command and here's the output

INFO[11-04|23:42:42.190] logging to file system                   log dir=/home/eth/data/eth/logs file prefix=integration log level=info json=false
INFO[11-04|23:42:42.196] [db] open                                label=chaindata sizeLimit=12TB pageSize=8192
INFO[11-04|23:42:46.683] [snapshots:all] Stat                     blocks=19800k indices=19800k alloc=2.9GB sys=3.0GB
INFO[11-04|23:42:46.690] [snapshots:all] Stat                     blocks=0k indices=0k alloc=2.9GB sys=3.0GB
INFO[11-04|23:42:46.897] Disk storage enabled for ethash DAGs     dir=/home/eth/.local/share/erigon-ethash count=2
INFO[11-04|23:43:43.089] Clear                                    table=NonCanonicalTransaction
INFO[11-04|23:43:43.090] Clear                                    table=BlockTransaction
INFO[11-04|23:43:43.090] Clear                                    table=MaxTxNum
INFO[11-04|23:44:13.091] [filling_db_from_snapshots] Total difficulty index: 2227k/19799k
INFO[11-04|23:44:43.090] [filling_db_from_snapshots] Total difficulty index: 3732k/19799k
INFO[11-04|23:45:13.090] [filling_db_from_snapshots] Total difficulty index: 6315k/19799k
INFO[11-04|23:45:43.014] [mem] memory stats                       Rss=12.1GB Size=0B Pss=12.1GB SharedClean=2.7MB SharedDirty=0B PrivateClean=5.5GB PrivateDirty=6.6GB Referenced=12.1GB Anonymous=6.6GB Swap=0B alloc=5.4GB sys=5.8GB
INFO[11-04|23:45:43.091] [filling_db_from_snapshots] Total difficulty index: 7807k/19799k
INFO[11-04|23:46:13.091] [filling_db_from_snapshots] Total difficulty index: 10662k/19799k
INFO[11-04|23:46:43.091] [filling_db_from_snapshots] Total difficulty index: 12381k/19799k
INFO[11-04|23:47:20.560] [filling_db_from_snapshots] Total difficulty index: 14913k/19799k
INFO[11-04|23:47:43.090] [filling_db_from_snapshots] Total difficulty index: 17035k/19799k
INFO[11-04|23:48:13.091] [filling_db_from_snapshots] Total difficulty index: 18722k/19799k
INFO[11-04|23:48:44.995] [mem] memory stats                       Rss=21.2GB Size=0B Pss=21.2GB SharedClean=2.7MB SharedDirty=0B PrivateClean=13.1GB PrivateDirty=8.1GB Referenced=21.2GB Anonymous=7.9GB Swap=0B alloc=4.0GB sys=5.8GB

we started erigon, and it has been downloading past blocks for more than 24h+ now. do you know how long it should take?

[INFO] [11-05|23:53:02.080] Node is still syncing... downloading past blocks app=caplin stage=DownloadHistoricalBlocks slot=9905496 blockNumber=20696885 blk/sec=6.8 snapshots=0
[INFO] [11-05|23:53:32.081] Node is still syncing... downloading past blocks app=caplin stage=DownloadHistoricalBlocks slot=9905374 blockNumber=20696763 blk/sec=4.1 snapshots=0