Add timeout for local cluster partition tests (#16123)

* Add timeout for local cluster partition tests

* fix optimistic conf test logs

* Bump instruction count assertions

Cargo.lock

@@ -4710,6 +4710,7 @@ dependencies = [
  "itertools",
  "log 0.4.11",
  "rand 0.7.3",
+ "rayon",
  "serial_test",
  "solana-client",
  "solana-config-program",

core/src/optimistic_confirmation_verifier.rs

@@ -76,7 +76,7 @@ impl OptimisticConfirmationVerifier {
         self.last_optimistic_slot_ts = Instant::now();
     }
 
-    pub fn format_optimistic_confirmd_slot_violation_log(slot: Slot) -> String {
+    pub fn format_optimistic_confirmed_slot_violation_log(slot: Slot) -> String {
         format!("Optimistically confirmed slot {} was not rooted", slot)
     }
 
@@ -109,7 +109,7 @@ impl OptimisticConfirmationVerifier {
                     voted stake: {},
                     total epoch stake: {},
                     pct: {}",
-                    Self::format_optimistic_confirmd_slot_violation_log(*optimistic_slot),
+                    Self::format_optimistic_confirmed_slot_violation_log(*optimistic_slot),
                     hash,
                     epoch,
                     r_slot_tracker

local-cluster/Cargo.toml

@@ -16,6 +16,7 @@ gag = "0.1.10"
 fs_extra = "1.2.0"
 log = "0.4.11"
 rand = "0.7.0"
+rayon = "1.5.0"
 solana-config-program = { path = "../programs/config", version = "=1.7.0" }
 solana-core = { path = "../core", version = "=1.7.0" }
 solana-client = { path = "../client", version = "=1.7.0" }

local-cluster/src/cluster_tests.rs

@@ -4,6 +4,7 @@ use log::*;
 /// All tests must start from an entry point and a funding keypair and
 /// discover the rest of the network.
 use rand::{thread_rng, Rng};
+use rayon::prelude::*;
 use solana_client::thin_client::create_client;
 use solana_core::validator::ValidatorExit;
 use solana_core::{
@@ -36,7 +37,7 @@ use std::{
 };
 
 /// Spend and verify from every node in the network
-pub fn spend_and_verify_all_nodes<S: ::std::hash::BuildHasher>(
+pub fn spend_and_verify_all_nodes<S: ::std::hash::BuildHasher + Sync + Send>(
     entry_point_info: &ContactInfo,
     funding_keypair: &Keypair,
     nodes: usize,
@@ -44,9 +45,10 @@ pub fn spend_and_verify_all_nodes<S: ::std::hash::BuildHasher>(
 ) {
     let cluster_nodes = discover_cluster(&entry_point_info.gossip, nodes).unwrap();
     assert!(cluster_nodes.len() >= nodes);
-    for ingress_node in &cluster_nodes {
+    let ignore_nodes = Arc::new(ignore_nodes);
+    cluster_nodes.par_iter().for_each(|ingress_node| {
         if ignore_nodes.contains(&ingress_node.id) {
-            continue;
+            return;
         }
         let random_keypair = Keypair::new();
         let client = create_client(ingress_node.client_facing_addr(), VALIDATOR_PORT_RANGE);
@@ -58,7 +60,7 @@ pub fn spend_and_verify_all_nodes<S: ::std::hash::BuildHasher>(
             .expect("balance in source");
         assert!(bal > 0);
         let (blockhash, _fee_calculator, _last_valid_slot) = client
-            .get_recent_blockhash_with_commitment(CommitmentConfig::processed())
+            .get_recent_blockhash_with_commitment(CommitmentConfig::confirmed())
             .unwrap();
         let mut transaction =
             system_transaction::transfer(&funding_keypair, &random_keypair.pubkey(), 1, blockhash);
@@ -73,7 +75,7 @@ pub fn spend_and_verify_all_nodes<S: ::std::hash::BuildHasher>(
             let client = create_client(validator.client_facing_addr(), VALIDATOR_PORT_RANGE);
             client.poll_for_signature_confirmation(&sig, confs).unwrap();
         }
-    }
+    });
 }
 
 pub fn verify_balances<S: ::std::hash::BuildHasher>(
@@ -276,17 +278,20 @@ pub fn check_for_new_roots(num_new_roots: usize, contact_infos: &[ContactInfo],
     let mut roots = vec![HashSet::new(); contact_infos.len()];
     let mut done = false;
     let mut last_print = Instant::now();
+    let loop_start = Instant::now();
+    let loop_timeout = Duration::from_secs(60);
     while !done {
+        assert!(loop_start.elapsed() < loop_timeout);
         for (i, ingress_node) in contact_infos.iter().enumerate() {
             let client = create_client(ingress_node.client_facing_addr(), VALIDATOR_PORT_RANGE);
             let slot = client.get_slot().unwrap_or(0);
             roots[i].insert(slot);
             let min_node = roots.iter().map(|r| r.len()).min().unwrap_or(0);
-            if last_print.elapsed().as_secs() > 3 {
+            done = min_node >= num_new_roots;
+            if done || last_print.elapsed().as_secs() > 3 {
                 info!("{} min observed roots {}/16", test_name, min_node);
                 last_print = Instant::now();
             }
-            done = min_node >= num_new_roots;
         }
         sleep(Duration::from_millis(clock::DEFAULT_MS_PER_SLOT / 2));
     }

local-cluster/tests/local_cluster.rs

@@ -64,10 +64,13 @@ use std::{
 };
 use tempfile::TempDir;
 
+const RUST_LOG_FILTER: &str =
+    "error,solana_core::replay_stage=warn,solana_local_cluster=info,local_cluster=info";
+
 #[test]
 #[serial]
 fn test_ledger_cleanup_service() {
-    solana_logger::setup();
+    solana_logger::setup_with_default(RUST_LOG_FILTER);
     error!("test_ledger_cleanup_service");
     let num_nodes = 3;
     let validator_config = ValidatorConfig {
@@ -108,7 +111,7 @@ fn test_ledger_cleanup_service() {
 #[test]
 #[serial]
 fn test_spend_and_verify_all_nodes_1() {
-    solana_logger::setup();
+    solana_logger::setup_with_default(RUST_LOG_FILTER);
     error!("test_spend_and_verify_all_nodes_1");
     let num_nodes = 1;
     let local = LocalCluster::new_with_equal_stakes(num_nodes, 10_000, 100);
@@ -123,7 +126,7 @@ fn test_spend_and_verify_all_nodes_1() {
 #[test]
 #[serial]
 fn test_spend_and_verify_all_nodes_2() {
-    solana_logger::setup();
+    solana_logger::setup_with_default(RUST_LOG_FILTER);
     error!("test_spend_and_verify_all_nodes_2");
     let num_nodes = 2;
     let local = LocalCluster::new_with_equal_stakes(num_nodes, 10_000, 100);
@@ -138,7 +141,7 @@ fn test_spend_and_verify_all_nodes_2() {
 #[test]
 #[serial]
 fn test_spend_and_verify_all_nodes_3() {
-    solana_logger::setup();
+    solana_logger::setup_with_default(RUST_LOG_FILTER);
     error!("test_spend_and_verify_all_nodes_3");
     let num_nodes = 3;
     let local = LocalCluster::new_with_equal_stakes(num_nodes, 10_000, 100);
@@ -153,7 +156,7 @@ fn test_spend_and_verify_all_nodes_3() {
 #[test]
 #[serial]
 fn test_local_cluster_signature_subscribe() {
-    solana_logger::setup();
+    solana_logger::setup_with_default(RUST_LOG_FILTER);
     let num_nodes = 2;
     let cluster = LocalCluster::new_with_equal_stakes(num_nodes, 10_000, 100);
     let nodes = cluster.get_node_pubkeys();
@@ -227,7 +230,7 @@ fn test_local_cluster_signature_subscribe() {
 #[allow(unused_attributes)]
 #[ignore]
 fn test_spend_and_verify_all_nodes_env_num_nodes() {
-    solana_logger::setup();
+    solana_logger::setup_with_default(RUST_LOG_FILTER);
     let num_nodes: usize = std::env::var("NUM_NODES")
         .expect("please set environment variable NUM_NODES")
         .parse()
@@ -245,7 +248,7 @@ fn test_spend_and_verify_all_nodes_env_num_nodes() {
 #[test]
 #[serial]
 fn test_leader_failure_4() {
-    solana_logger::setup();
+    solana_logger::setup_with_default(RUST_LOG_FILTER);
     error!("test_leader_failure_4");
     let num_nodes = 4;
     let validator_config = ValidatorConfig::default();
@@ -291,7 +294,7 @@ fn run_cluster_partition<E, F>(
     E: FnOnce(&mut LocalCluster),
     F: FnOnce(&mut LocalCluster),
 {
-    solana_logger::setup();
+    solana_logger::setup_with_default(RUST_LOG_FILTER);
     info!("PARTITION_TEST!");
     let num_nodes = partitions.len();
     let node_stakes: Vec<_> = partitions
@@ -372,7 +375,6 @@ fn run_cluster_partition<E, F>(
     for node in &cluster_nodes {
         let node_client = RpcClient::new_socket(node.rpc);
         let epoch_info = node_client.get_epoch_info().unwrap();
-        info!("slots_per_epoch: {:?}", epoch_info);
         assert_eq!(epoch_info.slots_in_epoch, slots_per_epoch);
     }
 
@@ -415,8 +417,6 @@ fn test_cluster_partition_1_2() {
     run_cluster_partition(&[&[1], &[1, 1]], None, empty, on_partition_resolved, vec![])
 }
 
-#[allow(unused_attributes)]
-#[ignore]
 #[test]
 #[serial]
 fn test_cluster_partition_1_1() {
@@ -620,7 +620,7 @@ fn test_kill_partition_switch_threshold_progress() {
 #[test]
 #[serial]
 fn test_two_unbalanced_stakes() {
-    solana_logger::setup();
+    solana_logger::setup_with_default(RUST_LOG_FILTER);
     error!("test_two_unbalanced_stakes");
     let validator_config = ValidatorConfig::default();
     let num_ticks_per_second = 100;
@@ -680,7 +680,7 @@ fn test_forwarding() {
 #[test]
 #[serial]
 fn test_restart_node() {
-    solana_logger::setup();
+    solana_logger::setup_with_default(RUST_LOG_FILTER);
     error!("test_restart_node");
     let slots_per_epoch = MINIMUM_SLOTS_PER_EPOCH * 2;
     let ticks_per_slot = 16;
@@ -734,7 +734,7 @@ fn test_listener_startup() {
 #[test]
 #[serial]
 fn test_mainnet_beta_cluster_type() {
-    solana_logger::setup();
+    solana_logger::setup_with_default(RUST_LOG_FILTER);
 
     let mut config = ClusterConfig {
         cluster_type: ClusterType::MainnetBeta,
@@ -841,7 +841,7 @@ fn generate_frozen_account_panic(mut cluster: LocalCluster, frozen_account: Arc<
 #[test]
 #[serial]
 fn test_frozen_account_from_genesis() {
-    solana_logger::setup();
+    solana_logger::setup_with_default(RUST_LOG_FILTER);
     let validator_identity =
         Arc::new(solana_sdk::signature::keypair_from_seed(&[0u8; 32]).unwrap());
 
@@ -862,7 +862,7 @@ fn test_frozen_account_from_genesis() {
 #[test]
 #[serial]
 fn test_frozen_account_from_snapshot() {
-    solana_logger::setup();
+    solana_logger::setup_with_default(RUST_LOG_FILTER);
     let validator_identity =
         Arc::new(solana_sdk::signature::keypair_from_seed(&[0u8; 32]).unwrap());
 
@@ -905,7 +905,7 @@ fn test_frozen_account_from_snapshot() {
 #[test]
 #[serial]
 fn test_consistency_halt() {
-    solana_logger::setup();
+    solana_logger::setup_with_default(RUST_LOG_FILTER);
     let snapshot_interval_slots = 20;
     let num_account_paths = 1;
 
@@ -994,7 +994,7 @@ fn test_consistency_halt() {
 #[test]
 #[serial]
 fn test_snapshot_download() {
-    solana_logger::setup();
+    solana_logger::setup_with_default(RUST_LOG_FILTER);
     // First set up the cluster with 1 node
     let snapshot_interval_slots = 50;
     let num_account_paths = 3;
@@ -1060,7 +1060,7 @@ fn test_snapshot_download() {
 #[test]
 #[serial]
 fn test_snapshot_restart_tower() {
-    solana_logger::setup();
+    solana_logger::setup_with_default(RUST_LOG_FILTER);
     // First set up the cluster with 2 nodes
     let snapshot_interval_slots = 10;
     let num_account_paths = 2;
@@ -1132,7 +1132,7 @@ fn test_snapshot_restart_tower() {
 #[test]
 #[serial]
 fn test_snapshots_blockstore_floor() {
-    solana_logger::setup();
+    solana_logger::setup_with_default(RUST_LOG_FILTER);
     // First set up the cluster with 1 snapshotting leader
     let snapshot_interval_slots = 10;
     let num_account_paths = 4;
@@ -1235,7 +1235,7 @@ fn test_snapshots_blockstore_floor() {
 #[test]
 #[serial]
 fn test_snapshots_restart_validity() {
-    solana_logger::setup();
+    solana_logger::setup_with_default(RUST_LOG_FILTER);
     let snapshot_interval_slots = 10;
     let num_account_paths = 1;
     let mut snapshot_test_config =
@@ -1331,7 +1331,7 @@ fn test_fake_shreds_broadcast_leader() {
 }
 
 fn test_faulty_node(faulty_node_type: BroadcastStageType) {
-    solana_logger::setup();
+    solana_logger::setup_with_default(RUST_LOG_FILTER);
     let num_nodes = 2;
     let error_validator_config = ValidatorConfig {
         broadcast_stage_type: faulty_node_type,
@@ -1361,7 +1361,7 @@ fn test_faulty_node(faulty_node_type: BroadcastStageType) {
 
 #[test]
 fn test_wait_for_max_stake() {
-    solana_logger::setup();
+    solana_logger::setup_with_default(RUST_LOG_FILTER);
     let validator_config = ValidatorConfig::default();
     let mut config = ClusterConfig {
         cluster_lamports: 10_000,
@@ -1382,7 +1382,7 @@ fn test_wait_for_max_stake() {
 // Test that when a leader is leader for banks B_i..B_{i+n}, and B_i is not
 // votable, then B_{i+1} still chains to B_i
 fn test_no_voting() {
-    solana_logger::setup();
+    solana_logger::setup_with_default(RUST_LOG_FILTER);
     let validator_config = ValidatorConfig {
         voting_disabled: true,
         ..ValidatorConfig::default()
@@ -1422,10 +1422,7 @@ fn test_no_voting() {
 #[test]
 #[serial]
 fn test_optimistic_confirmation_violation_detection() {
-    solana_logger::setup();
+    solana_logger::setup_with_default(RUST_LOG_FILTER);
-    let buf = std::env::var("OPTIMISTIC_CONF_TEST_DUMP_LOG")
-        .err()
-        .map(|_| BufferRedirect::stderr().unwrap());
     // First set up the cluster with 2 nodes
     let slots_per_epoch = 2048;
     let node_stakes = vec![51, 50];
@@ -1490,20 +1487,42 @@ fn test_optimistic_confirmation_violation_detection() {
         // ancestor in bank forks).
         blockstore.set_dead_slot(prev_voted_slot).unwrap();
     }
-    cluster.restart_node(&entry_point_id, exited_validator_info);
 
-    // Wait for a root > prev_voted_slot to be set. Because the root is on a
+    {
-    // different fork than `prev_voted_slot`, then optimistic confirmation is
+        // Buffer stderr to detect optimistic slot violation log
-    // violated
+        let buf = std::env::var("OPTIMISTIC_CONF_TEST_DUMP_LOG")
-    let client = cluster.get_validator_client(&entry_point_id).unwrap();
+            .err()
-    loop {
+            .map(|_| BufferRedirect::stderr().unwrap());
-        let last_root = client
+        cluster.restart_node(&entry_point_id, exited_validator_info);
-            .get_slot_with_commitment(CommitmentConfig::finalized())
+
-            .unwrap();
+        // Wait for a root > prev_voted_slot to be set. Because the root is on a
-        if last_root > prev_voted_slot {
+        // different fork than `prev_voted_slot`, then optimistic confirmation is
-            break;
+        // violated
+        let client = cluster.get_validator_client(&entry_point_id).unwrap();
+        loop {
+            let last_root = client
+                .get_slot_with_commitment(CommitmentConfig::finalized())
+                .unwrap();
+            if last_root > prev_voted_slot {
+                break;
+            }
+            sleep(Duration::from_millis(100));
+        }
+
+        // Check to see that validator detected optimistic confirmation for
+        // `prev_voted_slot` failed
+        let expected_log =
+            OptimisticConfirmationVerifier::format_optimistic_confirmed_slot_violation_log(
+                prev_voted_slot,
+            );
+        if let Some(mut buf) = buf {
+            let mut output = String::new();
+            buf.read_to_string(&mut output).unwrap();
+            assert!(output.contains(&expected_log));
+            print!("{}", output);
+        } else {
+            panic!("dumped log and disabled testing");
         }
-        sleep(Duration::from_millis(100));
     }
 
     // Make sure validator still makes progress
@@ -1512,26 +1531,12 @@ fn test_optimistic_confirmation_violation_detection() {
         &[cluster.get_contact_info(&entry_point_id).unwrap().clone()],
         "test_optimistic_confirmation_violation",
     );
-
-    // Check to see that validator detected optimistic confirmation for
-    // `prev_voted_slot` failed
-    let expected_log =
-        OptimisticConfirmationVerifier::format_optimistic_confirmd_slot_violation_log(
-            prev_voted_slot,
-        );
-    if let Some(mut buf) = buf {
-        let mut output = String::new();
-        buf.read_to_string(&mut output).unwrap();
-        assert!(output.contains(&expected_log));
-    } else {
-        panic!("dumped log and disaled testing");
-    }
 }
 
 #[test]
 #[serial]
 fn test_validator_saves_tower() {
-    solana_logger::setup();
+    solana_logger::setup_with_default(RUST_LOG_FILTER);
 
     let validator_config = ValidatorConfig {
         require_tower: true,
@@ -1744,7 +1749,7 @@ fn remove_tower(ledger_path: &Path, node_pubkey: &Pubkey) {
 //    `A` should not be able to generate a switching proof.
 //
 fn do_test_optimistic_confirmation_violation_with_or_without_tower(with_tower: bool) {
-    solana_logger::setup();
+    solana_logger::setup_with_default(RUST_LOG_FILTER);
 
     // First set up the cluster with 4 nodes
     let slots_per_epoch = 2048;
@@ -1937,7 +1942,7 @@ enum ClusterMode {
 }
 
 fn do_test_future_tower(cluster_mode: ClusterMode) {
-    solana_logger::setup();
+    solana_logger::setup_with_default(RUST_LOG_FILTER);
 
     // First set up the cluster with 4 nodes
     let slots_per_epoch = 2048;
@@ -2048,7 +2053,7 @@ fn test_future_tower_master_slave() {
 
 #[test]
 fn test_hard_fork_invalidates_tower() {
-    solana_logger::setup();
+    solana_logger::setup_with_default(RUST_LOG_FILTER);
 
     // First set up the cluster with 2 nodes
     let slots_per_epoch = 2048;
@@ -2349,7 +2354,7 @@ fn setup_transfer_scan_threads(
 }
 
 fn run_test_load_program_accounts(scan_commitment: CommitmentConfig) {
-    solana_logger::setup();
+    solana_logger::setup_with_default(RUST_LOG_FILTER);
     // First set up the cluster with 2 nodes
     let slots_per_epoch = 2048;
     let node_stakes = vec![51, 50];

programs/bpf/tests/programs.rs

@@ -1248,13 +1248,13 @@ fn assert_instruction_count() {
             ("solana_bpf_rust_128bit", 581),
             ("solana_bpf_rust_alloc", 8941),
             ("solana_bpf_rust_dep_crate", 2),
-            ("solana_bpf_rust_external_spend", 499),
+            ("solana_bpf_rust_external_spend", 522),
             ("solana_bpf_rust_iter", 724),
             ("solana_bpf_rust_many_args", 237),
-            ("solana_bpf_rust_noop", 473),
+            ("solana_bpf_rust_noop", 496),
             ("solana_bpf_rust_param_passing", 54),
-            ("solana_bpf_rust_ristretto", 19223),
+            ("solana_bpf_rust_ristretto", 19246),
-            ("solana_bpf_rust_sanity", 929),
+            ("solana_bpf_rust_sanity", 952),
         ]);
     }