From 7cf221f76777de1087ca518bceb17b3e85f5afdc Mon Sep 17 00:00:00 2001 From: Nikolay Kim Date: Sat, 20 Jan 2018 20:12:24 -0800 Subject: [PATCH] Log request processing errors --- CHANGES.md | 5 +++- Cargo.toml | 2 +- examples/basics/Cargo.toml | 2 +- examples/basics/src/main.rs | 15 ++++++++---- src/error.rs | 47 +++++++++++++++++++++++++++++++------ src/pipeline.rs | 28 +++++++++++++++------- 6 files changed, 75 insertions(+), 24 deletions(-) diff --git a/CHANGES.md b/CHANGES.md index 61af4ba8f..a696ae611 100644 --- a/CHANGES.md +++ b/CHANGES.md @@ -4,10 +4,13 @@ * Fix HEAD requests handling -* Can't have multiple Applications on a single server with different state #49 +* Log request processing errors + +* Allow multiple Applications on a single server with different state #49 * CORS middleware: allowed_headers is defaulting to None #50 + ## 0.3.1 (2018-01-13) * Fix directory entry path #47 diff --git a/Cargo.toml b/Cargo.toml index 6c04a4acd..90f49b13d 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -81,7 +81,7 @@ version = "0.9" optional = true [dev-dependencies] -env_logger = "0.4" +env_logger = "0.5" reqwest = "0.8" skeptic = "0.13" serde_derive = "1.0" diff --git a/examples/basics/Cargo.toml b/examples/basics/Cargo.toml index afded97b2..fd1f1ce4f 100644 --- a/examples/basics/Cargo.toml +++ b/examples/basics/Cargo.toml @@ -6,6 +6,6 @@ workspace = "../.." [dependencies] futures = "*" -env_logger = "0.4" +env_logger = "0.5" actix = "0.4" actix-web = { path="../.." } diff --git a/examples/basics/src/main.rs b/examples/basics/src/main.rs index 68dc17f30..f52b09544 100644 --- a/examples/basics/src/main.rs +++ b/examples/basics/src/main.rs @@ -7,6 +7,7 @@ extern crate env_logger; extern crate futures; use futures::Stream; +use std::{io, env}; use actix_web::*; use actix_web::middleware::RequestSession; use futures::future::{FutureResult, result}; @@ -56,17 +57,17 @@ fn index(mut req: HttpRequest) -> Result { fn p404(req: HttpRequest) -> Result { // html - let html = format!(r#"actix - basics + let html = r#"actix - basics back to home

404

-"#); +"#; // response Ok(HttpResponse::build(StatusCode::NOT_FOUND) .content_type("text/html; charset=utf-8") - .body(&html).unwrap()) + .body(html).unwrap()) } @@ -92,8 +93,9 @@ fn with_param(req: HttpRequest) -> Result } fn main() { - ::std::env::set_var("RUST_LOG", "actix_web=info"); - let _ = env_logger::init(); + env::set_var("RUST_LOG", "actix_web=debug"); + env::set_var("RUST_BACKTRACE", "1"); + env_logger::init(); let sys = actix::System::new("basic-example"); let addr = HttpServer::new( @@ -121,6 +123,9 @@ fn main() { _ => httpcodes::HTTPNotFound, } })) + .resource("/error.html", |r| r.f(|req| { + error::ErrorBadRequest(io::Error::new(io::ErrorKind::Other, "test")) + })) // static files .handler("/static/", fs::StaticFiles::new("../static/", true)) // redirect diff --git a/src/error.rs b/src/error.rs index 0fe12a807..512419a85 100644 --- a/src/error.rs +++ b/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 = result::Result; /// General purpose actix web error -#[derive(Fail, Debug)] pub struct Error { cause: Box, + backtrace: Option, } 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 for HttpResponse { fn from(err: Error) -> Self { @@ -74,7 +86,12 @@ impl From for HttpResponse { /// `Error` for any error that implements `ResponseError` impl From 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 Fail for $type {} - impl fmt::Display for $type { + impl Fail for $type {} + impl Fail for $type { + fn backtrace(&self) -> Option<&Backtrace> { + self.cause().backtrace() + } + } + + impl fmt::Display for $type { fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result { - write!(f, "{:?}", self.0) + fmt::Display::fmt(&self.0, f) } } impl 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 Responder for $type + where T: Send + Sync + fmt::Debug + fmt::Display + 'static + { + type Item = HttpResponse; + type Error = Error; + + fn respond_to(self, _: HttpRequest) -> Result { + Err(self.into()) + } + } } } diff --git a/src/pipeline.rs b/src/pipeline.rs index 55d2a4f8b..fb3c9b0b0 100644 --- a/src/pipeline.rs +++ b/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> PipelineState { struct PipelineInfo { req: HttpRequest, - count: usize, + count: u16, mws: Rc>>>, context: Option>, error: Option, @@ -211,13 +212,13 @@ impl> StartMiddlewares { fn init(info: &mut PipelineInfo, handler: Rc>) -> PipelineState { // 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> StartMiddlewares { } fn poll(&mut self, info: &mut PipelineInfo) -> Option> { - 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> StartMiddlewares { 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 RunMiddlewares { 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 ProcessResponse { } }; + 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 ProcessResponse { }, 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 ProcessResponse { 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 FinishingMiddlewares { 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 Completed { #[inline] fn init(info: &mut PipelineInfo) -> PipelineState { + if let Some(ref err) = info.error { + error!("Error occured during request handling: {}", err); + } + if info.context.is_none() { PipelineState::None } else {