diff --git a/Cargo.lock b/Cargo.lock index 98a35def3..a6ae8075d 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -451,6 +451,7 @@ dependencies = [ "itertools", "lazy_static", "lighthouse_metrics", + "logging", "lru", "maplit", "merkle_proof", @@ -3715,6 +3716,7 @@ dependencies = [ "lighthouse_metrics", "slog", "slog-term", + "sloggers", ] [[package]] @@ -5564,6 +5566,7 @@ dependencies = [ "lighthouse_metrics", "lmdb", "lmdb-sys", + "logging", "maplit", "parking_lot", "rand 0.7.3", @@ -6095,6 +6098,14 @@ dependencies = [ "winapi-util", ] +[[package]] +name = "test-test_logger" +version = "0.1.0" +dependencies = [ + "logging", + "slog", +] + [[package]] name = "test_random_derive" version = "0.2.0" diff --git a/Cargo.toml b/Cargo.toml index ab0cb15dc..b09406d1a 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -75,6 +75,7 @@ members = [ "testing/eth1_test_rig", "testing/node_test_rig", "testing/simulator", + "testing/test-test_logger", "testing/state_transition_vectors", "testing/web3signer_tests", diff --git a/beacon_node/beacon_chain/Cargo.toml b/beacon_node/beacon_chain/Cargo.toml index 96851e704..2a91c5b18 100644 --- a/beacon_node/beacon_chain/Cargo.toml +++ b/beacon_node/beacon_chain/Cargo.toml @@ -8,7 +8,6 @@ edition = "2018" default = ["participation_metrics"] write_ssz_files = [] # Writes debugging .ssz files to /tmp during block processing. participation_metrics = [] # Exposes validator participation metrics to Prometheus. -test_logger = [] # Print log output to stderr when running tests instead of dropping it fork_from_env = [] # Initialise the harness chain spec from the FORK_NAME env variable [dev-dependencies] @@ -55,3 +54,4 @@ itertools = "0.10.0" slasher = { path = "../../slasher" } eth2 = { path = "../../common/eth2" } strum = { version = "0.21.0", features = ["derive"] } +logging = { path = "../../common/logging" } diff --git a/beacon_node/beacon_chain/src/test_utils.rs b/beacon_node/beacon_chain/src/test_utils.rs index 2eb4489f2..11d4af90f 100644 --- a/beacon_node/beacon_chain/src/test_utils.rs +++ b/beacon_node/beacon_chain/src/test_utils.rs @@ -14,13 +14,13 @@ use bls::get_withdrawal_credentials; use futures::channel::mpsc::Receiver; pub use genesis::interop_genesis_state; use int_to_bytes::int_to_bytes32; +use logging::test_logger; use merkle_proof::MerkleTree; use parking_lot::Mutex; use rand::rngs::StdRng; use rand::Rng; use rand::SeedableRng; use rayon::prelude::*; -use slog::Logger; use slot_clock::TestingSlotClock; use state_processing::state_advance::complete_state_advance; use std::borrow::Cow; @@ -107,25 +107,6 @@ fn make_rng() -> Mutex { Mutex::new(StdRng::seed_from_u64(0x0DDB1A5E5BAD5EEDu64)) } -/// Return a logger suitable for test usage. -/// -/// By default no logs will be printed, but they can be enabled via the `test_logger` feature. -/// -/// We've tried the `slog_term::TestStdoutWriter` in the past, but found it too buggy because -/// of the threading limitation. -pub fn test_logger() -> Logger { - use sloggers::Build; - - if cfg!(feature = "test_logger") { - sloggers::terminal::TerminalLoggerBuilder::new() - .level(sloggers::types::Severity::Debug) - .build() - .unwrap() - } else { - sloggers::null::NullLoggerBuilder.build().unwrap() - } -} - /// Return a `ChainSpec` suitable for test usage. /// /// If the `fork_from_env` feature is enabled, read the fork to use from the FORK_NAME environment diff --git a/beacon_node/beacon_chain/src/validator_pubkey_cache.rs b/beacon_node/beacon_chain/src/validator_pubkey_cache.rs index 8b27d89e0..c1d7ab5d2 100644 --- a/beacon_node/beacon_chain/src/validator_pubkey_cache.rs +++ b/beacon_node/beacon_chain/src/validator_pubkey_cache.rs @@ -323,7 +323,8 @@ fn append_to_file(file: &mut File, index: usize, pubkey: &PublicKeyBytes) -> Res #[cfg(test)] mod test { use super::*; - use crate::test_utils::{test_logger, BeaconChainHarness, EphemeralHarnessType}; + use crate::test_utils::{BeaconChainHarness, EphemeralHarnessType}; + use logging::test_logger; use std::sync::Arc; use store::{HotColdDB, StoreConfig}; use tempfile::tempdir; diff --git a/beacon_node/beacon_chain/tests/block_verification.rs b/beacon_node/beacon_chain/tests/block_verification.rs index b03a106c9..d59be8571 100644 --- a/beacon_node/beacon_chain/tests/block_verification.rs +++ b/beacon_node/beacon_chain/tests/block_verification.rs @@ -4,9 +4,10 @@ extern crate lazy_static; use beacon_chain::test_utils::{ - test_logger, AttestationStrategy, BeaconChainHarness, BlockStrategy, EphemeralHarnessType, + AttestationStrategy, BeaconChainHarness, BlockStrategy, EphemeralHarnessType, }; use beacon_chain::{BeaconSnapshot, BlockError, ChainConfig, ChainSegmentResult}; +use logging::test_logger; use slasher::{Config as SlasherConfig, Slasher}; use state_processing::{ common::get_indexed_attestation, diff --git a/beacon_node/beacon_chain/tests/store_tests.rs b/beacon_node/beacon_chain/tests/store_tests.rs index b73056aed..afc14dce7 100644 --- a/beacon_node/beacon_chain/tests/store_tests.rs +++ b/beacon_node/beacon_chain/tests/store_tests.rs @@ -3,8 +3,8 @@ use beacon_chain::attestation_verification::Error as AttnError; use beacon_chain::builder::BeaconChainBuilder; use beacon_chain::test_utils::{ - test_logger, test_spec, AttestationStrategy, BeaconChainHarness, BlockStrategy, - DiskHarnessType, HARNESS_SLOT_TIME, + test_spec, AttestationStrategy, BeaconChainHarness, BlockStrategy, DiskHarnessType, + HARNESS_SLOT_TIME, }; use beacon_chain::{ historical_blocks::HistoricalBlockError, migrate::MigratorConfig, BeaconChain, @@ -12,6 +12,7 @@ use beacon_chain::{ WhenSlotSkipped, }; use lazy_static::lazy_static; +use logging::test_logger; use maplit::hashset; use rand::Rng; use std::collections::HashMap; diff --git a/book/src/setup.md b/book/src/setup.md index ea599f5eb..e4e1d92ff 100644 --- a/book/src/setup.md +++ b/book/src/setup.md @@ -8,22 +8,18 @@ Lighthouse. This will install Lighthouse to your `PATH`, which is not particularly useful for development but still a good way to ensure you have the base dependencies. -The only additional requirement for developers is -[`ganache-cli`](https://github.com/trufflesuite/ganache-cli). This is used to -simulate the Eth1 chain during tests. You'll get failures during tests if you -don't have `ganache-cli` available on your `PATH`. +The additional requirements for developers are: +- [`ganache-cli`](https://github.com/trufflesuite/ganache-cli). This is used to + simulate the Eth1 chain during tests. You'll get failures during tests if you + don't have `ganache-cli` available on your `PATH`. +- [`cmake`](https://cmake.org/cmake/help/latest/command/install.html). Used by + some dependencies. See [`Installation Guide`](./installation.md) for more info. +- [`java 11 runtime`](https://openjdk.java.net/projects/jdk/). 11 is the minimum, + used by web3signer_tests. -## Testing -As with most other Rust projects, Lighthouse uses `cargo test` for unit and -integration tests. For example, to test the `ssz` crate run: - -```bash -cd consensus/ssz -cargo test -``` - -We also wrap some of these commands and expose them via the `Makefile` in the +## Using `make` +Commands to run the test suite are avaiable via the `Makefile` in the project root for the benefit of CI/CD. We list some of these commands below so you can run them locally and avoid CI failures: @@ -36,6 +32,117 @@ you can run them locally and avoid CI failures: _The lighthouse test suite is quite extensive, running the whole suite may take 30+ minutes._ +## Testing + +As with most other Rust projects, Lighthouse uses `cargo test` for unit and +integration tests. For example, to test the `ssz` crate run: + +```bash +$ cd consensus/ssz +$ cargo test + Finished test [unoptimized + debuginfo] target(s) in 7.69s + Running unittests (target/debug/deps/ssz-61fc26760142b3c4) + +running 27 tests +test decode::impls::tests::awkward_fixed_length_portion ... ok +test decode::impls::tests::invalid_h256 ... ok + +test encode::tests::test_encode_length ... ok +test encode::impls::tests::vec_of_vec_of_u8 ... ok +test encode::tests::test_encode_length_above_max_debug_panics - should panic ... ok + +test result: ok. 27 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.00s + + Running tests/tests.rs (target/debug/deps/tests-f8fb1f9ccb197bf4) + +running 20 tests +test round_trip::bool ... ok +test round_trip::first_offset_skips_byte ... ok +test round_trip::fixed_len_excess_bytes ... ok + +test round_trip::vec_u16 ... ok +test round_trip::vec_of_vec_u16 ... ok + +test result: ok. 20 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.00s + + Doc-tests ssz + +running 3 tests +test src/decode.rs - decode::SszDecoder (line 258) ... ok +test src/encode.rs - encode::SszEncoder (line 57) ... ok +test src/lib.rs - (line 10) ... ok + +test result: ok. 3 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.15s$ cargo test -p eth2_ssz +``` + +Alternatively, since `lighthouse` is a cargo workspace you can use `-p eth2_ssz` where +`eth2_ssz` is the package name as defined `/consensus/ssz/Cargo.toml` +```bash +$ head -2 consensus/ssz/Cargo.toml +[package] +name = "eth2_ssz" +$ cargo test -p eth2_ssz + Finished test [unoptimized + debuginfo] target(s) in 7.69s + Running unittests (target/debug/deps/ssz-61fc26760142b3c4) + +running 27 tests +test decode::impls::tests::awkward_fixed_length_portion ... ok +test decode::impls::tests::invalid_h256 ... ok + +test encode::tests::test_encode_length ... ok +test encode::impls::tests::vec_of_vec_of_u8 ... ok +test encode::tests::test_encode_length_above_max_debug_panics - should panic ... ok + +test result: ok. 27 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.00s + + Running tests/tests.rs (target/debug/deps/tests-f8fb1f9ccb197bf4) + +running 20 tests +test round_trip::bool ... ok +test round_trip::first_offset_skips_byte ... ok +test round_trip::fixed_len_excess_bytes ... ok + +test round_trip::vec_u16 ... ok +test round_trip::vec_of_vec_u16 ... ok + +test result: ok. 20 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.00s + + Doc-tests ssz + +running 3 tests +test src/decode.rs - decode::SszDecoder (line 258) ... ok +test src/encode.rs - encode::SszEncoder (line 57) ... ok +test src/lib.rs - (line 10) ... ok + +test result: ok. 3 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.15s$ cargo test -p eth2_ssz +``` + +#### test_logger + +The test_logger, located in `/common/logging/` can be used to create a `Logger` that by +default returns a NullLogger. But if `--features 'logging/test_logger'` is passed while +testing the logs are displayed. This can be very helpful while debugging tests. + +Example: +``` +$ cargo test -p beacon_chain validator_pubkey_cache::test::basic_operation --features 'logging/test_logger' + Finished test [unoptimized + debuginfo] target(s) in 0.20s + Running unittests (target/debug/deps/beacon_chain-975363824f1143bc) + +running 1 test +Sep 19 19:23:25.192 INFO Beacon chain initialized, head_slot: 0, head_block: 0x2353…dcf4, head_state: 0xef4b…4615, module: beacon_chain::builder:649 +Sep 19 19:23:25.192 INFO Saved beacon chain to disk, module: beacon_chain::beacon_chain:3608 +Sep 19 19:23:26.798 INFO Beacon chain initialized, head_slot: 0, head_block: 0x2353…dcf4, head_state: 0xef4b…4615, module: beacon_chain::builder:649 +Sep 19 19:23:26.798 INFO Saved beacon chain to disk, module: beacon_chain::beacon_chain:3608 +Sep 19 19:23:28.407 INFO Beacon chain initialized, head_slot: 0, head_block: 0xdcdd…501f, head_state: 0x3055…032c, module: beacon_chain::builder:649 +Sep 19 19:23:28.408 INFO Saved beacon chain to disk, module: beacon_chain::beacon_chain:3608 +Sep 19 19:23:30.069 INFO Beacon chain initialized, head_slot: 0, head_block: 0xa739…1b22, head_state: 0xac1c…eab6, module: beacon_chain::builder:649 +Sep 19 19:23:30.069 INFO Saved beacon chain to disk, module: beacon_chain::beacon_chain:3608 +test validator_pubkey_cache::test::basic_operation ... ok + +test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 51 filtered out; finished in 6.46s +``` + ### Consensus Spec Tests The diff --git a/common/logging/Cargo.toml b/common/logging/Cargo.toml index 8e19c1f11..0deb55a6b 100644 --- a/common/logging/Cargo.toml +++ b/common/logging/Cargo.toml @@ -4,8 +4,12 @@ version = "0.2.0" authors = ["blacktemplar "] edition = "2018" +[features] +test_logger = [] # Print log output to stderr when running tests instead of dropping it + [dependencies] slog = "2.5.2" slog-term = "2.6.0" lighthouse_metrics = { path = "../lighthouse_metrics" } lazy_static = "1.4.0" +sloggers = "2.0.2" diff --git a/common/logging/src/lib.rs b/common/logging/src/lib.rs index f4bcd088d..06c121210 100644 --- a/common/logging/src/lib.rs +++ b/common/logging/src/lib.rs @@ -4,6 +4,7 @@ extern crate lazy_static; use lighthouse_metrics::{ inc_counter, try_create_int_counter, IntCounter, Result as MetricsResult, }; +use slog::Logger; use slog_term::Decorator; use std::io::{Result, Write}; @@ -157,3 +158,26 @@ impl<'a> slog_term::RecordDecorator for AlignedRecordDecorator<'a> { self.wrapped.start_separator() } } + +/// Return a logger suitable for test usage. +/// +/// By default no logs will be printed, but they can be enabled via +/// the `test_logger` feature. This feature can be enabled for any +/// dependent crate by passing `--features logging/test_logger`, e.g. +/// ```bash +/// cargo test -p beacon_chain --features logging/test_logger +/// ``` +pub fn test_logger() -> Logger { + use sloggers::Build; + + if cfg!(feature = "test_logger") { + sloggers::terminal::TerminalLoggerBuilder::new() + .level(sloggers::types::Severity::Debug) + .build() + .expect("Should build test_logger") + } else { + sloggers::null::NullLoggerBuilder + .build() + .expect("Should build null_logger") + } +} diff --git a/common/logging/tests/test.rs b/common/logging/tests/test.rs new file mode 100644 index 000000000..1d3d3c5e2 --- /dev/null +++ b/common/logging/tests/test.rs @@ -0,0 +1,53 @@ +use std::env; +use std::process::Command; +use std::process::Output; + +fn run_cmd(cmd_line: &str) -> Result { + let output; + if cfg!(target_os = "windows") { + output = Command::new(r#"cmd"#).args(["/C", cmd_line]).output(); + } else { + output = Command::new(r#"sh"#).args(["-c", cmd_line]).output(); + } + output +} + +#[test] +fn test_test_logger_with_feature_test_logger() { + let cur_dir = env::current_dir().unwrap(); + let test_dir = cur_dir + .join("..") + .join("..") + .join("testing") + .join("test-test_logger"); + let cmd_line = format!( + "cd {} && cargo test --features logging/test_logger", + test_dir.to_str().unwrap() + ); + + let output = run_cmd(&cmd_line); + + // Assert output data DOES contain "INFO hi, " + let data = String::from_utf8(output.unwrap().stderr).unwrap(); + println!("data={}", data); + assert!(data.contains("INFO hi, ")); +} + +#[test] +fn test_test_logger_no_features() { + // Test without features + let cur_dir = env::current_dir().unwrap(); + let test_dir = cur_dir + .join("..") + .join("..") + .join("testing") + .join("test-test_logger"); + let cmd_line = format!("cd {} && cargo test", test_dir.to_str().unwrap()); + + let output = run_cmd(&cmd_line); + + // Assert output data DOES contain "INFO hi, " + let data = String::from_utf8(output.unwrap().stderr).unwrap(); + println!("data={}", data); + assert!(!data.contains("INFO hi, ")); +} diff --git a/slasher/Cargo.toml b/slasher/Cargo.toml index 57aa81976..b51b38f0f 100644 --- a/slasher/Cargo.toml +++ b/slasher/Cargo.toml @@ -30,6 +30,5 @@ types = { path = "../consensus/types" } maplit = "1.0.2" rayon = "1.3.0" tempfile = "3.1.0" +logging = { path = "../common/logging" } -[features] -test_logger = [] diff --git a/slasher/src/test_utils.rs b/slasher/src/test_utils.rs index 46ce23da5..0011df1ff 100644 --- a/slasher/src/test_utils.rs +++ b/slasher/src/test_utils.rs @@ -1,5 +1,3 @@ -use slog::Logger; -use sloggers::Build; use std::collections::HashSet; use types::{ AggregateSignature, AttestationData, AttesterSlashing, BeaconBlockHeader, Checkpoint, Epoch, @@ -8,17 +6,6 @@ use types::{ pub type E = MainnetEthSpec; -pub fn logger() -> Logger { - if cfg!(feature = "test_logger") { - sloggers::terminal::TerminalLoggerBuilder::new() - .level(sloggers::types::Severity::Trace) - .build() - .unwrap() - } else { - sloggers::null::NullLoggerBuilder.build().unwrap() - } -} - pub fn indexed_att( attesting_indices: impl AsRef<[u64]>, source_epoch: u64, diff --git a/slasher/tests/attester_slashings.rs b/slasher/tests/attester_slashings.rs index 138d5526c..987853077 100644 --- a/slasher/tests/attester_slashings.rs +++ b/slasher/tests/attester_slashings.rs @@ -1,8 +1,9 @@ +use logging::test_logger; use maplit::hashset; use rayon::prelude::*; use slasher::{ config::DEFAULT_CHUNK_SIZE, - test_utils::{att_slashing, indexed_att, logger, slashed_validators_from_slashings, E}, + test_utils::{att_slashing, indexed_att, slashed_validators_from_slashings, E}, Config, Slasher, }; use std::collections::HashSet; @@ -171,7 +172,7 @@ fn slasher_test( ) { let tempdir = tempdir().unwrap(); let config = Config::new(tempdir.path().into()).for_testing(); - let slasher = Slasher::open(config, logger()).unwrap(); + let slasher = Slasher::open(config, test_logger()).unwrap(); let current_epoch = Epoch::new(current_epoch); for (i, attestation) in attestations.iter().enumerate() { @@ -200,7 +201,7 @@ fn parallel_slasher_test( ) { let tempdir = tempdir().unwrap(); let config = Config::new(tempdir.path().into()).for_testing(); - let slasher = Slasher::open(config, logger()).unwrap(); + let slasher = Slasher::open(config, test_logger()).unwrap(); let current_epoch = Epoch::new(current_epoch); attestations diff --git a/slasher/tests/proposer_slashings.rs b/slasher/tests/proposer_slashings.rs index ec46f6db8..13a9422fe 100644 --- a/slasher/tests/proposer_slashings.rs +++ b/slasher/tests/proposer_slashings.rs @@ -1,5 +1,6 @@ +use logging::test_logger; use slasher::{ - test_utils::{block as test_block, logger, E}, + test_utils::{block as test_block, E}, Config, Slasher, }; use tempfile::tempdir; @@ -9,7 +10,7 @@ use types::{Epoch, EthSpec}; fn empty_pruning() { let tempdir = tempdir().unwrap(); let config = Config::new(tempdir.path().into()).for_testing(); - let slasher = Slasher::::open(config, logger()).unwrap(); + let slasher = Slasher::::open(config, test_logger()).unwrap(); slasher.prune_database(Epoch::new(0)).unwrap(); } @@ -22,7 +23,7 @@ fn block_pruning() { config.chunk_size = 2; config.history_length = 2; - let slasher = Slasher::::open(config.clone(), logger()).unwrap(); + let slasher = Slasher::::open(config.clone(), test_logger()).unwrap(); let current_epoch = Epoch::from(2 * config.history_length); // Pruning the empty database should be safe. diff --git a/slasher/tests/random.rs b/slasher/tests/random.rs index 641a52b7e..22ae26d13 100644 --- a/slasher/tests/random.rs +++ b/slasher/tests/random.rs @@ -1,8 +1,9 @@ +use logging::test_logger; use rand::prelude::*; use rand::{rngs::StdRng, thread_rng, Rng, SeedableRng}; use slasher::{ test_utils::{ - block, indexed_att, logger, slashed_validators_from_attestations, + block, indexed_att, slashed_validators_from_attestations, slashed_validators_from_slashings, E, }, Config, Slasher, @@ -47,7 +48,7 @@ fn random_test(seed: u64, test_config: TestConfig) { config.chunk_size = 1 << chunk_size_exponent; config.history_length = 1 << rng.gen_range(chunk_size_exponent, chunk_size_exponent + 3); - let slasher = Slasher::::open(config.clone(), logger()).unwrap(); + let slasher = Slasher::::open(config.clone(), test_logger()).unwrap(); let validators = (0..num_validators as u64).collect::>(); diff --git a/slasher/tests/wrap_around.rs b/slasher/tests/wrap_around.rs index 79ec91fbe..47054ebc6 100644 --- a/slasher/tests/wrap_around.rs +++ b/slasher/tests/wrap_around.rs @@ -1,7 +1,5 @@ -use slasher::{ - test_utils::{indexed_att, logger}, - Config, Error, Slasher, -}; +use logging::test_logger; +use slasher::{test_utils::indexed_att, Config, Error, Slasher}; use tempfile::tempdir; use types::Epoch; @@ -13,7 +11,7 @@ fn attestation_pruning_empty_wrap_around() { config.chunk_size = 16; config.history_length = 16; - let slasher = Slasher::open(config.clone(), logger()).unwrap(); + let slasher = Slasher::open(config.clone(), test_logger()).unwrap(); let v = vec![0]; let history_length = config.history_length as u64; @@ -48,7 +46,7 @@ fn pruning_with_map_full() { config.history_length = 1024; config.max_db_size_mbs = 1; - let slasher = Slasher::open(config, logger()).unwrap(); + let slasher = Slasher::open(config, test_logger()).unwrap(); let v = vec![0, 1, 2, 3, 4, 5, 6, 7, 8, 9, 10, 11, 12]; diff --git a/testing/test-test_logger/Cargo.toml b/testing/test-test_logger/Cargo.toml new file mode 100644 index 000000000..d2a8b87b6 --- /dev/null +++ b/testing/test-test_logger/Cargo.toml @@ -0,0 +1,10 @@ +[package] +name = "test-test_logger" +version = "0.1.0" +edition = "2018" + +# See more keys and their definitions at https://doc.rust-lang.org/cargo/reference/manifest.html + +[dependencies] +logging = { path = "../../common/logging" } +slog = "2.7.0" diff --git a/testing/test-test_logger/src/lib.rs b/testing/test-test_logger/src/lib.rs new file mode 100644 index 000000000..a2e2a8094 --- /dev/null +++ b/testing/test-test_logger/src/lib.rs @@ -0,0 +1,22 @@ +use slog::{info, Logger}; + +pub struct Config { + log: Logger, +} + +pub fn fn_with_logging(config: &Config) { + info!(&config.log, "hi"); +} + +#[cfg(test)] +mod tests { + use super::*; + use logging::test_logger; + + #[test] + fn test_fn_with_logging() { + let config = Config { log: test_logger() }; + + fn_with_logging(&config); + } +}