f add slogging (initial version)

Cargo.toml

@@ -15,6 +15,12 @@ rocket_codegen="~0.3"
 serde="~1.0"
 serde_derive="~1.0"
 serde_json="~1.0"
+slog="~2.2"
+slog-async="~2.2"
+slog-term="~2.3"
+slog-json="~2.2"
+slog-scope="~4.0"
+slog-stdlog="~3.0"
 time="~0.1"
 
 [dependencies.rocket_contrib]

src/auth/mod.rs

@@ -9,6 +9,7 @@ use rocket::{Request, State};
 use error::{HandlerError, HandlerErrorKind, VALIDATION_FAILED};
 
 use config::ServerConfig;
+use logging::RBLogger;
 
 /// Fetch FxA scopes for a requests Authentication header.
 ///
@@ -57,13 +58,18 @@ impl FxAAuthenticator {
     ///  called '*fxa_response*` which contains the spoofed return data for
     /// Thus currently pulls a managed memory configuration object that contains
     /// an `.auth_app_name` String for `dryrun` and `test` configurations.
-    fn as_fxa_oauth(token: String, config: &ServerConfig) -> request::Outcome<Self, HandlerError> {
+    fn as_fxa_oauth(
+        token: String,
+        config: &ServerConfig,
+        logger: &RBLogger,
+    ) -> request::Outcome<Self, HandlerError> {
         // Get the scopes from the verify server.
         let fxa_host = &config.fxa_host;
         let fxa_url = Self::fxa_root(fxa_host);
         let mut body = HashMap::new();
         body.insert("token", token);
         if &config.dryrun == &true {
+            slog_debug!(logger.log, "Dryrun, skipping auth");
             return Success(FxAAuthenticator {
                 auth_type: AuthType::FxAOauth,
                 scope: vec![Self::fxa_root(&config.auth_app_name)],
@@ -76,10 +82,11 @@ impl FxAAuthenticator {
         {
             Ok(client) => client,
             Err(err) => {
+                slog_crit!(logger.log, "Reqwest failure"; "err" => format!("{:?}",err));
                 return Failure((
                     VALIDATION_FAILED,
                     HandlerErrorKind::Unauthorized(format!("Client error {:?}", err)).into(),
-                ))
+                ));
             }
         };
         let resp: FxAResp = if cfg!(test) {
@@ -172,6 +179,10 @@ impl<'a, 'r> FromRequest<'a, 'r> for FxAAuthenticator {
 
     /// Process the Authorization header and return the token.
     fn from_request(request: &'a Request<'r>) -> request::Outcome<Self, HandlerError> {
+        let logger = request
+            .guard::<State<RBLogger>>()
+            .expect("Logger missing")
+            .inner();
         if let Some(auth_header) = request.headers().get_one("Authorization") {
             // Get a copy of the rocket config from the request's managed memory.
             // There is no other way to get the rocket.config() from inside a request
@@ -181,6 +192,7 @@ impl<'a, 'r> FromRequest<'a, 'r> for FxAAuthenticator {
                 .expect("Application missing config")
                 .inner();
             let auth_bits: Vec<&str> = auth_header.splitn(2, " ").collect();
+            slog_info!(logger.log, "Checking auth token");
             if auth_bits.len() != 2 {
                 return Failure((
                     VALIDATION_FAILED,
@@ -191,20 +203,23 @@ impl<'a, 'r> FromRequest<'a, 'r> for FxAAuthenticator {
             };
             match auth_bits[0].to_lowercase().as_str() {
                 "bearer" | "fxa-oauth-token" => {
-                    return Self::as_fxa_oauth(auth_bits[1].into(), config)
+                    slog_info!(logger.log, "Found Oauth token");
+                    return Self::as_fxa_oauth(auth_bits[1].into(), config, logger);
                 }
                 "fxa-server-key" => return Self::as_server_token(auth_bits[1].into(), config),
                 _ => {
+                    slog_info!(logger.log, "Found Server token");
                     return Failure((
                         VALIDATION_FAILED,
                         HandlerErrorKind::Unauthorized(
                             "Incorrect Authorization Header Schema".to_string(),
                         ).into(),
-                    ))
+                    ));
                 }
             }
         } else {
             // No Authorization header
+            slog_info!(logger.log, "No Authorization Header found");
             return Failure((
                 VALIDATION_FAILED,
                 HandlerErrorKind::Unauthorized("Missing Authorization Header".to_string()).into(),
@@ -227,6 +242,7 @@ mod test {
     use super::FxAAuthenticator;
     use config::ServerConfig;
     use error::HandlerResult;
+    use logging::RBLogger;
 
     struct StubServer {}
     impl StubServer {
@@ -235,7 +251,8 @@ mod test {
                 .attach(AdHoc::on_attach(|rocket| {
                     // Copy the config into a state manager.
                     let rbconfig = ServerConfig::new(rocket.config());
-                    Ok(rocket.manage(rbconfig))
+                    let logger = RBLogger::new(rocket.config());
+                    Ok(rocket.manage(rbconfig).manage(logger))
                 }))
                 .mount("", routes![auth_test_read_stub, auth_test_write_stub]))
         }

src/db/models.rs

@@ -49,11 +49,7 @@ pub fn calc_ttl(seconds: u64) -> u64 {
 pub struct DatabaseManager {}
 
 impl DatabaseManager {
-    pub fn max_index(
-        conn: &MysqlConnection,
-        user_id: &String,
-        device_id: &String,
-    ) -> u64 {
+    pub fn max_index(conn: &MysqlConnection, user_id: &String, device_id: &String) -> u64 {
         let mut max_index_sel: Vec<i64> = match pushboxv1::table
             .select(pushboxv1::idx)
             .filter(pushboxv1::user_id.eq(user_id))
@@ -161,10 +157,8 @@ impl DatabaseManager {
                 .context(HandlerErrorKind::DBError)
                 .unwrap();
         } else {
-            diesel::delete(
-                pushboxv1::table
-                    .filter(pushboxv1::user_id.eq(user_id))
-            ).execute(conn)
+            diesel::delete(pushboxv1::table.filter(pushboxv1::user_id.eq(user_id)))
+                .execute(conn)
                 .context(HandlerErrorKind::DBError)
                 .unwrap();
         }

src/logging.rs

@@ -0,0 +1,34 @@
+use rocket::config::Config;
+use rocket::request::{self, FromRequest};
+use rocket::{Outcome, Request, State};
+use slog;
+use slog::Drain;
+use slog_async;
+use slog_scope;
+use slog_stdlog;
+use slog_term;
+
+#[derive(Clone, Debug)]
+pub struct RBLogger {
+    pub log: slog::Logger,
+}
+
+impl RBLogger {
+    pub fn new(config: &Config) -> RBLogger {
+        let decorator = slog_term::TermDecorator::new().build();
+        let drain = slog_term::CompactFormat::new(decorator).build().fuse();
+        let drain = slog_async::Async::new(drain).build().fuse();
+
+        RBLogger {
+            log: slog::Logger::root(drain, o!()).new(o!()),
+        }
+    }
+}
+
+impl<'a, 'r> FromRequest<'a, 'r> for RBLogger {
+    type Error = ();
+
+    fn from_request(req: &'a Request<'r>) -> request::Outcome<Self, ()> {
+        Outcome::Success(req.guard::<State<RBLogger>>().unwrap().inner().clone())
+    }
+}

src/main.rs

@@ -9,6 +9,10 @@ extern crate failure;
 extern crate serde_derive;
 #[macro_use]
 extern crate serde_json;
+#[macro_use]
+extern crate slog;
+#[macro_use]
+extern crate slog_scope;
 
 extern crate diesel_migrations;
 extern crate mysql;
@@ -17,11 +21,16 @@ extern crate reqwest;
 extern crate rocket;
 extern crate rocket_contrib;
 extern crate serde;
+extern crate slog_async;
+extern crate slog_json;
+extern crate slog_stdlog;
+extern crate slog_term;
 
 mod auth;
 mod config;
 mod db;
 mod error;
+mod logging;
 mod server;
 
 fn main() {

src/server.rs

@@ -7,12 +7,14 @@ use rocket::fairing::AdHoc;
 use rocket::http::Method;
 use rocket::request::{FormItems, FromForm};
 use rocket_contrib::json::Json;
+use slog::Logger;
 
 use auth::{AuthType, FxAAuthenticator};
 use config::ServerConfig;
 use db::models::{calc_ttl, DatabaseManager};
 use db::{pool_from_config, Conn};
 use error::{HandlerError, HandlerErrorKind, HandlerResult};
+use logging::RBLogger;
 
 #[derive(Deserialize, Debug)]
 pub struct DataRecord {
@@ -77,7 +79,9 @@ impl Server {
                 // Copy the config into a state manager.
                 let pool = pool_from_config(rocket.config()).expect("Could not get pool");
                 let rbconfig = ServerConfig::new(rocket.config());
-                Ok(rocket.manage(rbconfig).manage(pool))
+                let logger = RBLogger::new(rocket.config());
+                slog_info!(logger.log, "sLogging initialized...");
+                Ok(rocket.manage(rbconfig).manage(pool).manage(logger))
             }))
             .mount(
                 "/v1/store",
@@ -167,6 +171,7 @@ pub fn check_fxa_token(
 fn read_opt(
     conn: Conn,
     config: ServerConfig,
+    logger: RBLogger,
     token: HandlerResult<FxAAuthenticator>,
     user_id: String,
     device_id: String,
@@ -176,6 +181,7 @@ fn read_opt(
     // Validate::from_request extracts the token from the Authorization header, validates it
     // against FxA and the method, and either returns OK or an error. We need to reraise it to the
     // handler.
+    slog_info!(logger.log, "Handling Read");
     check_token(&config, Method::Get, &device_id, &token)?;
     let max_index = DatabaseManager::max_index(&conn, &user_id, &device_id);
     let mut index = options.index;
@@ -185,21 +191,23 @@ fn read_opt(
             // New entry, needs all data
             index = None;
             limit = None;
+            slog_debug!(logger.log, "Welcome new user");
         }
         "lost" => {
             // Just lost, needs just the next index.
             index = None;
             limit = Some(0);
+            slog_debug!(logger.log, "Sorry, you're lost.");
         }
         _ => {}
     };
     let messages =
-        DatabaseManager::read_records(&conn, &user_id, &device_id, &index, &limit)
-            .unwrap();
+        DatabaseManager::read_records(&conn, &user_id, &device_id, &index, &limit).unwrap();
     let mut msg_max: u64 = 0;
     for message in &messages {
         msg_max = cmp::max(msg_max, message.idx as u64);
     }
+    slog_info!(logger.log, "Found messages"; "len" => messages.len());
     // returns json {"status":200, "index": max_index, "messages":[{"index": #, "data": String}, ...]}
     let is_last = match limit {
         None => true,
@@ -221,13 +229,15 @@ fn read_opt(
 fn read(
     conn: Conn,
     config: ServerConfig,
+    logger: RBLogger,
     token: HandlerResult<FxAAuthenticator>,
     user_id: String,
     device_id: String,
 ) -> HandlerResult<Json> {
     read_opt(
         conn,
         config,
+        logger,
         token,
         user_id,
         device_id,
@@ -244,6 +254,7 @@ fn read(
 fn write(
     conn: Conn,
     config: ServerConfig,
+    logger: RBLogger,
     token: HandlerResult<FxAAuthenticator>,
     user_id: String,
     device_id: String,
@@ -258,20 +269,15 @@ fn write(
         .unwrap_or(false)
     {
         // Auth testing, do not write to db.
-        println!("INFO: Auth Skipping database check.");
+        slog_info!(logger.log, "Auth Skipping database check.");
         return Ok(Json(json!({
             "status": 200,
             "index": -1,
         })));
     }
-
-    let response = DatabaseManager::new_record(
-        &conn,
-        &user_id,
-        &device_id,
-        &data.data,
-        calc_ttl(data.ttl),
-    );
+    slog_debug!(logger.log, "Writing new record");
+    let response =
+        DatabaseManager::new_record(&conn, &user_id, &device_id, &data.data, calc_ttl(data.ttl));
     if response.is_err() {
         return Err(response.err().unwrap());
     }