eth_getBalance returns "inverted_index(v1-accounts.0-64.ef) at (0000000000000000000000000000000000000000, 20560892) returned value 0, but it out-of-bounds 100000000-7500001836"

[qnduncan]

This is the same issue as #700.

We followed the instructions in #700 (comment) to download the v1-accounts.0-64.ef and v1-accounts.0-64.efi files. The servers worked with the files, but they reencountered the same issue after a few days.

[blxdyx]

Do you have force kill the process? that's may change the v1-accounts.0-64.ef file

[qnduncan]

We use docker to run erigon and the stop_grace_period is set to 5m. It's rare that we force kill the container, as most of the time the container can be stopped within 5m.

[blxdyx]

You could refer to #700 (comment) to do temp fix. I will do more research about this.

[blxdyx]

BTW, do you have logs such as file len changed

[qnduncan]

Is file len changed the exact keyword to be used to search in the log?

[blxdyx]

Is file len changed the exact keyword to be used to search in the log?

yes

[quick-pawiromitchel]

seeing these in the logs

[INFO] [06-18|13:33:58.250] [snapshots] downloader stopped
[WARN] [06-18|13:33:58.732] file len changed: from 941125730 to 4862119068, v1-accounts.0-64.ef
panic: file len changed: from 941125730 to 4862119068, v1-accounts.0-64.ef

goroutine 1855524 [running]:
github.com/erigontech/erigon-lib/seg.(*Decompressor).checkFileLenChage(0xc08a934000)
	github.com/erigontech/erigon-lib@v0.0.0-00010101000000-000000000000/seg/decompress.go:469 +0x27d
github.com/erigontech/erigon-lib/seg.(*Decompressor).Close(0xc08a934000)
	github.com/erigontech/erigon-lib@v0.0.0-00010101000000-000000000000/seg/decompress.go:477 +0x45
github.com/erigontech/erigon-lib/state.(*filesItem).closeFiles(0xc08ab9ab80)
	github.com/erigontech/erigon-lib@v0.0.0-00010101000000-000000000000/state/files_item.go:87 +0x27
github.com/erigontech/erigon-lib/state.(*InvertedIndex).closeWhatNotInList(0xc000051800, {0xc367b0ff68, 0x0, 0xffffffffffffffff?})
	github.com/erigontech/erigon-lib@v0.0.0-00010101000000-000000000000/state/inverted_index.go:345 +0x185
github.com/erigontech/erigon-lib/state.(*InvertedIndex).Close(...)
	github.com/erigontech/erigon-lib@v0.0.0-00010101000000-000000000000/state/inverted_index.go:356
github.com/erigontech/erigon-lib/state.(*History).Close(0xc000c12848)
	github.com/erigontech/erigon-lib@v0.0.0-00010101000000-000000000000/state/history.go:308 +0x36
github.com/erigontech/erigon-lib/state.(*Domain).Close(0xc003324608)
	github.com/erigontech/erigon-lib@v0.0.0-00010101000000-000000000000/state/domain.go:458 +0x25
github.com/erigontech/erigon-lib/state.(*Aggregator).closeDirtyFiles.func1()
	github.com/erigontech/erigon-lib@v0.0.0-00010101000000-000000000000/state/aggregator.go:302 +0x47
created by github.com/erigontech/erigon-lib/state.(*Aggregator).closeDirtyFiles in goroutine 1842073
	github.com/erigontech/erigon-lib@v0.0.0-00010101000000-000000000000/state/aggregator.go:300 +0x65

[blxdyx]

Could you show more logs about this.

[blxdyx]

Try cat data-seed/data/snapshots/preverified.toml | grep 'v1-accounts.0-64.ef'

[qnduncan]

@blxdyx Here is more log around the panic on another server.

Details

[INFO] [06-17|03:07:30.947] [5/9 Bodies] Processed                   highest=51590334 blocks=94 in=5.617 blk/sec=16
[INFO] [06-17|03:07:30.947] [6/9 Senders] Started                    from=51590240 to=51590334
[INFO] [06-17|03:07:31.041] [7/9 Execution] starting                 from=51590240 to=51590334 fromTxNum=7831536750 offsetFromBlockBeginning=0 initialCycle=false useExternalTx=true inMem=false
[INFO] [06-17|03:07:31.042] [7/9 Execution] starting                 from=51590241 to=51590334 fromTxNum=7831536751 offsetFromBlockBeginning=0 initialCycle=false useExternalTx=true
[WARN] [06-17|03:07:35.526] [rpc] served                             conn=64.130.59.11:28116 method=eth_call reqid=1 err="execution reverted: ERC721: invalid token ID" errdata=0x08c379a0000000000000000000000000000000000000000000000000000000000000002000000000000000000000000000000000000000000000000000000000000000184552433732313a20696e76616c696420746f6b656e2049440000000000000000
[INFO] [06-17|03:07:37.524] Got interrupt, shutting down...          sig=terminated
[INFO] [06-17|03:07:37.525] Got interrupt, shutting down... 
[INFO] [06-17|03:07:37.525] [snapshots] stopping downloader          files=3296
[INFO] [06-17|03:07:37.526] [snapshots] closing torrents 
[INFO] [06-17|03:07:37.527] Exiting... 
[INFO] [06-17|03:07:37.706] [txpool] stopped 
[INFO] [06-17|03:07:37.706] devp2p txn pool goroutine terminated 
[INFO] [06-17|03:07:37.740] [7/9 Execution] Done                     blk=51590293 blks=53 blk/s=7.9 txs=15434 tx/s=2.30k gas/s=455.78M buf=8.8MB/2.0GB stepsInDB=0.00 step=5012.2 inMem=false alloc=21.9GB sys=36.4GB
[INFO] [06-17|03:07:38.093] HTTP endpoint closed                     url=[::]:8545
[INFO] [06-17|03:07:38.093] HTTP endpoint closed                     url=[::]:8546
[INFO] [06-17|03:07:38.093] RPC server shutting down 
[INFO] [06-17|03:07:38.722] [snapshots] closing db 
[INFO] [06-17|03:07:38.722] [snapshots] downloader stopped 
[WARN] [06-17|03:07:41.801] file len changed: from 1776072841 to 5895492060, v1-storage.0-64.ef 
panic: file len changed: from 1776072841 to 5895492060, v1-storage.0-64.ef

goroutine 24968127 [running]:
github.com/erigontech/erigon-lib/seg.(*Decompressor).checkFileLenChage(0xc0898c0000)
        github.com/erigontech/erigon-lib@v0.0.0-00010101000000-000000000000/seg/decompress.go:469 +0x27d
github.com/erigontech/erigon-lib/seg.(*Decompressor).Close(0xc0898c0000)
        github.com/erigontech/erigon-lib@v0.0.0-00010101000000-000000000000/seg/decompress.go:477 +0x45
github.com/erigontech/erigon-lib/state.(*filesItem).closeFiles(0xc089881d00)
        github.com/erigontech/erigon-lib@v0.0.0-00010101000000-000000000000/state/files_item.go:87 +0x27
github.com/erigontech/erigon-lib/state.(*InvertedIndex).closeWhatNotInList(0xc003cd2200, {0xc367d60f68, 0x0, 0xc2528ddbc0?})
        github.com/erigontech/erigon-lib@v0.0.0-00010101000000-000000000000/state/inverted_index.go:345 +0x185
github.com/erigontech/erigon-lib/state.(*InvertedIndex).Close(...)
        github.com/erigontech/erigon-lib@v0.0.0-00010101000000-000000000000/state/inverted_index.go:356
github.com/erigontech/erigon-lib/state.(*History).Close(0xc000679088)
        github.com/erigontech/erigon-lib@v0.0.0-00010101000000-000000000000/state/history.go:308 +0x36
github.com/erigontech/erigon-lib/state.(*Domain).Close(0xc000033b08)
        github.com/erigontech/erigon-lib@v0.0.0-00010101000000-000000000000/state/domain.go:458 +0x25
github.com/erigontech/erigon-lib/state.(*Aggregator).closeDirtyFiles.func1()
        github.com/erigontech/erigon-lib@v0.0.0-00010101000000-000000000000/state/aggregator.go:302 +0x47
created by github.com/erigontech/erigon-lib/state.(*Aggregator).closeDirtyFiles in goroutine 24951228
        github.com/erigontech/erigon-lib@v0.0.0-00010101000000-000000000000/state/aggregator.go:300 +0x65
[INFO] [06-17|03:07:45.448] logging to file system                   log dir=/data/logs file prefix=erigon log level=info json=false
[INFO] [06-17|03:07:45.448] Enabling metrics export to prometheus    path=http://0.0.0.0:6060/debug/metrics/prometheus
[INFO] [06-17|03:07:45.448] Starting pprof server                    cpu="go tool pprof -lines -http=: http://0.0.0.0:6061/debug/pprof/profile?seconds=20" heap="go tool pprof -lines -http=: http://0.0.0.0:6061/debug/pprof/heap"
[INFO] [06-17|03:07:45.448] Build info                               git_branch=HEAD git_tag=v1.3.8-dirty git_commit=1daeb8bc6dd9d9f4ff80d2ab929498941675ab32
[INFO] [06-17|03:07:45.449] Starting Erigon on BSC mainnet... 
[INFO] [06-17|03:07:45.473] Maximum peer count                       total=32
[INFO] [06-17|03:07:45.473] starting HTTP APIs                       port=8545 APIs=admin,debug,eth,net,txpool,web3,trace,erigon,ots,bsc
[INFO] [06-17|03:07:45.474] Set global gas cap                       cap=600000000
[INFO] [06-17|03:07:45.479] torrent verbosity                        level=WRN
[INFO] [06-17|03:07:45.493] [torrent] Public IP                      ip=208.91.110.21
[INFO] [06-17|03:07:45.493] [Downloader] Running with                ipv6-enabled=true ipv4-enabled=true download.rate=2048mb upload.rate=64mb
[INFO] [06-17|03:07:45.504] Opening Database                         label=chaindata path=/data/chaindata
[INFO] [06-17|03:07:45.507] [db] open                                label=chaindata sizeLimit=4TB pageSize=4KB
[INFO] [06-17|03:07:45.580] Initialised chain configuration          config="{ChainID: 56, Terminal Total Difficulty: <nil>, ShanghaiTime: 2024-01-23 08:00:00 +0000 UTC, KeplerTime 2024-01-23 08:00:00 +0000 UTC, FeynmanTime 2024-04-18 05:49:00 +0000 UTC, FeynmanFixTime 2024-04-18 05:49:00 +0000 UTC, CancunTime 2024-06-20 06:05:00 +0000 UTC, HaberTime 2024-06-20 06:05:00 +0000 UTC, HaberFixTime 2024-09-26 02:02:00 +0000 UTC, c.BohrTime 2024-09-26 02:20:00 +0000 UTC, c.PascalTime 2025-03-20 02:10:00 +0000 UTC, c.PragueTime 2025-03-20 02:10:00 +0000 UTC, c.LorentzTime 2025-04-29 05:05:00 +0000 UTC, c.MaxwellTime 2286-11-20 17:46:39 +0000 UTC, Engine: parlia}" genesis=0x0d21840abff46b96c84b2ac9e10e4f5cdaeb5693cb665db62a2f3b02d2d57b5b
[INFO] [06-17|03:08:51.061] Initialising Ethereum protocol           network=56
[INFO] [06-17|03:08:51.061] Opening Database                         label=parlia path=/data/parlia
setup_dxb:18034 opening after an unclean shutdown, but boot-id(98c710b30a3395d2-3c7b227cd0f0499d) is MATCH: rollback NOT needed, steady-sync NEEDED
[INFO] [06-17|03:08:51.066] Opening Database                         label=blob path=/data/blobs/blob
[INFO] [06-17|03:08:51.070] Parlia                                   chainConfig="{ChainID: 56, Terminal Total Difficulty: <nil>, ShanghaiTime: 2024-01-23 08:00:00 +0000 UTC, KeplerTime 2024-01-23 08:00:00 +0000 UTC, FeynmanTime 2024-04-18 05:49:00 +0000 UTC, FeynmanFixTime 2024-04-18 05:49:00 +0000 UTC, CancunTime 2024-06-20 06:05:00 +0000 UTC, HaberTime 2024-06-20 06:05:00 +0000 UTC, HaberFixTime 2024-09-26 02:02:00 +0000 UTC, c.BohrTime 2024-09-26 02:20:00 +0000 UTC, c.PascalTime 2025-03-20 02:10:00 +0000 UTC, c.PragueTime 2025-03-20 02:10:00 +0000 UTC, c.LorentzTime 2025-04-29 05:05:00 +0000 UTC, c.MaxwellTime 2286-11-20 17:46:39 +0000 UTC, Engine: parlia}"
[INFO] [06-17|03:08:51.155] rpc filters: subscribing to Erigon events 
[INFO] [06-17|03:08:51.155] Starting private RPC server              on=127.0.0.1:9090
[INFO] [06-17|03:08:51.155] new subscription to logs established 
[INFO] [06-17|03:08:51.155] new subscription to newHeaders established 
[INFO] [06-17|03:08:51.155] New txns subscriber joined 
[INFO] [06-17|03:08:51.156] JsonRpc endpoint opened                  ws=true ws.compression=true grpc=false websocket.url=[::]:8546 http.url=[::]:8545
[INFO] [06-17|03:08:51.177] [txpool] Started 
[INFO] [06-17|03:08:51.181] [OtterSync] Starting Ottersync 
[INFO] [06-17|03:08:51.181] 
   _____ _             _   _                ____  _   _                                       
  / ____| |           | | (_)              / __ \| | | |                                      
 | (___ | |_ __ _ _ __| |_ _ _ __   __ _  | |  | | |_| |_ ___ _ __ ___ _   _ _ __   ___       
  \___ \| __/ _ | '__| __| | '_ \ / _ | | |  | | __| __/ _ \ '__/ __| | | | '_ \ / __|      
  ____) | || (_| | |  | |_| | | | | (_| | | |__| | |_| ||  __/ |  \__ \ |_| | | | | (__ _ _ _ 
 |_____/ \__\__,_|_|   \__|_|_| |_|\__, |  \____/ \__|\__\___|_|  |___/\__, |_| |_|\___(_|_|_)
                                    __/ |                               __/ |                 
                                   |___/                               |___/                                            


                                        .:-===++**++===-:                                 
                                   :=##%@@@@@@@@@@@@@@@@@@%#*=.                           
                               .=#@@@@@@%##+====--====+##@@@@@@@#=.     ...               
                   .=**###*=:+#@@@@%*=:.                  .:=#%@@@@#==#@@@@@%#-           
                 -#@@@@%%@@@@@@%+-.                            .=*%@@@@#*+*#@@@%=         
                =@@@*:    -%%+:                                    -#@+.     =@@@-        
                %@@#     +@#.                                        :%%-     %@@*        
                @@@+    +%=.     -+=                        :=-       .#@-    %@@#        
                *@@%:  #@-      =@@@*                      +@@@%.       =@= -*@@@:        
                 #@@@##@+       #@@@@.                     %@@@@=        #@%@@@#-         
                  :#@@@@:       +@@@#       :=++++==-.     *@@@@:        =@@@@-           
                  =%@@%=         +#*.    =#%#+==-==+#%%=:  .+#*:         .#@@@#.          
                 +@@%+.               .+%+-.          :=##-                :#@@@-         
                -@@@=                -%#:     ..::.      +@*                 +@@%.        
    .::-========*@@@..              -@#      +%@@@@%.     -@#               .-@@@+=======-
.:-====----:::::#@@%:--=::::..      #@:      *@@@@@%:      *@=      ..:-:-=--:@@@+::::----
                =@@@:.......        @@        :+@#=.       -@+        .......-@@@:        
       .:=++####*%@@%=--::::..      @@   %#     %*    :@*  -@+      ...::---+@@@#*#*##+=-:
  ..--==::..     :%@@@-   ..:::..   @@   +@*:.-#@@+-.-#@-  -@+   ..:::..  .+@@@#.     ..:-
                  .#@@@##-:.        @@    :+#@%=.:+@@#=.   -@+        .-=#@@@@+           
             -=+++=--+%@@%+=.       @@       +%*=+#%-      -@+       :=#@@@%+--++++=:     
         .=**=:.      .=*@@@@@#=:.  @@         :--.        -@+  .-+#@@@@%+:       .:=*+-. 
        ::.              .=*@@@@@@%#@@+=-:..         ..::=+#@%#@@@@@@%+-.             ..-.
                            ..=*#@@@@@@@@@@@@@@@%%@@@@@@@@@@@@@@%#+-.                     
                                  .:-==++*#######%######**+==-:                           

             
 
[INFO] [06-17|03:08:51.181] [1/9 OtterSync] Requesting downloads 
[INFO] [06-17|03:08:51.210] Started P2P networking                   version=68 self=enode://562cd084783d3947cebd4a612fe28d0d8da943f1cb2472644c0e627af968583af03152ed77df506ce8e626b8e96c3a1ba7e201679eb0a280fa1badde5925dcee@208.91.110.21:30303 name=erigon/v1.3.8-1daeb8bc/linux-amd64/go1.24.3
[INFO] [06-17|03:08:51.342] [1/9 OtterSync] Requesting downloads 
[INFO] [06-17|03:08:51.758] [snapshots:download] Stat                blocks=51.58M indices=51.58M alloc=14.4GB sys=14.8GB
[INFO] [06-17|03:08:51.765] [snapshots:history] Stat                 blocks=51.58M txs=7.83B txNum2blockNum="4096=43490K,4608=48426K,4864=50754K,4992=51470K,5008=51560K,5012=51589K" first_history_idx_in_db=51589289 last_comitment_block=51589289 last_comitment_tx_num=7831250000 alloc=14.4GB sys=14.8GB
[INFO] [06-17|03:08:53.242] [2/9 Headers] Waiting for headers...     from=51590240 hash=0xbb9a9c1f6a2a031f5217ada145cd2a87005335d14f60a546c838504dcf14276f
[INFO] [06-17|03:08:53.752] [2/9 Headers] Processed                  highest=51590392 age=2s headers=152 in=0.510 blk/sec=298
[INFO] [06-17|03:08:53.758] [5/9 Bodies] Processing bodies...        from=51590240 to=51590392

[qnduncan]

Try cat data-seed/data/snapshots/preverified.toml | grep 'v1-accounts.0-64.ef'

Here is the output of the command cat snapshots/preverified.toml | grep 'v1-accounts.0-64.ef'.

'accessor/v1-accounts.0-64.efi' = 'cd4890e37bd3be160b38290654e7f169c0bffd96'
'idx/v1-accounts.0-64.ef' = 'cdca236cf08187acc8eb92a01386c022b503702b'

[qnduncan]

Hi @blxdyx,

We still encounter this issue quite often. Is there any update? Thanks.

[blxdyx]

It seems never reproduced in my local.

[qnduncan]

Do you have any advice or perhaps some erigon options we can try?

The log attached above shows that it was a normal stop, and then file len changed occurred. Our version is v1.3.10.

[blxdyx]

You could try latest main branch, it need sync all snapshots.