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()) {
   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_CHECKED,
+      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;
+
+  bound_net_log_.AddEvent(

[mmenke, 2012/02/03 17:59:45]

nit:  If this is called a lot, should give it the "if
(bound_net_log_.IsLoggingAllEvents())" / early "return ACTION_NONE;" treatment.

[ahendrickson, 2012/02/04 05:24:04]

It's called roughly twice a second, which doesn't seem excessive to me.  What do
you think?

[mmenke, 2012/02/04 05:35:28]

Given that the memory from a download's passive log collector could stay around
for weeks, I'd feel more comfortable with the check in.

[mmenke, 2012/02/04 05:57:04]

Actually, forgot we had a max number of entries we track per log...Which is
currently 30.  I still don't like it, but suppose I can live with it.  It's the
"hash_state_" string that bothers me the most...All those scary hashes lurking
around in memory...

[ahendrickson, 2012/02/04 23:20:57]

You've convinced me!

Filtered these events out in passive mode.

+      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)

[Randy Smith (Not in Mondays), 2012/02/03 18:05:30]

nit: I think this would be easier to read if you collapsed the bools into the
test.

[ahendrickson, 2012/02/04 05:24:04]

Really?  I took them out because I thought *this* way was easier to read!
Specifically, the names of the variables seem more descriptive to me.

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

I think it depends on how you're thinking about it--I was having to translate
"is_done && !was_done" into "transitioned out of IN_PROGRESS".  And all other
things being equal I prefer fewer lines of code.  But I guess it's a matter of
taste. 

+    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_CHECKED,

[Randy Smith (Not in Mondays), 2012/02/03 18:23:37]

If you want to say "SAFETY_STATE_UPDATED", I'm good with that.  But user
validation doesn't seem like a form of checking, so this name seems to specific
to me.

[ahendrickson, 2012/02/04 05:24:04]

Agreed.  Changed the name.

+        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,

[Randy Smith (Not in Mondays), 2012/02/03 18:23:37]

nit: I'm a bit worried about the confusion of terminology in these couple of
lines (if (active) above and the name of this event).  Can you either change the
name or comment it to resolve the confusion if someone comes to this code
without the perspective of reviewing this CL?

[ahendrickson, 2012/02/04 05:24:04]

Commented.

+      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 (!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;
   }
 }