Added net logging to DownloadItem.

content/browser/download/download_item_impl.cc

-// Copyright (c) 2011 The Chromium Authors. All rights reserved.
+// 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/download_item_impl.h"
 
 #include <vector>
 
 #include "base/basictypes.h"
 #include "base/bind.h"
 #include "base/file_util.h"
@@ skipping 141 matching lines @@
 }
 
 // Our download table ID starts at 1, so we use 0 to represent a download that
 // has started, but has not yet had its data persisted in the table. We use fake
 // database handles in incognito mode starting at -1 and progressively getting
 // more negative.
 
 // Constructor for reading from the history service.
 DownloadItemImpl::DownloadItemImpl(Delegate* delegate,
                                    DownloadId download_id,
-                                   const DownloadPersistentStoreInfo& info)
+                                   const DownloadPersistentStoreInfo& info,
+                                   const net::BoundNetLog& bound_net_log)
     : download_id_(download_id),
       full_path_(info.path),
       url_chain_(1, info.url),
       referrer_url_(info.referrer_url),
       total_bytes_(info.total_bytes),
       received_bytes_(info.received_bytes),
       bytes_per_sec_(0),
       last_reason_(DOWNLOAD_INTERRUPT_REASON_NONE),
       start_tick_(base::TimeTicks()),
       state_(static_cast<DownloadState>(info.state)),
       start_time_(info.start_time),
       end_time_(info.end_time),
       db_handle_(info.db_handle),
       delegate_(delegate),
       is_paused_(false),
       open_when_complete_(false),
       file_externally_removed_(false),
       safety_state_(SAFE),
       auto_opened_(false),
       is_otr_(false),
       is_temporary_(false),
       all_data_saved_(false),
       opened_(info.opened),
       open_enabled_(true),
-      delegate_delayed_complete_(false) {
+      delegate_delayed_complete_(false),
+      bound_net_log_(bound_net_log) {
   delegate_->Attach();
   if (IsInProgress())
     state_ = CANCELLED;
   if (IsComplete())
     all_data_saved_ = true;
-  Init(false /* not actively downloading */);
+  Init(false /* not actively downloading */,
+       download_net_logs::SRC_HISTORY_IMPORT);
 }
 
 // Constructing for a regular download:
 DownloadItemImpl::DownloadItemImpl(
     Delegate* delegate,
     const DownloadCreateInfo& info,
     DownloadRequestHandleInterface* request_handle,
     bool is_otr)
     : state_info_(info.original_name, info.save_info.file_path,
                   info.has_user_gesture, info.transition_type,
@@ skipping 21 matching lines @@
       is_paused_(false),
       open_when_complete_(false),
       file_externally_removed_(false),
       safety_state_(SAFE),
       auto_opened_(false),
       is_otr_(is_otr),
       is_temporary_(!info.save_info.file_path.empty()),
       all_data_saved_(false),
       opened_(false),
       open_enabled_(true),
-      delegate_delayed_complete_(false) {
+      delegate_delayed_complete_(false),
+      bound_net_log_(net::BoundNetLog()) {
   delegate_->Attach();
-  Init(true /* actively downloading */);
+  Init(true /* actively downloading */,
+       download_net_logs::SRC_NEW_DOWNLOAD);
 }
 
 // Constructing for the "Save Page As..." feature:
 DownloadItemImpl::DownloadItemImpl(Delegate* delegate,
                                    const FilePath& path,
                                    const GURL& url,
                                    bool is_otr,
-                                   DownloadId download_id)
+                                   DownloadId download_id,
+                                   const net::BoundNetLog& bound_net_log)
     : request_handle_(new NullDownloadRequestHandle()),
       download_id_(download_id),
       full_path_(path),
       url_chain_(1, url),
       referrer_url_(GURL()),
       total_bytes_(0),
       received_bytes_(0),
       bytes_per_sec_(0),
       last_reason_(DOWNLOAD_INTERRUPT_REASON_NONE),
       start_tick_(base::TimeTicks::Now()),
       state_(IN_PROGRESS),
       start_time_(base::Time::Now()),
       db_handle_(DownloadItem::kUninitializedHandle),
       delegate_(delegate),
       is_paused_(false),
       open_when_complete_(false),
       file_externally_removed_(false),
       safety_state_(SAFE),
       auto_opened_(false),
       is_otr_(is_otr),
       is_temporary_(false),
       all_data_saved_(false),
       opened_(false),
       open_enabled_(true),
-      delegate_delayed_complete_(false) {
+      delegate_delayed_complete_(false),
+      bound_net_log_(bound_net_log) {
   delegate_->Attach();
-  Init(true /* actively downloading */);
+  Init(true /* actively downloading */,
+       download_net_logs::SRC_SAVE_PAGE_AS);
 }
 
 DownloadItemImpl::~DownloadItemImpl() {
   // TODO(rdsmith): Change to DCHECK after http://crbug.com/85408 resolved.
   CHECK(BrowserThread::CurrentlyOn(BrowserThread::UI));
 
   TransitionTo(REMOVING);
   STLDeleteContainerPairSecondPointers(
       external_data_map_.begin(), external_data_map_.end());
   delegate_->AssertStateConsistent(this);
@@ skipping 72 matching lines @@
 
 void DownloadItemImpl::DangerousDownloadValidated() {
   DCHECK(BrowserThread::CurrentlyOn(BrowserThread::UI));
   DCHECK_EQ(DANGEROUS, GetSafetyState());
 
   UMA_HISTOGRAM_ENUMERATION("Download.DangerousDownloadValidated",
                             GetDangerType(),
                             content::DOWNLOAD_DANGER_TYPE_MAX);
 
   safety_state_ = DANGEROUS_BUT_VALIDATED;
+
+  bound_net_log_.AddEvent(
+      net::NetLog::TYPE_DOWNLOAD_ITEM_SAFETY_STATE_UPDATED,
+      make_scoped_refptr(
+          new download_net_logs::ItemCheckedParameters(safety_state_)));
+
   UpdateObservers();
 
   delegate_->MaybeCompleteDownload(this);
 }
 
 void DownloadItemImpl::ProgressComplete(int64 bytes_so_far,
                                         const std::string& final_hash) {
   // TODO(rdsmith): Change to DCHECK after http://crbug.com/85408 resolved.
   CHECK(BrowserThread::CurrentlyOn(BrowserThread::UI));
 
@@ skipping 11 matching lines @@
 void DownloadItemImpl::UpdateProgress(int64 bytes_so_far,
                                       const std::string& hash_state) {
   hash_state_ = hash_state;
 
   received_bytes_ = bytes_so_far;
 
   // If we've received more data than we were expecting (bad server info?),
   // revert to 'unknown size mode'.
   if (received_bytes_ > total_bytes_)
     total_bytes_ = 0;
+
+  if (bound_net_log_.IsLoggingAllEvents()) {
+    bound_net_log_.AddEvent(
+        net::NetLog::TYPE_DOWNLOAD_ITEM_UPDATED,
+        make_scoped_refptr(
+            new download_net_logs::ItemUpdatedParameters(received_bytes_,
+                                                         hash_state_)));
+  }
 }
 
 // Updates from the download thread may have been posted while this download
 // was being cancelled in the UI thread, so we'll accept them unless we're
 // complete.
 void DownloadItemImpl::UpdateProgress(int64 bytes_so_far,
                                       int64 bytes_per_sec,
                                       const std::string& hash_state) {
   // TODO(rdsmith): Change to DCHECK after http://crbug.com/85408 resolved.
   CHECK(BrowserThread::CurrentlyOn(BrowserThread::UI));
@@ skipping 89 matching lines @@
 
     auto_opened_ = true;
     UpdateObservers();
   }
 }
 
 void DownloadItemImpl::TransitionTo(DownloadState new_state) {
   if (state_ == new_state)
     return;
 
+  DownloadState old_state = state_;
   state_ = new_state;
+
+  switch (state_) {
+    case COMPLETE:
+      bound_net_log_.AddEvent(
+          net::NetLog::TYPE_DOWNLOAD_ITEM_FINISHED,
+          make_scoped_refptr(
+              new download_net_logs::ItemFinishedParameters(received_bytes_,
+                                                            hash_)));
+      break;
+    case INTERRUPTED:
+      bound_net_log_.AddEvent(
+          net::NetLog::TYPE_DOWNLOAD_ITEM_INTERRUPTED,
+          make_scoped_refptr(
+              new download_net_logs::ItemInterruptedParameters(last_reason_,
+                                                               received_bytes_,
+                                                               hash_state_)));
+      break;
+    case CANCELLED:
+      bound_net_log_.AddEvent(
+          net::NetLog::TYPE_DOWNLOAD_ITEM_CANCELED,
+          make_scoped_refptr(
+              new download_net_logs::ItemCanceledParameters(received_bytes_,
+                                                            hash_state_)));
+      break;
+    default:
+      break;
+  }
+
   UpdateObservers();
+
+  bool is_done = (state_ != IN_PROGRESS);
+  bool was_done = (old_state != IN_PROGRESS);
+  if (is_done && !was_done)
+    bound_net_log_.EndEvent(net::NetLog::TYPE_DOWNLOAD_ITEM_ACTIVE, NULL);
 }
 
 void DownloadItemImpl::UpdateSafetyState() {
   SafetyState updated_value = state_info_.IsDangerous() ?
     DownloadItem::DANGEROUS : DownloadItem::SAFE;
   if (updated_value != safety_state_) {
     safety_state_ = updated_value;
+
+    bound_net_log_.AddEvent(
+        net::NetLog::TYPE_DOWNLOAD_ITEM_SAFETY_STATE_UPDATED,
+        make_scoped_refptr(
+            new download_net_logs::ItemCheckedParameters(safety_state_)));
+
     UpdateObservers();
   }
 }
 
 void DownloadItemImpl::UpdateTarget() {
   // TODO(rdsmith): Change to DCHECK after http://crbug.com/85408 resolved.
   CHECK(BrowserThread::CurrentlyOn(BrowserThread::UI));
 
   if (state_info_.target_name.value().empty())
     state_info_.target_name = full_path_.BaseName();
@@ skipping 92 matching lines @@
 }
 
 void DownloadItemImpl::Rename(const FilePath& full_path) {
   // TODO(rdsmith): Change to DCHECK after http://crbug.com/85408 resolved.
   CHECK(BrowserThread::CurrentlyOn(BrowserThread::UI));
 
   VLOG(20) << __FUNCTION__ << "()"
            << " full_path = \"" << full_path.value() << "\""
            << " " << DebugString(true);
   DCHECK(!full_path.empty());
+
+  bound_net_log_.AddEvent(
+      net::NetLog::TYPE_DOWNLOAD_ITEM_RENAMED,
+      make_scoped_refptr(
+          new download_net_logs::ItemRenamedParameters(
+              full_path_.AsUTF8Unsafe(), full_path.AsUTF8Unsafe())));
+
   full_path_ = full_path;
 }
 
 void DownloadItemImpl::TogglePause() {
   // TODO(rdsmith): Change to DCHECK after http://crbug.com/85408 resolved.
   CHECK(BrowserThread::CurrentlyOn(BrowserThread::UI));
 
   DCHECK(IsInProgress());
   if (is_paused_)
     request_handle_->ResumeRequest();
@@ skipping 167 matching lines @@
 void DownloadItemImpl::OffThreadCancel(DownloadFileManager* file_manager) {
   DCHECK(BrowserThread::CurrentlyOn(BrowserThread::UI));
   request_handle_->CancelRequest();
 
   BrowserThread::PostTask(
       BrowserThread::FILE, FROM_HERE,
       base::Bind(&DownloadFileManager::CancelDownload,
                  file_manager, download_id_));
 }
 
-void DownloadItemImpl::Init(bool active) {
+void DownloadItemImpl::Init(bool active,
+                            download_net_logs::DownloadType download_type) {
   // TODO(rdsmith): Change to DCHECK after http://crbug.com/85408 resolved.
   CHECK(BrowserThread::CurrentlyOn(BrowserThread::UI));
 
   UpdateTarget();
   if (active)
     download_stats::RecordDownloadCount(download_stats::START_COUNT);
+
+  bound_net_log_.BeginEvent(
+      net::NetLog::TYPE_DOWNLOAD_ITEM_ACTIVE,
+      make_scoped_refptr(new download_net_logs::ItemActivatedParameters(
+          download_type,
+          download_id_.local(),
+          GetOriginalUrl().spec(),
+          GetURL().spec(),
+          full_path_.AsUTF8Unsafe(),
+          suggested_filename_,
+          safety_state_,
+          received_bytes_)));
+
+  // If this is not an active download, end the ACTIVE event now.
+  if (!active) {
+    bound_net_log_.AddEvent(
+        net::NetLog::TYPE_DOWNLOAD_ITEM_IN_HISTORY,
+        make_scoped_refptr(
+            new download_net_logs::ItemInHistoryParameters(db_handle_)));
+
+    bound_net_log_.EndEvent(net::NetLog::TYPE_DOWNLOAD_ITEM_ACTIVE, NULL);

[Randy Smith (Not in Mondays), 2012/02/05 23:49:15]

Do we want to log the probe to make sure the file is still there for history
downloads?

[ahendrickson, 2012/02/06 21:39:20]

Hmm, that's not strictly part of the download process . . .

It would also mean instrumenting DownloadManagerImpl with DOWNLOAD_ITEM* event
types, including an end for DOWNLOAD_ITEM_ACTIVE.  The latter has a bit of a bad
smell to me.

I'm not completely against it, but it seems worthy of a separate CL.

[Randy Smith (Not in Mondays), 2012/02/06 22:34:59]

I'm happy with it being in a separate CL, but the go/no-go decision should be
primarily based on "Do we expect this to be useful in debugging incoming
issues?" (secondarily on how much hassle it'll be to put in.)  I.e. "Not part of
the download process" doesn't have a lot of weight for me :-}.

[ahendrickson, 2012/02/07 00:16:19]

Per our conversation, I see how it could be useful.

I'll mark it for a future CL.

+  }
+
   VLOG(20) << __FUNCTION__ << "() " << DebugString(true);
 }
 
 // TODO(ahendrickson) -- Move |INTERRUPTED| from |IsCancelled()| to
 // |IsPartialDownload()|, when resuming interrupted downloads is implemented.
 bool DownloadItemImpl::IsPartialDownload() const {
   return (state_ == IN_PROGRESS);
 }
 
 bool DownloadItemImpl::IsInProgress() const {
@@ skipping 109 matching lines @@
 }
 const std::string& DownloadItemImpl::GetHash() const { return hash_; }
 int64 DownloadItemImpl::GetReceivedBytes() const { return received_bytes_; }
 const std::string& DownloadItemImpl::GetHashState() const {
   return hash_state_;
 }
 int32 DownloadItemImpl::GetId() const { return download_id_.local(); }
 DownloadId DownloadItemImpl::GetGlobalId() const { return download_id_; }
 base::Time DownloadItemImpl::GetStartTime() const { return start_time_; }
 base::Time DownloadItemImpl::GetEndTime() const { return end_time_; }
-void DownloadItemImpl::SetDbHandle(int64 handle) { db_handle_ = handle; }
+
+void DownloadItemImpl::SetDbHandle(int64 handle) {
+  db_handle_ = handle;
+
+  bound_net_log_.AddEvent(
+      net::NetLog::TYPE_DOWNLOAD_ITEM_IN_HISTORY,
+      make_scoped_refptr(
+          new download_net_logs::ItemInHistoryParameters(db_handle_)));
+}
+
 int64 DownloadItemImpl::GetDbHandle() const { return db_handle_; }
 bool DownloadItemImpl::IsPaused() const { return is_paused_; }
 bool DownloadItemImpl::GetOpenWhenComplete() const {
   return open_when_complete_;
 }
 void DownloadItemImpl::SetOpenWhenComplete(bool open) {
   open_when_complete_ = open;
 }
 bool DownloadItemImpl::GetFileExternallyRemoved() const {
   return file_externally_removed_;
@@ skipping 40 matching lines @@
   std::map<const void*, ExternalData*>::iterator it =
       external_data_map_.find(key);
 
   if (it == external_data_map_.end()) {
     external_data_map_[key] = data;
   } else if (it->second != data) {
     delete it->second;
     it->second = data;
   }
 }