Switch to tracing for logging

Cargo.toml

@@ -11,15 +11,13 @@ atomicwrites = "0.2"
 bincode = "1.0"
 brotli = "1.2"
 digest = "0.7"
-env_logger = "0.5"
 failure = "0.1"
 futures = "0.1"
 fnv = "1.0"
 hex = "0.3"
 hmac = "0.6"
 hyper = "0.12"
 lazy_static = "1.0"
-log = "0.4"
 regex = "0.2"
 reqwest = "0.9"
 serde = "1.0"
@@ -32,3 +30,5 @@ dotenv = "0.14"
 crossbeam = "0.7"
 percent-encoding = "2.1.0"
 threadpool = "1.8.1"
+tracing = "0.1.16"
+tracing-subscriber = "0.2.8"

src/bin/offline/extract.rs

@@ -1,7 +1,6 @@
 use crate::offline;
 use crate::rla;
 
-use log;
 use std::fs;
 use std::io::{self, Write};
 use std::path::Path;
@@ -61,19 +60,20 @@ pub fn dir(
 
         let now = Instant::now();
 
-        let level = if now - last_print >= progress_every {
+        if now - last_print >= progress_every {
             last_print = now;
-            log::Level::Debug
+            debug!(
+                "Extracting errors from {} [{}/?]...",
+                entry.path().display(),
+                count
+            );
         } else {
-            log::Level::Trace
-        };
-
-        log!(
-            level,
-            "Extracting errors from {} [{}/?]...",
-            entry.path().display(),
-            count
-        );
+            trace!(
+                "Extracting errors from {} [{}/?]...",
+                entry.path().display(),
+                count
+            );
+        }
 
         let log = offline::fs::load_maybe_compressed(entry.path())?;
         let lines = load_lines(ci, &log);

src/bin/offline/learn.rs

@@ -1,7 +1,6 @@
 use crate::offline;
 use crate::rla;
 
-use log;
 use std::path::{Path, PathBuf};
 use std::time::Duration;
 use std::time::Instant;
@@ -30,19 +29,12 @@ pub fn learn(
 
         let now = Instant::now();
 
-        let level = if now - last_print >= progress_every {
+        if now - last_print >= progress_every {
             last_print = now;
-            log::Level::Debug
+            debug!("Learning from {} [{}/?]...", input.path().display(), count);
         } else {
-            log::Level::Trace
-        };
-
-        log!(
-            level,
-            "Learning from {} [{}/?]...",
-            input.path().display(),
-            count
-        );
+            trace!("Learning from {} [{}/?]...", input.path().display(), count);
+        }
 
         let data = offline::fs::load_maybe_compressed(input.path())?;
 

src/bin/rla-offline.rs

@@ -6,11 +6,10 @@
 )]
 
 extern crate brotli;
-extern crate env_logger;
 #[macro_use]
 extern crate failure;
 #[macro_use]
-extern crate log;
+extern crate tracing;
 extern crate rust_log_analyzer as rla;
 extern crate walkdir;
 

src/bin/rla-server.rs

@@ -5,13 +5,12 @@
     clippy::useless_let_if_seq
 )]
 
-extern crate env_logger;
 #[macro_use]
 extern crate failure;
 extern crate futures;
 extern crate hyper;
 #[macro_use]
-extern crate log;
+extern crate tracing;
 extern crate crossbeam;
 extern crate regex;
 extern crate rust_log_analyzer as rla;

src/bin/server/mod.rs

@@ -6,7 +6,12 @@ pub use self::worker::Worker;
 mod service;
 mod worker;
 
-pub enum QueueItem {
+pub struct QueueItem {
+    pub kind: QueueItemKind,
+    pub delivery_id: String,
+}
+
+pub enum QueueItemKind {
     GitHubStatus(rla::github::CommitStatusEvent),
     GitHubCheckRun(rla::github::CheckRunEvent),
 }

src/bin/server/service.rs

@@ -1,4 +1,4 @@
-use super::QueueItem;
+use super::{QueueItem, QueueItemKind};
 
 use crate::rla;
 use futures::{future, Future, Stream};
@@ -68,7 +68,17 @@ impl RlaService {
             }
         };
 
-        match event {
+        let delivery_header = headers
+            .get("X-GitHub-Delivery")
+            .and_then(|s| s.to_str().ok())
+            .map(|s| s.to_string());
+        let delivery_id = if let Some(id) = delivery_header {
+            id
+        } else {
+            return reply(StatusCode::BAD_REQUEST, "Missing delivery ID.\n");
+        };
+
+        let item_kind = match event {
             "status" => {
                 let payload = match serde_json::from_slice(body) {
                     Ok(p) => p,
@@ -77,17 +87,7 @@ impl RlaService {
                         return reply(StatusCode::BAD_REQUEST, "Failed to decode payload.\n");
                     }
                 };
-
-                match self.queue.send(QueueItem::GitHubStatus(payload)) {
-                    Ok(()) => reply(StatusCode::OK, "Event processed.\n"),
-                    Err(e) => {
-                        error!("Failed to queue payload: {}", e);
-                        reply(
-                            StatusCode::INTERNAL_SERVER_ERROR,
-                            "Failed to process the event.\n",
-                        )
-                    }
-                }
+                QueueItemKind::GitHubStatus(payload)
             }
             "check_run" => {
                 let payload = match serde_json::from_slice(body) {
@@ -98,24 +98,30 @@ impl RlaService {
                     }
                 };
 
-                match self.queue.send(QueueItem::GitHubCheckRun(payload)) {
-                    Ok(()) => reply(StatusCode::OK, "Event processed.\n"),
-                    Err(e) => {
-                        error!("Failed to queue payload: {}", e);
-                        reply(
-                            StatusCode::INTERNAL_SERVER_ERROR,
-                            "Failed to process the event.\n",
-                        )
-                    }
-                }
+                QueueItemKind::GitHubCheckRun(payload)
             }
             "issue_comment" => {
                 debug!("Ignoring 'issue_comment' event.");
-                reply(StatusCode::OK, "Event ignored.\n")
+                return reply(StatusCode::OK, "Event ignored.\n");
             }
             _ => {
                 warn!("Unexpected '{}' event.", event);
-                reply(StatusCode::BAD_REQUEST, "Unexpected event.\n")
+                return reply(StatusCode::BAD_REQUEST, "Unexpected event.\n");
+            }
+        };
+
+        let item = QueueItem {
+            kind: item_kind,
+            delivery_id,
+        };
+        match self.queue.send(item) {
+            Ok(()) => reply(StatusCode::OK, "Event processed.\n"),
+            Err(e) => {
+                error!("Failed to queue payload: {}", e);
+                reply(
+                    StatusCode::INTERNAL_SERVER_ERROR,
+                    "Failed to process the event.\n",
+                )
             }
         }
     }

src/bin/server/worker.rs

@@ -1,4 +1,4 @@
-use super::QueueItem;
+use super::{QueueItem, QueueItemKind};
 
 use crate::rla;
 use crate::rla::ci::{self, BuildCommit, CiPlatform};
@@ -78,7 +78,16 @@ impl Worker {
     pub fn main(&mut self) -> rla::Result<()> {
         loop {
             let item = self.queue.recv()?;
-            match self.process(item) {
+
+            let span = span!(
+                tracing::Level::INFO,
+                "request",
+                delivery = item.delivery_id.as_str(),
+                build_id = tracing::field::Empty
+            );
+            let _enter = span.enter();
+
+            match self.process(item, &span) {
                 Ok(()) => (),
                 Err(e) => error!("Processing queue item failed: {}", e),
             }
@@ -92,9 +101,9 @@ impl Worker {
         self.secondary_repos.iter().find(|r| *r == repo).is_some()
     }
 
-    fn process(&mut self, item: QueueItem) -> rla::Result<()> {
-        let (repo, build_id, outcome) = match &item {
-            QueueItem::GitHubStatus(ev) => match self.ci.build_id_from_github_status(&ev) {
+    fn process(&mut self, item: QueueItem, span: &tracing::Span) -> rla::Result<()> {
+        let (repo, build_id, outcome) = match &item.kind {
+            QueueItemKind::GitHubStatus(ev) => match self.ci.build_id_from_github_status(&ev) {
                 Some(id) if self.is_repo_valid(&ev.repository.full_name) => {
                     (&ev.repository.full_name, id, None)
                 }
@@ -106,7 +115,7 @@ impl Worker {
                     return Ok(());
                 }
             },
-            QueueItem::GitHubCheckRun(ev) => match self.ci.build_id_from_github_check(&ev) {
+            QueueItemKind::GitHubCheckRun(ev) => match self.ci.build_id_from_github_check(&ev) {
                 Some(id) if self.is_repo_valid(&ev.repository.full_name) => {
                     (&ev.repository.full_name, id, Some(&ev.check_run.outcome))
                 }
@@ -120,10 +129,12 @@ impl Worker {
             },
         };
 
-        info!("build {}: started processing", build_id);
+        span.record("build_id", &build_id);
+
+        info!("started processing");
 
         if self.seen.contains(&build_id) {
-            info!("build {}: ignoring recently seen id", build_id);
+            info!("ignoring recently seen id");
             return Ok(());
         }
         let query_from = if self.query_builds_from_primary_repo {
@@ -138,34 +149,31 @@ impl Worker {
             _ => build.outcome(),
         };
 
-        debug!("build {}: current outcome: {:?}", build_id, outcome);
-        debug!("build {}: PR number: {:?}", build_id, build.pr_number());
-        debug!("build {}: branch name: {:?}", build_id, build.pr_number());
+        debug!("current outcome: {:?}", outcome);
+        debug!("PR number: {:?}", build.pr_number());
+        debug!("branch name: {:?}", build.branch_name());
 
         if !outcome.is_finished() {
-            info!("build {}: ignoring in-progress build", build_id);
+            info!("ignoring in-progress build");
             return Ok(());
         }
 
         // Avoid processing the same build multiple times.
-        info!("build {}: marked as seen", build_id);
+        info!("marked as seen");
         self.seen.push_front(build_id);
         if self.seen.len() > KEEP_IDS {
             self.seen.pop_back();
         }
 
         if !outcome.is_passed() {
-            info!("build {}: preparing report", build_id);
+            info!("preparing report");
             self.report_failed(build.as_ref())?;
         }
         if build.pr_number().is_none() && build.branch_name() == "auto" {
-            info!("build {}: learning from the log", build_id);
+            info!("learning from the log");
             self.learn(build.as_ref())?;
         } else {
-            info!(
-                "build {}: did not learn as it's not an auto build",
-                build_id
-            );
+            info!("did not learn as it's not an auto build");
         }
 
         Ok(())

src/bin/util/mod.rs

@@ -1,8 +1,5 @@
 use crate::rla;
-use env_logger;
 use failure::ResultExt;
-use log;
-use std::env;
 use std::process;
 
 pub(crate) enum CliCiPlatform {
@@ -40,19 +37,9 @@ impl std::str::FromStr for CliCiPlatform {
 }
 
 pub fn run<F: FnOnce() -> rla::Result<()>>(f: F) {
-    let mut log_builder = env_logger::Builder::new();
-
-    if let Ok(s) = env::var("RLA_LOG") {
-        log_builder.parse(&s);
-    } else {
-        log_builder.filter(None, log::LevelFilter::Info);
-    }
-
-    if let Ok(s) = env::var("RLA_LOG_STYLE") {
-        log_builder.parse_write_style(&s);
-    }
-
-    log_builder.init();
+    tracing_subscriber::fmt()
+        .with_env_filter(tracing_subscriber::EnvFilter::from_env("RLA_LOG"))
+        .init();
 
     log_and_exit_error(|| f());
 }

src/lib.rs

@@ -16,14 +16,14 @@ extern crate hmac;
 extern crate hyper;
 #[macro_use]
 extern crate lazy_static;
-#[macro_use]
-extern crate log;
 extern crate regex;
 extern crate reqwest;
 extern crate serde;
 #[macro_use]
 extern crate serde_derive;
 extern crate sha1;
+#[macro_use]
+extern crate tracing;
 
 pub mod ci;
 pub mod extract;