elf
/
ztp
1
0
Fork 0
Code Issues Pull Requests Projects Releases Wiki Activity

Added Telemetry: Logging and Analytics 

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`
pub struct SessionId(pub Uuid);

pub async fn session_id<B>(mut req: Request<B>, next: Next<B>)
  -> Result<Response, StatusCode> {
    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<SessionId>,
    Extension(pool): Extension<PgPool>,
    payload: Option<Form<NewSubscription>>,
) -> 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"
}
```

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.
This commit is contained in:
Elf M. Sternberg 2023-03-26 16:03:24 -07:00
parent 5cad24268f
commit 17eb9bbc4d
7 changed files with 256 additions and 7 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

39
Cargo.lock generated
View File

@ -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",

3
Cargo.toml
View File

@ -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]

3
db/schema.sql
View File

@ -66,6 +66,3 @@ ALTER TABLE ONLY public.subscriptions
--
-- Dbmate schema migrations
--
INSERT INTO public.schema_migrations (version) VALUES
('20230322174957');

178
docs/06-telemetry.md Normal file
View File

@ -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<B>(mut req: Request<B>, next: Next<B>)
-> Result<Response, StatusCode> {
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<SessionId>,
Extension(pool): Extension<PgPool>,
payload: Option<Form<NewSubscription>>,
) -> 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.

16
src/lib.rs
View File

@ -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() {

10
src/routes/subscribe.rs
View File

@ -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<SessionId>,
Extension(pool): Extension<PgPool>,
payload: Option<Form<NewSubscription>>,
) -> 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)
}

14
src/session_id.rs Normal file
View File

@ -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<B>(mut req: Request<B>, next: Next<B>) -> Result<Response, StatusCode> {
req.extensions_mut().insert(SessionId(Uuid::new_v4()));
Ok(next.run(req).await)
}