Auto merge of #381 - pietroalbini:restrict-log-size, r=pietroalbini

Restrict the amount of content allowed in build logs

This PR implements proper restrictions on the amount of data that can be stored in build logs. Instead of killing the process after it outputted too much data (like what was proposed in #160) this PR just stops recording log entries after the thresholds are reached, outputting a warning at the end. This allows us to keep testing the crates and detect possible regressions.

With the current configuration (tweakable through `cargo.toml`) logs are truncated when either of those conditions are reached:

* More than 10000 log lines
* More than 5MB of data

@Mark-Simulacrum or @aidanhs, are you OK with those values or should we tweak them?

Fixes #160

Author: bors

config.toml

@@ -29,6 +29,9 @@ local-crates = []
 [sandbox]
 # Maximum amount of RAM allowed during builds
 memory-limit = "1536M"  # 1.5G
+# Restrictions on the amount of information stored in build logs
+build-log-max-size = "5M"
+build-log-max-lines = 10000
 
 
 # These sections allows to customize how crater treats specific crates/repos

src/agent/results.rs

@@ -1,4 +1,5 @@
 use crate::agent::api::AgentApi;
+use crate::config::Config;
 use crate::crates::{Crate, GitHubRepo};
 use crate::experiments::Experiment;
 use crate::logs::{self, LogStorage};
@@ -49,12 +50,13 @@ impl<'a> WriteResults for ResultsUploader<'a> {
         toolchain: &Toolchain,
         krate: &Crate,
         existing_logs: Option<LogStorage>,
+        config: &Config,
         f: F,
     ) -> Fallible<TestResult>
     where
         F: FnOnce() -> Fallible<TestResult>,
     {
-        let storage = existing_logs.unwrap_or_else(|| LogStorage::new(LevelFilter::Info));
+        let storage = existing_logs.unwrap_or_else(|| LogStorage::new(LevelFilter::Info, config));
         let result = logs::capture(&storage, f)?;
         let output = storage.to_string();
 

src/config.rs

@@ -67,6 +67,8 @@ pub struct DemoCrates {
 #[serde(rename_all = "kebab-case")]
 pub struct SandboxConfig {
     pub memory_limit: Size,
+    pub build_log_max_size: Size,
+    pub build_log_max_lines: usize,
 }
 
 #[derive(Clone, Serialize, Deserialize)]
@@ -241,6 +243,8 @@ impl Default for Config {
             local_crates: HashMap::new(),
             sandbox: SandboxConfig {
                 memory_limit: Size::Gigabytes(2),
+                build_log_max_size: Size::Megabytes(1),
+                build_log_max_lines: 1000,
             },
             server: ServerConfig {
                 bot_acl: Vec::new(),
@@ -275,6 +279,8 @@ mod tests {
             "local-crates = []\n",
             "[sandbox]\n",
             "memory-limit = \"2G\"\n",
+            "build-log-max-size = \"2M\"\n",
+            "build-log-max-lines = 1000\n",
             "[crates]\n",
             "lazy_static = { skip = true }\n",
             "[github-repos]\n",

src/lib.rs

@@ -1,5 +1,9 @@
 #![recursion_limit = "256"]
-#![allow(clippy::needless_pass_by_value, clippy::new_ret_no_self)]
+#![allow(
+    clippy::needless_pass_by_value,
+    clippy::new_ret_no_self,
+    clippy::too_many_arguments
+)]
 
 #[cfg_attr(test, macro_use)]
 extern crate toml;

src/logs/mod.rs

@@ -1,6 +1,5 @@
 mod storage;
 
-use crate::prelude::*;
 use log::{Log, Metadata, Record};
 use std::cell::RefCell;
 use std::sync::Once;
@@ -60,9 +59,9 @@ impl Log for MultiLogger {
     }
 }
 
-pub fn capture<F, R, L>(storage: &L, f: F) -> Fallible<R>
+pub fn capture<F, R, L>(storage: &L, f: F) -> R
 where
-    F: FnOnce() -> Fallible<R>,
+    F: FnOnce() -> R,
     L: Log + Clone + 'static,
 {
     let storage = Box::new(storage.clone());

src/logs/storage.rs

@@ -1,30 +1,40 @@
+use crate::config::Config;
 use log::{Level, LevelFilter, Log, Metadata, Record};
 use std::fmt;
 use std::sync::{Arc, Mutex};
 
 #[derive(Clone)]
+#[cfg_attr(test, derive(Debug, PartialEq, Eq))]
 struct StoredRecord {
     level: Level,
     message: String,
 }
 
 struct InnerStorage {
     records: Vec<StoredRecord>,
+    size: usize,
+    truncated: bool,
 }
 
 #[derive(Clone)]
 pub struct LogStorage {
     inner: Arc<Mutex<InnerStorage>>,
     min_level: LevelFilter,
+    max_size: usize,
+    max_lines: usize,
 }
 
 impl LogStorage {
-    pub(crate) fn new(min_level: LevelFilter) -> Self {
+    pub(crate) fn new(min_level: LevelFilter, config: &Config) -> Self {
         LogStorage {
             inner: Arc::new(Mutex::new(InnerStorage {
                 records: Vec::new(),
+                truncated: false,
+                size: 0,
             })),
             min_level,
+            max_size: config.sandbox.build_log_max_size.to_bytes(),
+            max_lines: config.sandbox.build_log_max_lines,
         }
     }
 
@@ -33,8 +43,12 @@ impl LogStorage {
         LogStorage {
             inner: Arc::new(Mutex::new(InnerStorage {
                 records: inner.records.clone(),
+                truncated: inner.truncated,
+                size: inner.size,
             })),
             min_level: self.min_level,
+            max_size: self.max_size,
+            max_lines: self.max_lines,
         }
     }
 }
@@ -49,9 +63,30 @@ impl Log for LogStorage {
             return;
         }
         let mut inner = self.inner.lock().unwrap();
+        if inner.truncated {
+            return;
+        }
+        if inner.records.len() >= self.max_lines {
+            inner.records.push(StoredRecord {
+                level: Level::Warn,
+                message: "too many lines in the log, truncating it".into(),
+            });
+            inner.truncated = true;
+            return;
+        }
+        let message = record.args().to_string();
+        if inner.size + message.len() >= self.max_size {
+            inner.records.push(StoredRecord {
+                level: Level::Warn,
+                message: "too much data in the log, truncating it".into(),
+            });
+            inner.truncated = true;
+            return;
+        }
+        inner.size += message.len();
         inner.records.push(StoredRecord {
             level: record.level(),
-            message: record.args().to_string(),
+            message,
         });
     }
 
@@ -67,3 +102,89 @@ impl fmt::Display for LogStorage {
         Ok(())
     }
 }
+
+#[cfg(test)]
+mod tests {
+    use super::{LogStorage, StoredRecord};
+    use crate::config::Config;
+    use crate::logs;
+    use crate::prelude::*;
+    use crate::utils::size::Size;
+    use log::{Level, LevelFilter};
+
+    #[test]
+    fn test_log_storage() {
+        logs::init_test();
+        let config = Config::default();
+
+        let storage = LogStorage::new(LevelFilter::Info, &config);
+        logs::capture(&storage, || {
+            info!("an info record");
+            warn!("a warn record");
+            trace!("a trace record");
+        });
+
+        assert_eq!(
+            storage.inner.lock().unwrap().records,
+            vec![
+                StoredRecord {
+                    level: Level::Info,
+                    message: "an info record".to_string(),
+                },
+                StoredRecord {
+                    level: Level::Warn,
+                    message: "a warn record".to_string(),
+                },
+            ]
+        );
+    }
+
+    #[test]
+    fn test_too_much_content() {
+        logs::init_test();
+
+        let mut config = Config::default();
+        config.sandbox.build_log_max_size = Size::Kilobytes(4);
+
+        let storage = LogStorage::new(LevelFilter::Info, &config);
+        logs::capture(&storage, || {
+            let content = (0..Size::Kilobytes(8).to_bytes())
+                .map(|_| '.')
+                .collect::<String>();
+            info!("{}", content);
+        });
+
+        let inner = storage.inner.lock().unwrap();
+        assert_eq!(inner.records.len(), 1);
+        assert!(inner
+            .records
+            .last()
+            .unwrap()
+            .message
+            .contains("too much data"));
+    }
+
+    #[test]
+    fn test_too_many_lines() {
+        logs::init_test();
+
+        let mut config = Config::default();
+        config.sandbox.build_log_max_lines = 100;
+
+        let storage = LogStorage::new(LevelFilter::Info, &config);
+        logs::capture(&storage, || {
+            for _ in 0..200 {
+                info!("a line");
+            }
+        });
+
+        let inner = storage.inner.lock().unwrap();
+        assert_eq!(inner.records.len(), 101);
+        assert!(inner
+            .records
+            .last()
+            .unwrap()
+            .message
+            .contains("too many lines"));
+    }
+}

src/report/archives.rs

@@ -127,25 +127,25 @@ mod tests {
         // Fill some dummy results into the database
         let results = DatabaseDB::new(&db);
         results
-            .record_result(&ex, &ex.toolchains[0], &crate1, None, || {
+            .record_result(&ex, &ex.toolchains[0], &crate1, None, &config, || {
                 info!("tc1 crate1");
                 Ok(TestResult::TestPass)
             })
             .unwrap();
         results
-            .record_result(&ex, &ex.toolchains[1], &crate1, None, || {
+            .record_result(&ex, &ex.toolchains[1], &crate1, None, &config, || {
                 info!("tc2 crate1");
                 Ok(TestResult::BuildFail(FailureReason::Unknown))
             })
             .unwrap();
         results
-            .record_result(&ex, &ex.toolchains[0], &crate2, None, || {
+            .record_result(&ex, &ex.toolchains[0], &crate2, None, &config, || {
                 info!("tc1 crate2");
                 Ok(TestResult::TestPass)
             })
             .unwrap();
         results
-            .record_result(&ex, &ex.toolchains[1], &crate2, None, || {
+            .record_result(&ex, &ex.toolchains[1], &crate2, None, &config, || {
                 info!("tc2 crate2");
                 Ok(TestResult::TestPass)
             })

src/results/db.rs

@@ -1,3 +1,4 @@
+use crate::config::Config;
 use crate::crates::{Crate, GitHubRepo};
 use crate::db::{Database, QueryUtils};
 use crate::experiments::Experiment;
@@ -169,12 +170,13 @@ impl<'a> WriteResults for DatabaseDB<'a> {
         toolchain: &Toolchain,
         krate: &Crate,
         existing_logs: Option<LogStorage>,
+        config: &Config,
         f: F,
     ) -> Fallible<TestResult>
     where
         F: FnOnce() -> Fallible<TestResult>,
     {
-        let storage = existing_logs.unwrap_or_else(|| LogStorage::new(LevelFilter::Info));
+        let storage = existing_logs.unwrap_or_else(|| LogStorage::new(LevelFilter::Info, config));
         let result = logs::capture(&storage, f)?;
         let output = storage.to_string();
         self.store_result(ex, krate, toolchain, result, output.as_bytes())?;
@@ -299,7 +301,7 @@ mod tests {
 
         // Record a result with a message in it
         results
-            .record_result(&ex, &MAIN_TOOLCHAIN, &krate, None, || {
+            .record_result(&ex, &MAIN_TOOLCHAIN, &krate, None, &config, || {
                 info!("hello world");
                 Ok(TestResult::TestPass)
             })
@@ -336,7 +338,7 @@ mod tests {
 
         // Add another result
         results
-            .record_result(&ex, &TEST_TOOLCHAIN, &krate, None, || {
+            .record_result(&ex, &TEST_TOOLCHAIN, &krate, None, &config, || {
                 info!("Another log message!");
                 Ok(TestResult::TestFail(FailureReason::Unknown))
             })

src/results/mod.rs

@@ -2,6 +2,7 @@ mod db;
 #[cfg(test)]
 mod dummy;
 
+use crate::config::Config;
 use crate::crates::{Crate, GitHubRepo};
 use crate::experiments::Experiment;
 use crate::logs::LogStorage;
@@ -43,6 +44,7 @@ pub trait WriteResults {
         toolchain: &Toolchain,
         krate: &Crate,
         existing_logs: Option<LogStorage>,
+        config: &Config,
         f: F,
     ) -> Fallible<TestResult>
     where

src/runner/graph.rs

@@ -191,6 +191,7 @@ impl TasksGraph {
         ex: &Experiment,
         db: &DB,
         state: &RunnerState,
+        config: &Config,
         error: &F,
         result: TestResult,
     ) -> Fallible<()> {
@@ -199,11 +200,13 @@ impl TasksGraph {
             .neighbors_directed(node, Direction::Incoming)
             .collect::<Vec<_>>();
         for child in children.drain(..) {
-            self.mark_as_failed(child, ex, db, state, error, result)?;
+            self.mark_as_failed(child, ex, db, state, config, error, result)?;
         }
 
         match self.graph[node] {
-            Node::Task { ref task, .. } => task.mark_as_failed(ex, db, state, error, result)?,
+            Node::Task { ref task, .. } => {
+                task.mark_as_failed(ex, db, state, config, error, result)?
+            }
             Node::CrateCompleted | Node::Root => return Ok(()),
         }