feat: include the execution output in the logs

Author: art049

src/ci_provider/buildkite/logger.rs

@@ -1,4 +1,6 @@
-use crate::ci_provider::logger::{get_group_event, GroupEvent};
+use crate::ci_provider::logger::{
+    get_group_event, should_provider_logger_handle_record, GroupEvent,
+};
 use log::*;
 use simplelog::SharedLogger;
 use std::{env, io::Write};
@@ -26,6 +28,10 @@ impl Log for BuildkiteLogger {
     }
 
     fn log(&self, record: &Record) {
+        if !should_provider_logger_handle_record(record) {
+            return;
+        }
+
         let level = record.level();
         let message = record.args();
 

src/ci_provider/github_actions/logger.rs

@@ -1,4 +1,6 @@
-use crate::ci_provider::logger::{get_group_event, GroupEvent};
+use crate::ci_provider::logger::{
+    get_group_event, should_provider_logger_handle_record, GroupEvent,
+};
 use log::*;
 use simplelog::SharedLogger;
 use std::io::Write;
@@ -14,6 +16,10 @@ impl Log for GithubActionLogger {
     }
 
     fn log(&self, record: &Record) {
+        if !should_provider_logger_handle_record(record) {
+            return;
+        }
+
         let level = record.level();
         let message = record.args();
 

src/ci_provider/logger.rs

@@ -1,3 +1,5 @@
+use crate::runner::VALGRIND_EXECUTION_TARGET;
+
 /// This target is used exclusively to handle group events.
 pub const GROUP_TARGET: &str = "codspeed::group";
 pub const OPENED_GROUP_TARGET: &str = "codspeed::group::opened";
@@ -71,3 +73,8 @@ pub(super) fn get_group_event(record: &log::Record) -> Option<GroupEvent> {
         _ => None,
     }
 }
+
+pub(super) fn should_provider_logger_handle_record(record: &log::Record) -> bool {
+    // Provider logger should handle all records except the ones from the valgrind execution target
+    record.target() != VALGRIND_EXECUTION_TARGET
+}

src/logger.rs

@@ -1,3 +1,4 @@
+use crate::ci_provider::logger::{GROUP_TARGET, OPENED_GROUP_TARGET};
 use crate::runner::RunData;
 use crate::{ci_provider::CIProvider, prelude::*};
 use log::LevelFilter;
@@ -16,8 +17,12 @@ impl Logger {
         let provider_logger = provider.get_logger();
         let log_file = NamedTempFile::new().context("Failed to create log file")?;
         let log_file_path = log_file.path().to_path_buf();
-        let file_logger =
-            WriteLogger::new(LevelFilter::Trace, simplelog::Config::default(), log_file);
+        let file_logger_config = simplelog::ConfigBuilder::new()
+            // Groups are not logged to the file
+            .add_filter_ignore_str(GROUP_TARGET)
+            .add_filter_ignore_str(OPENED_GROUP_TARGET)
+            .build();
+        let file_logger = WriteLogger::new(LevelFilter::Trace, file_logger_config, log_file);
         CombinedLogger::init(vec![provider_logger, file_logger])
             .context("Failed to init logger")?;
         Ok(Self { log_file_path })

src/runner/mod.rs

@@ -6,3 +6,4 @@ mod valgrind;
 
 pub use self::run::RunData;
 pub use run::run;
+pub use valgrind::VALGRIND_EXECUTION_TARGET;

src/runner/valgrind.rs

@@ -4,10 +4,12 @@ use crate::prelude::*;
 use crate::runner::helpers::ignored_objects_path::get_objects_path_to_ignore;
 use crate::runner::helpers::introspected_node::setup_introspected_node;
 use lazy_static::lazy_static;
-use std::env;
 use std::fs::canonicalize;
+use std::io::{Read, Write};
 use std::path::Path;
+use std::process::ExitStatus;
 use std::{collections::HashMap, env::consts::ARCH, process::Command};
+use std::{env, thread};
 
 lazy_static! {
     static ref BASE_INJECTED_ENV: HashMap<&'static str, String> = {
@@ -54,6 +56,43 @@ fn get_bench_command(config: &Config) -> String {
         .replace("cargo codspeed", "cargo-codspeed")
 }
 
+pub const VALGRIND_EXECUTION_TARGET: &str = "valgrind::execution";
+
+fn run_command_with_log_pipe(mut cmd: Command) -> Result<ExitStatus> {
+    fn log_tee(
+        mut reader: impl Read,
+        mut writer: impl Write,
+        log_prefix: Option<&str>,
+    ) -> Result<()> {
+        let prefix = log_prefix.unwrap_or("");
+        let mut buffer = [0; 1024];
+        loop {
+            let bytes_read = reader.read(&mut buffer)?;
+            if bytes_read == 0 {
+                break;
+            }
+            writer.write_all(&buffer[..bytes_read])?;
+            trace!(target: VALGRIND_EXECUTION_TARGET, "{}{}", prefix, String::from_utf8_lossy(&buffer[..bytes_read]));
+        }
+        Ok(())
+    }
+
+    let mut process = cmd
+        .stdout(std::process::Stdio::piped())
+        .stderr(std::process::Stdio::piped())
+        .spawn()
+        .context("failed to spawn the process")?;
+    let stdout = process.stdout.take().expect("unable to get stdout");
+    let stderr = process.stderr.take().expect("unable to get stderr");
+    thread::spawn(move || {
+        log_tee(stdout, std::io::stdout(), None).unwrap();
+    });
+    thread::spawn(move || {
+        log_tee(stderr, std::io::stderr(), Some("[stderr]")).unwrap();
+    });
+    process.wait().context("failed to wait for the process")
+}
+
 pub fn measure(
     config: &Config,
     profile_folder: &Path,
@@ -102,8 +141,7 @@ pub fn measure(
     }
 
     debug!("cmd: {:?}", cmd);
-    let status = cmd
-        .status()
+    let status = run_command_with_log_pipe(cmd)
         .map_err(|e| anyhow!("failed to execute the benchmark process. {}", e))?;
     if !status.success() {
         bail!("failed to execute the benchmark process");