runner: include prepare step in the logs

Author: pietroalbini

src/agent/results.rs

@@ -48,12 +48,13 @@ impl<'a> WriteResults for ResultsUploader<'a> {
         _ex: &Experiment,
         toolchain: &Toolchain,
         krate: &Crate,
+        existing_logs: Option<LogStorage>,
         f: F,
     ) -> Fallible<TestResult>
     where
         F: FnOnce() -> Fallible<TestResult>,
     {
-        let storage = LogStorage::new(LevelFilter::Info);
+        let storage = existing_logs.unwrap_or_else(|| LogStorage::new(LevelFilter::Info));
         let result = logs::capture(&storage, f)?;
         let output = storage.to_string();
 

src/logs/mod.rs

@@ -5,7 +5,7 @@ use log::{Log, Metadata, Record};
 use std::cell::RefCell;
 use std::thread::LocalKey;
 
-pub(crate) use self::storage::LogStorage;
+pub use self::storage::LogStorage;
 
 thread_local! {
     static SCOPED: RefCell<Vec<Box<Log>>> = RefCell::new(Vec::new());

src/logs/storage.rs

@@ -2,6 +2,7 @@ use log::{Level, LevelFilter, Log, Metadata, Record};
 use std::fmt;
 use std::sync::{Arc, Mutex};
 
+#[derive(Clone)]
 struct StoredRecord {
     level: Level,
     message: String,
@@ -12,7 +13,7 @@ struct InnerStorage {
 }
 
 #[derive(Clone)]
-pub(crate) struct LogStorage {
+pub struct LogStorage {
     inner: Arc<Mutex<InnerStorage>>,
     min_level: LevelFilter,
 }
@@ -26,6 +27,16 @@ impl LogStorage {
             min_level,
         }
     }
+
+    pub(crate) fn duplicate(&self) -> LogStorage {
+        let inner = self.inner.lock().unwrap();
+        LogStorage {
+            inner: Arc::new(Mutex::new(InnerStorage {
+                records: inner.records.clone(),
+            })),
+            min_level: self.min_level,
+        }
+    }
 }
 
 impl Log for LogStorage {

src/results/db.rs

@@ -168,12 +168,13 @@ impl<'a> WriteResults for DatabaseDB<'a> {
         ex: &Experiment,
         toolchain: &Toolchain,
         krate: &Crate,
+        existing_logs: Option<LogStorage>,
         f: F,
     ) -> Fallible<TestResult>
     where
         F: FnOnce() -> Fallible<TestResult>,
     {
-        let storage = LogStorage::new(LevelFilter::Info);
+        let storage = existing_logs.unwrap_or_else(|| LogStorage::new(LevelFilter::Info));
         let result = logs::capture(&storage, f)?;
         let output = storage.to_string();
         self.store_result(ex, krate, toolchain, result, output.as_bytes())?;

src/results/mod.rs

@@ -4,6 +4,7 @@ mod dummy;
 
 use crate::crates::{Crate, GitHubRepo};
 use crate::experiments::Experiment;
+use crate::logs::LogStorage;
 use crate::prelude::*;
 pub use crate::results::db::{DatabaseDB, ProgressData};
 #[cfg(test)]
@@ -41,6 +42,7 @@ pub trait WriteResults {
         ex: &Experiment,
         toolchain: &Toolchain,
         krate: &Crate,
+        existing_logs: Option<LogStorage>,
         f: F,
     ) -> Fallible<TestResult>
     where

src/runner/graph.rs

@@ -20,7 +20,10 @@ use crate::config::Config;
 use crate::experiments::{Experiment, Mode};
 use crate::prelude::*;
 use crate::results::{TestResult, WriteResults};
-use crate::runner::tasks::{Task, TaskStep};
+use crate::runner::{
+    tasks::{Task, TaskStep},
+    RunnerState,
+};
 use failure::AsFail;
 use petgraph::{dot::Dot, graph::NodeIndex, stable_graph::StableDiGraph, Direction};
 use std::fmt::{self, Debug};
@@ -187,6 +190,7 @@ impl TasksGraph {
         node: NodeIndex,
         ex: &Experiment,
         db: &DB,
+        state: &RunnerState,
         error: &F,
         result: TestResult,
     ) -> Fallible<()> {
@@ -195,11 +199,11 @@ impl TasksGraph {
             .neighbors_directed(node, Direction::Incoming)
             .collect::<Vec<_>>();
         for child in children.drain(..) {
-            self.mark_as_failed(child, ex, db, error, result)?;
+            self.mark_as_failed(child, ex, db, state, error, result)?;
         }
 
         match self.graph[node] {
-            Node::Task { ref task, .. } => task.mark_as_failed(ex, db, error, result)?,
+            Node::Task { ref task, .. } => task.mark_as_failed(ex, db, state, error, result)?,
             Node::CrateCompleted | Node::Root => return Ok(()),
         }
 

src/runner/mod.rs

@@ -6,8 +6,10 @@ mod toml_frobber;
 mod unstable_features;
 
 use crate::config::Config;
+use crate::crates::Crate;
 use crate::docker::DockerEnv;
 use crate::experiments::Experiment;
+use crate::logs::LogStorage;
 use crate::prelude::*;
 use crate::results::{FailureReason, TestResult, WriteResults};
 use crate::runner::graph::{build_graph, WalkResult};
@@ -22,6 +24,28 @@ use std::thread;
 #[fail(display = "overridden task result to {}", _0)]
 pub struct OverrideResult(TestResult);
 
+struct RunnerStateInner {
+    prepare_logs: HashMap<Crate, LogStorage>,
+}
+
+struct RunnerState {
+    inner: Mutex<RunnerStateInner>,
+}
+
+impl RunnerState {
+    fn new() -> Self {
+        RunnerState {
+            inner: Mutex::new(RunnerStateInner {
+                prepare_logs: HashMap::new(),
+            }),
+        }
+    }
+
+    fn lock(&self) -> std::sync::MutexGuard<RunnerStateInner> {
+        self.inner.lock().unwrap()
+    }
+}
+
 pub fn run_ex<DB: WriteResults + Sync>(
     ex: &Experiment,
     db: &DB,
@@ -70,6 +94,7 @@ fn run_ex_inner<DB: WriteResults + Sync>(
     // An HashMap is used instead of an HashSet because Thread is not Eq+Hash
     let parked_threads: Mutex<HashMap<thread::ThreadId, thread::Thread>> =
         Mutex::new(HashMap::new());
+    let state = RunnerState::new();
 
     scope(|scope| -> Fallible<()> {
         let mut threads = Vec::new();
@@ -83,7 +108,7 @@ fn run_ex_inner<DB: WriteResults + Sync>(
                     match walk_result {
                         WalkResult::Task(id, task) => {
                             info!("running task: {:?}", task);
-                            if let Err(e) = task.run(config, ex, db, &docker_env) {
+                            if let Err(e) = task.run(config, ex, db, &docker_env, &state) {
                                 error!("task failed, marking childs as failed too: {:?}", task);
                                 utils::report_failure(&e);
 
@@ -103,7 +128,7 @@ fn run_ex_inner<DB: WriteResults + Sync>(
                                 graph
                                     .lock()
                                     .unwrap()
-                                    .mark_as_failed(id, ex, db, &e, result)?;
+                                    .mark_as_failed(id, ex, db, &state, &e, result)?;
                             } else {
                                 graph.lock().unwrap().mark_as_completed(id);
                             }

src/runner/tasks.rs

@@ -3,13 +3,14 @@ use crate::crates::Crate;
 use crate::dirs;
 use crate::docker::DockerEnv;
 use crate::experiments::Experiment;
+use crate::logs::{self, LogStorage};
 use crate::prelude::*;
 use crate::results::{TestResult, WriteResults};
-use crate::runner::prepare::PrepareCrate;
-use crate::runner::test;
+use crate::runner::{prepare::PrepareCrate, test, RunnerState};
 use crate::toolchain::Toolchain;
 use crate::utils;
 use failure::AsFail;
+use log::LevelFilter;
 use std::fmt;
 
 pub(super) struct TaskCtx<'ctx, DB: WriteResults + 'ctx> {
@@ -19,17 +20,20 @@ pub(super) struct TaskCtx<'ctx, DB: WriteResults + 'ctx> {
     pub(super) toolchain: &'ctx Toolchain,
     pub(super) krate: &'ctx Crate,
     pub(super) docker_env: &'ctx DockerEnv,
+    pub(super) state: &'ctx RunnerState,
     pub(super) quiet: bool,
 }
 
 impl<'ctx, DB: WriteResults + 'ctx> TaskCtx<'ctx, DB> {
+    #[allow(clippy::too_many_arguments)]
     fn new(
         config: &'ctx Config,
         db: &'ctx DB,
         experiment: &'ctx Experiment,
         toolchain: &'ctx Toolchain,
         krate: &'ctx Crate,
         docker_env: &'ctx DockerEnv,
+        state: &'ctx RunnerState,
         quiet: bool,
     ) -> Self {
         TaskCtx {
@@ -39,6 +43,7 @@ impl<'ctx, DB: WriteResults + 'ctx> TaskCtx<'ctx, DB> {
             toolchain,
             krate,
             docker_env,
+            state,
             quiet,
         }
     }
@@ -127,6 +132,7 @@ impl Task {
         &self,
         ex: &Experiment,
         db: &DB,
+        state: &RunnerState,
         err: &F,
         result: TestResult,
     ) -> Fallible<()> {
@@ -137,7 +143,12 @@ impl Task {
             | TaskStep::CheckOnly { ref tc, .. }
             | TaskStep::Rustdoc { ref tc, .. }
             | TaskStep::UnstableFeatures { ref tc } => {
-                db.record_result(ex, tc, &self.krate, || {
+                let log_storage = state
+                    .lock()
+                    .prepare_logs
+                    .get(&self.krate)
+                    .map(|s| s.duplicate());
+                db.record_result(ex, tc, &self.krate, log_storage, || {
                     error!("this task or one of its parent failed!");
                     utils::report_failure(err);
                     Ok(result)
@@ -154,36 +165,46 @@ impl Task {
         ex: &Experiment,
         db: &DB,
         docker_env: &DockerEnv,
+        state: &RunnerState,
     ) -> Fallible<()> {
         match self.step {
             TaskStep::Cleanup => {
                 // Ensure source directories are cleaned up
                 for tc in &ex.toolchains {
                     let _ = utils::fs::remove_dir_all(&dirs::crate_source_dir(ex, tc, &self.krate));
                 }
+                // Remove stored logs
+                state.lock().prepare_logs.remove(&self.krate);
             }
             TaskStep::Prepare => {
-                let prepare = PrepareCrate::new(ex, &self.krate, config, db);
-                prepare.prepare()?;
+                let storage = LogStorage::new(LevelFilter::Info);
+                state
+                    .lock()
+                    .prepare_logs
+                    .insert(self.krate.clone(), storage.clone());
+                logs::capture(&storage, || {
+                    let prepare = PrepareCrate::new(ex, &self.krate, config, db);
+                    prepare.prepare()
+                })?;
             }
             TaskStep::BuildAndTest { ref tc, quiet } => {
-                let ctx = TaskCtx::new(config, db, ex, tc, &self.krate, docker_env, quiet);
+                let ctx = TaskCtx::new(config, db, ex, tc, &self.krate, docker_env, state, quiet);
                 test::run_test("testing", &ctx, test::test_build_and_test)?;
             }
             TaskStep::BuildOnly { ref tc, quiet } => {
-                let ctx = TaskCtx::new(config, db, ex, tc, &self.krate, docker_env, quiet);
+                let ctx = TaskCtx::new(config, db, ex, tc, &self.krate, docker_env, state, quiet);
                 test::run_test("building", &ctx, test::test_build_only)?;
             }
             TaskStep::CheckOnly { ref tc, quiet } => {
-                let ctx = TaskCtx::new(config, db, ex, tc, &self.krate, docker_env, quiet);
+                let ctx = TaskCtx::new(config, db, ex, tc, &self.krate, docker_env, state, quiet);
                 test::run_test("checking", &ctx, test::test_check_only)?;
             }
             TaskStep::Rustdoc { ref tc, quiet } => {
-                let ctx = TaskCtx::new(config, db, ex, tc, &self.krate, docker_env, quiet);
+                let ctx = TaskCtx::new(config, db, ex, tc, &self.krate, docker_env, state, quiet);
                 test::run_test("documenting", &ctx, test::test_rustdoc)?;
             }
             TaskStep::UnstableFeatures { ref tc } => {
-                let ctx = TaskCtx::new(config, db, ex, tc, &self.krate, docker_env, false);
+                let ctx = TaskCtx::new(config, db, ex, tc, &self.krate, docker_env, state, false);
                 test::run_test(
                     "checking unstable",
                     &ctx,

src/runner/test.rs

@@ -70,8 +70,18 @@ pub(super) fn run_test<DB: WriteResults>(
         info!("skipping crate {}. existing result: {}", ctx.krate, res);
     } else {
         let source_path = crate::dirs::crate_source_dir(ctx.experiment, ctx.toolchain, ctx.krate);
-        ctx.db
-            .record_result(ctx.experiment, ctx.toolchain, ctx.krate, || {
+        let log_storage = ctx
+            .state
+            .lock()
+            .prepare_logs
+            .get(&ctx.krate)
+            .map(|s| s.duplicate());
+        ctx.db.record_result(
+            ctx.experiment,
+            ctx.toolchain,
+            ctx.krate,
+            log_storage,
+            || {
                 info!(
                     "{} {} against {} for {}",
                     action,
@@ -80,7 +90,8 @@ pub(super) fn run_test<DB: WriteResults>(
                     ctx.experiment.name
                 );
                 test_fn(ctx, &source_path)
-            })?;
+            },
+        )?;
     }
     Ok(())
 }