Add test_logger as feature to logging (#2586)

## Issue Addressed

Fix #2585

## Proposed Changes

Provide a canonical version of test_logger that can be used
throughout lighthouse.

## Additional Info

This allows tests to conditionally emit logging data by adding
test_logger as the default logger. And then when executing
`cargo test --features logging/test_logger` log output
will be visible:

  wink@3900x:~/lighthouse/common/logging/tests/test-feature-test_logger (Add-test_logger-as-feature-to-logging)
  $ cargo test --features logging/test_logger
      Finished test [unoptimized + debuginfo] target(s) in 0.02s
       Running unittests (target/debug/deps/test_logger-e20115db6a5e3714)

  running 1 test
  Sep 10 12:53:45.212 INFO hi, module: test_logger:8
  test tests::test_fn_with_logging ... ok

  test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.00s

     Doc-tests test-logger

  running 0 tests

  test result: ok. 0 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.00s

Or, in normal scenarios where logging isn't needed, executing
`cargo test` the log output will not be visible:

  wink@3900x:~/lighthouse/common/logging/tests/test-feature-test_logger (Add-test_logger-as-feature-to-logging)
  $ cargo test
      Finished test [unoptimized + debuginfo] target(s) in 0.02s
       Running unittests (target/debug/deps/test_logger-02e02f8d41e8cf8a)

  running 1 test
  test tests::test_fn_with_logging ... ok

  test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.00s

     Doc-tests test-logger

  running 0 tests

  test result: ok. 0 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.00s

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"

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",
 

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" }

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<StdRng> {
     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

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;

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,

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,
+    test_spec, AttestationStrategy, BeaconChainHarness, BlockStrategy, DiskHarnessType,
-    DiskHarnessType, HARNESS_SLOT_TIME,
+    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;

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
+The additional requirements for developers are:
-[`ganache-cli`](https://github.com/trufflesuite/ganache-cli). This is used to
+- [`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
+## Using `make`
-integration tests. For example, to test the `ssz` crate run:
+Commands to run the test suite are avaiable via the `Makefile` in the
-
-```bash
-cd consensus/ssz
-cargo test
-```
-
-We also wrap some of these commands and expose them 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
+<snip>
+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
+<snip>
+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
+<snip>
+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
+<snip>
+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

common/logging/Cargo.toml

@@ -4,8 +4,12 @@ version = "0.2.0"
 authors = ["blacktemplar <blacktemplar@a1.net>"]
 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"

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")
+    }
+}

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<Output, std::io::Error> {
+    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, "));
+}

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 = []

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,

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

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::<E>::open(config, logger()).unwrap();
+    let slasher = Slasher::<E>::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::<E>::open(config.clone(), logger()).unwrap();
+    let slasher = Slasher::<E>::open(config.clone(), test_logger()).unwrap();
     let current_epoch = Epoch::from(2 * config.history_length);
 
     // Pruning the empty database should be safe.

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::<E>::open(config.clone(), logger()).unwrap();
+    let slasher = Slasher::<E>::open(config.clone(), test_logger()).unwrap();
 
     let validators = (0..num_validators as u64).collect::<Vec<u64>>();
 

slasher/tests/wrap_around.rs

@@ -1,7 +1,5 @@
-use slasher::{
+use logging::test_logger;
-    test_utils::{indexed_att, logger},
+use slasher::{test_utils::indexed_att, Config, Error, Slasher};
-    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];
 

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"

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);
+    }
+}