First pass at adding http/backend cache to NetLog

net/http/http_cache_transaction.cc

 // Copyright (c) 2010 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/http/http_cache_transaction.h"
 
 #include "build/build_config.h"
 
 #if defined(OS_POSIX)
 #include <unistd.h>
 #endif
 
 #include <string>
 
 #include "base/compiler_specific.h"
 #include "base/metrics/field_trial.h"
 #include "base/metrics/histogram.h"
 #include "base/ref_counted.h"
 #include "base/string_util.h"
 #include "base/time.h"
+#include "base/values.h"
 #include "net/base/cert_status_flags.h"
 #include "net/base/io_buffer.h"
 #include "net/base/load_flags.h"
 #include "net/base/net_errors.h"
 #include "net/base/net_log.h"
 #include "net/base/ssl_cert_request_info.h"
 #include "net/base/ssl_config_service.h"
 #include "net/disk_cache/disk_cache.h"
 #include "net/http/disk_cache_based_ssl_host_info.h"
 #include "net/http/http_request_info.h"
@@ skipping 347 matching lines @@
 }
 
 LoadState HttpCache::Transaction::GetWriterLoadState() const {
   if (network_trans_.get())
     return network_trans_->GetLoadState();
   if (entry_ || !request_)
     return LOAD_STATE_IDLE;
   return LOAD_STATE_WAITING_FOR_CACHE;
 }
 
+const BoundNetLog& HttpCache::Transaction::net_log() const {
+  return net_log_;
+}
+
 //-----------------------------------------------------------------------------
 
 void HttpCache::Transaction::DoCallback(int rv) {
   DCHECK(rv != ERR_IO_PENDING);
   DCHECK(callback_);
 
   // Since Run may result in Read being called, clear callback_ up front.
   CompletionCallback* c = callback_;
   callback_ = NULL;
   c->Run(rv);
@@ skipping 161 matching lines @@
 
   if (rv != ERR_IO_PENDING)
     HandleResult(rv);
 
   return rv;
 }
 
 int HttpCache::Transaction::DoGetBackend() {
   cache_pending_ = true;
   next_state_ = STATE_GET_BACKEND_COMPLETE;
-  net_log_.BeginEvent(NetLog::TYPE_HTTP_CACHE_WAITING, NULL);
+  net_log_.BeginEvent(NetLog::TYPE_HTTP_CACHE_GET_BACKEND, NULL);
   return cache_->GetBackendForTransaction(this);
 }
 
 int HttpCache::Transaction::DoGetBackendComplete(int result) {
   DCHECK(result == OK || result == ERR_FAILED);
-  net_log_.EndEvent(NetLog::TYPE_HTTP_CACHE_WAITING, NULL);
+  net_log_.EndEventWithErrorCode(NetLog::TYPE_HTTP_CACHE_GET_BACKEND, result);
   cache_pending_ = false;
 
   if (!ShouldPassThrough()) {
     cache_key_ = cache_->GenerateCacheKey(request_);
 
     // Requested cache access mode.
     if (effective_load_flags_ & LOAD_ONLY_FROM_CACHE) {
       mode_ = READ;
     } else if (effective_load_flags_ & LOAD_BYPASS_CACHE) {
       mode_ = WRITE;
@@ skipping 153 matching lines @@
   next_state_ = STATE_OPEN_ENTRY_COMPLETE;
   cache_pending_ = true;
   net_log_.BeginEvent(NetLog::TYPE_HTTP_CACHE_OPEN_ENTRY, NULL);
   return cache_->OpenEntry(cache_key_, &new_entry_, this);
 }
 
 int HttpCache::Transaction::DoOpenEntryComplete(int result) {
   // It is important that we go to STATE_ADD_TO_ENTRY whenever the result is
   // OK, otherwise the cache will end up with an active entry without any
   // transaction attached.
-  net_log_.EndEvent(NetLog::TYPE_HTTP_CACHE_OPEN_ENTRY, NULL);
+  net_log_.EndEventWithErrorCode(NetLog::TYPE_HTTP_CACHE_OPEN_ENTRY, result);
   cache_pending_ = false;
   if (result == OK) {
     next_state_ = STATE_ADD_TO_ENTRY;
     return OK;
   }
 
   if (result == ERR_CACHE_RACE) {
     next_state_ = STATE_INIT_ENTRY;
     return OK;
   }
@@ skipping 22 matching lines @@
   next_state_ = STATE_CREATE_ENTRY_COMPLETE;
   cache_pending_ = true;
   net_log_.BeginEvent(NetLog::TYPE_HTTP_CACHE_CREATE_ENTRY, NULL);
   return cache_->CreateEntry(cache_key_, &new_entry_, this);
 }
 
 int HttpCache::Transaction::DoCreateEntryComplete(int result) {
   // It is important that we go to STATE_ADD_TO_ENTRY whenever the result is
   // OK, otherwise the cache will end up with an active entry without any
   // transaction attached.
-  net_log_.EndEvent(NetLog::TYPE_HTTP_CACHE_CREATE_ENTRY, NULL);
+  net_log_.EndEventWithErrorCode(NetLog::TYPE_HTTP_CACHE_CREATE_ENTRY, result);
   cache_pending_ = false;
   next_state_ = STATE_ADD_TO_ENTRY;
 
   if (result == ERR_CACHE_RACE) {
     next_state_ = STATE_INIT_ENTRY;
     return OK;
   }
 
   if (result != OK) {
     // We have a race here: Maybe we failed to open the entry and decided to
@@ skipping 10 matching lines @@
 }
 
 int HttpCache::Transaction::DoDoomEntry() {
   next_state_ = STATE_DOOM_ENTRY_COMPLETE;
   cache_pending_ = true;
   net_log_.BeginEvent(NetLog::TYPE_HTTP_CACHE_DOOM_ENTRY, NULL);
   return cache_->DoomEntry(cache_key_, this);
 }
 
 int HttpCache::Transaction::DoDoomEntryComplete(int result) {
-  net_log_.EndEvent(NetLog::TYPE_HTTP_CACHE_DOOM_ENTRY, NULL);
+  net_log_.EndEventWithErrorCode(NetLog::TYPE_HTTP_CACHE_DOOM_ENTRY, result);
   next_state_ = STATE_CREATE_ENTRY;
   cache_pending_ = false;
   if (result == ERR_CACHE_RACE)
     next_state_ = STATE_INIT_ENTRY;
 
   return OK;
 }
 
 int HttpCache::Transaction::DoAddToEntry() {
   DCHECK(new_entry_);
   cache_pending_ = true;
   next_state_ = STATE_ADD_TO_ENTRY_COMPLETE;
-  net_log_.BeginEvent(NetLog::TYPE_HTTP_CACHE_WAITING, NULL);
+  net_log_.BeginEvent(NetLog::TYPE_HTTP_CACHE_ADD_TO_ENTRY, NULL);
   DCHECK(entry_lock_waiting_since_.is_null());
   entry_lock_waiting_since_ = base::TimeTicks::Now();
   return cache_->AddTransactionToEntry(new_entry_, this);
 }
 
 int HttpCache::Transaction::DoAddToEntryComplete(int result) {
-  net_log_.EndEvent(NetLog::TYPE_HTTP_CACHE_WAITING, NULL);
-
+  net_log_.EndEventWithErrorCode(NetLog::TYPE_HTTP_CACHE_ADD_TO_ENTRY, result);
   const base::TimeDelta entry_lock_wait =
       base::TimeTicks::Now() - entry_lock_waiting_since_;
   UMA_HISTOGRAM_TIMES("HttpCache.EntryLockWait", entry_lock_wait);
   static const bool prefetching_fieldtrial =
       base::FieldTrialList::Find("Prefetch") &&
       !base::FieldTrialList::Find("Prefetch")->group_name().empty();
   if (prefetching_fieldtrial) {
     UMA_HISTOGRAM_TIMES(
         base::FieldTrial::MakeName("HttpCache.EntryLockWait", "Prefetch"),
         entry_lock_wait);
@@ skipping 129 matching lines @@
   next_state_ = truncated_ ? STATE_CACHE_WRITE_TRUNCATED_RESPONSE :
                              STATE_CACHE_WRITE_RESPONSE;
   return OK;
 }
 
 int HttpCache::Transaction::DoTruncateCachedData() {
   next_state_ = STATE_TRUNCATE_CACHED_DATA_COMPLETE;
   cache_callback_->AddRef();  // Balanced in DoTruncateCachedDataComplete.
   if (!entry_)
     return OK;
+  if (net_log_.IsLoggingAllEvents())
+    net_log_.BeginEvent(NetLog::TYPE_HTTP_CACHE_WRITE_DATA, NULL);
 
   // Truncate the stream.
   return WriteToEntry(kResponseContentIndex, 0, NULL, 0, cache_callback_);
 }
 
 int HttpCache::Transaction::DoTruncateCachedDataComplete(int result) {
+  if (net_log_.IsLoggingAllEvents() && entry_)
+    net_log_.EndEventWithErrorCode(NetLog::TYPE_HTTP_CACHE_WRITE_DATA, result);
+
   // Balance the AddRef from DoTruncateCachedData.
   cache_callback_->Release();
   next_state_ = STATE_TRUNCATE_CACHED_METADATA;
   return OK;
 }
 
 int HttpCache::Transaction::DoTruncateCachedMetadata() {
   next_state_ = STATE_TRUNCATE_CACHED_METADATA_COMPLETE;
   cache_callback_->AddRef();  // Balanced in DoTruncateCachedMetadataComplete.
   if (!entry_)
     return OK;
 
+  if (net_log_.IsLoggingAllEvents())
+    net_log_.BeginEvent(NetLog::TYPE_HTTP_CACHE_WRITE_INFO, NULL);
   return WriteToEntry(kMetadataIndex, 0, NULL, 0, cache_callback_);
 }
 
 int HttpCache::Transaction::DoTruncateCachedMetadataComplete(int result) {
+  if (net_log_.IsLoggingAllEvents() && entry_)
+    net_log_.EndEventWithErrorCode(NetLog::TYPE_HTTP_CACHE_WRITE_INFO, result);
+
   // Balance the AddRef from DoTruncateCachedMetadata.
   cache_callback_->Release();
 
   // If this response is a redirect, then we can stop writing now.  (We don't
   // need to cache the response body of a redirect.)
   if (response_.headers->IsRedirect(NULL))
     DoneWritingToEntry(true);
   next_state_ = STATE_PARTIAL_HEADERS_RECEIVED;
   return OK;
 }
@@ skipping 29 matching lines @@
   read_buf_ = new IOBuffer(io_buf_len_);
 
   net_log_.BeginEvent(NetLog::TYPE_HTTP_CACHE_READ_INFO, NULL);
   cache_callback_->AddRef();  // Balanced in DoCacheReadResponseComplete.
   return entry_->disk_entry->ReadData(kResponseInfoIndex, 0, read_buf_,
                                       io_buf_len_, cache_callback_);
 }
 
 int HttpCache::Transaction::DoCacheReadResponseComplete(int result) {
   cache_callback_->Release();  // Balance the AddRef from DoCacheReadResponse.
-  net_log_.EndEvent(NetLog::TYPE_HTTP_CACHE_READ_INFO, NULL);
+  net_log_.EndEventWithErrorCode(NetLog::TYPE_HTTP_CACHE_READ_INFO, result);
   if (result != io_buf_len_ ||
       !HttpCache::ParseResponseInfo(read_buf_->data(), io_buf_len_,
                                     &response_, &truncated_)) {
     DLOG(ERROR) << "ReadData failed: " << result;
     return ERR_CACHE_READ_FAILURE;
   }
 
   // We now have access to the cache entry.
   //
   //  o if we are a reader for the transaction, then we can start reading the
@@ skipping 19 matching lines @@
       break;
     case WRITE:
     default:
       NOTREACHED();
       result = ERR_FAILED;
   }
   return result;
 }
 
 int HttpCache::Transaction::DoCacheWriteResponse() {
+  if (net_log_.IsLoggingAllEvents() && entry_)
+    net_log_.BeginEvent(NetLog::TYPE_HTTP_CACHE_WRITE_INFO, NULL);
   return WriteResponseInfoToEntry(false);
 }
 
 int HttpCache::Transaction::DoCacheWriteTruncatedResponse() {
+  if (net_log_.IsLoggingAllEvents() && entry_)
+    net_log_.BeginEvent(NetLog::TYPE_HTTP_CACHE_WRITE_INFO, NULL);
   return WriteResponseInfoToEntry(true);
 }
 
 int HttpCache::Transaction::DoCacheWriteResponseComplete(int result) {
   next_state_ = target_state_;
   target_state_ = STATE_NONE;
   if (!entry_)
     return OK;
+  if (net_log_.IsLoggingAllEvents())
+    net_log_.EndEventWithErrorCode(NetLog::TYPE_HTTP_CACHE_WRITE_INFO, result);
 
   // Balance the AddRef from WriteResponseInfoToEntry.
   write_headers_callback_->Release();
   if (result != io_buf_len_) {
     DLOG(ERROR) << "failed to write response info to cache";
     DoneWritingToEntry(false);
   }
   return OK;
 }
 
 int HttpCache::Transaction::DoCacheReadMetadata() {
   DCHECK(entry_);
   DCHECK(!response_.metadata);
   next_state_ = STATE_CACHE_READ_METADATA_COMPLETE;
 
   response_.metadata =
       new IOBufferWithSize(entry_->disk_entry->GetDataSize(kMetadataIndex));
 
   net_log_.BeginEvent(NetLog::TYPE_HTTP_CACHE_READ_INFO, NULL);
   cache_callback_->AddRef();  // Balanced in DoCacheReadMetadataComplete.
   return entry_->disk_entry->ReadData(kMetadataIndex, 0, response_.metadata,
                                       response_.metadata->size(),
                                       cache_callback_);
 }
 
 int HttpCache::Transaction::DoCacheReadMetadataComplete(int result) {
   cache_callback_->Release();  // Balance the AddRef from DoCacheReadMetadata.
-  net_log_.EndEvent(NetLog::TYPE_HTTP_CACHE_READ_INFO, NULL);
+  net_log_.EndEventWithErrorCode(NetLog::TYPE_HTTP_CACHE_READ_INFO, result);
   if (result != response_.metadata->size()) {
     DLOG(ERROR) << "ReadData failed: " << result;
     return ERR_CACHE_READ_FAILURE;
   }
 
   return OK;
 }
 
 int HttpCache::Transaction::DoCacheQueryData() {
   next_state_ = STATE_CACHE_QUERY_DATA_COMPLETE;
@@ skipping 10 matching lines @@
   if (!cache_)
     return ERR_UNEXPECTED;
 
   return ValidateEntryHeadersAndContinue(true);
 }
 
 int HttpCache::Transaction::DoCacheReadData() {
   DCHECK(entry_);
   next_state_ = STATE_CACHE_READ_DATA_COMPLETE;
   cache_callback_->AddRef();  // Balanced in DoCacheReadDataComplete.
+
+  if (net_log_.IsLoggingAllEvents())
+    net_log_.BeginEvent(NetLog::TYPE_HTTP_CACHE_READ_DATA, NULL);
   if (partial_.get()) {
     return partial_->CacheRead(entry_->disk_entry, read_buf_, io_buf_len_,
                                cache_callback_);
   }
 
   return entry_->disk_entry->ReadData(kResponseContentIndex, read_offset_,
                                       read_buf_, io_buf_len_, cache_callback_);
 }
 
 int HttpCache::Transaction::DoCacheReadDataComplete(int result) {
   cache_callback_->Release();  // Balance the AddRef from DoCacheReadData.
+  if (net_log_.IsLoggingAllEvents())
+    net_log_.EndEventWithErrorCode(NetLog::TYPE_HTTP_CACHE_READ_DATA, result);
 
   if (!cache_)
     return ERR_UNEXPECTED;
 
   if (partial_.get())
     return DoPartialCacheReadCompleted(result);
 
   if (result > 0) {
     read_offset_ += result;
   } else if (result == 0) {  // End of file.
     cache_->DoneReadingFromEntry(entry_, this);
     entry_ = NULL;
   }
   return result;
 }
 
 int HttpCache::Transaction::DoCacheWriteData(int num_bytes) {
   next_state_ = STATE_CACHE_WRITE_DATA_COMPLETE;
   write_len_ = num_bytes;
+  if (net_log_.IsLoggingAllEvents())
+    net_log_.BeginEvent(NetLog::TYPE_HTTP_CACHE_WRITE_DATA, NULL);
   cache_callback_->AddRef();  // Balanced in DoCacheWriteDataComplete.
 
   return AppendResponseDataToEntry(read_buf_, num_bytes, cache_callback_);
 }
 
 int HttpCache::Transaction::DoCacheWriteDataComplete(int result) {
+  if (net_log_.IsLoggingAllEvents() && entry_)
+    net_log_.EndEventWithErrorCode(NetLog::TYPE_HTTP_CACHE_WRITE_DATA, result);
   // Balance the AddRef from DoCacheWriteData.
   cache_callback_->Release();
   if (!cache_)
     return ERR_UNEXPECTED;
 
   if (result != write_len_) {
     DLOG(ERROR) << "failed to write response data to cache";
     DoneWritingToEntry(false);
 
     // We want to ignore errors writing to disk and just keep reading from
@@ skipping 675 matching lines @@
   // |value| goes from 0 to 63. Actually, the max value should be 47 (0x2f)
   // but we'll see.
   UMA_HISTOGRAM_ENUMERATION("HttpCache.ResponseHeaders", value, 65);
 }
 
 void HttpCache::Transaction::OnIOComplete(int result) {
   DoLoop(result);
 }
 
 }  // namespace net