feat: upload execution logs with the profile

Cargo.toml

@@ -9,7 +9,6 @@ publish = false
 [dependencies]
 anyhow = "1.0.75"
 clap = { version = "4.4.8", features = ["derive", "env"] }
-env_logger = "0.10.1"
 itertools = "0.11.0"
 lazy_static = "1.4.0"
 log = "0.4.20"
@@ -31,12 +30,18 @@ tokio-tar = "0.3.1"
 md5 = "0.7.0"
 base64 = "0.21.0"
 async-compression = { version = "0.4.5", features = ["tokio", "gzip"] }
+simplelog = { version = "0.12.1", default-features = false }
+tempfile = "3.10.0"
 
 [dev-dependencies]
 temp-env = { version = "0.3.6", features = ["async_closure"] }
 insta = { version = "1.29.0", features = ["json", "redactions"] }
 
 
+[workspace.metadata.release]
+sign-tag = true
+sign-commit = true
+
 [profile.dist]
 inherits = "release"
 lto = "thin"

src/app.rs

@@ -1,6 +1,4 @@
-use std::env;
-
-use crate::{ci_provider, config::Config, prelude::*, runner, uploader, VERSION};
+use crate::{ci_provider, config::Config, logger::Logger, prelude::*, runner, uploader, VERSION};
 use clap::Parser;
 
 fn show_banner() {
@@ -82,20 +80,16 @@ pub async fn run() -> Result<()> {
     let args = AppArgs::parse();
     let config = Config::try_from(args)?;
     let provider = ci_provider::get_provider(&config)?;
-
-    let log_level = env::var("CODSPEED_LOG")
-        .ok()
-        .and_then(|log_level| log_level.parse::<log::LevelFilter>().ok())
-        .unwrap_or(log::LevelFilter::Info);
-    log::set_max_level(log_level);
-    provider.setup_logger()?;
+    let logger = Logger::new(&provider)?;
 
     show_banner();
     debug!("config: {:#?}", config);
 
     let run_data = runner::run(&config).await?;
+
     if !config.skip_upload {
         start_group!("Upload the results");
+        logger.persist_log_to_profile_folder(&run_data)?;
         uploader::upload(&config, provider, &run_data).await?;
         end_group!();
     }

src/ci_provider/buildkite/logger.rs

@@ -1,18 +1,37 @@
+use crate::ci_provider::logger::{
+    get_group_event, should_provider_logger_handle_record, GroupEvent,
+};
 use log::*;
-
-use crate::ci_provider::logger::{get_group_event, GroupEvent};
+use simplelog::SharedLogger;
+use std::{env, io::Write};
 
 /// A logger that prints logs in the format expected by Buildkite
 ///
 /// See https://buildkite.com/docs/pipelines/managing-log-output
-pub struct BuildkiteLogger;
+pub struct BuildkiteLogger {
+    log_level: LevelFilter,
+}
+
+impl BuildkiteLogger {
+    pub fn new() -> Self {
+        let log_level = env::var("CODSPEED_LOG")
+            .ok()
+            .and_then(|log_level| log_level.parse::<log::LevelFilter>().ok())
+            .unwrap_or(log::LevelFilter::Info);
+        Self { log_level }
+    }
+}
 
 impl Log for BuildkiteLogger {
     fn enabled(&self, _metadata: &Metadata) -> bool {
         true
     }
 
     fn log(&self, record: &Record) {
+        if !should_provider_logger_handle_record(record) {
+            return;
+        }
+
         let level = record.level();
         let message = record.args();
 
@@ -29,6 +48,9 @@ impl Log for BuildkiteLogger {
             return;
         }
 
+        if level > self.log_level {
+            return;
+        }
         // there is no support for log levels in Buildkite, so we print the level in the message
         match level {
             Level::Error => {
@@ -49,5 +71,21 @@ impl Log for BuildkiteLogger {
         }
     }
 
-    fn flush(&self) {}
+    fn flush(&self) {
+        std::io::stdout().flush().unwrap();
+    }
+}
+
+impl SharedLogger for BuildkiteLogger {
+    fn level(&self) -> LevelFilter {
+        self.log_level
+    }
+
+    fn config(&self) -> Option<&simplelog::Config> {
+        None
+    }
+
+    fn as_log(self: Box<Self>) -> Box<dyn Log> {
+        Box::new(*self)
+    }
 }

src/ci_provider/buildkite/provider.rs

@@ -2,6 +2,7 @@ use std::env;
 
 use lazy_static::lazy_static;
 use regex::Regex;
+use simplelog::SharedLogger;
 
 use crate::{
     ci_provider::{
@@ -125,9 +126,8 @@ impl CIProviderDetector for BuildkiteProvider {
 }
 
 impl CIProvider for BuildkiteProvider {
-    fn setup_logger(&self) -> Result<()> {
-        log::set_logger(&BuildkiteLogger)?;
-        Ok(())
+    fn get_logger(&self) -> Box<dyn SharedLogger> {
+        Box::new(BuildkiteLogger::new())
     }
 
     fn get_provider_name(&self) -> &'static str {

src/ci_provider/github_actions/logger.rs

@@ -1,6 +1,9 @@
+use crate::ci_provider::logger::{
+    get_group_event, should_provider_logger_handle_record, GroupEvent,
+};
 use log::*;
-
-use crate::ci_provider::logger::{get_group_event, GroupEvent};
+use simplelog::SharedLogger;
+use std::io::Write;
 
 /// A logger that prints logs in the format expected by GitHub Actions, with grouping support.
 ///
@@ -13,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();
 
@@ -41,5 +48,23 @@ impl Log for GithubActionLogger {
         lines.for_each(|line| println!("{}{}", prefix, line));
     }
 
-    fn flush(&self) {}
+    fn flush(&self) {
+        std::io::stdout().flush().unwrap();
+    }
+}
+
+impl SharedLogger for GithubActionLogger {
+    fn level(&self) -> LevelFilter {
+        // since TRACE and DEBUG use ::debug::, we always enable them and let GitHub handle the filtering
+        // thanks to https://docs.github.com/en/actions/monitoring-and-troubleshooting-workflows/enabling-debug-logging#enabling-step-debug-logging
+        LevelFilter::Trace
+    }
+
+    fn config(&self) -> Option<&simplelog::Config> {
+        None
+    }
+
+    fn as_log(self: Box<Self>) -> Box<dyn Log> {
+        Box::new(*self)
+    }
 }

src/ci_provider/github_actions/provider.rs

@@ -1,8 +1,8 @@
-use std::{env, fs};
-
 use lazy_static::lazy_static;
 use regex::Regex;
 use serde_json::Value;
+use simplelog::SharedLogger;
+use std::{env, fs};
 
 use crate::{
     ci_provider::{
@@ -116,12 +116,8 @@ impl CIProviderDetector for GitHubActionsProvider {
 }
 
 impl CIProvider for GitHubActionsProvider {
-    fn setup_logger(&self) -> Result<()> {
-        log::set_logger(&GithubActionLogger)?;
-        // since TRACE and DEBUG use ::debug::, we always enable them and let GitHub handle the filtering
-        // thanks to https://docs.github.com/en/actions/monitoring-and-troubleshooting-workflows/enabling-debug-logging#enabling-step-debug-logging
-        log::set_max_level(log::LevelFilter::Trace);
-        Ok(())
+    fn get_logger(&self) -> Box<dyn SharedLogger> {
+        Box::new(GithubActionLogger)
     }
 
     fn get_provider_name(&self) -> &'static str {

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/ci_provider/provider.rs

@@ -1,3 +1,5 @@
+use simplelog::SharedLogger;
+
 use crate::config::Config;
 use crate::prelude::*;
 use crate::uploader::{Runner, UploadMetadata};
@@ -11,8 +13,8 @@ pub trait CIProviderDetector {
 
 /// `CIProvider` is a trait that defines the necessary methods for a continuous integration provider.
 pub trait CIProvider {
-    /// Registers the logger for the CI provider.
-    fn setup_logger(&self) -> Result<()>;
+    /// Returns the logger for the CI provider.
+    fn get_logger(&self) -> Box<dyn SharedLogger>;
 
     /// Returns the name of the CI provider.
     ///

src/logger.rs

@@ -0,0 +1,39 @@
+use crate::ci_provider::logger::{GROUP_TARGET, OPENED_GROUP_TARGET};
+use crate::runner::RunData;
+use crate::{ci_provider::CIProvider, prelude::*};
+use log::LevelFilter;
+use simplelog::{CombinedLogger, WriteLogger};
+use std::fs::copy;
+use std::path::PathBuf;
+use tempfile::NamedTempFile;
+
+pub struct Logger {
+    log_file_path: PathBuf,
+}
+
+impl Logger {
+    #[allow(clippy::borrowed_box)]
+    pub fn new(provider: &Box<dyn CIProvider>) -> Result<Self> {
+        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_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 })
+    }
+
+    pub fn persist_log_to_profile_folder(&self, run_data: &RunData) -> Result<()> {
+        let profile_folder = run_data.profile_folder.clone();
+        let dest_log_file_path = profile_folder.join("runner.log");
+        debug!("Persisting log file to {}", dest_log_file_path.display());
+        log::logger().flush();
+        copy(&self.log_file_path, dest_log_file_path).context("Failed to copy log file")?;
+        Ok(())
+    }
+}

src/main.rs

@@ -3,14 +3,16 @@ mod ci_provider;
 mod config;
 mod helpers;
 mod instruments;
+mod logger;
 mod prelude;
 mod request_client;
 mod runner;
 mod uploader;
 
-use log::log_enabled;
 use prelude::*;
 
+use log::log_enabled;
+
 pub const VERSION: &str = env!("CARGO_PKG_VERSION");
 pub const MONGODB_TRACER_VERSION: &str = "cs-mongo-tracer-v0.2.0";
 pub const VALGRIND_CODSPEED_VERSION: &str = "3.21.0-0codspeed1";

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");