Use fmt::Display to format error messages in logs (#477)

This PR changes the proxy to log error messages using `fmt::Display` whenever possible, which should lead to much more readable and meaningful error messages

This is part of the work I started last week on issue #442. While I haven't finished everything for that issue (all errors still are mapped to HTTP 500 error codes), I wanted to go ahead and open a PR for the more readable error messages. This is partially because I found myself merging these changes into other branches to aid in debugging, and because I figured we may as well have the nicer logging on master.

proxy/router/src/lib.rs

@@ -6,8 +6,8 @@ use futures::{Future, Poll};
 use indexmap::IndexMap;
 use tower::Service;
 
+use std::{error, fmt, mem};
 use std::hash::Hash;
-use std::mem;
 use std::sync::{Arc, Mutex};
 
 /// Route requests based on the request authority
@@ -223,3 +223,42 @@ where T: Recognize,
         }
     }
 }
+
+// ===== impl RouteError =====
+
+impl<T, U> fmt::Display for Error<T, U>
+where
+    T: fmt::Display,
+    U: fmt::Display,
+{
+    fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result {
+        match *self {
+            Error::Inner(ref why) => fmt::Display::fmt(why, f),
+            Error::Route(ref why) =>
+                write!(f, "route recognition failed: {}", why),
+            Error::NotRecognized => f.pad("route not recognized"),
+        }
+    }
+}
+
+impl<T, U> error::Error for Error<T, U>
+where
+    T: error::Error,
+    U: error::Error,
+{
+    fn cause(&self) -> Option<&error::Error> {
+        match *self {
+            Error::Inner(ref why) => Some(why),
+            Error::Route(ref why) => Some(why),
+            _ => None,
+        }
+    }
+
+    fn description(&self) -> &str {
+        match *self {
+            Error::Inner(_) => "inner service error",
+            Error::Route(_) => "route recognition failed",
+            Error::NotRecognized => "route not recognized",
+        }
+    }
+}

proxy/src/bind.rs

@@ -1,3 +1,5 @@
+use std::error::Error;
+use std::fmt;
 use std::marker::PhantomData;
 use std::net::SocketAddr;
 use std::sync::Arc;
@@ -60,6 +62,33 @@ pub type Client<B> = transparency::Client<
     B,
 >;
 
+#[derive(Copy, Clone, Debug)]
+pub enum BufferSpawnError {
+    Inbound,
+    Outbound,
+}
+
+impl fmt::Display for BufferSpawnError {
+    fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result {
+        f.pad(self.description())
+    }
+}
+
+impl Error for BufferSpawnError {
+
+    fn description(&self) -> &str {
+        match *self {
+            BufferSpawnError::Inbound =>
+                "error spawning inbound buffer task",
+            BufferSpawnError::Outbound =>
+                "error spawning outbound buffer task",
+        }
+    }
+
+    fn cause(&self) -> Option<&Error> { None }
+}
+
+
 impl<B> Bind<(), B> {
     pub fn new(executor: Handle) -> Self {
         Self {

proxy/src/inbound.rs

@@ -43,7 +43,7 @@ where
         >
     >;
     type Key = (SocketAddr, bind::Protocol);
-    type RouteError = ();
+    type RouteError = bind::BufferSpawnError;
     type Service = InFlightLimit<Buffer<bind::Service<B>>>;
 
     fn recognize(&self, req: &Self::Request) -> Option<Self::Key> {
@@ -81,7 +81,7 @@ where
             .map(|buffer| {
                 InFlightLimit::new(buffer, MAX_IN_FLIGHT)
             })
-            .map_err(|_| {})
+            .map_err(|_| bind::BufferSpawnError::Inbound)
     }
 }
 

proxy/src/lib.rs

@@ -44,6 +44,7 @@ extern crate tower_in_flight_limit;
 
 use futures::*;
 
+use std::error::Error;
 use std::io;
 use std::net::SocketAddr;
 use std::sync::Arc;
@@ -53,7 +54,7 @@ use std::time::Duration;
 use tokio_core::reactor::{Core, Handle};
 use tower::NewService;
 use tower_fn::*;
-use conduit_proxy_router::{Recognize, Router};
+use conduit_proxy_router::{Recognize, Router, Error as RouteError};
 
 pub mod app;
 mod bind;
@@ -301,8 +302,8 @@ fn serve<R, B, E, F, G>(
 ) -> Box<Future<Item = (), Error = io::Error> + 'static>
 where
     B: tower_h2::Body + Default + 'static,
-    E: ::std::fmt::Debug + 'static,
+    E: Error + 'static,
-    F: ::std::fmt::Debug + 'static,
+    F: Error + 'static,
     R: Recognize<
         Request = http::Request<HttpBody>,
         Response = http::Response<telemetry::sensor::http::ResponseBody<B>>,
@@ -317,8 +318,23 @@ where
         // Clone the router handle
         let router = router.clone();
 
-        // Map errors to 500 responses
+        // Map errors to appropriate response error codes.
-        MapErr::new(router)
+        MapErr::new(router, |e| {
+            match e {
+                RouteError::Route(r) => {
+                    error!(" turning route error: {} into 500", r);
+                    http::StatusCode::INTERNAL_SERVER_ERROR
+                }
+                RouteError::Inner(i) => {
+                    error!("turning {} into 500", i);
+                    http::StatusCode::INTERNAL_SERVER_ERROR
+                }
+                RouteError::NotRecognized => {
+                    error!("turning route not recognized error into 500");
+                    http::StatusCode::INTERNAL_SERVER_ERROR
+                }
+            }
+        })
     }));
 
     let listen_addr = bound_port.local_addr();

proxy/src/map_err.rs

@@ -1,5 +1,5 @@
-use std::fmt::Debug;
 use std::marker::PhantomData;
+use std::sync::Arc;
 
 use futures::{Future, Poll};
 use h2;
@@ -8,43 +8,47 @@ use http::header::CONTENT_LENGTH;
 use tower::Service;
 
 /// Map an HTTP service's error to an appropriate 500 response.
-pub struct MapErr<T, E> {
+pub struct MapErr<T, E, F> {
     inner: T,
+    f: Arc<F>,
     _p: PhantomData<E>,
 }
 
 /// Catches errors from the inner future and maps them to 500 responses.
-pub struct ResponseFuture<T, E> {
+pub struct ResponseFuture<T, E, F> {
     inner: T,
+    f: Arc<F>,
     _p: PhantomData<E>,
 }
 
+
 // ===== impl MapErr =====
 
-impl<T, E> MapErr<T, E>
+impl<T, E, F> MapErr<T, E, F>
 where
     T: Service<Error = E>,
-    E: Debug,
+    F: Fn(E) -> http::StatusCode,
 {
     /// Crete a new `MapErr`
-    pub fn new(inner: T) -> Self {
+    pub fn new(inner: T, f: F) -> Self {
         MapErr {
             inner,
+            f: Arc::new(f),
             _p: PhantomData,
         }
     }
 }
 
-impl<T, B, E> Service for MapErr<T, E>
+impl<T, B, E, F> Service for MapErr<T, E, F>
 where
     T: Service<Response = http::Response<B>, Error = E>,
     B: Default,
-    E: Debug,
+    F: Fn(E) -> http::StatusCode,
 {
     type Request = T::Request;
     type Response = T::Response;
     type Error = h2::Error;
-    type Future = ResponseFuture<T::Future, E>;
+    type Future = ResponseFuture<T::Future, E, F>;
 
     fn poll_ready(&mut self) -> Poll<(), Self::Error> {
         self.inner.poll_ready()
@@ -56,6 +60,7 @@ where
         let inner = self.inner.call(request);
         ResponseFuture {
             inner,
+            f: self.f.clone(),
             _p: PhantomData,
         }
     }
@@ -63,20 +68,20 @@ where
 
 // ===== impl ResponseFuture =====
 
-impl<T, B, E> Future for ResponseFuture<T, E>
+impl<T, B, E, F> Future for ResponseFuture<T, E, F>
 where
     T: Future<Item = http::Response<B>, Error = E>,
     B: Default,
-    E: Debug,
+    F: Fn(E) -> http::StatusCode,
 {
     type Item = T::Item;
     type Error = h2::Error;
 
     fn poll(&mut self) -> Poll<Self::Item, Self::Error> {
         self.inner.poll().or_else(|e| {
-            error!("turning service error into 500: {:?}", e);
+            let status = (self.f)(e);
             let response = http::Response::builder()
-                .status(500)
+                .status(status)
                 .header(CONTENT_LENGTH, "0")
                 .body(Default::default())
                 .unwrap();

proxy/src/outbound.rs

@@ -1,10 +1,11 @@
+use std::{error, fmt};
 use std::net::SocketAddr;
 use std::time::Duration;
+use std::sync::Arc;
 
 use futures::{Async, Poll};
 use http;
 use rand;
-use std::sync::Arc;
 use tower;
 use tower_balance::{self, choose, load, Balance};
 use tower_buffer::Buffer;
@@ -65,7 +66,7 @@ where
     type Response = bind::HttpResponse;
     type Error = <Self::Service as tower::Service>::Error;
     type Key = (Destination, Protocol);
-    type RouteError = ();
+    type RouteError = bind::BufferSpawnError;
     type Service = InFlightLimit<Timeout<Buffer<Balance<
         load::WithPendingRequests<Discovery<B>>,
         choose::PowerOfTwoChoices<rand::ThreadRng>
@@ -145,7 +146,8 @@ where
         // `Timeout`.
         let handle = self.bind.executor();
 
-        let buffer = Buffer::new(balance, handle).map_err(|_| {})?;
+        let buffer = Buffer::new(balance, handle)
+            .map_err(|_| bind::BufferSpawnError::Outbound)?;
 
         let timeout = Timeout::new(buffer, self.bind_timeout, handle);
 
@@ -168,11 +170,12 @@ where
     type Response = bind::HttpResponse;
     type Error = <bind::Service<B> as tower::Service>::Error;
     type Service = bind::Service<B>;
-    type DiscoverError = ();
+    type DiscoverError = BindError;
 
     fn poll(&mut self) -> Poll<Change<Self::Key, Self::Service>, Self::DiscoverError> {
         match *self {
-            Discovery::LocalSvc(ref mut w) => w.poll(),
+            Discovery::LocalSvc(ref mut w) => w.poll()
+                .map_err(|_| BindError::Internal),
             Discovery::External(ref mut opt) => {
                 // This "discovers" a single address for an external service
                 // that never has another change. This can mean it floats
@@ -180,7 +183,8 @@ where
                 // circuit-breaking, this should be able to take care of itself,
                 // closing down when the connection is no longer usable.
                 if let Some((addr, bind)) = opt.take() {
-                    let svc = bind.bind(&addr)?;
+                    let svc = bind.bind(&addr)
+                        .map_err(|_| BindError::External{ addr })?;
                     Ok(Async::Ready(Change::Insert(addr, svc)))
                 } else {
                     Ok(Async::NotReady)
@@ -189,3 +193,31 @@ where
         }
     }
 }
+#[derive(Copy, Clone, Debug)]
+pub enum BindError {
+    External { addr: SocketAddr },
+    Internal,
+}
+
+impl fmt::Display for BindError {
+    fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result {
+        match *self {
+            BindError::External { addr } =>
+                write!(f, "binding external service for {:?} failed", addr),
+            BindError::Internal =>
+                write!(f, "binding internal service failed"),
+        }
+    }
+
+}
+
+impl error::Error for BindError {
+    fn description(&self) -> &str {
+        match *self {
+            BindError::External { .. } => "binding external service failed",
+            BindError::Internal => "binding internal service failed",
+        }
+    }
+
+    fn cause(&self) -> Option<&error::Error> { None }
+}