tracing

Cargo.lock

@@ -463,6 +463,16 @@ dependencies = [
  "windows-sys",
 ]
 
+[[package]]
+name = "nu-ansi-term"
+version = "0.46.0"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "77a8165726e8236064dbb45459242600304b42a5ea24ee2948e18e023bf7ba84"
+dependencies = [
+ "overload",
+ "winapi",
+]
+
 [[package]]
 name = "num_cpus"
 version = "1.15.0"
@@ -479,6 +489,12 @@ version = "1.17.0"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "6f61fba1741ea2b3d6a1e3178721804bb716a68a6aeba1149b5d52e3d464ea66"
 
+[[package]]
+name = "overload"
+version = "0.1.1"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "b15813163c1d831bf4a13c3610c05c0d03b39feb07f7e09fa234dac9b15aaf39"
+
 [[package]]
 name = "parking_lot"
 version = "0.12.1"
@@ -704,6 +720,15 @@ dependencies = [
  "digest",
 ]
 
+[[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"
@@ -755,6 +780,15 @@ version = "0.1.1"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "20518fe4a4c9acf048008599e464deb21beeae3d3578418951a189c235a7a9a8"
 
+[[package]]
+name = "thread_local"
+version = "1.1.4"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "5516c27b78311c50bf42c071425c560ac799b11c30b31f87e3081965fe5e0180"
+dependencies = [
+ "once_cell",
+]
+
 [[package]]
 name = "time"
 version = "0.3.17"
@@ -905,9 +939,21 @@ dependencies = [
  "cfg-if",
  "log",
  "pin-project-lite",
+ "tracing-attributes",
  "tracing-core",
 ]
 
+[[package]]
+name = "tracing-attributes"
+version = "0.1.23"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "4017f8f45139870ca7e672686113917c71c7a6e02d4924eda67186083c03081a"
+dependencies = [
+ "proc-macro2",
+ "quote",
+ "syn",
+]
+
 [[package]]
 name = "tracing-core"
 version = "0.1.30"
@@ -915,6 +961,32 @@ source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "24eb03ba0eab1fd845050058ce5e616558e8f8d8fca633e6b163fe25c797213a"
 dependencies = [
  "once_cell",
+ "valuable",
+]
+
+[[package]]
+name = "tracing-log"
+version = "0.1.3"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "78ddad33d2d10b1ed7eb9d1f518a5674713876e97e5bb9b7345a7984fbb4f922"
+dependencies = [
+ "lazy_static",
+ "log",
+ "tracing-core",
+]
+
+[[package]]
+name = "tracing-subscriber"
+version = "0.3.16"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "a6176eae26dd70d0c919749377897b54a9276bd7061339665dd68777926b5a70"
+dependencies = [
+ "nu-ansi-term",
+ "sharded-slab",
+ "smallvec",
+ "thread_local",
+ "tracing-core",
+ "tracing-log",
 ]
 
 [[package]]
@@ -944,6 +1016,12 @@ version = "1.0.6"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "84a22b9f218b40614adcb3f4ff08b703773ad44fa9423e4e0d346d5db86e4ebc"
 
+[[package]]
+name = "valuable"
+version = "0.1.0"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "830b7e5d4d90034032940e4ace0d9a9a057e7a45cd94e6c007832e39edb82f6d"
+
 [[package]]
 name = "vcpkg"
 version = "0.2.15"
@@ -1067,4 +1145,6 @@ dependencies = [
  "tower",
  "tower-cookies",
  "tower-http",
+ "tracing",
+ "tracing-subscriber",
 ]

Cargo.toml

@@ -10,9 +10,11 @@ tower-http = { version = "0.3.5", features = ["fs"] }
 tower-cookies = "0.8.0"
 tower = "0.4.13"
 bytes = "1.3.0"
-serde = { version = "1.0.152", features = ["derive"] }
+serde = { version = "1.0", features = ["derive"] }
 serde_json = { version = "1.0", features = ["std"] }
 rusqlite = { version = "0.28.0", features = ["bundled"] }
 rand = "0.8.5"
 time = "0.3.17"
-lazy_static = "1.4.0"
+lazy_static = "1.4.0"
+tracing = "0.1.37"
+tracing-subscriber = "0.3.16"

src/console.rs

@@ -48,7 +48,7 @@ pub async fn log(ip: IpAddr, method: Method, uri: Uri, path: Option<String>, bod
     let path = path.unwrap_or_default();
     let body = body.unwrap_or_default();
 
-    println!("{} {} {}{} {}", &ip, &method, &path, &uri, &body);
+    tracing::info!("{} {} {}{} {}", &ip, &method, &path, &uri, &body);
     
     let message = LogMessage {
         ip: ip, 

src/database/posts.rs

@@ -2,6 +2,7 @@ use std::collections::HashSet;
 use std::time::{SystemTime, UNIX_EPOCH};
 
 use rusqlite::{OptionalExtension, Row};
+use tracing::instrument;
 
 use crate::types::post::Post;
 use crate::database;
@@ -42,14 +43,18 @@ fn post_from_row(row: &Row) -> Result<Post, rusqlite::Error> {
     Ok(Post{post_id, user_id, content, likes, comments, date})
 }
 
+#[instrument()]
 pub fn get_post(post_id: u64) -> Result<Option<Post>, rusqlite::Error> {
+    tracing::trace!("Retrieving post");
     let conn = database::connect()?;
     let mut stmt = conn.prepare("SELECT * FROM posts WHERE post_id = ?")?;
     let row = stmt.query_row([post_id], |row| Ok(post_from_row(row)?)).optional()?;
     Ok(row)
 }
 
+#[instrument()]
 pub fn get_post_page(page: u64) -> Result<Vec<Post>, rusqlite::Error> {
+    tracing::trace!("Retrieving posts page");
     let page_size = 10;
     let conn = database::connect()?;
     let mut stmt = conn.prepare("SELECT * FROM posts ORDER BY post_id DESC LIMIT ? OFFSET ?")?;
@@ -57,14 +62,18 @@ pub fn get_post_page(page: u64) -> Result<Vec<Post>, rusqlite::Error> {
     Ok(row.into_iter().flatten().collect())
 }
 
+#[instrument()]
 pub fn get_users_posts(user_id: u64) -> Result<Vec<Post>, rusqlite::Error> {
+    tracing::trace!("Retrieving users posts");
     let conn = database::connect()?;
     let mut stmt = conn.prepare("SELECT * FROM posts WHERE user_id = ? ORDER BY post_id DESC")?;
     let row = stmt.query_map([user_id], |row| Ok(post_from_row(row)?))?;
     Ok(row.into_iter().flatten().collect())
 }
 
+#[instrument()]
 pub fn add_post(user_id: u64, content: &str) -> Result<Post, rusqlite::Error> {
+    tracing::trace!("Adding post");
     let likes: HashSet<u64> = HashSet::new();
     let comments: Vec<(u64, String)> = Vec::new();
     let Ok(likes_json) = serde_json::to_string(&likes) else {
@@ -80,7 +89,9 @@ pub fn add_post(user_id: u64, content: &str) -> Result<Post, rusqlite::Error> {
     Ok(post)
 }
 
+#[instrument()]
 pub fn update_post(post_id: u64, likes: &HashSet<u64>, comments: &Vec<(u64, String)>) -> Result<(), rusqlite::Error> {
+    tracing::trace!("Updating post");
     let Ok(likes_json) = serde_json::to_string(&likes) else {
         return Err(rusqlite::Error::InvalidQuery)
     };

src/database/sessions.rs

@@ -1,8 +1,10 @@
 use rusqlite::OptionalExtension;
+use tracing::instrument;
 
 use crate::{database, types::session::Session};
 
 pub fn init() -> Result<(), rusqlite::Error> {
+    tracing::trace!("Retrieving posts page");
     let sql = "
         CREATE TABLE IF NOT EXISTS sessions (
             user_id        INTEGER PRIMARY KEY NOT NULL,
@@ -15,7 +17,9 @@ pub fn init() -> Result<(), rusqlite::Error> {
     Ok(())
 }
 
+#[instrument()]
 pub fn get_session(token: &str) -> Result<Option<Session>, rusqlite::Error> {
+    tracing::trace!("Retrieving session");
     let conn = database::connect()?;
     let mut stmt = conn.prepare("SELECT * FROM sessions WHERE token = ?")?;
     let row = stmt.query_row([token], |row| {
@@ -27,14 +31,18 @@ pub fn get_session(token: &str) -> Result<Option<Session>, rusqlite::Error> {
     Ok(row)
 }
 
+#[instrument()]
 pub fn set_session(user_id: u64, token: &str) -> Result<(), Box<dyn std::error::Error>> {
+    tracing::trace!("Setting new session");
     let conn = database::connect()?;
     let sql = "INSERT OR REPLACE INTO sessions (user_id, token) VALUES (?, ?);";
     conn.execute(sql, (user_id, token))?;
     Ok(())
 }
 
+#[instrument()]
 pub fn delete_session(user_id: u64) -> Result<(), Box<dyn std::error::Error>> {
+    tracing::trace!("Deleting session");
     let conn = database::connect()?;
     let sql = "DELETE FROM sessions WHERE user_id = ?;";
     conn.execute(sql, [user_id])?;

src/database/users.rs

@@ -1,5 +1,6 @@
 use std::time::{SystemTime, UNIX_EPOCH};
 use rusqlite::{OptionalExtension, Row};
+use tracing::instrument;
 
 use crate::{database, types::user::User};
 
@@ -40,28 +41,36 @@ fn user_from_row(row: &Row, hide_password: bool) -> Result<User, rusqlite::Error
     Ok(User{user_id, firstname, lastname, email, password, gender,date, day, month, year})
 }
 
+#[instrument()]
 pub fn get_user_by_id(user_id: u64, hide_password: bool) -> Result<Option<User>, rusqlite::Error> {
+    tracing::trace!("Retrieving user by id");
     let conn = database::connect()?;
     let mut stmt = conn.prepare("SELECT * FROM users WHERE user_id = ?")?;
     let row = stmt.query_row([user_id], |row| Ok(user_from_row(row, hide_password)?)).optional()?;
     Ok(row)
 }
 
+#[instrument()]
 pub fn get_user_by_email(email: &str, hide_password: bool) -> Result<Option<User>, rusqlite::Error> {
+    tracing::trace!("Retrieving user by email");
     let conn = database::connect()?;
     let mut stmt = conn.prepare("SELECT * FROM users WHERE email = ?")?;
     let row = stmt.query_row([email], |row| Ok(user_from_row(row, hide_password)?)).optional()?;
     Ok(row)
 }
 
+#[instrument()]
 pub fn get_user_by_password(password: &str, hide_password: bool) -> Result<Option<User>, rusqlite::Error> {
+    tracing::trace!("Retrieving user by password");
     let conn = database::connect()?;
     let mut stmt = conn.prepare("SELECT * FROM users WHERE password = ?")?;
     let row = stmt.query_row([password], |row| Ok(user_from_row(row, hide_password)?)).optional()?;
     Ok(row)
 }
 
+#[instrument()]
 pub fn get_user_page(page: u64, hide_password: bool) -> Result<Vec<User>, rusqlite::Error> {
+    tracing::trace!("Retrieving user page");
     let page_size = 5;
     let conn = database::connect()?;
     let mut stmt = conn.prepare("SELECT * FROM users ORDER BY user_id DESC LIMIT ? OFFSET ?")?;
@@ -69,7 +78,9 @@ pub fn get_user_page(page: u64, hide_password: bool) -> Result<Vec<User>, rusqli
     Ok(row.into_iter().flatten().collect())
 }
 
+#[instrument()]
 pub fn add_user(firstname: &str, lastname: &str, email: &str, password: &str, gender: &str, day: u8, month: u8, year: u32) -> Result<User, rusqlite::Error> {
+    tracing::trace!("Adding new user");
     let date = SystemTime::now().duration_since(UNIX_EPOCH).unwrap().as_millis() as u64;
 
     let conn = database::connect()?;

src/main.rs

@@ -1,7 +1,9 @@
 use std::net::SocketAddr;
 use axum::{Router, response::Response, http::Request, middleware::{Next, self}, extract::ConnectInfo, RequestExt, body::HttpBody, Extension};
 use tower_cookies::CookieManagerLayer;
-use types::{response::ResponseCode};
+use tracing::metadata::LevelFilter;
+use tracing_subscriber::{prelude::__tracing_subscriber_SubscriberExt, util::SubscriberInitExt, Layer, filter::filter_fn};
+use types::response::ResponseCode;
 
 use crate::{api::{pages, auth, users, posts}, types::extract::RouterURI};
 
@@ -42,6 +44,15 @@ async fn main() {
 
     database::init().unwrap();
 
+    let fmt_layer = tracing_subscriber::fmt::layer();
+    tracing_subscriber::registry() 
+        .with(
+            fmt_layer.with_filter(LevelFilter::TRACE).with_filter(filter_fn(|metadata| {
+                metadata.target().starts_with("xssbook")
+            }))
+        )
+        .init();
+
     let app = Router::new()
     .fallback(not_found)
     .nest("/", pages::router())
@@ -56,7 +67,7 @@ async fn main() {
     ).layer(CookieManagerLayer::new());
 
     let addr = "[::]:8080".parse::<std::net::SocketAddr>().unwrap();
-    println!("Listening on {}", addr);
+    tracing::info!("listening on {}", addr);
     
     axum::Server::bind(&addr)
         .serve(app.into_make_service_with_connect_info::<SocketAddr>())

src/types/extract.rs

@@ -27,6 +27,7 @@ impl<S> FromRequestParts<S> for AuthorizedUser where S: Send + Sync {
         };
     
         let Ok(user) = User::from_user_id(session.user_id, true)  else {
+            tracing::error!("Valid token but no valid user");
             return Err(ResponseCode::InternalServerError.text("Valid token but no valid user"))
         };
 
@@ -84,6 +85,7 @@ impl<T, S, B> FromRequest<S, B> for Json<T> where
     async fn from_request(mut req: Request<B>, state: &S) ->  Result<Self> {
 
         let Ok(ConnectInfo(info)) = req.extract_parts::<ConnectInfo<SocketAddr>>().await else {
+            tracing::error!("Failed to read connection info");
             return Err(ResponseCode::InternalServerError.text("Failed to read connection info"));
         };
         let method = req.method().clone();
@@ -91,6 +93,7 @@ impl<T, S, B> FromRequest<S, B> for Json<T> where
         let uri = req.uri().clone();
         
         let Ok(bytes) = Bytes::from_request(req, state).await else {
+            tracing::error!("Failed to read request body");
             return Err(ResponseCode::InternalServerError.text("Failed to read request body"));
         };
         

src/types/post.rs

@@ -1,5 +1,7 @@
+use core::fmt;
 use std::collections::HashSet;
 use serde::Serialize;
+use tracing::instrument;
 
 use crate::database;
 use crate::types::response::{Result, ResponseCode};
@@ -14,8 +16,17 @@ pub struct Post {
     pub date: u64
 }
 
+impl fmt::Debug for Post {
+    fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
+        f.debug_struct("Post")
+         .field("post_id", &self.post_id)
+         .finish()
+    }
+}
+
 impl Post {
 
+    #[instrument()]
     pub fn from_post_id(post_id: u64) -> Result<Self> {
         let Ok(Some(post)) = database::posts::get_post(post_id) else {
             return Err(ResponseCode::BadRequest.text("Post does not exist"))
@@ -24,15 +35,7 @@ impl Post {
         Ok(post)
     }
 
-    // pub fn from_post_ids(post_ids: Vec<u64>) -> Vec<Self> {
+    #[instrument()]
-    //     post_ids.iter().map(|id| {
-    //         let Ok(post) = Post::from_post_id(*id) else {
-    //             return None;
-    //         };
-    //         Some(post)
-    //     }).flatten().collect()
-    // }
-
     pub fn from_post_page(page: u64) -> Result<Vec<Self>> {
         let Ok(posts) = database::posts::get_post_page(page) else {
             return Err(ResponseCode::BadRequest.text("Failed to fetch posts"))
@@ -40,6 +43,7 @@ impl Post {
         Ok(posts)
     }
 
+    #[instrument()]
     pub fn from_user_id(user_id: u64) -> Result<Vec<Self>> {
         let Ok(posts) = database::posts::get_users_posts(user_id) else {
             return Err(ResponseCode::BadRequest.text("Failed to fetch posts"))
@@ -47,24 +51,29 @@ impl Post {
         Ok(posts)
     }
 
+    #[instrument()]
     pub fn new(user_id: u64, content: String) -> Result<Self> {
         let Ok(post) = database::posts::add_post(user_id, &content) else {
+            tracing::error!("Failed to create post");
             return Err(ResponseCode::InternalServerError.text("Failed to create post"))
         };
 
         Ok(post)
     }
 
+    #[instrument()]
     pub fn comment(&mut self, user_id: u64, content: String) -> Result<()> {
         self.comments.push((user_id, content));
         
         if database::posts::update_post(self.post_id, &self.likes, &self.comments).is_err() {
+            tracing::error!("Failed to comment on post");
             return Err(ResponseCode::InternalServerError.text("Failed to comment on post"))
         }
 
         Ok(())
     }
 
+    #[instrument()]
     pub fn like(&mut self, user_id: u64, state: bool) -> Result<()> {
 
         if state {
@@ -74,7 +83,8 @@ impl Post {
         }
         
         if database::posts::update_post(self.post_id, &self.likes, &self.comments).is_err() {
-            return Err(ResponseCode::InternalServerError.text("Failed to comment on post"))
+            tracing::error!("Failed to change like state on post");
+            return Err(ResponseCode::InternalServerError.text("Failed to change like state on post"))
         }
 
         Ok(())

src/types/response.rs

@@ -1,6 +1,7 @@
 use axum::{response::{IntoResponse, Response}, http::{StatusCode, Request, HeaderValue}, body::Body, headers::HeaderName};
 use tower::ServiceExt;
 use tower_http::services::ServeFile;
+use tracing::instrument;
 
 #[derive(Debug)]
 pub enum ResponseCode {
@@ -15,6 +16,7 @@ pub enum ResponseCode {
 }
 
 impl ResponseCode {
+
     pub fn code(self) -> StatusCode {
         match self {
             Self::Success => StatusCode::OK,
@@ -28,10 +30,12 @@ impl ResponseCode {
         }
     }
 
+    #[instrument()]
     pub fn text(self, msg: &str) -> Response {
         (self.code(), msg.to_owned()).into_response()
     }
 
+    #[instrument()]
     pub fn json(self, json: &str) -> Response {
         let mut res = (self.code(), json.to_owned()).into_response();
         res.headers_mut().insert(
@@ -40,6 +44,7 @@ impl ResponseCode {
         res
     }
 
+    #[instrument()]
     pub fn html(self, json: &str) -> Response {
         let mut res = (self.code(), json.to_owned()).into_response();
         res.headers_mut().insert(
@@ -48,6 +53,7 @@ impl ResponseCode {
         res
     }
 
+    #[instrument()]
     pub async fn file(self, path: &str) -> Result<Response> {
         if path.chars().position(|c| c == '.' ).is_none() {
             return Err(ResponseCode::BadRequest.text("Folders cannot be served"));
@@ -55,7 +61,8 @@ impl ResponseCode {
         let path = format!("public{}", path);
         let svc = ServeFile::new(path);
         let Ok(mut res) = svc.oneshot(Request::new(Body::empty())).await else {
-            return Err(ResponseCode::InternalServerError.text("Error wile fetching file"));
+            tracing::error!("Error while fetching file");
+            return Err(ResponseCode::InternalServerError.text("Error while fetching file"));
         };
         if res.status() != StatusCode::OK {
             return Err(ResponseCode::NotFound.text("File not found"));

src/types/session.rs

@@ -1,5 +1,6 @@
 use rand::{distributions::Alphanumeric, Rng};
 use serde::Serialize;
+use tracing::instrument;
 
 use crate::database;
 use crate::types::response::{Result, ResponseCode};
@@ -12,6 +13,7 @@ pub struct Session {
 
 impl Session {
 
+    #[instrument()]
     pub fn from_token(token: &str) -> Result<Self> {
         let Ok(Some(session)) = database::sessions::get_session(token) else {
             return Err(ResponseCode::BadRequest.text("Invalid auth token"));
@@ -20,6 +22,7 @@ impl Session {
         Ok(session)
     }
 
+    #[instrument()]
     pub fn new(user_id: u64) -> Result<Self> {
         let token: String = rand::thread_rng().sample_iter(&Alphanumeric).take(32).map(char::from).collect();
         match database::sessions::set_session(user_id, &token) {
@@ -28,8 +31,10 @@ impl Session {
         };
     }
 
+    #[instrument()]
     pub fn delete(user_id: u64) -> Result<()> {
         if let Err(_) = database::sessions::delete_session(user_id) {
+            tracing::error!("Failed to logout user");
             return Err(ResponseCode::InternalServerError.text("Failed to logout"));
         };
         Ok(())

src/types/user.rs

@@ -1,4 +1,5 @@
 use serde::{Serialize, Deserialize};
+use tracing::instrument;
 
 use crate::database;
 use crate::types::response::{Result, ResponseCode};
@@ -20,6 +21,7 @@ pub struct User {
 
 impl User {
 
+    #[instrument()]
     pub fn from_user_id(user_id: u64, hide_password: bool) -> Result<Self> {
         let Ok(Some(user)) = database::users::get_user_by_id(user_id, hide_password) else {
             return Err(ResponseCode::BadRequest.text("User does not exist"))
@@ -28,6 +30,7 @@ impl User {
         Ok(user)
     }
 
+    #[instrument()]
     pub fn from_user_ids(user_ids: Vec<u64>) -> Vec<Self> {
         user_ids.iter().map(|user_id| {
             let Ok(Some(user)) = database::users::get_user_by_id(*user_id, true) else {
@@ -37,6 +40,7 @@ impl User {
         }).flatten().collect()
     }
 
+    #[instrument()]
     pub fn from_user_page(page: u64) -> Result<Vec<Self>> {
         let Ok(users) = database::users::get_user_page(page, true) else {
             return Err(ResponseCode::BadRequest.text("Failed to fetch users"))
@@ -44,6 +48,7 @@ impl User {
         Ok(users)
     }
 
+    #[instrument()]
     pub fn from_email(email: &str) -> Result<Self> {
         let Ok(Some(user)) = database::users::get_user_by_email(email, false) else {
             return Err(ResponseCode::BadRequest.text("User does not exist"))
@@ -52,6 +57,7 @@ impl User {
         Ok(user)
     }
 
+    #[instrument()]
     pub fn from_password(password: &str) -> Result<Self> {
         let Ok(Some(user)) = database::users::get_user_by_password(password, true) else {
             return Err(ResponseCode::BadRequest.text("User does not exist"))
@@ -60,6 +66,7 @@ impl User {
         Ok(user)
     }
 
+    #[instrument()]
     pub fn new(firstname: String, lastname: String, email: String, password: String, gender: String, day: u8, month: u8, year: u32) -> Result<Self> {
         if let Ok(_) = User::from_email(&email) {
             return Err(ResponseCode::BadRequest.text(&format!("Email is already in use by {}", &email)))
@@ -70,6 +77,7 @@ impl User {
         }
         
         let Ok(user) = database::users::add_user(&firstname, &lastname, &email, &password, &gender, day, month, year) else {
+            tracing::error!("Failed to create new user");
             return Err(ResponseCode::InternalServerError.text("Failed to create new uesr"))
         };