Logging downloads.

BUG=None
TEST=None.

Review URL: http://codereview.chromium.org/4222004

git-svn-id: svn://svn.chromium.org/chrome/trunk/src@67322 0039d316-1c4b-4281-b951-d872f2087c98

8 files changed, 139 insertions, 2 deletions

diff --git a/chrome/browser/download/base_file.cc b/chrome/browser/download/base_file.cc
index bed184c..2d89159 100644
--- a/chrome/browser/download/base_file.cc
+++ b/chrome/browser/download/base_file.cc
@@ -6,6 +6,7 @@
 
 #include "base/file_util.h"
 #include "base/logging.h"
+#include "base/stringprintf.h"
 #include "net/base/file_stream.h"
 #include "net/base/net_errors.h"
 #include "chrome/browser/browser_thread.h"
@@ -194,3 +195,9 @@ void BaseFile::Close() {
     file_stream_.reset();
   }
 }
+
+std::string BaseFile::DebugString() const {
+  return base::StringPrintf("{ source_url_ = \"%s\" full_path_ = \"%s\" }",
+                            source_url_.spec().c_str(),
+                            full_path_.value().c_str());
+}
diff --git a/chrome/browser/download/base_file.h b/chrome/browser/download/base_file.h
index 6c57165..ffa63cc 100644
--- a/chrome/browser/download/base_file.h
+++ b/chrome/browser/download/base_file.h
@@ -6,6 +6,8 @@
 #define CHROME_BROWSER_DOWNLOAD_BASE_FILE_H_
 #pragma once
 
+#include <string>
+
 #include "base/file_path.h"
 #include "base/linked_ptr.h"
 #include "chrome/browser/power_save_blocker.h"
@@ -51,6 +53,8 @@ class BaseFile {
   bool in_progress() const { return file_stream_ != NULL; }
   int64 bytes_so_far() const { return bytes_so_far_; }
 
+  virtual std::string DebugString() const;
+
  protected:
   bool Open();
   void Close();
diff --git a/chrome/browser/download/download_file.cc b/chrome/browser/download/download_file.cc
index 4495fe9..f9bcd1b 100644
--- a/chrome/browser/download/download_file.cc
+++ b/chrome/browser/download/download_file.cc
@@ -4,7 +4,10 @@
 
 #include "chrome/browser/download/download_file.h"
 
+#include <string>
+
 #include "base/file_util.h"
+#include "base/stringprintf.h"
 #include "chrome/browser/browser_thread.h"
 #include "chrome/browser/download/download_manager.h"
 #include "chrome/browser/download/download_util.h"
@@ -49,3 +52,18 @@ DownloadManager* DownloadFile::GetDownloadManager() {
   DCHECK(BrowserThread::CurrentlyOn(BrowserThread::FILE));
   return download_manager_.get();
 }
+
+std::string DownloadFile::DebugString() const {
+  return base::StringPrintf("{"
+                            " full_path_ = " "\"%s\""
+                            " id_ = " "%d"
+                            " child_id_ = " "%d"
+                            " request_id_ = " "%d"
+                            " Base File = %s"
+                            " }",
+                            full_path_.value().c_str(),
+                            id_,
+                            child_id_,
+                            request_id_,
+                            BaseFile::DebugString().c_str());
+}
diff --git a/chrome/browser/download/download_file.h b/chrome/browser/download/download_file.h
index 46ba40d..fb00f06 100644
--- a/chrome/browser/download/download_file.h
+++ b/chrome/browser/download/download_file.h
@@ -6,6 +6,8 @@
 #define CHROME_BROWSER_DOWNLOAD_DOWNLOAD_FILE_H_
 #pragma once
 
+#include <string>
+
 #include "base/basictypes.h"
 #include "base/ref_counted.h"
 #include "chrome/browser/download/base_file.h"
@@ -35,6 +37,8 @@ class DownloadFile : public BaseFile {
   int id() const { return id_; }
   DownloadManager* GetDownloadManager();
 
+  virtual std::string DebugString() const;
+
  private:
   // The unique identifier for this download, assigned at creation by
   // the DownloadFileManager for its internal record keeping.
diff --git a/chrome/browser/download/download_file_manager.cc b/chrome/browser/download/download_file_manager.cc
index 86346a8..e33003a 100644
--- a/chrome/browser/download/download_file_manager.cc
+++ b/chrome/browser/download/download_file_manager.cc
@@ -5,6 +5,7 @@
 #include "chrome/browser/download/download_file_manager.h"
 
 #include "base/file_util.h"
+#include "base/logging.h"
 #include "base/stl_util-inl.h"
 #include "base/task.h"
 #include "base/utf_string_conversions.h"
@@ -76,6 +77,7 @@ void DownloadFileManager::OnShutdown() {
 
 void DownloadFileManager::CreateDownloadFile(
     DownloadCreateInfo* info, DownloadManager* download_manager) {
+  VLOG(20) << __FUNCTION__ << "()" << " info = " << info->DebugString();
   DCHECK(BrowserThread::CurrentlyOn(BrowserThread::FILE));
 
   scoped_ptr<DownloadFile> download_file(
@@ -203,6 +205,7 @@ void DownloadFileManager::UpdateDownload(int id, DownloadBuffer* buffer) {
 }
 
 void DownloadFileManager::OnResponseCompleted(int id, DownloadBuffer* buffer) {
+  VLOG(20) << __FUNCTION__ << "()" << " id = " << id;
   DCHECK(BrowserThread::CurrentlyOn(BrowserThread::FILE));
   delete buffer;
   DownloadFileMap::iterator it = downloads_.find(id);
@@ -235,10 +238,13 @@ void DownloadFileManager::OnResponseCompleted(int id, DownloadBuffer* buffer) {
 // run on the download thread. Since this message has been sent from the UI
 // thread, the download may have already completed and won't exist in our map.
 void DownloadFileManager::CancelDownload(int id) {
+  VLOG(20) << __FUNCTION__ << "()" << " id = " << id;
   DCHECK(BrowserThread::CurrentlyOn(BrowserThread::FILE));
   DownloadFileMap::iterator it = downloads_.find(id);
   if (it != downloads_.end()) {
     DownloadFile* download = it->second;
+    VLOG(20) << __FUNCTION__ << "()"
+             << " download = " << download->DebugString();
     download->Cancel();
 
     if (download->path_renamed()) {
@@ -280,12 +286,15 @@ void DownloadFileManager::OnDownloadManagerShutdown(DownloadManager* manager) {
 void DownloadFileManager::OnIntermediateDownloadName(
     int id, const FilePath& full_path, DownloadManager* download_manager)
 {
+  VLOG(20) << __FUNCTION__ << "()" << " id = " << id
+           << " full_path = \"" << full_path.value() << "\"";
   DCHECK(BrowserThread::CurrentlyOn(BrowserThread::FILE));
   DownloadFileMap::iterator it = downloads_.find(id);
   if (it == downloads_.end())
     return;
 
   DownloadFile* download = it->second;
+  VLOG(20) << __FUNCTION__ << "()" << " download = " << download->DebugString();
   if (!download->Rename(full_path, false /* is_final_rename */)) {
     // Error. Between the time the UI thread generated 'full_path' to the time
     // this code runs, something happened that prevents us from renaming.
@@ -306,12 +315,15 @@ void DownloadFileManager::OnIntermediateDownloadName(
 void DownloadFileManager::OnFinalDownloadName(
     int id, const FilePath& full_path, bool need_delete_crdownload,
     DownloadManager* download_manager) {
+  VLOG(20) << __FUNCTION__ << "()" << " id = " << id
+           << " full_path = \"" << full_path.value() << "\""
+           << " need_delete_crdownload = " << need_delete_crdownload;
   DCHECK(BrowserThread::CurrentlyOn(BrowserThread::FILE));
 
   DownloadFile* download = GetDownloadFile(id);
   if (!download)
     return;
-
+  VLOG(20) << __FUNCTION__ << "()" << " download = " << download->DebugString();
   if (download->Rename(full_path, true /* is_final_rename */)) {
 #if defined(OS_MACOSX)
     // Done here because we only want to do this once; see
diff --git a/chrome/browser/download/download_item.cc b/chrome/browser/download/download_item.cc
index 886903f..8cd733e 100644
--- a/chrome/browser/download/download_item.cc
+++ b/chrome/browser/download/download_item.cc
@@ -5,8 +5,10 @@
 #include "chrome/browser/download/download_item.h"
 
 #include "app/l10n_util.h"
+#include "base/basictypes.h"
 #include "base/file_util.h"
 #include "base/logging.h"
+#include "base/stringprintf.h"
 #include "base/timer.h"
 #include "base/utf_string_conversions.h"
 #include "net/base/net_util.h"
@@ -36,6 +38,36 @@ void DeleteDownloadedFile(const FilePath& path) {
     file_util::Delete(path, false);
 }
 
+const char* DebugSafetyStateString(DownloadItem::SafetyState state) {
+  switch (state) {
+    case DownloadItem::SAFE:
+      return "SAFE";
+    case DownloadItem::DANGEROUS:
+      return "DANGEROUS";
+    case DownloadItem::DANGEROUS_BUT_VALIDATED:
+      return "DANGEROUS_BUT_VALIDATED";
+    default:
+      NOTREACHED() << "Unknown safety state " << state;
+      return "unknown";
+  };
+}
+
+const char* DebugDownloadStateString(DownloadItem::DownloadState state) {
+  switch (state) {
+    case DownloadItem::IN_PROGRESS:
+      return "IN_PROGRESS";
+    case DownloadItem::COMPLETE:
+      return "COMPLETE";
+    case DownloadItem::CANCELLED:
+      return "CANCELLED";
+    case DownloadItem::REMOVING:
+      return "REMOVING";
+    default:
+      NOTREACHED() << "Unknown download state " << state;
+      return "unknown";
+  };
+}
+
 }  // namespace
 
 // Constructor for reading from the history service.
@@ -251,6 +283,7 @@ void DownloadItem::Update(int64 bytes_so_far) {
 
 // Triggered by a user action.
 void DownloadItem::Cancel(bool update_history) {
+  VLOG(20) << __FUNCTION__ << "()" << " download = " << DebugString(true);
   if (state_ != IN_PROGRESS) {
     // Small downloads might be complete before this method has a chance to run.
     return;
@@ -443,3 +476,23 @@ void DownloadItem::Init(bool start_timer) {
   if (start_timer)
     StartProgressTimer();
 }
+
+std::string DownloadItem::DebugString(bool verbose) const {
+  std::string description =
+      base::StringPrintf("{ url = \"%s\"", url().spec().c_str());
+
+  if (verbose) {
+    description += base::StringPrintf(
+        " target_name_ = " "\"%s\""
+        " full_path = " "\"%s\""
+        " safety_state = " "%s",
+        target_name_.value().c_str(),
+        full_path().value().c_str(),
+        DebugSafetyStateString(safety_state()));
+  }
+
+  description += base::StringPrintf(" state = %s }",
+                                    DebugDownloadStateString(state()));
+
+  return description;
+}
diff --git a/chrome/browser/download/download_item.h b/chrome/browser/download/download_item.h
index 942d16a..4f963fb 100644
--- a/chrome/browser/download/download_item.h
+++ b/chrome/browser/download/download_item.h
@@ -222,6 +222,8 @@ class DownloadItem {
     return target_name_ != full_path_.BaseName();
   }
 
+  std::string DebugString(bool verbose) const;
+
  private:
   void Init(bool start_timer);
 
diff --git a/chrome/browser/download/download_manager.cc b/chrome/browser/download/download_manager.cc
index 3211507..746dbed 100644
--- a/chrome/browser/download/download_manager.cc
+++ b/chrome/browser/download/download_manager.cc
@@ -67,6 +67,8 @@ DownloadManager::~DownloadManager() {
 }
 
 void DownloadManager::Shutdown() {
+  VLOG(20) << __FUNCTION__ << "()"
+           << " shutdown_needed_ = " << shutdown_needed_;
   if (!shutdown_needed_)
     return;
   shutdown_needed_ = false;
@@ -329,6 +331,7 @@ void DownloadManager::CheckIfSuggestedPathExists(DownloadCreateInfo* info,
   FilePath dir = info->suggested_path.DirName();
   FilePath filename = info->suggested_path.BaseName();
   if (!file_util::PathIsWritable(dir)) {
+    VLOG(1) << "Unable to write to directory \"" << dir.value() << "\"";
     info->prompt_user_for_save_location = true;
     PathService::Get(chrome::DIR_USER_DOCUMENTS, &info->suggested_path);
     info->suggested_path = info->suggested_path.Append(filename);
@@ -367,6 +370,8 @@ void DownloadManager::CheckIfSuggestedPathExists(DownloadCreateInfo* info,
       info->path_uniquifier = 0;
     } else if (info->path_uniquifier == -1) {
       // We failed to find a unique path.  We have to prompt the user.
+      VLOG(1) << "Unable to find a unique path for suggested path \""
+                   << info->suggested_path.value() << "\"";
       info->prompt_user_for_save_location = true;
     }
   }
@@ -391,6 +396,7 @@ void DownloadManager::CheckIfSuggestedPathExists(DownloadCreateInfo* info,
 }
 
 void DownloadManager::OnPathExistenceAvailable(DownloadCreateInfo* info) {
+  VLOG(20) << __FUNCTION__ << "()" << " info = " << info->DebugString();
   DCHECK(BrowserThread::CurrentlyOn(BrowserThread::UI));
   DCHECK(info);
 
@@ -436,6 +442,10 @@ void DownloadManager::CreateDownloadItem(DownloadCreateInfo* info,
   bool download_finished = ContainsKey(pending_finished_downloads_,
                                        info->download_id);
 
+  VLOG(20) << __FUNCTION__ << "()"
+           << " download_finished = " << download_finished
+           << " info = " << info->DebugString();
+
   if (download_finished || info->is_dangerous) {
     // The download has already finished or the download is not safe.
     // We can now rename the file to its final name (or its tentative name
@@ -481,6 +491,8 @@ void DownloadManager::UpdateDownload(int32 download_id, int64 size) {
 }
 
 void DownloadManager::OnAllDataSaved(int32 download_id, int64 size) {
+  VLOG(20) << __FUNCTION__ << "()" << " download_id = " << download_id
+           << " size = " << size;
   DownloadMap::iterator it = in_progress_.find(download_id);
   if (it == in_progress_.end()) {
     // The download is done, but the user hasn't selected a final location for
@@ -491,16 +503,25 @@ void DownloadManager::OnAllDataSaved(int32 download_id, int64 size) {
         pending_finished_downloads_.find(download_id);
     DCHECK(erase_it == pending_finished_downloads_.end());
     pending_finished_downloads_[download_id] = size;
+    VLOG(20) << __FUNCTION__ << "()" << " Added download_id = " << download_id
+             << " to pending_finished_downloads_";
     return;
   }
 
   // Remove the id from the list of pending ids.
   PendingFinishedMap::iterator erase_it =
       pending_finished_downloads_.find(download_id);
-  if (erase_it != pending_finished_downloads_.end())
+  if (erase_it != pending_finished_downloads_.end()) {
     pending_finished_downloads_.erase(erase_it);
+    VLOG(20) << __FUNCTION__ << "()" << " Removed download_id = " << download_id
+             << " from pending_finished_downloads_";
+  }
 
   DownloadItem* download = it->second;
+
+  VLOG(20) << __FUNCTION__ << "()"
+           << " download = " << download->DebugString(true);
+
   download->OnAllDataSaved(size);
 
   // Clean up will happen when the history system create callback runs if we
@@ -537,6 +558,8 @@ void DownloadManager::OnAllDataSaved(int32 download_id, int64 size) {
 
 void DownloadManager::DownloadRenamedToFinalName(int download_id,
                                                  const FilePath& full_path) {
+  VLOG(20) << __FUNCTION__ << "()" << " download_id = " << download_id
+           << " full_path = \"" << full_path.value() << "\"";
   DCHECK(BrowserThread::CurrentlyOn(BrowserThread::UI));
   DownloadItem* item = GetDownloadItem(download_id);
   if (!item)
@@ -545,6 +568,8 @@ void DownloadManager::DownloadRenamedToFinalName(int download_id,
 }
 
 void DownloadManager::DownloadFinished(DownloadItem* download) {
+  VLOG(20) << __FUNCTION__ << "()"
+           << " download = " << download->DebugString(true);
   DCHECK(BrowserThread::CurrentlyOn(BrowserThread::UI));
 
   // If this was a dangerous download, it has now been approved and must be
@@ -588,6 +613,10 @@ void DownloadManager::DangerousDownloadRenamed(int64 download_handle,
                                                bool success,
                                                const FilePath& new_path,
                                                int new_path_uniquifier) {
+  VLOG(20) << __FUNCTION__ << "()" << " download_handle = " << download_handle
+           << " success = " << success
+           << " new_path = \"" << new_path.value() << "\""
+           << " new_path_uniquifier = " << new_path_uniquifier;
   DownloadMap::iterator it = downloads_.find(download_handle);
   if (it == downloads_.end()) {
     NOTREACHED();
@@ -613,6 +642,9 @@ void DownloadManager::DownloadCancelled(int32 download_id) {
     return;
   DownloadItem* download = it->second;
 
+  VLOG(20) << __FUNCTION__ << "()" << " download_id = " << download_id
+           << " download = " << download->DebugString(true);
+
   // Clean up will happen when the history system create callback runs if we
   // don't have a valid db_handle yet.
   if (download->db_handle() != DownloadHistory::kUninitializedHandle) {
@@ -892,6 +924,8 @@ void DownloadManager::OnQueryDownloadEntriesComplete(
     DownloadItem* download = new DownloadItem(this, entries->at(i));
     DCHECK(!ContainsKey(downloads_, download->db_handle()));
     downloads_[download->db_handle()] = download;
+    VLOG(20) << __FUNCTION__ << "()" << i << ">"
+             << " download = " << download->DebugString(true);
   }
   NotifyModelChanged();
 }
@@ -906,6 +940,9 @@ void DownloadManager::OnCreateDownloadEntryComplete(
   DCHECK(it != in_progress_.end());
 
   DownloadItem* download = it->second;
+  VLOG(20) << __FUNCTION__ << "()" << " db_handle = " << db_handle
+           << " download_id = " << info.download_id
+           << " download = " << download->DebugString(true);
 
   // It's not immediately obvious, but HistoryBackend::CreateDownload() can
   // call this function with an invalid |db_handle|. For instance, this can