Auto merge of #379 - pietroalbini:logs, r=pietroalbini

Refactor log handling

This PR refactors log handling to use the `log` and `env_logger` crates instead of `slog`. They provide more compatibility with the rest of the ecosystem, and they're more flexible to work with.

The refactor also prepends the logs generated during the prepare step to a crate's build log, so it's easier to investigate failures in that step.

Author: bors

Cargo.lock

@@ -49,9 +49,6 @@ serde = "1.0"
 serde_derive = "1.0"
 serde_json = "1.0"
 serde_regex = "0.3.0"
-slog = "2.4.1"
-slog-scope = "4"
-slog-term = "2"
 structopt = "0.2"
 structopt-derive = "0.2"
 tar = "0.4.0"
@@ -64,6 +61,8 @@ url = "1.1"
 walkdir = "2"
 warp = "0.1.9"
 winapi = "0.3"
+log = "0.4.6"
+env_logger = "0.6.0"
 
 [dev-dependencies]
 assert_cmd = "0.10.1"

Cargo.toml

@@ -1,11 +1,11 @@
 use crate::agent::api::AgentApi;
 use crate::crates::{Crate, GitHubRepo};
 use crate::experiments::Experiment;
-use crate::log;
+use crate::logs::{self, LogStorage};
 use crate::prelude::*;
 use crate::results::{TestResult, WriteResults};
 use crate::toolchain::Toolchain;
-use std::io::Read;
+use log::LevelFilter;
 use std::ops::DerefMut;
 use std::sync::{Arc, Mutex};
 
@@ -48,22 +48,21 @@ 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 mut log_file = ::tempfile::NamedTempFile::new()?;
-        let result = log::redirect(log_file.path(), f)?;
-
-        let mut buffer = Vec::new();
-        log_file.read_to_end(&mut buffer)?;
+        let storage = existing_logs.unwrap_or_else(|| LogStorage::new(LevelFilter::Info));
+        let result = logs::capture(&storage, f)?;
+        let output = storage.to_string();
 
         let shas = ::std::mem::replace(self.shas.lock().unwrap().deref_mut(), Vec::new());
 
         info!("sending results to the crater server...");
         self.api
-            .record_progress(krate, toolchain, &buffer, result, &shas)?;
+            .record_progress(krate, toolchain, output.as_bytes(), result, &shas)?;
 
         Ok(result)
     }

src/agent/results.rs

@@ -7,6 +7,7 @@ use r2d2_sqlite::SqliteConnectionManager;
 use rusqlite::types::ToSql;
 use rusqlite::{Connection, Row, Transaction};
 use std::sync::Arc;
+use std::time::Instant;
 use tempfile::NamedTempFile;
 
 static LEGACY_DATABASE_PATHS: &[&str] = &["server.db"];
@@ -50,6 +51,7 @@ impl Database {
         }
 
         let path = WORK_DIR.join(DATABASE_PATH);
+        std::fs::create_dir_all(&*WORK_DIR)?;
         Database::new(SqliteConnectionManager::file(path), None)
     }
 
@@ -118,16 +120,20 @@ pub trait QueryUtils {
 
     fn exists(&self, sql: &str, params: &[&ToSql]) -> Fallible<bool> {
         self.with_conn(|conn| {
-            let mut prepared = conn.prepare(sql)?;
-            Ok(prepared.exists(params)?)
+            self.trace(sql, || {
+                let mut prepared = conn.prepare(sql)?;
+                Ok(prepared.exists(params)?)
+            })
         })
     }
 
     fn execute(&self, sql: &str, params: &[&ToSql]) -> Fallible<usize> {
         self.with_conn(|conn| {
-            let mut prepared = conn.prepare(sql)?;
-            let changes = prepared.execute(params)?;
-            Ok(changes)
+            self.trace(sql, || {
+                let mut prepared = conn.prepare(sql)?;
+                let changes = prepared.execute(params)?;
+                Ok(changes)
+            })
         })
     }
 
@@ -138,14 +144,16 @@ pub trait QueryUtils {
         func: F,
     ) -> Fallible<Option<T>> {
         self.with_conn(|conn| {
-            let mut prepared = conn.prepare(sql)?;
-            let mut iter = prepared.query_map(params, func)?;
-
-            if let Some(item) = iter.next() {
-                Ok(Some(item?))
-            } else {
-                Ok(None)
-            }
+            self.trace(sql, || {
+                let mut prepared = conn.prepare(sql)?;
+                let mut iter = prepared.query_map(params, func)?;
+
+                if let Some(item) = iter.next() {
+                    Ok(Some(item?))
+                } else {
+                    Ok(None)
+                }
+            })
         })
     }
 
@@ -156,17 +164,26 @@ pub trait QueryUtils {
         func: F,
     ) -> Fallible<Vec<T>> {
         self.with_conn(|conn| {
-            let mut prepared = conn.prepare(sql)?;
-            let rows = prepared.query_map(params, func)?;
+            self.trace(sql, || {
+                let mut prepared = conn.prepare(sql)?;
+                let rows = prepared.query_map(params, func)?;
 
-            let mut results = Vec::new();
-            for row in rows {
-                results.push(row?);
-            }
+                let mut results = Vec::new();
+                for row in rows {
+                    results.push(row?);
+                }
 
-            Ok(results)
+                Ok(results)
+            })
         })
     }
+
+    fn trace<T, F: FnOnce() -> T>(&self, sql: &str, f: F) -> T {
+        let start = Instant::now();
+        let res = f();
+        trace!("sql query \"{}\" executed in {:?}", sql, start.elapsed());
+        res
+    }
 }
 
 impl QueryUtils for Database {

src/db/mod.rs

@@ -1,18 +1,13 @@
 #![recursion_limit = "256"]
 #![allow(clippy::needless_pass_by_value, clippy::new_ret_no_self)]
 
-#[macro_use(slog_o, slog_info, slog_error, slog_warn)]
-extern crate slog;
-#[macro_use]
-extern crate slog_scope;
 #[cfg_attr(test, macro_use)]
 extern crate toml;
 
 pub mod actions;
 pub mod agent;
 mod assets;
-#[macro_use]
-pub mod log;
+pub mod logs;
 #[macro_use]
 pub mod utils;
 pub mod config;

src/lib.rs

@@ -0,0 +1,102 @@
+mod storage;
+
+use crate::prelude::*;
+use log::{Log, Metadata, Record};
+use std::cell::RefCell;
+use std::sync::Once;
+use std::thread::LocalKey;
+
+pub use self::storage::LogStorage;
+
+static INIT_LOGS: Once = Once::new();
+
+thread_local! {
+    static SCOPED: RefCell<Vec<Box<Log>>> = RefCell::new(Vec::new());
+}
+
+struct MultiLogger {
+    global: Vec<Box<Log>>,
+    scoped: &'static LocalKey<RefCell<Vec<Box<Log>>>>,
+}
+
+impl MultiLogger {
+    fn new(global: Vec<Box<Log>>, scoped: &'static LocalKey<RefCell<Vec<Box<Log>>>>) -> Self {
+        MultiLogger { global, scoped }
+    }
+
+    fn each<F: FnMut(&Log)>(&self, mut f: F) {
+        for logger in &self.global {
+            f(logger.as_ref());
+        }
+        self.scoped.with(|scoped| {
+            for logger in &*scoped.borrow() {
+                f(logger.as_ref());
+            }
+        });
+    }
+}
+
+impl Log for MultiLogger {
+    fn enabled(&self, metadata: &Metadata) -> bool {
+        let mut result = false;
+        self.each(|logger| {
+            if logger.enabled(metadata) {
+                result = true;
+            }
+        });
+        result
+    }
+
+    fn log(&self, record: &Record) {
+        self.each(|logger| {
+            logger.log(record);
+        });
+    }
+
+    fn flush(&self) {
+        self.each(|logger| {
+            logger.flush();
+        });
+    }
+}
+
+pub fn capture<F, R, L>(storage: &L, f: F) -> Fallible<R>
+where
+    F: FnOnce() -> Fallible<R>,
+    L: Log + Clone + 'static,
+{
+    let storage = Box::new(storage.clone());
+    SCOPED.with(|scoped| scoped.borrow_mut().push(storage));
+    let result = f();
+    SCOPED.with(|scoped| {
+        let _ = scoped.borrow_mut().pop();
+    });
+    result
+}
+
+pub fn init() {
+    INIT_LOGS.call_once(|| {
+        // Initialize env_logger
+        // This doesn't use from_default_env() because it doesn't allow to override filter_module()
+        // with the RUST_LOG environment variable
+        let mut env = env_logger::Builder::new();
+        env.filter_module("crater", log::LevelFilter::Info);
+        if let Ok(content) = std::env::var("RUST_LOG") {
+            env.parse(&content);
+        }
+
+        let multi = MultiLogger::new(vec![Box::new(env.build())], &SCOPED);
+        log::set_boxed_logger(Box::new(multi)).unwrap();
+        log::set_max_level(log::LevelFilter::Trace);
+    });
+}
+
+#[cfg(test)]
+pub(crate) fn init_test() {
+    INIT_LOGS.call_once(|| {
+        // Avoid setting up ENV_LOGGER inside tests
+        let multi = MultiLogger::new(vec![], &SCOPED);
+        log::set_boxed_logger(Box::new(multi)).unwrap();
+        log::set_max_level(log::LevelFilter::Trace);
+    })
+}