From f92e8b793c601ee5935788914ba2a01b5cc14b7f Mon Sep 17 00:00:00 2001 From: Martin Pool Date: Sun, 14 Aug 2022 09:28:06 -0700 Subject: [PATCH] Add tracing debug.log --- Cargo.lock | 144 +++++++++++++++++++++++++++++++++++++++++++++++- Cargo.toml | 3 + DESIGN.md | 8 +++ src/cargo.rs | 24 ++++++-- src/console.rs | 2 + src/lab.rs | 12 ++++ src/manifest.rs | 5 +- tests/cli.rs | 4 ++ 8 files changed, 194 insertions(+), 8 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 38e8866e..56b3dfc4 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -152,6 +152,9 @@ dependencies = [ "syn", "tempfile", "toml", + "tracing", + "tracing-appender", + "tracing-subscriber", "walkdir", "whoami", ] @@ -264,7 +267,7 @@ dependencies = [ "libc", "num-integer", "num-traits", - "time", + "time 0.1.44", "winapi", ] @@ -291,6 +294,26 @@ dependencies = [ "filetime", ] +[[package]] +name = "crossbeam-channel" +version = "0.5.6" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "c2dd04ddaf88237dc3b8d8f9a3c1004b506b54b3313403944054d23c0870c521" +dependencies = [ + "cfg-if", + "crossbeam-utils", +] + +[[package]] +name = "crossbeam-utils" +version = "0.8.11" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "51887d4adc7b564537b15adcfb307936f8075dfcd5f00dde9a9f1d29383682bc" +dependencies = [ + "cfg-if", + "once_cell", +] + [[package]] name = "ctor" version = "0.1.23" @@ -624,6 +647,15 @@ dependencies = [ "autocfg", ] +[[package]] +name = "num_threads" +version = "0.1.6" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "2819ce041d2ee131036f4fc9d6ae7ae125a3a40e97ba64d04fe799ad9dabbb44" +dependencies = [ + "libc", +] + [[package]] name = "nutmeg" version = "0.1.2" @@ -680,6 +712,12 @@ version = "0.2.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "c54014ba3c1880122928735226f78b6f5bf5bd1fed15e41e92cf7aa20278ce28" +[[package]] +name = "pin-project-lite" +version = "0.2.9" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "e0a7ae3ac2f1173085d398531c705756c94a4c56843785df85a60c1a0afac116" + [[package]] name = "ppv-lite86" version = "0.2.16" @@ -904,6 +942,15 @@ dependencies = [ "yaml-rust", ] +[[package]] +name = "sharded-slab" +version = "0.1.4" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "900fba806f70c630b0a382d0d825e17a0f19fcd059a2ade1ff237bcddf446b31" +dependencies = [ + "lazy_static", +] + [[package]] name = "similar" version = "2.2.0" @@ -977,6 +1024,15 @@ version = "0.2.4" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "507e9898683b6c43a9aa55b64259b721b52ba226e0f3779137e50ad114a4c90b" +[[package]] +name = "thread_local" +version = "1.1.4" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "5516c27b78311c50bf42c071425c560ac799b11c30b31f87e3081965fe5e0180" +dependencies = [ + "once_cell", +] + [[package]] name = "time" version = "0.1.44" @@ -988,6 +1044,17 @@ dependencies = [ "winapi", ] +[[package]] +name = "time" +version = "0.3.13" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "db76ff9fa4b1458b3c7f077f3ff9887394058460d21e634355b273aaf11eea45" +dependencies = [ + "itoa", + "libc", + "num_threads", +] + [[package]] name = "toml" version = "0.5.9" @@ -997,6 +1064,75 @@ dependencies = [ "serde", ] +[[package]] +name = "tracing" +version = "0.1.36" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "2fce9567bd60a67d08a16488756721ba392f24f29006402881e43b19aac64307" +dependencies = [ + "cfg-if", + "pin-project-lite", + "tracing-attributes", + "tracing-core", +] + +[[package]] +name = "tracing-appender" +version = "0.2.2" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "09d48f71a791638519505cefafe162606f706c25592e4bde4d97600c0195312e" +dependencies = [ + "crossbeam-channel", + "time 0.3.13", + "tracing-subscriber", +] + +[[package]] +name = "tracing-attributes" +version = "0.1.22" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "11c75893af559bc8e10716548bdef5cb2b983f8e637db9d0e15126b61b484ee2" +dependencies = [ + "proc-macro2", + "quote", + "syn", +] + +[[package]] +name = "tracing-core" +version = "0.1.29" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "5aeea4303076558a00714b823f9ad67d58a3bbda1df83d8827d21193156e22f7" +dependencies = [ + "once_cell", + "valuable", +] + +[[package]] +name = "tracing-log" +version = "0.1.3" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "78ddad33d2d10b1ed7eb9d1f518a5674713876e97e5bb9b7345a7984fbb4f922" +dependencies = [ + "lazy_static", + "log", + "tracing-core", +] + +[[package]] +name = "tracing-subscriber" +version = "0.3.15" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "60db860322da191b40952ad9affe65ea23e7dd6a5c442c2c42865810c6ab8e6b" +dependencies = [ + "ansi_term", + "sharded-slab", + "smallvec", + "thread_local", + "tracing-core", + "tracing-log", +] + [[package]] name = "unicode-ident" version = "1.0.3" @@ -1015,6 +1151,12 @@ version = "0.1.9" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "3ed742d4ea2bd1176e236172c8429aaf54486e7ac098db29ffe6529e0ce50973" +[[package]] +name = "valuable" +version = "0.1.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "830b7e5d4d90034032940e4ace0d9a9a057e7a45cd94e6c007832e39edb82f6d" + [[package]] name = "wait-timeout" version = "0.2.0" diff --git a/Cargo.toml b/Cargo.toml index 5a7741cf..0bd515b9 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -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" diff --git a/DESIGN.md b/DESIGN.md index e6a6137a..983e37f1 100644 --- a/DESIGN.md +++ b/DESIGN.md @@ -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. diff --git a/src/cargo.rs b/src/cargo.rs index 066ae2d9..aad862e4 100644 --- a/src/cargo.rs +++ b/src/cargo.rs @@ -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 = 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 { { 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() diff --git a/src/console.rs b/src/console.rs index e6f61a3f..572d75d3 100644 --- a/src/console.rs +++ b/src/console.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) } diff --git a/src/lab.rs b/src/lab.rs index 66b1e354..cfeebd67 100644 --- a/src/lab.rs +++ b/src/lab.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 { + 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) diff --git a/src/manifest.rs b/src/manifest.rs index c94b72a2..358c66da 100644 --- a/src/manifest.rs +++ b/src/manifest.rs @@ -9,6 +9,7 @@ use std::fs; use anyhow::Context; use camino::Utf8Path; +use tracing::debug; use crate::path::ascent; use crate::Result; @@ -145,7 +146,9 @@ fn fix_path(path_str: &str, source_dir: &Utf8Path) -> Option { } else { let mut new_path = source_dir.to_owned(); new_path.push(path); - Some(new_path.to_string()) + let new_path_str = new_path.to_string(); + debug!("fix path {path_str} -> {new_path_str}"); + Some(new_path_str) } } diff --git a/tests/cli.rs b/tests/cli.rs index cd9a2a0e..bbd269ef 100644 --- a/tests/cli.rs +++ b/tests/cli.rs @@ -585,6 +585,10 @@ fn output_option() { .is_file(), "mutants.out/outcomes.json is in --output directory" ); + assert!( + output_tmpdir.path().join("mutants.out/debug.log").is_file(), + "mutants.out/debug.log is in --output directory" + ); } #[test]