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,
+                                   net::NetLog* 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_(net::BoundNetLog::Make(net_log,
+                                            net::NetLog::SOURCE_DOWNLOAD)) {
   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()) {

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

Put a TODO comment in here explaining why we're not creating the bound_net_log_
yet.  (I'll note that IMO the "right" way to do this is to put a NetLog in this
constructor as well and create a BNL based on that NetLog, then change that in
the next CL.  But that borders being pedantic for its own sake.)

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

Done.

[Randy Smith (Not in Mondays), 2012/02/07 15:09:45]

I don't feel like that comment explains why; do you?

Whenever you write a comment (or a document) it's worthwhile thinking about who
you're writing the comment for.  In general, I think of comments as being
primarily for people who are competent, but a couple of notches less familiar
with the code than the person writing the code.  For TODO comments, I think of
the author as someone who has to implement the TODO if the original author isn't
available (though there may be debate on this one--I think some people write
them as "notes to self").  

Either way, I'd like this comment to say a bit more as to why we can't create
one.  Even something like "The next CL will create the BoundNetLog based on the
NetLog associated with the URLRequest's BoundNetLog passed in the info struct,
but we don't yet have that information, so we can't create it yet."   would do. 
(Though the awkwardness of that comment, having to refer to future CL
implementation plans to justify the current CL, is why I was having the pull to
just create the BoundNetLog() from a passed in NetLog and and change it in the
next CL in my original comment.)

[ahendrickson, 2012/02/07 17:18:35]

Changed the comment.

   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,
+                                   net::NetLog* 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_(net::BoundNetLog::Make(net_log,
+                                            net::NetLog::SOURCE_DOWNLOAD)) {
   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_)));
+  }
 }
 
 // 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);
+
+  // full_path_ works for History and Save As versions.
+  std::string file_name = full_path_.AsUTF8Unsafe();
+  if (file_name.empty())
+    file_name = suggested_filename_;  // From 'download' attribute of anchor.
+  if (file_name.empty())
+    file_name = GetURL().ExtractFileName();  // URL file name.
+
+  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(),
+          file_name,
+          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);
+  }
+
   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;
   }
 }