erigon
erigon copied to clipboard
Published
20 hours ago •
erigontech
erigontech
Erigon fails to start with "runtime error: index out of range"
System information
Erigon version: 2022.08.2-alpha-35c4faa1
OS & Version: Ubuntu Linux 22.04
Commit hash : 35c4faa1b
Actual behaviour
I had a synced, working erigon node but today it is failing to start. It breaks with a catch panic saying runtime error: index out of range [15200000] with length 15200000
It was working ok. The only thing that changed is that I updated lighthouse and connected it via the engine API. Not sure if it's related because now even without lighthouse it will not start up.
$erigon --datadir ... --http --http.api eth,net,web3 --authrpc.jwtsecret ... --port ... --http.port ... --authrpc.port ... --prune htc --prune.r.before=11184524
INFO[08-22|11:32:41.331] Build info git_branch=HEAD git_tag=v2022.08.02 git_commit=35c4faa1b41e8379a74d0385505add0dd450c2ed
INFO[08-22|11:32:41.332] Starting Erigon on Ethereum mainnet...
INFO[08-22|11:32:41.332] Maximum peer count ETH=100 total=100
INFO[08-22|11:32:41.332] starting HTTP APIs APIs=eth,net,web3
INFO[08-22|11:32:41.333] torrent verbosity level=WRN
INFO[08-22|11:32:43.433] Set global gas cap cap=50000000
INFO[08-22|11:32:43.470] Opening Database label=chaindata path=.../.erigon/chaindata
INFO[08-22|11:32:43.472] Initialised chain configuration config="{ChainID: 1, Homestead: 1150000, DAO: 1920000, DAO Support: true, Tangerine Whistle: 2463000, Spurious Dragon: 2675000, Byzantium: 4370000, Constantinople: 7280000, Petersburg: 7280000, Istanbul: 9069000, Muir Glacier: 9200000, Berlin: 12244000, London: 12965000, Arrow Glacier: 13773000, Gray Glacier: 15050000, Terminal Total Difficulty: 58750000000000000000000, Merge Netsplit: <nil>, Engine: ethash}" genesis=0xd4e56740f876aef8c010b86a40d5f56745a118d0906a34e69aec8c0db1cb8fa3
INFO[08-22|11:32:43.472] Effective prune_flags="--prune.h.older=90000 --prune.t.older=90000 --prune.c.older=90000 --prune.r.before=11184524" snapshot_flags="--snapshots=true" history.v2=false
INFO[08-22|11:32:46.759] Initialising Ethereum protocol network=1
INFO[08-22|11:32:46.759] Disk storage enabled for ethash DAGs dir=.../.erigon/ethash-dags count=2
INFO[08-22|11:32:47.092] Starting private RPC server on=127.0.0.1:9090
INFO[08-22|11:32:47.092] rpc filters: subscribing to Erigon events
INFO[08-22|11:32:47.092] new subscription to logs established
INFO[08-22|11:32:47.092] New txs subscriber joined
INFO[08-22|11:32:47.092] new subscription to newHeaders established
INFO[08-22|11:32:47.855] [txpool] Started
EROR[08-22|11:32:58.940] catch panic err="runtime error: index out of range [15200000] with length 15200000" stack="[main.go:29 panic.go:838 panic.go:93 config.go:246 block_snapshots.go:186 config.go:245 block_snapshots.go:286 config.go:243 backend.go:572 node.go:115 main.go:58 app.go:526 app.go:286 main.go:34 proc.go:250 asm_amd64.s:1571]"
I went into the snapshots folder and removed some files with this wildcard v1-0152*. It started ok and went into fetching snapshots and doing all the stages. So far it seems ok except for this line in the logs that caught my attention:
Staged Sync err="[5/16 Senders] retireBlocksInSingleBackgroundThread: [5/16 Senders Prune] retire blocks last error: DumpBlocks: DumpHeaders: header missed in db: block_num=15200000, hash=23de0c44879d947b518415832ecae537d690d257782b27cfa4e4790131943cd0, fromBlock=15200000, toBlock=15300000"
These are the whole logs so far:
INFO[08-22|14:48:15.048] Build info git_branch=HEAD git_tag=v2022.08.02 git_commit=35c4faa1b41e8379a74d0385505add0dd450c2ed
INFO[08-22|14:48:15.048] Starting Erigon on Ethereum mainnet...
INFO[08-22|14:48:15.049] Maximum peer count ETH=100 total=100
INFO[08-22|14:48:15.049] starting HTTP APIs APIs=eth,net,web3
INFO[08-22|14:48:15.049] torrent verbosity level=WRN
INFO[08-22|14:48:17.150] Set global gas cap cap=50000000
INFO[08-22|14:48:17.225] Opening Database label=chaindata path=/home/martin/.erigon/chaindata
INFO[08-22|14:48:17.227] Initialised chain configuration config="{ChainID: 1, Homestead: 1150000, DAO: 1920000, DAO Support: true, Tangerine Whistle: 2463000, Spurious Dragon: 2675000, Byzantium: 4370000, Constantinople: 7280000, Petersburg: 7280000, Istanbul: 9069000, Muir Glacier: 9200000, Berlin: 12244000, London: 12965000, Arrow Glacier: 13773000, Gray Glacier: 15050000, Terminal Total Difficulty: 58750000000000000000000, Merge Netsplit: <nil>, Engine: ethash}" genesis=0xd4e56740f876aef8c010b86a40d5f56745a118d0906a34e69aec8c0db1cb8fa3
INFO[08-22|14:48:17.227] Effective prune_flags="--prune.h.older=90000 --prune.t.older=90000 --prune.c.older=90000 --prune.r.before=11184524" snapshot_flags="--snapshots=true" history.v2=false
INFO[08-22|14:48:20.281] Initialising Ethereum protocol network=1
INFO[08-22|14:48:20.281] Disk storage enabled for ethash DAGs dir=/home/martin/.erigon/ethash-dags count=2
INFO[08-22|14:48:20.630] Starting private RPC server on=127.0.0.1:9090
INFO[08-22|14:48:20.631] rpc filters: subscribing to Erigon events
INFO[08-22|14:48:20.631] new subscription to logs established
INFO[08-22|14:48:20.631] New txs subscriber joined
INFO[08-22|14:48:20.631] new subscription to newHeaders established
INFO[08-22|14:48:21.556] [txpool] Started
INFO[08-22|14:48:32.240] Reading JWT secret path=/var/lib/ethereum/jwttoken
INFO[08-22|14:48:32.240] HTTP endpoint opened for Engine API url=localhost:8552 ws=true ws.compression=true
INFO[08-22|14:48:32.240] HTTP endpoint opened url=localhost:8546 ws=false ws.compression=true grpc=false
INFO[08-22|14:48:32.252] [Snapshots] Fetching torrent files metadata
INFO[08-22|14:48:32.252] Started P2P networking version=66 self=enode://8bfa455f8bdb500d75a9671a99b5f6b2ac98e9b2563cbfb8964235b17ece6d822f7404333e5f6c2d63d93486f5afa949acc5e3864dc989ad4d4b9f2e2e502b0d@127.0.0.1:30304 name=erigon/v2022.08.2-alpha-35c4faa1/linux-amd64/go1.18.1
INFO[08-22|14:48:32.254] [Snapshots] Stat blocks=15200k indices=15200k alloc=3.5GB sys=4.7GB
INFO[08-22|14:48:32.254] [1/16 Headers] Waiting for headers... from=15390627
INFO[08-22|14:48:52.258] [1/16 Headers] Inserting headers progress=15391347 queue=1
INFO[08-22|14:48:52.862] Generating ethash verification cache epoch=514 percentage=98 elapsed=3.000s
INFO[08-22|14:48:53.515] Estimated to reaching TTD blocks=150465
INFO[08-22|14:49:00.997] Estimated to reaching TTD blocks=150462
INFO[08-22|14:49:01.018] [1/16 Headers] Processed highest inserted=15391689 age=22s
INFO[08-22|14:49:01.353] [4/16 Bodies] Processing bodies... from=15390627 to=15391689
INFO[08-22|14:49:10.390] [4/16 Bodies] Processed highest=15391689
INFO[08-22|14:49:10.391] [5/16 Senders] Started from=15390627 to=15391689
INFO[08-22|14:49:12.908] [6/16 Execution] Blocks execution from=15390627 to=15391689
INFO[08-22|14:49:20.631] [txpool] stat block=15390627 pending=922 baseFee=27101 queued=21665 alloc=3.1GB sys=4.9GB
INFO[08-22|14:49:32.911] [6/16 Execution] Executed blocks number=15390804 blk/s=8.8 tx/s=1569.0 Mgas/s=133.5 gasState=0.00 estimated duration=2m2.867s batch=4.6MB alloc=3.8GB sys=4.9GB
INFO[08-22|14:49:53.036] [6/16 Execution] Executed blocks number=15391037 blk/s=11.6 tx/s=2044.6 Mgas/s=180.4 gasState=0.01 estimated duration=1m44.473s batch=11.5MB alloc=2.6GB sys=5.4GB
INFO[08-22|14:50:12.913] [6/16 Execution] Executed blocks number=15391333 blk/s=14.9 tx/s=2562.5 Mgas/s=233.9 gasState=0.02 estimated duration=1m29.893s batch=19.2MB alloc=4.2GB sys=5.5GB
INFO[08-22|14:50:20.285] [p2p] GoodPeers eth66=1
INFO[08-22|14:50:20.637] [txpool] stat block=15390627 pending=922 baseFee=27279 queued=21682 alloc=2.8GB sys=5.5GB
INFO[08-22|14:50:32.993] [6/16 Execution] Executed blocks number=15391618 blk/s=14.2 tx/s=2471.1 Mgas/s=219.1 gasState=0.03 estimated duration=1m25.588s batch=27.6MB alloc=3.6GB sys=5.5GB
INFO[08-22|14:50:43.238] [6/16 Execution] Completed on block=15391689
INFO[08-22|14:50:43.238] [6/16 Execution] DONE in=1m30.329977323s
INFO[08-22|14:50:43.239] [8/16 HashState] Promoting plain state from=15390627 to=15391689
INFO[08-22|14:50:43.239] [8/16 HashState] Incremental promotion from=15390627 to=15391689 codes=true csbucket=AccountChangeSet
INFO[08-22|14:50:47.941] [8/16 HashState] Incremental promotion from=15390627 to=15391689 codes=false csbucket=AccountChangeSet
INFO[08-22|14:51:04.622] [8/16 HashState] Incremental promotion from=15390627 to=15391689 codes=false csbucket=StorageChangeSet
INFO[08-22|14:51:20.631] [txpool] stat block=15390627 pending=1351 baseFee=30000 queued=22185 alloc=2.7GB sys=5.6GB
INFO[08-22|14:51:33.789] [9/16 IntermediateHashes] Generating intermediate hashes from=15390627 to=15391689
INFO[08-22|14:52:05.781] [9/16 IntermediateHashes] Calculating Merkle root current key=836e8464...
INFO[08-22|14:52:20.282] [p2p] GoodPeers eth66=3
INFO[08-22|14:52:20.639] [txpool] stat block=15390627 pending=1735 baseFee=30000 queued=22409 alloc=4.4GB sys=6.3GB
INFO[08-22|14:52:35.781] [9/16 IntermediateHashes] Calculating Merkle root current key=f73ff706...
INFO[08-22|14:52:57.779] [9/16 IntermediateHashes] DONE in=1m23.991724251s
INFO[08-22|14:52:58.676] [10/16 CallTraces] Pruned call trace intermediate table from=15300627 to=15301688
INFO[08-22|14:53:20.631] [txpool] stat block=15390627 pending=2188 baseFee=30000 queued=22739 alloc=3.6GB sys=6.6GB
INFO[08-22|14:53:45.555] [13/16 LogIndex] processing from=15390628 to=15391689
INFO[08-22|14:54:20.282] [p2p] GoodPeers eth66=5
INFO[08-22|14:54:20.638] [txpool] stat block=15390627 pending=2615 baseFee=30000 queued=23153 alloc=2.6GB sys=6.6GB
INFO[08-22|14:54:48.283] Timings (slower than 50ms) Headers=28.767s BlockHashes=320ms Bodies=9.037s Senders=2.517s Execution=1m30.329s HashState=50.549s IntermediateHashes=1m23.991s CallTraces=16.949s AccountHistoryIndex=11.518s StorageHistoryIndex=19.307s LogIndex=18.892s TxLookup=19.046s Prune TxLookup=15.415s Prune StorageHistoryIndex=2.612s Prune AccountHistoryIndex=6.685s Prune Execution=68ms
INFO[08-22|14:54:48.284] [snapshots] Retire Blocks range=15200k-15300k
INFO[08-22|14:54:48.294] RPC Daemon notified of new headers from=15390665 to=15391689 header sending=10.705463ms log sending=500ns
INFO[08-22|14:54:48.295] [1/16 Headers] Waiting for headers... from=15391689
INFO[08-22|14:54:48.691] Estimated to reaching TTD blocks=150866
INFO[08-22|14:54:48.692] [1/16 Headers] Processed highest inserted=15391703 age=2m18s
INFO[08-22|14:54:52.769] [6/16 Execution] Completed on block=15391703
EROR[08-22|14:54:57.896] Staged Sync err="[5/16 Senders] retireBlocksInSingleBackgroundThread: [5/16 Senders Prune] retire blocks last error: DumpBlocks: DumpHeaders: header missed in db: block_num=15200000, hash=23de0c44879d947b518415832ecae537d690d257782b27cfa4e4790131943cd0, fromBlock=15200000, toBlock=15300000"
INFO[08-22|14:54:59.348] Commit cycle in=22.215µs
INFO[08-22|14:54:59.349] RPC Daemon notified of new headers from=15391689 to=15391690 header sending=16.499µs log sending=1.074µs
INFO[08-22|14:54:59.349] [1/16 Headers] Waiting for headers... from=15391689
INFO[08-22|14:54:59.350] [snapshots] Retire Blocks range=15200k-15300k
INFO[08-22|14:55:20.633] [txpool] stat block=15390627 pending=3106 baseFee=30000 queued=23553 alloc=3.8GB sys=6.6GB
INFO[08-22|14:56:20.282] [p2p] GoodPeers eth66=7
INFO[08-22|14:56:20.638] [txpool] stat block=15390627 pending=4939 baseFee=30000 queued=24038 alloc=2.5GB sys=6.6GB
INFO[08-22|14:56:39.349] Req/resp stats req=0 reqMin=0 reqMax=0 skel=17 skelMin=15393225 skelMax=15687945 resp=22 respMin=15391719 respMax=15391721 dups=4
INFO[08-22|14:56:39.349] Queue sizes anchors=0 links=18 persisted=65536
INFO[08-22|14:56:59.350] Req/resp stats req=0 reqMin=0 reqMax=0 skel=15 skelMin=15393225 skelMax=15687945 resp=24 respMin=15391721 respMax=15391721 dups=2
INFO[08-22|14:56:59.350] Queue sizes anchors=0 links=18 persisted=65536
INFO[08-22|14:57:19.350] Req/resp stats req=0 reqMin=0 reqMax=0 skel=15 skelMin=15393225 skelMax=15687945 resp=42 respMin=15391722 respMax=15391723 dups=4
INFO[08-22|14:57:19.350] Queue sizes anchors=0 links=20 persisted=65536
INFO[08-22|14:57:20.634] [txpool] stat block=15390627 pending=5565 baseFee=30000 queued=24803 alloc=2.8GB sys=6.6GB
INFO[08-22|14:57:39.349] Req/resp stats req=0 reqMin=0 reqMax=0 skel=16 skelMin=15393225 skelMax=15687945 resp=40 respMin=0 respMax=0 dups=0
INFO[08-22|14:57:39.349] Queue sizes anchors=0 links=20 persisted=65536
INFO[08-22|14:57:59.350] Req/resp stats req=0 reqMin=0 reqMax=0 skel=16 skelMin=15393225 skelMax=15687945 resp=44 respMin=15391724 respMax=15391725 dups=6
INFO[08-22|14:57:59.350] Queue sizes anchors=0 links=22 persisted=65536
INFO[08-22|14:58:19.349] Req/resp stats req=0 reqMin=0 reqMax=0 skel=14 skelMin=15393225 skelMax=15687945 resp=35 respMin=15391726 respMax=15391728 dups=6
INFO[08-22|14:58:19.350] Queue sizes anchors=0 links=25 persisted=65536
INFO[08-22|14:58:20.283] [p2p] GoodPeers eth66=12
INFO[08-22|14:58:25.279] [txpool] stat block=15390627 pending=6091 baseFee=30000 queued=28707 alloc=2.6GB sys=6.6GB
INFO[08-22|14:58:39.350] Req/resp stats req=0 reqMin=0 reqMax=0 skel=15 skelMin=15393225 skelMax=15687945 resp=39 respMin=15391725 respMax=15391725 dups=1
INFO[08-22|14:58:39.350] Queue sizes anchors=0 links=25 persisted=65536
INFO[08-22|14:58:59.349] Req/resp stats req=0 reqMin=0 reqMax=0 skel=15 skelMin=15393225 skelMax=15687945 resp=40 respMin=15391729 respMax=15391730 dups=8
INFO[08-22|14:58:59.349] Queue sizes anchors=0 links=27 persisted=65536
INFO[08-22|14:59:19.349] Req/resp stats req=0 reqMin=0 reqMax=0 skel=15 skelMin=15393225 skelMax=15687945 resp=37 respMin=15391731 respMax=15391732 dups=4
INFO[08-22|14:59:19.349] Queue sizes anchors=0 links=29 persisted=65536
INFO[08-22|14:59:20.633] [txpool] stat block=15390627 pending=6611 baseFee=30000 queued=29092 alloc=2.8GB sys=6.6GB
Did it continue syncing with no problem after that?
When you get an issue of index out of range as such please try running --downloader.verify
It seems to work fine but there is this repeated line that wasnt there before:
err="[5/16 Senders] retireBlocksInSingleBackgroundThread: [5/16 Senders Prune] retire blocks last error: DumpBlocks: DumpHeaders: header missed in db: block_num=15200000, hash=23de0c44879d947b518415832ecae537d690d257782b27cfa4e4790131943cd0, fromBlock=15200000, toBlock=15300000"
[INFO] [08-22|18:57:46.536] RPC Daemon notified of new headers from=15392778 to=15392779 header sending=28.968µs log sending=1.029µs
[INFO] [08-22|18:57:46.536] [snapshots] Retire Blocks range=15200k-15300k
[INFO] [08-22|18:57:46.536] [1/16 Headers] Waiting for headers... from=15392778
[INFO] [08-22|18:58:08.306] [p2p] GoodPeers eth66=1
[INFO] [08-22|18:58:08.333] Estimated to reaching TTD blocks=150211
[INFO] [08-22|18:58:08.333] [1/16 Headers] Processed highest inserted=15392782 age=27s
[INFO] [08-22|18:58:08.712] [txpool] stat block=15392717 pending=1239 baseFee=30000 queued=18557 alloc=3.2GB sys=5.2GB
[INFO] [08-22|18:58:09.464] [6/16 Execution] Completed on block=15392782
[EROR] [08-22|18:58:10.237] Staged Sync err="[5/16 Senders] retireBlocksInSingleBackgroundThread: [5/16 Senders Prune] retire blocks last error: DumpBlocks: DumpHeaders: header missed in db: block_num=15200000, hash=23de0c44879d947b518415832ecae537d690d257782b27cfa4e4790131943cd0, fromBlock=15200000, toBlock=15300000"
[INFO] [08-22|18:58:11.085] Commit cycle in=8.876µs
[INFO] [08-22|18:58:11.085] RPC Daemon notified of new headers from=15392778 to=15392779 header sending=9.867µs log sending=491ns
[INFO] [08-22|18:58:11.085] [snapshots] Retire Blocks range=15200k-15300k
[INFO] [08-22|18:58:11.085] [1/16 Headers] Waiting for headers... from=15392778
[INFO] [08-22|18:58:14.858] Estimated to reaching TTD blocks=150282
[INFO] [08-22|18:58:14.858] [1/16 Headers] Processed highest inserted=15392783 age=10s
[INFO] [08-22|18:58:15.837] [6/16 Execution] Completed on block=15392783
[EROR] [08-22|18:58:16.300] Staged Sync err="[5/16 Senders] retireBlocksInSingleBackgroundThread: [5/16 Senders Prune] retire blocks last error: DumpBlocks: DumpHeaders: header missed in db: block_num=15200000, hash=23de0c44879d947b518415832ecae537d690d257782b27cfa4e4790131943cd0, fromBlock=15200000, toBlock=15300000"
[INFO] [08-22|18:58:17.088] Commit cycle in=31.178µs
[INFO] [08-22|18:58:17.088] RPC Daemon notified of new headers from=15392778 to=15392779 header sending=22.55µs log sending=1.073µs
[INFO] [08-22|18:58:17.088] [snapshots] Retire Blocks range=15200k-15300k
[INFO] [08-22|18:58:17.088] [1/16 Headers] Waiting for headers... from=15392778
[INFO] [08-22|18:58:28.173] Estimated to reaching TTD blocks=150276
[INFO] [08-22|18:58:28.173] [1/16 Headers] Processed highest inserted=15392785 age=2s
[INFO] [08-22|18:58:29.267] [6/16 Execution] Completed on block=15392785
[EROR] [08-22|18:58:30.090] Staged Sync err="[5/16 Senders] retireBlocksInSingleBackgroundThread: [5/16 Senders Prune] retire blocks last error: DumpBlocks: DumpHeaders: header missed in db: block_num=15200000, hash=23de0c44879d947b518415832ecae537d690d257782b27cfa4e4790131943cd0, fromBlock=15200000, toBlock=15300000"
Then it stabilizes into a bunch of lines like this:
[INFO] [08-22|19:01:09.110] [txpool] stat block=15392717 pending=1238 baseFee=30000 queued=18616 alloc=3.7GB sys=5.2GB
[INFO] [08-22|19:02:06.431] Req/resp stats req=0 reqMin=0 reqMax=0 skel=16 skelMin=15394314 skelMax=15689034 resp=14 respMin=15392794 respMax=15392794 dups=0
[INFO] [08-22|19:02:06.431] Queue sizes anchors=0 links=3 persisted=65536
[INFO] [08-22|19:02:08.306] [p2p] GoodPeers eth66=1
[INFO] [08-22|19:02:08.715] [txpool] stat block=15392717 pending=1237 baseFee=30000 queued=18627 alloc=2.6GB sys=5.2GB
[INFO] [08-22|19:02:26.431] Req/resp stats req=0 reqMin=0 reqMax=0 skel=15 skelMin=15394314 skelMax=15689034 resp=36 respMin=15392795 respMax=15392795 dups=1
[INFO] [08-22|19:02:26.431] Queue sizes anchors=0 links=4 persisted=65536
[INFO] [08-22|19:02:46.432] Req/resp stats req=0 reqMin=0 reqMax=0 skel=14 skelMin=15394314 skelMax=15689034 resp=38 respMin=15392796 respMax=15392796 dups=2
[INFO] [08-22|19:02:46.432] Queue sizes anchors=0 links=5 persisted=65536
[INFO] [08-22|19:03:06.431] Req/resp stats req=0 reqMin=0 reqMax=0 skel=14 skelMin=15394314 skelMax=15689034 resp=36 respMin=15392797 respMax=15392798 dups=2
[INFO] [08-22|19:03:06.431] Queue sizes anchors=0 links=7 persisted=65536
[INFO] [08-22|19:03:08.701] [txpool] stat block=15392717 pending=1345 baseFee=30000 queued=19036 alloc=2.8GB sys=5.2GB
[INFO] [08-22|19:03:26.431] Req/resp stats req=0 reqMin=0 reqMax=0 skel=16 skelMin=15394314 skelMax=15689034 resp=37 respMin=15392798 respMax=15392798 dups=1
[INFO] [08-22|19:03:26.431] Queue sizes anchors=0 links=7 persisted=65536
[INFO] [08-22|19:03:46.431] Req/resp stats req=0 reqMin=0 reqMax=0 skel=15 skelMin=15394314 skelMax=15689034 resp=37 respMin=15392799 respMax=15392800 dups=1
[INFO] [08-22|19:03:46.432] Queue sizes anchors=0 links=9 persisted=65536
[INFO] [08-22|19:04:06.432] Req/resp stats req=0 reqMin=0 reqMax=0 skel=16 skelMin=15394314 skelMax=15689034 resp=29 respMin=15392800 respMax=15392801 dups=2
[INFO] [08-22|19:04:06.432] Queue sizes anchors=0 links=10 persisted=65536
[INFO] [08-22|19:04:08.306] [p2p] GoodPeers eth66=5
[INFO] [08-22|19:04:08.709] [txpool] stat block=15392717 pending=1612 baseFee=30000 queued=19337 alloc=2.7GB sys=5.2GB
[INFO] [08-22|19:04:26.432] Req/resp stats req=0 reqMin=0 reqMax=0 skel=14 skelMin=15394314 skelMax=15689034 resp=41 respMin=15392802 respMax=153
And the beacon node (lighthouse) does not complain and says Ready for the merge so that's good.
@enriavil1 Is there a way to make Erigon more robust in this case? If there is a index out of range exception, it could redownload whatever file that was or automatically verify, without crashing?
- Yes, erigon must not panic in this case, must return error. And likely it’s a bug.
- Erigon can download Only snapshots from whitelist (old one), all other snapshots Erigon creating locally by moving data from DB to snapshots. It means if remove recent snapshots - Erigon can’t re-create them - because it does not have such data in db. Automatic detect/re-download/re-execute some blocks in the middle of history is complex feature which likely we will not have in near future. If manually delete some block from DB - Erigon also will not recover it.
- Erigon already auto-re-download whitelisted snapshots if they are missed. Also flag —downloader.verify can force re-check and download if part of whitelisted snapshot is corrupted.
- now you can force re-download lost blocks by “integration stage_headers —reset” - but in future we will have more data in snapshots and this hack will not help.
- Automatic detect such cases - yes, doable on erigon startup. Just need compare first record in db and max available snapshot. Need add it.
One question, my logs are mainly looking like this:
[INFO] [08-23|12:01:53.363] Req/resp stats req=0 reqMin=0 reqMax=0 skel=13 skelMin=15396214 skelMax=15690934 resp=17 respMin=15396214 respMax=15397294 dups=16
[INFO] [08-23|12:01:53.363] Queue sizes anchors=0 links=2729 persisted=65536
[INFO] [08-23|12:01:58.343] [p2p] GoodPeers eth66=33
[INFO] [08-23|12:02:00.376] [txpool] stat block=15392778 pending=10000 baseFee=30000 queued=30000 alloc=3.6GB sys=6.4GB
[INFO] [08-23|12:02:13.363] Req/resp stats req=0 reqMin=0 reqMax=0 skel=17 skelMin=15396214 skelMax=15690934 resp=51 respMin=15396214 respMax=15397295 dups=41
[INFO] [08-23|12:02:13.363] Queue sizes anchors=0 links=2730 persisted=65536
[INFO] [08-23|12:02:33.363] Req/resp stats req=0 reqMin=0 reqMax=0 skel=15 skelMin=15396214 skelMax=15690934 resp=15 respMin=15396214 respMax=15396214 dups=15
[INFO] [08-23|12:02:33.363] Queue sizes anchors=0 links=2730 persisted=65536
[INFO] [08-23|12:02:53.362] Req/resp stats req=0 reqMin=0 reqMax=0 skel=14 skelMin=15396214 skelMax=15690934 resp=19 respMin=15396214 respMax=15397297 dups=15
[INFO] [08-23|12:02:53.363] Queue sizes anchors=0 links=2732 persisted=65536
[INFO] [08-23|12:03:00.829] [txpool] stat block=15392778 pending=10000 baseFee=30000 queued=30000 alloc=3.3GB sys=6.4GB
[INFO] [08-23|12:03:13.363] Req/resp stats req=0 reqMin=0 reqMax=0 skel=14 skelMin=15396214 skelMax=15690934 resp=39 respMin=15396214 respMax=15397299 dups=34
[INFO] [08-23|12:03:13.363] Queue sizes anchors=0 links=2734 persisted=65536
[INFO] [08-23|12:03:33.363] Req/resp stats req=0 reqMin=0 reqMax=0 skel=16 skelMin=15396214 skelMax=15690934 resp=34 respMin=15396214 respMax=15397302 dups=31
[INFO] [08-23|12:03:33.363] Queue sizes anchors=0 links=2737 persisted=65536
[INFO] [08-23|12:03:53.363] Req/resp stats req=0 reqMin=0 reqMax=0 skel=15 skelMin=15396214 skelMax=15690934 resp=15 respMin=15396214 respMax=15396214 dups=15
[INFO] [08-23|12:03:53.363] Queue sizes anchors=0 links=2737 persisted=65536
[INFO] [08-23|12:03:58.343] [p2p] GoodPeers eth66=33
[INFO] [08-23|12:04:00.379] [txpool] stat block=15392778 pending=10000 baseFee=30000 queued=30000 alloc=3.7GB sys=6.4GB
[INFO] [08-23|12:04:13.363] Req/resp stats req=0 reqMin=0 reqMax=0 skel=15 skelMin=15396214 skelMax=15690934 resp=29 respMin=15396214 respMax=15397305 dups=24
Does this look like a healthy output?
One question, my logs are mainly looking like this:
[INFO] [08-23|12:01:53.363] Req/resp stats req=0 reqMin=0 reqMax=0 skel=13 skelMin=15396214 skelMax=15690934 resp=17 respMin=15396214 respMax=15397294 dups=16 [INFO] [08-23|12:01:53.363] Queue sizes anchors=0 links=2729 persisted=65536 [INFO] [08-23|12:01:58.343] [p2p] GoodPeers eth66=33 [INFO] [08-23|12:02:00.376] [txpool] stat block=15392778 pending=10000 baseFee=30000 queued=30000 alloc=3.6GB sys=6.4GB [INFO] [08-23|12:02:13.363] Req/resp stats req=0 reqMin=0 reqMax=0 skel=17 skelMin=15396214 skelMax=15690934 resp=51 respMin=15396214 respMax=15397295 dups=41 [INFO] [08-23|12:02:13.363] Queue sizes anchors=0 links=2730 persisted=65536 [INFO] [08-23|12:02:33.363] Req/resp stats req=0 reqMin=0 reqMax=0 skel=15 skelMin=15396214 skelMax=15690934 resp=15 respMin=15396214 respMax=15396214 dups=15 [INFO] [08-23|12:02:33.363] Queue sizes anchors=0 links=2730 persisted=65536 [INFO] [08-23|12:02:53.362] Req/resp stats req=0 reqMin=0 reqMax=0 skel=14 skelMin=15396214 skelMax=15690934 resp=19 respMin=15396214 respMax=15397297 dups=15 [INFO] [08-23|12:02:53.363] Queue sizes anchors=0 links=2732 persisted=65536 [INFO] [08-23|12:03:00.829] [txpool] stat block=15392778 pending=10000 baseFee=30000 queued=30000 alloc=3.3GB sys=6.4GB [INFO] [08-23|12:03:13.363] Req/resp stats req=0 reqMin=0 reqMax=0 skel=14 skelMin=15396214 skelMax=15690934 resp=39 respMin=15396214 respMax=15397299 dups=34 [INFO] [08-23|12:03:13.363] Queue sizes anchors=0 links=2734 persisted=65536 [INFO] [08-23|12:03:33.363] Req/resp stats req=0 reqMin=0 reqMax=0 skel=16 skelMin=15396214 skelMax=15690934 resp=34 respMin=15396214 respMax=15397302 dups=31 [INFO] [08-23|12:03:33.363] Queue sizes anchors=0 links=2737 persisted=65536 [INFO] [08-23|12:03:53.363] Req/resp stats req=0 reqMin=0 reqMax=0 skel=15 skelMin=15396214 skelMax=15690934 resp=15 respMin=15396214 respMax=15396214 dups=15 [INFO] [08-23|12:03:53.363] Queue sizes anchors=0 links=2737 persisted=65536 [INFO] [08-23|12:03:58.343] [p2p] GoodPeers eth66=33 [INFO] [08-23|12:04:00.379] [txpool] stat block=15392778 pending=10000 baseFee=30000 queued=30000 alloc=3.7GB sys=6.4GB [INFO] [08-23|12:04:13.363] Req/resp stats req=0 reqMin=0 reqMax=0 skel=15 skelMin=15396214 skelMax=15690934 resp=29 respMin=15396214 respMax=15397305 dups=24Does this look like a healthy output?
not healthy, you need see something like [1/16 Headers] [6/16 Execution] also
maybe it not connected to lighthouse?
Hi, yes, I thought so too.
I ran the command integration stage_headers —reset and it fixed it. Now it looks healthy:
[INFO] [08-24|01:58:35.259] RPC Daemon notified of new headers from=15400951 to=15400952 header sending=8.387µs log sending=200ns
[INFO] [08-24|01:58:35.259] [1/16 Headers] Waiting for headers... from=15400952
[INFO] [08-24|01:58:38.689] [snapshots] Dumping txs block num=15284778 alloc=5.2GB sys=12.1GB
[INFO] [08-24|01:58:42.429] Estimated to reaching TTD blocks=140228
[INFO] [08-24|01:58:42.429] [1/16 Headers] Processed highest inserted=15400953 age=9s
[INFO] [08-24|01:58:43.919] [6/16 Execution] Completed on block=15400953
[INFO] [08-24|01:58:44.543] Timings (slower than 50ms) Headers=7.169s Bodies=836ms Execution=608ms HashState=128ms IntermediateHashes=252ms StorageHistoryIndex=62ms LogIndex=57ms
[INFO] [08-24|01:58:44.543] Tables PlainState=72.2GB AccountChangeSet=1.5GB StorageChangeSet=2.7GB BlockTransaction=18.5GB TransactionLog=259.8GB FreeList=13.3MB ReclaimableSpace=13.3GB
[INFO] [08-24|01:58:44.963] Commit cycle in=419.565174ms
[INFO] [08-24|01:58:44.963] RPC Daemon notified of new headers from=15400952 to=15400953 header sending=10.002µs log sending=239ns
[INFO] [08-24|01:58:44.963] [1/16 Headers] Waiting for headers... from=15400953
[INFO] [08-24|01:58:44.968] Estimated to reaching TTD blocks=140224
[INFO] [08-24|01:58:44.968] [1/16 Headers] Processed highest inserted=15400954 age=2s
[INFO] [08-24|01:58:44.988] [6/16 Execution] Completed on block=15400954
[INFO] [08-24|01:58:45.086] Commit cycle in=37.386897ms
[INFO] [08-24|01:58:45.086] RPC Daemon notified of new headers from=15400953 to=15400954 header sending=9.917µs log sending=237ns
[INFO] [08-24|01:58:45.086] [1/16 Headers] Waiting for headers... from=15400954
[INFO] [08-24|01:58:52.665] Estimated to reaching TTD blocks=140151
[INFO] [08-24|01:58:52.665] [1/16 Headers] Processed highest inserted=15400955 age=9s
[INFO] [08-24|01:58:52.761] [6/16 Execution] Completed on block=15400955
[INFO] [08-24|01:58:52.996] Timings (slower than 50ms) Headers=7.579s Execution=88ms IntermediateHashes=89ms
[INFO] [08-24|01:58:52.996] Tables PlainState=72.2GB AccountChangeSet=1.5GB StorageChangeSet=2.7GB BlockTransaction=18.5GB TransactionLog=259.8GB FreeList=13.3MB ReclaimableSpace=13.3GB
[INFO] [08-24|01:58:53.325] Commit cycle in=328.199258ms
So, now it's working ok. Thanks a lot for answering and please consider fixing this bug.
Hi, sorry, why do you close it? I fixed my node but will you not fix the bug?
ah, yep, need to implement this comment: https://github.com/ledgerwatch/erigon/issues/5138#issuecomment-1223513595
- Automatic detect such cases - yes, doable on erigon startup. Just need compare first record in db and max available snapshot. Need add it. - done by https://github.com/ledgerwatch/erigon/pull/5174
I too had the catch panic issue with 2002.08.02:
Aug 27 23:48:39 ckubuntu erigon[1617]: [EROR] [08-27|23:48:39.431] catch panic err="runtime error: index out of range [15310000] with length 15310000" stack="[main.go:29 panic.go:884 panic.go:119 config.go:246 block_snapshots.go:186 config.go:245 block_snapshots.go:286 config.go:243 backend.go:572 node.go:115 main.go:58 app.go:526 app.go:286 main.go:34 proc.go:250 asm_amd64.s:1594]"
After loading 2002.08.03, I now get stuck in a snapshot loop (note this is with the --downloader.verify option):
Aug 28 08:41:43 ckubuntu systemd[1]: Started erigon.service.
Aug 28 08:41:43 ckubuntu erigon[4700]: [INFO] [08-28|08:41:43.328] Starting metrics server addr=http://127.0.0.1:6060/debug/metrics/prometheus
Aug 28 08:41:43 ckubuntu erigon[4700]: [INFO] [08-28|08:41:43.328] Build info git_branch= git_tag= git_commit=
Aug 28 08:41:43 ckubuntu erigon[4700]: [INFO] [08-28|08:41:43.328] Starting Erigon on Ethereum mainnet...
Aug 28 08:41:43 ckubuntu erigon[4700]: [INFO] [08-28|08:41:43.328] Maximum peer count ETH=100 total=100
Aug 28 08:41:43 ckubuntu erigon[4700]: [INFO] [08-28|08:41:43.328] starting HTTP APIs APIs=engine,eth,net
Aug 28 08:41:43 ckubuntu erigon[4700]: [INFO] [08-28|08:41:43.328] torrent verbosity level=WRN
Aug 28 08:41:45 ckubuntu erigon[4700]: [INFO] [08-28|08:41:45.430] Set global gas cap cap=50000000
Aug 28 08:41:45 ckubuntu erigon[4700]: [WARN] [08-28|08:41:45.489] specifying prune.before.r might break CL compatibility
Aug 28 08:41:45 ckubuntu erigon[4700]: [INFO] [08-28|08:41:45.489] Opening Database label=chaindata path=/var/lib/erigon/chaindata
Aug 28 08:41:45 ckubuntu erigon[4700]: [INFO] [08-28|08:41:45.499] Initialised chain configuration config="{ChainID: 1, Homestead: 1150000, DAO: 1920000, DAO Support: true, Tangerine Whistle: 2463000, Spurious Dragon: 2675000, Byzantium: 4370000, Constantinople: 7280000, Petersburg: 7280000, Istanbul: 9069000, Muir Glacier: 9200000, Berlin: 12244000, London: 12965000, Arrow Glacier: 13773000, Gray Glacier: 15050000, Terminal Total Difficulty: 58750000000000000000000, Merge Netsplit: <nil>, Engine: ethash}" genesis=0xd4e56740f876aef8c010b86a40d5f56745a118d0906a34e69aec8c0db1cb8fa3
Aug 28 08:41:45 ckubuntu erigon[4700]: [INFO] [08-28|08:41:45.499] Effective prune_flags="--prune.h.older=90000 --prune.t.older=90000 --prune.c.older=90000 --prune.r.before=11052984" snapshot_flags="--snapshots=true" history.v2=false
Aug 28 08:41:46 ckubuntu erigon[4700]: [INFO] [08-28|08:41:46.031] Initialising Ethereum protocol network=1
Aug 28 08:41:46 ckubuntu erigon[4700]: [INFO] [08-28|08:41:46.031] Disk storage enabled for ethash DAGs dir=/var/lib/erigon/ethash-dags count=2
Aug 28 08:41:46 ckubuntu erigon[4700]: [INFO] [08-28|08:41:46.334] rpc filters: subscribing to Erigon events
Aug 28 08:41:46 ckubuntu erigon[4700]: [INFO] [08-28|08:41:46.334] new subscription to logs established
Aug 28 08:41:46 ckubuntu erigon[4700]: [INFO] [08-28|08:41:46.334] new subscription to newHeaders established
Aug 28 08:41:46 ckubuntu erigon[4700]: [INFO] [08-28|08:41:46.334] New txs subscriber joined
Aug 28 08:41:46 ckubuntu erigon[4700]: [INFO] [08-28|08:41:46.334] Reading JWT secret path=/var/lib/jwtsecret/jwt.hex
Aug 28 08:41:46 ckubuntu erigon[4700]: [INFO] [08-28|08:41:46.335] HTTP endpoint opened for Engine API url=localhost:8551 ws=true ws.compression=true
Aug 28 08:41:46 ckubuntu erigon[4700]: [INFO] [08-28|08:41:46.335] HTTP endpoint opened url=localhost:8545 ws=false ws.compression=true grpc=false
Aug 28 08:41:46 ckubuntu erigon[4700]: [INFO] [08-28|08:41:46.348] [Snapshots] Fetching torrent files metadata
Aug 28 08:41:46 ckubuntu erigon[4700]: [INFO] [08-28|08:41:46.348] Started P2P networking version=66 self=enode://b8718db6542ea663b4e54cc1c8af1b61cf1928e7b1f4f00a9a9dc4bf998deea4cd2700118e177931ddf0b9d0ec1c970015a520696b89fd79cb515fe69e720ecc@127.0.0.1:30303 name=erigon/v2022.08.3/linux-amd64/go1.19
Aug 28 08:41:48 ckubuntu erigon[4700]: [INFO] [08-28|08:41:48.614] [txpool] Started
Aug 28 08:42:06 ckubuntu erigon[4700]: [INFO] [08-28|08:42:06.349] [snapshots] Verifying progress=22.03%
Aug 28 08:42:26 ckubuntu erigon[4700]: [INFO] [08-28|08:42:26.353] [snapshots] Verifying progress=43.20%
Aug 28 08:42:46 ckubuntu erigon[4700]: [INFO] [08-28|08:42:46.354] [snapshots] Verifying progress=63.99%
Aug 28 08:42:46 ckubuntu erigon[4700]: [INFO] [08-28|08:42:46.359] [txpool] stat block=15426086 pending=9989 baseFee=30000 queued=6221 alloc=291.6MB sys=622.1MB
Aug 28 08:43:06 ckubuntu erigon[4700]: [INFO] [08-28|08:43:06.349] [snapshots] Verifying progress=84.54%
Aug 28 08:43:26 ckubuntu erigon[4700]: [INFO] [08-28|08:43:26.350] [snapshots] Verifying progress=99.46%
Aug 28 08:43:31 ckubuntu erigon[4700]: [INFO] [08-28|08:43:31.849] [Snapshots] Stat blocks=15310k indices=15310k alloc=2.7GB sys=2.8GB
Aug 28 08:43:31 ckubuntu erigon[4700]: [EROR] [08-28|08:43:31.902] Staged Sync err="[1/16 Headers] BuildMissedIndices: TransactionsIdx: at=15310000-15320000, expect: 1802591, got 1802590, [block_snapshots.go:1518 panic.go:890 block_snapshots.go:1541 block_snapshots.go:751 block_snapshots.go:792 asm_amd64.s:1594]"
Aug 28 08:43:32 ckubuntu erigon[4700]: [INFO] [08-28|08:43:32.674] [Snapshots] Fetching torrent files metadata
Aug 28 08:43:46 ckubuntu erigon[4700]: [INFO] [08-28|08:43:46.033] [p2p] GoodPeers eth66=2
Aug 28 08:43:46 ckubuntu erigon[4700]: [INFO] [08-28|08:43:46.367] [txpool] stat block=15426086 pending=10000 baseFee=30000 queued=7604 alloc=5.6GB sys=7.1GB
Aug 28 08:43:52 ckubuntu erigon[4700]: [INFO] [08-28|08:43:52.678] [snapshots] Verifying progress=19.06%
Aug 28 08:44:12 ckubuntu erigon[4700]: [INFO] [08-28|08:44:12.675] [snapshots] Verifying progress=38.23%
Aug 28 08:44:32 ckubuntu erigon[4700]: [INFO] [08-28|08:44:32.685] [snapshots] Verifying progress=57.24%
Aug 28 08:44:46 ckubuntu erigon[4700]: [INFO] [08-28|08:44:46.345] [txpool] stat block=15426086 pending=10000 baseFee=30000 queued=8123 alloc=6.0GB sys=7.2GB
Aug 28 08:44:52 ckubuntu erigon[4700]: [INFO] [08-28|08:44:52.876] [snapshots] Verifying progress=76.32%
Aug 28 08:45:12 ckubuntu erigon[4700]: [INFO] [08-28|08:45:12.677] [snapshots] Verifying progress=93.94%
Aug 28 08:45:26 ckubuntu erigon[4700]: [INFO] [08-28|08:45:26.277] [Snapshots] Stat blocks=15310k indices=15310k alloc=3.6GB sys=7.2GB
Aug 28 08:45:26 ckubuntu erigon[4700]: [EROR] [08-28|08:45:26.343] Staged Sync err="[1/16 Headers] BuildMissedIndices: TransactionsIdx: at=15310000-15320000, expect: 1802591, got 1802590, [block_snapshots.go:1518 panic.go:890 block_snapshots.go:1541 block_snapshots.go:751 block_snapshots.go:792 asm_amd64.s:1594]"
Aug 28 08:45:27 ckubuntu erigon[4700]: [INFO] [08-28|08:45:27.094] [Snapshots] Fetching torrent files metadata
Aug 28 08:45:46 ckubuntu erigon[4700]: [INFO] [08-28|08:45:46.139] [p2p] GoodPeers eth66=3
Aug 28 08:45:46 ckubuntu erigon[4700]: [INFO] [08-28|08:45:46.411] [txpool] stat block=15426086 pending=10000 baseFee=30000 queued=8457 alloc=6.6GB sys=7.2GB
Aug 28 08:45:47 ckubuntu erigon[4700]: [INFO] [08-28|08:45:47.102] [snapshots] Verifying progress=18.94%
Aug 28 08:46:07 ckubuntu erigon[4700]: [INFO] [08-28|08:46:07.097] [snapshots] Verifying progress=37.78%
Aug 28 08:46:27 ckubuntu erigon[4700]: [INFO] [08-28|08:46:27.105] [snapshots] Verifying progress=56.87%
Aug 28 08:46:47 ckubuntu erigon[4700]: [INFO] [08-28|08:46:47.097] [snapshots] Verifying progress=75.50%
Aug 28 08:46:49 ckubuntu erigon[4700]: [INFO] [08-28|08:46:49.897] [txpool] stat block=15426086 pending=10000 baseFee=30000 queued=9104 alloc=6.0GB sys=7.3GB
Aug 28 08:47:07 ckubuntu erigon[4700]: [INFO] [08-28|08:47:07.095] [snapshots] Verifying progress=93.12%
Aug 28 08:47:21 ckubuntu erigon[4700]: [INFO] [08-28|08:47:21.934] [Snapshots] Stat blocks=15310k indices=15310k alloc=3.1GB sys=7.3GB
Aug 28 08:47:22 ckubuntu erigon[4700]: [EROR] [08-28|08:47:22.143] Staged Sync err="[1/16 Headers] BuildMissedIndices: TransactionsIdx: at=15310000-15320000, expect: 1802591, got 1802590, [block_snapshots.go:1518 panic.go:890 block_snapshots.go:1541 block_snapshots.go:751 block_snapshots.go:792 asm_amd64.s:1594]"
So is there a way to recover without fully rebuilding the dB? Can I just delete the snapshot directory?
Thank you.
@drjake007 i advise go next way:
- stop erigon
- remove files >= 15310000 from datadir/snapshots dir
- run
make integration - run
./build/bin/integration stage_headers --reset --datadir=<your_datadir>/snapshots - start erigon
@AskAlexSharov
Yes, erigon must not panic in this case, must return error. And likely it’s a bug.
Erigon can download Only snapshots from whitelist (old one), all other snapshots Erigon creating locally by moving data from DB to snapshots. It means if remove recent snapshots - Erigon can’t re-create them - because it does not have such data in db. Automatic detect/re-download/re-execute some blocks in the middle of history is complex feature which likely we will not have in near future. If manually delete some block from DB - Erigon also will not recover it.
Erigon already auto-re-download whitelisted snapshots if they are missed. Also flag —downloader.verify can force re-check and download if part of whitelisted snapshot is corrupted.
now you can force re-download lost blocks by “integration stage_headers —reset” - but in future we will have more data in snapshots and this hack will not help.
Automatic detect such cases - yes, doable on erigon startup. Just need compare first record in db and max available snapshot. Need add it.
Hi.
I'm having the same problem. This happened very soon after the merge by the way. My problem is that it's happening with generated snapshots and not downloaded snapshots, so I can't just remove and redownload them:
taged Sync err="[1/15 Headers] BuildMissedIndices: TransactionsIdx: at=15410000-15420000, expect: 1721282, got 1721281, [block_snapshots.go:1537 panic.go:844 block_snapshots.go:1560 block_snapshots.go:760 block_snapshots.go:801 asm_amd64.s:1571]"
Any way I can fix this without resyncing from scratch? For instance, could I download those snapshot files from someone who already has them or just disable snapshots entirely?
I'm running the latest alpha (erigon version 2022.09.1-alpha-4067b7c4).
