Additional debug/trace logging (#180)

src/proto/streams/recv.rs

@@ -354,6 +354,7 @@ impl Recv {
         let sz = sz as WindowSize;
 
         if !stream.state.is_recv_streaming() {
+            trace!("stream is not in receiving state; state={:?}", stream.state);
             // Receiving a DATA frame when not expecting one is a protocol
             // error.
             return Err(RecvError::Connection(Reason::PROTOCOL_ERROR));
@@ -383,6 +384,7 @@ impl Recv {
         self.in_flight_data += sz;
 
         if stream.dec_content_length(frame.payload().len()).is_err() {
+            trace!("content-length overflow");
             return Err(RecvError::Stream {
                 id: stream.id,
                 reason: Reason::PROTOCOL_ERROR,
@@ -391,6 +393,7 @@ impl Recv {
 
         if frame.is_end_stream() {
             if stream.ensure_content_length_zero().is_err() {
+                trace!("content-length underflow");
                 return Err(RecvError::Stream {
                     id: stream.id,
                     reason: Reason::PROTOCOL_ERROR,
@@ -398,6 +401,7 @@ impl Recv {
             }
 
             if stream.state.recv_close().is_err() {
+                trace!("failed to transition to closed state");
                 return Err(RecvError::Connection(Reason::PROTOCOL_ERROR));
             }
         }
@@ -467,6 +471,7 @@ impl Recv {
     pub fn ensure_not_idle(&self, id: StreamId) -> Result<(), Reason> {
         if let Ok(next) = self.next_stream_id {
             if id >= next {
+                trace!("stream ID implicitly closed");
                 return Err(Reason::PROTOCOL_ERROR);
             }
         }

src/server.rs

@@ -427,12 +427,13 @@ impl proto::Peer for Peer {
         let (pseudo, fields) = headers.into_parts();
 
         macro_rules! malformed {
-            () => {
+            ($($arg:tt)*) => {{
+                debug!($($arg)*);
                 return Err(RecvError::Stream {
                     id: stream_id,
                     reason: Reason::PROTOCOL_ERROR,
                 });
-            }
+            }}
         };
 
         b.version(Version::HTTP_2);
@@ -440,7 +441,7 @@ impl proto::Peer for Peer {
         if let Some(method) = pseudo.method {
             b.method(method);
         } else {
-            malformed!();
+            malformed!("malformed headers: missing method");
         }
 
         // Specifying :status for a request is a protocol error
@@ -453,24 +454,24 @@ impl proto::Peer for Peer {
 
         if let Some(scheme) = pseudo.scheme {
             parts.scheme = Some(uri::Scheme::from_shared(scheme.into_inner())
-                .or_else(|_| malformed!())?);
+                .or_else(|_| malformed!("malformed headers: malformed scheme"))?);
         } else {
-            malformed!();
+            malformed!("malformed headers: missing scheme");
         }
 
         if let Some(authority) = pseudo.authority {
             parts.authority = Some(uri::Authority::from_shared(authority.into_inner())
-                .or_else(|_| malformed!())?);
+                .or_else(|_| malformed!("malformed headers: malformed authority"))?);
         }
 
         if let Some(path) = pseudo.path {
             // This cannot be empty
             if path.is_empty() {
-                malformed!();
+                malformed!("malformed headers: missing path");
             }
 
             parts.path_and_query = Some(uri::PathAndQuery::from_shared(path.into_inner())
-                .or_else(|_| malformed!())?);
+                .or_else(|_| malformed!("malformed headers: malformed path"))?);
         }
 
         b.uri(parts);