[BUG] Unexpected error when getting snapshot after prune

[du5]

System information

➜  /opt geth version
Geth
Version: 1.4.6
Git Commit: 43b2ffa63ba242437bcf19ee9bccf9595be0763a
Git Commit Date: 20240429
Architecture: amd64
Go Version: go1.22.2
Operating System: linux
GOPATH=
GOROOT=/opt/hostedtoolcache/go/1.22.2/x64
➜  /opt lsb_release -a
No LSB modules are available.
Distributor ID:	Debian
Description:	Debian GNU/Linux 12 (bookworm)
Release:	12
Codename:	bookworm
➜  /opt 

prunbe command

➜  /opt geth snapshot prune-block --datadir PATH --datadir.ancient PATH/geth/chaindata/ancient/chain
....
NFO [05-07|13:32:36.283] new offset/new startBlockNumber is       "new offset"=38,512,419
INFO [05-07|13:32:36.285] Opened ancient database                  database=/opt/geth.full/geth/chaindata/ancient/chain_back readonly=false frozen=38,512,419
INFO [05-07|13:32:36.285] prune info                               "old offset"=38,163,322 "number of items in ancientDB"=349,097 "amount to reserve"=0
INFO [05-07|13:32:36.285] new offset/new startBlockNumber recorded successfully  "new offset"=38,512,419
INFO [05-07|13:32:36.285] block back up done                       "current start blockNumber in ancientDB"=38,512,419
INFO [05-07|13:32:36.329] Block pruning BackUp successfully        "time duration since start is"=119.349ms
INFO [05-07|13:32:36.329] backup block successfully
INFO [05-07|13:32:36.333] Block prune successfully

➜  /opt geth snapshot prune-state --datadir PATH
INFO [05-07|13:32:40.558] Maximum peer count                       ETH=50 total=50
INFO [05-07|13:32:40.562] Set global gas cap                       cap=50,000,000
INFO [05-07|13:32:40.562] Initializing the KZG library             backend=gokzg
INFO [05-07|13:32:40.573] Using pebble as the backing database
INFO [05-07|13:32:40.573] Allocated cache and file handles         database=/opt/geth.full/geth/chaindata cache=409.00MiB handles=524,288 "memory table"=102.25MiB
INFO [05-07|13:32:40.667] Opened ancient database                  database=/opt/geth.full/geth/chaindata/ancient/chain readonly=false frozen=38,512,419
INFO [05-07|13:32:40.870] Snapshot loaded                          diskRoot=8459bb..6f2483 root=547f40..f24a31
INFO [05-07|13:32:40.871] Initialized state bloom                  size=2.00GiB
INFO [05-07|13:32:40.898] Selecting bottom-most difflayer as the pruning target root=ddde76..685f37 height=38,512,303
INFO [05-07|13:32:40.902] Iterating state snapshot                 accounts=0 slots=0 elapsed="118.439µs"
....
....
INFO [05-07|15:47:25.191] Pruning state data                       nodes=202,657,485 skipped=5,266,751,941 size=60.09GiB  elapsed=51m24.436s   eta=499ms
INFO [05-07|15:47:25.586] Pruned state data                        nodes=202,690,033 size=60.10GiB  elapsed=51m24.831s
INFO [05-07|15:47:25.633] Compacting database                      range=0x00-0x10 elapsed="1.633µs"
INFO [05-07|15:47:47.731] Compacting database                      range=0x10-0x20 elapsed=22.098s
INFO [05-07|15:48:07.242] Compacting database                      range=0x20-0x30 elapsed=41.608s
INFO [05-07|15:48:25.655] Compacting database                      range=0x30-0x40 elapsed=1m0.022s
INFO [05-07|15:48:41.663] Compacting database                      range=0x40-0x50 elapsed=1m16.029s
INFO [05-07|15:49:01.114] Compacting database                      range=0x50-0x60 elapsed=1m35.480s
INFO [05-07|15:49:19.108] Compacting database                      range=0x60-0x70 elapsed=1m53.474s
INFO [05-07|15:51:14.809] Compacting database                      range=0x70-0x80 elapsed=3m49.175s
INFO [05-07|15:51:34.779] Compacting database                      range=0x80-0x90 elapsed=4m9.145s
INFO [05-07|15:51:52.845] Compacting database                      range=0x90-0xa0 elapsed=4m27.211s
INFO [05-07|15:52:09.796] Compacting database                      range=0xa0-0xb0 elapsed=4m44.163s
INFO [05-07|15:52:28.905] Compacting database                      range=0xb0-0xc0 elapsed=5m3.271s
INFO [05-07|15:52:47.973] Compacting database                      range=0xc0-0xd0 elapsed=5m22.339s
INFO [05-07|15:53:13.377] Compacting database                      range=0xd0-0xe0 elapsed=5m47.743s
INFO [05-07|15:53:34.831] Compacting database                      range=0xe0-0xf0 elapsed=6m9.197s
INFO [05-07|15:53:55.401] Compacting database                      range=0xf0-     elapsed=6m29.768s
INFO [05-07|15:54:13.671] Database compaction finished             elapsed=6m48.037s
INFO [05-07|15:54:13.672] State pruning successful                 pruned=60.10GiB elapsed=2h21m32.772s

log

t=2024-05-08T02:20:51+0200 lvl=info msg="Use config state scheme" config=hash
t=2024-05-08T02:20:51+0200 lvl=info msg="Set global gas cap" cap=50000000
t=2024-05-08T02:20:51+0200 lvl=info msg="Initializing the KZG library" backend=gokzg
t=2024-05-08T02:20:51+0200 lvl=info msg="Using pebble as the backing database"
t=2024-05-08T02:20:51+0200 lvl=info msg="Allocated cache and file handles" database=/opt/geth.full/geth/chaindata cache="1.60 GiB" handles=524288 "memory table"="409.50 MiB"
t=2024-05-08T02:20:51+0200 lvl=info msg="Opened ancient database" database=/opt/geth.full/geth/chaindata/ancient/chain readonly=false frozen=38512429
t=2024-05-08T02:20:51+0200 lvl=info msg="State scheme set by user" scheme=hash
t=2024-05-08T02:20:51+0200 lvl=info msg="Allocated trie memory caches" clean="614.00 MiB" dirty="1024.00 MiB"
t=2024-05-08T02:20:51+0200 lvl=info msg=Parlia chainConfig="{ChainID: 56 Homestead: 0 DAO: <nil> DAOSupport: false EIP150: 0 EIP155: 0 EIP158: 0 Byzantium: 0 Constantinople: 0 Petersburg: 0 Istanbul: 0, Muir Glacier: 0, Ramanujan: 0, Niels: 0, MirrorSync: 5184000, Bruno: 13082000, Berlin: 31302048, YOLO v3: <nil>, CatalystBlock: <nil>, London: 31302048, ArrowGlacier: <nil>, MergeFork:<nil>, Euler: 18907621, Gibbs: 23846001, Nano: 21962149, Moran: 22107423, Planck: 27281024,Luban: 29020050, Plato: 30720096, Hertz: 31302048, Hertzfix: 34140700, ShanghaiTime: 1705996800, KeplerTime: 1705996800, FeynmanTime: 1713419340, FeynmanFixTime: 1713419340, CancunTime: <nil>, Engine: parlia}"
t=2024-05-08T02:20:51+0200 lvl=info msg="Initialising Ethereum protocol" network=56 dbversion=8
t=2024-05-08T02:20:51+0200 lvl=info msg="Initialised chain configuration" config="{ChainID: 56 Homestead: 0 DAO: <nil> DAOSupport: false EIP150: 0 EIP155: 0 EIP158: 0 Byzantium: 0 Constantinople: 0 Petersburg: 0 Istanbul: 0, Muir Glacier: 0, Ramanujan: 0, Niels: 0, MirrorSync: 5184000, Bruno: 13082000, Berlin: 31302048, YOLO v3: <nil>, CatalystBlock: <nil>, London: 31302048, ArrowGlacier: <nil>, MergeFork:<nil>, Euler: 18907621, Gibbs: 23846001, Nano: 21962149, Moran: 22107423, Planck: 27281024,Luban: 29020050, Plato: 30720096, Hertz: 31302048, Hertzfix: 34140700, ShanghaiTime: 1705996800, KeplerTime: 1705996800, FeynmanTime: 1713419340, FeynmanFixTime: 1713419340, CancunTime: <nil>, Engine: parlia}"
t=2024-05-08T02:20:51+0200 lvl=error msg="Unexpected error when getting snapshot" error="unknown ancestor" blockNumber=38512430 blockHash=0xad30be67dc6fc9f62716e3923221cb3bc06911fa6d6dc6a1a22190a544218b32
t=2024-05-08T02:20:51+0200 lvl=error msg="Unexpected error when getting snapshot" error="unknown ancestor" blockNumber=38512430 blockHash=0xad30be67dc6fc9f62716e3923221cb3bc06911fa6d6dc6a1a22190a544218b32
t=2024-05-08T02:20:51+0200 lvl=info msg="Loaded most recent local header" number=38512430 hash=0xad30be67dc6fc9f62716e3923221cb3bc06911fa6d6dc6a1a22190a544218b32 hash=0x547f4028e0053d4f08a0001009cc95b7358e687cd3c75f595976e20e53f24a31 td=76514304 age=12h58m40s
t=2024-05-08T02:20:51+0200 lvl=info msg="Loaded most recent local block" number=0 hash=0x0d21840abff46b96c84b2ac9e10e4f5cdaeb5693cb665db62a2f3b02d2d57b5b root=0x919fcc7ad870b53db0aa76eb588da06bacb6d230195100699fc928511003b422 td=1 age=4y1mo1w
t=2024-05-08T02:20:51+0200 lvl=info msg="Loaded most recent local snap block" number=38512430 hash=0xad30be67dc6fc9f62716e3923221cb3bc06911fa6d6dc6a1a22190a544218b32 root=0x547f4028e0053d4f08a0001009cc95b7358e687cd3c75f595976e20e53f24a31 td=76514304 age=12h58m40s
t=2024-05-08T02:20:51+0200 lvl=error msg="Unexpected error when getting snapshot" error="unknown ancestor" blockNumber=38512430 blockHash=0xad30be67dc6fc9f62716e3923221cb3bc06911fa6d6dc6a1a22190a544218b32
t=2024-05-08T02:20:51+0200 lvl=info msg="Loaded last snap-sync pivot marker" number=35881922
t=2024-05-08T02:20:51+0200 lvl=warn msg="Snapshot maintenance disabled (syncing)"
t=2024-05-08T02:20:51+0200 lvl=info msg="Initialized transaction indexer" range="entire chain"
t=2024-05-08T02:20:51+0200 lvl=warn msg="Sanitizing invalid txpool lifetime" provided=0s updated=3h0m0s
t=2024-05-08T02:20:51+0200 lvl=warn msg="Sanitizing invalid txpool reannounce time" provided=0s updated=1m0s
t=2024-05-08T02:20:51+0200 lvl=warn msg="Switch sync mode from full sync to snap sync" reason="snap sync incomplete"
t=2024-05-08T02:20:51+0200 lvl=info msg="Create votePool successfully"
t=2024-05-08T02:20:51+0200 lvl=warn msg="Sanitizing invalid gasprice oracle price cap" provided=<nil> updated=100000000000
t=2024-05-08T02:20:51+0200 lvl=warn msg="Sanitizing invalid gasprice oracle ignore price" provided=<nil> updated=4
t=2024-05-08T02:20:51+0200 lvl=warn msg="Sanitizing invalid gasprice oracle max header history" provided=0 updated=1
t=2024-05-08T02:20:51+0200 lvl=warn msg="Sanitizing invalid gasprice oracle max block history" provided=0 updated=1
t=2024-05-08T02:20:51+0200 lvl=info msg="Starting peer-to-peer node" instance=Geth/v1.4.6-43b2ffa6-20240429/linux-amd64/go1.22.2

....
....
t=2024-05-08T02:13:23+0200 lvl=warn msg="Ancestor below allowance" peer=13edaeca number=38422430 hash=0x0000000000000000000000000000000000000000000000000000000000000000 allowance=38422430
t=2024-05-08T02:13:23+0200 lvl=warn msg="Synchronisation failed, dropping peer" peer=13edaeca09ce0d2dede2c4d63fb8215de29b0919a3bf7e820f5ca6b5e1bba213 err="retrieved ancestor is invalid"
t=2024-05-08T02:13:23+0200 lvl=warn msg="Synchronisation failed, retrying" peer=13edaeca09ce0d2dede2c4d63fb8215de29b0919a3bf7e820f5ca6b5e1bba213 err="peer is unknown or unhealthy"
t=2024-05-08T02:13:24+0200 lvl=warn msg="Multiple headers for single request" peer=26a80013 headers=0
t=2024-05-08T02:13:24+0200 lvl=warn msg="Synchronisation failed, dropping peer" peer=26a80013e9c2c55799fd062d80700722eebee27fc7de12a8460e150c475906f8 err="action from bad peer ignored: multiple headers (0) for single request"
t=2024-05-08T02:13:24+0200 lvl=warn msg="Synchronisation failed, retrying" peer=26a80013e9c2c55799fd062d80700722eebee27fc7de12a8460e150c475906f8 err="peer is unknown or unhealthy"
t=2024-05-08T02:13:24+0200 lvl=warn msg="Multiple headers for single request" peer=274b8e75 headers=0
t=2024-05-08T02:13:24+0200 lvl=warn msg="Synchronisation failed, dropping peer" peer=274b8e7591d5111f1b343d0492c8d91f42b1cc5850975d8e385bd45aed063c77 err="action from bad peer ignored: multiple headers (0) for single request"
t=2024-05-08T02:13:24+0200 lvl=warn msg="Multiple headers for single request" peer=a56ee3ac headers=0
t=2024-05-08T02:13:24+0200 lvl=warn msg="Synchronisation failed, dropping peer" peer=a56ee3aca2d6f751b379a044349ad8e483a2f60fdc3bac7732454da2bb2570e1 err="action from bad peer ignored: multiple headers (0) for single request"
t=2024-05-08T02:13:24+0200 lvl=warn msg="Synchronisation failed, retrying" peer=a56ee3aca2d6f751b379a044349ad8e483a2f60fdc3bac7732454da2bb2570e1 err="peer is unknown or unhealthy"
t=2024-05-08T02:13:24+0200 lvl=warn msg="Multiple headers for single request" peer=0c7a6fb7 headers=0
t=2024-05-08T02:13:24+0200 lvl=warn msg="Synchronisation failed, dropping peer" peer=0c7a6fb7cca963d9e52c702a81c53905dfa66b9dffb200d331d57d37ef7b493d err="action from bad peer ignored: multiple headers (0) for single request"
t=2024-05-08T02:13:24+0200 lvl=warn msg="Synchronisation failed, retrying" peer=0c7a6fb7cca963d9e52c702a81c53905dfa66b9dffb200d331d57d37ef7b493d err="peer is unknown or unhealthy"
t=2024-05-08T02:13:25+0200 lvl=warn msg="Multiple headers for single request" peer=9dc47f42 headers=0
t=2024-05-08T02:13:25+0200 lvl=warn msg="Synchronisation failed, dropping peer" peer=9dc47f4296c3f3d533f54f139ac8b0d90f429923a50872adab4ac3d59865a173 err="action from bad peer ignored: multiple headers (0) for single request"
t=2024-05-08T02:13:25+0200 lvl=warn msg="Synchronisation failed, retrying" peer=9dc47f4296c3f3d533f54f139ac8b0d90f429923a50872adab4ac3d59865a173 err="peer is unknown or unhealthy"
t=2024-05-08T02:13:25+0200 lvl=warn msg="Multiple headers for single request" peer=66700e71 headers=0
t=2024-05-08T02:13:25+0200 lvl=warn msg="Synchronisation failed, dropping peer" peer=66700e719e0366e3feb5c123f39a6d267904111c7987deadfc83e5d9a12128f9 err="action from bad peer ignored: multiple headers (0) for single request"
t=2024-05-08T02:13:25+0200 lvl=warn msg="Synchronisation failed, retrying" peer=66700e719e0366e3feb5c123f39a6d267904111c7987deadfc83e5d9a12128f9 err="peer is unknown or unhealthy"
t=2024-05-08T02:13:29+0200 lvl=warn msg="Multiple headers for single request" peer=0c7a6fb7 headers=0
t=2024-05-08T02:13:29+0200 lvl=warn msg="Synchronisation failed, dropping peer" peer=0c7a6fb7cca963d9e52c702a81c53905dfa66b9dffb200d331d57d37ef7b493d err="action from bad peer ignored: multiple headers (0) for single request"
t=2024-05-08T02:13:29+0200 lvl=warn msg="Synchronisation failed, retrying" peer=0c7a6fb7cca963d9e52c702a81c53905dfa66b9dffb200d331d57d37ef7b493d err="peer is unknown or unhealthy"
t=2024-05-08T02:13:29+0200 lvl=warn msg="Multiple headers for single request" peer=3e58ca1d headers=0
t=2024-05-08T02:13:29+0200 lvl=warn msg="Synchronisation failed, dropping peer" peer=3e58ca1d20782f09a85dd1352249da27bb8343595fa13cf0f7c9457069ffe00a err="action from bad peer ignored: multiple headers (0) for single request"
t=2024-05-08T02:13:29+0200 lvl=warn msg="Synchronisation failed, retrying" peer=3e58ca1d20782f09a85dd1352249da27bb8343595fa13cf0f7c9457069ffe00a err="peer is unknown or unhealthy"
t=2024-05-08T02:13:50+0200 lvl=warn msg="Synchronisation failed, retrying" peer=8f8e1af6742dc373fae48ec506709d925c1c22cc1ba4dfbdcbec6f07f1e49399 err="peer is unknown or unhealthy"
t=2024-05-08T02:13:59+0200 lvl=warn msg="Synchronisation failed, retrying" peer=11fd523624af8519737e9f2831506e4ee595428ac5486cf7e9b1d96109d9d25b err="peer is unknown or unhealthy"
t=2024-05-08T02:14:00+0200 lvl=warn msg="Multiple headers for single request" peer=11fcb735 headers=0
t=2024-05-08T02:14:00+0200 lvl=warn msg="Synchronisation failed, dropping peer" peer=11fcb735f266720e69bde8372d5c01b39b981daca10ddf3f2f6444105f415390 err="action from bad peer ignored: multiple headers (0) for single request"
t=2024-05-08T02:14:00+0200 lvl=warn msg="Synchronisation failed, retrying" peer=11fcb735f266720e69bde8372d5c01b39b981daca10ddf3f2f6444105f415390 err="peer is unknown or unhealthy"
t=2024-05-08T02:14:07+0200 lvl=warn msg="Ancestor below allowance" peer=10c1fae0 number=38422430 hash=0x0000000000000000000000000000000000000000000000000000000000000000 allowance=38422430
t=2024-05-08T02:14:07+0200 lvl=warn msg="Synchronisation failed, dropping peer" peer=10c1fae0b25ac54c851e46fb65d4c615d694edb20752fac0b01cec23426c865f err="retrieved ancestor is invalid"
t=2024-05-08T02:14:07+0200 lvl=warn msg="Ancestor below allowance" peer=21d746b3 number=38422430 hash=0x0000000000000000000000000000000000000000000000000000000000000000 allowance=38422430
t=2024-05-08T02:14:07+0200 lvl=warn msg="Synchronisation failed, dropping peer" peer=21d746b3f32a5321bacef09b5797ef6de092238c12d4652da15dc4bb2114c3d7 err="retrieved ancestor is invalid"
t=2024-05-08T02:14:07+0200 lvl=warn msg="Synchronisation failed, retrying" peer=21d746b3f32a5321bacef09b5797ef6de092238c12d4652da15dc4bb2114c3d7 err="peer is unknown or unhealthy"
t=2024-05-08T02:14:10+0200 lvl=warn msg="Multiple headers for single request" peer=0c985054 headers=0
t=2024-05-08T02:14:10+0200 lvl=warn msg="Synchronisation failed, dropping peer" peer=0c985054f7ad7826b9e643b0c371ef856f891e1df630cecfbaa5ca4c3ccdeaa6 err="action from bad peer ignored: multiple headers (0) for single request"
t=2024-05-08T02:14:10+0200 lvl=warn msg="Synchronisation failed, retrying" peer=0c985054f7ad7826b9e643b0c371ef856f891e1df630cecfbaa5ca4c3ccdeaa6 err="peer is unknown or unhealthy"
t=2024-05-08T02:14:11+0200 lvl=warn msg="Multiple headers for single request" peer=b0a69ac2 headers=0
t=2024-05-08T02:14:11+0200 lvl=warn msg="Synchronisation failed, dropping peer" peer=b0a69ac2b08d3c1ee83ac6e01e5ab50bda9d4839e474f2d8fc7c36dc285f3626 err="action from bad peer ignored: multiple headers (0) for single request"
t=2024-05-08T02:14:11+0200 lvl=warn msg="Synchronisation failed, retrying" peer=b0a69ac2b08d3c1ee83ac6e01e5ab50bda9d4839e474f2d8fc7c36dc285f3626 err="peer is unknown or unhealthy"
t=2024-05-08T02:14:36+0200 lvl=warn msg="Multiple headers for single request" peer=3e941471 headers=0
t=2024-05-08T02:14:36+0200 lvl=warn msg="Synchronisation failed, dropping peer" peer=3e9414713d5b4eee3c48f743a68128976b086e838e1d8c549b5e3f30383f6af1 err="action from bad peer ignored: multiple headers (0) for single request"
t=2024-05-08T02:14:36+0200 lvl=warn msg="Synchronisation failed, retrying" peer=3e9414713d5b4eee3c48f743a68128976b086e838e1d8c549b5e3f30383f6af1 err="peer is unknown or unhealthy"
t=2024-05-08T02:14:51+0200 lvl=warn msg="Ancestor below allowance" peer=13edaeca number=38422430 hash=0x0000000000000000000000000000000000000000000000000000000000000000 allowance=38422430
t=2024-05-08T02:14:51+0200 lvl=warn msg="Synchronisation failed, dropping peer" peer=13edaeca09ce0d2dede2c4d63fb8215de29b0919a3bf7e820f5ca6b5e1bba213 err="retrieved ancestor is invalid"
t=2024-05-08T02:14:51+0200 lvl=warn msg="Synchronisation failed, retrying" peer=13edaeca09ce0d2dede2c4d63fb8215de29b0919a3bf7e820f5ca6b5e1bba213 err="peer is unknown or unhealthy"
t=2024-05-08T02:15:00+0200 lvl=warn msg="Multiple headers for single request" peer=0c985054 headers=0
t=2024-05-08T02:15:00+0200 lvl=warn msg="Synchronisation failed, dropping peer" peer=0c985054f7ad7826b9e643b0c371ef856f891e1df630cecfbaa5ca4c3ccdeaa6 err="action from bad peer ignored: multiple headers (0) for single request"
t=2024-05-08T02:15:00+0200 lvl=warn msg="Synchronisation failed, retrying" peer=0c985054f7ad7826b9e643b0c371ef856f891e1df630cecfbaa5ca4c3ccdeaa6 err="peer is unknown or unhealthy"
t=2024-05-08T02:15:10+0200 lvl=warn msg="Multiple headers for single request" peer=919e705d headers=0
t=2024-05-08T02:15:10+0200 lvl=warn msg="Synchronisation failed, dropping peer" peer=919e705de10a9ac4ec7870eb6037fd79362c879f61b486d6a3732380c26ec7a8 err="action from bad peer ignored: multiple headers (0) for single request"
t=2024-05-08T02:15:10+0200 lvl=warn msg="Synchronisation failed, retrying" peer=919e705de10a9ac4ec7870eb6037fd79362c879f61b486d6a3732380c26ec7a8 err="peer is unknown or unhealthy"
t=2024-05-08T02:15:31+0200 lvl=warn msg="Synchronisation failed, retrying" peer=429f5d6f875fe850a241064568b588d1c1e94e75b22cf495c563ba5a5f9bae34 err="peer is unknown or unhealthy"
t=2024-05-08T02:15:41+0200 lvl=warn msg="Multiple headers for single request" peer=d3c37101 headers=0
t=2024-05-08T02:15:41+0200 lvl=warn msg="Synchronisation failed, dropping peer" peer=d3c371011dc3894b4ca346adb8ef30cd8ad1dbca4ec217aedcbd09241e9783ba err="action from bad peer ignored: multiple headers (0) for single request"
t=2024-05-08T02:15:41+0200 lvl=warn msg="Synchronisation failed, retrying" peer=d3c371011dc3894b4ca346adb8ef30cd8ad1dbca4ec217aedcbd09241e9783ba err="peer is unknown or unhealthy"
t=2024-05-08T02:15:53+0200 lvl=error msg="Bsc extension Handshake failed" peer=53e93867 err=EOF
t=2024-05-08T02:15:57+0200 lvl=warn msg="Multiple headers for single request" peer=d7cae44f headers=0
t=2024-05-08T02:15:57+0200 lvl=warn msg="Synchronisation failed, dropping peer" peer=d7cae44f1032dd708e8f481323db6ca4b468f02c58ec10d81ac93d9203b2054d err="action from bad peer ignored: multiple headers (0) for single request"
t=2024-05-08T02:15:58+0200 lvl=warn msg="Multiple headers for single request" peer=99724741 headers=0
t=2024-05-08T02:15:58+0200 lvl=warn msg="Synchronisation failed, dropping peer" peer=99724741653aa1ba9226f5d8f1828deaa6bd6da3b3ae9bbdf2f7b2fb0a581714 err="action from bad peer ignored: multiple headers (0) for single request"
t=2024-05-08T02:15:58+0200 lvl=warn msg="Synchronisation failed, retrying" peer=99724741653aa1ba9226f5d8f1828deaa6bd6da3b3ae9bbdf2f7b2fb0a581714 err="peer is unknown or unhealthy"
t=2024-05-08T02:16:14+0200 lvl=warn msg="Multiple headers for single request" peer=d3558f3b headers=0
t=2024-05-08T02:16:14+0200 lvl=warn msg="Synchronisation failed, dropping peer" peer=d3558f3b3f926dc85d84875a81f7db12fbeccc2b8aa52433a596ce22eab949c3 err="action from bad peer ignored: multiple headers (0) for single request"
t=2024-05-08T02:16:14+0200 lvl=warn msg="Synchronisation failed, retrying" peer=d3558f3b3f926dc85d84875a81f7db12fbeccc2b8aa52433a596ce22eab949c3 err="peer is unknown or unhealthy"
t=2024-05-08T02:16:36+0200 lvl=warn msg="Multiple headers for single request" peer=0c985054 headers=0
t=2024-05-08T02:16:36+0200 lvl=warn msg="Synchronisation failed, dropping peer" peer=0c985054f7ad7826b9e643b0c371ef856f891e1df630cecfbaa5ca4c3ccdeaa6 err="action from bad peer ignored: multiple headers (0) for single request"
t=2024-05-08T02:16:36+0200 lvl=warn msg="Synchronisation failed, retrying" peer=0c985054f7ad7826b9e643b0c371ef856f891e1df630cecfbaa5ca4c3ccdeaa6 err="peer is unknown or unhealthy"
t=2024-05-08T02:16:41+0200 lvl=warn msg="Synchronisation failed, retrying" peer=a2c8bcb4c21b229a1845875b2b45faaa4d30921f0a641004ae2992b5aef857e4 err="peer is unknown or unhealthy"
t=2024-05-08T02:17:19+0200 lvl=error msg="Bsc extension Handshake failed" peer=c884bfa8 err=EOF
t=2024-05-08T02:17:19+0200 lvl=warn msg="Ancestor below allowance" peer=9b2c0b66 number=38422430 hash=0x0000000000000000000000000000000000000000000000000000000000000000 allowance=38422430
t=2024-05-08T02:17:19+0200 lvl=warn msg="Synchronisation failed, dropping peer" peer=9b2c0b66c7f2e75f57096bb7ea9fcedcd01fd59e7396b145fbc9723c06a0cb2e err="retrieved ancestor is invalid"
t=2024-05-08T02:17:19+0200 lvl=warn msg="Synchronisation failed, retrying" peer=9b2c0b66c7f2e75f57096bb7ea9fcedcd01fd59e7396b145fbc9723c06a0cb2e err="peer is unknown or unhealthy"
t=2024-05-08T02:17:33+0200 lvl=warn msg="Multiple headers for single request" peer=0c985054 headers=0
t=2024-05-08T02:17:33+0200 lvl=warn msg="Synchronisation failed, dropping peer" peer=0c985054f7ad7826b9e643b0c371ef856f891e1df630cecfbaa5ca4c3ccdeaa6 err="action from bad peer ignored: multiple headers (0) for single request"
t=2024-05-08T02:17:33+0200 lvl=warn msg="Synchronisation failed, retrying" peer=0c985054f7ad7826b9e643b0c371ef856f891e1df630cecfbaa5ca4c3ccdeaa6 err="peer is unknown or unhealthy"

When submitting logs: please submit them as text and not screenshots.

[du5]

btw, In v1.4.5 version, prune can work properly

[sysvm]

@du5 Which snapshot do you use to prune?

[du5]

@du5 Which snapshot do you use to prune?

--history.transactions=0 --syncmode=full --db.engine=pebble --state.scheme=hash

[sysvm]

@du5 Which snapshot do you use to prune?

--history.transactions=0 --syncmode=full --db.engine=pebble --state.scheme=hash

Can you give me a snapshot that you'are using to prune block? Do you use muti-database to store block data?

[sysvm]

@du5 I want to ensure the step you are using:

1. Use geth snapshot prune-block and geth snapshot prune-state to prune a complete hash data.
2. Start importing blocks in the data of step 1. Can you give me the geth flag you are using to run node?

Is this right?

[du5]

link #2436

[jingjunLi]

Hi, @du5
The cause of the problem is: In the multi-database PR, the introduction of "uses the finalized block tag as the indicator for chain freezing" in the chainDb resulted in the retention of only a few dozen blocks. After executing prune-block, a restart typically triggers a "rewound" action ("Head state missing, repairing"), rewinding to blocks that do not exist in the chainDb.Since the block data does not exist at this time, it is not possible to perform block tracking.
for example:
t1: block height 38486723, chaindb blocks [38486700- 38486723], you may rewound to 38482500, but this block was deleted;

The issue can be resolved by running the command:
./geth_linux snapshot prune-block --datadir PATH --datadir.ancient PATH/chaindata/ancient/chain --block-amount-reserved 90000
This command allows specifying the block-amount-reserved parameter to reserve a sufficient number of blocks.

We will work on optimizing the subsequent code to address this issue as soon as possible.

[du5]

Hi, @du5 The cause of the problem is: In the multi-database PR, the introduction of "uses the finalized block tag as the indicator for chain freezing" in the chainDb resulted in the retention of only a few dozen blocks. After executing prune-block, a restart typically triggers a "rewound" action ("Head state missing, repairing"), rewinding to blocks that do not exist in the chainDb.Since the block data does not exist at this time, it is not possible to perform block tracking. for example: t1: block height 38486723, chaindb blocks [38486700- 38486723], you may rewound to 38482500, but this block was deleted;

The issue can be resolved by running the command: ./geth_linux snapshot prune-block --datadir PATH --datadir.ancient PATH/chaindata/ancient/chain --block-amount-reserved 90000 This command allows specifying the block-amount-reserved parameter to reserve a sufficient number of blocks.

We will work on optimizing the subsequent code to address this issue as soon as possible.

thanks for your help

[du5]

Hi, @du5 The cause of the problem is: In the multi-database PR, the introduction of "uses the finalized block tag as the indicator for chain freezing" in the chainDb resulted in the retention of only a few dozen blocks. After executing prune-block, a restart typically triggers a "rewound" action ("Head state missing, repairing"), rewinding to blocks that do not exist in the chainDb.Since the block data does not exist at this time, it is not possible to perform block tracking. for example: t1: block height 38486723, chaindb blocks [38486700- 38486723], you may rewound to 38482500, but this block was deleted;

The issue can be resolved by running the command: ./geth_linux snapshot prune-block --datadir PATH --datadir.ancient PATH/chaindata/ancient/chain --block-amount-reserved 90000 This command allows specifying the block-amount-reserved parameter to reserve a sufficient number of blocks.

We will work on optimizing the subsequent code to address this issue as soon as possible.

prune

➜ geth snapshot prune-block --datadir PATH --datadir.ancient PATH/geth/chaindata/ancient/chain --block-amount-reserved 90000
INFO [05-15|02:36:36.425] Maximum peer count                       ETH=50 total=50
INFO [05-15|02:36:36.429] Set global gas cap                       cap=50,000,000
INFO [05-15|02:36:36.429] Initializing the KZG library             backend=gokzg
INFO [05-15|02:36:36.442] Using pebble as the backing database
INFO [05-15|02:36:36.442] Allocated cache and file handles         database=/opt/geth.fast2/geth/chaindata cache=409.00MiB handles=524,288 "memory table"=102.25MiB
INFO [05-15|02:36:37.771] Found legacy ancient chain path          location=/opt/geth.fast2/geth/chaindata/ancient/chain
INFO [05-15|02:36:37.808] Opened ancient database                  database=/opt/geth.fast2/geth/chaindata/ancient/chain readonly=false frozen=38,721,904
INFO [05-15|02:36:38.488] file lock existed, waiting for prune recovery and continue err=<nil>
INFO [05-15|02:36:38.488] RecoverInterruption for block prune
INFO [05-15|02:36:38.488] New ancientDB_backup did not exist in interruption scenario
INFO [05-15|02:36:38.489] Using pebble as the backing database
INFO [05-15|02:36:38.489] Allocated cache and file handles         database=/opt/geth.fast2/geth/chaindata cache=512.00MiB handles=524,288 "memory table"=128.00MiB
INFO [05-15|02:36:38.517] Found legacy ancient chain path          location=/opt/geth.fast2/geth/chaindata/ancient/chain
INFO [05-15|02:36:38.517] Opened ancient database                  database=/opt/geth.fast2/geth/chaindata/ancient/chain readonly=false frozen=38,721,904
INFO [05-15|02:36:38.518] chainDB opened successfully
INFO [05-15|02:36:38.518] the number of items in ancientDB is      itemsOfAncient=239,510
INFO [05-15|02:36:38.518] the oldOffSet is                         oldOffSet=38,482,394
INFO [05-15|02:36:38.518] new offset/new startBlockNumber is       "new offset"=38,631,904
INFO [05-15|02:36:38.520] Opened ancient database                  database=/opt/geth.fast2/geth/chaindata/ancient/chain_back readonly=false frozen=38,631,904
INFO [05-15|02:36:38.520] prune info                               "old offset"=38,482,394 "number of items in ancientDB"=239,510 "amount to reserve"=90000
INFO [05-15|02:36:38.520] new offset/new startBlockNumber recorded successfully  "new offset"=38,631,904
INFO [05-15|02:36:43.521] block backup process running successfully "current blockNumber for backup"=38,634,259
INFO [05-15|02:36:48.521] block backup process running successfully "current blockNumber for backup"=38,637,734
INFO [05-15|02:36:53.522] block backup process running successfully "current blockNumber for backup"=38,642,135
INFO [05-15|02:36:58.523] block backup process running successfully "current blockNumber for backup"=38,645,184
INFO [05-15|02:37:03.524] block backup process running successfully "current blockNumber for backup"=38,647,775
INFO [05-15|02:37:08.524] block backup process running successfully "current blockNumber for backup"=38,650,309
INFO [05-15|02:37:13.527] block backup process running successfully "current blockNumber for backup"=38,652,635
^[INFO [05-15|02:37:18.528] block backup process running successfully "current blockNumber for backup"=38,654,886
INFO [05-15|02:37:23.531] block backup process running successfully "current blockNumber for backup"=38,657,131
INFO [05-15|02:37:28.533] block backup process running successfully "current blockNumber for backup"=38,659,208
INFO [05-15|02:37:33.534] block backup process running successfully "current blockNumber for backup"=38,661,422
INFO [05-15|02:37:38.535] block backup process running successfully "current blockNumber for backup"=38,663,895
INFO [05-15|02:37:43.535] block backup process running successfully "current blockNumber for backup"=38,667,098
INFO [05-15|02:37:48.536] block backup process running successfully "current blockNumber for backup"=38,670,661
INFO [05-15|02:37:53.536] block backup process running successfully "current blockNumber for backup"=38,673,295
INFO [05-15|02:37:58.538] block backup process running successfully "current blockNumber for backup"=38,675,520
INFO [05-15|02:38:03.538] block backup process running successfully "current blockNumber for backup"=38,677,954
INFO [05-15|02:38:08.538] block backup process running successfully "current blockNumber for backup"=38,680,242
INFO [05-15|02:38:13.545] block backup process running successfully "current blockNumber for backup"=38,682,200
INFO [05-15|02:38:18.545] block backup process running successfully "current blockNumber for backup"=38,684,336
INFO [05-15|02:38:23.547] block backup process running successfully "current blockNumber for backup"=38,686,365
INFO [05-15|02:38:28.552] block backup process running successfully "current blockNumber for backup"=38,688,289
INFO [05-15|02:38:33.554] block backup process running successfully "current blockNumber for backup"=38,689,947
INFO [05-15|02:38:38.555] block backup process running successfully "current blockNumber for backup"=38,692,320
INFO [05-15|02:38:43.556] block backup process running successfully "current blockNumber for backup"=38,695,311
INFO [05-15|02:38:48.557] block backup process running successfully "current blockNumber for backup"=38,698,731
INFO [05-15|02:38:53.558] block backup process running successfully "current blockNumber for backup"=38,701,651
INFO [05-15|02:38:58.560] block backup process running successfully "current blockNumber for backup"=38,704,094
INFO [05-15|02:39:03.561] block backup process running successfully "current blockNumber for backup"=38,706,614
INFO [05-15|02:39:08.563] block backup process running successfully "current blockNumber for backup"=38,708,783
INFO [05-15|02:39:13.564] block backup process running successfully "current blockNumber for backup"=38,711,104
INFO [05-15|02:39:18.565] block backup process running successfully "current blockNumber for backup"=38,713,441
INFO [05-15|02:39:23.572] block backup process running successfully "current blockNumber for backup"=38,715,618
INFO [05-15|02:39:28.572] block backup process running successfully "current blockNumber for backup"=38,717,492
INFO [05-15|02:39:33.573] block backup process running successfully "current blockNumber for backup"=38,719,600
INFO [05-15|02:39:38.040] block back up done                       "current start blockNumber in ancientDB"=38,631,904
INFO [05-15|02:39:38.067] Block pruning BackUp successfully        "time duration since start is"=2m59.578s
INFO [05-15|02:39:38.172] Block prune successfully

start geth

➜ geth --config config.toml --history.transactions=0 --syncmode=full --tries-verify-mode=none --db.engine=pebble --datadir geth.fast
t=2024-05-15T03:00:57+0200 lvl=info msg="Use config state scheme" config=hash
t=2024-05-15T03:00:57+0200 lvl=info msg="Automatically disables snap protocol due to verify mode" mode=none
t=2024-05-15T03:00:57+0200 lvl=info msg="Set global gas cap" cap=50000000
t=2024-05-15T03:00:57+0200 lvl=info msg="Initializing the KZG library" backend=gokzg
t=2024-05-15T03:00:57+0200 lvl=info msg="Using pebble as the backing database"
t=2024-05-15T03:00:57+0200 lvl=info msg="Allocated cache and file handles" database=/opt/test/geth.fast/geth/chaindata cache="1.60 GiB" handles=524288 "memory table"="409.50 MiB"
t=2024-05-15T03:00:57+0200 lvl=info msg="Opened ancient database" database=/opt/test/geth.fast/geth/chaindata/ancient/chain readonly=false frozen=38721904
t=2024-05-15T03:00:57+0200 lvl=info msg="State scheme set by user" scheme=hash
t=2024-05-15T03:00:57+0200 lvl=info msg="Allocated trie memory caches" clean="614.00 MiB" dirty="1024.00 MiB"
t=2024-05-15T03:00:57+0200 lvl=info msg=Parlia chainConfig="{ChainID: 56 Homestead: 0 DAO: <nil> DAOSupport: false EIP150: 0 EIP155: 0 EIP158: 0 Byzantium: 0 Constantinople: 0 Petersburg: 0 Istanbul: 0, Muir Glacier: 0, Ramanujan: 0, Niels: 0, MirrorSync: 5184000, Bruno: 13082000, Berlin: 31302048, YOLO v3: <nil>, CatalystBlock: <nil>, London: 31302048, ArrowGlacier: <nil>, MergeFork:<nil>, Euler: 18907621, Gibbs: 23846001, Nano: 21962149, Moran: 22107423, Planck: 27281024,Luban: 29020050, Plato: 30720096, Hertz: 31302048, Hertzfix: 34140700, ShanghaiTime: 1705996800, KeplerTime: 1705996800, FeynmanTime: 1713419340, FeynmanFixTime: 1713419340, CancunTime: <nil>, Engine: parlia}"
t=2024-05-15T03:00:57+0200 lvl=info msg="Initialising Ethereum protocol" network=56 dbversion=8
t=2024-05-15T03:00:57+0200 lvl=info msg="Initialised chain configuration" config="{ChainID: 56 Homestead: 0 DAO: <nil> DAOSupport: false EIP150: 0 EIP155: 0 EIP158: 0 Byzantium: 0 Constantinople: 0 Petersburg: 0 Istanbul: 0, Muir Glacier: 0, Ramanujan: 0, Niels: 0, MirrorSync: 5184000, Bruno: 13082000, Berlin: 31302048, YOLO v3: <nil>, CatalystBlock: <nil>, London: 31302048, ArrowGlacier: <nil>, MergeFork:<nil>, Euler: 18907621, Gibbs: 23846001, Nano: 21962149, Moran: 22107423, Planck: 27281024,Luban: 29020050, Plato: 30720096, Hertz: 31302048, Hertzfix: 34140700, ShanghaiTime: 1705996800, KeplerTime: 1705996800, FeynmanTime: 1713419340, FeynmanFixTime: 1713419340, CancunTime: <nil>, Engine: parlia}"
t=2024-05-15T03:00:58+0200 lvl=info msg="Loaded most recent local block" number=38722533 hash=0xf9f6ca86c6ee569ff1cb73ff8b7dc8d3725e1d5d55e7a3605e74fb70aac31088 root=0x8f31932a65b59f0ca9cbd8fbc9096140075e048c70e9cd21e771272c5e8eead0 td=76932116 age=6h11m1s
t=2024-05-15T03:00:58+0200 lvl=info msg="Loaded most recent local finalized block" number=38722531 hash=0x2d856153b85bc3b09a8ded03f5ff4059c81583e6db8c81668997a7484c2256c2 root=0xef931cd78d64981d3b9a2f19787ccfec92e7f2efbaa92ebde861ead0097a5753 td=76932113 age=6h11m8s
t=2024-05-15T03:00:58+0200 lvl=info msg="Loaded last snap-sync pivot marker" number=35881922
t=2024-05-15T03:00:58+0200 lvl=warn msg="Head state missing, repairing" number=38722533 hash=0xf9f6ca86c6ee569ff1cb73ff8b7dc8d3725e1d5d55e7a3605e74fb70aac31088 diskRoot=0xf5ed38b113869315e7b11acea2df2e2c3c726a9e7f2f43d12fe8c43c4b252246
t=2024-05-15T03:00:58+0200 lvl=info msg="Snapshot loaded" diskRoot=0xf5ed38b113869315e7b11acea2df2e2c3c726a9e7f2f43d12fe8c43c4b252246 root=0x8f31932a65b59f0ca9cbd8fbc9096140075e048c70e9cd21e771272c5e8eead0
t=2024-05-15T03:00:58+0200 lvl=info msg="Rewound to block with state" number=38722375 hash=0xc8e330e3de53ad2a63985d50da15b196673113b09e66767fdb91801194f677bf
t=2024-05-15T03:00:59+0200 lvl=warn msg="Snapshot is not continuous with chain" snaproot=0x8f31932a65b59f0ca9cbd8fbc9096140075e048c70e9cd21e771272c5e8eead0 chainroot=0xf5ed38b113869315e7b11acea2df2e2c3c726a9e7f2f43d12fe8c43c4b252246
t=2024-05-15T03:00:59+0200 lvl=info msg="Snapshot loaded" diskRoot=0xf5ed38b113869315e7b11acea2df2e2c3c726a9e7f2f43d12fe8c43c4b252246 root=0xf5ed38b113869315e7b11acea2df2e2c3c726a9e7f2f43d12fe8c43c4b252246
t=2024-05-15T03:00:59+0200 lvl=info msg="Rewound to block with state" number=38722375 hash=0xc8e330e3de53ad2a63985d50da15b196673113b09e66767fdb91801194f677bf
t=2024-05-15T03:00:59+0200 lvl=info msg="Loaded most recent local block" number=38722375 hash=0xc8e330e3de53ad2a63985d50da15b196673113b09e66767fdb91801194f677bf root=0xf5ed38b113869315e7b11acea2df2e2c3c726a9e7f2f43d12fe8c43c4b252246 td=76931824 age=6h19m8s
t=2024-05-15T03:00:59+0200 lvl=info msg="Loaded most recent local finalized block" number=38722373 hash=0x6a99e96559878c5d77f97cf7e10e4a917105d905ccac1a6335e4bb5d0171c4ed root=0xade8b5fefee38a1b7e7fd33b7a9b41f22ab8382b83199fae187865cbc5cdfeb8 td=76931820 age=6h19m14s
t=2024-05-15T03:00:59+0200 lvl=info msg="Loaded last snap-sync pivot marker" number=35881922
t=2024-05-15T03:00:59+0200 lvl=warn msg="Enabling snapshot recovery" chainhead=38722375 diskbase=38722375
t=2024-05-15T03:01:00+0200 lvl=warn msg="Snapshot is not continuous with chain" snaproot=0x8f31932a65b59f0ca9cbd8fbc9096140075e048c70e9cd21e771272c5e8eead0 chainroot=0xf5ed38b113869315e7b11acea2df2e2c3c726a9e7f2f43d12fe8c43c4b252246
t=2024-05-15T03:01:00+0200 lvl=info msg="Snapshot loaded" diskRoot=0xf5ed38b113869315e7b11acea2df2e2c3c726a9e7f2f43d12fe8c43c4b252246 root=0xf5ed38b113869315e7b11acea2df2e2c3c726a9e7f2f43d12fe8c43c4b252246
t=2024-05-15T03:01:00+0200 lvl=info msg="Initialized transaction indexer" range="entire chain"
t=2024-05-15T03:01:00+0200 lvl=warn msg="Sanitizing invalid txpool lifetime" provided=0s updated=3h0m0s
t=2024-05-15T03:01:00+0200 lvl=warn msg="Sanitizing invalid txpool reannounce time" provided=0s updated=1m0s
t=2024-05-15T03:01:00+0200 lvl=info msg="Create votePool successfully"
t=2024-05-15T03:01:00+0200 lvl=warn msg="Sanitizing invalid gasprice oracle price cap" provided=<nil> updated=100000000000
t=2024-05-15T03:01:00+0200 lvl=warn msg="Sanitizing invalid gasprice oracle ignore price" provided=<nil> updated=4
t=2024-05-15T03:01:00+0200 lvl=warn msg="Sanitizing invalid gasprice oracle max header history" provided=0 updated=1
t=2024-05-15T03:01:00+0200 lvl=warn msg="Sanitizing invalid gasprice oracle max block history" provided=0 updated=1
t=2024-05-15T03:01:00+0200 lvl=info msg="Starting peer-to-peer node" instance=Geth/v1.4.6-43b2ffa6-20240429/linux-amd64/go1.22.2
t=2024-05-15T03:01:00+0200 lvl=info msg="New local node record" seq=1715240731947 id=9d1f46dc2faac029cd07165f33e1b806bc8e2d8d3ea07ade5e4e9ac404778ae1 ip=127.0.0.1 udp=30311 tcp=30311
t=2024-05-15T03:01:00+0200 lvl=info msg="Started P2P networking" self=enode://81de309872ef2f11d72f6aeb48744667c37ec6693ca93ba1b638845d4a347f0d8522257b834c90d65724a587e840e03dba26282276606a291b559324582335bd@127.0.0.1:30311
t=2024-05-15T03:01:00+0200 lvl=info msg="IPC endpoint opened" url=/opt/test/geth.fast/geth.ipc
...
t=2024-05-15T03:01:25+0200 lvl=info msg="Imported new chain segment" number=38722382 hash=0xd781576a6f5f8201fc3de05d119700d1e2d0abc7f9aed4d2219311b3c7b62d16 miner=0xfC1004C0f296Ec3Df4F6762E9EabfcF20EB304a2 blocks=7 txs=644 blobs=0 mgas=76.244849 elapsed=1.168s mgasps=65.2735813708198 age=6h19m13s snapdiffs="4.08 MiB" triedirty="0.00 B" trieimutabledirty="0.00 B"

It seems that the problem has been solved, after adding the --block-amount-reserved=90000 parameter

[du5]

This parameter was not needed before. I decided to open this issue so that people with the same problem can check it.