Add NetLog event for invalid Http/2 response header

net/spdy/chromium/header_coalescer.cc

Index: net/spdy/chromium/header_coalescer.cc
diff --git a/net/spdy/chromium/header_coalescer.cc b/net/spdy/chromium/header_coalescer.cc
index f5693d68452d7e5271b927e7e63f3dcc09393c95..744ed9e5a9b681205178c8535031d8752859b395 100644
--- a/net/spdy/chromium/header_coalescer.cc
+++ b/net/spdy/chromium/header_coalescer.cc
@@ -6,31 +6,70 @@
 
 #include <utility>
 
+#include "base/bind.h"
+#include "base/memory/ptr_util.h"
 #include "base/strings/string_util.h"
+#include "base/values.h"
+#include "net/http/http_log_util.h"
 #include "net/http/http_util.h"
 #include "net/spdy/platform/api/spdy_estimate_memory_usage.h"
 #include "net/spdy/platform/api/spdy_string.h"
 
 namespace net {
+namespace {
+std::unique_ptr<base::Value> ElideNetLogHeaderCallback(
+    SpdyStringPiece header_name,
+    SpdyStringPiece header_value,
+    NetLogCaptureMode capture_mode) {
+  auto dict = base::MakeUnique<base::DictionaryValue>();
+  dict->SetString("header_name", header_name);
+  dict->SetString("header_value", ElideHeaderValueForNetLog(
+                                      capture_mode, header_name.as_string(),
+                                      header_value.as_string()));
+  return std::move(dict);
+}
+
+}  // namespace
 
 const size_t kMaxHeaderListSize = 256 * 1024;
 
+HeaderCoalescer::HeaderCoalescer(const NetLogWithSource& net_log)
+    : net_log_(net_log) {}
+
 void HeaderCoalescer::OnHeader(SpdyStringPiece key, SpdyStringPiece value) {
+  if (!AddHeader(key, value)) {
+    error_seen_ = true;
+    if (net_log_.IsCapturing()) {
+      net_log_.AddEvent(NetLogEventType::HTTP2_SESSION_RECV_INVALID_HEADER,
+                        base::Bind(&ElideNetLogHeaderCallback, key, value));
+    }
+  }
+}
+
+SpdyHeaderBlock HeaderCoalescer::release_headers() {
+  DCHECK(headers_valid_);
+  headers_valid_ = false;
+  return std::move(headers_);
+}
+
+size_t HeaderCoalescer::EstimateMemoryUsage() const {
+  return SpdyEstimateMemoryUsage(headers_);
+}
+
+bool HeaderCoalescer::AddHeader(SpdyStringPiece key, SpdyStringPiece value) {

[Bence, 2017/04/28 18:08:35]

Maybe define an enum: kOk, kEmptyName, kPseudoHeaderAfterRegularHeader,
kInvalidHeaderName, kHeaderListTooLarge, kEolInHeaderValue.  Maybe return this
enum from AddHeader(), and log this (along with the header name and value which
triggered the error) if != OK.

(Note that preferred enum member name style changed two weeks ago.)

[xunjieli, 2017/05/10 01:13:48]

That's a bit more code that I am comfortable with for this problem. My guess is
that we won't frequently deal with kPseudoHeaderAfterRegularHeader case. The
other invalid cases should be obvious if we just log the invalid header.

[Bence, 2017/05/10 12:43:29]

Okay, I understand.

   if (error_seen_) {
-    return;
+    return false;

[Bence, 2017/04/28 18:08:35]

This will cause every header to be logged after a single invalid header.  Do you
not want to return true here instead?  Better yet, move this early return much
later, just above actually inserving the header, so that every single invalid
header can be logged.

[xunjieli, 2017/05/10 01:13:48]

I have moved this conditional out of this method. Changing this to return true
is a bit counter-intuitive because AddHeader() should only return true if the
header is successfully added.

   }
 
   if (key.empty()) {
     DVLOG(1) << "Header name must not be empty.";
-    error_seen_ = true;
-    return;
+    return false;
   }
 
   SpdyStringPiece key_name = key;
   if (key[0] == ':') {
     if (regular_header_seen_) {
-      error_seen_ = true;
-      return;
+      return false;

[Bence, 2017/04/28 18:08:35]

Is there a better mechanism to log that pseudo/regular header order rule is
violated?  Just logging the header key+value in this case is not informative
enough.

[xunjieli, 2017/05/10 01:13:47]

I am not sure. We can also log every header value pair, but that seems to be an
overkill. My guess is that this is infrequent enough that we do not need to
worry about it.

[Bence, 2017/05/10 12:43:29]

Sounds good.

     }
     key_name.remove_prefix(1);
   } else if (!regular_header_seen_) {
@@ -38,23 +77,18 @@ void HeaderCoalescer::OnHeader(SpdyStringPiece key, SpdyStringPiece value) {
   }
 
   if (!HttpUtil::IsValidHeaderName(key_name)) {
-    error_seen_ = true;
-    return;
+    return false;
   }
 
   // 32 byte overhead according to RFC 7540 Section 6.5.2.
   header_list_size_ += key.size() + value.size() + 32;
-  if (header_list_size_ > kMaxHeaderListSize) {
-    error_seen_ = true;
-    return;
-  }
+  if (header_list_size_ > kMaxHeaderListSize)
+    return false;

[Bence, 2017/04/28 18:08:35]

Is there a better mechanism to log that pseudo/regular header order rule is
violated?  Just logging the header key+value in this case is not informative
enough.

 
   // End of line delimiter is forbidden according to RFC 7230 Section 3.2.
   // Line folding, RFC 7230 Section 3.2.4., is a special case of this.
-  if (value.find("\r\n") != SpdyStringPiece::npos) {
-    error_seen_ = true;
-    return;
-  }
+  if (value.find("\r\n") != SpdyStringPiece::npos)
+    return false;

[Bence, 2017/04/28 18:08:35]

I'm not sure NetLog correctly displays string values with such delimiters, but I
don't think it's worth worrying about.

[xunjieli, 2017/05/10 01:13:48]

Acknowledged.

 
   auto iter = headers_.find(key);
   if (iter == headers_.end()) {
@@ -72,16 +106,8 @@ void HeaderCoalescer::OnHeader(SpdyStringPiece key, SpdyStringPiece value) {
     value.AppendToString(&s);
     headers_[key] = s;
   }
+  return true;
 }
 
-SpdyHeaderBlock HeaderCoalescer::release_headers() {
-  DCHECK(headers_valid_);
-  headers_valid_ = false;
-  return std::move(headers_);
-}
-
-size_t HeaderCoalescer::EstimateMemoryUsage() const {
-  return SpdyEstimateMemoryUsage(headers_);
-}
 
 }  // namespace net