Add error message to HTTP2_SESSION_RECV_INVALID_HEADER.

Now with unittests!

Also do not try to put non-UTF8 strings into NetLog,
because a DCHECK files as soon as a TestBoundNetLog is used.

Also remove a solitary DVLOG() statement,
since other failure modes do not have one.

Change-Id: I67e82c09a4e73a8561973c3db432e4364d05ad55
Reviewed-on: https://chromium-review.googlesource.com/570627
Commit-Queue: Bence Béky <bnc@chromium.org>
Reviewed-by: Ryan Hamilton <rch@chromium.org>
Cr-Commit-Position: refs/heads/master@{#487608}

net/log/net_log_event_type_list.h

@@ -1470,6 +1470,7 @@ EVENT_TYPE(HTTP2_SESSION_UPDATE_RECV_WINDOW)
 //   {
 //     "header_name": <The header name>,
 //     "header_value": <The header value>,
+//     "error": <Error message>,
 //   }
 EVENT_TYPE(HTTP2_SESSION_RECV_INVALID_HEADER)
 

net/spdy/chromium/header_coalescer.cc

@@ -8,8 +8,8 @@
 
 #include "base/bind.h"
 #include "base/memory/ptr_util.h"
-#include "base/strings/string_util.h"
 #include "base/values.h"
+#include "net/base/escape.h"
 #include "net/http/http_log_util.h"
 #include "net/http/http_util.h"
 #include "net/spdy/platform/api/spdy_estimate_memory_usage.h"
@@ -20,12 +20,15 @@ namespace {
 std::unique_ptr<base::Value> ElideNetLogHeaderCallback(
     SpdyStringPiece header_name,
     SpdyStringPiece header_value,
+    SpdyStringPiece error_message,
     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()));
+  dict->SetString("header_name", EscapeExternalHandlerValue(header_name));
+  dict->SetString(
+      "header_value",
+      EscapeExternalHandlerValue(ElideHeaderValueForNetLog(
+          capture_mode, header_name.as_string(), header_value.as_string())));
+  dict->SetString("error", error_message);
   return std::move(dict);
 }
 
@@ -37,13 +40,8 @@ HeaderCoalescer::HeaderCoalescer(const NetLogWithSource& net_log)
 void HeaderCoalescer::OnHeader(SpdyStringPiece key, SpdyStringPiece value) {
   if (error_seen_)
     return;
-  if (!AddHeader(key, 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() {
@@ -58,13 +56,19 @@ size_t HeaderCoalescer::EstimateMemoryUsage() const {
 
 bool HeaderCoalescer::AddHeader(SpdyStringPiece key, SpdyStringPiece value) {
   if (key.empty()) {
-    DVLOG(1) << "Header name must not be empty.";
+    net_log_.AddEvent(NetLogEventType::HTTP2_SESSION_RECV_INVALID_HEADER,
+                      base::Bind(&ElideNetLogHeaderCallback, key, value,
+                                 "Header name must not be empty."));
     return false;
   }
 
   SpdyStringPiece key_name = key;
   if (key[0] == ':') {
     if (regular_header_seen_) {
+      net_log_.AddEvent(
+          NetLogEventType::HTTP2_SESSION_RECV_INVALID_HEADER,
+          base::Bind(&ElideNetLogHeaderCallback, key, value,
+                     "Pseudo header must not follow regular headers."));
       return false;
     }
     key_name.remove_prefix(1);
@@ -73,18 +77,29 @@ bool HeaderCoalescer::AddHeader(SpdyStringPiece key, SpdyStringPiece value) {
   }
 
   if (!HttpUtil::IsValidHeaderName(key_name)) {
+    net_log_.AddEvent(NetLogEventType::HTTP2_SESSION_RECV_INVALID_HEADER,
+                      base::Bind(&ElideNetLogHeaderCallback, key, value,
+                                 "Invalid character in header name."));
     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)
+  if (header_list_size_ > kMaxHeaderListSize) {
+    net_log_.AddEvent(NetLogEventType::HTTP2_SESSION_RECV_INVALID_HEADER,
+                      base::Bind(&ElideNetLogHeaderCallback, key, value,
+                                 "Header list too large."));
     return false;
+  }
 
   // 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)
+  if (value.find("\r\n") != SpdyStringPiece::npos) {
+    net_log_.AddEvent(NetLogEventType::HTTP2_SESSION_RECV_INVALID_HEADER,
+                      base::Bind(&ElideNetLogHeaderCallback, key, value,
+                                 "Header value must not contain CR+LF."));
     return false;
+  }
 
   auto iter = headers_.find(key);
   if (iter == headers_.end()) {

net/spdy/chromium/header_coalescer_test.cc

@@ -6,7 +6,7 @@
 
 #include <vector>
 
-#include "net/log/net_log_with_source.h"
+#include "net/log/test_net_log.h"
 #include "net/spdy/platform/api/spdy_string.h"
 #include "net/spdy/platform/api/spdy_string_utils.h"
 #include "testing/gmock/include/gmock/gmock.h"
@@ -20,9 +20,28 @@ namespace test {
 
 class HeaderCoalescerTest : public ::testing::Test {
  public:
-  HeaderCoalescerTest() : header_coalescer_(NetLogWithSource()) {}
+  HeaderCoalescerTest() : header_coalescer_(net_log_.bound()) {}
+
+  void ExpectEntry(SpdyStringPiece expected_header_name,
+                   SpdyStringPiece expected_header_value,
+                   SpdyStringPiece expected_error_message) {
+    TestNetLogEntry::List entry_list;
+    net_log_.GetEntries(&entry_list);
+    ASSERT_EQ(1u, entry_list.size());
+    EXPECT_EQ(entry_list[0].type,
+              NetLogEventType::HTTP2_SESSION_RECV_INVALID_HEADER);
+    EXPECT_EQ(entry_list[0].source.id, net_log_.bound().source().id);
+    std::string value;
+    EXPECT_TRUE(entry_list[0].GetStringValue("header_name", &value));
+    EXPECT_EQ(expected_header_name, value);
+    EXPECT_TRUE(entry_list[0].GetStringValue("header_value", &value));
+    EXPECT_EQ(expected_header_value, value);
+    EXPECT_TRUE(entry_list[0].GetStringValue("error", &value));
+    EXPECT_EQ(expected_error_message, value);
+  }
 
  protected:
+  BoundTestNetLog net_log_;
   HeaderCoalescer header_coalescer_;
 };
 
@@ -37,9 +56,9 @@ TEST_F(HeaderCoalescerTest, CorrectHeaders) {
 }
 
 TEST_F(HeaderCoalescerTest, EmptyHeaderKey) {
-  EXPECT_FALSE(header_coalescer_.error_seen());
   header_coalescer_.OnHeader("", "foo");
   EXPECT_TRUE(header_coalescer_.error_seen());
+  ExpectEntry("", "foo", "Header name must not be empty.");
 }
 
 TEST_F(HeaderCoalescerTest, HeaderBlockTooLarge) {
@@ -49,9 +68,11 @@ TEST_F(HeaderCoalescerTest, HeaderBlockTooLarge) {
   header_coalescer_.OnHeader("foo", data);
   EXPECT_FALSE(header_coalescer_.error_seen());
 
-  // Another 3 + 3 + 32 bytes: too large.
-  header_coalescer_.OnHeader("bar", "baz");
+  // Another 3 + 4 + 32 bytes: too large.
+  SpdyStringPiece header_value("\x1\x7F\x80\xFF");
+  header_coalescer_.OnHeader("bar", header_value);
   EXPECT_TRUE(header_coalescer_.error_seen());
+  ExpectEntry("bar", "%01%7F%80%FF", "Header list too large.");
 }
 
 TEST_F(HeaderCoalescerTest, PseudoHeadersMustNotFollowRegularHeaders) {
@@ -59,6 +80,7 @@ TEST_F(HeaderCoalescerTest, PseudoHeadersMustNotFollowRegularHeaders) {
   EXPECT_FALSE(header_coalescer_.error_seen());
   header_coalescer_.OnHeader(":baz", "qux");
   EXPECT_TRUE(header_coalescer_.error_seen());
+  ExpectEntry(":baz", "qux", "Pseudo header must not follow regular headers.");
 }
 
 TEST_F(HeaderCoalescerTest, Append) {
@@ -75,15 +97,16 @@ TEST_F(HeaderCoalescerTest, Append) {
 }
 
 TEST_F(HeaderCoalescerTest, CRLFInHeaderValue) {
-  EXPECT_FALSE(header_coalescer_.error_seen());
   header_coalescer_.OnHeader("foo", "bar\r\nbaz");
   EXPECT_TRUE(header_coalescer_.error_seen());
+  ExpectEntry("foo", "bar%0D%0Abaz", "Header value must not contain CR+LF.");
 }
 
 TEST_F(HeaderCoalescerTest, HeaderNameNotValid) {
-  SpdyStringPiece header_name("\x01\x7F\x80\xff");
+  SpdyStringPiece header_name("\x1\x7F\x80\xFF");
   header_coalescer_.OnHeader(header_name, "foo");
   EXPECT_TRUE(header_coalescer_.error_seen());
+  ExpectEntry("%01%7F%80%FF", "foo", "Invalid character in header name.");
 }
 
 // RFC 7230 Section 3.2. Valid header name is defined as: