diff --git a/Cargo.lock b/Cargo.lock index c49f58b71c..f30028b100 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -4710,6 +4710,7 @@ dependencies = [ "itertools", "log 0.4.11", "rand 0.7.3", + "rayon", "serial_test", "solana-client", "solana-config-program", diff --git a/core/src/optimistic_confirmation_verifier.rs b/core/src/optimistic_confirmation_verifier.rs index 6746da6944..2f27bc2b78 100644 --- a/core/src/optimistic_confirmation_verifier.rs +++ b/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 diff --git a/local-cluster/Cargo.toml b/local-cluster/Cargo.toml index b96cc41aab..54f8408f95 100644 --- a/local-cluster/Cargo.toml +++ b/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" } diff --git a/local-cluster/src/cluster_tests.rs b/local-cluster/src/cluster_tests.rs index 74d1151bb9..29ea476033 100644 --- a/local-cluster/src/cluster_tests.rs +++ b/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( +pub fn spend_and_verify_all_nodes( entry_point_info: &ContactInfo, funding_keypair: &Keypair, nodes: usize, @@ -44,9 +45,10 @@ pub fn spend_and_verify_all_nodes( ) { 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( .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( let client = create_client(validator.client_facing_addr(), VALIDATOR_PORT_RANGE); client.poll_for_signature_confirmation(&sig, confs).unwrap(); } - } + }); } pub fn verify_balances( @@ -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)); } diff --git a/local-cluster/tests/local_cluster.rs b/local-cluster/tests/local_cluster.rs index 94989cf51b..d4d9fce1d7 100644 --- a/local-cluster/tests/local_cluster.rs +++ b/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: 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( 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(); - let buf = std::env::var("OPTIMISTIC_CONF_TEST_DUMP_LOG") - .err() - .map(|_| BufferRedirect::stderr().unwrap()); + 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]; @@ -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 - // 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; + { + // Buffer stderr to detect optimistic slot violation log + let buf = std::env::var("OPTIMISTIC_CONF_TEST_DUMP_LOG") + .err() + .map(|_| BufferRedirect::stderr().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 + // 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]; diff --git a/programs/bpf/tests/programs.rs b/programs/bpf/tests/programs.rs index a644cfeb37..77768ff404 100644 --- a/programs/bpf/tests/programs.rs +++ b/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_sanity", 929), + ("solana_bpf_rust_ristretto", 19246), + ("solana_bpf_rust_sanity", 952), ]); }