refactor(lib): improve some trace logs for upgrades

src/proto/h1/conn.rs

@@ -298,6 +298,7 @@ where I: AsyncRead + AsyncWrite,
                 Ok(Async::NotReady)
             },
             Err(e) => {
+                trace!("try_io_read; error = {}", e);
                 self.state.close();
                 Err(e)
             }
@@ -346,7 +347,7 @@ where I: AsyncRead + AsyncWrite,
     }
 
     fn try_keep_alive(&mut self) {
-        self.state.try_keep_alive();
+        self.state.try_keep_alive::<T>();
         self.maybe_notify();
     }
 
@@ -556,7 +557,7 @@ where I: AsyncRead + AsyncWrite,
     pub fn flush(&mut self) -> Poll<(), io::Error> {
         try_ready!(self.io.flush());
         self.try_keep_alive();
-        trace!("flushed {:?}", self.state);
+        trace!("flushed({}): {:?}", T::LOG, self.state);
         Ok(Async::Ready(()))
     }
 
@@ -599,6 +600,7 @@ where I: AsyncRead + AsyncWrite,
     }
 
     pub(super) fn on_upgrade(&mut self) -> ::upgrade::OnUpgrade {
+        trace!("{}: prepare possible HTTP upgrade", T::LOG);
         self.state.prepare_upgrade()
     }
 
@@ -754,12 +756,13 @@ impl State {
         }
     }
 
-    fn try_keep_alive(&mut self) {
+    fn try_keep_alive<T: Http1Transaction>(&mut self) {
         match (&self.reading, &self.writing) {
             (&Reading::KeepAlive, &Writing::KeepAlive) => {
                 if let KA::Busy = self.keep_alive.status() {
                     self.idle();
                 } else {
+                    trace!("try_keep_alive({}): could keep-alive, but status = {:?}", T::LOG, self.keep_alive);
                     self.close();
                 }
             },
@@ -816,7 +819,6 @@ impl State {
     }
 
     fn prepare_upgrade(&mut self) -> ::upgrade::OnUpgrade {
-        trace!("prepare possible HTTP upgrade");
         debug_assert!(self.upgrade.is_none());
         let (tx, rx) = ::upgrade::pending();
         self.upgrade = Some(tx);

src/proto/h1/mod.rs

@@ -25,6 +25,7 @@ pub(crate) type ClientTransaction = role::Client;
 pub(crate) trait Http1Transaction {
     type Incoming;
     type Outgoing: Default;
+    const LOG: &'static str;
     fn parse(bytes: &mut BytesMut, ctx: ParseContext) -> ParseResult<Self::Incoming>;
     fn encode(enc: Encode<Self::Outgoing>, dst: &mut Vec<u8>) -> ::Result<Encoder>;
 

src/proto/h1/role.rs

@@ -23,6 +23,7 @@ pub(crate) enum Server {}
 impl Http1Transaction for Server {
     type Incoming = RequestLine;
     type Outgoing = StatusCode;
+    const LOG: &'static str = "{role=server}";
 
     fn parse(buf: &mut BytesMut, ctx: ParseContext) -> ParseResult<RequestLine> {
         if buf.len() == 0 {
@@ -190,7 +191,12 @@ impl Http1Transaction for Server {
     }
 
     fn encode(mut msg: Encode<Self::Outgoing>, dst: &mut Vec<u8>) -> ::Result<Encoder> {
-        trace!("Server::encode body={:?}, method={:?}", msg.body, msg.req_method);
+        trace!(
+            "Server::encode status={:?}, body={:?}, req_method={:?}",
+            msg.head.subject,
+            msg.body,
+            msg.req_method
+        );
         debug_assert!(!msg.title_case_headers, "no server config for title case headers");
 
         // hyper currently doesn't support returning 1xx status codes as a Response
@@ -440,7 +446,11 @@ impl Http1Transaction for Server {
         }
 
         if !Server::can_have_body(msg.req_method, msg.head.subject) {
-            trace!("body not allowed for {:?} {:?}", msg.req_method, msg.head.subject);
+            trace!(
+                "server body forced to 0; method={:?}, status={:?}",
+                msg.req_method,
+                msg.head.subject
+            );
             encoder = Encoder::length(0);
         }
 
@@ -517,6 +527,7 @@ impl Server {
 impl Http1Transaction for Client {
     type Incoming = StatusCode;
     type Outgoing = RequestLine;
+    const LOG: &'static str = "{role=client}";
 
     fn parse(buf: &mut BytesMut, ctx: ParseContext) -> ParseResult<StatusCode> {
         // Loop to skip information status code headers (100 Continue, etc).
@@ -580,7 +591,7 @@ impl Http1Transaction for Client {
     }
 
     fn encode(msg: Encode<Self::Outgoing>, dst: &mut Vec<u8>) -> ::Result<Encoder> {
-        trace!("Client::encode body={:?}, method={:?}", msg.body, msg.req_method);
+        trace!("Client::encode method={:?}, body={:?}", msg.head.subject.0, msg.body);
 
         *msg.req_method = Some(msg.head.subject.0.clone());
 

src/upgrade.rs

@@ -228,12 +228,14 @@ impl fmt::Debug for OnUpgrade {
 
 impl Pending {
     pub(crate) fn fulfill(self, upgraded: Upgraded) {
+        trace!("pending upgrade fulfill");
         let _ = self.tx.send(Ok(upgraded));
     }
 
     /// Don't fulfill the pending Upgrade, but instead signal that
     /// upgrades are handled manually.
     pub(crate) fn manual(self) {
+        trace!("pending upgrade handled manually");
         let _ = self.tx.send(Err(::Error::new_user_manual_upgrade()));
     }
 }