First pass at adding http/backend cache events to the NetLog.

Adds sources and events for ActiveCacheEntry and EntryImpl 
objects, as well as adding cache read/write events to 
HttpCacheTransactions. Most new read/write events are 
only logged when NetLog logging mode is set to log all events. 

Also, net-internals now merges begin and end events that have 
parameters, as long as only one of them has parameters. 
I think this increases readability, at the cost of making 
it a little more difficult to follow timings with just the "st" 
values. 

BUG=59382
TEST=none yet, other than updates to existing tests.

Review URL: http://codereview.chromium.org/4067002

git-svn-id: svn://svn.chromium.org/chrome/trunk/src@70618 0039d316-1c4b-4281-b951-d872f2087c98

1 files changed, 45 insertions, 27 deletions

diff --git a/net/http/http_cache_unittest.cc b/net/http/http_cache_unittest.cc
index a40a5b8..bf8cb6b 100644
--- a/net/http/http_cache_unittest.cc
+++ b/net/http/http_cache_unittest.cc
@@ -536,7 +536,8 @@ class MockDiskCache : public disk_cache::Backend {
 
 class MockBackendFactory : public net::HttpCache::BackendFactory {
  public:
-  virtual int CreateBackend(disk_cache::Backend** backend,
+  virtual int CreateBackend(net::NetLog*  /* net_log */,
+                            disk_cache::Backend** backend,
                             net::CompletionCallback* callback) {
     *backend = new MockDiskCache();
     return net::OK;
@@ -546,11 +547,11 @@ class MockBackendFactory : public net::HttpCache::BackendFactory {
 class MockHttpCache {
  public:
   MockHttpCache()
-      : http_cache_(new MockNetworkLayer(), new MockBackendFactory()) {
+      : http_cache_(new MockNetworkLayer(), NULL, new MockBackendFactory()) {
   }
 
   explicit MockHttpCache(net::HttpCache::BackendFactory* disk_cache_factory)
-      : http_cache_(new MockNetworkLayer(), disk_cache_factory) {
+      : http_cache_(new MockNetworkLayer(), NULL, disk_cache_factory) {
   }
 
   net::HttpCache* http_cache() { return &http_cache_; }
@@ -610,7 +611,8 @@ class MockHttpCache {
   }
 
   // Helper function to synchronously create a backend entry.
-  bool CreateBackendEntry(const std::string& key, disk_cache::Entry** entry) {
+  bool CreateBackendEntry(const std::string& key, disk_cache::Entry** entry,
+                          net::NetLog*  /* net_log */) {
     TestCompletionCallback cb;
     int rv = disk_cache()->CreateEntry(key, entry, &cb);
     return (cb.GetResult(rv) == net::OK);
@@ -630,7 +632,8 @@ class MockDiskCacheNoCB : public MockDiskCache {
 
 class MockBackendNoCbFactory : public net::HttpCache::BackendFactory {
  public:
-  virtual int CreateBackend(disk_cache::Backend** backend,
+  virtual int CreateBackend(net::NetLog*  /* net_log */,
+                            disk_cache::Backend** backend,
                             net::CompletionCallback* callback) {
     *backend = new MockDiskCacheNoCB();
     return net::OK;
@@ -643,7 +646,8 @@ class MockBlockingBackendFactory : public net::HttpCache::BackendFactory {
   MockBlockingBackendFactory()
       : backend_(NULL), callback_(NULL), block_(true), fail_(false) {}
 
-  virtual int CreateBackend(disk_cache::Backend** backend,
+  virtual int CreateBackend(net::NetLog*  /* net_log */,
+                            disk_cache::Backend** backend,
                             net::CompletionCallback* callback) {
     if (!block_) {
       if (!fail_)
@@ -1037,6 +1041,7 @@ TEST(HttpCache, SimpleGETNoDiskCache) {
   cache.disk_cache()->set_fail_requests();
 
   net::CapturingBoundNetLog log(net::CapturingNetLog::kUnbounded);
+  log.SetLogLevel(net::NetLog::LOG_BASIC);
 
   // Read from the network, and don't use the cache.
   RunTransactionTestWithLog(cache.http_cache(), kSimpleGET_Transaction,
@@ -1049,9 +1054,9 @@ TEST(HttpCache, SimpleGETNoDiskCache) {
 
   EXPECT_EQ(6u, entries.size());
   EXPECT_TRUE(net::LogContainsBeginEvent(
-      entries, 0, net::NetLog::TYPE_HTTP_CACHE_WAITING));
+      entries, 0, net::NetLog::TYPE_HTTP_CACHE_GET_BACKEND));
   EXPECT_TRUE(net::LogContainsEndEvent(
-      entries, 1, net::NetLog::TYPE_HTTP_CACHE_WAITING));
+      entries, 1, net::NetLog::TYPE_HTTP_CACHE_GET_BACKEND));
   EXPECT_TRUE(net::LogContainsBeginEvent(
       entries, 2, net::NetLog::TYPE_HTTP_CACHE_OPEN_ENTRY));
   EXPECT_TRUE(net::LogContainsEndEvent(
@@ -1143,6 +1148,9 @@ TEST(HttpCache, SimpleGET_LoadOnlyFromCache_Hit) {
 
   net::CapturingBoundNetLog log(net::CapturingNetLog::kUnbounded);
 
+  // This prevents a number of write events from being logged.
+  log.SetLogLevel(net::NetLog::LOG_BASIC);
+
   // write to the cache
   RunTransactionTestWithLog(cache.http_cache(), kSimpleGET_Transaction,
                             log.bound());
@@ -1153,9 +1161,9 @@ TEST(HttpCache, SimpleGET_LoadOnlyFromCache_Hit) {
 
   EXPECT_EQ(8u, entries.size());
   EXPECT_TRUE(net::LogContainsBeginEvent(
-      entries, 0, net::NetLog::TYPE_HTTP_CACHE_WAITING));
+      entries, 0, net::NetLog::TYPE_HTTP_CACHE_GET_BACKEND));
   EXPECT_TRUE(net::LogContainsEndEvent(
-      entries, 1, net::NetLog::TYPE_HTTP_CACHE_WAITING));
+      entries, 1, net::NetLog::TYPE_HTTP_CACHE_GET_BACKEND));
   EXPECT_TRUE(net::LogContainsBeginEvent(
       entries, 2, net::NetLog::TYPE_HTTP_CACHE_OPEN_ENTRY));
   EXPECT_TRUE(net::LogContainsEndEvent(
@@ -1165,9 +1173,9 @@ TEST(HttpCache, SimpleGET_LoadOnlyFromCache_Hit) {
   EXPECT_TRUE(net::LogContainsEndEvent(
       entries, 5, net::NetLog::TYPE_HTTP_CACHE_CREATE_ENTRY));
   EXPECT_TRUE(net::LogContainsBeginEvent(
-      entries, 6, net::NetLog::TYPE_HTTP_CACHE_WAITING));
+      entries, 6, net::NetLog::TYPE_HTTP_CACHE_ADD_TO_ENTRY));
   EXPECT_TRUE(net::LogContainsEndEvent(
-      entries, 7, net::NetLog::TYPE_HTTP_CACHE_WAITING));
+      entries, 7, net::NetLog::TYPE_HTTP_CACHE_ADD_TO_ENTRY));
 
   // force this transaction to read from the cache
   MockTransaction transaction(kSimpleGET_Transaction);
@@ -1182,17 +1190,17 @@ TEST(HttpCache, SimpleGET_LoadOnlyFromCache_Hit) {
 
   EXPECT_EQ(8u, entries.size());
   EXPECT_TRUE(net::LogContainsBeginEvent(
-      entries, 0, net::NetLog::TYPE_HTTP_CACHE_WAITING));
+      entries, 0, net::NetLog::TYPE_HTTP_CACHE_GET_BACKEND));
   EXPECT_TRUE(net::LogContainsEndEvent(
-      entries, 1, net::NetLog::TYPE_HTTP_CACHE_WAITING));
+      entries, 1, net::NetLog::TYPE_HTTP_CACHE_GET_BACKEND));
   EXPECT_TRUE(net::LogContainsBeginEvent(
       entries, 2, net::NetLog::TYPE_HTTP_CACHE_OPEN_ENTRY));
   EXPECT_TRUE(net::LogContainsEndEvent(
       entries, 3, net::NetLog::TYPE_HTTP_CACHE_OPEN_ENTRY));
   EXPECT_TRUE(net::LogContainsBeginEvent(
-      entries, 4, net::NetLog::TYPE_HTTP_CACHE_WAITING));
+      entries, 4, net::NetLog::TYPE_HTTP_CACHE_ADD_TO_ENTRY));
   EXPECT_TRUE(net::LogContainsEndEvent(
-      entries, 5, net::NetLog::TYPE_HTTP_CACHE_WAITING));
+      entries, 5, net::NetLog::TYPE_HTTP_CACHE_ADD_TO_ENTRY));
   EXPECT_TRUE(net::LogContainsBeginEvent(
       entries, 6, net::NetLog::TYPE_HTTP_CACHE_READ_INFO));
   EXPECT_TRUE(net::LogContainsEndEvent(
@@ -1273,6 +1281,9 @@ TEST(HttpCache, SimpleGET_LoadBypassCache) {
 
   net::CapturingBoundNetLog log(net::CapturingNetLog::kUnbounded);
 
+  // This prevents a number of write events from being logged.
+  log.SetLogLevel(net::NetLog::LOG_BASIC);
+
   RunTransactionTestWithLog(cache.http_cache(), transaction, log.bound());
 
   // Check that the NetLog was filled as expected.
@@ -1281,9 +1292,9 @@ TEST(HttpCache, SimpleGET_LoadBypassCache) {
 
   EXPECT_EQ(8u, entries.size());
   EXPECT_TRUE(net::LogContainsBeginEvent(
-      entries, 0, net::NetLog::TYPE_HTTP_CACHE_WAITING));
+      entries, 0, net::NetLog::TYPE_HTTP_CACHE_GET_BACKEND));
   EXPECT_TRUE(net::LogContainsEndEvent(
-      entries, 1, net::NetLog::TYPE_HTTP_CACHE_WAITING));
+      entries, 1, net::NetLog::TYPE_HTTP_CACHE_GET_BACKEND));
   EXPECT_TRUE(net::LogContainsBeginEvent(
       entries, 2, net::NetLog::TYPE_HTTP_CACHE_DOOM_ENTRY));
   EXPECT_TRUE(net::LogContainsEndEvent(
@@ -1293,9 +1304,9 @@ TEST(HttpCache, SimpleGET_LoadBypassCache) {
   EXPECT_TRUE(net::LogContainsEndEvent(
       entries, 5, net::NetLog::TYPE_HTTP_CACHE_CREATE_ENTRY));
   EXPECT_TRUE(net::LogContainsBeginEvent(
-      entries, 6, net::NetLog::TYPE_HTTP_CACHE_WAITING));
+      entries, 6, net::NetLog::TYPE_HTTP_CACHE_ADD_TO_ENTRY));
   EXPECT_TRUE(net::LogContainsEndEvent(
-      entries, 7, net::NetLog::TYPE_HTTP_CACHE_WAITING));
+      entries, 7, net::NetLog::TYPE_HTTP_CACHE_ADD_TO_ENTRY));
 
   EXPECT_EQ(2, cache.network_layer()->transaction_count());
   EXPECT_EQ(0, cache.disk_cache()->open_count());
@@ -3302,7 +3313,8 @@ TEST(HttpCache, GET_Previous206_NotSparse) {
 
   // Create a disk cache entry that stores 206 headers while not being sparse.
   disk_cache::Entry* entry;
-  ASSERT_TRUE(cache.CreateBackendEntry(kSimpleGET_Transaction.url, &entry));
+  ASSERT_TRUE(cache.CreateBackendEntry(kSimpleGET_Transaction.url, &entry,
+                                       NULL));
 
   std::string raw_headers(kRangeGET_TransactionOK.status);
   raw_headers.append("\n");
@@ -3345,7 +3357,8 @@ TEST(HttpCache, RangeGET_Previous206_NotSparse_2) {
 
   // Create a disk cache entry that stores 206 headers while not being sparse.
   disk_cache::Entry* entry;
-  ASSERT_TRUE(cache.CreateBackendEntry(kRangeGET_TransactionOK.url, &entry));
+  ASSERT_TRUE(cache.CreateBackendEntry(kRangeGET_TransactionOK.url, &entry,
+                                       NULL));
 
   std::string raw_headers(kRangeGET_TransactionOK.status);
   raw_headers.append("\n");
@@ -3943,7 +3956,8 @@ TEST(HttpCache, RangeGET_OK_LoadOnlyFromCache) {
 TEST(HttpCache, WriteResponseInfo_Truncated) {
   MockHttpCache cache;
   disk_cache::Entry* entry;
-  ASSERT_TRUE(cache.CreateBackendEntry("http://www.google.com", &entry));
+  ASSERT_TRUE(cache.CreateBackendEntry("http://www.google.com", &entry,
+                                       NULL));
 
   std::string headers("HTTP/1.1 200 OK");
   headers = net::HttpUtil::AssembleRawHeaders(headers.data(), headers.size());
@@ -4142,7 +4156,8 @@ TEST(HttpCache, GET_IncompleteResource) {
 
   // Create a disk cache entry that stores an incomplete resource.
   disk_cache::Entry* entry;
-  ASSERT_TRUE(cache.CreateBackendEntry(kRangeGET_TransactionOK.url, &entry));
+  ASSERT_TRUE(cache.CreateBackendEntry(kRangeGET_TransactionOK.url, &entry,
+                                       NULL));
 
   std::string raw_headers("HTTP/1.1 200 OK\n"
                           "Last-Modified: Sat, 18 Apr 2009 01:10:43 GMT\n"
@@ -4202,7 +4217,8 @@ TEST(HttpCache, GET_IncompleteResource2) {
 
   // Create a disk cache entry that stores an incomplete resource.
   disk_cache::Entry* entry;
-  ASSERT_TRUE(cache.CreateBackendEntry(kRangeGET_TransactionOK.url, &entry));
+  ASSERT_TRUE(cache.CreateBackendEntry(kRangeGET_TransactionOK.url, &entry,
+                                       NULL));
 
 
   // Content-length will be intentionally bad.
@@ -4261,7 +4277,8 @@ TEST(HttpCache, GET_CancelIncompleteResource) {
 
   // Create a disk cache entry that stores an incomplete resource.
   disk_cache::Entry* entry;
-  ASSERT_TRUE(cache.CreateBackendEntry(kRangeGET_TransactionOK.url, &entry));
+  ASSERT_TRUE(cache.CreateBackendEntry(kRangeGET_TransactionOK.url, &entry,
+                                       NULL));
 
   std::string raw_headers("HTTP/1.1 200 OK\n"
                           "Last-Modified: Sat, 18 Apr 2009 01:10:43 GMT\n"
@@ -4326,7 +4343,8 @@ TEST(HttpCache, RangeGET_IncompleteResource) {
 
   // Create a disk cache entry that stores an incomplete resource.
   disk_cache::Entry* entry;
-  ASSERT_TRUE(cache.CreateBackendEntry(kRangeGET_TransactionOK.url, &entry));
+  ASSERT_TRUE(cache.CreateBackendEntry(kRangeGET_TransactionOK.url, &entry,
+                                       NULL));
 
   // Content-length will be intentionally bogus.
   std::string raw_headers("HTTP/1.1 200 OK\n"