diff --git a/Cargo.lock b/Cargo.lock index a89dc8fed8..4438b5bd12 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -647,6 +647,18 @@ version = "1.0.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "baf1de4339761588bc0619e3cbc0120ee582ebb74b53b4efbf79117bd2da40fd" +[[package]] +name = "chrono" +version = "0.4.19" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "670ad68c9088c2a963aaa298cb369688cf3f9465ce5e2d4ca10e6e0098a1ce73" +dependencies = [ + "libc", + "num-integer", + "num-traits 0.2.14", + "winapi 0.3.9", +] + [[package]] name = "concurrent-queue" version = "1.2.2" @@ -936,19 +948,6 @@ version = "0.1.2" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "c34f04666d835ff5d62e058c3995147c06f42fe86ff053337632bca83e42702d" -[[package]] -name = "env_logger" -version = "0.8.3" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "17392a012ea30ef05a610aa97dfb49496e71c9f676b27879922ea5bdf60d9d3f" -dependencies = [ - "atty", - "humantime", - "log", - "regex", - "termcolor", -] - [[package]] name = "event-listener" version = "2.5.1" @@ -1328,12 +1327,6 @@ dependencies = [ "tokio 1.5.0", ] -[[package]] -name = "humantime" -version = "2.1.0" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "9a3a5bfb195931eeb336b2a7b4d761daec841b97f947d34394601737a7bba5e4" - [[package]] name = "hyper" version = "0.13.10" @@ -1670,6 +1663,21 @@ dependencies = [ "value-bag", ] +[[package]] +name = "maplit" +version = "1.0.2" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "3e2e65a1a2e43cfcb47a895c4c8b10d1f4a61097f9f254f183aee60cad9c651d" + +[[package]] +name = "matchers" +version = "0.0.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "f099785f7595cc4b4553a174ce30dd7589ef93391ff414dbb67f62392b9e0ce1" +dependencies = [ + "regex-automata", +] + [[package]] name = "matches" version = "0.1.8" @@ -1690,6 +1698,9 @@ dependencies = [ "anyhow", "merino-settings", "merino-web", + "tracing", + "tracing-log", + "tracing-subscriber", "viaduct", "viaduct-reqwest", ] @@ -1700,7 +1711,6 @@ version = "0.1.0" dependencies = [ "actix-web", "anyhow", - "env_logger", "futures", "merino-settings", "merino-suggest", @@ -1712,10 +1722,9 @@ dependencies = [ "serde_derive", "serde_json", "serde_qs", - "serde_url_params", "tokio 1.5.0", + "tracing", "viaduct", - "viaduct-reqwest", ] [[package]] @@ -1725,12 +1734,17 @@ dependencies = [ "actix-rt", "anyhow", "httpmock", + "maplit", "merino-settings", "merino-web", "reqwest 0.11.3", "serde 1.0.125", "serde_json", + "serde_with", "tokio 1.5.0", + "tokio-test", + "tracing", + "tracing-subscriber", "viaduct", "viaduct-reqwest", ] @@ -1741,6 +1755,9 @@ version = "0.1.0" dependencies = [ "config", "serde 1.0.125", + "serde_with", + "tracing", + "tracing-subscriber", ] [[package]] @@ -1765,6 +1782,9 @@ dependencies = [ "thiserror", "tokio 1.5.0", "tokio-test", + "tracing", + "tracing-actix-web", + "uuid", ] [[package]] @@ -1910,6 +1930,16 @@ dependencies = [ "winapi 0.3.9", ] +[[package]] +name = "num-integer" +version = "0.1.44" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "d2cc698a63b549a70bc047073d2949cce27cd1c7b0a4a862d08a8031bc2801db" +dependencies = [ + "autocfg", + "num-traits 0.2.14", +] + [[package]] name = "num-traits" version = "0.1.43" @@ -2294,6 +2324,16 @@ dependencies = [ "regex-syntax", ] +[[package]] +name = "regex-automata" +version = "0.1.9" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "ae1ded71d66a4a97f5e961fd0cb25a5f366a42a41570d16a763a69c092c26ae4" +dependencies = [ + "byteorder", + "regex-syntax", +] + [[package]] name = "regex-syntax" version = "0.6.23" @@ -2422,6 +2462,12 @@ dependencies = [ "semver", ] +[[package]] +name = "rustversion" +version = "1.0.4" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "cb5d2a036dc6d2d8fd16fde3498b04306e29bd193bf306a57427019b823d5acd" + [[package]] name = "ryu" version = "1.0.5" @@ -2552,16 +2598,6 @@ dependencies = [ "serde 1.0.125", ] -[[package]] -name = "serde_url_params" -version = "0.2.1" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "2c43307d0640738af32fe8d01e47119bc0fc8a686be470a44a586caff76dfb34" -dependencies = [ - "serde 1.0.125", - "url", -] - [[package]] name = "serde_urlencoded" version = "0.7.0" @@ -2574,6 +2610,29 @@ dependencies = [ "serde 1.0.125", ] +[[package]] +name = "serde_with" +version = "1.8.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "26b0b98f61935da47683bf5c46b965ce1642ef1db78860b8a1defb68bf1b5b43" +dependencies = [ + "rustversion", + "serde 1.0.125", + "serde_with_macros", +] + +[[package]] +name = "serde_with_macros" +version = "1.4.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "e48b35457e9d855d3dc05ef32a73e0df1e2c0fd72c38796a4ee909160c8eeec2" +dependencies = [ + "darling", + "proc-macro2", + "quote", + "syn", +] + [[package]] name = "sha-1" version = "0.9.4" @@ -2593,6 +2652,15 @@ version = "0.6.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "2579985fda508104f7587689507983eadd6a6e84dd35d6d115361f530916fa0d" +[[package]] +name = "sharded-slab" +version = "0.1.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "79c719719ee05df97490f80a45acfc99e5a30ce98a1e4fb67aee422745ae14e3" +dependencies = [ + "lazy_static", +] + [[package]] name = "signal-hook" version = "0.3.8" @@ -2780,15 +2848,6 @@ dependencies = [ "winapi 0.3.9", ] -[[package]] -name = "termcolor" -version = "1.1.2" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "2dfed899f0eb03f32ee8c6a0aabdb8a7949659e3466561fc0adf54e26d88c5f4" -dependencies = [ - "winapi-util", -] - [[package]] name = "thiserror" version = "1.0.24" @@ -2809,6 +2868,15 @@ dependencies = [ "syn", ] +[[package]] +name = "thread_local" +version = "1.1.3" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "8018d24e04c95ac8790716a5987d0fec4f8b27249ffa0f7d33f1369bdfb88cbd" +dependencies = [ + "once_cell", +] + [[package]] name = "time" version = "0.2.26" @@ -3009,9 +3077,9 @@ checksum = "360dfd1d6d30e05fda32ace2c8c70e9c0a9da713275777f5a4dbb8a1893930c6" [[package]] name = "tracing" -version = "0.1.25" +version = "0.1.26" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "01ebdc2bb4498ab1ab5f5b73c5803825e60199229ccba0698170e3be0e7f959f" +checksum = "09adeb8c97449311ccd28a427f96fb563e7fd31aabf994189879d9da2394b89d" dependencies = [ "cfg-if 1.0.0", "log", @@ -3020,6 +3088,21 @@ dependencies = [ "tracing-core", ] +[[package]] +name = "tracing-actix-web" +version = "0.4.0-beta.4" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "d232c700ac99b41f56aac3832f138009b2dc7538cbdc76fdc6b8304a1ee2d2e0" +dependencies = [ + "actix-http", + "actix-service", + "actix-web", + "futures", + "tracing", + "tracing-futures", + "uuid", +] + [[package]] name = "tracing-attributes" version = "0.1.15" @@ -3033,9 +3116,9 @@ dependencies = [ [[package]] name = "tracing-core" -version = "0.1.17" +version = "0.1.18" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "f50de3927f93d202783f4513cda820ab47ef17f624b03c096e86ef00c67e6b5f" +checksum = "a9ff14f98b1a4b289c6248a023c1c2fa1491062964e9fed67ab29c4e4da4a052" dependencies = [ "lazy_static", ] @@ -3050,6 +3133,49 @@ dependencies = [ "tracing", ] +[[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-serde" +version = "0.1.2" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "fb65ea441fbb84f9f6748fd496cf7f63ec9af5bca94dd86456978d055e8eb28b" +dependencies = [ + "serde 1.0.125", + "tracing-core", +] + +[[package]] +name = "tracing-subscriber" +version = "0.2.18" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "aa5553bf0883ba7c9cbe493b085c29926bd41b66afc31ff72cf17ff4fb60dcd5" +dependencies = [ + "ansi_term", + "chrono", + "lazy_static", + "matchers", + "regex", + "serde 1.0.125", + "serde_json", + "sharded-slab", + "smallvec", + "thread_local", + "tracing", + "tracing-core", + "tracing-log", + "tracing-serde", +] + [[package]] name = "try-lock" version = "0.2.3" @@ -3107,6 +3233,15 @@ dependencies = [ "percent-encoding", ] +[[package]] +name = "uuid" +version = "0.8.2" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "bc5cf98d8186244414c848017f0e2676b3fcb46807f6668a97dfe67359a3c4b7" +dependencies = [ + "getrandom 0.2.2", +] + [[package]] name = "value-bag" version = "1.0.0-alpha.6" @@ -3299,15 +3434,6 @@ version = "0.4.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "ac3b87c63620426dd9b991e5ce0329eff545bccbbb34f3be09ff6fb6ab51b7b6" -[[package]] -name = "winapi-util" -version = "0.1.5" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "70ec6ce85bb158151cae5e5c87f95a8e97d2c0c4b001223f33a334e3ce5de178" -dependencies = [ - "winapi 0.3.9", -] - [[package]] name = "winapi-x86_64-pc-windows-gnu" version = "0.4.0" diff --git a/config/base.yaml b/config/base.yaml index 0aed6dd9f5..1a04ed9a5c 100644 --- a/config/base.yaml +++ b/config/base.yaml @@ -8,3 +8,6 @@ adm: remote_settings: storage_path: "./rs-cache" collection: "quicksuggest" + +logging: + levels: [INFO] diff --git a/merino-adm/Cargo.toml b/merino-adm/Cargo.toml index 5d3719c6da..0294068153 100644 --- a/merino-adm/Cargo.toml +++ b/merino-adm/Cargo.toml @@ -9,18 +9,16 @@ serde = "1.0.125" serde_derive = "1.0.125" serde_json = "1.0.64" serde_qs = "0.8.3" -serde_url_params = "0.2.1" remote-settings-client = { git = "https://github.com/mozilla-services/remote-settings-client", rev = "06fbe92e3e45c42ff1bdd9b71ceda6e9e908a656" } viaduct = { git = "https://github.com/mozilla/application-services", rev = "v75.0.0"} -viaduct-reqwest = { git = "https://github.com/mozilla/application-services", rev = "v75.0.0"} anyhow = "1.0.40" -env_logger = "0.8.3" reqwest = { version = "0.11.3", features = ["json"] } tokio = { version = "1.5.0", features = ["rt", "macros", "rt-multi-thread"] } radix_trie = "0.2.1" merino-suggest = { path = "../merino-suggest" } futures = "0.3.14" merino-settings = { path = "../merino-settings" } +tracing = "0.1.26" [dev-dependencies] pretty_assertions = "0.7.1" diff --git a/merino-adm/src/remote_settings.rs b/merino-adm/src/remote_settings.rs index bb7bfb7267..52d1ec4bc9 100644 --- a/merino-adm/src/remote_settings.rs +++ b/merino-adm/src/remote_settings.rs @@ -26,7 +26,9 @@ impl RemoteSettingsSuggester { /// Download suggestions from Remote Settings /// /// This must be called at least once before any suggestions will be provided + #[tracing::instrument(skip(self, settings))] pub async fn sync(&mut self, settings: &Settings) -> Result<()> { + tracing::info!("Syncing quicksuggest records from Remote Settings"); let reqwest_client = reqwest::Client::new(); // Set up and sync a Remote Settings client for the quicksuggest collection. @@ -112,10 +114,11 @@ impl RemoteSettingsSuggester { } if suggestions.is_empty() { - println!("Warn: No suggestion records found on Remote Settings"); + tracing::warn!("No suggestion records found on Remote Settings"); } self.suggestions = suggestions; + tracing::info!("Completed syncing quicksuggest records from Remote Settings"); Ok(()) } diff --git a/merino-integration-tests/Cargo.toml b/merino-integration-tests/Cargo.toml index bbc82dc4cd..512fcc92a4 100644 --- a/merino-integration-tests/Cargo.toml +++ b/merino-integration-tests/Cargo.toml @@ -6,12 +6,17 @@ edition = "2018" [dependencies] actix-rt = "2.2.0" tokio = "1.5.0" +tokio-test = "0.4.1" reqwest = { version = "0.11.3", features = ["json"] } anyhow = "1.0.40" serde = { version = "1.0.125", features = ["derive"] } serde_json = "1.0.64" +serde_with = "1.8.1" merino-web = { path = "../merino-web" } merino-settings = { path = "../merino-settings" } httpmock = "0.5.8" viaduct = { git = "https://github.com/mozilla/application-services", rev = "v75.0.0"} viaduct-reqwest = { git = "https://github.com/mozilla/application-services", rev = "v75.0.0"} +tracing = "0.1.26" +tracing-subscriber = "0.2.18" +maplit = "1.0.2" diff --git a/merino-integration-tests/src/debug.rs b/merino-integration-tests/src/debug.rs index bea25109a3..aeb557c2c2 100644 --- a/merino-integration-tests/src/debug.rs +++ b/merino-integration-tests/src/debug.rs @@ -1,39 +1,46 @@ //! Tests Merino's debug pages. +#![cfg(test)] +use crate::{merino_test, TestingTools}; +use merino_settings::Settings; use reqwest::StatusCode; -use crate::TestingTools; - #[actix_rt::test] async fn cant_use_debug_settings_route_when_debug_is_false() { - let TestingTools { test_client, .. } = TestingTools::new(|settings| settings.debug = false); - - let response = test_client - .get("/debug/settings") - .send() - .await - .expect("failed to execute request"); - - assert_eq!(response.status(), StatusCode::NOT_FOUND); - assert_eq!(response.content_length(), Some(0)); + merino_test( + |settings: &mut Settings| settings.debug = false, + |TestingTools { test_client, .. }| async move { + let response = test_client + .get("/debug/settings") + .send() + .await + .expect("failed to execute request"); + + assert_eq!(response.status(), StatusCode::NOT_FOUND); + assert_eq!(response.content_length(), Some(0)); + }, + ) + .await } #[actix_rt::test] async fn can_use_debug_settings_route_when_debug_is_true() { - let TestingTools { test_client, .. } = TestingTools::new(|settings| { - settings.debug = true; - }); - - let response = test_client - .get("/debug/settings") - .send() - .await - .expect("failed to execute request"); - - assert_eq!(response.status(), StatusCode::OK); - assert_eq!( - response.headers().get("content-type").unwrap(), - &"application/json" - ); - assert!(response.json::().await.is_ok()); + merino_test( + |settings: &mut Settings| settings.debug = true, + |TestingTools { test_client, .. }| async move { + let response = test_client + .get("/debug/settings") + .send() + .await + .expect("failed to execute request"); + + assert_eq!(response.status(), StatusCode::OK); + assert_eq!( + response.headers().get("content-type").unwrap(), + &"application/json" + ); + assert!(response.json::().await.is_ok()); + }, + ) + .await } diff --git a/merino-integration-tests/src/dockerflow.rs b/merino-integration-tests/src/dockerflow.rs index ee903e174a..b5733f2f7e 100644 --- a/merino-integration-tests/src/dockerflow.rs +++ b/merino-integration-tests/src/dockerflow.rs @@ -1,92 +1,108 @@ //! Tests that Merino conforms to [Dockerflow](https://github.com/mozilla-services/dockerflow). +#![cfg(test)] +use crate::{merino_test, TestingTools}; use anyhow::Result; use reqwest::StatusCode; use serde::Deserialize; -use crate::TestingTools; - #[actix_rt::test] async fn lbheartbeat_works() { - let TestingTools { test_client, .. } = TestingTools::new(|_| ()); - - let response = test_client - .get("/__lbheartbeat__") - .send() - .await - .expect("failed to execute request"); - - assert_eq!(response.status(), StatusCode::OK); - assert_eq!(response.content_length(), Some(0)); + merino_test( + |_| (), + |TestingTools { test_client, .. }| async move { + let response = test_client + .get("/__lbheartbeat__") + .send() + .await + .expect("failed to execute request"); + + assert_eq!(response.status(), StatusCode::OK); + assert_eq!(response.content_length(), Some(0)); + }, + ) + .await } #[actix_rt::test] async fn heartbeat_works() -> Result<()> { - let TestingTools { test_client, .. } = TestingTools::new(|_| ()); - - let response = test_client - .get("/__heartbeat__") - .send() - .await - .expect("failed to execute request"); - - assert!(response.status().is_success()); - assert_eq!( - response - .headers() - .get_all("content-type") - .iter() - .collect::>(), - vec!["application/json"] - ); - Ok(()) + merino_test( + |_| (), + |TestingTools { test_client, .. }| async move { + let response = test_client + .get("/__heartbeat__") + .send() + .await + .expect("failed to execute request"); + + assert!(response.status().is_success()); + assert_eq!( + response + .headers() + .get_all("content-type") + .iter() + .collect::>(), + vec!["application/json"] + ); + Ok(()) + }, + ) + .await } #[actix_rt::test] async fn version_works() -> Result<()> { - let TestingTools { test_client, .. } = TestingTools::new(|_| ()); - - let response = test_client - .get("/__version__") - .send() - .await - .expect("failed to execute request"); - - assert!(response.status().is_success()); - assert_eq!( - response - .headers() - .get_all("content-type") - .iter() - .collect::>(), - vec!["application/json"] - ); - - #[derive(Deserialize, Debug)] - #[allow(dead_code)] - struct VersionInfo { - source: String, - version: String, - commit: String, - build: String, - } - let body: Result = response.json().await; - assert!(body.is_ok()); - - Ok(()) + merino_test( + |_| (), + |TestingTools { test_client, .. }| async move { + let response = test_client + .get("/__version__") + .send() + .await + .expect("failed to execute request"); + + assert!(response.status().is_success()); + assert_eq!( + response + .headers() + .get_all("content-type") + .iter() + .collect::>(), + vec!["application/json"] + ); + + #[derive(Deserialize, Debug)] + #[allow(dead_code)] + struct VersionInfo { + source: String, + version: String, + commit: String, + build: String, + } + let body: Result = response.json().await; + assert!(body.is_ok()); + + Ok(()) + }, + ) + .await } #[actix_rt::test] async fn error_works() -> Result<()> { - let TestingTools { test_client, .. } = TestingTools::new(|_| ()); - - let response = test_client - .get("/__error__") - .send() - .await - .expect("failed to execute request"); - - assert!(response.status().is_server_error()); - - Ok(()) + merino_test( + |_| (), + |TestingTools { test_client, .. }| async move { + let response = test_client + .get("/__error__") + .send() + .await + .expect("failed to execute request"); + + assert!(response.status().is_server_error()); + + Ok(()) + }, + ) + .await } diff --git a/merino-integration-tests/src/lib.rs b/merino-integration-tests/src/lib.rs index 0f737d1703..ba545bc8cf 100644 --- a/merino-integration-tests/src/lib.rs +++ b/merino-integration-tests/src/lib.rs @@ -1,5 +1,8 @@ #![warn(missing_docs, clippy::missing_docs_in_private_items)] -#![cfg(test)] +// None of the tests are seen by the linter, so none of the utilities are marked +// as used. But docs don't generate for the below if they are `#[cfg(test)]`. +// This is a compromise. +#![allow(dead_code)] //! Tests for Merino that work by reading from the external API only. //! @@ -10,58 +13,124 @@ //! This is structured as a separate crate so that it produces a single test //! binary instead of one test per file like would happen if this were //! `merino/tests/...`. This improves compilation and test times. +//! +//! The primary tool used by tests is [`merino_test`], which creates mock +//! servers, sets up the application for testing, and provides helpers to inspect +//! the state of the app. It then calls the test function that is passed to it, +//! providing the above tools as an argument. + +mod debug; +mod dockerflow; +mod logging; +mod suggest; +pub mod utils; +use crate::utils::logging::LogWatcher; use httpmock::MockServer; +use merino_settings::Settings; use reqwest::{Client, RequestBuilder}; use std::{net::TcpListener, sync::Once}; -use merino_settings::Settings; +use tracing_subscriber::{fmt::MakeWriter, layer::SubscriberExt}; -mod debug; -mod dockerflow; -mod suggest; +/// A marker to track that the viaduct backend has been initialized. +static VIADUCT_INIT: Once = Once::new(); -static ONE_TIME_INIT: Once = Once::new(); +/// Run a test with a full configured Merino server. +/// +/// The server will listen on a port assigned arbitrarily by the OS. +/// +/// A suite of tools will be passed to the test function, which will include an +/// HTTP client configured to use the test server, an HTTP mock server that +/// Remote Settings has been configured to read from, and a log collector that +/// can make assertions about logs that were printed. +/// +/// # Example +/// +/// ``` +/// # use merino_integration_tests::{merino_test, TestingTools}; +/// #[actix_rt::test] +/// async fn a_test() { +/// merino_test( +/// |settings| settings.debug = false, +/// |TestingTools { test_client, mut log_watcher, .. }| async move { +/// assert!(true) // Test goes here +/// } +/// ).await +/// } +/// ``` +pub fn merino_test(settings_changer: FSettings, test: FTest) -> R +where + FSettings: FnOnce(&mut Settings), + FTest: Fn(TestingTools) -> R, +{ + // Set up a mock server for Remote Settings to talk to + let remote_settings_mock = MockServer::start(); -#[non_exhaustive] -pub(crate) struct TestingTools { - test_client: TestReqwestClient, - remote_settings_mock: MockServer, -} + // Load settings + let settings = Settings::load_for_tests(|settings| { + settings.adm.remote_settings.server = Some(remote_settings_mock.url("")); + settings_changer(settings); + }); -impl TestingTools { - /// Start the fully configured application server. - /// - /// The server will listen on a port assigned arbitrarily by the OS. A test HTTP - /// client that automatically targets the server will be returned. - pub(crate) fn new(settings_changer: F) -> Self { - // Set up a mock server for remote settings to talk to - let remote_settings_mock = MockServer::start(); + // `remote_settings_client` uses viaduct. Tell viaduct to use reqwest. + VIADUCT_INIT.call_once(|| { + viaduct::set_backend(&viaduct_reqwest::ReqwestBackend) + .expect("Failed to set viaduct backend"); + }); - // remote_settings_client uses viaduct. Tell viaduct to use reqwest. - ONE_TIME_INIT.call_once(|| { - viaduct::set_backend(&viaduct_reqwest::ReqwestBackend) - .expect("Failed to set viaduct backend"); - }); + // Set up logging + let log_watcher = LogWatcher::default(); + let log_watcher_writer = log_watcher.make_writer(); - let settings = Settings::load_for_tests(|settings| { - settings.adm.remote_settings.server = Some(remote_settings_mock.url("")); - settings_changer(settings); - }); - let listener = TcpListener::bind(settings.http.listen).expect("Failed to bind to a port"); - let address = listener.local_addr().unwrap().to_string(); - let server = merino_web::run(listener, settings).expect("Failed to start server"); + let subscriber = tracing_subscriber::registry() + .with( + tracing_subscriber::fmt::layer() + .json() + .with_writer(move || log_watcher_writer.clone()), + ) + .with(tracing_subscriber::fmt::layer().pretty().with_test_writer()); - // Run the server in the background - tokio::spawn(server); + // Run server in the background + let listener = TcpListener::bind(settings.http.listen).expect("Failed to bind to a port"); + let address = listener.local_addr().unwrap().to_string(); + let server = merino_web::run(listener, settings).expect("Failed to start server"); + tokio::spawn(server); + let test_client = TestReqwestClient::new(address); - let test_client = TestReqwestClient::new(address); + // Assemble the tools + let tools = TestingTools { + test_client, + remote_settings_mock, + log_watcher, + }; - Self { - test_client, - remote_settings_mock, - } - } + // Run the test + tracing::subscriber::with_default(subscriber, || test(tools)) +} + +/// A set of tools for tests, including mock servers and logging helpers. +/// +/// The fields of this struct are marked as non-exhaustive, meaning that any +/// destructuring of this struct will require a `..` "and the rest" entry, even +/// if all present items are named. This makes adding tools in the future easier, +/// since old tests won't need to be rewritten to account for the added tools. +#[non_exhaustive] +pub struct TestingTools { + /// A wrapper around a `reqwest::client` that automatically uses the Merino + /// server under test. + pub test_client: TestReqwestClient, + + /// A [`httpmock::MockServer`] that remote settings has been configured to use + /// as its default server. Does not contain mock responses, any needed must + /// be adde /// Start the fully configured application server. + /// + /// The server will listen on a port assigned arbitrarily by the OS. A test HTTP + /// client that automatically targets the server will be returned. + pub remote_settings_mock: MockServer, + + /// To make assertions about logs. + pub log_watcher: LogWatcher, } /// A wrapper around a `[reqwest::client]` that automatically sends requests to @@ -69,12 +138,16 @@ impl TestingTools { /// /// Note: This only handles `GET` requests right now. Other methods should be /// added as needed. -pub(crate) struct TestReqwestClient { +pub struct TestReqwestClient { + /// The wrapped client. client: Client, + + /// The server address to implicitly use for all requests. address: String, } impl TestReqwestClient { + /// Construct a new test client that uses `address` for every request given. fn new(address: String) -> Self { Self { address, diff --git a/merino-integration-tests/src/logging.rs b/merino-integration-tests/src/logging.rs new file mode 100644 index 0000000000..ab19ea374b --- /dev/null +++ b/merino-integration-tests/src/logging.rs @@ -0,0 +1,27 @@ +//! Tests that Merino logs behave as expected. +//! +//! This module should be used for general logging behavior. Logging behavior for +//! specific parts of Merino should be placed in more specific test modules. +#![cfg(text)] + +use crate::TestingTools; +use anyhow::Result; + +#[actix_rt::test] +async fn error_handler_writes_logs() -> Result<()> { + let TestingTools { + test_client, + mut log_watcher, + .. + } = TestingTools::new(|_| ()); + + test_client + .get("/__error__") + .send() + .await + .expect("failed to execute request"); + + assert!(log_watcher.has(|msg| msg.field_contains("message", "__error__"))); + + Ok(()) +} diff --git a/merino-integration-tests/src/suggest.rs b/merino-integration-tests/src/suggest.rs index 6cb2917396..090b10f24a 100644 --- a/merino-integration-tests/src/suggest.rs +++ b/merino-integration-tests/src/suggest.rs @@ -1,31 +1,36 @@ //! Tests Merino's ability to make basic suggestions. +#![cfg(test)] +use crate::{merino_test, TestingTools}; use anyhow::Result; use httpmock::{Method::GET, MockServer}; use reqwest::StatusCode; use serde_json::json; -use crate::TestingTools; - #[actix_rt::test] async fn suggest_wikifruit_works() -> Result<()> { - let TestingTools { - test_client, - remote_settings_mock, - .. - } = TestingTools::new(|_| ()); - setup_empty_remote_settings_collection(remote_settings_mock); - - let response = test_client.get("/api/v1/suggest?q=apple").send().await?; - - assert_eq!(response.status(), StatusCode::OK); - let body: serde_json::Value = response.json().await?; - assert_eq!( - body["suggestions"][0]["url"], - json!("https://en.wikipedia.org/wiki/Apple") - ); - - Ok(()) + merino_test( + |_| (), + |TestingTools { + test_client, + remote_settings_mock, + .. + }| async move { + setup_empty_remote_settings_collection(remote_settings_mock); + + let response = test_client.get("/api/v1/suggest?q=apple").send().await?; + + assert_eq!(response.status(), StatusCode::OK); + let body: serde_json::Value = response.json().await?; + assert_eq!( + body["suggestions"][0]["url"], + json!("https://en.wikipedia.org/wiki/Apple") + ); + + Ok(()) + }, + ) + .await } fn setup_empty_remote_settings_collection(server: MockServer) { diff --git a/merino-integration-tests/src/utils/logging.rs b/merino-integration-tests/src/utils/logging.rs new file mode 100644 index 0000000000..be7944e603 --- /dev/null +++ b/merino-integration-tests/src/utils/logging.rs @@ -0,0 +1,161 @@ +//! Testing utilities to work with logs. + +use serde::Deserialize; +use serde_json::Value; +use std::{ + collections::HashMap, + io::Write, + ops::Deref, + sync::{Arc, Mutex}, +}; +use tracing::Level; +use tracing_subscriber::fmt::MakeWriter; + +/// Helper to collect events emitted by Tracing and later make assertions about +/// the collected events. +#[derive(Default)] +pub struct LogWatcher { + /// The raw bytes received from Tracing. Should represent new-line separated JSON objects. + buf: Arc>>, + + /// Events serialized from [`buf`](Self::buf). As valid JSON objects are + /// parsed from `buf`, the corresponding bytes are removed from `buf`. This + /// way if there are any partial writes, only the complete objects are + /// processed from the buffer, leaving incomplete objects in place. + events: Vec, +} + +impl LogWatcher { + /// Make a new LogWatcher with some events pre-populated. Primarily for testing LogWatcher itself. + pub fn with_events(events: Vec) -> Self { + Self { + events, + buf: Arc::new(Mutex::new(Vec::new())), + } + } + + /// Test if any event this logger received matches `predicate`. + /// + /// # Example + /// + /// ``` + /// # use merino_integration_tests::utils::logging::{LogWatcher, TracingJsonEvent}; + /// # use std::sync::{Arc, Mutex}; + /// # use tracing::Level; + /// # let mut log_watcher = LogWatcher::with_events(vec![ + /// # TracingJsonEvent { + /// # fields: maplit::hashmap!{ "message".to_string() => serde_json::json!("request success") }, + /// # level: Level::INFO, + /// # target: String::new(), + /// # timestamp: String::new(), + /// # } + /// # ]); + /// # + /// assert!(log_watcher.has(|msg| msg.field_contains("message", "request success"))); + /// ``` + pub fn has(&mut self, predicate: F) -> bool + where + F: FnMut(&TracingJsonEvent) -> bool, + { + self.convert_events(); + self.events.iter().any(predicate) + } + + /// Iterate through `self.buf` to convert newline separated, completed JSON + /// objects into [`TracingJsonEvent`] instances that are placed in + /// `self.events`. + fn convert_events(&mut self) { + let mut buf = self.buf.lock().expect("mutex was poisoned"); + let mut log_text = String::from_utf8(buf.clone()).expect("bad utf8"); + + // Repeatedly find the next newline char... + while let Some(idx) = log_text.find('\n') { + // Split the string at that point... + let mut message_json = log_text.split_off(idx); + // and keep the left side, and return the right side to the string + std::mem::swap(&mut message_json, &mut log_text); + // Remove the leading newline we left there. + assert_eq!(log_text.chars().next(), Some('\n')); + log_text.remove(0); + + // Skip blank lines + if message_json.trim().is_empty() { + continue; + } + + // Now `message_join` contains the first line of logs, and `log_text` contains the rest. + let message: TracingJsonEvent = serde_json::from_str(&message_json) + .unwrap_or_else(|_| panic!("Bad JSON in log line: {}", &message_json)); + self.events.push(message); + } + + // Now put the rest of the text back into the buffer. + *buf = log_text.into_bytes(); + // and the mutex unlocks when it drops at the end of the function. + } +} + +impl MakeWriter for LogWatcher { + type Writer = LogWatcherWriter; + + fn make_writer(&self) -> Self::Writer { + LogWatcherWriter { + buf: self.buf.clone(), + } + } +} + +/// A helper that collects log events emitted from Tracing. +/// +/// This is needed because Tracing consumes its subscribers. This type is a +/// "scout" that is split off from the main [`LogWatcher`] to give to Tracing, +/// and the data is written back to the parent type. +#[derive(Clone)] +pub struct LogWatcherWriter { + /// The handle to the parent log watcher's buffer. + buf: Arc>>, +} + +impl Write for LogWatcherWriter { + fn write(&mut self, new_bytes: &[u8]) -> std::io::Result { + let mut buf = self + .buf + .lock() + .map_err(|e| std::io::Error::new(std::io::ErrorKind::Other, e.to_string()))?; + buf.extend(new_bytes.iter()); + Ok(new_bytes.len()) + } + + fn flush(&mut self) -> std::io::Result<()> { + Ok(()) + } +} + +/// A deserialization of [`tracing_subscriber::fmt::format::Json`]'s output format. +#[derive(Debug, Deserialize)] +pub struct TracingJsonEvent { + /// The key-value fields logged on the event, usually including `message`. + pub fields: HashMap, + /// The level the event was emitted at. + #[serde(with = "serde_with::rust::display_fromstr")] + pub level: Level, + /// The target of the event. + pub target: String, + /// The time the event was emitted. + pub timestamp: String, +} + +impl TracingJsonEvent { + /// Test if the field named `field_name` is a string that contains `pat` as a + /// substring. + pub fn field_contains<'a, S>(&'a self, field_name: &'a str, pat: S) -> bool + where + S: Deref, + { + self.fields + .get(field_name) + .and_then(|value| value.as_str()) + .map(|value| value.contains(pat.deref())) + .unwrap_or(false) + } +} diff --git a/merino-integration-tests/src/utils/mod.rs b/merino-integration-tests/src/utils/mod.rs new file mode 100644 index 0000000000..f8e7a97b1d --- /dev/null +++ b/merino-integration-tests/src/utils/mod.rs @@ -0,0 +1,3 @@ +//! Utilities to aid in testing. + +pub mod logging; diff --git a/merino-settings/Cargo.toml b/merino-settings/Cargo.toml index 9702119c37..2eac25789b 100644 --- a/merino-settings/Cargo.toml +++ b/merino-settings/Cargo.toml @@ -6,3 +6,6 @@ edition = "2018" [dependencies] config = "0.11.0" serde = { version = "1.0.125", features = ["derive"] } +serde_with = "1.8.1" +tracing = "0.1.26" +tracing-subscriber = { version = "0.2.18", features = ["env-filter"] } diff --git a/merino-settings/src/lib.rs b/merino-settings/src/lib.rs index 1e030c5234..3b1e608034 100644 --- a/merino-settings/src/lib.rs +++ b/merino-settings/src/lib.rs @@ -25,6 +25,10 @@ //! format, simply use a different extension for your file, like //! `config/local.toml`. +mod logging; + +pub use logging::LoggingSettings; + use config::{Config, ConfigError, Environment, File}; use serde::{Deserialize, Serialize}; use std::{net::SocketAddr, path::PathBuf}; @@ -35,7 +39,6 @@ use std::{net::SocketAddr, path::PathBuf}; pub struct Settings { /// The environment Merino is running in. Should only be set with the /// `MERINO_ENV` environment variable. - #[doc()] pub env: String, /// Enable additional features to debug the application. This should not be @@ -43,12 +46,13 @@ pub struct Settings { pub debug: bool, /// Settings for the HTTP server. - #[doc(inline)] pub http: HttpSettings, /// Settings for adM integration. - #[doc(inline)] pub adm: AdmSettings, + + /// Logging settings. + pub logging: LoggingSettings, } /// Settings for the HTTP server. diff --git a/merino-settings/src/logging.rs b/merino-settings/src/logging.rs new file mode 100644 index 0000000000..08ad5fbb06 --- /dev/null +++ b/merino-settings/src/logging.rs @@ -0,0 +1,151 @@ +use std::{ops::AddAssign, str::FromStr}; + +use serde::{de, ser::SerializeSeq, Deserialize, Serialize}; +use tracing_subscriber::{filter::Directive, EnvFilter}; + +/// Logging settings. +#[derive(Debug, Clone, Serialize, Deserialize)] +pub struct LoggingSettings { + /// The minimum level that logs should be reported at. + /// + /// Each entry can be one of `ERROR`, `WARN`, `INFO`, `DEBUG`, or `TRACE` (in + /// increasing verbosity), with an optional component that specifies the + /// source of the logs. + /// + /// This setting combined with the contents of the environment variable + /// `RUST_LOG`, with values from the environment variable overriding the + /// config file. + /// + /// The environment variable `MERINO_LOGGING__LEVELS` can be used. This + /// environment variable will completely override the config file, and wil be + /// merged with the envvar `RUST_LOG`. `RUST_LOG` takes precedence again. + /// + /// # Examples + /// + /// The configurations below are identical + /// + /// ```yaml + /// # config/local.yaml + /// logging: + /// levels: + /// - INFO # default to INFO + /// - merino_web=DEBUG # noisier logs from merino_web + /// - viaduct=WARN # viaduct's INFO level is too noisy + /// ``` + /// + /// ```shell + /// RUST_LOG=INFO,merino_web=DEBUG,viaduct=WARN + /// ``` + pub levels: DirectiveWrapper, +} + +/// Tracing's Directive object for filter logs isn't `Clone` or `Serializable`. +/// Make a wrapper for a collection of Directives so that we can work more easily +/// with it. +/// +///This struct can be deserialized from either a comma separated string of +///directives (`"INFO,component1=WARN"), or from a sequence of comma separated +///strings (`["INFO", "component1=WARN,component2=DEBUG"]`). This is important +///because the config files use sequences, but environment variables are always +///strings. +/// +/// Every entry in this struct is guaranteed to be parsable as a valid Directive. +#[derive(Debug, Clone, PartialEq)] +pub struct DirectiveWrapper(Vec); + +impl Serialize for DirectiveWrapper { + fn serialize(&self, serializer: S) -> Result + where + S: serde::Serializer, + { + let mut seq = serializer.serialize_seq(Some(self.0.len()))?; + for directive in &self.0 { + seq.serialize_element(&directive)?; + } + seq.end() + } +} + +impl<'de> Deserialize<'de> for DirectiveWrapper { + fn deserialize(deserializer: D) -> Result + where + D: serde::Deserializer<'de>, + { + struct Visitor; + + impl<'de> de::Visitor<'de> for Visitor { + type Value = DirectiveWrapper; + + fn expecting(&self, formatter: &mut std::fmt::Formatter) -> std::fmt::Result { + write!(formatter, "directive or list of directives") + } + + fn visit_str(self, s: &str) -> Result + where + E: de::Error, + { + s.parse().map_err(|_err| { + de::Error::invalid_value(de::Unexpected::Str(s), &"valid directive") + }) + } + + fn visit_seq(self, mut seq: A) -> Result + where + A: de::SeqAccess<'de>, + { + let mut rv = DirectiveWrapper(vec![]); + + while let Some(item) = seq.next_element::()? { + let parsed: DirectiveWrapper = item.parse().map_err(|_err| { + de::Error::invalid_value(de::Unexpected::Str(&item), &"valid directive") + })?; + rv += parsed; + } + + Ok(rv) + } + } + + let mut rv = deserializer.deserialize_any(Visitor)?; + + // Add settings from RUST_LOG env var, which should always be respected + if let Some(rust_log) = std::option_env!("RUST_LOG") { + let from_env: DirectiveWrapper = rust_log.parse().map_err(|_err| { + de::Error::invalid_value(de::Unexpected::Str(&rust_log), &"valid directive") + })?; + rv += from_env; + } + + Ok(rv) + } +} + +impl FromStr for DirectiveWrapper { + type Err = tracing_subscriber::filter::ParseError; + + fn from_str(s: &str) -> Result { + let parts: Vec = s.split(',').map(|s| s.to_string()).collect(); + // Test that each part can be parsed as a logging filter directive. + if let Some(err) = parts.iter().find_map(|p| p.parse::().err()) { + return Err(err); + } + // Wrap the string and return it. + Ok(Self(parts)) + } +} + +impl AddAssign for DirectiveWrapper { + fn add_assign(&mut self, rhs: Self) { + self.0.extend(rhs.0) + } +} + +impl From<&DirectiveWrapper> for EnvFilter { + fn from(val: &DirectiveWrapper) -> Self { + let mut rv = EnvFilter::default(); + for directive in &val.0 { + rv = rv.add_directive(directive.parse().unwrap()); + } + rv + } +} diff --git a/merino-web/Cargo.toml b/merino-web/Cargo.toml index 86b3a81076..f1b9d884a3 100644 --- a/merino-web/Cargo.toml +++ b/merino-web/Cargo.toml @@ -10,8 +10,11 @@ serde_json = "1.0.64" thiserror = "1.0.24" actix-cors = "0.6.0-beta.1" tokio = { version = "1.5.0", features = ["sync"] } -tokio-test = "0.4.1" anyhow = "1.0.40" merino-suggest = { path = "../merino-suggest" } merino-adm = { path = "../merino-adm" } merino-settings = { path = "../merino-settings" } +uuid = { version = "0.8.2", features = ["v4"] } +tracing = "0.1.26" +tokio-test = "0.4.1" +tracing-actix-web = { version = "0.4.0-beta.4", default_features = false } diff --git a/merino-web/src/dockerflow.rs b/merino-web/src/dockerflow.rs index 3256016d2b..e0a6586156 100644 --- a/merino-web/src/dockerflow.rs +++ b/merino-web/src/dockerflow.rs @@ -4,6 +4,7 @@ use std::collections::HashMap; use actix_web::{get, web, HttpRequest, HttpResponse}; use serde::Serialize; +use tracing::Level; use crate::errors::HandlerError; @@ -114,6 +115,7 @@ fn heartbeat(_: HttpRequest) -> HttpResponse { /// Returning an API error to test error handling. #[get("__error__")] -async fn test_error(_: HttpRequest) -> Result { +async fn test_error() -> Result { + tracing::event!(Level::ERROR, "The __error__ endpoint was called"); Err(HandlerError::Internal) } diff --git a/merino-web/src/lib.rs b/merino-web/src/lib.rs index 78c94f6fc3..4382426bf9 100644 --- a/merino-web/src/lib.rs +++ b/merino-web/src/lib.rs @@ -5,13 +5,14 @@ mod debug; mod dockerflow; mod errors; +mod logging; mod suggest; -use std::net::TcpListener; - use actix_cors::Cors; use actix_web::{dev::Server, web, App, HttpServer}; +use logging::MerinoRootSpanBuilder; use merino_settings::Settings; +use std::net::TcpListener; /// Run the web server /// @@ -69,6 +70,7 @@ pub fn run(listener: TcpListener, settings: Settings) -> Result((&settings).clone()) + .wrap(tracing_actix_web::TracingLogger::::new()) .wrap(Cors::permissive()) // The core functionality of Merino .service(web::scope("api/v1/suggest").configure(suggest::configure)) diff --git a/merino-web/src/logging.rs b/merino-web/src/logging.rs new file mode 100644 index 0000000000..964aef2374 --- /dev/null +++ b/merino-web/src/logging.rs @@ -0,0 +1,75 @@ +//! Loggers for the request/response cycle. + +use actix_web::{dev::ServiceResponse, http::StatusCode}; +use tracing::Span; +use tracing_actix_web::{RequestId, RootSpanBuilder}; + +/// A root span builder for tracing_actix_web to customize the extra fields we +/// log with requests, and to log an event when requests end. +pub struct MerinoRootSpanBuilder; + +impl RootSpanBuilder for MerinoRootSpanBuilder { + fn on_request_start(request: &actix_web::dev::ServiceRequest) -> tracing::Span { + let http_route: std::borrow::Cow<'static, str> = request + .match_pattern() + .map(Into::into) + .unwrap_or_else(|| "default".into()); + let http_method = request.method().as_str(); + + use actix_web::HttpMessage; + + let request_id = request.extensions().get::().cloned().unwrap(); + + let span = tracing::info_span!( + "HTTP request", + http.method = %http_method, + http.route = %http_route, + http.target = %request.uri().path_and_query().map(|p| p.as_str()).unwrap_or(""), + http.status_code = tracing::field::Empty, + request_id = %request_id, + exception.message = tracing::field::Empty, + exception.details = tracing::field::Empty, + ); + + span + } + + fn on_request_end(span: Span, outcome: &Result, actix_web::Error>) { + let status = match &outcome { + Ok(response) => { + if let Some(error) = response.response().error() { + handle_error(span, error) + } else { + span.record("http.status_code", &response.response().status().as_u16()); + response.status() + } + } + Err(error) => handle_error(span, error), + }; + + match status.as_u16() { + status_code if (100..400).contains(&status_code) => tracing::info!("Request success"), + status_code if (400..500).contains(&status_code) => { + tracing::warn!("Request client error") + } + status_code if (500..600).contains(&status_code) => { + tracing::error!("Request server error") + } + status_code => { + tracing::error!(%status_code, "Request ended with unknown status code {}", status_code); + } + }; + } +} + +/// Annotate the root request span with information about a request error. +fn handle_error(span: Span, error: &actix_web::Error) -> StatusCode { + let response_error = error.as_response_error(); + let status = response_error.status_code(); + span.record( + "exception.message", + &tracing::field::display(response_error), + ); + span.record("exception.details", &tracing::field::debug(response_error)); + status +} diff --git a/merino-web/src/suggest.rs b/merino-web/src/suggest.rs index ea1c0f066b..b2ad6ff82b 100644 --- a/merino-web/src/suggest.rs +++ b/merino-web/src/suggest.rs @@ -19,6 +19,7 @@ type SuggesterSet = OnceCell>>; /// Configure a route to use the Suggest service. pub fn configure(config: &mut ServiceConfig) { + tracing::info!("configuring suggest service"); config .data::(OnceCell::new()) .service(suggest); @@ -26,7 +27,7 @@ pub fn configure(config: &mut ServiceConfig) { /// Set up configured suggestion providers. async fn setup_suggesters(settings: &Settings) -> Result>> { - println!("Setting up suggesters"); + tracing::info!("Setting up suggesters"); let mut adm_rs_provider = merino_adm::remote_settings::RemoteSettingsSuggester::default(); adm_rs_provider .sync(settings) @@ -37,6 +38,7 @@ async fn setup_suggesters(settings: &Settings) -> Result> /// Suggest content in response to the queried text. #[get("")] +#[tracing::instrument(skip(query, suggesters, settings))] async fn suggest( query: Query, suggesters: Data, @@ -46,17 +48,21 @@ async fn suggest( .get_or_try_init(|| setup_suggesters(settings.as_ref())) .await .map_err(|e| { - println!( + tracing::error!( "suggester error {:?}\nchain: {:?}", e, e.chain().collect::>(), ); HandlerError::Internal })?; - let suggestions = suggesters + let suggestions: Vec = suggesters .iter() .flat_map(|sug| sug.suggest(&query.q)) .collect(); + tracing::info!( + suggestion_count = suggestions.len(), + "Providing suggestions" + ); Ok(HttpResponse::Ok().json(SuggestResponse { suggestions })) } diff --git a/merino/Cargo.toml b/merino/Cargo.toml index 5415b4cae7..3be6a6a17d 100644 --- a/merino/Cargo.toml +++ b/merino/Cargo.toml @@ -12,3 +12,6 @@ merino-web = { path = "../merino-web" } merino-settings = { path = "../merino-settings" } viaduct = { git = "https://github.com/mozilla/application-services", rev = "v75.0.0"} viaduct-reqwest = { git = "https://github.com/mozilla/application-services", rev = "v75.0.0"} +tracing-subscriber = { version = "0.2.18", features = ["registry", "env-filter"] } +tracing = "0.1.26" +tracing-log = "0.1.2" diff --git a/merino/src/docs/adrs/adr_0001_logging.rs b/merino/src/docs/adrs/adr_0001_logging.rs new file mode 100644 index 0000000000..e2752cca32 --- /dev/null +++ b/merino/src/docs/adrs/adr_0001_logging.rs @@ -0,0 +1,130 @@ +/*! +# Choosing a logging library for Merino + +- Status: accepted +- Date: 2021-05-11 + +Tracking issue: +[mozilla-services/merino#15](https://github.com/mozilla-services/merino/issues/15) + +## Context and Problem Statement + +Merino needs a system to produce logging. Rust has several options to do this, +with no clear winner. What library should Merino use? + +### The `log` Crate + +There is a de facto standard logging library for Rust, +[`log`](https://crates.io/crates/log). It is an important part of the decision, +but it is not a solution to the problem: it is a logging _facade_ that provides +a way for libraries to produce their own logs, but does not provide any logging +capabilities itself. Without a logger crate to use it with, the logs compile +away to nothing. + +## Decision Drivers + +- Sentry integration should be available +- MozLog format should be supported +- There should be both human and machine friendly logging output options. +- Library compatibility + +## Considered Options + +1. [slog](https://crates.io/crates/slog) +2. [tracing](https://crates.io/crates/tracing) +- Something from the `log` ecosystem + +## Decision Outcome + +Option 2 - Tracing. Although Slog has more momentum at this time, Tracing +sets us up for a better set of tools long term. + +## Pros and Cons of the Options + +### Option 1 - Slog + +> `slog` is an ecosystem of reusable components for structured, extensible, +> composable and contextual logging for Rust. + +Slog's first release was 0.1.0 in June of 2016, and it's 1.0 release was in +September of 2016. + +To use it, developers create logger objects that provide methods to produce log +lines and create sub-loggers. These loggers must be passed to lower level code +explicitly to be used. + +Slog is compatible with the de facto `log` crate. Log lines emitted using that +system (such as by libraries) can be routed to a logger object, with no loss of +detail. Few libraries use slog directly, and none of the libraries that are +currently used in Merino do at all. Since libraries aren't using `slog`, it will +be harder to make them participate in the logging hierarchy. + +Structured logging is supported. Logs can carry associated data, which can aid +in the machine readability of logs. + +The tree of loggers is built explicitly through the loggers objects, and +subloggers must be aware of superloggers, since the only way to get a sublogger +is to call a method on a logger. This separates the logging structure from the +call stack, but makes it awkward to recover that information should it be +helpful. This means that logging generally has to be passed as arguments to many +functions, making the tree of loggers less flexible. + +The Sentry library for Rust has support for slog. There is a a +[MozLog crate](https://crates.io/crates/slog-mozlog-json) for slog that Mozilla +wrote. + +- Good, because structured logging helps provide more useful logs. +- Good, because it has Sentry integration. +- Good, because it already has MozLog integration. +- Bad, because it has little library support. +- Bad, because explicitly building the logging tree is rigid. + +### Option 2 - Tracing + +> `tracing` is a framework for instrumenting Rust programs to collect +> structured, event-based diagnostic information. + +Tracing's first release was 0.0.0 in November of 2017. It has not had a 1.0 +release. It's latest release is 0.1.26, published April 2021. + +To use it, developers set up a global or scope-based subscriber of logs, which +collects _spans_ and _events_ that are generated in the code. Spans can be +`enter`ed and `exit`ed. During the time between these, all spans and events are +associated with the entered span as their parent. This association happens +explicitly, and can cross call boundaries. However, spans can be entered and +exited in more fine grained ways if needed. + +Tracing is compatible with the de facto `log` crate. Log lines emitted using +that system are seen as events in Tracing, with no loss of detail. + +Structured logging is supported. Both spans and events can carry associated +data. This data can be accessed hierarchically, building up a context of +execution. + +The tree of spans is built by entering spans. Loggers do not have to be aware of +their parents, their logs are placed in the context of whatever set of spans has +been entered at that moment. because [ one like we did with slog. + +Tracing is developed as a part of the Tokio ecosystem, the same that our web +framework (Actix), http client (Reqwest), and async runtime (Tokio) are +developed under. It has some library support. Additionally, since the tree of +spans is built more implicitly, libraries that use the `log` facade can +participate in our structured logging. + +[sentry-tracing]: https://github.com/getsentry/sentry-rust/issues/180 + +- Good, because structured logging helps provide more useful logs. +- Good, because it has good integration into the libraries we use. +- Good, because implicitly building the logging hierarchy and context is + flexible. +- Bad, because it lacks Sentry support. +- Bad, because it lacks MozLog support. + +### Option 3 - Something in the `log` ecosystem + +This option was not considered deeply because `log` does not support structured +logging. Not being able to attach concrete data to logs makes much of the +logging tasks much harder. + +- Bad, because it lacks structured logging. +*/ diff --git a/merino/src/docs/adrs/mod.rs b/merino/src/docs/adrs/mod.rs new file mode 100644 index 0000000000..820961ed24 --- /dev/null +++ b/merino/src/docs/adrs/mod.rs @@ -0,0 +1,3 @@ +//! Architecture Decision Records for Merino. + +mod adr_0001_logging; diff --git a/merino/src/docs/adrs/template.md b/merino/src/docs/adrs/template.md new file mode 100644 index 0000000000..f4795ee3a0 --- /dev/null +++ b/merino/src/docs/adrs/template.md @@ -0,0 +1,74 @@ +# [short title of solved problem and solution] + +- Status: [proposed | rejected | accepted | deprecated | … | superseded by + [ADR-0005](0005-example.md)] +- Date: [YYYY-MM-DD when the decision was last updated] + +Tracking issue: [ticket/issue URL] + +## Context and Problem Statement + +[Describe the context and problem statement, e.g., in free form using two to +three sentences. You may want to articulate the problem in form of a question.] + +## Decision Drivers + +- [driver 1, e.g., a force, facing concern, …] +- [driver 2, e.g., a force, facing concern, …] +- … + +## Considered Options + +1. [option 1] +2. [option 2] +3. [option 3] +4. … + +## Decision Outcome + +Chosen option: "[option 1]", because [justification. e.g., only option, which +meets k.o. criterion decision driver | which resolves force force | … | comes +out best (see below)]. + +### Positive Consequences + +- [e.g., improvement of quality attribute satisfaction, follow-up decisions + required, …] +- … + +### Negative Consequences + +- [e.g., compromising quality attribute, follow-up decisions required, …] +- … + +## Pros and Cons of the Options + +### Option 1 - … + +[example | description | pointer to more information | …] + +- Good, because [argument a] +- Bad, because [argument b] +- … + +### Option 2 - … + +[example | description | pointer to more information | …] + +- Good, because [argument a] +- Bad, because [argument b] +- … + +### Option 3 - … + +[example | description | pointer to more information | …] + +- Good, because [argument a] +- Bad, because [argument b] +- … + +## Links + +- [Link type] [Link to ADR] + +- … diff --git a/merino/src/docs/mod.rs b/merino/src/docs/mod.rs new file mode 100644 index 0000000000..a237e69f6e --- /dev/null +++ b/merino/src/docs/mod.rs @@ -0,0 +1,3 @@ +//! Non-code based documentation for Merino. + +mod adrs; diff --git a/merino/src/main.rs b/merino/src/main.rs index f6000e6448..83930eb224 100644 --- a/merino/src/main.rs +++ b/merino/src/main.rs @@ -13,14 +13,20 @@ //! - [merino-suggest](../merino_suggest/index.html) //! - [merino-web](../merino_web/index.html) +mod docs; + use anyhow::{Context, Result}; +use merino_settings::Settings; use std::net::TcpListener; +use tracing_log::LogTracer; +use tracing_subscriber::{layer::SubscriberExt, EnvFilter}; use viaduct_reqwest::ReqwestBackend; /// Primary entry point #[actix_rt::main] async fn main() -> Result<()> { let settings = merino_settings::Settings::load()?; + init_logging(&settings)?; viaduct::set_backend(&ReqwestBackend).context("setting viaduct backend")?; let listener = TcpListener::bind(settings.http.listen).context("Binding port")?; @@ -31,3 +37,17 @@ async fn main() -> Result<()> { Ok(()) } + +/// Set up logging for Merino, based on settings and the `RUST_LOG` environment variable. +fn init_logging(settings: &Settings) -> Result<()> { + LogTracer::init()?; + let env_filter: EnvFilter = (&settings.logging.levels).into(); + + let subscriber = tracing_subscriber::fmt::Subscriber::builder() + .pretty() + .finish() + .with(env_filter); + + tracing::subscriber::set_global_default(subscriber)?; + Ok(()) +}