From aa0f4777e26202077be35ca0174943304f5bbad8 Mon Sep 17 00:00:00 2001 From: Rob Ede Date: Sun, 4 Oct 2020 16:03:52 +0100 Subject: [PATCH] improve logging (#62) --- Cargo.lock | 137 ++++++++++++++++++++++++++++++-- Cargo.toml | 3 +- src/engine/fut/analyze.rs | 48 ++++------- src/engine/machines/analyzer.rs | 11 ++- src/interactors/crates.rs | 17 +++- src/interactors/github.rs | 13 ++- src/interactors/mod.rs | 13 ++- src/interactors/rustsec.rs | 10 ++- src/main.rs | 25 +++--- src/server/mod.rs | 63 +++++++++------ src/utils/cache.rs | 25 ++++-- 11 files changed, 268 insertions(+), 97 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index b298f18..e66672a 100644 --- a/Cargo.lock +++ b/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" diff --git a/Cargo.toml b/Cargo.toml index 66f9d11..227f707 100644 --- a/Cargo.toml +++ b/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" diff --git a/src/engine/fut/analyze.rs b/src/engine/fut/analyze.rs index 6bf98ea..ce620d9 100644 --- a/src/engine/fut/analyze.rs +++ b/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 { + 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); diff --git a/src/engine/machines/analyzer.rs b/src/engine/machines/analyzer.rs index 655e5b6..a2c8b5d 100644 --- a/src/engine/machines/analyzer.rs +++ b/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()) diff --git a/src/interactors/crates.rs b/src/interactors/crates.rs index f95ff31..f0ad44b 100644 --- a/src/interactors/crates.rs +++ b/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, } -#[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 for QueryCrate { type Response = QueryCrateResponse; type Error = Error; @@ -145,7 +151,7 @@ fn convert_summary(response: SummaryResponse) -> Result, 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; type Error = Error; diff --git a/src/interactors/github.rs b/src/interactors/github.rs index a81c068..6057168 100644 --- a/src/interactors/github.rs +++ b/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; type Error = Error; diff --git a/src/interactors/mod.rs b/src/interactors/mod.rs index df3085d..f6aead6 100644 --- a/src/interactors/mod.rs +++ b/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") + } +} diff --git a/src/interactors/rustsec.rs b/src/interactors/rustsec.rs index c670557..5aadafa 100644 --- a/src/interactors/rustsec.rs +++ b/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") + } +} diff --git a/src/main.rs b/src/main.rs index b207d99..0f70596 100644 --- a/src/main.rs +++ b/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); } } diff --git a/src/server/mod.rs b/src/server/mod.rs index 5d719d7..724f6e7 100644 --- a/src/server/mod.rs +++ b/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) -> Result, 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 { + Response::builder() + .status(StatusCode::NOT_FOUND) + .body(Body::empty()) + .unwrap() +} + static SELF_BASE_URL: Lazy = Lazy::new(|| env::var("BASE_URL").unwrap_or_else(|_| "http://localhost:8080".to_string())); diff --git a/src/utils/cache.rs b/src/utils/cache.rs index ac801fd..df2efbf 100644 --- a/src/utils/cache.rs +++ b/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 Debug for Cache +impl fmt::Debug for Cache where - S: Service + Debug, + S: Service + 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 Cache where - S: Service, + S: Service + 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 { 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?;