add logging

src/main.rs

@@ -3,11 +3,16 @@ use std::sync::{Arc, Mutex};
 use askama::Template;
 use axum::{
     Router,
-    extract::{Path, State},
+    extract::{MatchedPath, Path, State},
+    http::Request,
     response::Html,
     routing::{get, post},
 };
 use rusqlite::Connection;
+use tower_http::trace::TraceLayer;
+use tower_request_id::{RequestId, RequestIdLayer};
+use tracing::{debug, info, info_span};
+use tracing_subscriber::{layer::SubscriberExt as _, util::SubscriberInitExt as _};
 
 #[derive(Template)]
 #[template(path = "index.html")]
@@ -36,6 +41,21 @@ struct Food {
 
 #[tokio::main]
 async fn main() {
+    tracing_subscriber::registry()
+        .with(
+            tracing_subscriber::EnvFilter::try_from_default_env().unwrap_or_else(|_| {
+                // axum logs rejections from built-in extractors with the `axum::rejection`
+                // target, at `TRACE` level. `axum::rejection=trace` enables showing those events
+                format!(
+                    "{}=debug,tower_http=debug,axum::rejection=trace",
+                    env!("CARGO_CRATE_NAME")
+                )
+                .into()
+            }),
+        )
+        .with(tracing_subscriber::fmt::layer())
+        .init();
+
     let db_connecion_str = "./foods.db".to_string();
     let conn = Connection::open(db_connecion_str).unwrap();
     conn.execute(include_str!("create_tables.sql"), ()).unwrap();
@@ -45,10 +65,31 @@ async fn main() {
         .route("/", get(root))
         .route("/increase/{id}", post(increase))
         .route("/decrease/{id}", post(decrease))
+        .layer(
+            TraceLayer::new_for_http().make_span_with(|request: &Request<_>| {
+                let matched_path = request
+                    .extensions()
+                    .get::<MatchedPath>()
+                    .map(MatchedPath::as_str);
+                let request_id = request
+                    .extensions()
+                    .get::<RequestId>()
+                    .map(ToString::to_string)
+                    .unwrap_or_else(|| "unknown".into());
+                info_span!(
+                    "request",
+                    method = ?request.method(),
+                    matched_path,
+                    uri = ?request.uri(),
+                    id = %request_id,
+                )
+            }),
+        )
+        .layer(RequestIdLayer)
         .with_state(conn);
 
     let listener = tokio::net::TcpListener::bind("0.0.0.0:3001").await.unwrap();
-    println!("listening on {}", listener.local_addr().unwrap());
+    info!("listening on {}", listener.local_addr().unwrap());
     axum::serve(listener, app).await.unwrap();
 }
 
@@ -59,7 +100,7 @@ fn get_foods(conn: &Arc<Mutex<Connection>>) -> Vec<Food> {
             "SELECT id, portion, name, kc_per_serving, target_servings, actual_servings, color FROM food",
         )
         .unwrap();
-    let foods = stmt
+    let foods: Vec<_> = stmt
         .query_map((), |row| {
             Ok(Food {
                 id: row.get(0).unwrap(),
@@ -74,6 +115,7 @@ fn get_foods(conn: &Arc<Mutex<Connection>>) -> Vec<Food> {
         .unwrap()
         .collect::<Result<_, _>>()
         .unwrap();
+    debug!(num_foods = foods.len());
     foods
 }
 
@@ -83,6 +125,7 @@ fn get_sum(conn: &Arc<Mutex<Connection>>) -> i32 {
         .prepare("SELECT SUM(kc_per_serving * actual_servings) as kc FROM food")
         .unwrap();
     let sum = stmt.query_one((), |row| row.get(0)).unwrap();
+    debug!(sum);
     sum
 }
 
@@ -95,8 +138,9 @@ async fn root(State(conn): State<Arc<Mutex<Connection>>>) -> Html<String> {
 
 fn do_increase(conn: &Arc<Mutex<Connection>>, id: i32) {
     let conn = conn.lock().unwrap();
-    let mut stmt = conn.prepare("UPDATE food SET actual_servings = (SELECT actual_servings FROM food WHERE id = ?1) + 1 WHERE id = ?1").unwrap();
-    stmt.execute((id,)).unwrap();
+    let mut stmt = conn.prepare("UPDATE food SET actual_servings = (SELECT actual_servings FROM food WHERE id = ?1) + 1 WHERE id = ?1 RETURNING actual_servings").unwrap();
+    let new: i32 = stmt.query_one((id,), |row| row.get(0)).unwrap();
+    debug!(id, new_serving_count = new, "increase");
 }
 
 fn get_food(conn: &Arc<Mutex<Connection>>, id: i32) -> Food {
@@ -115,6 +159,7 @@ fn get_food(conn: &Arc<Mutex<Connection>>, id: i32) -> Food {
             })
         })
         .unwrap();
+    debug!(?food);
     food
 }
 
@@ -128,8 +173,9 @@ async fn increase(State(conn): State<Arc<Mutex<Connection>>>, Path(id): Path<i32
 
 fn do_decrease(conn: &Arc<Mutex<Connection>>, id: i32) {
     let conn = conn.lock().unwrap();
-    let mut stmt = conn.prepare("UPDATE food SET actual_servings = MAX((SELECT actual_servings FROM food WHERE id = ?1) - 1, 0) WHERE id = ?1").unwrap();
-    stmt.execute((id,)).unwrap();
+    let mut stmt = conn.prepare("UPDATE food SET actual_servings = MAX((SELECT actual_servings FROM food WHERE id = ?1) - 1, 0) WHERE id = ?1 RETURNING actual_servings").unwrap();
+    let new: i32 = stmt.query_one((id,), |row| row.get(0)).unwrap();
+    debug!(id, new_serving_count = new, "decrease");
 }
 
 async fn decrease(State(conn): State<Arc<Mutex<Connection>>>, Path(id): Path<i32>) -> Html<String> {