Debugging Consensus Failures

This page is meant to provide some steps to identify and narrow down the cause of consensus failures on nodes. The high level steps include:

1. Finding the slot where consensus broke
2. Gathering the necessary artifacts to reproduce the issue locally
3. Testing with both "good" (consensus matches cluster) and "bad" code versions
4. Diffing good/bad output to identify accounts and/or transactions where consensus broke
5. Inspiration for root causing beyond above step

Identifying a Consensus Failure

There are several symptoms that could be indicative of a consensus failure; these include:

• No new roots being made
• Sharp increase in memory usage

That being said, logs provide the ultimate source of truth. The below section includes some log statements that would confirm if a node had a consensus failure.

Finding the Offending Slot

Scanning the validator logs is the best route to finding the slot where consensus broke. Finding the latest new root is a good starting point:

[TIMESTAMP INFO  solana_core::replay_stage] new root {}

With the last new root known, search the surrounding "area" (both before and after - often a tower distance away) for the following log statements:

[TIMESTAMP WARN  solana_core::cluster_slot_state_verifier] Cluster duplicate confirmed slot {} with hash {}, but our version has hash {}
[TIMESTAMP WARN  solana_vote_program::vote_state] {} dropped vote slots {:?} failed to match hash {} {}

Sometimes, a node that has experienced a consensus failure will get into a loop of checking / failing / purging / repairing a slot. Seeing the bank frozen log line for the same slot repeatedly is a quick way to identify this (and further inspection should show the repeated purges/repairs as well):

[TIMESTAMP INFO  solana_runtime::bank] bank frozen: {} hash: {} accounts_delta: {} signature_count: {} last_blockhash: {} capitalization: {}

Bank hashes are computed here. As of writing this, the bank hash is a "combined" hash of the slots's:

1. parent bank hash
2. account delta hash
3. signature count
4. blockhash As such, any of these items being off will cause the bank hash to be wrong.

For the rest of this guide, FAIL_SLOT will refer to the slot where the failure was identified.

Finding the Offending Account and/or Transaction

Collect a Ledger

Once the offending slot is known, the first step is collecting a ledger to reliably and quickly reproduce the issue. This process can be a little complicated in itself, and more details on this can be found TODO. Namely, a ledger with the following is needed to replay:

• A snapshot at slot SNAPSHOT_SLOT where SNAPSHOT_SLOT < FAIL_SLOT.
  • This is the file of form snapshot-SNAPSHOT_SLOT-HASH.tar.zst
• The shreds (transaction data) for slots [SNAPSHOT_SLOT, FAIL_SLOT].
  • This is the data contained in rocksdb directory.
  • For good measure and if available, grab the shreds for slots SNAPSHOT_SLOT - 1 and FAIL_SLOT + 1 as well
  • Shreds for a range of slots can be collected using the solana-ledger-tool copy command
• The cluster specific genesis.bin file.
  • Running solana-validator will sync this so this file can be copied from the node that break was found on.

Reproduce Locally

With a ledger in-hand, solana-ledger-tool verify can be used to replay FAIL_SLOT with the following command:

$ solana-ledger-tool verify --ledger LEDGER_DIR --halt-at-slot FAIL_SLOT

Note that replaying a ledger requires large amount of system resources. I.e. you may have problems with your personal laptop and will have more success with a proper validator setup.

Replaying will log bank hashes; the log statement to look for is:

[TIMESTAMP INFO  solana_runtime::bank] bank frozen: SLOT hash: BANK_HASH accounts_delta: ACCOUNT_HASH signature_count: M last_blockhash: BLOCK_HASH capitalization: N

Perform the following steps to confirm that the correct & incorrect behavior can be reproduced locally:

1. Backup the rocksdb folder somewhere just incase.
2. Using the command above, replay with the cluster majority software version and confirm the correct bank hash is calculated for FAIL_SLOT.
3. Using the command above, replay with the version that broke and confirm the incorrect bank hash is calculated for FAIL_SLOT.

Find Differing Accounts

Looking at list of updated accounts will shed some light on which transaction had a different result between the two software versions. Note that looking at accounts could reveal a difference in a Sysvar, which may not necessarily be tied to a specific transaction. The following patch is a simple change that will log all updated accounts.

Patch to Print Updated Accounts

diff --git a/runtime/src/accounts_db.rs b/runtime/src/accounts_db.rs
index 4893f3104c..34a9f02d33 100644
--- a/runtime/src/accounts_db.rs
+++ b/runtime/src/accounts_db.rs
@@ -5937,7 +5937,7 @@ impl AccountsDb {
             hashes.retain(|(pubkey, _hash)| !self.is_filler_account(pubkey));
         }
 
-        let ret = AccountsHash::accumulate_account_hashes(hashes);
+        let ret = AccountsHash::accumulate_account_hashes(slot, hashes);
         accumulate.stop();
         let mut uncleaned_time = Measure::start("uncleaned_index");
         self.uncleaned_pubkeys.insert(slot, dirty_keys);
diff --git a/runtime/src/accounts_hash.rs b/runtime/src/accounts_hash.rs
index 54aaa5c475..252dd44833 100644
--- a/runtime/src/accounts_hash.rs
+++ b/runtime/src/accounts_hash.rs
@@ -3,6 +3,7 @@ use {
     rayon::prelude::*,
     solana_measure::measure::Measure,
     solana_sdk::{
+        clock::Slot,
         hash::{Hash, Hasher},
         pubkey::Pubkey,
     },
@@ -487,9 +488,13 @@ impl AccountsHash {
         )
     }
 
-    pub fn accumulate_account_hashes(mut hashes: Vec<(Pubkey, Hash)>) -> Hash {
+    pub fn accumulate_account_hashes(slot: Slot, mut hashes: Vec<(Pubkey, Hash)>) -> Hash {
         Self::sort_hashes_by_pubkey(&mut hashes);
-
+        if slot == FAIL_SLOT {
+            for hash in hashes.iter() {
+                warn!("Updated Account: {:?}", hash);
+            }
+        }
         Self::compute_merkle_root_loop(hashes, MERKLE_FANOUT, |i| i.1)
     }

Perform the following steps to finally narrow down on divergent transaction:

1. Apply the above patch - make sure to plug in the actual value of FAIL_SLOT.
2. Replay with both the good and bad software versions using the same command as above; however, make the following tweaks to get more verbose output and write to file (make sure to change the output log filename for good and bad):

$ RUST_LOG=solana=debug solana-ledger-tool verify --ledger LEDGER_DIR --halt-at-slot FAIL_SLOT 2> {good|bad}_output.log

3. Run the following command on each output file to parse out the "Updated Account" statements.

$ grep -o "Updated Account: .*" {good|bad}_output.log > {good|bad}_updated_accounts.txt

4. Diff the files from previous step that contain all updated accounts for each software version, and note any differing accounts (the pubkey is first element in tuple). Suppose that DIFF_PUBKEY is the / one of the accounts that has different state.

Log Differing Account(s) Details

With known differing accounts, additional logging can be done to print out specifics of these accounts. The following patch shows where to plug into to print state for specific accounts.

Patch to Print Specific Account Details

diff --git a/runtime/src/bank.rs b/runtime/src/bank.rs
index 50e8aed5fa..a451ba6ed6 100644
--- a/runtime/src/bank.rs
+++ b/runtime/src/bank.rs
@@ -158,6 +158,7 @@ use {
         ops::{Deref, Div, RangeInclusive},
         path::PathBuf,
         rc::Rc,
+        str::FromStr,
         sync::{
             atomic::{
                 AtomicBool, AtomicI64, AtomicU64, AtomicUsize,
@@ -6660,6 +6661,10 @@ impl Bank {
     /// Hash the `accounts` HashMap. This represents a validator's interpretation
     ///  of the delta of the ledger since the last vote and up to now
     fn hash_internal_state(&self) -> Hash {
+        if self.slot() == FAIL_SLOT {
+            warn!("Account details: {:?}", self.get_account_with_fixed_root(&Pubkey::from_str("DIFF_PUBKEY").unwrap()));
+        }
+
         // If there are no accounts, return the hash of the previous state and the latest blockhash
         let accounts_delta_hash = self
             .rc

With this patch in place, run solana-ledger-tool verify with same arguments to yield the new log statements.

Find Transactions that Touch Differing Account(s)

1. Run solana-ledger-tool slot to display all transaction information for a given slot. Combined with account pubkey(s) that differed between runs before, run the following to see what transaction(s) involve the differing account(s).

$ solana-ledger-tool slot FAIL_SLOT -vv | grep DIFF_PUBKEY

Finding the Root Cause

At this point, it should be known which account(s)/transaction(s) caused the consensus break. If the failure can be traced to a specific transaction, the below sections provide some more insight into how one could learn more about why the transaction is differing between two versions. If the failure isn't tied to a specific transaction, it is likely that the affected account is "special" in some way, and digging through the explorer.solana.com and/or the code to see how/when that account is updated is likely necessary.

Examine Transaction Details

Look for things that might be "special" about this transaction, such as the slot, involved programs, last deploy date, read/write, etc.

Lookup Transaction Error

If a transaction had different result between versions, it is very possible that it failed on one version. Log output might contain some more information, such as an error for why the transaction failed. To find this log output:

1. Note one of the signatures for the transaction in question from solana-ledger-tool slot output.
2. Search the log output from replay for this signature (log level must at least include debug to get anything useful here):

$ < output.log grep TX_SIGNATURE

Depending on the situation, adding the flags to include lines before and after match might be helpful. But, there will be a line of log output that includes the signature, and also includes the error right at the start.

[TIMESTAMP DEBUG solana_runtime::bank] tx error: Err(...

This error will provide a good starting point to search the codebase and determine what is causing logic to fall through to error case.

Git Bisect

Given that replaying should only take several minutes if the snapshot is at a slot shortly before FAIL_SLOT, running a bisect to find the breaking commit is manageable.