Cause "Failed to journal state snapshot" error when shutting down Geth

[junichi-tanaka]

Hi team,

I faced "Failed to journal state snapshot" error and rebuilding state snapshot twice. I would like to know whether this is a normal behavior or not.

System information

Geth version: ethereum/client-go:v1.15.10 CL client & version: chainsafe/lodestar:v1.29.0 OS & Version: Linux (Ubuntu 22.04

geth
 --mainnet
 --syncmode=snap
 --gcmode=archive
 --datadir=/data
 --http
 --http.api=debug,eth,net,web3,admin,txpool,engine
 --http.addr=0.0.0.0
 --http.port=8545
 --http.vhosts=*
 --http.corsdomain=*
 --rpc.gascap=100000000
 --rpc.batch-response-max-size=50000000
 --graphql
 --graphql.vhosts=*
 --graphql.corsdomain=*
 --authrpc.addr=0.0.0.0
 --authrpc.vhosts=*
 --authrpc.jwtsecret=/secrets/jwt-secret-1
 --port=30303
 --maxpeers=100
 --cache=4096
 --metrics
 --metrics.addr=0.0.0.0
 --metrics.port=8008
 --verbosity=3
 --rpc.txfeecap=15

Expected behaviour

• shutting down a Geth instance without error
• Then, restart it without rebuilding state snapshot

Actual behaviour

• When shutting down a Geth instance with Failed to journal state snapshot
• Then, rebuilding state snapshot due to head doesn't match snapshot error

Geth1

shutting down

INFO [05-07|01:16:14.679] Got interrupt, shutting down...
INFO [05-07|01:16:14.681] HTTP server stopped                      endpoint=[::]:8545
INFO [05-07|01:16:15.629] Imported new potential chain segment     number=22,428,467 hash=ca968e..31c965 blocks=1 txs=225  mgas=35.988 elapsed=14.909s       mgasps=2.414   triedirty=0.00B
WARN [05-07|01:16:15.632] Ignoring already known beacon payload    number=22,428,467 hash=ca968e..31c965 age=16s
INFO [05-07|01:16:15.729] HTTP server stopped                      endpoint=[::]:8551
INFO [05-07|01:16:15.732] IPC endpoint closed                      url=/data/geth.ipc
INFO [05-07|01:16:15.734] Ethereum protocol stopped
INFO [05-07|01:16:15.734] Transaction pool stopped
ERROR[05-07|01:16:15.788] Failed to journal state snapshot         err="snapshot [0x56aac4350b6092db078c380d4fac950ab299b968e860621b9fac5322fce40fc0] missing"
INFO [05-07|01:16:15.789] Blockchain stopped

restart

INFO [05-07|01:58:05.247] Loaded most recent local block           number=22,428,470 hash=4be369..36b1ac age=41m30s
INFO [05-07|01:58:05.247] Loaded most recent local finalized block number=22,428,393 hash=d3e55d..7a20b8 age=56m54s
INFO [05-07|01:58:05.247] Loaded last snap-sync pivot marker       number=21,417,004
WARN [05-07|01:58:05.661] Loaded snapshot journal                  diskroot=56aac4..e40fc0 diffs=unmatched
WARN [05-07|01:58:05.661] Failed to load snapshot                  err="head doesn't match snapshot: have 0x56aac4350b6092db078c380d4fac950ab299b968e860621b9fac5322fce40fc0, want 0xa72786c0763dc9c13950ec72ccf5a2473031d6bef677d20af20d7eda6f727b52"
INFO [05-07|01:58:06.448] Rebuilding state snapshot
INFO [05-07|01:58:06.453] Initialized transaction indexer          range="entire chain"
INFO [05-07|01:58:06.453] Resuming state snapshot generation       root=a72786..727b52 accounts=0 slots=0 storage=0.00B dangling=0 elapsed=4.809ms

Geth2

shutting down

INFO [05-09|04:26:20.853] Got interrupt, shutting down...
INFO [05-09|04:26:20.855] HTTP server stopped                      endpoint=[::]:8545
INFO [05-09|04:26:20.856] HTTP server stopped                      endpoint=[::]:8551
INFO [05-09|04:26:20.865] IPC endpoint closed                      url=/data/geth.ipc
INFO [05-09|04:26:20.866] Ethereum protocol stopped
INFO [05-09|04:26:20.867] Transaction pool stopped
ERROR[05-09|04:26:20.927] Failed to journal state snapshot         err="snapshot [0x45ba4ae309d068088f5e11a6041cca07553f82294e133f091b7e1347052ce866] missing"
INFO [05-09|04:26:20.928] Blockchain stopped

restart

INFO [05-09|04:34:32.676] Loaded most recent local block           number=22,443,535 hash=d219ef..40c4c7 age=8m21s
INFO [05-09|04:34:32.676] Loaded most recent local finalized block number=22,443,472 hash=5fc539..0cf1b8 age=21m21s
INFO [05-09|04:34:32.676] Loaded last snap-sync pivot marker       number=21,416,947
WARN [05-09|04:34:32.874] Loaded snapshot journal                  diskroot=451c36..92d621 diffs=unmatched
WARN [05-09|04:34:32.874] Failed to load snapshot                  err="head doesn't match snapshot: have 0x451c360a2b4c05e0147845a4465eeb5c3faac593a736308ffb2b5b40fb92d621, want 0x45ba4ae309d068088f5e11a6041cca07553f82294e133f091b7e1347052ce866"
INFO [05-09|04:34:32.922] Rebuilding state snapshot
INFO [05-09|04:34:32.936] Initialized transaction indexer          range="entire chain"
INFO [05-09|04:34:32.936] Resuming state snapshot generation       root=45ba4a..2ce866 accounts=0 slots=0 storage=0.00B dangling=0 elapsed=14.239ms

Steps to reproduce the behaviour

1. Stop a running Geth instance (with syncmode=snap?)
2. Restart it