Fix the inconsistency check in get_entries_in_data_block()

[yhchiang-sol]

Problem

get_entries_in_data_block() panics when there's inconsistency between
slot_meta and data_shred.

However, as we don't lock on reads, reading across multiple column families is
not atomic (especially for older slots) and thus does not guarantee consistency
as the background cleanup service could purge the slot in the middle. Such
panic was reported in #26980 when the validator serves a high load of RPC calls.

Summary of Changes

This PR makes get_entries_in_data_block() panic only when the inconsistency
between slot-meta and data-shred happens on a slot newer than lowest_cleanup_slot.

[lijunwangs]

Looks good!

Pull request has been modified.

Pull request has been modified.

[mergify]

automerge label removed due to a CI failure

[ryoqun]

no test? ;)

[behzadnouri]

@yhchiang-sol This function is called from replay stage when processing shreds for completed sets for the first time.
Why should slot < self.lowest_cleanup_slot() ever in that case?
i.e. why should blockstore prematurely cleanup slots that the replay stage hasn't processed yet.

The commit is suppressing the panic, but if the slot is incorrectly cleaned up, then the culprit is somewhere else!

solana_core::replay_stage::ReplayStage::replay_active_banks::{{closure}}
solana_core::replay_stage::ReplayStage::replay_active_bank
solana_core::replay_stage::ReplayStage::replay_blockstore_into_bank
solana_ledger::blockstore_processor::confirm_slot
solana_ledger::blockstore::Blockstore::get_slot_entries_with_shred_info

[yhchiang-sol]

@behzadnouri Thanks for raising it. Let me revisit the purge logic a bit.

[yhchiang-sol]

@behzadnouri The purge is determined by the ledger_cleanup_service, where anything older than the max-ledger-shreds (i.e., the --limit_ledger_size argument) will be purged. Looks like it doesn't check any replay status.

Is there any atomic variable that stores the current replay status so that the purge process can honor this? Although it will then keep more shreds than the configured --limit_ledger_size.

[yhchiang-sol]

Is there any atomic variable that stores the current replay status so that the purge process can honor this? Although it will then keep more shreds than the configured --limit_ledger_size.

In any case, I will do some code study and file a PR to make the cleanup service honor the replay progress.

[yhchiang-sol]

Hey @behzadnouri. @steviez and I chatted a little bit about this, and we found that the replay stage isn't the only call-stack that might invoke get_slot_entries_with_shred_info(). The get_block() RPC call will also trigger this call, and the validator that hit this issue was also serving heavy load RPC calls.

rpc::get_block
Blockstore::get_complete_block
Blockstore::get_slot_entries
Blockstore::get_slot_entries_with_shred_info

We also double-checked the ledger_cleanup_service code, and it never purges anything newer than the root.

So everything is good.

[steviez]

Thanks for posting the summary @yhchiang-sol. Poking around a little more, there is another codepath that will hit Blockstore::get_slot_entries_with_shred_info():

rpc::get_block
Blockstore::get_rooted_block
Blockstore::get_complete_block
Blockstore::get_slot_entries
Blockstore::get_slot_entries_with_shred_info

From the get_block() comments, Blockstore::get_rooted_block() is called for finalized slots whereas Blockstore::get_confirmed_block() is called for committed blocks:

Here is the implementation for get_rooted_block:

    pub fn get_rooted_block(
    ...
    ) -> Result<VersionedConfirmedBlock> {
        datapoint_info!("blockstore-rpc-api", ("method", "get_rooted_block", String));
        let _lock = self.check_lowest_cleanup_slot(slot)?;

        if self.is_root(slot) {
            return self.get_complete_block(slot, require_previous_blockhash);
        }
        Err(BlockstoreError::SlotNotRooted)
    }

And the implementation for check_lowest_cleanup_slot:

    fn check_lowest_cleanup_slot(&self, slot: Slot) -> Result<std::sync::RwLockReadGuard<Slot>> {
        // lowest_cleanup_slot is the last slot that was not cleaned up by LedgerCleanupService
        let lowest_cleanup_slot = self.lowest_cleanup_slot.read().unwrap();
        if *lowest_cleanup_slot > 0 && *lowest_cleanup_slot >= slot {
            return Err(BlockstoreError::SlotCleanedUp);
        }
        // Make caller hold this lock properly; otherwise LedgerCleanupService can purge/compact
        // needed slots here at any given moment
        Ok(lowest_cleanup_slot)
    }

Note that the lock is held for get_rooted_block() but not when get_complete_block() is called directly. The instance in which the individual who provided reliable report of hitting this said they were serving RPC requests on very old slots, some details in this Discord thread. Namely, Lijun commented:

Do you have RPC calls loading relatively older slots? The slot in question 145566485 was completed 4 hours before the panic

However, if the node was serving RPC requests on very old slots, those very old slots should have been rooted, so I think the codepath would have hit the route that involves lowest_cleanup_slot lock

[behzadnouri]

The get_block() RPC call will also trigger this call, and the validator that hit this issue was also serving heavy load RPC calls.

I have seen this panic a lot on the cluster from non-rpc nodes.
I think it is a major bug if ledger clean-up service is removing shreds prematurely.

The way this commit is silencing the panic prevents us from identifying and fixing the root cause here.

I don't know about the RPC call path, but we need to make sure the other call paths (replay and anything else) don't simply ignore the error here.

[yhchiang-sol]

I don't know about the RPC call path, but we need to make sure the other call paths (replay and anything else) don't simply ignore the error here.

Sure thing. I will create follow-up PR to make sure those critical code-path panic for this type of error.

[yhchiang-sol]

I have seen this panic a lot on the cluster from non-rpc nodes.

@behzadnouri: Can I know whether this is seen recently or it has been there for a while? In addition, can I know whether this happens during the initial catch-up duration or not?

I think it is a major bug if ledger clean-up service is removing shreds prematurely.

Originally I was baking #27498 that makes ledger-cleanup-service honor the confirm slot progress, but I found the ledger-cleanup-service already honors the root so it never purges anything newer than the root inside find_slots_to_clean:

    fn find_slots_to_clean(
        blockstore: &Arc<Blockstore>,
        root: Slot,
        max_ledger_shreds: u64,
    ) -> (bool, Slot, u64) {
        ...
        for (i, (slot, meta)) in blockstore.slot_meta_iterator(0).unwrap().enumerate() {
            if i == 0 {
                debug!("purge: searching from slot: {}", slot);
            }
            // Not exact since non-full slots will have holes
            total_shreds += meta.received;
            total_slots.push((slot, meta.received));
            if slot > root { // <--- this makes sure we never return the lowest_cleanup_slot that is newer than root.
                break;
            }
        }

[behzadnouri]

@behzadnouri: Can I know whether this is seen recently or it has been there for a while? In addition, can I know whether this happens during the initial catch-up duration or not?

There were some from last 30 day which I was querying but I don't remember their exact days.
You can query panics from the metrics:
https://github.com/solana-labs/solana/blob/2da93bd45/metrics/src/metrics.rs#L452-L460

[behzadnouri]

https://discord.com/channels/428295358100013066/439194979856809985/1070199891609014292

This is now panicking on mainnet on v1.15.

[mvines]

This may be related to a reduced --limit-ledger-size that I hacked in, it may be harder to get the stock build to panic. I'll work on some STR and open an issue once I localize

[steviez]

I started peaking around code a little bit since I had touched some of these items recently and things are still fairly fresh. As a general refresher (for my own sake too), the issue stems from inconsistency between meta data and shreds for a slot. For some slot s, we have meta information (such as from a SlotMeta) that leads us to believe shreds should be present. But, we hit the panic if those shreds aren't actually retrievable.

Here are some miscellaneous notes; LCS = LedgerCleanupService:

• LCS idles until it observes a new root that is 512 slots newer than from the last time it ran
  

  solana/core/src/ledger_cleanup_service.rs

  Line 41 in a5af546

  pub const DEFAULT_PURGE_SLOT_INTERVAL: u64 = 512;

  • mvines' reduced --limit-ledger-size could be around this such that we're hitting some weird edge case where we're essentially purging all unrooted slot
• LCS has a guard to avoid cleaning newer than latest root (these roots passed to LCS through a crossbeam channel)
  

  solana/core/src/ledger_cleanup_service.rs

  Lines 164 to 165 in a5af546

  	// Ensure we don't cleanup anything past the last root we saw
  	let lowest_cleanup_slot = std::cmp::min(lowest_slot + num_slots_to_clean - 1, root);

  • As a result of this check, the issue should NOT be occurring from ReplayStage (through blockstore_processor), as a slot will not be rooted (or at least not known to be rooted to us if we're catching up) until after we've replayed it

Reading the meta information and reading the shreds are separate queries to rocks, so it is seemingly the case that a slot is getting cleaned up between reads. We could grab a lowest_cleanup_slot read-lock after querying the meta information, but the function is called so often, that this could potentially interfere with LCS (multiple threads may be calling this function, can't recall if heavy/overlapping read-locks would starve the write-lock needed by LCS).

If we get steps to repro, I think the following things would be helpful:

• Full backtrace so we can see which service is panicking (ie confirm if my theory about it not being ReplayStage is true)
• Logs from shortly before the panic, specifically, those from solana_core::ledger_cleanup_service.
  • This would confirm if the slot we panicked on was just cleaned up.

At the moment, my money is on CompletedDataSetService; it calls Blockstore::get_entries_in_data_block() directly with meta information that it pulls out of a crossbeam channel, so a decent opportunity for latency to creep in between reads.