Unable to initialize backfill verifier: no state with blockroot

[terencechain]

In the latest commit, dbcf5c29cdbfd24757a1d6b4d67d76e9c56bd167, we encountered an error that prevents the beacon node from starting up. To reproduce it, first run --enable-experimental-backfill --force-clear-db, then run --enable-experimental-backfill only for the second run.

It seems to me that the original root state was deleted during backfilling.

Log:

[2024-01-23 09:12:03]  INFO Starting pprof server addr=http://127.0.0.1:6060/debug/pprof
[2024-01-23 09:12:03]  INFO Finished reading JWT secret from /tmp/jwt.hex
[2024-01-23 09:12:03]  WARN flags: Running on the Prater Testnet
[2024-01-23 09:12:03]  WARN flags: Enabled feature flag enable-eip-4881=Enables the deposit tree specified in EIP-4881.
[2024-01-23 09:12:03]  WARN node: In order to receive transaction fees from proposing blocks, you must provide flag --suggested-fee-recipient with a valid ethereum address when starting your beacon node. Please see our documentation for more information on this requirement (https://docs.prylabs.network/docs/execution-node/fee-recipient).
[2024-01-23 09:12:03] DEBUG node: Starting DB
[2024-01-23 09:12:03]  INFO node: Checking DB database-path=/Users/t/goerli/beaconchaindata
[2024-01-23 09:12:03]  INFO db: Opening Bolt DB at /Users/t/goerli/beaconchaindata/beaconchain.db
[2024-01-23 09:12:03]  WARN genesis: database contains genesis with htr=0x895390e92edc03df7096e9f51e51896e8dbe6e7e838180dadbfd869fdd77a659, ignoring remote genesis state parameter
[2024-01-23 09:12:03]  WARN origin checkpoint root 0xb43ed4b7062d88a72ae9c087b36b12d9dbbb36101dbe57329f664ad7b6d24876 found in db, ignoring checkpoint sync flags
[2024-01-23 09:12:03]  INFO node: Deposit contract: 0xff50ed3d0ec03ac01d4c79aad74928bff48a7b2b
[2024-01-23 09:12:03] DEBUG node: Starting Slashing DB
[2024-01-23 09:12:03] DEBUG node: Registering P2P Service
[2024-01-23 09:12:03]  INFO p2p: Running node with peer id of 16Uiu2HAmQLbbtyP3mk3JWmBy7QT1ntoSntA6koJsrcXvETCgwPoG
[2024-01-23 09:12:03] DEBUG p2p: ECDSA private key generated
[2024-01-23 09:12:03] DEBUG node: Starting State Gen
[2024-01-23 09:12:04] DEBUG state-gen: Replaying state diff=352 endSlot=7457120 startSlot=7456768
[2024-01-23 09:12:05] DEBUG Warmed up pruner cache duration=2.083647792s
[2024-01-23 09:12:12] DEBUG state-gen: Replayed state diff=352 duration=8.5425385s endSlot=7457120 startSlot=7456768
[2024-01-23 09:12:12] DEBUG node: Registering POW Chain Service
[2024-01-23 09:12:14] DEBUG node: Registering Attestation Pool Service
[2024-01-23 09:12:14] DEBUG node: Registering Deterministic Genesis Service
[2024-01-23 09:12:14] DEBUG node: Registering Blockchain Service
[2024-01-23 09:12:14] DEBUG blockchain: --weak-subjectivity-checkpoint not provided
[2024-01-23 09:12:14] DEBUG node: Registering Initial Sync Service
[2024-01-23 09:12:14] DEBUG node: Registering Sync Service
[2024-01-23 09:12:14] DEBUG node: Registering Slasher Service
[2024-01-23 09:12:14] DEBUG node: Registering builder service
[2024-01-23 09:12:14]  INFO Builder has been configured endpoint=https://0xafa4c6985aa049fb79dd37010438cfebeb0f2bd42b115b89dd678dab0670c1de38da0c4e9138c9290a398ecd9a0b3110@boost-relay-goerli.flashbots.net/
[2024-01-23 09:12:14]  WARN Outsourcing block construction to external builders adds non-trivial delay to block propagation time.  Builder-constructed blocks or fallback blocks may get orphaned. Use at your own risk!
[2024-01-23 09:12:14] DEBUG node: Registering RPC Service
[2024-01-23 09:12:14]  INFO rpc: gRPC server listening on port address=127.0.0.1:4000
[2024-01-23 09:12:14]  WARN rpc: You are using an insecure gRPC server. If you are running your beacon node and validator on the same machines, you can ignore this message. If you want to know how to enable secure connections, see: https://docs.prylabs.network/docs/prysm-usage/secure-grpc
[2024-01-23 09:12:14] DEBUG node: Registering GRPC Gateway Service
[2024-01-23 09:12:14] DEBUG node: Registering Validator Monitoring Service
[2024-01-23 09:12:14] DEBUG node: Registering Prometheus Service
[2024-01-23 09:12:14]  INFO node: Starting beacon node version=Prysm/Unknown/Local build. Built at: Moments ago
[2024-01-23 09:12:14] DEBUG registry: Starting 11 services: [*p2p.Service *backfill.Service *execution.Service *attestations.Service *blockchain.Service *initialsync.Service *sync.Service *builder.Service *rpc.Service *gateway.Gateway *prometheus.Service]
[2024-01-23 09:12:14] DEBUG registry: Starting service type *p2p.Service
[2024-01-23 09:12:14] DEBUG registry: Starting service type *backfill.Service
[2024-01-23 09:12:14] DEBUG registry: Starting service type *execution.Service
[2024-01-23 09:12:14] DEBUG registry: Starting service type *attestations.Service
[2024-01-23 09:12:14] DEBUG registry: Starting service type *blockchain.Service
[2024-01-23 09:12:14] DEBUG registry: Starting service type *initialsync.Service
[2024-01-23 09:12:14] DEBUG registry: Starting service type *sync.Service
[2024-01-23 09:12:14] DEBUG registry: Starting service type *builder.Service
[2024-01-23 09:12:14] DEBUG registry: Starting service type *rpc.Service
[2024-01-23 09:12:14] DEBUG registry: Starting service type *gateway.Gateway
[2024-01-23 09:12:14] DEBUG registry: Starting service type *prometheus.Service
[2024-01-23 09:12:14]  INFO blockchain: Blockchain data already exists in DB, initializing...
[2024-01-23 09:12:14]  INFO initial-sync: Waiting for state to be initialized
[2024-01-23 09:12:14] DEBUG state-gen: Populating pubkey cache
[2024-01-23 09:12:14] DEBUG prometheus: Starting prometheus service address=127.0.0.1:8080
[2024-01-23 09:12:14]  INFO rpc: Enabled debug gRPC endpoints
[2024-01-23 09:12:14]  INFO gateway: Starting gRPC gateway address=127.0.0.1:3500
[2024-01-23 09:12:15]  INFO initial-sync: Received state initialized event
[2024-01-23 09:12:15]  INFO initial-sync: Starting initial chain sync...
[2024-01-23 09:12:15] FATAL Unable to initialize backfill verifier, quitting. error=no state with blockroot=0xb43ed4b7062d88a72ae9c087b36b12d9dbbb36101dbe57329f664ad7b6d24876: state not found: not found in db

[terencechain]

The culprit is CleanUpDirtyStates. We remove the origin state at start-up. As you sync forward, the state will get deleted because it's no longer finalized

// 1.) state_slot % archived_interval == 0. (e.g. archived_interval=2048, states with slot 2048, 4096... etc)
// 2.) archived_interval - archived_interval/3 < state_slot % archived_interval
// 3.) state with current finalized root
// 4.) unfinalized States
			
if mod != 0 && mod <= slotsPerArchivedPoint-slotsPerArchivedPoint/3 && !finalizedChkpt && !nonFinalized {
		deletedRoots = append(deletedRoots, bytesutil.ToBytes32(v))
}

[rauljordan]

thats a really gnarly conditional above, wondering if we may want more coverage on it? Is it possible we could have found this with an integration test?

[terencechain]

+1, CleanUpDirtyStates should be rewritten now that we have backfill as a feature