Added net logging to BaseFile.

content/browser/download/base_file.cc

 // Copyright (c) 2012 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 "content/browser/download/base_file.h"
 
 #include "base/file_util.h"
 #include "base/format_macros.h"
 #include "base/logging.h"
 #include "base/pickle.h"
 #include "base/stringprintf.h"
 #include "base/threading/thread_restrictions.h"
 #include "base/utf_string_conversions.h"
+#include "content/browser/download/download_net_log_parameters.h"
 #include "content/browser/download/download_stats.h"
 #include "content/public/browser/browser_thread.h"
 #include "content/public/browser/content_browser_client.h"
 #include "crypto/secure_hash.h"
 #include "net/base/file_stream.h"
 #include "net/base/net_errors.h"
 
 #if defined(OS_WIN)
 #include <windows.h>
 #include <shellapi.h>
 
 #include "content/browser/safe_util_win.h"
 #elif defined(OS_MACOSX)
 #include "content/browser/file_metadata_mac.h"
 #endif
 
 using content::BrowserThread;
 
 namespace {
 
-#define LOG_ERROR(o, e)  LogError(__FILE__, __LINE__, __FUNCTION__, o, e)
+#define LOG_ERROR(o, e)  \
+  LogError(__FILE__, __LINE__, __FUNCTION__, bound_net_log_, o, e)
 
 // Logs the value and passes error on through, converting to a |net::Error|.
 // Returns |ERR_UNEXPECTED| if the value is not in the enum.
-net::Error LogError(const char* file, int line, const char* func,
-                    const char* operation, int error) {
+net::Error LogError(const char* file,
+                    int line,
+                    const char* func,
+                    const net::BoundNetLog& bound_net_log,
+                    const char* operation,
+                    int error) {
   const char* err_string = "";
   net::Error net_error = net::OK;
 
 #define NET_ERROR(label, value)  \
   case net::ERR_##label: \
     err_string = #label; \
     net_error = net::ERR_##label; \
     break;
 
   switch (error) {
     case net::OK:
       return net::OK;
 
 #include "net/base/net_error_list.h"
 
     default:
       err_string = "Unexpected enum value";
       net_error = net::ERR_UNEXPECTED;
       break;
   }
 
 #undef NET_ERROR
 
   VLOG(1) << " " << func << "(): " << operation
           << "() returned error " << error << " (" << err_string << ")";
 
+  bound_net_log.AddEvent(
+      net::NetLog::TYPE_DOWNLOAD_FILE_ERROR,
+      make_scoped_refptr(
+          new download_net_logs::FileErrorParameters(operation, net_error)));
+
   return net_error;
 }
 
 #if defined(OS_WIN)
 
 #define SHFILE_TO_NET_ERROR(symbol, value, mapping, description) \
   case value: return net::ERR_##mapping;
 
 // Maps the result of a call to |SHFileOperation()| onto a |net::Error|.
 //
@@ skipping 113 matching lines @@
 
 // This will initialize the entire array to zero.
 const unsigned char BaseFile::kEmptySha256Hash[] = { 0 };
 
 BaseFile::BaseFile(const FilePath& full_path,
                    const GURL& source_url,
                    const GURL& referrer_url,
                    int64 received_bytes,
                    bool calculate_hash,
                    const std::string& hash_state,
-                   const linked_ptr<net::FileStream>& file_stream)
+                   const linked_ptr<net::FileStream>& file_stream,
+                   const net::BoundNetLog& bound_net_log)
     : full_path_(full_path),
       source_url_(source_url),
       referrer_url_(referrer_url),
       file_stream_(file_stream),
       bytes_so_far_(received_bytes),
       start_tick_(base::TimeTicks::Now()),
       power_save_blocker_(PowerSaveBlocker::kPowerSaveBlockPreventSystemSleep),
       calculate_hash_(calculate_hash),
-      detached_(false) {
+      detached_(false),
+      bound_net_log_(bound_net_log) {
   DCHECK(BrowserThread::CurrentlyOn(BrowserThread::FILE));
   memcpy(sha256_hash_, kEmptySha256Hash, kSha256HashLen);
-  if (file_stream_.get())
+  if (file_stream_.get()) {
+    file_stream_->SetBoundNetLogSource(bound_net_log_);
     file_stream_->EnableErrorStatistics();
+  }
 
   if (calculate_hash_) {
     secure_hash_.reset(crypto::SecureHash::Create(crypto::SecureHash::SHA256));
     if ((bytes_so_far_ > 0) &&  // Not starting at the beginning.
         (hash_state != "") &&  // Reasonably sure we have a hash state.
         (!IsEmptyHash(hash_state))) {
       SetHashState(hash_state);
     }
   }
 }
@@ skipping 23 matching lines @@
 
   return Open();
 }
 
 net::Error BaseFile::AppendDataToFile(const char* data, size_t data_len) {
   DCHECK(BrowserThread::CurrentlyOn(BrowserThread::FILE));
   DCHECK(!detached_);
 
   // NOTE(benwells): The above DCHECK won't be present in release builds,
   // so we log any occurences to see how common this error is in the wild.
-  if (detached_)
+  if (detached_) {
     download_stats::RecordDownloadCount(
         download_stats::APPEND_TO_DETACHED_FILE_COUNT);
+  }
+
+  bound_net_log_.AddEvent(

[mmenke1, 2012/02/03 18:32:32]

This should be wrapped in:

if (bound_net_log_.IsLoggingAllEvents())

[ahendrickson, 2012/02/04 05:27:14]

Done.

+      net::NetLog::TYPE_DOWNLOAD_FILE_WRITTEN,
+      make_scoped_refptr(
+          new download_net_logs::FileWrittenParameters(
+              data_len, bytes_so_far_)));
 
   if (!file_stream_.get())
     return LOG_ERROR("get", net::ERR_INVALID_HANDLE);
 
   // TODO(phajdan.jr): get rid of this check.
   if (data_len == 0)
     return net::OK;
 
   // The Write call below is not guaranteed to write all the data.
   size_t write_count = 0;
@@ skipping 16 matching lines @@
     }
 
     // Update status.
     size_t write_size = static_cast<size_t>(write_result);
     DCHECK_LE(write_size, len);
     len -= write_size;
     current_data += write_size;
     bytes_so_far_ += write_size;
   }
 
-  // TODO(ahendrickson) -- Uncomment these when the functions are available.
-   download_stats::RecordDownloadWriteSize(data_len);
-   download_stats::RecordDownloadWriteLoopCount(write_count);
+  download_stats::RecordDownloadWriteSize(data_len);
+  download_stats::RecordDownloadWriteLoopCount(write_count);
 
   if (calculate_hash_)
     secure_hash_->Update(data, data_len);
 
   return net::OK;
 }
 
 net::Error BaseFile::Rename(const FilePath& new_path) {
   DCHECK(BrowserThread::CurrentlyOn(BrowserThread::FILE));
 
   // Save the information whether the download is in progress because
   // it will be overwritten by closing the file.
   bool saved_in_progress = in_progress();
 
+  bound_net_log_.AddEvent(
+      net::NetLog::TYPE_DOWNLOAD_FILE_RENAMED,
+      make_scoped_refptr(
+          new download_net_logs::FileRenamedParameters(
+              full_path_.AsUTF8Unsafe(), new_path.AsUTF8Unsafe())));
+
   // If the new path is same as the old one, there is no need to perform the
   // following renaming logic.
   if (new_path == full_path_) {
     // Don't close the file if we're not done (finished or canceled).
     if (!saved_in_progress)
       Close();
 
     return net::OK;
   }
 
@@ skipping 47 matching lines @@
 
   // We don't need to re-open the file if we're done (finished or canceled).
   if (!saved_in_progress)
     return net::OK;
 
   return Open();
 }
 
 void BaseFile::Detach() {
   detached_ = true;
+  bound_net_log_.AddEvent(net::NetLog::TYPE_DOWNLOAD_FILE_DETACHED, NULL);
 }
 
 void BaseFile::Cancel() {
   DCHECK(BrowserThread::CurrentlyOn(BrowserThread::FILE));
   DCHECK(!detached_);
 
+  bound_net_log_.AddEvent(net::NetLog::TYPE_DOWNLOAD_FILE_CANCELED, NULL);

[mmenke1, 2012/02/03 18:32:32]

I'd suggest using the generic NetLog::TYPE_CANCELLED here.  This allows some
future net-internals code to identify cancelled things easily.

[ahendrickson, 2012/02/04 05:27:14]

Done.

+
   Close();
 
-  if (!full_path_.empty())
+  if (!full_path_.empty()) {
+    bound_net_log_.AddEvent(net::NetLog::TYPE_DOWNLOAD_FILE_DELETED, NULL);
+
     file_util::Delete(full_path_, false);
+  }
 }
 
 void BaseFile::Finish() {
   DCHECK(BrowserThread::CurrentlyOn(BrowserThread::FILE));
 
   if (calculate_hash_)
     secure_hash_->Finish(sha256_hash_, kSha256HashLen);
 
   Close();
 }
@@ skipping 43 matching lines @@
                                       UTF8ToWide(source_url_.spec()));
 #elif defined(OS_MACOSX)
   file_metadata::AddQuarantineMetadataToFile(full_path_, source_url_,
                                              referrer_url_);
   file_metadata::AddOriginMetadataToFile(full_path_, source_url_,
                                          referrer_url_);
 #endif
 }
 
 void BaseFile::CreateFileStream() {
-  file_stream_.reset(new net::FileStream(NULL));
+  file_stream_.reset(new net::FileStream(bound_net_log_.net_log()));
+  file_stream_->SetBoundNetLogSource(bound_net_log_);
 }
 
 net::Error BaseFile::Open() {
   DCHECK(BrowserThread::CurrentlyOn(BrowserThread::FILE));
   DCHECK(!detached_);
   DCHECK(!full_path_.empty());
 
+  bound_net_log_.BeginEvent(
+      net::NetLog::TYPE_DOWNLOAD_FILE_OPENED,
+      make_scoped_refptr(
+          new download_net_logs::FileOpenedParameters(
+              full_path_.AsUTF8Unsafe(), bytes_so_far_)));
+
   // Create a new file stream if it is not provided.
   if (!file_stream_.get()) {
     CreateFileStream();
     file_stream_->EnableErrorStatistics();
     int open_result = file_stream_->Open(
         full_path_,
         base::PLATFORM_FILE_OPEN_ALWAYS | base::PLATFORM_FILE_WRITE);
-    if (open_result != net::OK) {
-      file_stream_.reset();
-      return LOG_ERROR("Open", open_result);
-    }
+    if (open_result != net::OK)
+      return AbortOpen(LOG_ERROR("Open", open_result));
 
     // We may be re-opening the file after rename. Always make sure we're
     // writing at the end of the file.
     int64 seek_result = file_stream_->Seek(net::FROM_END, 0);
-    if (seek_result < 0) {
-      file_stream_.reset();
-      return LOG_ERROR("Seek", seek_result);
-    }
+    if (seek_result < 0)
+      return AbortOpen(LOG_ERROR("Seek", seek_result));
+  } else {
+    file_stream_->SetBoundNetLogSource(bound_net_log_);
   }
 
 #if defined(OS_WIN)
   AnnotateWithSourceInformation();
 #endif
+
   return net::OK;
 }
 
+net::Error BaseFile::AbortOpen(net::Error net_error) {

[Randy Smith (Not in Mondays), 2012/02/02 20:05:54]

nit: I don't think that there's particular value to the whitespace in this
routine.

(FWIW, I actually don't think the gain in code collapsing is worth the extra
routine; you're replacing two lines + a closing brace with one in two places,
but adding four lines + a closing brace here and a declaration in the .h file.)

[ahendrickson, 2012/02/02 22:23:36]

This function is called in 2 places (now 3, but I've renamed it to ClearStream).

Additionally, whenever file_stream_ is reset to NULL I want to have the EndEvent
occur for OPEN.

I think this is valuable enough to keep it as a function.

[Randy Smith (Not in Mondays), 2012/02/03 17:02:17]

This comment had two parts, and you only responded to the second part.  Could
you adjust the routine whitespace?

(I also don't feel like you responded to the arguments in my FWIW, but I also
don't feel strongly about those arguments, so I'm not going to worry about it.)

[ahendrickson, 2012/02/03 17:29:32]

Ah, sorry about not responding to the whitespace portion of the comment -- I
simply changed it without mentioning it!

+  file_stream_.reset();
+
+  bound_net_log_.EndEvent(net::NetLog::TYPE_DOWNLOAD_FILE_OPENED, NULL);
+
+  return net_error;
+}
+
+
 void BaseFile::Close() {
   DCHECK(BrowserThread::CurrentlyOn(BrowserThread::FILE));
+
+  bound_net_log_.AddEvent(net::NetLog::TYPE_DOWNLOAD_FILE_CLOSED, NULL);
+
   if (file_stream_.get()) {
 #if defined(OS_CHROMEOS)
     // Currently we don't really care about the return value, since if it fails
     // theres not much we can do.  But we might in the future.
     file_stream_->Flush();
 #endif
     file_stream_->Close();
     file_stream_.reset();
+
+    bound_net_log_.EndEvent(net::NetLog::TYPE_DOWNLOAD_FILE_OPENED, NULL);
   }
 }
 
 std::string BaseFile::DebugString() const {
   return base::StringPrintf("{ source_url_ = \"%s\""
                             " full_path_ = \"%" PRFilePath "\""
                             " bytes_so_far_ = %" PRId64
                             " detached_ = %c }",
                             source_url_.spec().c_str(),
                             full_path_.value().c_str(),
                             bytes_so_far_,
                             detached_ ? 'T' : 'F');
 }
 
 int64 BaseFile::CurrentSpeedAtTime(base::TimeTicks current_time) const {
   base::TimeDelta diff = current_time - start_tick_;
   int64 diff_ms = diff.InMilliseconds();
   return diff_ms == 0 ? 0 : bytes_so_far() * 1000 / diff_ms;
 }
 
 int64 BaseFile::CurrentSpeed() const {
   DCHECK(BrowserThread::CurrentlyOn(BrowserThread::FILE));
   return CurrentSpeedAtTime(base::TimeTicks::Now());
 }