improve logging (#62)

Cargo.lock

@@ -18,6 +18,29 @@ version = "0.4.7"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "4d25d88fd6b8041580a654f9d0c581a047baee2b3efee13275f2fc392fc75034"
 
+[[package]]
+name = "arrayref"
+version = "0.3.6"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "a4c527152e37cf757a3f78aae5a06fbeefdb07ccc535c980a3208ee3060dd544"
+
+[[package]]
+name = "arrayvec"
+version = "0.5.1"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "cff77d8686867eceff3105329d4698d96c2391c176d5d03adc90c7389162b5b8"
+
+[[package]]
+name = "atty"
+version = "0.2.14"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "d9b39be18770d11421cdb1b9947a45dd3f37e93092cbf377614828a319d5fee8"
+dependencies = [
+ "hermit-abi",
+ "libc",
+ "winapi 0.3.9",
+]
+
 [[package]]
 name = "autocfg"
 version = "1.0.1"
@@ -45,6 +68,17 @@ version = "1.2.1"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "cf1de2fe8c75bc145a2f577add951f8134889b4795d47466a54a5c846d691693"
 
+[[package]]
+name = "blake2b_simd"
+version = "0.5.10"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "d8fb2d74254a3a0b5cac33ac9f8ed0e44aa50378d9dbb2e5d83bd21ed1dc2c8a"
+dependencies = [
+ "arrayref",
+ "arrayvec",
+ "constant_time_eq",
+]
+
 [[package]]
 name = "bumpalo"
 version = "3.4.0"
@@ -107,6 +141,12 @@ dependencies = [
  "winapi 0.3.9",
 ]
 
+[[package]]
+name = "constant_time_eq"
+version = "0.1.5"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "245097e9a4535ee1e3e3931fcfcd55a796a44c643e8596ff6566d68f09b87bbc"
+
 [[package]]
 name = "core-foundation"
 version = "0.7.0"
@@ -180,6 +220,27 @@ dependencies = [
  "syn",
 ]
 
+[[package]]
+name = "dirs"
+version = "2.0.2"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "13aea89a5c93364a98e9b37b2fa237effbb694d5cfe01c5b70941f7eb087d5e3"
+dependencies = [
+ "cfg-if",
+ "dirs-sys",
+]
+
+[[package]]
+name = "dirs-sys"
+version = "0.3.5"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "8e93d7f5705de3e49895a2b5e0b8855a1c27f080192ae9c32a6432d50741a57a"
+dependencies = [
+ "libc",
+ "redox_users",
+ "winapi 0.3.9",
+]
+
 [[package]]
 name = "dtoa"
 version = "0.4.6"
@@ -995,6 +1056,17 @@ version = "0.1.57"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "41cc0f7e4d5d4544e8861606a285bb08d3e70712ccc7d2b84d7c0ccfaf4b05ce"
 
+[[package]]
+name = "redox_users"
+version = "0.3.5"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "de0737333e7a9502c789a36d7c7fa6092a49895d4faa31ca5df163857ded2e9d"
+dependencies = [
+ "getrandom",
+ "redox_syscall",
+ "rust-argon2",
+]
+
 [[package]]
 name = "relative-path"
 version = "1.3.2"
@@ -1055,6 +1127,18 @@ version = "0.2.0"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "56770675ebc04927ded3e60633437841581c285dc6236109ea25fbf3beb7b59e"
 
+[[package]]
+name = "rust-argon2"
+version = "0.8.2"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "9dab61250775933275e84053ac235621dfb739556d5c54a2f2e9313b7cf43a19"
+dependencies = [
+ "base64",
+ "blake2b_simd",
+ "constant_time_eq",
+ "crossbeam-utils",
+]
+
 [[package]]
 name = "rustsec"
 version = "0.21.0"
@@ -1245,7 +1329,8 @@ dependencies = [
  "serde",
  "serde_json",
  "slog",
- "slog-json",
+ "slog-async",
+ "slog-term",
  "tokio",
  "toml",
 ]
@@ -1273,15 +1358,28 @@ source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "1cc9c640a4adbfbcc11ffb95efe5aa7af7309e002adab54b185507dbf2377b99"
 
 [[package]]
-name = "slog-json"
-version = "2.3.0"
+name = "slog-async"
+version = "2.5.0"
 source = "registry+https://github.com/rust-lang/crates.io-index"
-checksum = "ddc0d2aff1f8f325ef660d9a0eb6e6dcd20b30b3f581a5897f58bf42d061c37a"
+checksum = "51b3336ce47ce2f96673499fc07eb85e3472727b9a7a2959964b002c2ce8fbbb"
 dependencies = [
- "chrono",
- "serde",
- "serde_json",
+ "crossbeam-channel",
  "slog",
+ "take_mut",
+ "thread_local",
+]
+
+[[package]]
+name = "slog-term"
+version = "2.6.0"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "bab1d807cf71129b05ce36914e1dbb6fbfbdecaf686301cb457f4fa967f9f5b6"
+dependencies = [
+ "atty",
+ "chrono",
+ "slog",
+ "term",
+ "thread_local",
 ]
 
 [[package]]
@@ -1316,6 +1414,12 @@ dependencies = [
  "unicode-xid",
 ]
 
+[[package]]
+name = "take_mut"
+version = "0.2.2"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "f764005d11ee5f36500a149ace24e00e3da98b0158b3e2d53a7495660d3f4d60"
+
 [[package]]
 name = "tempfile"
 version = "3.1.0"
@@ -1330,6 +1434,16 @@ dependencies = [
  "winapi 0.3.9",
 ]
 
+[[package]]
+name = "term"
+version = "0.6.1"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "c0863a3345e70f61d613eab32ee046ccd1bcc5f9105fe402c61fcd0c13eeb8b5"
+dependencies = [
+ "dirs",
+ "winapi 0.3.9",
+]
+
 [[package]]
 name = "thiserror"
 version = "1.0.20"
@@ -1350,6 +1464,15 @@ dependencies = [
  "syn",
 ]
 
+[[package]]
+name = "thread_local"
+version = "1.0.1"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "d40c6d1b69745a6ec6fb1ca717914848da4b44ae29d9b3080cbee91d72a69b14"
+dependencies = [
+ "lazy_static",
+]
+
 [[package]]
 name = "time"
 version = "0.1.44"

Cargo.toml

@@ -31,7 +31,8 @@ reqwest = { version = "0.10", features = ["json"] }
 serde = { version = "1", features = ["derive"] }
 serde_json = "1"
 slog = "2"
-slog-json = "2"
+slog-async = "2"
+slog-term = "2"
 tokio = { version = "0.2", features = ["full"] }
 toml = "0.5"
 

src/engine/fut/analyze.rs

@@ -1,8 +1,19 @@
 use anyhow::Error;
 use futures::StreamExt;
 
-use crate::models::crates::{AnalyzedDependencies, CrateDeps};
-use crate::{engine::machines::analyzer::DependencyAnalyzer, Engine};
+use crate::{
+    engine::machines::analyzer::DependencyAnalyzer,
+    models::crates::{AnalyzedDependencies, CrateDep, CrateDeps, CrateName},
+    Engine,
+};
+
+fn filter_external((name, dep): (CrateName, CrateDep)) -> Option<CrateName> {
+    if dep.is_external() {
+        Some(name)
+    } else {
+        None
+    }
+}
 
 pub async fn analyze_dependencies(
     engine: Engine,
@@ -11,36 +22,9 @@ pub async fn analyze_dependencies(
     let advisory_db = engine.fetch_advisory_db().await?;
     let mut analyzer = DependencyAnalyzer::new(&deps, Some(advisory_db));
 
-    let main_deps =
-        deps.main.into_iter().filter_map(
-            |(name, dep)| {
-                if dep.is_external() {
-                    Some(name)
-                } else {
-                    None
-                }
-            },
-        );
-    let dev_deps =
-        deps.dev.into_iter().filter_map(
-            |(name, dep)| {
-                if dep.is_external() {
-                    Some(name)
-                } else {
-                    None
-                }
-            },
-        );
-    let build_deps =
-        deps.build.into_iter().filter_map(
-            |(name, dep)| {
-                if dep.is_external() {
-                    Some(name)
-                } else {
-                    None
-                }
-            },
-        );
+    let main_deps = deps.main.into_iter().filter_map(filter_external);
+    let dev_deps = deps.dev.into_iter().filter_map(filter_external);
+    let build_deps = deps.build.into_iter().filter_map(filter_external);
 
     let deps_iter = main_deps.chain(dev_deps).chain(build_deps);
     let mut releases = engine.fetch_releases(deps_iter);

src/engine/machines/analyzer.rs

@@ -1,6 +1,9 @@
 use std::sync::Arc;
 
-use rustsec::database::{Database, Query};
+use rustsec::{
+    cargo_lock,
+    database::{self, Database},
+};
 use semver::Version;
 
 use crate::models::crates::{
@@ -35,9 +38,9 @@ impl DependencyAnalyzer {
                 dep.latest_that_matches = Some(ver.clone());
             }
 
-            let name: rustsec::cargo_lock::Name = name.as_ref().parse().unwrap();
-            let version: rustsec::cargo_lock::Version = ver.to_string().parse().unwrap();
-            let query = Query::new().package_version(name, version);
+            let name: cargo_lock::Name = name.as_ref().parse().unwrap();
+            let version: cargo_lock::Version = ver.to_string().parse().unwrap();
+            let query = database::Query::new().package_version(name, version);
 
             if !advisory_db
                 .map(|db| db.query(&query).is_empty())

src/interactors/crates.rs

@@ -1,4 +1,4 @@
-use std::{str, task::Context, task::Poll};
+use std::{fmt, str, task::Context, task::Poll};
 
 use anyhow::Error;
 use futures::FutureExt as _;
@@ -66,7 +66,7 @@ pub struct QueryCrateResponse {
     pub releases: Vec<CrateRelease>,
 }
 
-#[derive(Debug, Clone)]
+#[derive(Clone)]
 pub struct QueryCrate {
     client: reqwest::Client,
 }
@@ -105,6 +105,12 @@ impl QueryCrate {
     }
 }
 
+impl fmt::Debug for QueryCrate {
+    fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
+        f.write_str("QueryCrate")
+    }
+}
+
 impl Service<CrateName> for QueryCrate {
     type Response = QueryCrateResponse;
     type Error = Error;
@@ -145,7 +151,7 @@ fn convert_summary(response: SummaryResponse) -> Result<Vec<CratePath>, Error> {
         .collect()
 }
 
-#[derive(Debug, Clone, Default)]
+#[derive(Clone, Default)]
 pub struct GetPopularCrates {
     client: reqwest::Client,
 }
@@ -164,6 +170,11 @@ impl GetPopularCrates {
     }
 }
 
+impl fmt::Debug for GetPopularCrates {
+    fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
+        f.write_str("GetPopularCrates")
+    }
+}
 impl Service<()> for GetPopularCrates {
     type Response = Vec<CratePath>;
     type Error = Error;

src/interactors/github.rs

@@ -1,4 +1,7 @@
-use std::task::{Context, Poll};
+use std::{
+    fmt,
+    task::{Context, Poll},
+};
 
 use anyhow::Error;
 
@@ -30,7 +33,7 @@ struct GithubOwner {
     login: String,
 }
 
-#[derive(Debug, Clone)]
+#[derive(Clone)]
 pub struct GetPopularRepos {
     client: reqwest::Client,
 }
@@ -64,6 +67,12 @@ impl GetPopularRepos {
     }
 }
 
+impl fmt::Debug for GetPopularRepos {
+    fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
+        f.write_str("GetPopularRepos")
+    }
+}
+
 impl Service<()> for GetPopularRepos {
     type Response = Vec<Repository>;
     type Error = Error;

src/interactors/mod.rs

@@ -1,4 +1,7 @@
-use std::task::{Context, Poll};
+use std::{
+    fmt,
+    task::{Context, Poll},
+};
 
 use anyhow::{anyhow, Error};
 use futures::FutureExt as _;
@@ -11,7 +14,7 @@ pub mod crates;
 pub mod github;
 pub mod rustsec;
 
-#[derive(Debug, Clone)]
+#[derive(Clone)]
 pub struct RetrieveFileAtPath {
     client: reqwest::Client,
 }
@@ -51,3 +54,9 @@ impl Service<(RepoPath, RelativePathBuf)> for RetrieveFileAtPath {
         Self::query(client, repo_path, path).boxed()
     }
 }
+
+impl fmt::Debug for RetrieveFileAtPath {
+    fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
+        f.write_str("RetrieveFileAtPath")
+    }
+}

src/interactors/rustsec.rs

@@ -1,4 +1,4 @@
-use std::{sync::Arc, task::Context, task::Poll};
+use std::{fmt, sync::Arc, task::Context, task::Poll};
 
 use anyhow::Error;
 use futures::FutureExt as _;
@@ -7,7 +7,7 @@ use rustsec::database::Database;
 
 use crate::BoxFuture;
 
-#[derive(Debug, Clone)]
+#[derive(Clone)]
 pub struct FetchAdvisoryDatabase {
     client: reqwest::Client,
 }
@@ -37,3 +37,9 @@ impl Service<()> for FetchAdvisoryDatabase {
         Self::fetch(client).boxed()
     }
 }
+
+impl fmt::Debug for FetchAdvisoryDatabase {
+    fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
+        f.write_str("FetchAdvisoryDatabase")
+    }
+}

src/main.rs

@@ -6,7 +6,6 @@ use std::{
     future::Future,
     net::{IpAddr, Ipv4Addr, SocketAddr, UdpSocket},
     pin::Pin,
-    sync::Mutex,
     time::Duration,
 };
 
@@ -18,7 +17,7 @@ use hyper::{
 };
 
 use reqwest::redirect::Policy as RedirectPolicy;
-use slog::{o, Drain};
+use slog::{error, info, o, Drain, Logger};
 
 mod engine;
 mod interactors;
@@ -43,12 +42,17 @@ fn init_metrics() -> QueuingMetricSink {
     QueuingMetricSink::from(sink)
 }
 
+fn init_root_logger() -> Logger {
+    let decorator = slog_term::TermDecorator::new().build();
+    let drain = slog_term::FullFormat::new(decorator).build().fuse();
+    let drain = slog_async::Async::new(drain).build().fuse();
+
+    Logger::root(drain, o!())
+}
+
 #[tokio::main]
 async fn main() {
-    let logger = slog::Logger::root(
-        Mutex::new(slog_json::Json::default(std::io::stderr())).map(slog::Fuse),
-        o!("version" => env!("CARGO_PKG_VERSION")),
-    );
+    let logger = init_root_logger();
 
     let metrics = init_metrics();
 
@@ -66,12 +70,13 @@ async fn main() {
 
     let addr = SocketAddr::new(IpAddr::V4(Ipv4Addr::UNSPECIFIED), port);
 
-    let mut engine = Engine::new(client.clone(), logger.clone());
+    let mut engine = Engine::new(client.clone(), logger.new(o!()));
     engine.set_metrics(metrics);
 
+    let svc_logger = logger.new(o!());
     let make_svc = make_service_fn(move |_socket: &AddrStream| {
-        let logger = logger.clone();
         let engine = engine.clone();
+        let logger = svc_logger.clone();
 
         async move {
             let server = App::new(logger.clone(), engine.clone());
@@ -83,9 +88,9 @@ async fn main() {
     });
     let server = Server::bind(&addr).serve(make_svc);
 
-    println!("Server running on port {}", port);
+    info!(logger, "Server running on port {}", port);
 
     if let Err(e) = server.await {
-        eprintln!("server error: {}", e);
+        error!(logger, "server error: {}", e);
     }
 }

src/server/mod.rs

@@ -1,4 +1,4 @@
-use std::{env, sync::Arc};
+use std::{env, sync::Arc, time::Instant};
 
 use futures::future;
 use hyper::{
@@ -8,7 +8,7 @@ use hyper::{
 use once_cell::sync::Lazy;
 use route_recognizer::{Params, Router};
 use semver::VersionReq;
-use slog::{error, o, Logger};
+use slog::{error, info, o, Logger};
 
 mod assets;
 mod views;
@@ -81,45 +81,49 @@ impl App {
     }
 
     pub async fn handle(&self, req: Request<Body>) -> Result<Response<Body>, HyperError> {
-        let logger = self
-            .logger
-            .new(o!("http_path" => req.uri().path().to_owned()));
+        let logger = self.logger.new(o!("path" => req.uri().path().to_owned()));
+        let logger2 = logger.clone();
+        let start = Instant::now();
 
-        if let Ok(route_match) = self.router.recognize(req.uri().path()) {
+        let res = if let Ok(route_match) = self.router.recognize(req.uri().path()) {
             match (req.method(), route_match.handler) {
-                (&Method::GET, Route::Index) => {
-                    return self.index(req, route_match.params, logger).await;
-                }
+                (&Method::GET, Route::Index) => self.index(req, route_match.params, logger).await,
 
                 (&Method::GET, Route::RepoStatus(format)) => {
-                    return self
-                        .repo_status(req, route_match.params, logger, *format)
-                        .await;
+                    self.repo_status(req, route_match.params, logger, *format)
+                        .await
                 }
 
                 (&Method::GET, Route::CrateStatus(format)) => {
-                    return self
-                        .crate_status(req, route_match.params, logger, *format)
-                        .await;
+                    self.crate_status(req, route_match.params, logger, *format)
+                        .await
                 }
 
                 (&Method::GET, Route::CrateRedirect) => {
-                    return self.crate_redirect(req, route_match.params, logger).await;
+                    self.crate_redirect(req, route_match.params, logger).await
                 }
 
-                (&Method::GET, Route::Static(file)) => {
-                    return Ok(App::static_file(*file));
-                }
+                (&Method::GET, Route::Static(file)) => Ok(App::static_file(*file)),
 
-                // fall through to 404
-                _ => {}
-            }
+                _ => Ok(not_found()),
             }
+        } else {
+            Ok(not_found())
+        };
 
-        Ok(Response::builder()
-            .status(StatusCode::NOT_FOUND)
-            .body(Body::empty())
-            .unwrap())
+        let end = Instant::now();
+        let diff = end - start;
+
+        match &res {
+            Ok(res) => info!(
+                logger2, "";
+                "status" => res.status().to_string(),
+                "time" => format!("{}ms", diff.as_millis())
+            ),
+            Err(err) => error!(logger2, ""; "error" => err.to_string()),
+        };
+
+        res
     }
 }
 
@@ -348,5 +352,12 @@ impl App {
     }
 }
 
+fn not_found() -> Response<Body> {
+    Response::builder()
+        .status(StatusCode::NOT_FOUND)
+        .body(Body::empty())
+        .unwrap()
+}
+
 static SELF_BASE_URL: Lazy<String> =
     Lazy::new(|| env::var("BASE_URL").unwrap_or_else(|_| "http://localhost:8080".to_string()));

src/utils/cache.rs

@@ -1,5 +1,5 @@
 use std::{
-    fmt::{Debug, Formatter, Result as FmtResult},
+    fmt,
     hash::Hash,
     time::{Duration, Instant},
 };
@@ -26,12 +26,12 @@ where
     logger: Logger,
 }
 
-impl<S, Req> Debug for Cache<S, Req>
+impl<S, Req> fmt::Debug for Cache<S, Req>
 where
-    S: Service<Req> + Debug,
+    S: Service<Req> + fmt::Debug,
     Req: Hash + Eq,
 {
-    fn fmt(&self, fmt: &mut Formatter<'_>) -> FmtResult {
+    fn fmt(&self, fmt: &mut fmt::Formatter<'_>) -> fmt::Result {
         fmt.debug_struct("Cache")
             .field("inner", &self.inner)
             .field("duration", &self.duration)
@@ -41,9 +41,9 @@ where
 
 impl<S, Req> Cache<S, Req>
 where
-    S: Service<Req>,
+    S: Service<Req> + fmt::Debug,
     S::Response: Clone,
-    Req: Clone + Eq + Hash,
+    Req: Clone + Eq + Hash + fmt::Debug,
 {
     pub fn new(service: S, duration: Duration, capacity: usize, logger: Logger) -> Cache<S, Req> {
         Cache {
@@ -62,13 +62,22 @@ where
 
             if let Some((ref valid_until, ref cached_response)) = cache.get_mut(&req) {
                 if *valid_until > now {
-                    debug!(self.logger, "cache hit");
+                    debug!(
+                        self.logger, "cache hit";
+                        "svc" => format!("{:?}", self.inner),
+                        "req" => format!("{:?}", &req)
+                    );
+
                     return Ok(cached_response.clone());
                 }
             }
         }
 
-        debug!(self.logger, "cache miss");
+        debug!(
+            self.logger, "cache miss";
+            "svc" => format!("{:?}", self.inner),
+            "req" => format!("{:?}", &req)
+        );
 
         let fresh = self.inner.call(req.clone()).await?;