From 0819356e36e48d534b8f14568bc80aad3517ebe2 Mon Sep 17 00:00:00 2001
From: danielsanchezq <daniel.sanchez@iohk.io>
Date: Wed, 29 Jul 2020 10:59:15 +0200
Subject: [PATCH] Implemented abstracted logging methods for requests elapsed
 time and for rejected api tokens

---
 vit-servicing-station-lib/src/lib.rs          |  1 +
 vit-servicing-station-lib/src/logging/mod.rs  | 27 +++++++++++++++++++
 vit-servicing-station-lib/src/v0/api_token.rs |  7 +++--
 vit-servicing-station-lib/src/v0/mod.rs       | 14 +---------
 4 files changed, 34 insertions(+), 15 deletions(-)
 create mode 100644 vit-servicing-station-lib/src/logging/mod.rs

diff --git a/vit-servicing-station-lib/src/lib.rs b/vit-servicing-station-lib/src/lib.rs
index 587ecf60..ff160060 100644
--- a/vit-servicing-station-lib/src/lib.rs
+++ b/vit-servicing-station-lib/src/lib.rs
@@ -7,6 +7,7 @@ extern crate structopt;
 extern crate diesel_migrations;
 
 pub mod db;
+mod logging;
 pub mod server;
 pub mod utils;
 pub mod v0;
diff --git a/vit-servicing-station-lib/src/logging/mod.rs b/vit-servicing-station-lib/src/logging/mod.rs
new file mode 100644
index 00000000..eb50ebbd
--- /dev/null
+++ b/vit-servicing-station-lib/src/logging/mod.rs
@@ -0,0 +1,27 @@
+use logging_lib::messages::{DefaultLogMessageBuilder, DefaultMetadata, LogMessageId};
+use std::time::Duration;
+
+pub fn log_request_elapsed_time(elapsed_time: Duration) {
+    let elapsed = elapsed_time.as_nanos().to_string();
+    let mut metadata = DefaultMetadata::new();
+    metadata.insert("elapsed_nano_seconds".into(), elapsed.clone());
+    DefaultLogMessageBuilder::new()
+        .with_level(log::Level::Info)
+        .with_tags(vec!["request", "elapsed"])
+        .with_message(format!("Request elapsed time: {}ns", elapsed))
+        .with_id(LogMessageId::Other("request_elapsed_time".into()))
+        .build()
+        .log();
+}
+
+pub fn log_rejected_api_key(api_key: String) {
+    let mut metadata = DefaultMetadata::new();
+    metadata.insert("api_key".into(), api_key.clone());
+    DefaultLogMessageBuilder::new()
+        .with_level(log::Level::Info)
+        .with_tags(vec!["api_key", "reject"])
+        .with_message(format!("Rejected API-Token: {}", api_key))
+        .with_id(LogMessageId::Other("RejectedAPIToken".into()))
+        .build()
+        .log();
+}
diff --git a/vit-servicing-station-lib/src/v0/api_token.rs b/vit-servicing-station-lib/src/v0/api_token.rs
index 7b5e00d8..556bcdda 100644
--- a/vit-servicing-station-lib/src/v0/api_token.rs
+++ b/vit-servicing-station-lib/src/v0/api_token.rs
@@ -61,7 +61,7 @@ async fn authorize_token(token: String, context: SharedContext) -> Result<(), Re
     let manager = APITokenManager::new(context.read().await.db_connection_pool.clone());
 
     let mut token_vec: Vec<u8> = Vec::new();
-    base64::decode_config_buf(token, base64::URL_SAFE, &mut token_vec).map_err(|_err| {
+    base64::decode_config_buf(token.clone(), base64::URL_SAFE, &mut token_vec).map_err(|_err| {
         warp::reject::custom(HandleError::InvalidHeader(
             API_TOKEN_HEADER,
             "header should be base64 url safe decodable",
@@ -72,7 +72,10 @@ async fn authorize_token(token: String, context: SharedContext) -> Result<(), Re
 
     match manager.is_token_valid(api_token).await {
         Ok(true) => Ok(()),
-        Ok(false) => Err(warp::reject::custom(HandleError::UnauthorizedToken)),
+        Ok(false) => {
+            crate::logging::log_rejected_api_key(token);
+            Err(warp::reject::custom(HandleError::UnauthorizedToken))
+        }
         Err(e) => Err(warp::reject::custom(e)),
     }
 }
diff --git a/vit-servicing-station-lib/src/v0/mod.rs b/vit-servicing-station-lib/src/v0/mod.rs
index 024283e0..6830a90b 100644
--- a/vit-servicing-station-lib/src/v0/mod.rs
+++ b/vit-servicing-station-lib/src/v0/mod.rs
@@ -4,7 +4,6 @@ pub mod endpoints;
 pub mod errors;
 pub mod result;
 
-use logging_lib::messages::LogMessageId;
 use warp::{Filter, Rejection, Reply};
 
 pub async fn filter(
@@ -13,18 +12,7 @@ pub async fn filter(
     let root = warp::path!("api" / "v0" / ..);
 
     // log request statistics
-    let log = warp::log::custom(|info| {
-        let elapsed = info.elapsed().as_nanos().to_string();
-        let mut metadata = logging_lib::messages::DefaultMetadata::new();
-        metadata.insert("elapsed_nano_seconds".into(), elapsed.clone());
-        logging_lib::messages::DefaultLogMessageBuilder::new()
-            .with_level(log::Level::Info)
-            .with_tags(vec!["request", "elapsed"])
-            .with_message(elapsed)
-            .with_id(LogMessageId::Other("request_average".into()))
-            .build()
-            .log();
-    });
+    let log = warp::log::custom(|info| crate::logging::log_request_elapsed_time(info.elapsed()));
 
     endpoints::filter(root.boxed(), ctx)
         .await