Added net logging to DownloadItem.

content/browser/download/download_item_impl.cc

Index: content/browser/download/download_item_impl.cc
diff --git a/content/browser/download/download_item_impl.cc b/content/browser/download/download_item_impl.cc
index aeea3c9debb4d828bc4afc0aeecd042b793a0285..fd8a622a9279ef07664a089bf7ab46b47ae1fc01 100644
--- a/content/browser/download/download_item_impl.cc
+++ b/content/browser/download/download_item_impl.cc
@@ -1,4 +1,4 @@
-// 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.
 
@@ -160,7 +160,8 @@ void DownloadItemImpl::Delegate::Detach() {
 // 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),
@@ -185,13 +186,16 @@ DownloadItemImpl::DownloadItemImpl(Delegate* delegate,
       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:
@@ -233,9 +237,11 @@ DownloadItemImpl::DownloadItemImpl(
       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:
@@ -243,7 +249,8 @@ 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),
@@ -268,9 +275,12 @@ DownloadItemImpl::DownloadItemImpl(Delegate* delegate,
       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() {
@@ -363,6 +373,12 @@ void DownloadItemImpl::DangerousDownloadValidated() {
                             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);
@@ -394,6 +410,12 @@ void DownloadItemImpl::UpdateProgress(int64 bytes_so_far,
   // 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
@@ -503,8 +525,42 @@ 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() {
@@ -512,6 +568,12 @@ void DownloadItemImpl::UpdateSafetyState() {
     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();
   }
 }
@@ -624,6 +686,13 @@ void DownloadItemImpl::Rename(const FilePath& full_path) {
            << " 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;
 }
 
@@ -811,13 +880,36 @@ void DownloadItemImpl::OffThreadCancel(DownloadFileManager* file_manager) {
                  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);
 }
 
@@ -947,7 +1039,16 @@ 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 {