Reland: Adjust ChromeToMobile error logging and mitigation.

chrome/browser/chrome_to_mobile_service.cc

 // 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 "chrome/browser/chrome_to_mobile_service.h"
 
 #include "base/bind.h"
 #include "base/command_line.h"
 #include "base/file_util.h"
 #include "base/guid.h"
@@ skipping 25 matching lines @@
 #include "content/public/browser/notification_details.h"
 #include "content/public/browser/notification_source.h"
 #include "content/public/browser/web_contents.h"
 #include "google/cacheinvalidation/include/types.h"
 #include "google/cacheinvalidation/types.pb.h"
 #include "google_apis/gaia/gaia_constants.h"
 #include "google_apis/gaia/gaia_urls.h"
 #include "google_apis/gaia/oauth2_access_token_fetcher.h"
 #include "net/base/escape.h"
 #include "net/base/load_flags.h"
+#include "net/http/http_status_code.h"
 #include "net/url_request/url_fetcher.h"
 #include "net/url_request/url_request_context_getter.h"
 #include "sync/notifier/invalidation_util.h"
 
 namespace {
 
 // The maximum number of retries for the URLFetcher requests.
-const size_t kMaxRetries = 1;
+const size_t kMaxRetries = 5;
 
-// The number of hours to delay before retrying authentication on failure.
-const size_t kAuthRetryDelayHours = 6;
-
-// The number of hours before subsequent search requests are allowed.
-// This value is used to throttle expensive cloud print search requests.
-// Note that this limitation does not hold across application restarts.
-const int kSearchRequestDelayHours = 24;
+// The number of hours to delay before retrying certain failed operations.
+const size_t kDelayHours = 1;
 
 // The sync invalidation object ID for Chrome to Mobile's mobile device list.
 // This corresponds with cloud print's server-side invalidation object ID.
 // Meaning: "U" == "User", "CM" == "Chrome to Mobile", "MLST" == "Mobile LiST".
 const char kSyncInvalidationObjectIdChromeToMobileDeviceList[] = "UCMMLST";
 
 // The cloud print OAuth2 scope and 'printer' type of compatible mobile devices.
 const char kCloudPrintAuth[] = "https://www.googleapis.com/auth/cloudprint";
 const char kTypeAndroid[] = "ANDROID_CHROME_SNAPSHOT";
 const char kTypeIOS[] = "IOS_CHROME_SNAPSHOT";
@@ skipping 233 matching lines @@
       profile_ ? ProfileSyncServiceFactory::GetForProfile(profile_) : NULL;
   if (profile_sync_service)
     profile_sync_service->UnregisterInvalidationHandler(this);
 }
 
 void ChromeToMobileService::OnURLFetchComplete(const net::URLFetcher* source) {
   if (source->GetURL() == GetSearchURL(cloud_print_url_))
     HandleSearchResponse(source);
   else
     HandleSubmitResponse(source);
+
+  // Remove the URLFetcher from the ScopedVector; this deletes the URLFetcher.
+  for (ScopedVector<net::URLFetcher>::iterator it = url_fetchers_.begin();
+       it != url_fetchers_.end(); ++it) {
+    if (*it == source) {
+      url_fetchers_.erase(it);
+      break;
+    }
+  }
 }
 
 void ChromeToMobileService::Observe(
     int type,
     const content::NotificationSource& source,
     const content::NotificationDetails& details) {
   DCHECK_EQ(type, chrome::NOTIFICATION_TOKEN_AVAILABLE);
   TokenService::TokenAvailableDetails* token_details =
       content::Details<TokenService::TokenAvailableDetails>(details).ptr();
   // Invalidate the cloud print access token on Gaia login token updates.
-  if (token_details->service() == GaiaConstants::kGaiaOAuth2LoginRefreshToken)
+  if (token_details->service() == GaiaConstants::kGaiaOAuth2LoginRefreshToken ||
+      token_details->service() == GaiaConstants::kGaiaOAuth2LoginAccessToken)
     access_token_.clear();
 }
 
 void ChromeToMobileService::OnGetTokenSuccess(
     const std::string& access_token,
     const base::Time& expiration_time) {
   DCHECK(!access_token.empty());
   access_token_fetcher_.reset();
   auth_retry_timer_.Stop();
   access_token_ = access_token;
 
   while (!task_queue_.empty()) {
     // Post all tasks that were queued and waiting on a valid access token.
     if (!content::BrowserThread::PostTask(content::BrowserThread::UI, FROM_HERE,
                                           task_queue_.front())) {
       NOTREACHED();
     }
     task_queue_.pop();
   }
 }
 
 void ChromeToMobileService::OnGetTokenFailure(
     const GoogleServiceAuthError& error) {
+  LogMetric(BAD_TOKEN);
+  access_token_.clear();
   access_token_fetcher_.reset();
   auth_retry_timer_.Stop();
 
-  auth_retry_timer_.Start(
-      FROM_HERE, base::TimeDelta::FromHours(kAuthRetryDelayHours),
-      this, &ChromeToMobileService::RequestAccessToken);
+  base::TimeDelta delay = std::max(base::TimeDelta::FromHours(kDelayHours),
+                                   auth_retry_timer_.GetCurrentDelay() * 2);
+  auth_retry_timer_.Start(FROM_HERE, delay, this,
+                          &ChromeToMobileService::RequestAccessToken);
+
+  // Clear the mobile list, which may be (or become) out of date.
+  ListValue empty;
+  profile_->GetPrefs()->Set(prefs::kChromeToMobileDeviceList, empty);
+  UpdateCommandState();
 }
 
 void ChromeToMobileService::OnNotificationsEnabled() {
   sync_invalidation_enabled_ = true;
   UpdateCommandState();
 }
 
 void ChromeToMobileService::OnNotificationsDisabled(
     syncer::NotificationsDisabledReason reason) {
   sync_invalidation_enabled_ = false;
@@ skipping 50 matching lines @@
   } else if (observer.get()) {
     // Signal snapshot generation failure.
     observer->SnapshotGenerated(FilePath(), 0);
   }
 }
 
 net::URLFetcher* ChromeToMobileService::CreateRequest() {
   net::URLFetcher* request = net::URLFetcher::Create(
       cloud_print::GetUrlForSubmit(cloud_print_url_),
       net::URLFetcher::POST, this);
+  url_fetchers_.push_back(request);
   InitRequest(request);
   return request;
 }
 
 void ChromeToMobileService::InitRequest(net::URLFetcher* request) {
   request->SetRequestContext(profile_->GetRequestContext());
   request->SetMaxRetries(kMaxRetries);
   DCHECK(!access_token_.empty());
   request->SetExtraRequestHeaders("Authorization: OAuth " +
       access_token_ + "\r\n" + cloud_print::kChromeCloudPrintProxyHeader);
@@ skipping 44 matching lines @@
   request->Start();
 }
 
 void ChromeToMobileService::RequestAccessToken() {
   // Register to observe Gaia login refresh token updates.
   TokenService* token_service = TokenServiceFactory::GetForProfile(profile_);
   if (registrar_.IsEmpty())
     registrar_.Add(this, chrome::NOTIFICATION_TOKEN_AVAILABLE,
                    content::Source<TokenService>(token_service));
 
-  // Deny concurrent requests and bail without a valid Gaia login refresh token.
-  if (access_token_fetcher_.get() || !token_service->HasOAuthLoginToken())
+  // Deny concurrent requests.
+  if (access_token_fetcher_.get())
     return;
 
+  // Handle invalid login refresh tokens as a failure.
+  if (!token_service->HasOAuthLoginToken()) {
+    OnGetTokenFailure(GoogleServiceAuthError(GoogleServiceAuthError::NONE));
+    return;
+  }
+
   auth_retry_timer_.Stop();
   access_token_fetcher_.reset(
       new OAuth2AccessTokenFetcher(this, profile_->GetRequestContext()));
   GaiaUrls* gaia_urls = GaiaUrls::GetInstance();
   access_token_fetcher_->Start(gaia_urls->oauth2_chrome_client_id(),
                                gaia_urls->oauth2_chrome_client_secret(),
                                token_service->GetOAuth2LoginRefreshToken(),
                                std::vector<std::string>(1, kCloudPrintAuth));
 }
 
 void ChromeToMobileService::RequestDeviceSearch() {
+  search_retry_timer_.Stop();
   if (access_token_.empty()) {
     // Enqueue this task to perform after obtaining an access token.
     task_queue_.push(base::Bind(&ChromeToMobileService::RequestDeviceSearch,
                                 weak_ptr_factory_.GetWeakPtr()));
     RequestAccessToken();
     return;
   }
 
   LogMetric(DEVICES_REQUESTED);
 
   net::URLFetcher* search_request = net::URLFetcher::Create(
       GetSearchURL(cloud_print_url_), net::URLFetcher::GET, this);
+  url_fetchers_.push_back(search_request);
   InitRequest(search_request);
   search_request->Start();
 }
 
 void ChromeToMobileService::HandleSearchResponse(
     const net::URLFetcher* source) {
   DCHECK(content::BrowserThread::CurrentlyOn(content::BrowserThread::UI));
   DCHECK_EQ(source->GetURL(), GetSearchURL(cloud_print_url_));
 
+  ListValue mobiles;
   std::string data;
   ListValue* list = NULL;
   DictionaryValue* dictionary = NULL;
   source->GetResponseAsString(&data);
   scoped_ptr<Value> json(base::JSONReader::Read(data));
   if (json.get() && json->GetAsDictionary(&dictionary) && dictionary &&
       dictionary->GetList(cloud_print::kPrinterListValue, &list)) {
-    ListValue mobiles;
     std::string type, name, id;
     DictionaryValue* printer = NULL;
     DictionaryValue* mobile = NULL;
     for (size_t index = 0; index < list->GetSize(); ++index) {
       if (list->GetDictionary(index, &printer) &&
           printer->GetString("type", &type) &&
           (type.compare(kTypeAndroid) == 0 || type.compare(kTypeIOS) == 0)) {
         // Copy just the requisite values from the full |printer| definition.
         if (printer->GetString("displayName", &name) &&
             printer->GetString("id", &id)) {
           mobile = new DictionaryValue();
           mobile->SetString("type", type);
           mobile->SetString("name", name);
           mobile->SetString("id", id);
           mobiles.Append(mobile);
         } else {
           NOTREACHED();
         }
       }
     }
+  } else if (source->GetResponseCode() == net::HTTP_FORBIDDEN) {
+    LogMetric(BAD_SEARCH_AUTH);
+    // Invalidate the access token and retry a delayed search on access errors.
+    access_token_.clear();
+    search_retry_timer_.Stop();
+    base::TimeDelta delay = std::max(base::TimeDelta::FromHours(kDelayHours),
+                                     search_retry_timer_.GetCurrentDelay() * 2);
+    search_retry_timer_.Start(FROM_HERE, delay, this,
+                              &ChromeToMobileService::RequestDeviceSearch);
+  } else {
+    LogMetric(BAD_SEARCH_OTHER);
+  }
 
-    // Update the cached mobile device list in profile prefs.
-    profile_->GetPrefs()->Set(prefs::kChromeToMobileDeviceList, mobiles);
-
-    if (HasMobiles())
-      LogMetric(DEVICES_AVAILABLE);
-    UpdateCommandState();
-  }
+  // Update the cached mobile device list in profile prefs.
+  profile_->GetPrefs()->Set(prefs::kChromeToMobileDeviceList, mobiles);
+  if (HasMobiles())
+    LogMetric(DEVICES_AVAILABLE);
+  UpdateCommandState();
 }
 
 void ChromeToMobileService::HandleSubmitResponse(
     const net::URLFetcher* source) {
   // Get the success value from the cloud print server response data.
   std::string data;
+  bool success = false;
   source->GetResponseAsString(&data);
-  bool success = false;
   DictionaryValue* dictionary = NULL;
   scoped_ptr<Value> json(base::JSONReader::Read(data));
-  if (json.get() && json->GetAsDictionary(&dictionary) && dictionary)
+  if (json.get() && json->GetAsDictionary(&dictionary) && dictionary) {
     dictionary->GetBoolean("success", &success);
+    int error_code = -1;
+    if (dictionary->GetInteger("errorCode", &error_code))
+      LogMetric(error_code == 407 ? BAD_SEND_407 : BAD_SEND_ERROR);
+  } else if (source->GetResponseCode() == net::HTTP_FORBIDDEN) {
+    LogMetric(BAD_SEND_AUTH);
+  } else {
+    LogMetric(BAD_SEND_OTHER);
+  }
 
   // Log each URL and [DELAYED_]SNAPSHOT job submission response.
   LogMetric(success ? SEND_SUCCESS : SEND_ERROR);
+  LOG_IF(INFO, !success) << "ChromeToMobile send failed (" <<
+                            source->GetResponseCode() << "): " << data;
 
   // Get the observer for this job submission response.
   base::WeakPtr<Observer> observer;
   RequestObserverMap::iterator i = request_observer_map_.find(source);
   if (i != request_observer_map_.end()) {
     observer = i->second;
     request_observer_map_.erase(i);
   }
 
   // Check if the observer is waiting on a second response (url or snapshot).
   for (RequestObserverMap::iterator other = request_observer_map_.begin();
        observer.get() && (other != request_observer_map_.end()); ++other) {
     if (other->second == observer) {
       // Delay reporting success until the second response is received.
       if (success)
         return;
 
       // Report failure below and ignore the second response.
       request_observer_map_.erase(other);
       break;
     }
   }
 
   if (observer.get())
     observer->OnSendComplete(success);
 }