Merge pull request #60 from gotham-rs/catch-panics

Catch synchronous panics in `NewHandlerService`

examples/kitchen-sink/src/main.rs

@@ -12,6 +12,8 @@ extern crate mime;
 
 mod middleware;
 
+use std::panic::RefUnwindSafe;
+
 use futures::{future, Future, Stream};
 
 use hyper::{Body, Response, Method, StatusCode};
@@ -70,7 +72,7 @@ fn static_route<NH, P, C>(
 where
     NH: NewHandler + 'static,
     C: PipelineHandleChain<P> + Send + Sync + 'static,
-    P: Send + Sync + 'static,
+    P: Send + Sync + RefUnwindSafe + 'static,
 {
     let matcher = MethodOnlyRouteMatcher::new(methods);
     let dispatcher = DispatcherImpl::new(new_handler, active_pipelines, pipeline_set);
@@ -93,7 +95,7 @@ fn dynamic_route<NH, P, C>(
 where
     NH: NewHandler + 'static,
     C: PipelineHandleChain<P> + Send + Sync + 'static,
-    P: Send + Sync + 'static,
+    P: Send + Sync + RefUnwindSafe + 'static,
 {
     let matcher = MethodOnlyRouteMatcher::new(methods);
     let dispatcher = DispatcherImpl::new(new_handler, active_pipelines, pipeline_set);

src/handler/mod.rs

@@ -7,19 +7,19 @@
 
 use std::io;
 use std::sync::Arc;
-use std::error::Error;
+use std::panic::{AssertUnwindSafe, RefUnwindSafe};
 
-use chrono::prelude::*;
 use hyper;
 use hyper::server::{NewService, Service};
 use hyper::{Request, Response};
 use futures::{future, Future};
 
-use state::{State, set_request_id, request_id};
+use state::{State, set_request_id};
 use http::request::path::RequestPathSegments;
-use http::header::XRuntimeMicroseconds;
 
 mod error;
+mod timing;
+mod trap;
 
 pub use self::error::{HandlerError, IntoHandlerError};
 
@@ -148,7 +148,6 @@ where
     type Future = Box<Future<Item = Self::Response, Error = Self::Error>>;
 
     fn call(&self, req: Self::Request) -> Self::Future {
-        let s = Utc::now();
         let (method, uri, version, headers, body) = req.deconstruct();
 
         let mut state = State::new();
@@ -160,77 +159,7 @@ where
         state.put(body);
         set_request_id(&mut state);
 
-        // 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) => {
-                let f = handler
-                    .handle(state)
-                    .and_then(move |(state, res)| {
-                        let f = Utc::now();
-                        match f.signed_duration_since(s).num_microseconds() {
-                            Some(dur) => {
-                                info!(
-                                    "[RESPONSE][{}][{}][{}][{}µs]",
-                                    request_id(&state),
-                                    res.version(),
-                                    res.status(),
-                                    dur
-                                );
-
-                                future::ok(res.with_header(XRuntimeMicroseconds(dur)))
-                            }
-                            None => {
-                                // Valid response is still sent to client in this case but
-                                // timing has failed and should be looked into.
-                                error!(
-                                    "[RESPONSE][{}][{}][{}][invalid]",
-                                    request_id(&state),
-                                    res.version(),
-                                    res.status()
-                                );
-                                future::ok(res)
-                            }
-                        }
-                    })
-                    .or_else(move |(state, err)| {
-                        let f = Utc::now();
-
-                        {
-                            // HandlerError::cause() is far more interesting for logging,
-                            // but the API doesn't guarantee its presence (even though it
-                            // always is).
-                            let err_description = err.cause().map(Error::description).unwrap_or(
-                                err.description(),
-                            );
-
-                            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::ok(err.into_response(&state))
-                    });
-
-                Box::new(f)
-            }
-            Err(e) => Box::new(future::err(e.into())),
-        }
+        trap::call_handler(self.t.as_ref(), AssertUnwindSafe(state))
     }
 }
 
@@ -251,7 +180,7 @@ pub trait Handler {
 }
 
 /// Creates new `Handler` values.
-pub trait NewHandler: Send + Sync {
+pub trait NewHandler: Send + Sync + RefUnwindSafe {
     /// The type of `Handler` created by the implementor.
     type Instance: Handler;
 
@@ -261,7 +190,7 @@ pub trait NewHandler: Send + Sync {
 
 impl<F, H> NewHandler for F
 where
-    F: Fn() -> io::Result<H> + Send + Sync,
+    F: Fn() -> io::Result<H> + Send + Sync + RefUnwindSafe,
     H: Handler,
 {
     type Instance = H;

src/handler/timing.rs

@@ -0,0 +1,79 @@
+//! Defines types for timing requests and emitting timing information into logs and responses.
+
+use std::fmt::{self, Display, Formatter};
+
+use chrono::prelude::*;
+use hyper::Response;
+
+use state::{State, request_id};
+use http::header::XRuntimeMicroseconds;
+
+/// Used by `NewHandlerService` to time requests. The `elapsed` function returns the elapsed time
+/// in a way that can be used for logging and adding the `X-Runtime-Microseconds` header to
+/// responses.
+#[derive(Clone, Copy)]
+pub(super) struct Timer {
+    start: DateTime<Utc>,
+}
+
+impl Timer {
+    /// Begins measuring from the current time.
+    pub(super) fn new() -> Timer {
+        Timer { start: Utc::now() }
+    }
+
+    /// Finishes measuring, and returns the elapsed time as a `Timing` value.
+    pub(super) fn elapsed(self, state: &State) -> Timing {
+        let timing = self.elapsed_no_logging();
+
+        if let Timing::Invalid = timing {
+            error!(
+                "[{}] Unable to measure timing of request, num_microseconds was None",
+                request_id(state)
+            );
+        }
+
+        timing
+    }
+
+    pub(super) fn elapsed_no_logging(self) -> Timing {
+        let Timer { start } = self;
+        match Utc::now().signed_duration_since(start).num_microseconds() {
+            Some(dur) => Timing::Microseconds(dur),
+            None => Timing::Invalid,
+        }
+    }
+}
+
+/// Represents an elapsed time measured by `Timer`.
+#[derive(Clone, Copy)]
+pub(super) enum Timing {
+    /// A number of microseconds measured by `Timer`.
+    Microseconds(i64),
+
+    /// An invalid state, where the amount of time elapsed was unable to be measured.
+    Invalid,
+}
+
+impl Timing {
+    /// Converts a `Response` into a new `Response` with the `X-Runtime-Microseconds` header
+    /// included (assuming the time elapsed was able to be measured).
+    pub(super) fn add_to_response(&self, response: Response) -> Response {
+        match *self {
+            Timing::Microseconds(i) => response.with_header(XRuntimeMicroseconds(i)),
+            Timing::Invalid => response,
+        }
+    }
+}
+
+impl Display for Timing {
+    fn fmt(&self, f: &mut Formatter) -> fmt::Result {
+        match *self {
+            Timing::Microseconds(i) => {
+                i.fmt(f)?;
+                f.write_str("µs")
+            }
+            Timing::Invalid => f.write_str("invalid"),
+        }
+    }
+}