simulator: Write dependency logs to separate files (#7433)

This PR relates to:
- https://github.com/sigp/lighthouse/pull/7199
- -> workspace_filter has been enabled (dependency logging has been disabled)
- https://github.com/sigp/lighthouse/pull/7394
- -> file logging has been optionally enabled

Building on these, this PR enables dependency logging for the simulators. The logs are written to separate files.

The libp2p/discv5 logs:
- are saved to the directory  specified with `--log-dir`
- respects the `RUST_LOG` environment variable for log level configuration

Cargo.lock

@@ -8384,6 +8384,7 @@ dependencies = [
  "sensitive_url",
  "serde_json",
  "tokio",
+ "tracing",
  "tracing-subscriber",
  "types",
 ]

lighthouse/environment/src/tracing_common.rs

@@ -37,7 +37,11 @@ pub fn construct_logger<E: EthSpec>(
         environment_builder.init_tracing(logger_config.clone(), logfile_prefix);
 
     let libp2p_discv5_layer = if let Some(subcommand_name) = subcommand_name {
-        if subcommand_name == "beacon_node" || subcommand_name == "boot_node" {
+        if subcommand_name == "beacon_node"
+            || subcommand_name == "boot_node"
+            || subcommand_name == "basic-sim"
+            || subcommand_name == "fallback-sim"
+        {
             if logger_config.max_log_size == 0 || logger_config.max_log_number == 0 {
                 // User has explicitly disabled logging to file.
                 None

testing/simulator/Cargo.toml

@@ -20,5 +20,6 @@ rayon = { workspace = true }
 sensitive_url  = { path = "../../common/sensitive_url" }
 serde_json = { workspace = true }
 tokio = { workspace = true }
+tracing = { workspace = true }
 tracing-subscriber = { workspace = true }
 types = { workspace = true }

testing/simulator/src/basic_sim.rs

@@ -17,10 +17,11 @@ use std::time::Duration;
 
 use environment::tracing_common;
 use tracing_subscriber::prelude::*;
-use tracing_subscriber::{layer::SubscriberExt, util::SubscriberInitExt};
+use tracing_subscriber::{layer::SubscriberExt, util::SubscriberInitExt, EnvFilter};
 
 use logging::build_workspace_filter;
 use tokio::time::sleep;
+use tracing::Level;
 use types::{Epoch, EthSpec, MinimalEthSpec};
 
 const END_EPOCH: u64 = 16;
@@ -36,12 +37,13 @@ const SUGGESTED_FEE_RECIPIENT: [u8; 20] =
 
 #[allow(clippy::large_stack_frames)]
 pub fn run_basic_sim(matches: &ArgMatches) -> Result<(), String> {
-    let node_count = matches
+    let (_name, subcommand_matches) = matches.subcommand().expect("subcommand");
+    let node_count = subcommand_matches
         .get_one::<String>("nodes")
         .expect("missing nodes default")
         .parse::<usize>()
         .expect("missing nodes default");
-    let proposer_nodes = matches
+    let proposer_nodes = subcommand_matches
         .get_one::<String>("proposer-nodes")
         .unwrap_or(&String::from("0"))
         .parse::<usize>()
@@ -49,23 +51,25 @@ pub fn run_basic_sim(matches: &ArgMatches) -> Result<(), String> {
     // extra beacon node added with delay
     let extra_nodes: usize = 1;
     println!("PROPOSER-NODES: {}", proposer_nodes);
-    let validators_per_node = matches
+    let validators_per_node = subcommand_matches
         .get_one::<String>("validators-per-node")
         .expect("missing validators-per-node default")
         .parse::<usize>()
         .expect("missing validators-per-node default");
-    let speed_up_factor = matches
+    let speed_up_factor = subcommand_matches
         .get_one::<String>("speed-up-factor")
         .expect("missing speed-up-factor default")
         .parse::<u64>()
         .expect("missing speed-up-factor default");
-    let log_level = matches
+    let log_level = subcommand_matches
         .get_one::<String>("debug-level")
         .expect("missing debug-level");
 
-    let continue_after_checks = matches.get_flag("continue-after-checks");
+    let continue_after_checks = subcommand_matches.get_flag("continue-after-checks");
-    let log_dir = matches.get_one::<String>("log-dir").map(PathBuf::from);
+    let log_dir = subcommand_matches
-    let disable_stdout_logging = matches.get_flag("disable-stdout-logging");
+        .get_one::<String>("log-dir")
+        .map(PathBuf::from);
+    let disable_stdout_logging = subcommand_matches.get_flag("disable-stdout-logging");
 
     println!("Basic Simulator:");
     println!(" nodes: {}", node_count);
@@ -98,7 +102,7 @@ pub fn run_basic_sim(matches: &ArgMatches) -> Result<(), String> {
         stdout_logging_layer,
         file_logging_layer,
         _sse_logging_layer_opt,
-        _libp2p_discv5_layer,
+        libp2p_discv5_layer,
     ) = tracing_common::construct_logger(
         LoggerConfig {
             path: log_dir,
@@ -138,6 +142,17 @@ pub fn run_basic_sim(matches: &ArgMatches) -> Result<(), String> {
                 .boxed(),
         );
     }
+    if let Some(libp2p_discv5_layer) = libp2p_discv5_layer {
+        logging_layers.push(
+            libp2p_discv5_layer
+                .with_filter(
+                    EnvFilter::builder()
+                        .with_default_directive(Level::DEBUG.into())
+                        .from_env_lossy(),
+                )
+                .boxed(),
+        );
+    }
 
     if let Err(e) = tracing_subscriber::registry()
         .with(logging_layers)

testing/simulator/src/fallback_sim.rs

@@ -5,6 +5,7 @@ use clap::ArgMatches;
 use crate::retry::with_retry;
 use environment::tracing_common;
 use futures::prelude::*;
+use logging::build_workspace_filter;
 use node_test_rig::{
     environment::{EnvironmentBuilder, LoggerConfig},
     testing_validator_config, ValidatorFiles,
@@ -15,8 +16,9 @@ use std::path::PathBuf;
 use std::sync::Arc;
 use std::time::Duration;
 use tokio::time::sleep;
+use tracing::Level;
 use tracing_subscriber::prelude::*;
-use tracing_subscriber::{layer::SubscriberExt, util::SubscriberInitExt};
+use tracing_subscriber::{layer::SubscriberExt, util::SubscriberInitExt, EnvFilter};
 use types::{Epoch, EthSpec, MinimalEthSpec};
 const END_EPOCH: u64 = 16;
 const GENESIS_DELAY: u64 = 32;
@@ -39,40 +41,43 @@ const SUGGESTED_FEE_RECIPIENT: [u8; 20] =
     [0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 1];
 
 pub fn run_fallback_sim(matches: &ArgMatches) -> Result<(), String> {
-    let vc_count = matches
+    let (_name, subcommand_matches) = matches.subcommand().expect("subcommand");
+    let vc_count = subcommand_matches
         .get_one::<String>("vc-count")
         .expect("missing vc-count default")
         .parse::<usize>()
         .expect("missing vc-count default");
 
-    let validators_per_vc = matches
+    let validators_per_vc = subcommand_matches
         .get_one::<String>("validators-per-vc")
         .expect("missing validators-per-vc default")
         .parse::<usize>()
         .expect("missing validators-per-vc default");
 
-    let bns_per_vc = matches
+    let bns_per_vc = subcommand_matches
         .get_one::<String>("bns-per-vc")
         .expect("missing bns-per-vc default")
         .parse::<usize>()
         .expect("missing bns-per-vc default");
 
     assert!(bns_per_vc > 1);
-    let speed_up_factor = matches
+    let speed_up_factor = subcommand_matches
         .get_one::<String>("speed-up-factor")
         .expect("missing speed-up-factor default")
         .parse::<u64>()
         .expect("missing speed-up-factor default");
 
-    let log_level = matches
+    let log_level = subcommand_matches
         .get_one::<String>("debug-level")
         .expect("missing debug-level default");
 
-    let continue_after_checks = matches.get_flag("continue-after-checks");
+    let continue_after_checks = subcommand_matches.get_flag("continue-after-checks");
 
-    let log_dir = matches.get_one::<String>("log-dir").map(PathBuf::from);
+    let log_dir = subcommand_matches
+        .get_one::<String>("log-dir")
+        .map(PathBuf::from);
 
-    let disable_stdout_logging = matches.get_flag("disable-stdout-logging");
+    let disable_stdout_logging = subcommand_matches.get_flag("disable-stdout-logging");
 
     println!("Fallback Simulator:");
     println!(" vc-count: {}", vc_count);
@@ -104,7 +109,7 @@ pub fn run_fallback_sim(matches: &ArgMatches) -> Result<(), String> {
         stdout_logging_layer,
         file_logging_layer,
         _sse_logging_layer_opt,
-        _libp2p_discv5_layer,
+        libp2p_discv5_layer,
     ) = tracing_common::construct_logger(
         LoggerConfig {
             path: log_dir,
@@ -126,11 +131,13 @@ pub fn run_fallback_sim(matches: &ArgMatches) -> Result<(), String> {
         EnvironmentBuilder::minimal(),
     );
 
+    let workspace_filter = build_workspace_filter()?;
     let mut logging_layers = vec![];
     if !disable_stdout_logging {
         logging_layers.push(
             stdout_logging_layer
                 .with_filter(logger_config.debug_level)
+                .with_filter(workspace_filter.clone())
                 .boxed(),
         );
     }
@@ -138,6 +145,18 @@ pub fn run_fallback_sim(matches: &ArgMatches) -> Result<(), String> {
         logging_layers.push(
             file_logging_layer
                 .with_filter(logger_config.logfile_debug_level)
+                .with_filter(workspace_filter)
+                .boxed(),
+        );
+    }
+    if let Some(libp2p_discv5_layer) = libp2p_discv5_layer {
+        logging_layers.push(
+            libp2p_discv5_layer
+                .with_filter(
+                    EnvFilter::builder()
+                        .with_default_directive(Level::DEBUG.into())
+                        .from_env_lossy(),
+                )
                 .boxed(),
         );
     }

testing/simulator/src/main.rs

@@ -29,15 +29,15 @@ fn main() {
     Builder::from_env(Env::default()).init();
 
     let matches = cli_app().get_matches();
-    match matches.subcommand() {
+    match matches.subcommand_name() {
-        Some(("basic-sim", matches)) => match basic_sim::run_basic_sim(matches) {
+        Some("basic-sim") => match basic_sim::run_basic_sim(&matches) {
             Ok(()) => println!("Simulation exited successfully"),
             Err(e) => {
                 eprintln!("Simulation exited with error: {}", e);
                 std::process::exit(1)
             }
         },
-        Some(("fallback-sim", matches)) => match fallback_sim::run_fallback_sim(matches) {
+        Some("fallback-sim") => match fallback_sim::run_fallback_sim(&matches) {
             Ok(()) => println!("Simulation exited successfully"),
             Err(e) => {
                 eprintln!("Simulation exited with error: {}", e);