Log request processing errors

src/error.rs

@@ -9,8 +9,8 @@ use std::error::Error as StdError;
 
 use cookie;
 use httparse;
-use failure::Fail;
 use futures::Canceled;
+use failure::{Fail, Backtrace};
 use http2::Error as Http2Error;
 use http::{header, StatusCode, Error as HttpError};
 use http::uri::InvalidUriBytes;
@@ -22,6 +22,8 @@ use url::ParseError as UrlParseError;
 pub use cookie::{ParseError as CookieParseError};
 
 use body::Body;
+use handler::Responder;
+use httprequest::HttpRequest;
 use httpresponse::HttpResponse;
 use httpcodes::{HTTPBadRequest, HTTPMethodNotAllowed, HTTPExpectationFailed};
 
@@ -33,9 +35,9 @@ use httpcodes::{HTTPBadRequest, HTTPMethodNotAllowed, HTTPExpectationFailed};
 pub type Result<T, E=Error> = result::Result<T, E>;
 
 /// General purpose actix web error
-#[derive(Fail, Debug)]
 pub struct Error {
     cause: Box<ResponseError>,
+    backtrace: Option<Backtrace>,
 }
 
 impl Error {
@@ -64,6 +66,16 @@ impl fmt::Display for Error {
     }
 }
 
+impl fmt::Debug for Error {
+    fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result {
+        if self.backtrace.is_none() {
+            fmt::Debug::fmt(&self.cause, f)
+        } else {
+            write!(f, "{:?}\n\n{:?}", &self.cause, self.backtrace.as_ref().unwrap())
+        }
+    }
+}
+
 /// `HttpResponse` for `Error`
 impl From<Error> for HttpResponse {
     fn from(err: Error) -> Self {
@@ -74,7 +86,12 @@ impl From<Error> for HttpResponse {
 /// `Error` for any error that implements `ResponseError`
 impl<T: ResponseError> From<T> for Error {
     fn from(err: T) -> Error {
-        Error { cause: Box::new(err) }
+        let backtrace = if err.backtrace().is_none() {
+            Some(Backtrace::new())
+        } else {
+            None
+        };
+        Error { cause: Box::new(err), backtrace: backtrace }
     }
 }
 
@@ -489,21 +506,37 @@ macro_rules! ERROR_WRAP {
             }
         }
 
-        impl<T: fmt::Debug + 'static> Fail for $type {}
-        impl<T: fmt::Debug + 'static> fmt::Display for $type {
+        impl<T: fmt::Display + fmt::Debug + 'static> Fail for $type {}
+        impl<T: Fail> Fail for $type {
+            fn backtrace(&self) -> Option<&Backtrace> {
+                self.cause().backtrace()
+            }
+        }
+
+        impl<T: fmt::Display + 'static> fmt::Display for $type {
             fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result {
-                write!(f, "{:?}", self.0)
+                fmt::Display::fmt(&self.0, f)
             }
         }
 
         impl<T> ResponseError for $type
-            where T: Send + Sync + fmt::Debug + 'static,
+            where T: Send + Sync + fmt::Debug + fmt::Display + 'static
         {
             fn error_response(&self) -> HttpResponse {
                 HttpResponse::new($status, Body::Empty)
             }
         }
 
+        impl<T> Responder for $type
+            where T: Send + Sync + fmt::Debug + fmt::Display + 'static
+        {
+            type Item = HttpResponse;
+            type Error = Error;
+
+            fn respond_to(self, _: HttpRequest) -> Result<HttpResponse, Error> {
+                Err(self.into())
+            }
+        }
     }
 }
 

src/pipeline.rs

@@ -3,6 +3,7 @@ use std::rc::Rc;
 use std::cell::RefCell;
 use std::marker::PhantomData;
 
+use log::Level::Debug;
 use futures::{Async, Poll, Future, Stream};
 use futures::unsync::oneshot;
 
@@ -56,7 +57,7 @@ impl<S: 'static, H: PipelineHandler<S>> PipelineState<S, H> {
 
 struct PipelineInfo<S> {
     req: HttpRequest<S>,
-    count: usize,
+    count: u16,
     mws: Rc<Vec<Box<Middleware<S>>>>,
     context: Option<Box<ActorHttpContext>>,
     error: Option<Error>,
@@ -211,13 +212,13 @@ impl<S: 'static, H: PipelineHandler<S>> StartMiddlewares<S, H> {
     fn init(info: &mut PipelineInfo<S>, handler: Rc<RefCell<H>>) -> PipelineState<S, H> {
         // execute middlewares, we need this stage because middlewares could be non-async
         // and we can move to next state immediately
-        let len = info.mws.len();
+        let len = info.mws.len() as u16;
         loop {
             if info.count == len {
                 let reply = handler.borrow_mut().handle(info.req.clone());
                 return WaitingResponse::init(info, reply)
             } else {
-                match info.mws[info.count].start(&mut info.req) {
+                match info.mws[info.count as usize].start(&mut info.req) {
                     Ok(Started::Done) =>
                         info.count += 1,
                     Ok(Started::Response(resp)) =>
@@ -246,7 +247,7 @@ impl<S: 'static, H: PipelineHandler<S>> StartMiddlewares<S, H> {
     }
 
     fn poll(&mut self, info: &mut PipelineInfo<S>) -> Option<PipelineState<S, H>> {
-        let len = info.mws.len();
+        let len = info.mws.len() as u16;
         'outer: loop {
             match self.fut.as_mut().unwrap().poll() {
                 Ok(Async::NotReady) => return None,
@@ -260,7 +261,7 @@ impl<S: 'static, H: PipelineHandler<S>> StartMiddlewares<S, H> {
                         return Some(WaitingResponse::init(info, reply));
                     } else {
                         loop {
-                            match info.mws[info.count].start(info.req_mut()) {
+                            match info.mws[info.count as usize].start(info.req_mut()) {
                                 Ok(Started::Done) =>
                                     info.count += 1,
                                 Ok(Started::Response(resp)) => {
@@ -334,7 +335,7 @@ impl<S: 'static, H> RunMiddlewares<S, H> {
         loop {
             resp = match info.mws[curr].response(info.req_mut(), resp) {
                 Err(err) => {
-                    info.count = curr + 1;
+                    info.count = (curr + 1) as u16;
                     return ProcessResponse::init(err.into())
                 }
                 Ok(Response::Done(r)) => {
@@ -458,6 +459,13 @@ impl<S: 'static, H> ProcessResponse<S, H> {
                             }
                         };
 
+                        if let Some(err) = self.resp.error() {
+                            warn!("Error occured during request handling: {}", err);
+                            if log_enabled!(Debug) {
+                                debug!("{:?}", err);
+                            }
+                        }
+
                         match self.resp.replace_body(Body::Empty) {
                             Body::Streaming(stream) =>
                                 self.iostate = IOState::Payload(stream),
@@ -586,7 +594,6 @@ impl<S: 'static, H> ProcessResponse<S, H> {
                 },
                 Ok(Async::NotReady) => return Err(PipelineState::Response(self)),
                 Err(err) => {
-                    debug!("Error sending data: {}", err);
                     info.error = Some(err.into());
                     return Ok(FinishingMiddlewares::init(info, self.resp))
                 }
@@ -599,7 +606,6 @@ impl<S: 'static, H> ProcessResponse<S, H> {
                 match io.write_eof() {
                     Ok(_) => (),
                     Err(err) => {
-                        debug!("Error sending data: {}", err);
                         info.error = Some(err.into());
                         return Ok(FinishingMiddlewares::init(info, self.resp))
                     }
@@ -661,7 +667,7 @@ impl<S: 'static, H> FinishingMiddlewares<S, H> {
             self.fut = None;
             info.count -= 1;
 
-            match info.mws[info.count].finish(info.req_mut(), &self.resp) {
+            match info.mws[info.count as usize].finish(info.req_mut(), &self.resp) {
                 Finished::Done => {
                     if info.count == 0 {
                         return Some(Completed::init(info))
@@ -682,6 +688,10 @@ impl<S, H> Completed<S, H> {
 
     #[inline]
     fn init(info: &mut PipelineInfo<S>) -> PipelineState<S, H> {
+        if let Some(ref err) = info.error {
+            error!("Error occured during request handling: {}", err);
+        }
+
         if info.context.is_none() {
             PipelineState::None
         } else {