Merge pull request #89 from EETagent/logging

(backend) Logging

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

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" }

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())),
+            Ok(model) => {
-            Err(e) => Outcome::Failure(
+                warn!("{}: ADMIN {} AUTHENTICATED", format_request(req), model.id);
-                (Status::from_code(e.code()).unwrap_or(Status::Unauthorized), None)
+                Outcome::Success(AdminAuth(model, private_key.to_string()))
-            ),
+            },
+            Err(e) => {
+                info!("{}: ADMIN AUTHENTICATION FAILED: {}", format_request(req), e);
+                Outcome::Failure((Status::Unauthorized, None))
+        },
         }
 
     }

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())),
+            Ok(model) => {
-            Err(_) => Outcome::Failure((Status::Unauthorized, None)),
+                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))
+            },
         }
     }
 }

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<Build>) -> 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<Build>) -> fairing::Result {
 
 pub fn rocket() -> Rocket<Build> {
     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<Build> {
 
 #[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(|_| ())
 }
 

api/src/logging.rs

@@ -0,0 +1,42 @@
+use std::net::Ipv4Addr;
+
+use log::info;
+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<'_>, _: &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();
+
+        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();
+
+        format!("[{}] {} {} (User-Agent: {}, Content-Length: {}, Host: {})",
+            client_ip,
+            method,
+            uri,
+            user_agent,
+            content_length,
+            host,
+        )
+}

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)

api/src/routes/mod.rs

@@ -5,6 +5,10 @@ pub mod admin;
 pub mod candidate;
 
 pub fn to_custom_error(e: ServiceError) -> Custom<String> {
+    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()

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 = [

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::Model, DbErr> {
-        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)
     }
 }
 

core/src/error.rs

@@ -103,4 +103,23 @@ impl ServiceError {
             ServiceError::CsvIntoInnerError => 500,
         }
     }
-}
+
+    pub fn inner_trace(&self) -> Option<String> {
+        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,
+        }
+    }
+}

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<parent::Model, ServiceError> {
-        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,

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<u8>,
         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<Vec<u8>, 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 =
+        let buffer = crypto::decrypt_file_with_private_key_as_buffer(path, &private_key).await?;
-            crypto::decrypt_file_with_private_key_as_buffer(path, &private_key).await?;
 
+        info!("PORTFOLIO {} DECRYPT FINISHED", candidate_id);
         Ok(buffer)
     }
 }