From a499dc5cbabf2e70bdc9768289ca837b80e44c97 Mon Sep 17 00:00:00 2001 From: Sebastian Pravda Date: Thu, 15 Dec 2022 13:55:29 +0100 Subject: [PATCH 1/3] feat: initial logging implementation --- Cargo.lock | 13 +++++++++ api/Cargo.toml | 4 +++ api/src/lib.rs | 28 ++++++++++++++++++- api/src/logging.rs | 36 +++++++++++++++++++++++++ api/src/pool.rs | 3 ++- api/src/routes/mod.rs | 4 +++ core/Cargo.toml | 4 +++ core/src/database/mutation/candidate.rs | 19 ++++++++++--- core/src/error.rs | 21 ++++++++++++++- core/src/services/parent_service.rs | 10 ------- core/src/services/portfolio_service.rs | 16 +++++++++-- 11 files changed, 139 insertions(+), 19 deletions(-) create mode 100644 api/src/logging.rs diff --git a/Cargo.lock b/Cargo.lock index 7d061c8..23be0b9 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -884,6 +884,15 @@ dependencies = [ "instant", ] +[[package]] +name = "fern" +version = "0.6.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "3bdd7b0849075e79ee9a1836df22c717d1eba30451796fdc631b04565dd11e2a" +dependencies = [ + "log", +] + [[package]] name = "figment" version = "0.10.8" @@ -2022,6 +2031,8 @@ dependencies = [ "async-trait", "chrono", "dotenv", + "fern", + "log", "once_cell", "portfolio-core", "portfolio-entity", @@ -2058,8 +2069,10 @@ dependencies = [ "chrono", "csv", "dotenv", + "fern", "futures", "infer", + "log", "once_cell", "portfolio-entity", "rand 0.8.5", diff --git a/api/Cargo.toml b/api/Cargo.toml index 67a8da3..201451b 100644 --- a/api/Cargo.toml +++ b/api/Cargo.toml @@ -19,6 +19,10 @@ serde_json = { version = "^1.0" } chrono = "^0.4" +# logging +log = "0.4" +fern = "0.6" + portfolio-entity = { path = "../entity" } portfolio-migration = { path = "../migration" } portfolio-core = { path = "../core" } diff --git a/api/src/lib.rs b/api/src/lib.rs index bb1b2d7..29499c0 100644 --- a/api/src/lib.rs +++ b/api/src/lib.rs @@ -1,6 +1,7 @@ #[macro_use] extern crate rocket; +use logging::Logging; use rocket::fairing::{self, AdHoc, Fairing, Info, Kind}; use rocket::http::Header; @@ -13,6 +14,7 @@ mod guards; mod pool; mod requests; mod routes; +mod logging; pub mod test; use pool::Db; @@ -70,6 +72,25 @@ async fn hello() -> &'static str { "Hello, world!" } +fn setup_logger() -> Result<(), fern::InitError> { + fern::Dispatch::new() + .format(|out, message, record| { + out.finish(format_args!( + "{}[{}][{}] {}", + chrono::Local::now().format("[%Y-%m-%d][%H:%M:%S]"), + record.target(), + record.level(), + message + )) + }) + .filter(|m| m.target() != "_" && m.target() != "rocket::server") // suppress rocket.rs messages + .level(::log::LevelFilter::Info) + .chain(std::io::stdout()) + .chain(fern::log_file("output.log")?) + .apply()?; + Ok(()) +} + async fn run_migrations(rocket: Rocket) -> fairing::Result { let conn = &Db::fetch(&rocket).unwrap().conn; let _ = migration::Migrator::up(conn, None).await; @@ -78,10 +99,10 @@ async fn run_migrations(rocket: Rocket) -> fairing::Result { pub fn rocket() -> Rocket { rocket::build() + .attach(Logging) .attach(CORS) .attach(Db::init()) .attach(AdHoc::try_on_ignite("Migrations", run_migrations)) - //.mount("/", FileServer::from(relative!("/static"))) .mount("/", routes![hello, all_options]) .mount( "/candidate/", @@ -137,6 +158,11 @@ pub fn rocket() -> Rocket { #[tokio::main] async fn start() -> Result<(), rocket::Error> { + let result = setup_logger(); + if let Some(err) = result.err() { + panic!("Error: {}", err); + } + rocket().launch().await.map(|_| ()) } diff --git a/api/src/logging.rs b/api/src/logging.rs new file mode 100644 index 0000000..702c4a1 --- /dev/null +++ b/api/src/logging.rs @@ -0,0 +1,36 @@ +use std::net::Ipv4Addr; + +use rocket::{fairing::{Fairing, Info, Kind}, Request, Data}; + +pub struct Logging; + +#[rocket::async_trait] +impl Fairing for Logging { + fn info(&self) -> rocket::fairing::Info { + Info { + name: "Log", + kind: Kind::Request, + } + } + + async fn on_request(&self, request: &mut Request<'_>, d: &mut Data<'_>) { + let client_ip = request.client_ip().unwrap_or(std::net::IpAddr::V4(Ipv4Addr::new(127, 0, 0, 1))).to_string(); + + let method = request.method().to_string(); + + let uri = request.uri().to_string(); + let host = request.headers().get_one("Host").unwrap_or("").to_string(); + let user_agent = request.headers().get_one("User-Agent").unwrap_or("").to_string(); + let content_length = request.headers().get_one("Content-Length").unwrap_or("").to_string(); + + info!("[{}] {} {} (User-Agent: {}, Content-Length: {}, Host: {})", + client_ip, + method, + uri, + user_agent, + content_length, + host, + ); + + } +} \ No newline at end of file diff --git a/api/src/pool.rs b/api/src/pool.rs index ab4c715..153f2b2 100644 --- a/api/src/pool.rs +++ b/api/src/pool.rs @@ -37,7 +37,8 @@ impl sea_orm_rocket::Pool for SeaOrmPool { options .max_connections(1024) .min_connections(0) - .connect_timeout(Duration::from_secs(3)); + .connect_timeout(Duration::from_secs(3)) + .sqlx_logging(false); /* options .max_connections(config.max_connections as u32) diff --git a/api/src/routes/mod.rs b/api/src/routes/mod.rs index 24af610..ce23f18 100644 --- a/api/src/routes/mod.rs +++ b/api/src/routes/mod.rs @@ -5,6 +5,10 @@ pub mod admin; pub mod candidate; pub fn to_custom_error(e: ServiceError) -> Custom { + if e.code() == 500 { + warn!("Internal server error: {} ({})", e, e.inner_trace().unwrap_or("".to_string())); + } + Custom( Status::from_code(e.code()).unwrap_or_default(), e.to_string() diff --git a/core/Cargo.toml b/core/Cargo.toml index 567e9ca..94ae6e3 100644 --- a/core/Cargo.toml +++ b/core/Cargo.toml @@ -40,6 +40,10 @@ age = { version = "^0.9", features = ["async"] } secrecy = { version = "^0.8" } base64 = "^0.13" +# logging +log = "0.4" +fern = "0.6" + [dependencies.sea-orm] version = "^0.10" features = [ diff --git a/core/src/database/mutation/candidate.rs b/core/src/database/mutation/candidate.rs index b64a029..411aa05 100644 --- a/core/src/database/mutation/candidate.rs +++ b/core/src/database/mutation/candidate.rs @@ -1,6 +1,7 @@ use crate::{Mutation, models::candidate_details::{EncryptedCandidateDetails}}; use ::entity::candidate::{self}; +use log::{info, warn}; use sea_orm::*; impl Mutation { @@ -12,7 +13,7 @@ impl Mutation { pubkey: String, encrypted_priv_key: String, ) -> Result { - candidate::ActiveModel { + let insert = candidate::ActiveModel { application: Set(application_id), personal_identification_number: Set(enc_personal_id_number), code: Set(hashed_password), @@ -23,7 +24,10 @@ impl Mutation { ..Default::default() } .insert(db) - .await + .await?; + + info!("CANDIDATE CREATED"); + Ok(insert) } pub async fn update_candidate_password_and_keys( @@ -38,7 +42,10 @@ impl Mutation { candidate.public_key = Set(pub_key); candidate.private_key = Set(priv_key_enc); - candidate.update(db).await + let update = candidate.update(db).await?; + + warn!("CANDIDATE PASSWORD CHANGED"); + Ok(update) } pub async fn add_candidate_details( @@ -61,7 +68,11 @@ impl Mutation { user.updated_at = Set(chrono::offset::Local::now().naive_local()); - user.update(db).await + let update = user.update(db).await?; + + info!("CANDIDATE DETAILS ADDED"); + + Ok(update) } } diff --git a/core/src/error.rs b/core/src/error.rs index dc5992a..72bbca0 100644 --- a/core/src/error.rs +++ b/core/src/error.rs @@ -103,4 +103,23 @@ impl ServiceError { ServiceError::CsvIntoInnerError => 500, } } -} \ No newline at end of file + + pub fn inner_trace(&self) -> Option { + match self { + ServiceError::DbError(e) => Some(e.to_string()), + ServiceError::AgeEncryptError(e) => Some(e.to_string()), + ServiceError::AgeDecryptError(e) => Some(e.to_string()), + ServiceError::AgeKeyError(e) => Some(e.to_string()), + ServiceError::IOError(e) => Some(e.to_string()), + ServiceError::Base64DecodeError(e) => Some(e.to_string()), + ServiceError::UTF8DecodeError(e) => Some(e.to_string()), + ServiceError::ArgonHashError(e) => Some(e.to_string()), + ServiceError::TokioJoinError(e) => Some(e.to_string()), + ServiceError::AesError(e) => Some(e.to_string()), + ServiceError::ArgonConfigError(e) => Some(e.to_string()), + ServiceError::ZipError(e) => Some(e.to_string()), + ServiceError::CsvError(e) => Some(e.to_string()), + _ => None, + } + } +} diff --git a/core/src/services/parent_service.rs b/core/src/services/parent_service.rs index 347292d..c3aee6c 100644 --- a/core/src/services/parent_service.rs +++ b/core/src/services/parent_service.rs @@ -16,16 +16,6 @@ impl ParentService { Ok(parent) } - /* pub async fn add_parent_details( - db: &DbConn, - parent: parent::Model, - enc_details: EncryptedParentDetails, - ) -> Result { - let parent = Mutation::add_parent_details(db, parent, enc_details) - .await?; - - Ok(parent) - } */ pub async fn add_parents_details( db: &DbConn, ref_candidate: candidate::Model, diff --git a/core/src/services/portfolio_service.rs b/core/src/services/portfolio_service.rs index 7657bb2..e5b9618 100644 --- a/core/src/services/portfolio_service.rs +++ b/core/src/services/portfolio_service.rs @@ -1,6 +1,7 @@ use std::{path::{PathBuf, Path}}; use entity::candidate; +use log::info; use sea_orm::{DbConn}; use serde::{Serialize, ser::{SerializeStruct}}; use tokio::io::{AsyncReadExt, AsyncWriteExt}; @@ -136,12 +137,15 @@ impl PortfolioService { data: Vec, filename: FileType, ) -> Result<(), ServiceError> { + info!("PORTFOLIO {} CACHE {} WRITE STARTED", candidate_id, filename.as_str()); + let cache_path = Self::get_file_store_path().join(&candidate_id.to_string()).join("cache"); let mut file = tokio::fs::File::create(cache_path.join(filename.as_str())).await?; file.write_all(&data).await?; + info!("PORTFOLIO {} CACHE {} WRITE FINISHED", candidate_id, filename.as_str()); Ok(()) } @@ -271,6 +275,8 @@ impl PortfolioService { if Self::is_portfolio_prepared(candidate_id).await == false { return Err(ServiceError::IncompletePortfolio); } + + info!("PORTFOLIO {} SUBMIT STARTED", candidate.application); let mut archive = tokio::fs::File::create(path.join(FileType::PortfolioZip.as_str())).await?; let mut writer = async_zip::write::ZipFileWriter::new(&mut archive); @@ -319,11 +325,14 @@ impl PortfolioService { return Err(ServiceError::PortfolioWriteError) } + info!("PORTFOLIO {} SUBMIT FINISHED", candidate_id); + Ok(()) } /// Delete PORTFOLIO.age file pub async fn delete_portfolio(candidate_id: i32) -> Result<(), ServiceError> { + info!("PORTFOLIO {} DELETE STARTED", candidate_id); let path = Self::get_file_store_path().join(&candidate_id.to_string()).to_path_buf(); let portfolio_path = path.join(FileType::PortfolioZip.as_str()); @@ -337,6 +346,8 @@ impl PortfolioService { tokio::fs::remove_file(&portfolio_age_path).await?; } + info!("PORTFOLIO {} DELETE FINISHED", candidate_id); + Ok(()) } @@ -349,13 +360,14 @@ impl PortfolioService { /// Returns decrypted portfolio zip as Vec of bytes pub async fn get_portfolio(candidate_id: i32, private_key: String) -> Result, ServiceError> { + info!("PORTFOLIO {} DECRYPT STARTED", candidate_id); let path = Self::get_file_store_path().join(&candidate_id.to_string()).to_path_buf(); let path = path.join(FileType::Age.as_str()); - let buffer = - crypto::decrypt_file_with_private_key_as_buffer(path, &private_key).await?; + let buffer = crypto::decrypt_file_with_private_key_as_buffer(path, &private_key).await?; + info!("PORTFOLIO {} DECRYPT FINISHED", candidate_id); Ok(buffer) } } From 593d04a1061998de35e1351880032cd1e03e3183 Mon Sep 17 00:00:00 2001 From: Sebastian Pravda Date: Thu, 15 Dec 2022 14:17:39 +0100 Subject: [PATCH 2/3] feat: session auth logging --- api/src/guards/request/auth/admin.rs | 14 ++++++++++---- api/src/guards/request/auth/candidate.rs | 11 +++++++++-- api/src/logging.rs | 18 ++++++++++++------ 3 files changed, 31 insertions(+), 12 deletions(-) diff --git a/api/src/guards/request/auth/admin.rs b/api/src/guards/request/auth/admin.rs index 717e41a..984c082 100644 --- a/api/src/guards/request/auth/admin.rs +++ b/api/src/guards/request/auth/admin.rs @@ -1,10 +1,12 @@ use entity::admin::Model as Admin; +use log::info; use portfolio_core::sea_orm::prelude::Uuid; use portfolio_core::services::admin_service::AdminService; use rocket::http::Status; use rocket::outcome::Outcome; use rocket::request::{FromRequest, Request}; +use crate::logging::format_request; use crate::pool::Db; pub struct AdminAuth(Admin, String); @@ -49,10 +51,14 @@ impl<'r> FromRequest<'r> for AdminAuth { let session = AdminService::auth(conn, uuid).await; match session { - Ok(model) => Outcome::Success(AdminAuth(model, private_key.to_string())), - Err(e) => Outcome::Failure( - (Status::from_code(e.code()).unwrap_or(Status::Unauthorized), None) - ), + Ok(model) => { + warn!("{}: ADMIN {} AUTHENTICATED", format_request(req), model.id); + Outcome::Success(AdminAuth(model, private_key.to_string())) + }, + Err(e) => { + info!("{}: ADMIN AUTHENTICATION FAILED: {}", format_request(req), e); + Outcome::Failure((Status::Unauthorized, None)) + }, } } diff --git a/api/src/guards/request/auth/candidate.rs b/api/src/guards/request/auth/candidate.rs index 2f49e1e..08d5fe3 100644 --- a/api/src/guards/request/auth/candidate.rs +++ b/api/src/guards/request/auth/candidate.rs @@ -5,6 +5,7 @@ use rocket::http::Status; use rocket::outcome::Outcome; use rocket::request::{FromRequest, Request}; +use crate::logging::format_request; use crate::pool::Db; pub struct CandidateAuth(Candidate, String); @@ -51,8 +52,14 @@ impl<'r> FromRequest<'r> for CandidateAuth { let session = CandidateService::auth(conn, uuid).await; match session { - Ok(model) => Outcome::Success(CandidateAuth(model, private_key.to_string().to_string())), - Err(_) => Outcome::Failure((Status::Unauthorized, None)), + Ok(model) => { + info!("{}: CANDIDATE {} AUTHENTICATED", format_request(req), model.application); + Outcome::Success(CandidateAuth(model, private_key.to_string().to_string())) + }, + Err(e) => { + info!("{}: CANDIDATE {} AUTHENTICATION FAILED", format_request(req), e); + Outcome::Failure((Status::Unauthorized, None)) + }, } } } diff --git a/api/src/logging.rs b/api/src/logging.rs index 702c4a1..cfe258a 100644 --- a/api/src/logging.rs +++ b/api/src/logging.rs @@ -1,5 +1,6 @@ use std::net::Ipv4Addr; +use log::info; use rocket::{fairing::{Fairing, Info, Kind}, Request, Data}; pub struct Logging; @@ -13,8 +14,15 @@ impl Fairing for Logging { } } - async fn on_request(&self, request: &mut Request<'_>, d: &mut Data<'_>) { - let client_ip = request.client_ip().unwrap_or(std::net::IpAddr::V4(Ipv4Addr::new(127, 0, 0, 1))).to_string(); + async fn on_request(&self, request: &mut Request<'_>, _: &mut Data<'_>) { + let s = format_request(request); + info!("> {}", s); + + } +} + +pub fn format_request(request: &Request<'_>) -> String { + let client_ip = request.client_ip().unwrap_or(std::net::IpAddr::V4(Ipv4Addr::new(127, 0, 0, 1))).to_string(); let method = request.method().to_string(); @@ -23,14 +31,12 @@ impl Fairing for Logging { let user_agent = request.headers().get_one("User-Agent").unwrap_or("").to_string(); let content_length = request.headers().get_one("Content-Length").unwrap_or("").to_string(); - info!("[{}] {} {} (User-Agent: {}, Content-Length: {}, Host: {})", + format!("[{}] {} {} (User-Agent: {}, Content-Length: {}, Host: {})", client_ip, method, uri, user_agent, content_length, host, - ); - - } + ) } \ No newline at end of file From 7a74dba54291a8131d05ac300cf47626f7753e9e Mon Sep 17 00:00:00 2001 From: Sebastian Pravda Date: Fri, 16 Dec 2022 11:00:11 +0100 Subject: [PATCH 3/3] chore: versions --- api/Cargo.toml | 4 ++-- core/Cargo.toml | 4 ++-- 2 files changed, 4 insertions(+), 4 deletions(-) diff --git a/api/Cargo.toml b/api/Cargo.toml index 201451b..dd35d21 100644 --- a/api/Cargo.toml +++ b/api/Cargo.toml @@ -20,8 +20,8 @@ serde_json = { version = "^1.0" } chrono = "^0.4" # logging -log = "0.4" -fern = "0.6" +log = "^0.4" +fern = "^0.6" portfolio-entity = { path = "../entity" } portfolio-migration = { path = "../migration" } diff --git a/core/Cargo.toml b/core/Cargo.toml index 94ae6e3..be3962a 100644 --- a/core/Cargo.toml +++ b/core/Cargo.toml @@ -41,8 +41,8 @@ secrecy = { version = "^0.8" } base64 = "^0.13" # logging -log = "0.4" -fern = "0.6" +log = "^0.4" +fern = "^0.6" [dependencies.sea-orm] version = "^0.10"