feat: Reduce logging for tests with --quiet (#7656)

The test driver by default is configured to run at `Trace`, configured
through the shared `slog`
[dependency](https://github.com/dfinity/ic/blob/23d89f18b6e0ff711931b17fe8d115e2694fcae5/bazel/external_crates.bzl#L1298-L1305).
This adds a new `--quiet` flag that reduces the log level to `Info`, and
suppresses some of the more verbose logs from background tasks.

Author: Bownairo

rs/tests/driver/src/driver/bootstrap.rs

@@ -41,7 +41,7 @@ use ic_registry_canister_api::IPv4Config;
 use ic_registry_provisional_whitelist::ProvisionalWhitelist;
 use ic_registry_subnet_type::SubnetType;
 use ic_types::malicious_behavior::MaliciousBehavior;
-use slog::{Logger, info, warn};
+use slog::{Logger, debug, info, warn};
 use std::{
     collections::BTreeMap,
     convert::Into,
@@ -213,7 +213,7 @@ pub fn init_ic(
         ic_config.skip_unassigned_record();
     }
 
-    info!(test_env.logger(), "Initializing via {:?}", &ic_config);
+    debug!(test_env.logger(), "Initializing via {:?}", &ic_config);
 
     Ok(ic_config.initialize()?)
 }

rs/tests/driver/src/driver/context.rs

@@ -26,6 +26,7 @@ pub struct GroupContext {
     pub group_base_name: String,
     pub logs_enabled: bool,
     pub exclude_logs: Vec<Regex>,
+    pub quiet: bool,
 }
 
 impl GroupContext {
@@ -43,11 +44,12 @@ impl GroupContext {
         group_base_name: String,
         logs_enabled: bool,
         exclude_logs: Vec<Regex>,
+        quiet: bool,
     ) -> Result<Self> {
         let task_id = subproc_info.as_ref().map(|t| t.0.clone());
         let sock_id = subproc_info.map(|t| t.1).unwrap_or_default();
         let socket_path = Self::log_socket_path(sock_id);
-        let logger = Self::create_logger(socket_path, task_id)?;
+        let logger = Self::create_logger(socket_path, task_id, quiet)?;
 
         let exec_path = std::env::current_exe().expect("could not acquire parent process path");
         if !exec_path.is_file() {
@@ -68,6 +70,7 @@ impl GroupContext {
             group_base_name,
             logs_enabled,
             exclude_logs,
+            quiet,
         })
     }
 
@@ -188,14 +191,18 @@ impl GroupContext {
     }
 
     /// Create a logger for this process.
-    fn create_logger(sock_path: PathBuf, subproc_id: Option<TaskId>) -> Result<Logger> {
+    fn create_logger(
+        sock_path: PathBuf,
+        subproc_id: Option<TaskId>,
+        quiet: bool,
+    ) -> Result<Logger> {
         if let Some(task_id) = subproc_id {
             let sender = LogSender::new(task_id, sock_path.clone())
                 .with_context(|| format!("Log socket path: {sock_path:?}"))?;
             let logger = Logger::root(sender, slog::o!());
             Ok(logger)
         } else {
-            let logger = crate::driver::logger::new_stdout_logger();
+            let logger = crate::driver::logger::new_stdout_logger(quiet);
             Ok(logger)
         }
     }

rs/tests/driver/src/driver/group.rs

@@ -141,6 +141,9 @@ pub struct CliArgs {
         help = "The list of regexes which will be skipped from the streaming."
     )]
     pub exclude_logs: Vec<Regex>,
+
+    #[clap(long, short, help = "Reduce terminal logging to mostly test output.")]
+    pub quiet: bool,
 }
 
 impl CliArgs {
@@ -218,9 +221,16 @@ fn subproc(
     task_id: TaskId,
     target_fn: impl SubprocessFn,
     ctx: &mut ComposeContext,
+    quiet: bool,
 ) -> SubprocessTask {
     trace!(ctx.group_ctx.log(), "subproc(task_name={})", &task_id);
-    SubprocessTask::new(task_id, ctx.rh.clone(), target_fn, ctx.group_ctx.clone())
+    SubprocessTask::new(
+        task_id,
+        ctx.rh.clone(),
+        target_fn,
+        ctx.group_ctx.clone(),
+        quiet,
+    )
 }
 
 fn timed(
@@ -393,7 +403,7 @@ impl SystemTestSubGroup {
                 };
                 timed(
                     Plan::Leaf {
-                        task: Box::from(subproc(task_id, closure, ctx)),
+                        task: Box::from(subproc(task_id, closure, ctx, false)),
                     },
                     ctx.timeout_per_test,
                     None,
@@ -567,6 +577,8 @@ impl SystemTestGroup {
         debug!(group_ctx.log(), "SystemTestGroup.make_plan");
         let start_time = Utc::now();
 
+        let quiet = group_ctx.quiet;
+
         let mut compose_ctx = ComposeContext {
             rh,
             group_ctx: group_ctx.clone(),
@@ -645,6 +657,7 @@ impl SystemTestGroup {
                 }
             },
             &mut compose_ctx,
+            false,
         )) as Box<dyn Task>;
 
         // The ID of the root task is needed outside this function for awaiting when the plan execution finishes.
@@ -699,6 +712,7 @@ impl SystemTestGroup {
                     }
                 },
                 &mut compose_ctx,
+                quiet,
             )) as Box<dyn Task>
         } else {
             Box::from(EmptyTask::new(keepalive_task_id)) as Box<dyn Task>
@@ -734,6 +748,7 @@ impl SystemTestGroup {
                     }
                 },
                 &mut compose_ctx,
+                quiet,
             );
 
             Box::from(log_task) as Box<dyn Task>
@@ -765,6 +780,7 @@ impl SystemTestGroup {
                     SetupResult {}.write_attribute(&env);
                 },
                 &mut compose_ctx,
+                false,
             );
             timed(
                 Plan::Leaf {
@@ -787,6 +803,7 @@ impl SystemTestGroup {
                     teardown_fn(env);
                 },
                 &mut compose_ctx,
+                false,
             );
             timed(
                 Plan::Leaf {
@@ -927,6 +944,7 @@ impl SystemTestGroup {
             args.group_base_name,
             !args.no_logs,
             args.exclude_logs,
+            args.quiet,
         )?;
 
         let with_farm = self.with_farm;

rs/tests/driver/src/driver/logger.rs

@@ -2,7 +2,7 @@
 
 use crate::driver::constants;
 use anyhow::Result;
-use slog::{Drain, KV, Key, Logger, OwnedKVList, Record, o};
+use slog::{Drain, KV, Key, Level, Logger, OwnedKVList, Record, o};
 use slog_term::Decorator;
 use std::{fmt, fs::File, io};
 use std::{os::unix::prelude::AsRawFd, path::Path};
@@ -39,15 +39,23 @@ fn new_file_logger<P: AsRef<Path>>(p: P) -> Result<Logger> {
     Ok(slog::Logger::root(async_drain(file_drain), o!()))
 }
 
+pub fn new_discard_logger() -> Logger {
+    slog::Logger::root(async_drain(slog::Discard), o!())
+}
+
 fn multiplex_logger(l1: Logger, l2: Logger) -> Logger {
     slog::Logger::root(slog::Duplicate(l1, l2).fuse(), o!())
 }
 
 /// creates a slog::Logger that prints to standard out using an asynchronous drain
-pub fn new_stdout_logger() -> Logger {
-    let decorator = slog_term::TermDecorator::new().build();
-    let drain = SysTestLogFormatter::new(decorator).fuse();
-    slog::Logger::root(async_drain(drain), o!())
+pub fn new_stdout_logger(quiet: bool) -> Logger {
+    let decorator = slog_term::TermDecorator::new().force_color().build();
+    let drain = SysTestLogFormatter::new(decorator);
+    if quiet {
+        slog::Logger::root(async_drain(drain.filter_level(Level::Info).fuse()), o!())
+    } else {
+        slog::Logger::root(async_drain(drain.fuse()), o!())
+    }
 }
 
 struct SysTestLogFormatter<D> {

rs/tests/driver/src/driver/subprocess_task.rs

@@ -7,6 +7,7 @@ use crate::driver::{
     context::GroupContext,
     dsl::SubprocessFn,
     event::TaskId,
+    logger::new_discard_logger,
     process::{KillFn, Process},
     subprocess_ipc::{LogReceiver, ReportOrFailure, log_panic_event},
     task::{Task, TaskHandle},
@@ -33,6 +34,7 @@ pub struct SubprocessTask {
     f: Arc<Mutex<Option<Box<dyn SubprocessFn>>>>,
     spawned: AtomicBool,
     group_ctx: GroupContext,
+    quiet: bool,
 }
 
 impl SubprocessTask {
@@ -41,13 +43,15 @@ impl SubprocessTask {
         rt: RtHandle,
         f: F,
         group_ctx: GroupContext,
+        quiet: bool,
     ) -> Self {
         Self {
             task_id,
             rt,
             f: shared_mutex(Some(Box::new(f))),
             spawned: Default::default(),
             group_ctx,
+            quiet,
         }
     }
 }
@@ -85,7 +89,15 @@ impl Task for SubprocessTask {
 
         info!(self.group_ctx.log(), "Spawning {:?} ...", child_cmd);
 
-        let log = self.group_ctx.logger();
+        // When this subtask is `quiet`, have the receiver discard logs.
+        // NOTE: We discard on the receiver rather than the sender, so that no
+        // information is lost. Eventually, we may want to split the logfile
+        // and stdout, and will leave this to the receiver.
+        let log = if !self.quiet {
+            self.group_ctx.logger()
+        } else {
+            new_discard_logger()
+        };
         let log_rcvr = self
             .rt
             .block_on(LogReceiver::new(sock_path, log.clone()))

rs/tests/driver/src/driver/test_env.rs

@@ -46,7 +46,7 @@ impl TestEnv {
     pub fn new<P: AsRef<Path>>(path: P, logger: Logger) -> Result<TestEnv> {
         let base_path = PathBuf::from(path.as_ref());
         let log_file = append_and_lock_exclusive(base_path.join("test.log"))?;
-        let file_drain = slog_term::FullFormat::new(slog_term::PlainSyncDecorator::new(log_file))
+        let file_drain = slog_term::FullFormat::new(slog_term::PlainDecorator::new(log_file))
             .build()
             .fuse();
         let file_drain = slog_async::Async::new(file_drain)