Need help with 1.10.22 regression, in 1.10.23 I get `Unhandled trie error: missing trie node`

[Sajjon]

Hey, this morning I started using the 1.10.22 version this morning for maybe 1 hour, and then I saw that there were reports about regression bug with it. So I followed the instructions in the release notes for 1.10.23 to use debug.setHead with a blocknumber older than when I moved from 1.10.21 to 1.10.22. I used block number 15400840 from 8 hours ago. 0d15400840 is 0xEAFF88 in hex, so I did this command

> debug.setHead("0xEAFF88")

which looked like it hanged, and then after maybe a minute, I got this error output.:

Error: Post "http://localhost:3334": EOF
	at web3.js:6365:9(45)
	at send (web3.js:5099:62(34))
	at <eval>:1:14(4)

Then I wanted to know which block I was at and if I was syncing:

> eth.syncing
{
  currentBlock: 15371819,
  healedBytecodeBytes: 0,
  healedBytecodes: 0,
  healedTrienodeBytes: 0,
  healedTrienodes: 0,
  healingBytecode: 0,
  healingTrienodes: 0,
  highestBlock: 15402202,
  startingBlock: 15402191,
  syncedAccountBytes: 0,
  syncedAccounts: 0,
  syncedBytecodeBytes: 0,
  syncedBytecodes: 0,
  syncedStorage: 0,
  syncedStorageBytes: 0
}
> eth.syncing.highestBlock - eth.syncing.currentBlock
30383

So it looks like it used some other block number than what I specified, because currentBlock was set to 15371819 and not 15400840 as I specified, which was weird.

Now I see a crazy amount of errors in log

ERROR[08-24|12:21:26.881] Unhandled trie error: missing trie node b4fd295a8de6d22dd1009b7e281451681c13a04a122d7de37a89617859548089 (path 08070a) <nil>
ERROR[08-24|12:21:26.946] Unhandled trie error: missing trie node f330119795ef1ffb240126b5cf53d34db7a4ba45f051f804b35830af25ccfb05 (path 09010904) <nil>
ERROR[08-24|12:21:26.946] Unhandled trie error: missing trie node f330119795ef1ffb240126b5cf53d34db7a4ba45f051f804b35830af25ccfb05 (path 09010904) <nil>
ERROR[08-24|12:21:27.181] Unhandled trie error: missing trie node 1e4d3aa7ac49b97d1e1bfd8f2e02be05d7627341ad14e25e9e10f82e42704f7e (path 0f0b0103) <nil>
ERROR[08-24|12:21:27.181] Unhandled trie error: missing trie node 1e4d3aa7ac49b97d1e1bfd8f2e02be05d7627341ad14e25e9e10f82e42704f7e (path 0f0b0103) <nil>
ERROR[08-24|12:21:27.274] Unhandled trie error: missing trie node d0dac8813869164c560910aee54856c50b85177ab7499601d69d6923f356373a (path 050c0c00) <nil>
ERROR[08-24|12:21:27.274] Unhandled trie error: missing trie node d0dac8813869164c560910aee54856c50b85177ab7499601d69d6923f356373a (path 050c0c00) <nil>
ERROR[08-24|12:21:27.303] Unhandled trie error: missing trie node 1e5c54aece0093e0be2eda6116dd958062f3523b2bf12b416f4668abd6e7134a (path 050e01) <nil>
ERROR[08-24|12:21:27.303] Unhandled trie error: missing trie node 1e5c54aece0093e0be2eda6116dd958062f3523b2bf12b416f4668abd6e7134a (path 050e01) <nil>
ERROR[08-24|12:21:27.346] Unhandled trie error: missing trie node 0e6f00399370f7d4b177e4deac666b54c1b146e40dc14bfafefbdfbad1ab96e2 (path 0105060b) <nil>
ERROR[08-24|12:21:27.346] Unhandled trie error: missing trie node 0e6f00399370f7d4b177e4deac666b54c1b146e40dc14bfafefbdfbad1ab96e2 (path 0105060b) <nil>
ERROR[08-24|12:21:27.418] Unhandled trie error: missing trie node 0e6f00399370f7d4b177e4deac666b54c1b146e40dc14bfafefbdfbad1ab96e2 (path 0105060b) <nil>
ERROR[08-24|12:21:27.418] Unhandled trie error: missing trie node 0e6f00399370f7d4b177e4deac666b54c1b146e40dc14bfafefbdfbad1ab96e2 (path 0105060b) <nil>
ERROR[08-24|12:21:27.490] Unhandled trie error: missing trie node f330119795ef1ffb240126b5cf53d34db7a4ba45f051f804b35830af25ccfb05 (path 09010904) <nil>
ERROR[08-24|12:21:27.490] Unhandled trie error: missing trie node f330119795ef1ffb240126b5cf53d34db7a4ba45f051f804b35830af25ccfb05 (path 09010904) <nil>
ERROR[08-24|12:21:27.514] Unhandled trie error: missing trie node 7922024350a418118480a9a08345cd717476146e5f7c68ada7399b5de05d8d36 (path 0c030b0b) <nil>
ERROR[08-24|12:21:27.514] Unhandled trie error: missing trie node 7922024350a418118480a9a08345cd717476146e5f7c68ada7399b5de05d8d36 (path 0c030b0b) <nil>
ERROR[08-24|12:21:27.547] Unhandled trie error: missing trie node 881d144514a217e25338ab52f8ae41830c149b8daa9c8e7543116af7393ed162 (path 0d020307) <nil>
ERROR[08-24|12:21:27.547] Unhandled trie error: missing trie node 881d144514a217e25338ab52f8ae41830c149b8daa9c8e7543116af7393ed162 (path 0d020307) <nil>
ERROR[08-24|12:21:27.550] Unhandled trie error: missing trie node 881d144514a217e25338ab52f8ae41830c149b8daa9c8e7543116af7393ed162 (path 0d020307) <nil>
ERROR[08-24|12:21:27.550] Unhandled trie error: missing trie node 881d144514a217e25338ab52f8ae41830c149b8daa9c8e7543116af7393ed162 (path 0d020307) <nil>
INFO [08-24|12:21:27.581] Imported new chain segment               blocks=16    txs=1791      mgas=191.093 elapsed=5.423s      mgasps=35.233  number=15,376,561 hash=99400b..d401ac age=4d1h56m  dirty=1018.49MiB
INFO [08-24|12:21:27.960] Importing heavy sidechain segment        blocks=811   start=15,376,562 end=15,377,372
INFO [08-24|12:21:28.094] Unindexed transactions                   blocks=821   txs=130,461   tail=13,026,562 elapsed=512.120ms
INFO [08-24|12:21:36.485] Imported new chain segment               blocks=13    txs=3571      mgas=242.603 elapsed=8.525s      mgasps=28.456  number=15,376,574 hash=9e3069..6e85de age=4d1h54m  dirty=1023.51MiB
INFO [08-24|12:21:44.997] Imported new chain segment               blocks=20    txs=3720      mgas=298.215 elapsed=8.511s      mgasps=35.036  number=15,376,594 hash=8d8539..b0b388 age=4d1h48m  dirty=1023.18MiB
INFO [08-24|12:21:53.875] Imported new chain segment               blocks=17    txs=4552      mgas=325.808 elapsed=8.877s      mgasps=36.699  number=15,376,611 hash=f72b3b..206d5e age=4d1h44m  dirty=1022.29MiB
ERROR[08-24|12:22:22.498] Unhandled trie error: missing trie node 17cae2616b12b1f7032d041d2a2b0e681a1416506ffed502d46b51ab48c0f3f0 (path 0e0c0107) <nil>
ERROR[08-24|12:22:22.498] Unhandled trie error: missing trie node 17cae2616b12b1f7032d041d2a2b0e681a1416506ffed502d46b51ab48c0f3f0 (path 0e0c0107) <nil>
ERROR[08-24|12:22:23.028] Unhandled trie error: missing trie node 17cae2616b12b1f7032d041d2a2b0e681a1416506ffed502d46b51ab48c0f3f0 (path 0e0c0107) <nil>
ERROR[08-24|12:22:23.029] Unhandled trie error: missing trie node 17cae2616b12b1f7032d041d2a2b0e681a1416506ffed502d46b51ab48c0f3f0 (path 0e0c0107) <nil>
ERROR[08-24|12:22:24.629] Unhandled trie error: missing trie node f9d725c99e120e0f6c1f8dc9cb3d7bab497ed646c6f8bccb6b4b9123840dc44c (path 010f0404) <nil>
ERROR[08-24|12:22:24.629] Unhandled trie error: missing trie node f9d725c99e120e0f6c1f8dc9cb3d7bab497ed646c6f8bccb6b4b9123840dc44c (path 010f0404) <nil>
ERROR[08-24|12:22:24.693] Unhandled trie error: missing trie node e5b7e37abe5e439ef607018e93729940fab123238920988e548f669d02d14eec (path 0d0b09) <nil>
ERROR[08-24|12:22:24.693] Unhandled trie error: missing trie node e5b7e37abe5e439ef607018e93729940fab123238920988e548f669d02d14eec (path 0d0b09) <nil>
ERROR[08-24|12:22:24.736] Unhandled trie error: missing trie node e5b7e37abe5e439ef607018e93729940fab123238920988e548f669d02d14eec (path 0d0b09) <nil>
ERROR[08-24|12:22:24.736] Unhandled trie error: missing trie node e5b7e37abe5e439ef607018e93729940fab123238920988e548f669d02d14eec (path 0d0b09) <nil>
ERROR[08-24|12:22:25.281] Unhandled trie error: missing trie node f9d725c99e120e0f6c1f8dc9cb3d7bab497ed646c6f8bccb6b4b9123840dc44c (path 010f0404) <nil>
ERROR[08-24|12:22:25.281] Unhandled trie error: missing trie node f9d725c99e120e0f6c1f8dc9cb3d7bab497ed646c6f8bccb6b4b9123840dc44c (path 010f0404) <nil>
ERROR[08-24|12:22:25.342] Unhandled trie error: missing trie node e5b7e37abe5e439ef607018e93729940fab123238920988e548f669d02d14eec (path 0d0b09) <nil>
ERROR[08-24|12:22:25.342] Unhandled trie error: missing trie node e5b7e37abe5e439ef607018e93729940fab123238920988e548f669d02d14eec (path 0d0b09) <nil>
ERROR[08-24|12:22:25.381] Unhandled trie error: missing trie node 10731524a3e6d4e99017a9a2245cde3acf639007ae150f77b1bb640df5e7506b (path 040f0a03) <nil>
ERROR[08-24|12:22:25.381] Unhandled trie error: missing trie node 10731524a3e6d4e99017a9a2245cde3acf639007ae150f77b1bb640df5e7506b (path 040f0a03) <nil>
ERROR[08-24|12:22:25.391] Unhandled trie error: missing trie node 6d683e09199f2e85ba9b700db06305ac344f21a2ffccb1fe2cdd8f62275dd2dc (path 050e07) <nil>
ERROR[08-24|12:22:25.391] Unhandled trie error: missing trie node 6d683e09199f2e85ba9b700db06305ac344f21a2ffccb1fe2cdd8f62275dd2dc (path 050e07) <nil>
ERROR[08-24|12:22:25.703] Unhandled trie error: missing trie node 984fc8385f7111d46c03ad478f4f433d2c01b16da4fc2102892035121c845252 (path 040a09) <nil>
ERROR[08-24|12:22:25.730] Unhandled trie error: missing trie node b7e1d3b67cd6c6e72625b629a7ea410626722cd0c3e6c5d6dea02a00e9db77b3 (path 0b0c05) <nil>
ERROR[08-24|12:22:25.730] Unhandled trie error: missing trie node b7e1d3b67cd6c6e72625b629a7ea410626722cd0c3e6c5d6dea02a00e9db77b3 (path 0b0c05) <nil>
ERROR[08-24|12:22:25.730] Unhandled trie error: missing trie node b7e1d3b67cd6c6e72625b629a7

Maybe not relevant, I also saw:

WARN [08-24|12:24:54.078] Merge is configured, but previously seen beacon client is offline. Please ensure it is operational before the transition arrives! eta=3w1d1h

But lighthouse is not running now, because of cannot start it sigp/lighthouse#3500

So what does this ocean of Unhandled trie error: missing trie node mean? Am I f**ked, do I have to do a clean sync from start (7 days)? Or is this normal, i.e. these errors will disappear onces eth.syncing goes to false? Because when checking, it looks that I'm making progress:

> eth.syncing.highestBlock - eth.syncing.currentBlock
27981
> eth.syncing.highestBlock - eth.syncing.currentBlock
27584
> eth.syncing.highestBlock - eth.syncing.currentBlock
27399
> eth.syncing.highestBlock - eth.syncing.currentBlock
27034
> eth.syncing.highestBlock - eth.syncing.currentBlock
25933
> eth.syncing.highestBlock - eth.syncing.currentBlock
24759

But I don't remember having seen Unhandled trie error: missing trie node before!

Please please help <3

System information

Geth version: 1.10.23
OS & Version: macOS Monterey 12.5.1 (21G83)

Expected behaviour

Actual behaviour

Steps to reproduce the behaviour

Backtrace

[backtrace]

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

[Sajjon]

I just tried restaring geth to see what I see, I get Head state missing, repairing, what does that mean?

Full log:

INFO [08-24|12:33:53.395] Disk storage enabled for ethash caches   dir=/Users/sajjode/Library/Ethereum/geth/ethash count=3
INFO [08-24|12:33:53.396] Disk storage enabled for ethash DAGs     dir=/Users/sajjode/Library/Ethash count=2
INFO [08-24|12:33:53.398] Initialising Ethereum protocol           network=1 dbversion=8
INFO [08-24|12:33:53.437] Loaded most recent local header          number=15,378,033 hash=db6612..1c3690 td=56,803,191,999,581,582,767,893 age=3d20h28m
INFO [08-24|12:33:53.438] Loaded most recent local full block      number=15,378,033 hash=db6612..1c3690 td=56,803,191,999,581,582,767,893 age=3d20h28m
INFO [08-24|12:33:53.438] Loaded most recent local fast block      number=15,378,033 hash=db6612..1c3690 td=56,803,191,999,581,582,767,893 age=3d20h28m
INFO [08-24|12:33:53.438] Loaded last fast-sync pivot marker       number=12,467,495
WARN [08-24|12:33:53.439] Head state missing, repairing            number=15,378,033 hash=db6612..1c3690 snaproot=07944c..a49773

[garyng2000]

indeed, that debug.setHead("0xEAFF88") gives me the exact same message

Error: Post "http://localhost:3334": EOF
at web3.js:6365:9(45)
at send (web3.js:5099:62(34))
at :1:14(4)

but my journal log seems to suggest it is still syncing. just don't know what state it is. This release(.22 and .23) seems to be too rush and the 'patch' is my scary(without warning that the above command may not return immediately and not sure what exactly the above message means

[garyng2000]

and now my log is showing huge amount of this

ERROR[08-24|12:09:27.894] Demoting invalidated transaction hash=41b422..127396
and
now it disappear and continue syncing from the block I specify, but extremely slow.

this regression is a nightmare

and now I see these Tries missing error(and the imported new chain segment is extremely slow, at this rate I would further lag behind as my other node which I haven't done the rewind is importing faster which is already like 10k block ahead and counting)

Aug 24 12:31:21 hqprdubeth startmainnet.sh[3940083]: INFO [08-24|12:31:21.226] Resuming state snapshot generation       root=e25933..59c0d5 at=004550..1aae0f accounts=190,049 slots=1,179,077 storage=93.40MiB dangling=0 elapsed=6m33.>
Aug 24 12:31:21 hqprdubeth startmainnet.sh[3940083]: INFO [08-24|12:31:21.226] Trie missing, state snapshotting paused  root=e25933..59c0d5 at=004550..1aae0f accounts=190,049 slots=1,179,077 storage=93.40MiB dangling=0 elapsed=6m33.>
Aug 24 12:31:21 hqprdubeth startmainnet.sh[3940083]: INFO [08-24|12:31:21.228] Imported new chain segment               blocks=1 txs=74  mgas=6.826  elapsed=14.535s     mgasps=0.470 number=15,393,661 hash=b86569..d8482f age=1d11h12m>
Aug 24 12:31:47 hqprdubeth startmainnet.sh[3940083]: INFO [08-24|12:31:47.648] Resuming state snapshot generation       root=f2b19b..de357b at=004550..1aae0f accounts=190,049 slots=1,179,077 storage=93.40MiB dangling=0 elapsed=7m0.3>
Aug 24 12:31:47 hqprdubeth startmainnet.sh[3940083]: INFO [08-24|12:31:47.648] Trie missing, state snapshotting paused  root=f2b19b..de357b at=004550..1aae0f accounts=190,049 slots=1,179,077 storage=93.40MiB dangling=0 elapsed=7m0.3>
Aug 24 12:31:47 hqprdubeth startmainnet.sh[3940083]: INFO [08-24|12:31:47.653] Imported new chain segment               blocks=1 txs=173 mgas=19.751 elapsed=26.424s     mgasps=0.747 number=15,393,662 hash=232236..c92d4c age=1d11h12m>

[holiman]

Trie missing, state snapshotting paused @garyng2000 yes this is borked. Did you do a sethead back? It appears it didn't go far enough. I would recommend a fresh sync, via geth ... removedb but opt to keep the ancients in place.

@RisingPaw can't say for sure without logs. "trie missing errors" -- in what context?

[garyng2000]

@RisingPaw indeed. I usually would delay my upgrade or at least test them out on a spare setup for a while. But this time it is about the merge, sigh.

@holiman, thanks. I would just sync from fresh.

[garyng2000]

and I really strongly suggest to not even mentioning that debug.setHead patch, just re-sync with the ancient data kept(based on what I see only about 1 week of data). It seems to cause my trouble.

[holiman]

@RisingPaw that's a lot of errors. I'd recommend to just resync with the ancient data kept.

[garyng2000]

geth removedb but keep the ancient data when asked

[garyng2000]

that is what I have done, and waiting the re-sync about a week behind

[cybersi]

I took me about 15 hours, to sync from scratch, so it's not that bad. The snapshot sync is now enabled by default and it helps a lot.

[Sajjon]

Trie missing, state snapshotting paused @garyng2000 yes this is borked. Did you do a sethead back? It appears it didn't go far enough. I would recommend a fresh sync, via geth ... removedb but opt to keep the ancients in place.

@RisingPaw can't say for sure without logs. "trie missing errors" -- in what context?

Am I (OP) borked too?

[gitmewai]

We are running archive nodes with --gcmode archive with SyncMode = "full" and NoPruning = true in config file. Is the archive node also affected by the 1.10.22 regression if there is no pruning action on the node?

The command geth snapshot traverse-state has been running for almost 2.5 hours on this goerli archive node and no errors reported so far. You know, it's not practical to resync an archive node from genesis.

Thanks

[c0deright]

The EOF error is most likely a timeout between geth cli and geth daemon and can be ignored. Just check the log of your daemon and you will see that geth is indeed rewinding the blockchain.

But I have these

Unhandled trie error: missing trie node 9a2047c93da8dd3f9a92a18295a3569ebb41371e6676650d239cae8561536257 (path 0c04040a) <nil>

errors, too, but geth is still syncing.

[holiman]

Now that I think about it... Archive nodes should not be affected. They don't have a node garbage collector, so everything is immediately flushed. You should be fine.