From 4b81e528d584d12d39d7618d147d32b7f60eb767 Mon Sep 17 00:00:00 2001
From: Eliza Weisman <eliza@buoyant.io>
Date: Wed, 23 Jan 2019 11:44:32 -0800
Subject: [PATCH] Log more information when rejecting malformed pseudo-headers
 (#342)

Currently, when a `h2` server receives a HEADERS frame with malformed
pseudo-headers, it logs which pseudo-heade was malformed at the debug
level before sending a reset. This behaviour is correct. However, it can
be difficult to debug misbehaving clients, as the server's log message
doesn't include the *value* of the invalid pseudo-header, or indicate
*why* it was incorrect.

This branch changes the log message to include both the value of the
malformed header and the error that caused it to be rejected.

For example, here is the output from the test
`server::recv_invalid_authority`, before and after making this change.

Before:
```
...
DEBUG 2019-01-23T19:16:28Z: h2::server: malformed headers: malformed authority
...
```

After:
```
...
DEBUG 2019-01-23T19:15:37Z: h2::server: malformed headers: malformed authority ("not:a/good authority"): invalid uri character
...
```

Note that it was necessary to clone the value of each pseudo-header
before passing it to the `uri::{Scheme, Authority, Path}::from_shared`
constructors, so that the value could be logged if those functions
return errors. However, since the pseudo-headers are internally
represented using `Bytes`, this should just increase the reference count
rather than copy the string, so I thought this was acceptable.

If even a ref-count bump has an undesirable performance overhead, we
could consider using
```rust
if log_enabled!(Level::Debug) {
    // ...
}
```
to only clone if the message will be logged, but this makes the code
somewhat significantly more complicated. Therefore, I decided to punt on
that unless requested by a reviewer.

See also linkerd/linkerd2#2133

Signed-off-by: Eliza Weisman <eliza@buoyant.io>
---
 src/server.rs | 18 ++++++++++++------
 1 file changed, 12 insertions(+), 6 deletions(-)

diff --git a/src/server.rs b/src/server.rs
index 15558ea..6072db5 100644
--- a/src/server.rs
+++ b/src/server.rs
@@ -1226,15 +1226,19 @@ impl proto::Peer for Peer {
         let mut parts = uri::Parts::default();
 
         if let Some(scheme) = pseudo.scheme {
-            parts.scheme = Some(uri::Scheme::from_shared(scheme.into_inner())
-                .or_else(|_| malformed!("malformed headers: malformed scheme"))?);
+            let maybe_scheme = uri::Scheme::from_shared(scheme.clone().into_inner());
+            parts.scheme = Some(maybe_scheme.or_else(|why| malformed!(
+                "malformed headers: malformed scheme ({:?}): {}", scheme, why,
+            ))?);
         } else {
             malformed!("malformed headers: missing scheme");
         }
 
         if let Some(authority) = pseudo.authority {
-            parts.authority = Some(uri::Authority::from_shared(authority.into_inner())
-                .or_else(|_| malformed!("malformed headers: malformed authority"))?);
+            let maybe_authority = uri::Authority::from_shared(authority.clone().into_inner());
+            parts.authority = Some(maybe_authority.or_else(|why| malformed!(
+                "malformed headers: malformed authority ({:?}): {}", authority, why,
+            ))?);
         }
 
         if let Some(path) = pseudo.path {
@@ -1243,8 +1247,10 @@ impl proto::Peer for Peer {
                 malformed!("malformed headers: missing path");
             }
 
-            parts.path_and_query = Some(uri::PathAndQuery::from_shared(path.into_inner())
-                .or_else(|_| malformed!("malformed headers: malformed path"))?);
+            let maybe_path = uri::PathAndQuery::from_shared(path.clone().into_inner());
+            parts.path_and_query = Some(maybe_path.or_else(|why| malformed!(
+                "malformed headers: malformed path ({:?}): {}", path, why,
+            ))?);
         }
 
         b.uri(parts);