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.
2021-11-16 13:50:32 +10:00 · 2021-11-16 13:50:32 +10:00 · 1f06f5e66f
commit 1f06f5e66f
parent a746b45f78
8 changed files with 252 additions and 15 deletions
--- 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"
--- 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"
 
--- a/src/lib.rs
+++ b/src/lib.rs
@ -1,3 +1,4 @@
 pub mod configuration;
 pub mod routes;
-pub mod startup;
+pub mod startup;
+pub mod telemetry;
--- 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(())
 }
--- 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<FormData>, pool: web::Data<PgPool>,) -> 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<FormData>, pool: web::Data<PgPool>,) -> 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(())
 }
--- 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<Server, std::io::Error> {
    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)?
--- a/src/telemetry.rs
+++ 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");
+}
--- 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())