Switch to tracing for logging

Cargo.lock

@@ -446,19 +446,6 @@ version = "1.0.1"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "b5320ae4c3782150d900b79807611a59a99fc9a1d61d686faafc24b93fc8d7ca"
 
-[[package]]
-name = "env_logger"
-version = "0.7.1"
-source = "registry+https://github.com/rust-lang/crates.io-index"
-checksum = "44533bbbb3bb3c1fa17d9f2e4e38bbbaf8396ba82193c4cb1b6445d711445d36"
-dependencies = [
- "atty",
- "humantime",
- "log",
- "regex",
- "termcolor",
-]
-
 [[package]]
 name = "fake-simd"
 version = "0.1.2"
@@ -759,15 +746,6 @@ version = "1.0.2"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "c4a1e36c821dbe04574f602848a19f742f4fb3c98d40449f11bcad18d6b17421"
 
-[[package]]
-name = "humantime"
-version = "1.3.0"
-source = "registry+https://github.com/rust-lang/crates.io-index"
-checksum = "df004cfca50ef23c36850aaaa59ad52cc70d0e90243c3c7737a4dd32dc7a3c4f"
-dependencies = [
- "quick-error",
-]
-
 [[package]]
 name = "hyper"
 version = "0.14.16"
@@ -1328,12 +1306,6 @@ dependencies = [
  "unicase",
 ]
 
-[[package]]
-name = "quick-error"
-version = "1.2.3"
-source = "registry+https://github.com/rust-lang/crates.io-index"
-checksum = "a1d01941d82fa2ab50be1e79e6714289dd7cde78eba4c074bc5a4374f650dfe0"
-
 [[package]]
 name = "quote"
 version = "1.0.10"
@@ -1613,6 +1585,15 @@ dependencies = [
  "digest 0.10.0",
 ]
 
+[[package]]
+name = "sharded-slab"
+version = "0.1.4"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "900fba806f70c630b0a382d0d825e17a0f19fcd059a2ade1ff237bcddf446b31"
+dependencies = [
+ "lazy_static",
+]
+
 [[package]]
 name = "shell-words"
 version = "1.0.0"
@@ -1738,15 +1719,6 @@ dependencies = [
  "unic-segment",
 ]
 
-[[package]]
-name = "termcolor"
-version = "1.1.2"
-source = "registry+https://github.com/rust-lang/crates.io-index"
-checksum = "2dfed899f0eb03f32ee8c6a0aabdb8a7949659e3466561fc0adf54e26d88c5f4"
-dependencies = [
- "winapi-util",
-]
-
 [[package]]
 name = "textwrap"
 version = "0.11.0"
@@ -1909,9 +1881,21 @@ checksum = "375a639232caf30edfc78e8d89b2d4c375515393e7af7e16f01cd96917fb2105"
 dependencies = [
  "cfg-if",
  "pin-project-lite",
+ "tracing-attributes",
  "tracing-core",
 ]
 
+[[package]]
+name = "tracing-attributes"
+version = "0.1.18"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "f4f480b8f81512e825f337ad51e94c1eb5d3bbdf2b363dcd01e2b19a9ffe3f8e"
+dependencies = [
+ "proc-macro2",
+ "quote",
+ "syn",
+]
+
 [[package]]
 name = "tracing-core"
 version = "0.1.21"
@@ -1921,6 +1905,31 @@ dependencies = [
  "lazy_static",
 ]
 
+[[package]]
+name = "tracing-log"
+version = "0.1.2"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "a6923477a48e41c1951f1999ef8bb5a3023eb723ceadafe78ffb65dc366761e3"
+dependencies = [
+ "lazy_static",
+ "log",
+ "tracing-core",
+]
+
+[[package]]
+name = "tracing-subscriber"
+version = "0.3.3"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "245da694cc7fc4729f3f418b304cb57789f1bed2a78c575407ab8a23f53cb4d3"
+dependencies = [
+ "ansi_term",
+ "sharded-slab",
+ "smallvec",
+ "thread_local",
+ "tracing-core",
+ "tracing-log",
+]
+
 [[package]]
 name = "triagebot"
 version = "0.1.0"
@@ -1931,13 +1940,11 @@ dependencies = [
  "comrak",
  "cynic",
  "dotenv",
- "env_logger",
  "futures",
  "glob",
  "hex",
  "hyper",
  "lazy_static",
- "log",
  "native-tls",
  "octocrab",
  "once_cell",
@@ -1955,6 +1962,8 @@ dependencies = [
  "tokio",
  "tokio-postgres",
  "toml",
+ "tracing",
+ "tracing-subscriber",
  "url",
  "uuid",
 ]

Cargo.toml

@@ -13,10 +13,8 @@ dotenv = "0.15"
 reqwest = { version = "0.11.4", features = ["json", "blocking"] }
 regex = "1"
 lazy_static = "1"
-log = "0.4"
 anyhow = "1"
 hex = "0.4"
-env_logger = "0.7"
 parser = { path = "parser" }
 rust_team_data = { git = "https://github.com/rust-lang/team" }
 glob = "0.3.0"
@@ -26,6 +24,8 @@ tokio = { version = "1.7.1", features = ["macros", "time", "rt"] }
 futures = { version = "0.3", default-features = false, features = ["std"] }
 async-trait = "0.1.31"
 uuid = { version = "0.8", features = ["v4"] }
+tracing = "0.1"
+tracing-subscriber = "0.3"
 url = "2.1.0"
 once_cell = "1"
 chrono = { version = "0.4", features = ["serde"] }

src/bin/lang.rs

@@ -1,9 +1,9 @@
-use triagebot::{agenda, logger};
+use triagebot::agenda;
 
 #[tokio::main(flavor = "current_thread")]
 async fn main() {
     dotenv::dotenv().ok();
-    logger::init();
+    tracing_subscriber::fmt::init();
 
     let args: Vec<String> = std::env::args().collect();
     if args.len() == 2 {

src/bin/prioritization-agenda.rs

@@ -1,9 +1,9 @@
-use triagebot::{agenda, logger};
+use triagebot::agenda;
 
 #[tokio::main(flavor = "current_thread")]
 async fn main() {
     dotenv::dotenv().ok();
-    logger::init();
+    tracing_subscriber::fmt::init();
 
     let agenda = agenda::prioritization();
 

src/config.rs

@@ -4,6 +4,7 @@ use std::collections::{HashMap, HashSet};
 use std::fmt;
 use std::sync::{Arc, RwLock};
 use std::time::{Duration, Instant};
+use tracing as log;
 
 static CONFIG_FILE_NAME: &str = "triagebot.toml";
 const REFRESH_EVERY: Duration = Duration::from_secs(2 * 60); // Every two minutes

src/db/notifications.rs

@@ -1,6 +1,7 @@
 use anyhow::Context as _;
 use chrono::{DateTime, FixedOffset};
 use tokio_postgres::Client as DbClient;
+use tracing as log;
 
 pub struct Notification {
     pub user_id: i64,

src/github.rs

@@ -1,4 +1,5 @@
 use anyhow::Context;
+use tracing as log;
 
 use async_trait::async_trait;
 use chrono::{DateTime, FixedOffset, Utc};

src/handlers.rs

@@ -4,6 +4,7 @@ use octocrab::Octocrab;
 use parser::command::{Command, Input};
 use std::fmt;
 use std::sync::Arc;
+use tracing as log;
 
 #[derive(Debug)]
 pub enum HandlerError {

src/handlers/assign.rs

@@ -19,6 +19,7 @@ use crate::{
 };
 use anyhow::Context as _;
 use parser::command::assign::AssignCommand;
+use tracing as log;
 
 #[derive(Debug, PartialEq, Eq, serde::Serialize, serde::Deserialize)]
 struct AssignData {

src/handlers/autolabel.rs

@@ -3,6 +3,8 @@ use crate::{
     github::{IssuesAction, IssuesEvent, Label},
     handlers::Context,
 };
+use tracing as log;
+
 pub(super) struct AutolabelInput {
     labels: Vec<Label>,
 }

src/handlers/github_releases.rs

@@ -7,6 +7,7 @@ use crate::{
 use anyhow::Context as _;
 use octocrab::Page;
 use std::{collections::HashMap, time::Duration};
+use tracing as log;
 
 pub(super) async fn handle(
     ctx: &Context,

src/handlers/glacier.rs

@@ -1,11 +1,11 @@
 //! Allows team members to directly create a glacier PR with the code provided.
 
 use crate::{config::GlacierConfig, github::Event, handlers::Context};
-
 use models::repos::Object;
 use octocrab::models;
 use octocrab::params::repos::Reference;
 use parser::command::glacier::GlacierCommand;
+use tracing as log;
 
 pub(super) async fn handle_command(
     ctx: &Context,

src/handlers/major_change.rs

@@ -6,6 +6,7 @@ use crate::{
 };
 use anyhow::Context as _;
 use parser::command::second::SecondCommand;
+use tracing as log;
 
 #[derive(Clone, PartialEq, Eq, Debug)]
 pub enum Invocation {

src/handlers/milestone_prs.rs

@@ -4,6 +4,7 @@ use crate::{
 };
 use anyhow::Context as _;
 use reqwest::StatusCode;
+use tracing as log;
 
 pub async fn handle(ctx: &Context, event: &Event) -> anyhow::Result<()> {
     let e = if let Event::Issue(e) = event {

src/handlers/notification.rs

@@ -12,6 +12,7 @@ use crate::{
 use anyhow::Context as _;
 use std::collections::HashSet;
 use std::convert::{TryFrom, TryInto};
+use tracing as log;
 
 pub async fn handle(ctx: &Context, event: &Event) -> anyhow::Result<()> {
     let body = match event.comment_body() {

src/handlers/notify_zulip.rs

@@ -3,6 +3,7 @@ use crate::{
     github::{Issue, IssuesAction, IssuesEvent, Label},
     handlers::Context,
 };
+use tracing as log;
 
 pub(super) struct NotifyZulipInput {
     notification_type: NotificationType,

src/handlers/rustc_commits.rs

@@ -4,6 +4,7 @@ use crate::{
     handlers::Context,
 };
 use std::convert::TryInto;
+use tracing as log;
 
 const BORS_GH_ID: i64 = 3372342;
 

src/lib.rs

@@ -7,6 +7,7 @@ use anyhow::Context;
 use handlers::HandlerError;
 use interactions::ErrorComment;
 use std::fmt;
+use tracing as log;
 
 pub mod actions;
 pub mod agenda;
@@ -16,7 +17,6 @@ pub mod db;
 pub mod github;
 pub mod handlers;
 pub mod interactions;
-pub mod logger;
 pub mod notification_listing;
 pub mod payload;
 pub mod team;

src/logger.rs

@@ -1,77 +0,0 @@
-use log::Record;
-use std::cell::Cell;
-use std::future::Future;
-use std::pin::Pin;
-use uuid::Uuid;
-
-thread_local! {
-    static REQUEST_ID: Cell<Option<Uuid>> = Cell::new(None);
-}
-
-fn format_record_to_buf(
-    f: &mut env_logger::fmt::Formatter,
-    record: &Record,
-) -> std::io::Result<()> {
-    use std::io::Write;
-    let rid = REQUEST_ID.with(|rid| {
-        if let Some(uuid) = rid.get() {
-            format!(" request_id={}", uuid)
-        } else {
-            String::from("")
-        }
-    });
-    writeln!(
-        f,
-        "[{time} {level:<5} {module_path} {file}:{line}]{request_id} {record}",
-        time = f.timestamp_millis(),
-        request_id = rid,
-        level = record.level(),
-        module_path = record.module_path().unwrap_or(""),
-        file = record.file().unwrap_or("???"),
-        line = record.line().map(|l| l as i64).unwrap_or(-1),
-        record = record.args(),
-    )
-}
-
-pub fn init() {
-    eprintln!("setting logger");
-    log::set_boxed_logger(Box::new(
-        env_logger::Builder::from_default_env()
-            .format(format_record_to_buf)
-            .build(),
-    ))
-    .unwrap();
-    log::set_max_level(log::LevelFilter::Trace);
-    log::trace!("initialized logging infra");
-}
-
-pub struct LogFuture<F> {
-    uuid: Uuid,
-    future: F,
-}
-
-impl<F: Future> Future for LogFuture<F> {
-    type Output = F::Output;
-    fn poll(
-        self: Pin<&mut Self>,
-        cx: &mut std::task::Context<'_>,
-    ) -> std::task::Poll<Self::Output> {
-        unsafe {
-            let self_ = self.get_unchecked_mut();
-            REQUEST_ID.with(|thread| {
-                let uuid = self_.uuid;
-                thread.set(Some(uuid));
-                let fut = Pin::new_unchecked(&mut self_.future);
-                let ret = fut.poll(cx);
-                thread.set(None);
-                ret
-            })
-        }
-    }
-}
-
-impl<F> LogFuture<F> {
-    pub fn new(uuid: Uuid, future: F) -> Self {
-        Self { uuid, future }
-    }
-}

src/main.rs

@@ -7,8 +7,9 @@ use hyper::{header, Body, Request, Response, Server, StatusCode};
 use reqwest::Client;
 use route_recognizer::Router;
 use std::{env, net::SocketAddr, sync::Arc};
-use triagebot::{db, github, handlers::Context, logger, notification_listing, payload, EventName};
-use uuid::Uuid;
+use tracing as log;
+use tracing::Instrument;
+use triagebot::{db, github, handlers::Context, notification_listing, payload, EventName};
 
 async fn serve_req(req: Request<Body>, ctx: Arc<Context>) -> Result<Response<Body>, hyper::Error> {
     log::info!("request = {:?}", req);
@@ -208,19 +209,19 @@ async fn run_server(addr: SocketAddr) -> anyhow::Result<()> {
     let svc = hyper::service::make_service_fn(move |_conn| {
         let ctx = ctx.clone();
         async move {
-            let uuid = Uuid::new_v4();
             Ok::<_, hyper::Error>(hyper::service::service_fn(move |req| {
-                logger::LogFuture::new(
-                    uuid,
-                    serve_req(req, ctx.clone()).map(move |mut resp| {
+                let uuid = uuid::Uuid::new_v4();
+                let span = tracing::span!(tracing::Level::INFO, "request", ?uuid);
+                serve_req(req, ctx.clone())
+                    .map(move |mut resp| {
                         if let Ok(resp) = &mut resp {
                             resp.headers_mut()
                                 .insert("X-Request-Id", uuid.to_string().parse().unwrap());
                         }
                         log::info!("response = {:?}", resp);
                         resp
-                    }),
-                )
+                    })
+                    .instrument(span)
             }))
         }
     });
@@ -233,7 +234,7 @@ async fn run_server(addr: SocketAddr) -> anyhow::Result<()> {
 #[tokio::main(flavor = "current_thread")]
 async fn main() {
     dotenv::dotenv().ok();
-    logger::init();
+    tracing_subscriber::fmt::init();
 
     let port = env::var("PORT")
         .ok()

src/payload.rs

@@ -17,7 +17,7 @@ pub fn assert_signed(signature: &str, payload: &[u8]) -> Result<(), SignedPayloa
     let signature = match hex::decode(&signature) {
         Ok(e) => e,
         Err(e) => {
-            log::trace!("hex decode failed for {:?}: {:?}", signature, e);
+            tracing::trace!("hex decode failed for {:?}: {:?}", signature, e);
             return Err(SignedPayloadError);
         }
     };

src/zulip.rs

@@ -6,6 +6,7 @@ use anyhow::Context as _;
 use std::convert::TryInto;
 use std::env;
 use std::fmt::Write as _;
+use tracing as log;
 
 #[derive(Debug, serde::Deserialize)]
 pub struct Request {