diff --git a/Cargo.lock b/Cargo.lock index 231bea9..2c81fba 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -601,6 +601,12 @@ dependencies = [ "pin-project-lite", ] +[[package]] +name = "http-range-header" +version = "0.3.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "0bfe8eed0a9285ef776bb792479ea3834e8b94e13d615c2f66d03dd50a435a29" + [[package]] name = "httparse" version = "1.8.0" @@ -1714,6 +1720,25 @@ dependencies = [ "tracing", ] +[[package]] +name = "tower-http" +version = "0.4.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "5d1d42a9b3f3ec46ba828e8d376aec14592ea199f70a06a548587ecd1c4ab658" +dependencies = [ + "bitflags", + "bytes", + "futures-core", + "futures-util", + "http", + "http-body", + "http-range-header", + "pin-project-lite", + "tower-layer", + "tower-service", + "tracing", +] + [[package]] name = "tower-layer" version = "0.3.2" @@ -1771,6 +1796,16 @@ dependencies = [ "tracing-core", ] +[[package]] +name = "tracing-serde" +version = "0.1.3" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "bc6b213177105856957181934e4920de57730fc69bf42c37ee5bb664d406d9e1" +dependencies = [ + "serde", + "tracing-core", +] + [[package]] name = "tracing-subscriber" version = "0.3.16" @@ -1778,11 +1813,14 @@ source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "a6176eae26dd70d0c919749377897b54a9276bd7061339665dd68777926b5a70" dependencies = [ "nu-ansi-term", + "serde", + "serde_json", "sharded-slab", "smallvec", "thread_local", "tracing-core", "tracing-log", + "tracing-serde", ] [[package]] @@ -2121,6 +2159,7 @@ dependencies = [ "thiserror", "tokio", "tower", + "tower-http", "tracing", "tracing-subscriber", "uuid", diff --git a/Cargo.toml b/Cargo.toml index b025f53..d8a7629 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -21,8 +21,9 @@ sqlx = { version = "0.6.3", features = ["runtime-tokio-native-tls", "macros", "p thiserror = "1.0.40" tokio = { version = "1.26.0", features = ["full"] } tower = "0.4.13" +tower-http = { version = "0.4.0", features = ["trace", "tracing"] } tracing = "0.1.35" -tracing-subscriber = "0.3.14" +tracing-subscriber = { version = "0.3.16", features = ["json"] } uuid = { version = "1.3.0", features = ["v4", "serde"] } [profile.release] diff --git a/db/schema.sql b/db/schema.sql index 47a791c..907a9be 100644 --- a/db/schema.sql +++ b/db/schema.sql @@ -66,6 +66,3 @@ ALTER TABLE ONLY public.subscriptions -- -- Dbmate schema migrations -- - -INSERT INTO public.schema_migrations (version) VALUES - ('20230322174957'); diff --git a/docs/06-telemetry.md b/docs/06-telemetry.md new file mode 100644 index 0000000..c1900b9 --- /dev/null +++ b/docs/06-telemetry.md @@ -0,0 +1,178 @@ ++++ +title = "Telemetry: Logging and Analytics" +date = 2023-03-20T17:38:12Z +weight = 6 ++++ + +## Chapter 4: Telemetry + +In Chapter 4, Palmieri focuses on logging and telemetry. Axum is very different +from Actix, and my first foray into trying to understand it led me to +[Tower](https://docs.rs/tower/latest/tower/), the Rust community's de-facto +standards for modular networking development and design. + +I completely short-circuited much of what the book recommended and, instead, +just went with the most basic implementation possible. I added the tracing +libraries as recommended by the Axum developers, and then implemented the first +level of tracing as recommended by Tower: + +``` sh +$ cargo add --features tower_http/trace,tracing tower tower_http tracing tracing_subscriber +``` + +And then I updated the app startup code to include it: + +``` rust +pub async fn app(configuration: &Settings) -> Router { + tracing_subscriber::fmt::init(); + + let pool = PgPoolOptions::new() + .max_connections(50) + .connect(&configuration.database.url()) + .await + .expect("could not connect to database_url"); + + routes().layer(Extension(pool)).layer(TraceLayer::new_for_http()) +} +``` + +That is literally all that was needed. And the output is: + +``` plaintext +2023-03-25T16:49:06.385563Z DEBUG request{method=GET uri=/ version=HTTP/1.1}: + tower_http::trace::on_request: started processing request +2023-03-25T16:49:06.386270Z DEBUG request{method=GET uri=/ version=HTTP/1.1}: + tower_http::trace::on_response: finished processing request latency=0 ms + status=200 +``` + +That's not great logging, but it's a start. As I understand it, +`tracing_subscriber::fmt::init()` initializes the formatter, but I'm confused as +to where this is saved or stored, since it seems to be... nowhere. The deeper +Rust gets, the wilder it seems. + +What I did manage was to create, [as recommended by Chris +Allen](https://bitemyapp.com/blog/notes-on-zero2prod-rust/), a very simple Layer +that shoves a new object into the collection of data being passed around by the +request. That object contains a unique UUID for the session being processed. +Since Tokio is a multi-threaded system, having a UUID allows us to trace each +individual request from beginning to end... provided I've hooked up by handlers +just right. + +I learned most of this by reading the [Axum Session source +code](https://docs.rs/axum-sessions/latest/src/axum_sessions/session.rs.html), +which implements something much more complex. Since we're at a deeper level of +the service handling I need a function takes a Request and returns a Response, +and in the middle inserts a SessionId into the Request passed in; by giving the +type a name any handlers can now find and use that SessionId: + +``` rust +/// In file `session_id.rs` +#[derive(Clone)] +pub struct SessionId(pub Uuid); + +pub async fn session_id(mut req: Request, next: Next) + -> Result { + req.extensions_mut().insert(SessionId(Uuid::new_v4())); + Ok(next.run(req).await) +} +``` + +With that, I now need to add it to the layers initialized with the app object: + +```rust +/// In lib.rs:pub async fn app()`: + routes() + .layer(Extension(pool)) + .layer(TraceLayer::new_for_http()) + .layer(middleware::from_fn(session_id::session_id)) +``` + +And with that, the SessionId is available. Since it's the outermost layer, it +can now be used by anything deeper in. Let's add it to the `subscribe` +function: + +``` rust +/// In routes/subscribe.rs/subscribe() +pub(crate) async fn subscribe( + Extension(session): Extension, + Extension(pool): Extension, + payload: Option>, +) -> Result<(StatusCode, ()), ZTPError> { + if let Some(payload) = payload { + // Multi-line strings in Rust. Ugly. Would have preferred a macro. + let sql = r#"INSERT INTO subscriptions + (id, email, name, subscribed_at) + VALUES ($1, $2, $3, $4);"#.to_string(); + let subscription: Subscription = (&(payload.0)).into(); + + tracing::info!( + "request_id {} - Adding '{}' as a new subscriber.", + session.0.to_string(), + subscription.name + ); + // ... +``` + +And with that, every Request now has a strong ID associated with it: + +``` plaintext +2023-03-26T22:19:23.305421Z INFO ztp::routes::subscribe: + request_id d0f4a6e7-de0d-48bc-902b-713901c1d63b - + Adding 'Elf M. Sternberg' as a new subscriber. +``` + +That's a very noisy trace; I'd like to start knocking it down to something more +like a responsible log, or give me permission to format it the way I like. I'm +also getting incredibly noisy messages from the `sqlx::query` call, including +the text of the SQL template (the `let sql = ...` line above), which I really +don't need every time someone makes a request, and is horribly formatted for +principled analytics. + +Configuring it to return JSON turned out to be easy, although my first pass +puzzled me. I had to turn `json` formatting on as a feature: + +``` sh +$ cargo add --features=json tracing_subscriber +``` + +And then it was possible to configure the format: + +``` rust + // in lib.rs:app() + // ... + let format = tracing_subscriber::fmt::format() + .with_level(false) // don't include levels in formatted output + .with_thread_names(true) + .json(); // include the name of the current thread + + tracing_subscriber::fmt().event_format(format).init(); + // ... +``` + +``` json +{ + "timestamp":"2023-03-26T22:53:13.091366Z", + "fields": { + "message":"request_id 479014e2-5f13-4e12-8401-34d8f8bf1a18 - " + "Adding 'Elf M. Sternberg' as a new subscriber."}, + "target":"ztp::routes::subscribe", + "threadName":"tokio-runtime-worker" +} +``` + +## Conclusion + +This pretty much concludes my week-long foray into Palmieri's book; I'm not +going to worry too much about the deployment stuff, since that's part of my +daytime job and I'm not interesting in going over it again. + +Overall, this was an excellent book for teaching me many of the basics, and +provides a really good introduction into the way application servers can be +written in Rust. I disagree with the premise that "the language doesn't mean +anything to the outcome," as I've heard some people say, nor do I think using +Rust is some kind of badge of honor. Instead, I think it's a mark of a +responsible developer, one who can produce code that works well the first time, +and with some hard thinking about how types work (and some heavy-duty exposure +to Haskell), Rust development can be your first thought, not your "I need +speed!" thought, when developing HTTP-based application servers. diff --git a/src/lib.rs b/src/lib.rs index 3ce9bd7..fa6cfcf 100644 --- a/src/lib.rs +++ b/src/lib.rs @@ -1,6 +1,8 @@ -use axum::{Extension, Router}; +use axum::{middleware, Extension, Router}; use std::net::SocketAddr; +use tower_http::trace::TraceLayer; pub mod configuration; +pub mod session_id; use configuration::{get_configuration, Settings}; mod errors; mod routes; @@ -8,13 +10,23 @@ use routes::routes; use sqlx::postgres::PgPoolOptions; pub async fn app(configuration: &Settings) -> Router { + let format = tracing_subscriber::fmt::format() + .with_level(false) // don't include levels in formatted output + .with_thread_names(true) + .json(); // include the name of the current thread + + tracing_subscriber::fmt().event_format(format).init(); + let pool = PgPoolOptions::new() .max_connections(50) .connect(&configuration.database.url()) .await .expect("could not connect to database_url"); - routes().layer(Extension(pool)) + routes() + .layer(Extension(pool)) + .layer(TraceLayer::new_for_http()) + .layer(middleware::from_fn(session_id::session_id)) } pub async fn run() { diff --git a/src/routes/subscribe.rs b/src/routes/subscribe.rs index 49e74b5..89760bc 100644 --- a/src/routes/subscribe.rs +++ b/src/routes/subscribe.rs @@ -1,4 +1,5 @@ use crate::errors::ZTPError; +use crate::session_id::SessionId; use axum::{http::StatusCode, Extension, Form}; use chrono::{DateTime, Utc}; use sqlx::types::Uuid; @@ -30,6 +31,7 @@ impl From<&NewSubscription> for Subscription { } pub(crate) async fn subscribe( + Extension(session): Extension, Extension(pool): Extension, payload: Option>, ) -> Result<(StatusCode, ()), ZTPError> { @@ -37,6 +39,12 @@ pub(crate) async fn subscribe( let sql = "INSERT INTO subscriptions (id, email, name, subscribed_at) VALUES ($1, $2, $3, $4);".to_string(); let subscription: Subscription = (&(payload.0)).into(); + tracing::info!( + "request_id {} - Adding '{}' as a new subscriber.", + session.0.to_string(), + subscription.name + ); + sqlx::query(&sql) .bind(subscription.id) .bind(subscription.email) @@ -44,7 +52,7 @@ pub(crate) async fn subscribe( .bind(subscription.subscribed_at) .execute(&pool) .await - .map_or(Ok((StatusCode::OK, ())), |_| Err(ZTPError::DuplicateEmail)) + .map_or(Err(ZTPError::DuplicateEmail), |_| Ok((StatusCode::OK, ()))) } else { Err(ZTPError::FormIncomplete) } diff --git a/src/session_id.rs b/src/session_id.rs new file mode 100644 index 0000000..7b8fad2 --- /dev/null +++ b/src/session_id.rs @@ -0,0 +1,14 @@ +use axum::{ + http::{Request, StatusCode}, + middleware::Next, + response::Response, +}; +use uuid::Uuid; + +#[derive(Clone)] +pub struct SessionId(pub Uuid); + +pub async fn session_id(mut req: Request, next: Next) -> Result { + req.extensions_mut().insert(SessionId(Uuid::new_v4())); + Ok(next.run(req).await) +}