From 487d97cb019ef1a37d3ef90c6b051ba0389c6d15 Mon Sep 17 00:00:00 2001 From: Tyler Murphy Date: Sat, 28 Jan 2023 11:52:32 -0500 Subject: [PATCH] tracing --- Cargo.lock | 80 ++++++++++++++++++++++++++++++++++++++++ Cargo.toml | 6 ++- src/console.rs | 2 +- src/database/posts.rs | 11 ++++++ src/database/sessions.rs | 8 ++++ src/database/users.rs | 11 ++++++ src/main.rs | 15 +++++++- src/types/extract.rs | 3 ++ src/types/post.rs | 30 ++++++++++----- src/types/response.rs | 9 ++++- src/types/session.rs | 5 +++ src/types/user.rs | 8 ++++ 12 files changed, 172 insertions(+), 16 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index b490d6b..defab1a 100644 --- a/Cargo.lock +++ b/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", ] diff --git a/Cargo.toml b/Cargo.toml index e81c936..f74b284 100644 --- a/Cargo.toml +++ b/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" \ No newline at end of file +lazy_static = "1.4.0" +tracing = "0.1.37" +tracing-subscriber = "0.3.16" \ No newline at end of file diff --git a/src/console.rs b/src/console.rs index 660fb25..756bf56 100644 --- a/src/console.rs +++ b/src/console.rs @@ -48,7 +48,7 @@ pub async fn log(ip: IpAddr, method: Method, uri: Uri, path: Option, 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, diff --git a/src/database/posts.rs b/src/database/posts.rs index 96cd18a..6ee5e0f 100644 --- a/src/database/posts.rs +++ b/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 { Ok(Post{post_id, user_id, content, likes, comments, date}) } +#[instrument()] pub fn get_post(post_id: u64) -> Result, 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, 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, rusqlite::Error> { Ok(row.into_iter().flatten().collect()) } +#[instrument()] pub fn get_users_posts(user_id: u64) -> Result, 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 { + tracing::trace!("Adding post"); let likes: HashSet = 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 { Ok(post) } +#[instrument()] pub fn update_post(post_id: u64, likes: &HashSet, 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) }; diff --git a/src/database/sessions.rs b/src/database/sessions.rs index 7866d76..a2a2f6e 100644 --- a/src/database/sessions.rs +++ b/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, 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, rusqlite::Error> { Ok(row) } +#[instrument()] pub fn set_session(user_id: u64, token: &str) -> Result<(), Box> { + 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> { + tracing::trace!("Deleting session"); let conn = database::connect()?; let sql = "DELETE FROM sessions WHERE user_id = ?;"; conn.execute(sql, [user_id])?; diff --git a/src/database/users.rs b/src/database/users.rs index 2618dce..56b8814 100644 --- a/src/database/users.rs +++ b/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 Result, 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, 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, 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, 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, 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 { + tracing::trace!("Adding new user"); let date = SystemTime::now().duration_since(UNIX_EPOCH).unwrap().as_millis() as u64; let conn = database::connect()?; diff --git a/src/main.rs b/src/main.rs index 54c73c1..ab5a9cc 100644 --- a/src/main.rs +++ b/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::().unwrap(); - println!("Listening on {}", addr); + tracing::info!("listening on {}", addr); axum::Server::bind(&addr) .serve(app.into_make_service_with_connect_info::()) diff --git a/src/types/extract.rs b/src/types/extract.rs index 399fe67..69c6ed8 100644 --- a/src/types/extract.rs +++ b/src/types/extract.rs @@ -27,6 +27,7 @@ impl FromRequestParts 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 FromRequest for Json where async fn from_request(mut req: Request, state: &S) -> Result { let Ok(ConnectInfo(info)) = req.extract_parts::>().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 FromRequest for Json 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")); }; diff --git a/src/types/post.rs b/src/types/post.rs index 7805a4e..7ca0a3c 100644 --- a/src/types/post.rs +++ b/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 { 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) -> Vec { - // post_ids.iter().map(|id| { - // let Ok(post) = Post::from_post_id(*id) else { - // return None; - // }; - // Some(post) - // }).flatten().collect() - // } - + #[instrument()] pub fn from_post_page(page: u64) -> Result> { 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> { 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 { 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(()) diff --git a/src/types/response.rs b/src/types/response.rs index 72c1334..de572b2 100644 --- a/src/types/response.rs +++ b/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 { 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")); diff --git a/src/types/session.rs b/src/types/session.rs index 9b949be..e05dc49 100644 --- a/src/types/session.rs +++ b/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 { 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 { 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(()) diff --git a/src/types/user.rs b/src/types/user.rs index 56ef467..031946a 100644 --- a/src/types/user.rs +++ b/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 { 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) -> Vec { 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> { 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 { 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 { 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 { 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")) };