Prysm: Block is invalid error during initial sync

[peterbitfly]

🐞 Bug Report

Description

During a full sync with the new state management enabled we often get the following error which causes the sync process to stall:

time="2020-05-25 12:41:14" level=info msg="Processing block 0x33abb3f1... 60851/270206 - estimated time remaining 2h13m25s" blocksPerSecond=26.1 peers=30 prefix=initial-sync
time="2020-05-25 12:41:14" level=info msg="Block is invalid" error="beacon node doesn't have a block in db with root 0x104a46ff995a11619263913158505edb574a3222aa796b21dc5059d9fd9422f2" prefix=initial-sync
time="2020-05-25 12:41:14" level=info msg="Processing block 0x109bf2eb... 60852/270206 - estimated time remaining 2h13m10s" blocksPerSecond=26.2 peers=30 prefix=initial-sync
time="2020-05-25 12:41:14" level=info msg="Block is invalid" error="beacon node doesn't have a block in db with root 0x33abb3f1f8ce3c1ba5a44b39d3562da638f5be4f7fed95634317a986a5d3066a" prefix=initial-sync
time="2020-05-25 12:41:14" level=info msg="Processing block 0xb45c21d9... 60853/270206 - estimated time remaining 2h12m55s" blocksPerSecond=26.2 peers=30 prefix=initial-sync
time="2020-05-25 12:41:14" level=info msg="Block is invalid" error="beacon node doesn't have a block in db with root 0x109bf2eb808a6cd86710cdc8874939e1a30d1777ac79a7499cfa17406e294911" prefix=initial-sync
time="2020-05-25 12:41:14" level=info msg="Processing block 0xe0d896cc... 60855/270206 - estimated time remaining 2h12m40s" blocksPerSecond=26.3 peers=30 prefix=initial-sync
time="2020-05-25 12:41:14" level=info msg="Block is invalid" error="beacon node doesn't have a block in db with root 0xb45c21d92be7ed278574b1a46cccd65e331e184ac5ba4aabe57abc84c7c1e192" prefix=initial-sync
time="2020-05-25 12:41:14" level=info msg="Processing block 0xe2ba676b... 60857/270206 - estimated time remaining 2h12m24s" blocksPerSecond=26.4 peers=30 prefix=initial-sync
time="2020-05-25 12:41:14" level=info msg="Block is invalid" error="beacon node doesn't have a block in db with root 0x70451731ec253772d06fe6c2db26ba5ae039e2d400e8262235dd7ed9860b5cc7" prefix=initial-sync
time="2020-05-25 12:41:14" level=info msg="Processing block 0x61f7c510... 60858/270206 - estimated time remaining 2h12m9s" blocksPerSecond=26.4 peers=30 prefix=initial-sync
time="2020-05-25 12:41:14" level=info msg="Block is invalid" error="beacon node doesn't have a block in db with root 0xe2ba676b5555cfa714078468211fc1aaf6cf267e2155ea28f87432dd62c6bcca" prefix=initial-sync
time="2020-05-25 12:41:14" level=info msg="Processing block 0xcf1f79cd... 60859/270206 - estimated time remaining 2h11m54s" blocksPerSecond=26.4 peers=30 prefix=initial-sync
time="2020-05-25 12:41:14" level=info msg="Block is invalid" error="beacon node doesn't have a block in db with root 0x61f7c51052c7780aceeab8db98bb39038528c5a766b5b7944e9ee27288502232" prefix=initial-sync
time="2020-05-25 12:41:14" level=info msg="Processing block 0x0e5bf96e... 60860/270206 - estimated time remaining 2h11m39s" blocksPerSecond=26.5 peers=30 prefix=initial-sync
time="2020-05-25 12:41:14" level=info msg="Block is invalid" error="beacon node doesn't have a block in db with root 0xcf1f79cd5b0d6c780700d200dfb2317583bd16a2aacc0b746ac34dcbeb5d3473" prefix=initial-sync
time="2020-05-25 12:41:14" level=info msg="Processing block 0x801af201... 60862/270206 - estimated time remaining 2h11m24s" blocksPerSecond=26.6 peers=30 prefix=initial-sync
time="2020-05-25 12:41:14" level=info msg="Block is invalid" error="beacon node doesn't have a block in db with root 0x0e5bf96eeb1da94c83293778ef015d065455165ae2ae51e495264ac0035efe54" prefix=initial-sync
time="2020-05-25 12:41:14" level=info msg="Processing block 0x3923d93b... 60863/270206 - estimated time remaining 2h11m10s" blocksPerSecond=26.6 peers=30 prefix=initial-sync
time="2020-05-25 12:41:14" level=info msg="Block is invalid" error="beacon node doesn't have a block in db with root 0x801af2013dbe0804a278bcd3ad840a8aba3e2c2f4d1e785c64465aadd07ab36f" prefix=initial-sync

It continues to sync a few blocks but the error appears for some successive blocks. Also it causes the sync process to stall for quite some time.

Tested on latest master.

[farazdagi]

Does it stall the process forever, or it eventually continues to sync? That's I am trying to understand whether we have some inefficiency here, or an infinite loop.

Also, do you run with --dev flag or just --enable-new-state-mgmt? When using --dev it should rely on optimized fetching routine as well (weighted round robin, with better bandwidth utilization).

[peterbitfly]

Eventually we restarted the prysm node and at some point it started to sync properly again. We are currently running it only with the --enable-new-state-mgmt flag but will re-try it with the --dev flag during our next sync tomorrow.

[terencechain]

Are you by chance running v0.12 branch to sync with Topaz testnet? I've made the same mistake just now and reproduced the exact same error:

[2020-05-25 06:57:11] INFO initial-sync: Block is invalid error=parent root 0xd9f658528376936f7e923bcaf948e59e6a8e0c6598dad81f715e61ac9a9b6446 does not match the latest block header signing root in state 0x5e43c48bdf736db64caf3b348132a5b4128b9244727f3182e2edb04e1684417e

[peterbitfly]

No, I am running the latest docker image: gcr.io/prysmaticlabs/prysm/beacon-chain:latest
I am also getting the error when syncing just with --archive

[farazdagi]

@ppratscher can you please try with the latest master? Ideally, with and without --dev flag. Thank you for your help!

[peterbitfly]

Tried with latest master with the --dev flag without encountering the error, will try without the flag next.

[farazdagi]

Issue seems to be resolved. Feel free to re-open, if regression is spotted.