net: Add more net-internals logging to the HTTP cache.

This adds three new event types: the original request headers when they are
interesting for the cache, and two uncommon conditions that cause the state
machine to restart part of the request.

BUG=none
TEST=net_unittests

Review URL: https://codereview.chromium.org/830683002

Cr-Commit-Position: refs/heads/master@{#309862}

4 files changed, 117 insertions, 5 deletions

diff --git a/chrome/browser/resources/net_internals/log_view_painter.js b/chrome/browser/resources/net_internals/log_view_painter.js
index 7565cd1..05d85eb 100644
--- a/chrome/browser/resources/net_internals/log_view_painter.js
+++ b/chrome/browser/resources/net_internals/log_view_painter.js
@@ -273,6 +273,7 @@ function getParamaterWriterForEventType(eventType) {
   switch (eventType) {
     case EventType.HTTP_TRANSACTION_SEND_REQUEST_HEADERS:
     case EventType.HTTP_TRANSACTION_SEND_TUNNEL_HEADERS:
+    case EventType.TYPE_HTTP_CACHE_CALLER_REQUEST_HEADERS:
       return writeParamsForRequestHeaders;
 
     case EventType.PROXY_CONFIG_CHANGED:
diff --git a/net/base/net_log_event_type_list.h b/net/base/net_log_event_type_list.h
index c110a3d..21de471 100644
--- a/net/base/net_log_event_type_list.h
+++ b/net/base/net_log_event_type_list.h
@@ -847,6 +847,20 @@ EVENT_TYPE(HTTP_CACHE_WRITE_INFO)
 EVENT_TYPE(HTTP_CACHE_READ_DATA)
 EVENT_TYPE(HTTP_CACHE_WRITE_DATA)
 
+// The request headers received by the HTTP cache.
+// The following parameters are attached:
+//   {
+//     "line": <empty>,
+//     "headers": <The list of header:value pairs>,
+//   }
+EVENT_TYPE(HTTP_CACHE_CALLER_REQUEST_HEADERS)
+
+// Signal a significant change on the flow of the satate machine: start again
+// from scratch or create a new network request for byte-range operations.
+// There are no parameters.
+EVENT_TYPE(HTTP_CACHE_RESTART_PARTIAL_REQUEST)
+EVENT_TYPE(HTTP_CACHE_RE_SEND_PARTIAL_REQUEST)
+
 // Identifies the NetLog::Source() for the asynchronous HttpCache::Transaction
 // that will revalidate this entry.
 // The event parameters are:
diff --git a/net/http/http_cache_transaction.cc b/net/http/http_cache_transaction.cc
index 61d992f..1f2d9ff 100644
--- a/net/http/http_cache_transaction.cc
+++ b/net/http/http_cache_transaction.cc
@@ -1219,6 +1219,7 @@ int HttpCache::Transaction::DoSuccessfulSendRequest() {
     // If we have an authentication response, we are exposed to weird things
     // hapenning if the user cancels the authentication before we receive
     // the new response.
+    net_log_.AddEvent(NetLog::TYPE_HTTP_CACHE_RE_SEND_PARTIAL_REQUEST);
     UpdateTransactionPattern(PATTERN_NOT_COVERED);
     response_ = HttpResponseInfo();
     ResetNetworkTransaction();
@@ -2211,6 +2212,7 @@ void HttpCache::Transaction::SetRequest(const BoundNetLog& net_log,
 
   bool range_found = false;
   bool external_validation_error = false;
+  bool special_headers = false;
 
   if (request_->extra_headers.HasHeader(HttpRequestHeaders::kRange))
     range_found = true;
@@ -2218,6 +2220,7 @@ void HttpCache::Transaction::SetRequest(const BoundNetLog& net_log,
   for (size_t i = 0; i < arraysize(kSpecialHeaders); ++i) {
     if (HeaderMatches(request_->extra_headers, kSpecialHeaders[i].search)) {
       effective_load_flags_ |= kSpecialHeaders[i].load_flag;
+      special_headers = true;
       break;
     }
   }
@@ -2238,6 +2241,15 @@ void HttpCache::Transaction::SetRequest(const BoundNetLog& net_log,
     }
   }
 
+  if (range_found || special_headers || external_validation_.initialized) {
+    // Log the headers before request_ is modified.
+    std::string empty;
+    net_log_.AddEvent(
+        NetLog::TYPE_HTTP_CACHE_CALLER_REQUEST_HEADERS,
+        base::Bind(&HttpRequestHeaders::NetLogCallback,
+                   base::Unretained(&request_->extra_headers), &empty));
+  }
+
   // We don't support ranges and validation headers.
   if (range_found && external_validation_.initialized) {
     LOG(WARNING) << "Byte ranges AND validation headers found.";
@@ -3009,6 +3021,7 @@ int HttpCache::Transaction::DoPartialCacheReadCompleted(int result) {
 int HttpCache::Transaction::DoRestartPartialRequest() {
   // The stored data cannot be used. Get rid of it and restart this request.
   // We need to also reset the |truncated_| flag as a new entry is created.
+  net_log_.AddEvent(NetLog::TYPE_HTTP_CACHE_RESTART_PARTIAL_REQUEST);
   DoomPartialEntry(!range_requested_);
   mode_ = WRITE;
   truncated_ = false;
diff --git a/net/http/http_cache_unittest.cc b/net/http/http_cache_unittest.cc
index 5199368..c52fbc4 100644
--- a/net/http/http_cache_unittest.cc
+++ b/net/http/http_cache_unittest.cc
@@ -185,6 +185,12 @@ void RunTransactionTest(net::HttpCache* cache,
   RunTransactionTestAndGetTiming(cache, trans_info, net::BoundNetLog(), NULL);
 }
 
+void RunTransactionTestWithLog(net::HttpCache* cache,
+                               const MockTransaction& trans_info,
+                               const net::BoundNetLog& log) {
+  RunTransactionTestAndGetTiming(cache, trans_info, log, NULL);
+}
+
 void RunTransactionTestWithResponseInfo(net::HttpCache* cache,
                                         const MockTransaction& trans_info,
                                         net::HttpResponseInfo* response) {
@@ -534,6 +540,17 @@ void FilterLogEntries(net::CapturingNetLog::CapturedEntryList* entries) {
                  entries->end());
 }
 
+bool LogContainsEventType(const net::CapturingBoundNetLog& log,
+                          net::NetLog::EventType expected) {
+  net::CapturingNetLog::CapturedEntryList entries;
+  log.GetEntries(&entries);
+  for (size_t i = 0; i < entries.size(); i++) {
+    if (entries[i].type == expected)
+      return true;
+  }
+  return false;
+}
+
 }  // namespace
 
 
@@ -3627,6 +3644,52 @@ TEST(HttpCache, RangeGET_SkipsCache2) {
   EXPECT_EQ(0, cache.disk_cache()->create_count());
 }
 
+TEST(HttpCache, SimpleGET_DoesntLogHeaders) {
+  MockHttpCache cache;
+
+  net::CapturingBoundNetLog log;
+  RunTransactionTestWithLog(cache.http_cache(), kSimpleGET_Transaction,
+                            log.bound());
+
+  EXPECT_FALSE(LogContainsEventType(
+      log, net::NetLog::TYPE_HTTP_CACHE_CALLER_REQUEST_HEADERS));
+}
+
+TEST(HttpCache, RangeGET_LogsHeaders) {
+  MockHttpCache cache;
+
+  net::CapturingBoundNetLog log;
+  RunTransactionTestWithLog(cache.http_cache(), kRangeGET_Transaction,
+                            log.bound());
+
+  EXPECT_TRUE(LogContainsEventType(
+      log, net::NetLog::TYPE_HTTP_CACHE_CALLER_REQUEST_HEADERS));
+}
+
+TEST(HttpCache, ExternalValidation_LogsHeaders) {
+  MockHttpCache cache;
+
+  net::CapturingBoundNetLog log;
+  MockTransaction transaction(kSimpleGET_Transaction);
+  transaction.request_headers = "If-None-Match: foo\r\n" EXTRA_HEADER;
+  RunTransactionTestWithLog(cache.http_cache(), transaction, log.bound());
+
+  EXPECT_TRUE(LogContainsEventType(
+      log, net::NetLog::TYPE_HTTP_CACHE_CALLER_REQUEST_HEADERS));
+}
+
+TEST(HttpCache, SpecialHeaders_LogsHeaders) {
+  MockHttpCache cache;
+
+  net::CapturingBoundNetLog log;
+  MockTransaction transaction(kSimpleGET_Transaction);
+  transaction.request_headers = "cache-control: no-cache\r\n" EXTRA_HEADER;
+  RunTransactionTestWithLog(cache.http_cache(), transaction, log.bound());
+
+  EXPECT_TRUE(LogContainsEventType(
+      log, net::NetLog::TYPE_HTTP_CACHE_CALLER_REQUEST_HEADERS));
+}
+
 // Tests that receiving 206 for a regular request is handled correctly.
 TEST(HttpCache, GET_Crazy206) {
   MockHttpCache cache;
@@ -3729,6 +3792,27 @@ TEST(HttpCache, RangeGET_NoValidation) {
   RemoveMockTransaction(&transaction);
 }
 
+// Tests that restarting a partial request when the cached data cannot be
+// revalidated logs an event.
+TEST(HttpCache, RangeGET_NoValidation_LogsRestart) {
+  MockHttpCache cache;
+
+  // Write to the cache (40-49).
+  ScopedMockTransaction transaction(kRangeGET_TransactionOK);
+  transaction.response_headers =
+      "Content-Length: 10\n"
+      "ETag: w/\"foo\"\n";
+  RunTransactionTest(cache.http_cache(), transaction);
+
+  // Now verify that the cached data is not used.
+  net::CapturingBoundNetLog log;
+  RunTransactionTestWithLog(cache.http_cache(), kRangeGET_TransactionOK,
+                            log.bound());
+
+  EXPECT_TRUE(LogContainsEventType(
+      log, net::NetLog::TYPE_HTTP_CACHE_RESTART_PARTIAL_REQUEST));
+}
+
 // Tests that we cache partial responses that lack content-length.
 TEST(HttpCache, RangeGET_NoContentLength) {
   MockHttpCache cache;
@@ -4954,11 +5038,10 @@ TEST(HttpCache, RangeHEAD) {
 TEST(HttpCache, RangeGET_FastFlakyServer) {
   MockHttpCache cache;
 
-  MockTransaction transaction(kRangeGET_TransactionOK);
+  ScopedMockTransaction transaction(kRangeGET_TransactionOK);
   transaction.request_headers = "Range: bytes = 40-\r\n" EXTRA_HEADER;
   transaction.test_mode = TEST_MODE_SYNC_NET_START;
   transaction.load_flags |= net::LOAD_VALIDATE_CACHE;
-  AddMockTransaction(&transaction);
 
   // Write to the cache.
   RunTransactionTest(cache.http_cache(), kRangeGET_TransactionOK);
@@ -4967,13 +5050,14 @@ TEST(HttpCache, RangeGET_FastFlakyServer) {
   RangeTransactionServer handler;
   handler.set_bad_200(true);
   transaction.data = "Not a range";
-  RunTransactionTest(cache.http_cache(), transaction);
+  net::CapturingBoundNetLog log;
+  RunTransactionTestWithLog(cache.http_cache(), transaction, log.bound());
 
   EXPECT_EQ(3, cache.network_layer()->transaction_count());
   EXPECT_EQ(1, cache.disk_cache()->open_count());
   EXPECT_EQ(1, cache.disk_cache()->create_count());
-
-  RemoveMockTransaction(&transaction);
+  EXPECT_TRUE(LogContainsEventType(
+      log, net::NetLog::TYPE_HTTP_CACHE_RE_SEND_PARTIAL_REQUEST));
 }
 
 // Tests that when the server gives us less data than expected, we don't keep