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);
+  }
+
+  if (bound_net_log_.IsLoggingAllEvents()) {
+    bound_net_log_.AddEvent(
+        net::NetLog::TYPE_DOWNLOAD_FILE_WRITTEN,

[mmenke, 2012/02/04 05:49:45]

nit:  Since this is logged before the write, which might well fail, suggest you
call this TYPE_DOWNLOAD_FILE_WRITE.  Suggest the same for other events in this
file.

[ahendrickson, 2012/02/04 19:27:56]

I'd prefer not to.

+        make_scoped_refptr(new net::NetLogIntegerParameter(
+            "byte_count", data_len)));
+  }
 
   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_CANCELLED, NULL);
+
   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 ClearStream(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 ClearStream(LOG_ERROR("Seek", seek_result));
+  } else {
+    file_stream_->SetBoundNetLogSource(bound_net_log_);
   }
 
 #if defined(OS_WIN)
   AnnotateWithSourceInformation();
 #endif
+
   return net::OK;
 }
 
 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();
+    ClearStream(net::OK);
   }
 }
 
+net::Error BaseFile::ClearStream(net::Error net_error) {
+  // This should only be called when we have a stream.
+  DCHECK(file_stream_.get() != NULL);
+  file_stream_.reset();
+  bound_net_log_.EndEvent(net::NetLog::TYPE_DOWNLOAD_FILE_OPENED, NULL);
+  return net_error;
+}
+
 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());
 }