Merge pull request #107 from sogrim/better-logging

Better logging (server side)

packages/server/Cargo.toml

@@ -6,13 +6,15 @@ edition = "2018"
 # See more keys and their definitions at https://doc.rust-lang.org/cargo/reference/manifest.html
 
 [dependencies]
+log = "0.4"
+colored = "2"
 mongodb = { version = "2.0.0"}
 bson = "2.0.0"
 serde = { version = "1.0", features = ["derive"] }
 serde_json = "1.0"
 my_internet_ip = "0.1.1"
 actix-rt = "2.2.0"
-actix-web = "4.0.0-beta.14"
+actix-web = "4.0.0-rc.2"
 actix-cors = "0.6.0-beta.6"
 actix-service = "2.0.1"
 futures-util = "0.3.17"

packages/server/src/api/students.rs

@@ -35,9 +35,10 @@ pub async fn get_all_catalogs(
 #[get("/students/login")]
 pub async fn login(client: web::Data<Client>, req: HttpRequest) -> Result<HttpResponse, Error> {
     let extensions = req.extensions();
-    let user_id = extensions
-        .get::<Sub>()
-        .ok_or_else(|| ErrorInternalServerError("Middleware Internal Error"))?;
+    let user_id = extensions.get::<Sub>().ok_or_else(|| {
+        log::error!("Middleware Internal Error");
+        ErrorInternalServerError("")
+    })?;
 
     let document = doc! {"$setOnInsert" : User::new_document(user_id)};
     let updated_user = db::services::find_and_update_user(user_id, document, &client).await?;
@@ -66,7 +67,10 @@ pub async fn add_catalog(
             .await?;
             Ok(HttpResponse::Ok().json(updated_user))
         }
-        None => Err(ErrorInternalServerError("No data exists for user")),
+        None => {
+            log::error!("No data exists for user");
+            Err(ErrorInternalServerError("No data exists for user"))
+        }
     }
 }
 
@@ -89,7 +93,10 @@ pub async fn add_courses(
             .await?;
             Ok(HttpResponse::Ok().json(updated_user))
         }
-        None => Err(ErrorInternalServerError("No data exists for user")),
+        None => {
+            log::error!("No data exists for user");
+            Err(ErrorInternalServerError("No data exists for user"))
+        }
     }
 }
 
@@ -99,15 +106,18 @@ pub async fn compute_degree_status(
     mut user: User,
     client: web::Data<Client>,
 ) -> Result<HttpResponse, Error> {
-    let mut user_details = user
-        .details
-        .as_mut()
-        .ok_or_else(|| ErrorInternalServerError("No data exists for user"))?;
+    let mut user_details = user.details.as_mut().ok_or_else(|| {
+        log::error!("No data exists for user");
+        ErrorInternalServerError("")
+    })?;
 
     let catalog_id = user_details
         .catalog
         .as_ref()
-        .ok_or_else(|| ErrorInternalServerError("No data exists for user"))?
+        .ok_or_else(|| {
+            log::error!("No data exists for user");
+            ErrorInternalServerError("")
+        })?
         .id;
 
     let catalog = db::services::get_catalog_by_id(&catalog_id, &client).await?;

packages/server/src/core/parser.rs

@@ -23,7 +23,8 @@ pub fn parse_copy_paste_data(data: &str) -> Result<Vec<CourseStatus>, Error> {
     // Sanity validation
     if !(data.starts_with("גיליון ציונים") && data.contains("סוף גיליון ציונים"))
     {
-        return Err(ErrorBadRequest("Bad Format"));
+        log::error!("Invalid copy paste data");
+        return Err(ErrorBadRequest("Invalid copy paste data"));
     }
 
     let mut courses = HashMap::<String, CourseStatus>::new();
@@ -51,9 +52,8 @@ pub fn parse_copy_paste_data(data: &str) -> Result<Vec<CourseStatus>, Error> {
                 (_, true, _) => "קיץ",
                 (_, _, true) => "חורף",
                 _ => {
-                    return Err(ErrorInternalServerError(
-                        "Something really unexpected happened",
-                    ))
+                    log::error!("Something really unexpected happened");
+                    return Err(ErrorInternalServerError(""));
                 }
             };
 
@@ -101,7 +101,8 @@ pub fn parse_copy_paste_data(data: &str) -> Result<Vec<CourseStatus>, Error> {
     vec_courses.append(&mut sport_courses);
 
     if vec_courses.is_empty() {
-        return Err(ErrorBadRequest("Bad Format"));
+        log::error!("Invalid copy paste data");
+        return Err(ErrorBadRequest("Invalid copy paste data"));
     }
     Ok(vec_courses)
 }
@@ -135,13 +136,14 @@ fn set_grades_for_uncompleted_courses(
 fn parse_course_status_pdf_format(line: &str) -> Result<(Course, Option<Grade>), Error> {
     let clean_line = line.replace("*", "");
     let id = {
-        let number = clean_line
-            .split(' ')
-            .next()
-            .ok_or_else(|| ErrorBadRequest("Bad Format"))?;
+        let number = clean_line.split(' ').next().ok_or_else(|| {
+            log::error!("Bad Format");
+            ErrorBadRequest("Bad Format")
+        })?;
         if number.parse::<f32>().is_ok() {
             Ok(String::from(number))
         } else {
+            log::error!("Bad Format");
             Err(ErrorBadRequest("Bad Format"))
         }?
     };
@@ -174,7 +176,10 @@ fn parse_course_status_pdf_format(line: &str) -> Result<(Course, Option<Grade>),
     let grade_str = clean_line
         .split(' ')
         .last()
-        .ok_or_else(|| ErrorBadRequest("Bad Format"))?
+        .ok_or_else(|| {
+            log::error!("Bad Format");
+            ErrorBadRequest("Bad Format")
+        })?
         .trim();
 
     let grade = match grade_str as &str {

packages/server/src/db/services.rs

@@ -27,9 +27,12 @@ macro_rules! impl_get {
                 .await
             {
                 Ok(Some(id)) => Ok(id),
-                Ok(None) => Err(error::ErrorNotFound(id.to_string())),
+                Ok(None) => {
+                    log::error!("{:#?} not found", stringify!($db_item));
+                    Err(error::ErrorNotFound(id.to_string()))
+                }
                 Err(err) => {
-                    eprintln!("{:#?}", err);
+                    log::error!("{:#?}", err);
                     Err(error::ErrorInternalServerError(err.to_string()))
                 }
             }
@@ -51,11 +54,14 @@ macro_rules! impl_get_all {
                 .find(None, None)
                 .await
             {
-                Ok(docs) => Ok(docs
-                    .try_collect::<Vec<$db_item>>()
-                    .await
-                    .map_err(|e| ErrorInternalServerError(e.to_string()))?),
-                Err(err) => Err(ErrorInternalServerError(err.to_string())),
+                Ok(docs) => Ok(docs.try_collect::<Vec<$db_item>>().await.map_err(|e| {
+                    log::error!("{}", e.to_string());
+                    ErrorInternalServerError("")
+                })?),
+                Err(err) => {
+                    log::error!("{}", err.to_string());
+                    Err(ErrorInternalServerError(""))
+                }
             }
         }
     };
@@ -93,8 +99,8 @@ macro_rules! impl_update {
                 // We can safely unwrap here thanks to upsert=true and ReturnDocument::After
                 Ok(item) => Ok(item.unwrap()),
                 Err(err) => {
-                    let err = format!("monogdb driver error: {}", err);
-                    eprintln!("{}", err);
+                    let err = format!("MongoDB driver error: {}", err);
+                    log::error!("{}", err);
                     Err(ErrorInternalServerError(err))
                 }
             }
@@ -120,8 +126,8 @@ macro_rules! impl_delete {
             {
                 Ok(_) => Ok(()),
                 Err(err) => {
-                    let err = format!("monogdb driver error: {}", err);
-                    eprintln!("{}", err);
+                    let err = format!("MongoDB driver error: {}", err);
+                    log::error!("{}", err);
                     Err(ErrorInternalServerError(err))
                 }
             }

packages/server/src/logger.rs

@@ -0,0 +1,20 @@
+use actix_web::middleware::Logger;
+use colored::Colorize;
+
+pub fn init_env_logger() {
+    env_logger::Builder::from_env(env_logger::Env::new().default_filter_or("info"))
+        .format_timestamp(None)
+        .init();
+}
+pub fn init_actix_logger() -> Logger {
+    Logger::new(
+        format!(
+            "{} | {} | {} seconds",
+            "%r".yellow(),
+            "%s".bold().magenta(),
+            "%T".cyan()
+        )
+        .as_str(),
+    )
+    .log_target("sogrim_server")
+}

packages/server/src/main.rs

@@ -1,31 +1,38 @@
 extern crate my_internet_ip;
 use crate::config::CONFIG;
 use actix_cors::Cors;
-use actix_web::{middleware::Logger, web, App, HttpServer};
+use actix_web::{web, App, HttpServer};
 use dotenv::dotenv;
 use mongodb::Client;
 
 mod api;
 mod config;
 mod core;
 mod db;
+mod logger;
 mod middleware;
 mod resources;
 
 #[actix_web::main]
 async fn main() -> std::io::Result<()> {
+    // Load .env (in development environment)
     dotenv().ok();
+
+    // Initialize MongoDB client
     let client = Client::with_uri_str(&CONFIG.uri)
         .await
-        .expect("failed to connect");
-    env_logger::init_from_env(env_logger::Env::new().default_filter_or("info"));
+        .expect("ERROR: Failed to connect with MongoDB");
+
+    // Initialize logger
+    logger::init_env_logger();
 
+    // Start the server
     HttpServer::new(move || {
         App::new()
             .app_data(web::Data::new(client.clone()))
             .wrap(middleware::auth::AuthenticateMiddleware)
             .wrap(Cors::permissive())
-            .wrap(Logger::default())
+            .wrap(logger::init_actix_logger())
             .service(api::students::get_all_catalogs)
             .service(api::students::login)
             .service(api::students::add_catalog)

packages/server/src/middleware/auth.rs

@@ -70,12 +70,17 @@ where
 }
 
 macro_rules! return_401_with_reason(
-    ($request:ident,$reason:expr) => {
+    ($request:ident,$reason:expr) => {{
+        if $reason.contains("Expired") {
+            log::warn!("{}", $reason);
+        } else {
+            log::error!("{}", $reason);
+        }
         return Ok(ServiceResponse::new(
             $request,
             HttpResponse::Unauthorized().body($reason).map_into_right_body(),
         ))
-    };
+    }};
 );
 
 pub struct Authenticator<S> {

packages/server/src/middleware/from_request.rs

@@ -11,14 +11,18 @@ macro_rules! impl_from_request {
                     let client = match req.app_data::<web::Data<Client>>() {
                         Some(client) => client,
                         None => {
-                            return Err(ErrorInternalServerError("Db client was not initialized!"))
+                            log::error!("Db client was not initialized!");
+                            return Err(ErrorInternalServerError(""));
                         }
                     };
                     match req.extensions().get::<Sub>() {
                         Some(key) => db::services::$get_fn(key, client).await,
-                        None => Err(ErrorUnauthorized(
-                            "Authorization process did not complete successfully!",
-                        )),
+                        None => {
+                            log::error!("Authorization process did not complete successfully!");
+                            Err(ErrorUnauthorized(
+                                "Authorization process did not complete successfully!",
+                            ))
+                        }
                     }
                 })
             }