"Unexpected trie node in disk" with path-based storage

[JustinDrake]

I'm running geth version 1.13.0-unstable-5976e584-20230818 with state.scheme=path on a Mac and getting some "Unexpected trie node in disk" errors. Steps I used:

1. started a fresh checkpoint sync with Lighthouse v4.3.0
2. ran geth removedb and deleted the chaindata folder
3. ran geth state.scheme=path
4. shut down Lighthouse with checkpoint sync flags
5. restarted Lighthouse without checkpoint sync flags

[karalabe]

Just a note, the above screenshot has a node whilst it is still span syncing (heal phase) where the state trie is not yet fuly assembled. Justing confirmed that once sync completed, the error messages disappeared.

Interestingly, Lighthouse should not be querying anything in checkpoint syncmode, but perhaps the root of the annyoing logs is the restart of lighthouse in normal mode before Geth finished syncing. We should try to repro that and see if it does some weird RPC calls and why we're serving them instead of just ignoring the unservable calls (missing root node).

[molaughlen]

I'm seeing this after upgrading geth, removing and rebuilding the DB. Lighthouse is the consensus client.

CLI args: --syncmode snap --state.scheme path

geth finished sync'ing but this error has remained for the past 96 hours.

   slots=659,803,107             storage=50.89GiB   dangling=0 elapsed=74h34m12.257s eta=131h14m44.871s
Nov 20 12:21:00 ip-10-0-0-11.ec2.internal geth[18425]: INFO [11-20|12:21:00.346] Imported new potential chain segment     number=18,612,963 hash=296aab..f8682a blocks=1  txs=143   mgas=11.844 elapsed=264.770ms     mgasps=44.731  snapdiffs=320.09KiB triediffs=183.38MiB triedirty=56.53MiB
Nov 20 12:21:00 ip-10-0-0-11.ec2.internal geth[18425]: ERROR[11-20|12:21:00.401] Unexpected trie node in disk             owner=5cc0a4..667982 path="[12 5 9 3 7]"             expect=8b09b1..e87152 got=99f9a0..b9f78f
Nov 20 12:21:00 ip-10-0-0-11.ec2.internal geth[18425]: ERROR[11-20|12:21:00.401] State snapshotter failed to iterate trie err=nil
Nov 20 12:21:00 ip-10-0-0-11.ec2.internal geth[18425]: INFO [11-20|12:21:00.948] Chain head was updated                   number=18,612,963 hash=296aab..f8682a root=6b5095..844674 elapsed=19.059446ms
Nov 20 12:21:13 ip-10-0-0-11.ec2.internal geth[18425]: INFO [11-20|12:21:13.817] Resuming state snapshot generation       root=88a2ed..86827b in=5cc0a4..667982 at=c528e6..3f228f accounts=81,827,943           slots=659,806,109             storage=50.89GiB   dangling=0 elapsed=74h34m25.752s eta=131h15m8.623s
Nov 20 12:21:13 ip-10-0-0-11.ec2.internal geth[18425]: INFO [11-20|12:21:13.864] Imported new potential chain segment     number=18,612,964 hash=16504b..a6a093 blocks=1  txs=256   mgas=20.011 elapsed=761.573ms     mgasps=26.276  snapdiffs=324.66KiB triediffs=183.94MiB triedirty=56.80MiB
Nov 20 12:21:13 ip-10-0-0-11.ec2.internal geth[18425]: ERROR[11-20|12:21:13.992] Unexpected trie node in disk             owner=5cc0a4..667982 path="[12 5 9 3 7]"             expect=8b09b1..e87152 got=99f9a0..b9f78f
Nov 20 12:21:13 ip-10-0-0-11.ec2.internal geth[18425]: ERROR[11-20|12:21:13.992] State snapshotter failed to iterate trie err=nil
Nov 20 12:21:14 ip-10-0-0-11.ec2.internal geth[18425]: INFO [11-20|12:21:14.244] Chain head was updated                   number=18,612,964 hash=16504b..a6a093 root=35526f..7fe483 elapsed=24.553583ms
Nov 20 12:21:24 ip-10-0-0-11.ec2.internal geth[18425]: INFO [11-20|12:21:24.636] Resuming state snapshot generation       root=6cbb62..60d860 in=5cc0a4..667982 at=c528e6..3f228f accounts=81,827,943           slots=659,809,111             storage=50.89GiB   dangling=0 elapsed=74h34m36.571s eta=131h15m27.664s
Nov 20 12:21:24 ip-10-0-0-11.ec2.internal geth[18425]: INFO [11-20|12:21:24.665] Imported new potential chain segment     number=18,612,965 hash=833fba..22f170 blocks=1  txs=125   mgas=8.195  elapsed=173.435ms     mgasps=47.249  snapdiffs=335.19KiB triediffs=183.77MiB triedirty=57.10MiB
Nov 20 12:21:24 ip-10-0-0-11.ec2.internal geth[18425]: ERROR[11-20|12:21:24.728] Unexpected trie node in disk             owner=5cc0a4..667982 path="[12 5 9 3 7]"             expect=8b09b1..e87152 got=99f9a0..b9f78f
Nov 20 12:21:24 ip-10-0-0-11.ec2.internal geth[18425]: ERROR[11-20|12:21:24.728] State snapshotter failed to iterate trie err=nil
Nov 20 12:21:24 ip-10-0-0-11.ec2.internal geth[18425]: INFO [11-20|12:21:24.930] Chain head was updated                   number=18,612,965 hash=833fba..22f170 root=b0587e..adf841 elapsed=4.411775ms
Nov 20 12:21:37 ip-10-0-0-11.ec2.internal geth[18425]: INFO [11-20|12:21:37.758] Resuming state snapshot generation       root=771977..09f7db in=5cc0a4..667982 at=c528e6..3f228f accounts=81,827,943   

[rjl493456442]

What's the geth version you are using? What's the original geth version you used?

I'm seeing this after upgrading geth, removing and rebuilding the DB

Did you upgrade geth in the middle of snap sync? Or you delete the entire geth database and sync from scratch?

[rjl493456442]

Do you have the log during the sync? Please attach it if possible.

[molaughlen]

I was on geth 1.10.23 which kept getting out of sync/requiring a restart. I purged the DB (rm -rf data-dir) before I started the new version geth 1.13.5. This error doesn't appear to be affecting the validators/beacon.

I've attached the log output 10 minutes before the error appeared in the log until the first instance(s).

geth-unexpected-trie-2023-11-17.txt

[rjl493456442]

Do you have the full log for sync?

This error doesn't appear to be affecting the validators/beacon.

Unfortunately your state is corrupted because of a "unsuccessful" state sync. The node can still operate without printing any other error if because the corrupted state is not touched yet. The only way to fix it is resync the node(of course, you can still keep the ancient which is correct)

But I would appreciate if you can run this branch [EDIT, it's merged into master branch now] on top of your existent datadir just to dump more information for debugging.

[molaughlen]

Correction I was on ... instance=Geth/v1.11.5-stable-a38f4108/linux-amd64/go1.20.2

I will share more logs when I started rebuilding.

Here it is -- I had a few mis-starts in the log but each time I purged the DB

sync-log.zip

[rjl493456442]

Thanks. Your node took very long time to finish the initial sync(roughly 40 hours). It might touch some corner case and eventually result in the corrupted state.

Would you mind run the latest master branch on top of your existent node to expose more information?

[rjl493456442]

Nov 15 17:47:33 ip-10-0-0-11.ec2.internal geth[18425]: INFO [11-15|17:47:33.376] Writing custom genesis block This line is pretty weird, a customized genesis is written instead of the default mainnet block? I guess you are using some config file with genesis specified?

[rjl493456442]

Another catch up is there are a tons of block truncations which I believe shouldn't occur. Although maybe it's not relevant with the issue itself. Should still fix it.

Nov 15 18:21:30 ip-10-0-0-11.ec2.internal geth[18425]: WARN [11-15|18:21:30.430] Rewinding blockchain to block            target=3,223,551
Nov 15 18:21:33 ip-10-0-0-11.ec2.internal geth[18425]: INFO [11-15|18:21:33.424] Loaded most recent local header          number=3,223,551  hash=a0aaff..914938 td=146,234,259,464,463,532,817 age=6y9mo4w
Nov 15 18:21:33 ip-10-0-0-11.ec2.internal geth[18425]: INFO [11-15|18:21:33.424] Loaded most recent local block           number=0          hash=d4e567..cb8fa3 td=17,179,869,184              age=54y7mo3w
Nov 15 18:21:33 ip-10-0-0-11.ec2.internal geth[18425]: INFO [11-15|18:21:33.424] Loaded most recent local snap block      number=3,223,551  hash=a0aaff..914938 td=146,234,259,464,463,532,817 age=6y9mo4w
Nov 15 18:21:33 ip-10-0-0-11.ec2.internal geth[18425]: INFO [11-15|18:21:33.424] Loaded last snap-sync pivot marker       number=18,578,974
Nov 15 18:21:33 ip-10-0-0-11.ec2.internal geth[18425]: ERROR[11-15|18:21:33.424] Failed to reset txpool state             err="missing trie node d7f8974fb5ac78d9ac099b9ad5018bedc2ce0a72dad1827a1709da30580f0544 (path ) layer stale"
Nov 15 18:21:33 ip-10-0-0-11.ec2.internal geth[18425]: ERROR[11-15|18:21:33.424] Failed to reset blobpool state           err="missing trie node d7f8974fb5ac78d9ac099b9ad5018bedc2ce0a72dad1827a1709da30580f0544 (path ) layer stale"

[molaughlen]

I had a toml file but after running into invalid config issues I removed it. After changing the config I wiped the DB.

This is on an EC2 box -- so maybe my EBS volumes iops aren't very high..

[rjl493456442]

But the weird thing is: log prints Writing custom genesis block and then starts sync. They are in the same cycle I think.

[molaughlen]

I will need to set up the build environment for the binary -- will likely be tomorrow before I can run it.