Solana: MismatchedBankHash when loading a mainnet-beta snapshot

[mvines]

STR:

1. Using the v1.0.10 release, run solana-validator -l ledger -n mainnet-beta.solana.com:8001 -o -

The snapshot produces a bank hash mismatch and the validator terminates:

[2020-03-28T03:38:09.912189893Z INFO  solana_ledger::snapshot_utils] Loaded bank for slot: 2242884
[2020-03-28T03:38:09.912278093Z INFO  solana_runtime::accounts_db] total_stores: 188, newest_slot: 2242884, oldest_slot: 0, max_slot: 0 (num=5), min_slot: 1816112 (num=1)
[2020-03-28T03:38:09.912427593Z INFO  solana_metrics::metrics] datapoint: accounts_db-stores total_count=188i
[2020-03-28T03:38:09.922820695Z WARN  solana_runtime::accounts_db] mismatched bank hash for slot 2242884: t6z86G59dJovkMtQ4f3VLKb4RCTHW2fWzKy7GrYuRFF (calculated) != 24LJe47dJQAbavHKhDZ8bP4iT7f1BuqT7s1wzpPyNnfX (expected)
[2020-03-28T03:38:09.922856295Z WARN  solana_runtime::accounts] verify_bank_hash failed: MismatchedBankHash
thread 'main' panicked at 'Snapshot bank for slot 2242884 failed to verify', ledger/src/snapshot_utils.rs:460:9

[mvines]

The last known good snapshot with 12 hours of ledger leading up to the bank hash mismatch can be fetched with:

$ gsutil cp gs://mainnet-beta-ledger-us-west1/2142928/rocksdb.tar.bz2 .
$ gsutil cp gs://mainnet-beta-ledger-us-west1/2142928/snapshot-2142928-5ZC8wD6DtjykpGrPwDkXi9xQzVpu9VvjKZNgSRuVHrMa.tar.bz2 .

[mvines]

When I restarted the warehouse nodes from the 2142928/ snapshot, they replayed the ledger from 2142928/rocksdb.tar.bz2, and the first new snapshot they produced was also bad. So it seems like we have a way to reproduce at least!

[mvines]

Snapshots are ok on tds and devnet, both running the same software version as mainnet-beta

[ryoqun]

I've found more recent working snapshot. :)
Slot 2238409
From 35.197.15.55

[2020-03-28T04:51:04.811561856Z INFO  solana_ledger::blockstore] Maximum open file descriptors: 65000
[2020-03-28T04:51:04.985970088Z INFO  solana_ledger::blockstore] "/home/ryoqun/work/solana/solana/mainnet-beta/35.197.15.55/rocksdb" open took 174ms
[2020-03-28T04:51:04.986123824Z INFO  solana_ledger::bank_forks_utils] Initializing snapshot path: "/home/ryoqun/work/solana/solana/mainnet-beta/35.197.15.55/snapshot"
[2020-03-28T04:51:04.994578290Z INFO  solana_ledger::bank_forks_utils] Loading snapshot package: "/home/ryoqun/work/solana/solana/mainnet-beta/35.197.15.55/snapshot-2238409-HWjPWLw6tUxcaAYPYzmHoueP7cYZmNmjTZaDF6r4RNsE.tar.bz2"
[2020-03-28T04:51:08.840105058Z INFO  solana_ledger::snapshot_utils] snapshot untar took 3.8s
[2020-03-28T04:51:08.840398957Z INFO  solana_ledger::snapshot_utils] snapshot version: 1.0.0
[2020-03-28T04:51:08.840491948Z INFO  solana_ledger::snapshot_utils] Loading bank from "/home/ryoqun/work/solana/solana/mainnet-beta/35.197.15.55/snapshot/.tmpe73pca/snapshots/2238409/2238409"
[2020-03-28T04:51:08.875675345Z INFO  solana_ledger::snapshot_utils] Rebuilding accounts...
[2020-03-28T04:51:10.672421825Z INFO  solana_ledger::snapshot_utils] Rebuilding status cache...
[2020-03-28T04:51:10.924630056Z INFO  solana_ledger::snapshot_utils] Loaded bank for slot: 2238409
[2020-03-28T04:51:10.925497741Z INFO  solana_runtime::accounts_db] total_stores: 244, newest_slot: 2238409, oldest_slot: 0, max_slot: 0 (num=5), min_slot: 1302412 (num=1)
[2020-03-28T04:51:10.925590145Z INFO  solana_metrics::metrics] metrics disabled: SOLANA_METRICS_CONFIG: environment variable not found
[2020-03-28T04:51:10.925802926Z INFO  solana_metrics::metrics] datapoint: accounts_db-stores total_count=244i
[2020-03-28T04:51:11.019361353Z INFO  solana_runtime::accounts_db] scan took 659us merge took 80us accumulate took 611us
[2020-03-28T04:51:11.019720849Z INFO  solana_runtime::bank] bank frozen: 2238409 hash: BAJcCVYbuyHojT1sMomdbMQZQpiqD9uw5KfWvSJPzaKh accounts_delta: 4tMhdhj2rSfuJVQr1ETpiZGfqPsA8fN8S7KFubUJFgg4 signature_count: 56 last_blockhash: ECDEZqCRX6GSoDxCauWv5wRNdtPfFAFhg3rmTQRbM18p
[2020-03-28T04:51:11.019980253Z INFO  solana_runtime::bank] accounts hash slot: 2238409 stats: BankHashStats { num_removed_accounts: 118, num_added_accounts: 0, num_lamports_stored: 28057641856565, total_data_len: 366577, num_executable_accounts: 0 }
[2020-03-28T04:51:11.020045213Z INFO  solana_ledger::snapshot_utils] bank rebuild from snapshot took 2.2s
[2020-03-28T04:51:11.025110941Z INFO  solana_ledger::blockstore_processor] processing ledger from slot 2238409...
[2020-03-28T04:51:11.931675719Z INFO  solana_ledger::blockstore_processor] ledger processed in 905ms. 88 MB allocated. 1 fork at 2238409, with 1 frozen bank
Ok

[ryoqun]

The last known good snapshot with 12 hours of ledger leading up to the bank hash mismatch can be fetched with:

$ gsutil cp gs://mainnet-beta-ledger-us-west1/2142928/rocksdb.tar.bz2 .
$ gsutil cp gs://mainnet-beta-ledger-us-west1/2142928/snapshot-2142928-5ZC8wD6DtjykpGrPwDkXi9xQzVpu9VvjKZNgSRuVHrMa.tar.bz2 .

My strategy is that I try to create a bad snapshot at Slot 2238409 from this data and compare to it to the good snapshot with the same slot.

[mvines]

@ryoqun - I placed a good and bad snapshot for slot 2238208 at
https://drive.google.com/drive/folders/1arL8Tk3X448MKM4O5VUBGKO50ZPRDxJO?usp=sharing

The bad snapshot was generated by warehouse-us-west1-b, the good snapshot was generated by running solana-ledger-tool create-snapshot 2238208 ... on my local machine

[ryoqun]

Still investigating, the current finding is that it seems that there're yet yet yet another bug in cleaning zero lamport accounts. The following 2 pubkeys appear only in the bad account:

--- /dev/fd/63  2020-03-28 15:38:47.259515568 +0900
+++ /dev/fd/62  2020-03-28 15:38:47.259515568 +0900
@@ -33,6 +33,7 @@
 2T1aRXuA72o19Wrne1HZCZkhLGgt44h9mVML7UiMfscj AccountStorageEntry
 2utNvDN3Q25Z72C613ANSZvVdrKixiAx6xSTq5u3bU2q AccountStorageEntry
 2VmrF27dwgAt5Kv9QivLeYLagvjp79va9p6bZ4SYaLeV AccountStorageEntry
+2w52TS1ixFkKF57ctvkngz3cvwJ6kAVUk5y3Lm2AcqZr AccountStorageEntry
 2Xmbd9YDdqeFHtQ3SG4WPmUAxgftAHPR5zgGJnWurjq3 AccountStorageEntry
 2XspGK3MffSjTv67ouj3aX1iwncmtjnsgnMJ6zNUu8BE AccountStorageEntry
 2YPQaJk2x74yaW3jQuDzkcpgo3Vz99BpEtAcUbDRc5Pb AccountStorageEntry
@@ -280,6 +281,7 @@
 8yp7p6uYLZpqzBC1PCUT5fwfa42QCNhh5HbaJKhEatfn AccountStorageEntry
 8yWT1CRuwfbSmeSrWdCvp7h2Pe9sNTt6K2HS5x1BTTtf AccountStorageEntry
 8ZWFEoAz3zzN2gbtwY6CSWsk3174cvByDREvx5kvnr8N AccountStorageEntry
+92viKFftk1dJjqJwreFqT2qHXxjSUuEE9VyHvTdY1mpY AccountStorageEntry
 93E4vRVizTe1eT9RRNyi3gadGE1JW8oq5EXbxtFP5g5j AccountStorageEntry
 95HsPFFvwbWpk42MKzenauSoULNzk8Tg6fc6EiJhLsUZ AccountStorageEntry
 95Nf8XfoecteSXU9nbcvzkrFQdu6FqPaH3EvhwLaC83t AccountStorageEntry

[ryoqun]

Progressed a little. :)

The bad snapshot problem is that some Storage entry didn't correctly removed. Apparently, when 2w52TS1ixFkKF57ctvkngz3cvwJ6kAVUk5y3Lm2AcqZr and 92viKFftk1dJjqJwreFqT2qHXxjSUuEE9VyHvTdY1mpY got cleaned as cleanable zero lamport account, it didn't remove all of storage entries which contained updates to the pubkeys.

Namely, bad snapshots can become good ones merely removing two files in the snapshot manually!..

[2020-03-28T09:40:05.479945488Z WARN  solana_runtime::accounts_db] AccountsDB error: "Unable to move \"/home/ryoqun/work/solana/solana/mainnet-beta/34.82.103.142/snapshot/.tmpU9qbYA/accounts/109212.110258\" to \"/home/ryoqun/work/so>
[2020-03-28T09:40:05.480023239Z INFO  solana_runtime::accounts_db] Err(Custom { kind: Other, error: "Unable to move \"/home/ryoqun/work/solana/solana/mainnet-beta/34.82.103.142/snapshot/.tmpU9qbYA/accounts/109212.110258\" to \"/home>
[2020-03-28T09:40:05.498922853Z WARN  solana_runtime::accounts_db] AccountsDB error: "Unable to move \"/home/ryoqun/work/solana/solana/mainnet-beta/34.82.103.142/snapshot/.tmpU9qbYA/accounts/1240368.4258182\" to \"/home/ryoqun/work/>
[2020-03-28T09:40:05.498991782Z INFO  solana_runtime::accounts_db] Err(Custom { kind: Other, error: "Unable to move \"/home/ryoqun/work/solana/solana/mainnet-beta/34.82.103.142/snapshot/.tmpU9qbYA/accounts/1240368.4258182\" to \"/ho>
...
Ok

[ryoqun]

Steps to create a good snapshot from a bad snapshot...

(mkdir -p mainnet-beta3 && cd mainnet-beta3  && curl -O $(curl -I -Ls -o /dev/null -w %{url_effective} http://34.91.171.91:8899/snapshot.tar.bz2) && curl -O http://34.91.171.91:8899/genesis.tar.bz2)
cd mainnet-beta3/
tar xvf genesis.tar.bz2
solana-ledger-tool --ledger . verify # should fail
mv snapshot-2304616-8RdFwdnDWBw73itnWyHo5j8oHVpRUcWF7wPf325w2aqz{,.orig}.tar.bz2
mkdir for-edit
cd for-edit/
tar xvf ../snapshot-2304616-8RdFwdnDWBw73itnWyHo5j8oHVpRUcWF7wPf325w2aqz.orig.tar.bz2
rm accounts/109212.109960
rm accounts/1240368.3553798
tar cjvf ../snapshot-2304616-8RdFwdnDWBw73itnWyHo5j8oHVpRUcWF7wPf325w2aqz.tar.bz2 accounts/ snapshots/ version
cd ..
solana-ledger-tool --ledger . verify # should succeed

[sakridge]

I made a patch to run from the 2142928 slot snapshot and ledger:
thread 'solana-snapshot-packager' panicked at 'Snapshot bank for slot 2177740

This is the one that fails. I have snapshots for 2177640 which is good and 2177740 which is bad.

[sakridge]

I put them here:
https://drive.google.com/drive/folders/1bTzBVi39lhRDHgvgFsyf7MasMVkLmDRR?usp=sharing

[ryoqun]

Hmm, I've come up with a possibility, finally... I'll try to write a test

[sakridge]

Hmm, I've come up with a possibility, finally... I'll try to write a test

I think it's an issue with this loop:

purges.retain(|pubkey, account_infos| {
    let mut would_unref_count = 0;
    for (_slot_id, account_info) in account_infos.iter() {
        if *store_counts.get(&account_info.store_id).unwrap() == 0 {
            would_unref_count += 1;
        } else {
            return false;
        }
    }

    would_unref_count == accounts_index.ref_count_from_storage(&pubkey)
}

Two accounts are in store 110705, but only one of them would unref itself. So this account is removed but store 110705 remains. In the new snapshot the account which is removed is revived which is the 92viKF one.