Add tracing debug.log

Author: sourcefrog

Cargo.lock

@@ -31,6 +31,9 @@ similar = "2.0"
 subprocess = "0.2.8"
 tempfile = "3.2"
 toml = "0.5"
+tracing = "0.1"
+tracing-appender = "0.2"
+tracing-subscriber = "0.3"
 walkdir = "2.3"
 whoami = "1.2"
 

Cargo.toml

@@ -122,3 +122,11 @@ default the source directory.
 Some trees are configured so that any unused variable is an error. This is a reasonable choice to keep the tree very clean in CI, but if unhandled it would be a problem for cargo mutants. Many mutants -- in fact at the time of writing all generated mutants -- ignore function parameters and return a static value. Rejecting them due to the lint failure is a missed opportunity to consider a similar but more subtle potential bug.
 
 Therefore when running `rustc` we configure all warnings off, with `--cap-lints`.
+
+## Logging
+
+cargo-mutants writes two types of log files into the `mutants.out` directory:
+
+Within the `log` directory, there is a file for each mutant scenario. This mostly contains the output from the Cargo commands, interspersed with some lines showing what command was run and the outcome. This is opened in append mode so that both cargo-mutants and cargo can write to it. This log is watched and the last line is shown in the progress bar to indicate what's going on.
+
+Also, a file `mutants.out/debug.log` is written using [tracing](https://docs.rs/tracing) and written using the tracing macros. This contains more detailed information about what's happening in cargo-mutants itself.

DESIGN.md

@@ -10,6 +10,7 @@ use camino::Utf8Path;
 use serde::Serialize;
 use serde_json::Value;
 use subprocess::{Popen, PopenConfig, Redirection};
+use tracing::{debug, info, warn};
 
 use crate::console::Console;
 use crate::log_file::LogFile;
@@ -63,7 +64,9 @@ pub fn run_cargo(
 
     let mut argv: Vec<String> = vec![cargo_bin];
     argv.extend(cargo_args.iter().cloned());
-    log_file.message(&format!("run {}", argv.join(" "),));
+    let message = format!("run {}", argv.join(" "),);
+    log_file.message(&message);
+    info!("{}", message);
     let mut child = Popen::create(
         &argv,
         PopenConfig {
@@ -78,14 +81,16 @@ pub fn run_cargo(
     .with_context(|| format!("failed to spawn {}", argv.join(" ")))?;
     let exit_status = loop {
         if start.elapsed() > timeout {
-            log_file.message(&format!(
+            let message = format!(
                 "timeout after {:.3}s, terminating cargo process...\n",
                 start.elapsed().as_secs_f32()
-            ));
+            );
+            log_file.message(&message);
+            info!("{}", message);
             terminate_child(child, log_file)?;
             return Ok(CargoResult::Timeout);
         } else if let Err(e) = check_interrupted() {
-            log_file.message("interrupted\n");
+            warn!("interrupted: {}", e);
             console.message(&console::style_interrupted());
             terminate_child(child, log_file)?;
             return Err(e);
@@ -94,11 +99,13 @@ pub fn run_cargo(
         }
         console.tick();
     };
-    log_file.message(&format!(
+    let message = format!(
         "cargo result: {:?} in {:.3}s",
         exit_status,
         start.elapsed().as_secs_f64()
-    ));
+    );
+    log_file.message(&message);
+    info!("{}", message);
     check_interrupted()?;
     if exit_status.success() {
         Ok(CargoResult::Success)
@@ -133,12 +140,14 @@ fn terminate_child(mut child: Popen, log_file: &mut LogFile) -> Result<()> {
     use std::convert::TryInto;
 
     let pid = nix::unistd::Pid::from_raw(child.pid().expect("child has a pid").try_into().unwrap());
+    info!("terminating cargo process {}", pid);
     if let Err(errno) = killpg(pid, Signal::SIGTERM) {
         if errno == Errno::ESRCH {
             // most likely we raced and it's already gone
             return Ok(());
         } else {
             let message = format!("failed to terminate child: {}", errno);
+            warn!("{}", message);
             log_file.message(&message);
             return Err(anyhow!(message));
         }
@@ -151,9 +160,11 @@ fn terminate_child(mut child: Popen, log_file: &mut LogFile) -> Result<()> {
 
 #[cfg(not(unix))]
 fn terminate_child(mut child: Popen, log_file: &mut LogFile) -> Result<()> {
+    info!("terminating cargo process {child:?}");
     if let Err(e) = child.terminate() {
         // most likely we raced and it's already gone
         let message = format!("failed to terminate child: {}", e);
+        warn!("{}", message);
         log_file.message(&message);
         return Err(anyhow!(message));
     }
@@ -203,6 +214,7 @@ pub fn locate_project(path: &Utf8Path) -> Result<Utf8PathBuf> {
     {
         return Err(anyhow!(stderr));
     }
+    debug!("locate-project output: {stdout}");
     let val: Value = serde_json::from_str(&stdout).context("parse cargo locate-project output")?;
     let root = &val["root"];
     root.as_str()

src/cargo.rs

@@ -8,6 +8,7 @@ use std::time::{Duration, Instant};
 
 use ::console::{style, StyledObject};
 use camino::Utf8Path;
+use tracing::info;
 
 use crate::outcome::SummaryOutcome;
 use crate::*;
@@ -106,6 +107,7 @@ impl Console {
     }
 
     pub fn message(&self, message: &str) {
+        info!("{}", message);
         self.view.message(message)
     }
 

src/console.rs

@@ -12,6 +12,7 @@ use anyhow::{anyhow, Result};
 use camino::Utf8Path;
 use rand::prelude::*;
 use serde::Serialize;
+use tracing::info;
 
 use crate::cargo::{cargo_args, run_cargo};
 use crate::console::{self, plural, Console};
@@ -72,6 +73,15 @@ pub fn test_unmutated_then_all_mutants(
         source_tree.path()
     };
     let output_dir = OutputDir::new(output_in_dir)?;
+
+    let debug_log = tracing_appender::rolling::never(output_dir.path(), "debug.log");
+    tracing_subscriber::fmt()
+        .with_ansi(false)
+        .with_file(true) // source file name
+        .with_line_number(true)
+        .with_writer(debug_log)
+        .init();
+
     let console = Console::new();
 
     if options.build_source {
@@ -184,6 +194,7 @@ fn run_cargo_phases(
     phases: &[Phase],
     console: &Console,
 ) -> Result<Outcome> {
+    info!("start testing {scenario} in {in_dir}");
     let mut log_file = output_dir.create_log(scenario)?;
     log_file.message(&scenario.to_string());
     let start_time = Instant::now();
@@ -207,6 +218,7 @@ fn run_cargo_phases(
             break;
         }
     }
+    info!("{scenario} outcome {:?}", outcome.summary());
     console.cargo_outcome(scenario, start_time, &outcome, options);
 
     Ok(outcome)