Add logging

Provides extensive logging across the project, especially at the
TRACE level.

Currently also tracking
rust-lang/log#149. Keen to have Gotham
move to structured logging as soon as practical.

Cargo.toml

@@ -7,6 +7,7 @@ name = "gotham"
 version = "0.1.0"
 
 [dependencies]
+log = "0.3"
 hyper = { git = "https://github.com/hyperium/hyper.git" }
 futures = "~0.1.11"
 tokio-core = "*"
@@ -15,3 +16,4 @@ mio = "*"
 borrow-bag = "0.3"
 url = "1.4.0"
 uuid = { version = "0.5", features = ["v4"] }
+chrono = "0.3"

examples/kitchen-sink/Cargo.toml

@@ -9,5 +9,7 @@ gotham = { path = "../.." }
 gotham_derive = { path = "../../gotham_derive" }
 futures = "*"
 hyper = { git = "https://github.com/hyperium/hyper.git" }
-pretty_env_logger = "*"
 borrow-bag = "*"
+log = "0.3"
+fern = "0.4"
+chrono = "0.3.1"

examples/kitchen-sink/src/main.rs

@@ -1,11 +1,13 @@
 #![deny(warnings)]
 extern crate futures;
 extern crate hyper;
-extern crate pretty_env_logger;
 extern crate gotham;
 #[macro_use]
 extern crate gotham_derive;
 extern crate borrow_bag;
+extern crate chrono;
+extern crate log;
+extern crate fern;
 
 mod middleware;
 
@@ -15,6 +17,8 @@ use hyper::header::ContentLength;
 use hyper::server::{Http, Request, Response};
 use hyper::Method;
 
+use log::LogLevelFilter;
+
 use gotham::http::request_path::NoopRequestPathExtractor;
 use gotham::http::query_string::NoopQueryStringExtractor;
 use gotham::router::response_extender::ResponseExtenderBuilder;
@@ -196,7 +200,20 @@ impl Echo {
 }
 
 fn main() {
-    pretty_env_logger::init().unwrap();
+    fern::Dispatch::new()
+        .format(|out, message, record| {
+                    out.finish(format_args!("{}[{}][{}]{}",
+                                            chrono::UTC::now().format("[%Y-%m-%d %H:%M:%S%.9f]"),
+                                            record.target(),
+                                            record.level(),
+                                            message))
+                })
+        .level(LogLevelFilter::Error)
+        .level_for("gotham", log::LogLevelFilter::Trace)
+        .chain(std::io::stdout())
+        .apply()
+        .unwrap();
+
     let addr = "127.0.0.1:7878".parse().unwrap();
 
     let mut tree_builder = TreeBuilder::new();

src/dispatch/mod.rs

@@ -3,15 +3,16 @@
 //! These types are intended to be used internally by Gotham's `Router` and supporting code. Gotham
 //! applications should not need to consume these types directly.
 
-use handler::{Handler, NewHandler, HandlerFuture};
-use middleware::pipeline::{NewMiddlewareChain, Pipeline};
-use state::State;
-use borrow_bag::{BorrowBag, Handle, Lookup};
 use std::marker::PhantomData;
 
+use borrow_bag::{BorrowBag, Handle, Lookup};
 use hyper::server::Request;
 use futures::{future, Future};
 
+use handler::{Handler, NewHandler, HandlerFuture};
+use middleware::pipeline::{NewMiddlewareChain, Pipeline};
+use state::{State, request_id};
+
 /// Internal type used by `Router` to dispatch requests via the configured `Pipeline`(s) and to the
 /// correct `Handler`.
 pub struct Dispatcher<H, C, P>
@@ -45,13 +46,17 @@ impl<H, C, P> Dispatcher<H, C, P>
                     -> Box<HandlerFuture> {
         match self.new_handler.new_handler() {
             Ok(h) => {
+                trace!("[{}] cloning handler", request_id(&state));
                 self.pipeline_chain
                     .call(pipelines,
                           state,
                           req,
                           move |state, req| h.handle(state, req))
             }
-            Err(e) => future::err((state, e.into())).boxed(),
+            Err(e) => {
+                trace!("[{}] error cloning handler", request_id(&state));
+                future::err((state, e.into())).boxed()
+            }
         }
     }
 }
@@ -104,7 +109,10 @@ impl<'a, P, T, N, U> PipelineHandleChain<P> for (Handle<Pipeline<T>, N>, U)
                            req,
                            move |state, req| p.call(state, req, f))
             }
-            Err(e) => future::err((state, e.into())).boxed(),
+            Err(e) => {
+                trace!("[{}] error borrowing pipeline", request_id(&state));
+                future::err((state, e.into())).boxed()
+            }
         }
     }
 }
@@ -114,6 +122,7 @@ impl<P> PipelineHandleChain<P> for () {
     fn call<F>(&self, _: &BorrowBag<P>, state: State, req: Request, f: F) -> Box<HandlerFuture>
         where F: FnOnce(State, Request) -> Box<HandlerFuture> + Send + 'static
     {
+        trace!("[{}] start pipeline", request_id(&state));
         f(state, req)
     }
 }

src/handler/mod.rs

@@ -5,13 +5,17 @@
 //!
 //! [handler-impl]: trait.Handler.html#implementors
 
+use std::io;
+use std::sync::Arc;
+use std::error::Error;
+
+use chrono;
 use hyper;
 use hyper::server;
 use hyper::server::Request;
 use futures::{future, Future};
-use state::{State, set_request_id};
-use std::io;
-use std::sync::Arc;
+
+use state::{State, set_request_id, request_id};
 
 /// A type alias for the trait objects returned by `HandlerService`
 pub type HandlerFuture =
@@ -129,26 +133,66 @@ impl<T> server::Service for NewHandlerService<T>
     type Future = Box<Future<Item = server::Response, Error = hyper::Error>>;
 
     fn call(&self, req: Self::Request) -> Self::Future {
+        let s = chrono::UTC::now();
+
         let mut state = State::new();
         set_request_id(&mut state, &req);
 
+        info!("[REQUEST][{}][{}][{}]",
+              request_id(&state),
+              req.method(),
+              req.path());
+
         // Hyper doesn't allow us to present an affine-typed `Handler` interface directly. We have
         // to emulate the promise given by hyper's documentation, by creating a `Handler` value and
         // immediately consuming it.
         match self.t.new_handler() {
             Ok(handler) => {
                 handler
                     .handle(state, req)
-                    .and_then(|(_, response)| future::ok(response))
-                    .or_else(|(_, error)| future::err(error))
+                    .and_then(move |(state, res)| {
+                        let f = chrono::UTC::now();
+                        match f.signed_duration_since(s).num_microseconds() {
+                            Some(dur) => {
+                                info!("[RESPONSE][{}][{}][{}][{}µs]",
+                                      request_id(&state),
+                                      res.version(),
+                                      res.status(),
+                                      dur);
+                            }
+                            None => {
+                                info!("[RESPONSE][{}][{}][{}][invalid]",
+                                      request_id(&state),
+                                      res.version(),
+                                      res.status());
+                            }
+                        }
+                        future::ok(res)
+                    })
+                    .or_else(move |(state, err)| {
+                        let f = chrono::UTC::now();
+                        match f.signed_duration_since(s).num_microseconds() {
+                            Some(dur) => {
+                                error!("[ERROR][{}][Error: {}][{}]",
+                                       request_id(&state),
+                                       err.description(),
+                                       dur);
+                            }
+                            None => {
+                                error!("[ERROR][{}][Error: {}][invalid]",
+                                       request_id(&state),
+                                       err.description());
+                            }
+                        }
+                        future::err(err)
+                    })
                     .boxed()
             }
             Err(e) => future::err(e.into()).boxed(),
         }
     }
 }
 
-// TODO: Ensure this is actually true in the new implementation of `Router`
 /// A `Handler` receives some subset of requests to the application, and returns a future which
 /// resolves to a response. This represents the common entry point for the parts of a Gotham
 /// application, implemented by `Router` and `Pipeline`.

src/http/mod.rs

@@ -18,8 +18,14 @@ impl PercentDecoded {
     /// has already occured.
     pub fn new(raw: &str) -> Option<Self> {
         match percent_decode(raw.as_bytes()).decode_utf8() {
-            Ok(pd) => Some(PercentDecoded { val: pd.into_owned() }),
-            Err(_) => None,
+            Ok(pd) => {
+                trace!(" percent_decode: {}, src: {}", pd, raw);
+                Some(PercentDecoded { val: pd.into_owned() })
+            }
+            Err(_) => {
+                trace!(" percent_decode: error, src: {}", raw);
+                None
+            }
         }
     }
 
@@ -44,8 +50,14 @@ impl FormUrlDecoded {
     /// has already occured.
     pub fn new(raw: &str) -> Option<Self> {
         match percent_decode(raw.replace("+", " ").as_bytes()).decode_utf8() {
-            Ok(pd) => Some(FormUrlDecoded { val: pd.into_owned() }),
-            Err(_) => None,
+            Ok(pd) => {
+                trace!(" form_url_decoded: {}, src: {}", pd, raw);
+                Some(FormUrlDecoded { val: pd.into_owned() })
+            }
+            Err(_) => {
+                trace!(" form_url_decoded: error, src: {}", raw);
+                None
+            }
         }
     }
 

src/lib.rs

@@ -24,6 +24,9 @@ extern crate mio;
 extern crate borrow_bag;
 extern crate url;
 extern crate uuid;
+#[macro_use]
+extern crate log;
+extern crate chrono;
 
 pub mod dispatch;
 pub mod handler;
@@ -32,9 +35,3 @@ pub mod http;
 pub mod router;
 pub mod state;
 pub mod test;
-
-#[cfg(test)]
-mod tests {
-    #[test]
-    fn it_works() {}
-}

src/middleware/mod.rs

@@ -1,9 +1,11 @@
 //! Defines types for Gotham middleware
 
 use std::io;
+
+use hyper::server::Request;
+
 use handler::HandlerFuture;
 use state::State;
-use hyper::server::Request;
 
 pub mod pipeline;
 

src/middleware/pipeline.rs

@@ -1,11 +1,13 @@
 //! Defines types for a middleware pipeline
 
 use std::io;
-use middleware::{Middleware, NewMiddleware};
-use handler::HandlerFuture;
-use state::State;
+
 use hyper::server::Request;
 
+use handler::HandlerFuture;
+use middleware::{Middleware, NewMiddleware};
+use state::{State, request_id};
+
 /// When using middleware, one or more [`Middleware`][Middleware] are combined to form a
 /// `Pipeline`. `Middleware` are invoked strictly in the order they're added to the `Pipeline`.
 ///
@@ -185,6 +187,7 @@ impl<T> PipelineInstance<T>
     pub fn call<F>(self, state: State, req: Request, f: F) -> Box<HandlerFuture>
         where F: FnOnce(State, Request) -> Box<HandlerFuture> + Send + 'static
     {
+        trace!("[{}] calling middleware", request_id(&state));
         self.chain.call(state, req, f)
     }
 }
@@ -195,6 +198,7 @@ impl<T> PipelineInstance<T>
 ///
 /// [PipelineBuilder]: struct.PipelineBuilder.html
 pub fn new_pipeline() -> PipelineBuilder<()> {
+    trace!(" starting pipeline construction");
     // See: `impl NewMiddlewareChain for ()`
     PipelineBuilder { t: () }
 }
@@ -317,6 +321,7 @@ impl<T> PipelineBuilder<T>
         // An empty `PipelineBuilder` is represented as:
         //
         //     PipelineBuilder { t: () }
+        trace!(" adding middleware to pipeline");
         PipelineBuilder { t: (m, self.t) }
     }
 }
@@ -345,6 +350,7 @@ unsafe impl<T, U> NewMiddlewareChain for (T, U)
         // creating the `Middleware` instances for serving a single request.
         //
         // The reversed order is preserved in the return value.
+        trace!(" adding middleware instance to pipeline");
         let (ref nm, ref tail) = *self;
         Ok((nm.new_middleware()?, tail.construct()?))
     }
@@ -355,6 +361,7 @@ unsafe impl NewMiddlewareChain for () {
 
     fn construct(&self) -> io::Result<Self::Instance> {
         // () marks the end of the list, so is returned as-is.
+        trace!(" completed middleware pipeline construction");
         Ok(())
     }
 }
@@ -381,6 +388,7 @@ unsafe impl MiddlewareChain for () {
         //
         // In the case of 0 middleware, `f` is the function created in `MiddlewareChain::call`
         // which invokes the `Handler` directly.
+        trace!("pipeline complete, invoking handler");
         f(state, request)
     }
 }
@@ -408,6 +416,7 @@ unsafe impl<T, U> MiddlewareChain for (T, U)
         //  }
         //
         // The resulting function is called by `<() as MiddlewareChain>::call`
+        trace!("[{}] executing middleware", request_id(&state));
         p.call(state, request, move |state, req| m.call(state, req, f))
     }
 }