Add some VLOG debugging info for extensions updating.

chrome/browser/extensions/extension_updater.cc

 // Copyright (c) 2011 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 "chrome/browser/extensions/extension_updater.h"
 
 #include <algorithm>
 #include <set>
 
 #include "base/bind.h"
@@ skipping 579 matching lines @@
   STLDeleteElements(&manifests_pending_);
   manifests_pending_.clear();
   extensions_pending_.clear();
 }
 
 void ExtensionUpdater::OnURLFetchComplete(const content::URLFetcher* source) {
   // Stop() destroys all our URLFetchers, which means we shouldn't be
   // called after Stop() is called.
   DCHECK(alive_);
 
+  VLOG(2) << source->GetResponseCode() << " " << source->GetURL();
+
   if (source == manifest_fetcher_.get()) {
     std::string data;
     source->GetResponseAsString(&data);
     OnManifestFetchComplete(source->GetURL(),
                             source->GetStatus(),
                             source->GetResponseCode(),
                             data);
   } else if (source == extension_fetcher_.get()) {
     OnCRXFetchComplete(source,
                        source->GetURL(),
@@ skipping 72 matching lines @@
                           OnParseUpdateManifestSucceeded)
       IPC_MESSAGE_HANDLER(ChromeUtilityHostMsg_ParseUpdateManifest_Failed,
                           OnParseUpdateManifestFailed)
       IPC_MESSAGE_UNHANDLED(handled = false)
     IPC_END_MESSAGE_MAP()
     return handled;
   }
 
   void OnParseUpdateManifestSucceeded(
       const UpdateManifest::Results& results) {
+    VLOG(2) << "parsing manifest succeeded (" << fetch_data_->full_url()
+            << ")";
     DCHECK(BrowserThread::CurrentlyOn(BrowserThread::UI));
     if (!updater_) {
       return;
     }
     updater_->HandleManifestResults(*fetch_data_, &results);
   }
 
   void OnParseUpdateManifestFailed(const std::string& error_message) {
+    VLOG(2) << "parsing manifest failed (" << fetch_data_->full_url() << ")";
     DCHECK(BrowserThread::CurrentlyOn(BrowserThread::UI));
     if (!updater_) {
       return;
     }
     LOG(WARNING) << "Error parsing update manifest:\n" << error_message;
     updater_->HandleManifestResults(*fetch_data_, NULL);
   }
 
  private:
   ~SafeManifestParser() {
@@ skipping 11 matching lines @@
 
 void ExtensionUpdater::OnManifestFetchComplete(
     const GURL& url,
     const net::URLRequestStatus& status,
     int response_code,
     const std::string& data) {
   // We want to try parsing the manifest, and if it indicates updates are
   // available, we want to fire off requests to fetch those updates.
   if (status.status() == net::URLRequestStatus::SUCCESS &&
       (response_code == 200 || (url.SchemeIsFile() && data.length() > 0))) {
+    VLOG(2) << "beginning manifest parse for " << url;
     scoped_refptr<SafeManifestParser> safe_parser(
         new SafeManifestParser(data, current_manifest_fetch_.release(),
                                weak_ptr_factory_.GetWeakPtr()));
     safe_parser->Start();
   } else {
     // TODO(asargent) Do exponential backoff here. (http://crbug.com/12546).
     VLOG(1) << "Failed to fetch manifest '" << url.possibly_invalid_spec()
             << "' response code:" << response_code;
     RemoveFromInProgress(current_manifest_fetch_->extension_ids());
   }
@@ skipping 131 matching lines @@
     extensions_pending_.pop_front();
     FetchUpdatedExtension(next.id, next.url, next.package_hash, next.version);
   }
 }
 
 void ExtensionUpdater::OnCRXFileWritten(const std::string& id,
                                         const FilePath& path,
                                         const GURL& download_url) {
   DCHECK(alive_);
 
+  VLOG(2) << download_url << " written to " << path.value();
+
   FetchedCRXFile fetched(id, path, download_url);
   fetched_crx_files_.push(fetched);
 
   MaybeInstallCRXFile();
 }
 
 bool ExtensionUpdater::MaybeInstallCRXFile() {
   if (crx_install_is_running_)
     return false;
 
   while (!fetched_crx_files_.empty() && !crx_install_is_running_) {
     const FetchedCRXFile& crx_file = fetched_crx_files_.top();
 
+    VLOG(2) << "updating " << crx_file.id << " with " << crx_file.path.value();
+
     // The ExtensionService is now responsible for cleaning up the temp file
     // at |extension_file.path|.
     CrxInstaller* installer = NULL;
     if (service_->UpdateExtension(crx_file.id,
                                   crx_file.path,
                                   crx_file.download_url,
                                   &installer)) {
       crx_install_is_running_ = true;
 
       // Source parameter ensures that we only see the completion event for the
@@ skipping 93 matching lines @@
   return will_check_soon_;
 }
 
 void ExtensionUpdater::DoCheckSoon() {
   DCHECK(will_check_soon_);
   CheckNow();
   will_check_soon_ = false;
 }
 
 void ExtensionUpdater::CheckNow() {
+  VLOG(2) << "Starting update check";
   DCHECK(alive_);
   NotifyStarted();
   ManifestFetchesBuilder fetches_builder(service_, extension_prefs_);
 
   const PendingExtensionManager* pending_extension_manager =
       service_->pending_extension_manager();
   std::set<std::string> pending_ids;
 
   PendingExtensionManager::const_iterator iter;
   for (iter = pending_extension_manager->begin();
@@ skipping 76 matching lines @@
 
   // This will only be valid if one of possible_updates specifies
   // browser_min_version.
   Version browser_version;
   PendingExtensionManager* pending_extension_manager =
       service_->pending_extension_manager();
 
   for (size_t i = 0; i < possible_updates.list.size(); i++) {
     const UpdateManifest::Result* update = &possible_updates.list[i];
 
-    if (!fetch_data.Includes(update->extension_id))
+    if (!fetch_data.Includes(update->extension_id)) {
+      VLOG(2) << "Ignoring " << update->extension_id << " from this manifest";
       continue;
+    }
+
+    if (VLOG_IS_ON(2)) {
+      if (update->version.empty())
+        VLOG(2) << "manifest indicates " << update->extension_id
+                << " has no update";
+      else
+        VLOG(2) << "manifest indicates " << update->extension_id
+                << " latest version is '" << update->version << "'";
+    }
 
     if (!pending_extension_manager->IsIdPending(update->extension_id)) {
       // If we're not installing pending extension, and the update
       // version is the same or older than what's already installed,
       // we don't want it.
       std::string version;
-      if (!GetExistingVersion(update->extension_id, &version))
+      if (!GetExistingVersion(update->extension_id, &version)) {
+        VLOG(2) << update->extension_id << " is not installed";
         continue;
+      }
+
+      VLOG(2) << update->extension_id << " is at '" << version << "'";
 
       Version existing_version(version);
       Version update_version(update->version);
 
       if (!update_version.IsValid() ||
           update_version.CompareTo(existing_version) <= 0) {
         continue;
       }
     }
 
     // If the update specifies a browser minimum version, do we qualify?
     if (update->browser_min_version.length() > 0) {
       // First determine the browser version if we haven't already.
       if (!browser_version.IsValid()) {
         chrome::VersionInfo version_info;
         if (version_info.is_valid())
           browser_version = Version(version_info.Version());
       }
       Version browser_min_version(update->browser_min_version);
       if (browser_version.IsValid() && browser_min_version.IsValid() &&
           browser_min_version.CompareTo(browser_version) > 0) {
         // TODO(asargent) - We may want this to show up in the extensions UI
         // eventually. (http://crbug.com/12547).
         LOG(WARNING) << "Updated version of extension " << update->extension_id
                      << " available, but requires chrome version "
                      << update->browser_min_version;
         continue;
       }
     }
+    VLOG(2) << "will try to update " << update->extension_id;
     result.push_back(i);
   }
   return result;
 }
 
 void ExtensionUpdater::StartUpdateCheck(ManifestFetchData* fetch_data) {
   AddToInProgress(fetch_data->extension_ids());
 
   scoped_ptr<ManifestFetchData> scoped_fetch_data(fetch_data);
   if (CommandLine::ForCurrentProcess()->HasSwitch(
       switches::kDisableBackgroundNetworking))
     return;
 
   std::deque<ManifestFetchData*>::const_iterator i;
   for (i = manifests_pending_.begin(); i != manifests_pending_.end(); i++) {
     if (fetch_data->full_url() == (*i)->full_url()) {
       // This url is already scheduled to be fetched.
       return;
     }
   }
 
   if (manifest_fetcher_.get() != NULL) {
     if (manifest_fetcher_->GetURL() != fetch_data->full_url()) {
       manifests_pending_.push_back(scoped_fetch_data.release());
     }
   } else {
     UMA_HISTOGRAM_COUNTS("Extensions.UpdateCheckUrlLength",
         fetch_data->full_url().possibly_invalid_spec().length());
 
+    if (VLOG_IS_ON(2)) {
+      const std::set<std::string>& id_set = fetch_data->extension_ids();
+      std::vector<std::string> id_vector(id_set.begin(), id_set.end());
+      std::string id_list = JoinString(id_vector, ',');
+      VLOG(2) << "Fetching " << fetch_data->full_url() << " for "
+              << id_list;
+    }
+
     current_manifest_fetch_.swap(scoped_fetch_data);
     manifest_fetcher_.reset(content::URLFetcher::Create(
         kManifestFetcherId, fetch_data->full_url(), content::URLFetcher::GET,
         this));
     manifest_fetcher_->SetRequestContext(profile_->GetRequestContext());
     manifest_fetcher_->SetLoadFlags(net::LOAD_DO_NOT_SEND_COOKIES |
                                     net::LOAD_DO_NOT_SAVE_COOKIES |
                                     net::LOAD_DISABLE_CACHE);
     manifest_fetcher_->Start();
   }
@@ skipping 23 matching lines @@
     extension_fetcher_->SetLoadFlags(net::LOAD_DO_NOT_SEND_COOKIES |
                                      net::LOAD_DO_NOT_SAVE_COOKIES |
                                      net::LOAD_DISABLE_CACHE);
     // Download CRX files to a temp file. The blacklist is small and will be
     // processed in memory, so it is fetched into a string.
     if (id != ExtensionUpdater::kBlacklistAppID) {
       extension_fetcher_->SaveResponseToTemporaryFile(
           BrowserThread::GetMessageLoopProxyForThread(BrowserThread::FILE));
     }
 
+    VLOG(2) << "Starting fetch of " << url << " for " << id;
+
     extension_fetcher_->Start();
     current_extension_fetch_ = ExtensionFetch(id, url, hash, version);
   }
 }
 
 void ExtensionUpdater::NotifyStarted() {
   content::NotificationService::current()->Notify(
       chrome::NOTIFICATION_EXTENSION_UPDATING_STARTED,
       content::Source<Profile>(profile_),
       content::NotificationService::NoDetails());
@@ skipping 20 matching lines @@
   std::set<std::string>::const_iterator i;
   for (i = ids.begin(); i != ids.end(); ++i)
     in_progress_ids_.insert(*i);
 }
 
 void ExtensionUpdater::RemoveFromInProgress(const std::set<std::string>& ids) {
   std::set<std::string>::const_iterator i;
   for (i = ids.begin(); i != ids.end(); ++i)
     in_progress_ids_.erase(*i);
 }