From 1f06f5e66fb1adcc40d164ae7614431899a67870 Mon Sep 17 00:00:00 2001 From: Nick Bland Date: Tue, 16 Nov 2021 13:50:32 +1000 Subject: [PATCH] Changes to allow more dynamic logging Logs in much greater detail using the tracing packages and formatted using Bunyan. Advised to install bunyan on machine for more pretty logs over raw json. --- Cargo.lock | 158 ++++++++++++++++++++++++++++++++++++ Cargo.toml | 7 ++ src/lib.rs | 3 +- src/main.rs | 7 +- src/routes/subscriptions.rs | 38 +++++++-- src/startup.rs | 9 +- src/telemetry.rs | 28 +++++++ tests/health_check.rs | 17 +++- 8 files changed, 252 insertions(+), 15 deletions(-) create mode 100644 src/telemetry.rs diff --git a/Cargo.lock b/Cargo.lock index f2d680f..0f6e36d 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -228,6 +228,15 @@ dependencies = [ "memchr", ] +[[package]] +name = "ansi_term" +version = "0.12.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "d52a9bb7ec0cf484c551830a7ce27bd20d67eac647e1befb56b0be4ee39a55d2" +dependencies = [ + "winapi", +] + [[package]] name = "arrayvec" version = "0.5.2" @@ -660,6 +669,16 @@ dependencies = [ "version_check", ] +[[package]] +name = "gethostname" +version = "0.2.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "e692e296bfac1d2533ef168d0b60ff5897b8b70a4009276834014dd8924cc028" +dependencies = [ + "libc", + "winapi", +] + [[package]] name = "getrandom" version = "0.2.3" @@ -963,13 +982,29 @@ dependencies = [ "actix-web", "chrono", "config", + "once_cell", "reqwest", "serde 1.0.130", "sqlx", "tokio", + "tracing", + "tracing-actix-web", + "tracing-bunyan-formatter", + "tracing-futures", + "tracing-log", + "tracing-subscriber", "uuid", ] +[[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.9" @@ -1353,6 +1388,15 @@ dependencies = [ "regex-syntax", ] +[[package]] +name = "regex-automata" +version = "0.1.10" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "6c230d73fb8d8c1b9c0b3135c5142a8acee3a0558fb8db5cf1cb65f8d7862132" +dependencies = [ + "regex-syntax", +] + [[package]] name = "regex-syntax" version = "0.6.25" @@ -1636,6 +1680,15 @@ dependencies = [ "opaque-debug", ] +[[package]] +name = "sharded-slab" +version = "0.1.4" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "900fba806f70c630b0a382d0d825e17a0f19fcd059a2ade1ff237bcddf446b31" +dependencies = [ + "lazy_static", +] + [[package]] name = "signal-hook-registry" version = "1.4.0" @@ -1904,6 +1957,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.1.43" @@ -2064,10 +2126,53 @@ source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "375a639232caf30edfc78e8d89b2d4c375515393e7af7e16f01cd96917fb2105" dependencies = [ "cfg-if", + "log", "pin-project-lite", + "tracing-attributes", "tracing-core", ] +[[package]] +name = "tracing-actix-web" +version = "0.4.0-beta.16" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "f2c2b77e219084424d5928fc42557bdaa011a8ef00a1c8492adcfc8fb8bb83c6" +dependencies = [ + "actix-web", + "pin-project", + "tracing", + "tracing-futures", + "uuid", +] + +[[package]] +name = "tracing-attributes" +version = "0.1.18" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "f4f480b8f81512e825f337ad51e94c1eb5d3bbdf2b363dcd01e2b19a9ffe3f8e" +dependencies = [ + "proc-macro2", + "quote", + "syn", +] + +[[package]] +name = "tracing-bunyan-formatter" +version = "0.1.7" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "06718867c20ea03700d41a9413610cccf5d772caea792f34cc73cdd43f0e14a6" +dependencies = [ + "chrono", + "gethostname", + "log", + "serde 1.0.130", + "serde_json", + "tracing", + "tracing-core", + "tracing-log", + "tracing-subscriber", +] + [[package]] name = "tracing-core" version = "0.1.21" @@ -2077,6 +2182,59 @@ dependencies = [ "lazy_static", ] +[[package]] +name = "tracing-futures" +version = "0.2.5" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "97d095ae15e245a057c8e8451bab9b3ee1e1f68e9ba2b4fbc18d0ac5237835f2" +dependencies = [ + "pin-project", + "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.130", + "tracing-core", +] + +[[package]] +name = "tracing-subscriber" +version = "0.2.25" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "0e0d2eaa99c3c2e41547cfa109e910a68ea03823cccad4a0525dcbc9b01e8c71" +dependencies = [ + "ansi_term", + "chrono", + "lazy_static", + "matchers", + "regex", + "serde 1.0.130", + "serde_json", + "sharded-slab", + "smallvec", + "thread_local", + "tracing", + "tracing-core", + "tracing-log", + "tracing-serde", +] + [[package]] name = "try-lock" version = "0.2.3" diff --git a/Cargo.toml b/Cargo.toml index 75816e4..e72c7e8 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -13,6 +13,12 @@ config = "0.11.0" serde = { version = "1", features = ["derive"]} uuid = { version = "0.8.1", features = ["v4"] } chrono = "0.4.15" +tracing = "0.1.19" +tracing-futures = "0.2.4" +tracing-subscriber = { version = "0.2.12", features = ["registry", "env-filter"] } +tracing-bunyan-formatter = "0.1.6" +tracing-log = "0.1.1" +tracing-actix-web = "0.4.0-beta.12" [dependencies.sqlx] version = "0.5.7" @@ -28,6 +34,7 @@ features = [ [dev-dependencies] actix-rt = "2" +once_cell = "1.8.0" reqwest = "0.11" tokio = "1" \ No newline at end of file diff --git a/src/lib.rs b/src/lib.rs index c50b134..1555d5a 100644 --- a/src/lib.rs +++ b/src/lib.rs @@ -1,3 +1,4 @@ pub mod configuration; pub mod routes; -pub mod startup; \ No newline at end of file +pub mod startup; +pub mod telemetry; \ No newline at end of file diff --git a/src/main.rs b/src/main.rs index 93bff68..1074c73 100644 --- a/src/main.rs +++ b/src/main.rs @@ -1,10 +1,14 @@ use mail_app::startup::run; use mail_app::configuration::get_configuration; +use mail_app::telemetry::{get_subscriber, init_subscriber}; use std::net::TcpListener; use sqlx::PgPool; #[actix_web::main] async fn main() -> std::io::Result<()> { + let subscriber = get_subscriber("mail_app".into(), "info".into(), std::io::stdout); + init_subscriber(subscriber); + // Attempt to read from config let configuration = get_configuration().expect("Failed to read configuration data."); @@ -16,5 +20,6 @@ async fn main() -> std::io::Result<()> { // Take port from settings file let address = format!("127.0.0.1:{}", configuration.application_port); let listener = TcpListener::bind(address)?; - run(listener, connection_pool)?.await + run(listener, connection_pool)?.await?; + Ok(()) } \ No newline at end of file diff --git a/src/routes/subscriptions.rs b/src/routes/subscriptions.rs index 13b7edf..6b7b89f 100644 --- a/src/routes/subscriptions.rs +++ b/src/routes/subscriptions.rs @@ -2,6 +2,7 @@ use actix_web::{web, HttpResponse}; use sqlx::PgPool; use chrono::Utc; use uuid::Uuid; +// use tracing_futures::Instrument; #[derive(serde::Deserialize)] pub struct FormData { @@ -9,10 +10,31 @@ pub struct FormData { name: String } +#[allow(clippy::async_yields_async)] +#[tracing::instrument( + name = "Adding a new subscriber", + skip(form, pool), + fields( + subscriber_email = %form.email, + subscriber_name = %form.name + ) +)] + pub async fn subscribe(form: web::Form, pool: web::Data,) -> HttpResponse { + match insert_subscriber(&pool, &form).await { + Ok(_) => HttpResponse::Ok().finish(), + Err(_) => HttpResponse::InternalServerError().finish(), + } +} + +#[tracing::instrument( + name = "Saving new subscriber details in the database", + skip(form, pool) +)] +pub async fn insert_subscriber(pool: &PgPool, form: &FormData) -> Result<(), sqlx::Error> { // _connect uses PgPool from the application state as defined in startup.rs // Use a match statement for the query as it only returns two outcomes - match sqlx::query!( + sqlx::query!( r#" INSERT INTO subscriptions (id, email, name, subscribed_at) VALUES($1, $2, $3, $4) @@ -22,13 +44,11 @@ pub async fn subscribe(form: web::Form, pool: web::Data,) -> H form.name, Utc::now() ) - .execute(pool.as_ref()) + .execute(pool) .await - { - Ok(_) => HttpResponse::Ok().finish(), - Err(e) => { - println!("Failed to execute query: {}", e); - HttpResponse::InternalServerError().finish() - } - } + .map_err(|e| { + tracing::error!("Failed to execute query: {:?}", e); + e + })?; + Ok(()) } \ No newline at end of file diff --git a/src/startup.rs b/src/startup.rs index 6c4de05..485a885 100644 --- a/src/startup.rs +++ b/src/startup.rs @@ -1,16 +1,19 @@ use actix_web::{web, App, HttpServer}; use actix_web::dev::Server; +use actix_web::web::Data; use std::net::TcpListener; use sqlx::PgPool; +use tracing_actix_web::TracingLogger; -use crate::routes; +use crate::routes::{health_check, subscribe}; pub fn run(listener: TcpListener, db_pool: PgPool) -> Result { let db_pool = web::Data::new(db_pool); // Wrap connection in a smart pointer let server = HttpServer::new(move || { App::new() - .route("/health_check", web::get().to(routes::health_check)) - .route("/subscriptions", web::post().to(routes::subscribe)) + .wrap(TracingLogger::default()) + .route("/health_check", web::get().to(health_check)) + .route("/subscriptions", web::post().to(subscribe)) .app_data(db_pool.clone()) // Get pointer copy and attach to application state }) .listen(listener)? diff --git a/src/telemetry.rs b/src/telemetry.rs new file mode 100644 index 0000000..51a5c9d --- /dev/null +++ b/src/telemetry.rs @@ -0,0 +1,28 @@ +use tracing::{Subscriber, subscriber::set_global_default}; +use tracing_bunyan_formatter::{BunyanFormattingLayer, JsonStorageLayer}; +use tracing_log::LogTracer; +use tracing_subscriber::{layer::SubscriberExt, EnvFilter, Registry, fmt::MakeWriter}; + +/// Compose multiple layers into a tracing compatible subscriber +pub fn get_subscriber( + name: String, + env_filter: String, + sink: impl MakeWriter + Send + Sync + 'static, +) -> impl Subscriber + Sync + Send { + let env_filter = EnvFilter::try_from_default_env() + .unwrap_or_else(|_| EnvFilter::new(env_filter)); + let formatting_layer = BunyanFormattingLayer::new( + name, + sink + ); + Registry::default() + .with(env_filter) + .with(JsonStorageLayer) + .with(formatting_layer) +} + +/// Register a subscriber as global default to process span data. +pub fn init_subscriber(subscriber: impl Subscriber + Sync + Send) { + LogTracer::init().expect("Failed to set logger"); + set_global_default(subscriber).expect("Failed to set subscriber"); +} \ No newline at end of file diff --git a/tests/health_check.rs b/tests/health_check.rs index 3eec10a..a446eba 100644 --- a/tests/health_check.rs +++ b/tests/health_check.rs @@ -1,17 +1,33 @@ use std::net::TcpListener; use sqlx::{Connection, Executor, PgConnection, PgPool}; use uuid::Uuid; +use once_cell::sync::Lazy; use mail_app::startup::run; use mail_app::configuration::{get_configuration, DatabaseSettings}; +use mail_app::telemetry::{get_subscriber, init_subscriber}; pub struct TestApp { pub address: String, pub db_pool: PgPool, } +static TRACING: Lazy<()> = Lazy::new(|| { + let default_filter_level = "info".to_string(); + let subscriber_name = "test".to_string(); + if std::env::var("TEST_LOG").is_ok() { + let subscriber = get_subscriber(subscriber_name, default_filter_level, std::io::stdout); + init_subscriber(subscriber); + } else { + let subscriber = get_subscriber(subscriber_name, default_filter_level, std::io::sink); + init_subscriber(subscriber); + }; +}); + // Create new instance of the application on a random port and return address [`http://localhost:XXXX`] async fn spawn_app() -> TestApp { + Lazy::force(&TRACING); + let listener = TcpListener::bind("127.0.0.1:0") .expect("Failed to bind to random port"); let port = listener.local_addr().unwrap().port(); @@ -20,7 +36,6 @@ async fn spawn_app() -> TestApp { let mut configuration = get_configuration() .expect("Failed to read configuration."); configuration.database.database_name = Uuid::new_v4().to_string(); // Adjust database string to be random! - let connection_pool = configure_database(&configuration.database).await; let server = run(listener, connection_pool.clone())