Solana: Validator creates bad snapshot when there is unfunded vote account

[ryoqun]

Problem

In some condition, validator creates bad snapshot and prevents other nodes from resuming from the snapshot after fetching it.

STR:

1. ./run.sh
2. solana create-vote-account
3. (may be optional; fund some to vote some to the node)
4. join a node to the leader node.
5. wait until the node's balance becomes zero and the leader node creates a new snapshot
6. (once funded again, snapshot resumption failure disappears.)

The problem is that there is an account with zero lamports in snapshot if there is unfunded vote account, triggering verification failure when resuming.

In a clean and controlled environment, this is rather rare case, but, this sure will happen a lot on the wild. ;)

According to @mvines, he also spotted these errors as well.

Details

The problematic snapshot is causing trouble on the verification when resuming from it.

Although, it seems that BQgq3WRtoB3TwQ16dLZTamupnEz6WY7FvV7RfivLyag9 doesn't exist, but it's contained in snapshot:

ryoqun@ubuqun:~/work/solana/solana$ ./target/release/solana --url http://127.0.0.1:8899 show-validators
RPC Endpoint: http://127.0.0.1:8899
Active Stake: 12334.576987186 SOL
Current Stake: 12334.076987186 SOL (100.00%)
Delinquent Stake: 0.5 SOL (0.00%)

  Identity Pubkey                               Vote Account Pubkey                           Commission    Last Vote   Root Block  Active Stake
  Dry9EWJ86qangjcaDvFMNMJoysq3xbnHGMG4U9jyLuAo  CzJKNwdmVcrwDxKX7C74KybGB2JL666sEPnaXpCnsiLg    0 ( 0.0%)       22511        22480  12334.076987186 SOL (100.00%)
! BQgq3WRtoB3TwQ16dLZTamupnEz6WY7FvV7RfivLyag9  7Aetw8C36S6vtKGzLxj36LC43YzPakUJ7FzsyhSTgVtH    0 ( 0.0%)       10845        10814  0.5 SOL (0.00%)
! 7SgZJnxM7PSSE7PJ7BgPXdG1NH5sqxDDnNyiie5d1Aqg  8b7Q1HCqvssRTUsjp1L2jre1uNoSrNVExzYNCHinwD4i    0 ( 0.0%)       22461        22430            -

ryoqun@ubuqun:~/work/solana/solana$ SOLANA_LOGFILE=/dev/stderr ./target/release/solana --url http://127.0.0.1:8899 show-account BQgq3WRtoB3TwQ16dLZTamupnEz6WY7FvV7RfivLyag9
RPC Endpoint: http://127.0.0.1:8899
Error: Custom { kind: Other, error: "AccountNotFound: pubkey=BQgq3WRtoB3TwQ16dLZTamupnEz6WY7FvV7RfivLyag9: solana client error" }
ryoqun@ubuqun:~/work/solana/solana$ SOLANA_LOGFILE=/dev/stderr ./target/release/solana --url http://127.0.0.1:8899 show-vote-account BQgq3WRtoB3TwQ16dLZTamupnEz6WY7FvV7RfivLyag9
RPC Endpoint: http://127.0.0.1:8899
Error: Custom { kind: Other, error: "AccountNotFound: pubkey=BQgq3WRtoB3TwQ16dLZTamupnEz6WY7FvV7RfivLyag9: solana client error" }




ryoqun@ubuqun:~/work/solana/solana$ grep found solana-validator-BQgq3WRtoB3TwQ16dLZTamupnEz6WY7FvV7RfivLyag9-20191112-143530.log
[2019-11-12T14:35:30.447950519Z INFO  solana_metrics::metrics] metrics disabled: SOLANA_METRICS_CONFIG: environment variable not found
[2019-11-12T14:35:37.675238551Z WARN  solana_runtime::bank] found zero lamports BQgq3WRtoB3TwQ16dLZTamupnEz6WY7FvV7RfivLyag9, Account { lamports: 0 data.len: 0 owner: 11111111111111111111111111111111 executable: false rent_epoch: 0 ha
10846

```
[2019-11-11T12:50:39.150796904Z INFO solana_ledger::bank_forks_utils] Loading snapshot package: "/home/ryoqun/work/solana/solana/for-small-patches/config/ledger/snapshot.tar.bz2"
[2019-11-11T12:50:39.200157953Z INFO solana_ledger::snapshot_utils] Loading from "/home/ryoqun/work/solana/solana/for-small-patches/config/ledger/snapshot/.tmplU4qyN/snapshots/6400/6400"
thread 'main' panicked at 'Snapshot bank failed to verify', ledger/src/snapshot_utils.rs:226:9
stack backtrace:
0: backtrace::backtrace::libunwind::trace
at /cargo/registry/src/github.com-1ecc6299db9ec823/backtrace-0.3.37/src/backtrace/libunwind.rs:88
1: backtrace::backtrace::trace_unsynchronized
at /cargo/registry/src/github.com-1ecc6299db9ec823/backtrace-0.3.37/src/backtrace/mod.rs:66
2: std::sys_common::backtrace::_print_fmt
at src/libstd/sys_common/backtrace.rs:77
3: ::fmt
at src/libstd/sys_common/backtrace.rs:61
4: core::fmt::write
at src/libcore/fmt/mod.rs:1028
5: std::io::Write::write_fmt
at src/libstd/io/mod.rs:1412
6: std::sys_common::backtrace::_print
at src/libstd/sys_common/backtrace.rs:65
7: std::sys_common::backtrace::print
at src/libstd/sys_common/backtrace.rs:50
8: std::panicking::default_hook::{{closure}}
at src/libstd/panicking.rs:189
9: std::panicking::default_hook
at src/libstd/panicking.rs:206
10: solana_metrics::metrics::set_panic_hook::{{closure}}::{{closure}}
11: std::panicking::rust_panic_with_hook
at src/libstd/panicking.rs:473
12: std::panicking::begin_panic
13: solana_ledger::snapshot_utils::bank_from_archive
14: solana_ledger::bank_forks_utils::load
15: solana_core::validator::new_banks_from_blocktree
16: solana_core::validator::Validator::new
17: solana_validator::main
...
[2019-11-11T12:50:43.029912207Z ERROR solana_metrics::metrics] datapoint: panic program="validator" thread="main" one=1i message="panicked at 'Snapshot bank failed to verify', ledger/src/snapshot_utils.rs:226:9" location="ledger/src/snapshot_utils.rs:226:9"

```patch
ryoqun@ubuqun:~/work/solana/solana$ git diff
diff --git a/runtime/src/accounts_db.rs b/runtime/src/accounts_db.rs
index 949cf20d4..3a56deba1 100644
--- a/runtime/src/accounts_db.rs
+++ b/runtime/src/accounts_db.rs
@@ -860,8 +860,10 @@ impl AccountsDB {
         }
         let slot_hashes = self.slot_hashes.read().unwrap();
         if let Some((_, state)) = slot_hashes.get(&slot) {
+            warn!("ryoqun verify: {}", hash_state == *state);
             hash_state == *state
         } else {
+            warn!("ryoqun failed111");
             false
         }
     }
diff --git a/runtime/src/bank.rs b/runtime/src/bank.rs
index c784d9d14..afd32f3a4 100644
--- a/runtime/src/bank.rs
+++ b/runtime/src/bank.rs
@@ -1403,8 +1403,9 @@ impl Bank {
         self.rc.accounts.accounts_db.scan_accounts(
             &self.ancestors,
             |collector: &mut bool, option| {
-                if let Some((_, account, _)) = option {
+                if let Some((_a, account, _b)) = option {
                     if account.lamports == 0 {
+                        warn!("found zero lamports {:?}, {:?}, {:?}", _a, account, _b);
                         *collector = true;
                     }
                 }

Proposed Solution

• Ignore such a vote_account when creating? (This might be better considering the first existence of snapshot verification code)
• Skip such a vote_account when importing?

I didn't thought about solution much; As this is a simple corner-casing bug, I'm pretty sure some knowledgeable guy than me can just quickly propose a solution. :smile:

[mvines]

I am able to reproduce this issue on testnet.solana.com right now thanks to a report from Discord

[mvines]

I pulled off the bad snapshot from testnet.solana.com: bad.tar.gz

STR:

1. On the 0.20 branch, untar the bad snapshot
2. Run cargo run --package solana-validator -- --ledger bad --log -:

$ cargo run --package solana-validator -- --ledger bad --log -
    Finished dev [unoptimized + debuginfo] target(s) in 0.26s
     Running `target/debug/solana-validator --ledger bad --log -`
solana-validator 0.20.5 [channel=unknown commit=unknown]
[2019-11-12T16:58:27.493260000Z INFO  solana_metrics::metrics] host id: 5eGrAWrpvk5CdFpMsEDw3zQXvWYab9aXtwCJgW7p7L9s
[2019-11-12T16:58:27.494397000Z WARN  solana_core::validator] identity pubkey: 5eGrAWrpvk5CdFpMsEDw3zQXvWYab9aXtwCJgW7p7L9s
[2019-11-12T16:58:27.494473000Z WARN  solana_core::validator] vote pubkey: F1SK7awZX1oH47XuTTsdfQ2sJU8NkALfxYVUJjAfjfJ7
[2019-11-12T16:58:27.494572000Z WARN  solana_core::validator] CUDA is disabled
[2019-11-12T16:58:27.494606000Z INFO  solana_core::validator] AVX detected
[2019-11-12T16:58:27.494627000Z INFO  solana_core::validator] entrypoint: None
[2019-11-12T16:58:27.494655000Z INFO  solana_core::validator] ContactInfo { id: 5eGrAWrpvk5CdFpMsEDw3zQXvWYab9aXtwCJgW7p7L9s, gossip: V4(127.0.0.1:8254), tvu: V4(127.0.0.1:9929), tvu_forwards: V4(127.0.0.1:9860), repair: V4(127.0.0.1:8328), tpu: V4(127.0.0.1:8685), tpu_forwards: V4(127.0.0.1:8378), storage_addr: V4(0.0.0.0:0), rpc: V4(0.0.0.0:0), rpc_pubsub: V4(0.0.0.0:0), wallclock: 0 }
[2019-11-12T16:58:27.494829000Z INFO  solana_core::validator] local gossip address: 0.0.0.0:8254
[2019-11-12T16:58:27.494860000Z INFO  solana_core::validator] local broadcast address: 0.0.0.0:8888
[2019-11-12T16:58:27.494888000Z INFO  solana_core::validator] local repair address: 0.0.0.0:8328
[2019-11-12T16:58:27.494927000Z INFO  solana_core::validator] local retransmit address: 0.0.0.0:9076
[2019-11-12T16:58:27.494954000Z INFO  solana_core::validator] Initializing sigverify, this could take a while...
[2019-11-12T16:58:27.494981000Z INFO  solana_core::validator] Done.
[2019-11-12T16:58:27.495001000Z INFO  solana_core::validator] creating bank...
[2019-11-12T16:58:27.526865000Z INFO  solana_core::validator] genesis blockhash: 7XSCeq8EZ8LQxsQaAKcBPa44eRoqkvjSVjv4KycYkpjq
[2019-11-12T16:58:27.527026000Z INFO  solana_ledger::blocktree] Maximum open file descriptors: 65000
[2019-11-12T16:58:27.586258000Z INFO  solana_ledger::bank_forks_utils] Initializing snapshot path: "bad/snapshot"
[2019-11-12T16:58:27.586590000Z INFO  solana_ledger::bank_forks_utils] Loading snapshot package: "bad/snapshot.tar.bz2"
[2019-11-12T16:58:31.287706000Z INFO  solana_ledger::snapshot_utils] Loading from "/Users/mvines/ws/solana/bad/snapshot/.tmp7gnSeF/snapshots/129500/129500"
thread 'main' panicked at 'Snapshot bank failed to verify', ledger/src/snapshot_utils.rs:225:9
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace.
[2019-11-12T16:58:31.954384000Z INFO  solana_metrics::metrics] metrics disabled: SOLANA_METRICS_CONFIG: environment variable not found
[2019-11-12T16:58:31.954713000Z ERROR solana_metrics::metrics] datapoint: panic program="validator" thread="main" one=1i message="panicked at 'Snapshot bank failed to verify', ledger/src/snapshot_utils.rs:225:9" location="ledger/src/snapshot_utils.rs:225:9"

[mvines]

Serializing out an account with no lamports in it seems like a bug!

[sakridge]

This code is different in master, we purge the lamport=0 accounts before ingesting the snapshot, so I'm not sure if we would see it there.

edit: actually this is wrong, just in my PR. I forgot I did not merge that.

[mvines]

@sakridge - Oh which PR is that?

[ryoqun]

@mvines maybe this one? https://github.com/solana-labs/solana/pull/6797 (FYI: @sakridge)

[sakridge]

@mvines maybe this one? #6797 (FYI: @sakridge)

Yes, that's right.

[ryoqun]

I've confirmed this is fixed by #7010.