Add NetLog event for invalid Http/2 response header

net/spdy/chromium/header_coalescer.cc

 // Copyright (c) 2016 The Chromium Authors. All rights reserved.
 // Use of this source code is governed by a BSD-style license that can be
 // found in the LICENSE file.
 
 #include "net/spdy/chromium/header_coalescer.h"
 
 #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_) {
     regular_header_seen_ = true;
   }
 
   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()) {
     headers_[key] = value;
   } else {
     // This header had multiple values, so it must be reconstructed.
     SpdyStringPiece v = iter->second;
     SpdyString s(v.data(), v.length());
     if (key == "cookie") {
       // Obeys section 8.1.2.5 in RFC 7540 for cookie reconstruction.
       s.append("; ");
     } else {
       SpdyStringPiece("\0", 1).AppendToString(&s);
     }
     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