From 6a81e1f137a73f37ce340c3cc225cd660e38d854 Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Thu, 19 Jul 2018 16:38:31 -0700 Subject: [PATCH] Improve error messages in logs (#18) Currently, the messages that the proxy logs on errors are often not very useful. For example, when an error occurred that caused the proxy to return HTTP 500, we log a message like this: ``` ERR! proxy={server=in listen=0.0.0.0:4143 remote=127.0.0.1:57416} linkerd2_proxy turning Error caused by underlying HTTP/2 error: protocol error: unexpected internal error encountered into 500 ``` Note that: + Regardless of what the error actually was, the current log message *always* says protocol error: unexpected internal error encountered, which is both fairly unclear *and* often not actually the case. + Regardless of whether the error was encountered by an HTTP/1 or HTTP/2 client, the error message always includes the string "underlying HTTP/2 error". This is probably fairly confusing for users who are, say, only proxying HTTP/1 traffic. This branch fixes several related issues around the clarity of the proxy's error messages: + A couple cases in the `transparency` module that returned `io::Error::from(io::ErrorKind::Other)` have been replaced with more descriptive errors that propagate the underlying error. This necessitated adding bounds on some error types. + Introduced a new `transparency::client::Error` enum that can be either a `h2::Error` or a `hyper::Error`, depending on whether the client is HTTP/1 or HTTP/2, and proxies its' `std::error::Error` impl to the wrapped error types. This way, we don't return a `tower_h2::client::Error` (with format output that includes the string "HTTP/2") from everything, and discard significantly less error information. Signed-off-by: Eliza Weisman --- src/telemetry/sensor/http.rs | 11 +++-- src/telemetry/sensor/mod.rs | 5 +- src/transparency/client.rs | 93 ++++++++++++++++++++++++++++-------- src/transparency/glue.rs | 33 ++++++------- src/transparency/mod.rs | 2 +- src/transparency/server.rs | 14 +++--- 6 files changed, 109 insertions(+), 49 deletions(-) diff --git a/src/telemetry/sensor/http.rs b/src/telemetry/sensor/http.rs index 95cfb48f6..79a951524 100644 --- a/src/telemetry/sensor/http.rs +++ b/src/telemetry/sensor/http.rs @@ -7,10 +7,11 @@ use std::marker::PhantomData; use std::sync::Arc; use std::time::Instant; use tower_service::{NewService, Service}; -use tower_h2::{client, Body}; +use tower_h2::Body; use ctx; use telemetry::event::{self, Event}; +use transparency::ClientError; const GRPC_STATUS: &str = "grpc-status"; @@ -118,7 +119,7 @@ where N: NewService< Request = http::Request>, Response = http::Response, - Error = client::Error, + Error = ClientError, > + 'static, { @@ -143,7 +144,7 @@ where N: NewService< Request = http::Request>, Response = http::Response, - Error = client::Error, + Error = ClientError, > + 'static, { @@ -200,7 +201,7 @@ where S: Service< Request = http::Request>, Response = http::Response, - Error = client::Error, + Error = ClientError, > + 'static, { @@ -281,7 +282,7 @@ where impl Future for Respond where - F: Future, Error=client::Error>, + F: Future, Error=ClientError>, B: Body + 'static, { type Item = http::Response>; diff --git a/src/telemetry/sensor/mod.rs b/src/telemetry/sensor/mod.rs index c76377b42..194f97339 100644 --- a/src/telemetry/sensor/mod.rs +++ b/src/telemetry/sensor/mod.rs @@ -6,11 +6,12 @@ use http::{Request, Response}; use tokio_connect; use tokio::io::{AsyncRead, AsyncWrite}; use tower_service::NewService; -use tower_h2::{client, Body}; +use tower_h2::Body; use ctx; use telemetry::event; use transport::{Connection, tls}; +use transparency::ClientError; pub mod http; mod transport; @@ -90,7 +91,7 @@ impl Sensors { N: NewService< Request = Request>, Response = Response, - Error = client::Error + Error = ClientError > + 'static, { diff --git a/src/transparency/client.rs b/src/transparency/client.rs index 33cd3e786..5d5d7cf07 100644 --- a/src/transparency/client.rs +++ b/src/transparency/client.rs @@ -14,9 +14,24 @@ use telemetry::sensor::http::RequestBody; use super::glue::{BodyPayload, HttpBody, HyperConnect}; use super::upgrade::{HttpConnect, Http11Upgrade}; +use std::{self, fmt}; + type HyperClient = hyper::Client, BodyPayload>>; +/// A wrapper around the error types produced by the HTTP/1 and HTTP/2 clients. +/// +/// Note that the names of the variants of this type (`Error::Http1` and +/// `Error::Http2`) aren't intended to imply that the error was a protocol +/// error; instead, they refer simply to which client the error occurred in. +/// Values of either variant may ultimately be caused by IO errors or other +/// types of error which could effect either protocol client. +#[derive(Debug)] +pub enum Error { + Http1(hyper::Error), + Http2(tower_h2::client::Error), +} + /// A `NewService` that can speak either HTTP/1 or HTTP/2. pub struct Client where @@ -91,6 +106,7 @@ impl Client where C: Connect + Clone + Send + Sync + 'static, C::Future: Send + 'static, + ::Error: ::std::error::Error + Send + Sync, C::Connected: Send, E: Executor + Clone, E: future::Executor + Send + 'static>> + Send + Sync + 'static, @@ -130,6 +146,7 @@ impl NewService for Client where C: Connect + Clone + Send + Sync + 'static, C::Future: Send + 'static, + ::Error: ::std::error::Error + Send + Sync, C::Connected: Send, E: Executor + Clone, E: future::Executor + Send + 'static>> + Send + Sync + 'static, @@ -138,7 +155,7 @@ where { type Request = bind::HttpRequest; type Response = http::Response; - type Error = tower_h2::client::Error; + type Error = Error; type InitError = tower_h2::client::ConnectError; type Service = ClientService; type Future = ClientNewServiceFuture; @@ -192,6 +209,7 @@ where C: Connect + Send + Sync + 'static, C::Connected: Send, C::Future: Send + 'static, + ::Error: ::std::error::Error + Send + Sync, E: Executor + Clone, E: future::Executor + Send + 'static>> + Send + Sync + 'static, B: tower_h2::Body + Send + 'static, @@ -199,13 +217,13 @@ where { type Request = bind::HttpRequest; type Response = http::Response; - type Error = tower_h2::client::Error; + type Error = Error; type Future = ClientServiceFuture; fn poll_ready(&mut self) -> Poll<(), Self::Error> { match self.inner { ClientServiceInner::Http1(_) => Ok(Async::Ready(())), - ClientServiceInner::Http2(ref mut h2) => h2.poll_ready(), + ClientServiceInner::Http2(ref mut h2) => h2.poll_ready().map_err(Error::from), } } @@ -245,28 +263,25 @@ pub enum ClientServiceFuture { impl Future for ClientServiceFuture { type Item = http::Response; - type Error = tower_h2::client::Error; + type Error = Error; fn poll(&mut self) -> Poll { match self { ClientServiceFuture::Http1 { future, upgrade, is_http_connect } => { - match future.poll() { - Ok(Async::Ready(res)) => { - let mut res = res.map(move |b| HttpBody::Http1 { - body: Some(b), - upgrade: upgrade.take(), - }); - if *is_http_connect { - res.extensions_mut().insert(HttpConnect); - } - Ok(Async::Ready(res)) - }, - Ok(Async::NotReady) => Ok(Async::NotReady), - Err(e) => { + let poll = future.poll() + .map_err(|e| { debug!("http/1 client error: {}", e); - Err(h2::Reason::INTERNAL_ERROR.into()) - } + Error::from(e) + }); + let mut res = try_ready!(poll) + .map(move |b| HttpBody::Http1 { + body: Some(b), + upgrade: upgrade.take(), + }); + if *is_http_connect { + res.extensions_mut().insert(HttpConnect); } + Ok(Async::Ready(res)) }, ClientServiceFuture::Http2(f) => { let res = try_ready!(f.poll()); @@ -277,3 +292,43 @@ impl Future for ClientServiceFuture { } } +impl From for Error { + fn from(e: tower_h2::client::Error) -> Self { + Error::Http2(e) + } +} + +impl From for Error { + fn from(e: hyper::Error) -> Self { + Error::Http1(e) + } +} + +impl fmt::Display for Error { + fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result { + match self { + Error::Http1(ref e) => fmt::Display::fmt(e, f), + Error::Http2(ref e) => fmt::Display::fmt(e, f), + } + } +} + +impl std::error::Error for Error { + fn cause(&self) -> Option<&std::error::Error> { + match self { + Error::Http1(e) => e.cause(), + Error::Http2(e) => e.cause(), + } + } +} + +impl Error { + pub fn reason(&self) -> Option { + match self { + // TODO: it would be good to provide better error + // details in metrics for HTTP/1... + Error::Http1(_) => Some(h2::Reason::INTERNAL_ERROR), + Error::Http2(e) => e.reason(), + } + } +} diff --git a/src/transparency/glue.rs b/src/transparency/glue.rs index 347bffaf6..e98bbd468 100644 --- a/src/transparency/glue.rs +++ b/src/transparency/glue.rs @@ -1,6 +1,8 @@ -use std::fmt; -use std::io; -use std::sync::Arc; +use std::{ + error::Error, + fmt, + sync::Arc, +}; use bytes::{Bytes, IntoBuf}; use futures::{future, Async, Future, Poll}; @@ -241,14 +243,14 @@ where Request=http::Request, Response=http::Response, >, - S::Error: fmt::Debug, + S::Error: Error + Send + Sync + 'static, B: tower_h2::Body + Default + Send + 'static, ::Buf: Send, E: Executor + Clone + Send + Sync + 'static, { type ReqBody = hyper::Body; type ResBody = BodyPayload; - type Error = h2::Error; + type Error = S::Error; type Future = Either< HyperServerSvcFuture, future::FutureResult, Self::Error>, @@ -303,15 +305,15 @@ where impl Future for HyperServerSvcFuture where F: Future>, - F::Error: fmt::Debug, + F::Error: Error + fmt::Debug + Send + Sync + 'static, { type Item = http::Response>; - type Error = h2::Error; + type Error = F::Error; fn poll(&mut self) -> Poll { let mut res = try_ready!(self.inner.poll().map_err(|e| { - debug!("h2 error: {:?}", e); - h2::Error::from(io::Error::from(io::ErrorKind::Other)) + debug!("HTTP/1 error: {}", e); + e })); if h1::is_upgrade(&res) { @@ -409,10 +411,11 @@ impl hyper_connect::Connect for HyperConnect where C: Connect + Send + Sync, C::Future: Send + 'static, + ::Error: Error + Send + Sync + 'static, C::Connected: Send + 'static, { type Transport = C::Connected; - type Error = io::Error; + type Error = ::Error; type Future = HyperConnectFuture; fn connect(&self, _dst: hyper_connect::Destination) -> Self::Future { @@ -425,16 +428,14 @@ where impl Future for HyperConnectFuture where - F: Future, + F: Future + 'static, + F::Error: Error + Send + Sync, { type Item = (F::Item, hyper_connect::Connected); - type Error = io::Error; + type Error = F::Error; fn poll(&mut self) -> Poll { - let transport = try_ready!( - self.inner.poll() - .map_err(|_| io::Error::from(io::ErrorKind::Other)) - ); + let transport = try_ready!(self.inner.poll()); let connected = hyper_connect::Connected::new() .proxy(self.absolute_form); Ok(Async::Ready((transport, connected))) diff --git a/src/transparency/mod.rs b/src/transparency/mod.rs index 942cd9d6f..77aa505a9 100644 --- a/src/transparency/mod.rs +++ b/src/transparency/mod.rs @@ -6,6 +6,6 @@ mod protocol; mod server; mod tcp; -pub use self::client::Client; +pub use self::client::{Client, Error as ClientError}; pub use self::glue::HttpBody; pub use self::server::Server; diff --git a/src/transparency/server.rs b/src/transparency/server.rs index 72d710fb3..d714a412c 100644 --- a/src/transparency/server.rs +++ b/src/transparency/server.rs @@ -1,7 +1,10 @@ -use std::fmt; -use std::net::SocketAddr; -use std::sync::Arc; -use std::time::{Duration, Instant}; +use std::{ + error::Error, + fmt, + net::SocketAddr, + sync::Arc, + time::{Duration, Instant}, +}; use futures::{future::Either, Future}; use http; @@ -57,12 +60,11 @@ where > + Clone + Send + 'static, S::Future: 'static, ::Service: Send, - S::Error: fmt::Debug, <::Service as ::tower_service::Service>::Future: Send, S::InitError: fmt::Debug, S::Future: Send + 'static, B: tower_h2::Body + 'static, - S::Error: Send + fmt::Debug, + S::Error: Error + Send + Sync + 'static, S::InitError: Send + fmt::Debug, B: tower_h2::Body + Send + Default + 'static, B::Data: Send,