Pruning logic broken on `unstable`

[michaelsproul]

Pruning broke on one of our nodes:

Apr 10 05:49:52.162 WARN Hot DB pruning failed error: PruningError(SummariesDagError("new StateSumariesDAG", StateSummariesNotContiguous { state_root: 0xf31eb42f8ba90b9622d7efd4458bcb2a3366b15bcec38f633db7d87c46505c3e, state_slot: Slot(11445760), latest_block_root: 0x0c080eb6784758b40e5c4b34b6115b77fd4c3f447acb36ac02ef4128850c43d0, parent_block_root: 0x22d785d9ab5641d408eb538819e7bb805e1927d78ece6d21f4bfa329878b586e, parent_block_latest_state_summary: Some((Slot(11445760), 0xf8ca88e4eb785d26fcf48d7844ab32dda4e05bca8be5e56fdf72885926e27722)) }))

Need to investigate why.

Caused by:

• Drop head tracker for summaries DAG #6744

[michaelsproul]

This error indicates:

• We were trying to compute the previous_state_root for the state summary at slot 11445760
• LH thinks the latest block root at slot 11445760 is 0x0c080eb6784758b40e5c4b34b6115b77fd4c3f447acb36ac02ef4128850c43d0, which is correct.
• LH thinks the parent block root is 0x22d785d9ab5641d408eb538819e7bb805e1927d78ece6d21f4bfa329878b586e, which is the block from the previous slot.
• The DAG does not contain any state summaries from slot 11445759 for the parent block root (0x22d785d9ab5641d408eb538819e7bb805e1927d78ece6d21f4bfa329878b586e), however it does contain a summary for the slot 11445760. This is a skipped slot state summary.

It looks like what might have happened is:

• We had already pruned states prior to 11445760, so it should have been the root of the tree.
• A state summary was still present for a non-canonical fork around 11445760. Q: why wasn't this pruned when 11445760 was set as the split? This state summary does not descend from the canonical state at 11445760, which does have a block applied to it.

[michaelsproul]

Inb4 Lion says this would be solved by just merging full tree states:

• Hierarchical state diffs in hot DB #6750

Because this bug is specific to the translation from V22 hot state summaries into quasi-V23. In V23, this translation only needs to happen once (on migration) rather than every time pruning runs. This greatly reduces the scope for errors.

However, I still think we should fix the wrong assumption here, as a bug that can break pruning here, could break the V23 upgrade migration.

[michaelsproul]

Second instance reported on Discord

Apr 23 09:06:17.945 WARN Hot DB pruning failed error: PruningError(SummariesDagError("new StateSumariesDAG", StateSummariesNotContiguous { state_root: 0x6ec80ddf39687f16aba976c8d1cf0af5a0c4cc9e786da6931678feb9c3a0cb93, state_slot: Slot(11442048), latest_block_root: 0xe8e7fbd2dcecde6c85e75b66838c0808032e6cf84c9e4c6ab1c5e6d8f9db1ea1, parent_block_root: 0xc5dda48025acefbc843ff03302e73f4c076a80031e9202484fc148a133c80a44, parent_block_latest_state_summary: Some((Slot(11442048), 0xa6ed74126349a067cdb445a8d22f2f5d224e926f0ef1955b891c68cd5e20a770)) }))

Very similar case. Block on the epoch boundary (11442048) and there's no summary in the DAG for its parent at slot 11442047, only a summary for a skipped slot at 11442048 descended from the parent block

[dapplion]

Canonical chain:

11442047 - proposed - slot 31/32
b 0xc5dda48025acefbc843ff03302e73f4c076a80031e9202484fc148a133c80a44
s 0xca97f3b2a946167f23d42d7693380678c14515b13dccaa672d80c4599dfef80c

11442048 - proposed - slot 0/32
b 0xe8e7fbd2dcecde6c85e75b66838c0808032e6cf84c9e4c6ab1c5e6d8f9db1ea1
s 0x6ec80ddf39687f16aba976c8d1cf0af5a0c4cc9e786da6931678feb9c3a0cb93

As you say the summaries of parent block 0xc5dda48025acefbc843ff03302e73f4c076a80031e9202484fc148a133c80a44 include the summary of a skipped slot 11442048 with root 0xa6ed74126349a067cdb445a8d22f2f5d224e926f0ef1955b891c68cd5e20a770 but not 0xca97f3b2a946167f23d42d7693380678c14515b13dccaa672d80c4599dfef80c

[dapplion]

The latest reported error is for slot 11442048, with timestamp Apr-08-2025 13:09:59 UTC-3. But the error fired on Apr 23 09:06:17.945. This must be happening during sync then?

The first error was at slot 11445760 with timestamp Apr-09-2025 01:32:23 UTC-3. The log is from Apr 10 05:49:52.162 but we don't know the timezone. But the slot timestamp and the log timestamp are far enough that regardless of timezone it must also have happened during sync.

If both are happening during sync, why is there a summary for a non-canonical state? Who could be triggering a state advance during sync?

[michaelsproul]

where was this reported from that we don't know the timezone? does it help that LH always logs in utc?

[michaelsproul]

oh you got the discord logs I'm guessing

[chong-he]

I am not sure if this is related. I got this error upon restarting the beacon node:
May 12 07:34:03.763 CRIT Failed to start beacon node reason: "Failed to build beacon chain: DB error when reading head state: HotColdDBError(MissingEpochBoundaryState(0x5da49f6f10792e6fb38f117e9e6b9364a64bbd20fb1453f1a491542fddb749ec, 0xd9cd784355649e194257b848371411e06e26e2ee5c31d5fe34c37eebdea89525)). Database corruption may be present. If the issue persists, use --purge-db to permanently delete the existing data directory."

Before this error, I got this:
May 12 06:44:01.379 CRIT Beacon block processing error error: DBError(LevelDbError(Error { message: "IO error: /var/lib/lighthouse_test1/beacon/chain_db/1937397.log: Too many open files" }))
May 12 06:55:00.075 CRIT Beacon block processing error error: MissingBeaconBlock(0xac570df800192fa208c3db65c2a03d038bf25860c96bf18331e48ffa066579cf)