[Sync] Log age of auth tokens on authentication failure

The fetch/refresh time of the sync credentials are plumbed through to the
server connection manager, which can then histogram their age in the event
that there is an auth failure.

BUG=none
R=tim@chromium.org

Review URL: https://codereview.chromium.org/14888003

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

chrome/browser/signin/about_signin_internals.cc

@@ -18,15 +18,16 @@
 #include "chrome/browser/ui/webui/signin_internals_ui.h"
 #include "google_apis/gaia/gaia_constants.h"
 
+using base::Time;
 using namespace signin_internals_util;
 
 AboutSigninInternals::AboutSigninInternals() : profile_(NULL) {
   // Initialize default values for tokens.
   for (size_t i = 0; i < kNumTokenPrefs; ++i) {
     signin_status_.token_info_map.insert(std::pair<std::string, TokenInfo>(
         kTokenPrefsArray[i],
-        TokenInfo(
-            std::string(), "Not Loaded", std::string(), kTokenPrefsArray[i])));
+        TokenInfo(std::string(), "Not Loaded", std::string(), 0,
+                  kTokenPrefsArray[i])));
   }
 }
 
@@ -66,15 +67,15 @@ void AboutSigninInternals::NotifySigninValueChanged(
   DCHECK(field_index >= 0 &&
          field_index < signin_status_.timed_signin_fields.size());
 
-  std::string time_as_str = UTF16ToUTF8(base::TimeFormatFriendlyDateAndTime(
-      base::Time::NowFromSystemTime()));
+  Time now = Time::NowFromSystemTime();
+  std::string time_as_str = UTF16ToUTF8(base::TimeFormatFriendlyDate(now));
   TimedSigninStatusValue timed_value(value, time_as_str);
 
   signin_status_.timed_signin_fields[field_index] = timed_value;
 
   // Also persist these values in the prefs.
   const std::string value_pref = SigninStatusFieldToString(field) + ".value";
-  const std::string time_pref =  SigninStatusFieldToString(field) + ".time";
+  const std::string time_pref = SigninStatusFieldToString(field) + ".time";
   profile_->GetPrefs()->SetString(value_pref.c_str(), value);
   profile_->GetPrefs()->SetString(time_pref.c_str(), time_as_str);
 
@@ -111,10 +112,12 @@ void AboutSigninInternals::RefreshSigninPrefs() {
     const std::string value = pref + ".value";
     const std::string status = pref + ".status";
     const std::string time = pref + ".time";
+    const std::string time_internal = pref + ".time_internal";
 
     TokenInfo token_info(pref_service->GetString(value.c_str()),
                          pref_service->GetString(status.c_str()),
                          pref_service->GetString(time.c_str()),
+                         pref_service->GetInt64(time_internal.c_str()),
                          kTokenPrefsArray[i]);
 
     signin_status_.token_info_map[kTokenPrefsArray[i]] = token_info;
@@ -137,16 +140,22 @@ void AboutSigninInternals::NotifyTokenReceivedSuccess(
   // Also update preferences.
   const std::string value_pref = TokenPrefPath(token_name) + ".value";
   const std::string time_pref = TokenPrefPath(token_name) + ".time";
+  const std::string time_internal_pref =
+      TokenPrefPath(token_name) + ".time_internal";
   const std::string status_pref = TokenPrefPath(token_name) + ".status";
   profile_->GetPrefs()->SetString(value_pref.c_str(), token);
   profile_->GetPrefs()->SetString(status_pref.c_str(), "Successful");
 
   // Update timestamp if needed.
   if (update_time) {
-    const std::string time_as_str = UTF16ToUTF8(
-        base::TimeFormatFriendlyDateAndTime(base::Time::NowFromSystemTime()));
+    Time now = Time::NowFromSystemTime();
+    int64 time_as_int = now.ToInternalValue();
+    const std::string time_as_str =
+        UTF16ToUTF8(base::TimeFormatFriendlyDate(now));
     signin_status_.token_info_map[token_name].time = time_as_str;
+    signin_status_.token_info_map[token_name].time_internal = time_as_int;
     profile_->GetPrefs()->SetString(time_pref.c_str(), time_as_str);
+    profile_->GetPrefs()->SetInt64(time_internal_pref.c_str(), time_as_int);
   }
 
   NotifyObservers();
@@ -156,23 +165,28 @@ void AboutSigninInternals::NotifyTokenReceivedSuccess(
 void AboutSigninInternals::NotifyTokenReceivedFailure(
     const std::string& token_name,
     const std::string& error) {
+  Time now = Time::NowFromSystemTime();
+  int64 time_as_int = now.ToInternalValue();
   const std::string time_as_str =
-      UTF16ToUTF8(base::TimeFormatFriendlyDateAndTime(
-          base::Time::NowFromSystemTime()));
+      UTF16ToUTF8(base::TimeFormatFriendlyDate(now));
 
   // This should have been initialized already.
   DCHECK(signin_status_.token_info_map.count(token_name));
 
   signin_status_.token_info_map[token_name].token.clear();
   signin_status_.token_info_map[token_name].status = error;
   signin_status_.token_info_map[token_name].time = time_as_str;
+  signin_status_.token_info_map[token_name].time_internal = time_as_int;
 
   // Also update preferences.
   const std::string value_pref = TokenPrefPath(token_name) + ".value";
   const std::string time_pref = TokenPrefPath(token_name) + ".time";
+  const std::string time_internal_pref =
+      TokenPrefPath(token_name) + ".time_internal";
   const std::string status_pref = TokenPrefPath(token_name) + ".status";
   profile_->GetPrefs()->SetString(value_pref.c_str(), std::string());
   profile_->GetPrefs()->SetString(time_pref.c_str(), time_as_str);
+    profile_->GetPrefs()->SetInt64(time_internal_pref.c_str(), time_as_int);
   profile_->GetPrefs()->SetString(status_pref.c_str(), error);
 
   NotifyObservers();
@@ -220,3 +234,12 @@ void AboutSigninInternals::NotifyObservers() {
 scoped_ptr<DictionaryValue> AboutSigninInternals::GetSigninStatus() {
   return signin_status_.ToValue().Pass();
 }
+
+Time AboutSigninInternals::GetTokenTime(
+    const std::string& token_name) const {
+  TokenInfoMap::const_iterator iter =
+      signin_status_.token_info_map.find(token_name);
+  if (iter == signin_status_.token_info_map.end())
+    return base::Time();
+  return base::Time::FromInternalValue(iter->second.time_internal);
+}

chrome/browser/signin/about_signin_internals.h

@@ -82,6 +82,11 @@ class AboutSigninInternals
   //  }
   scoped_ptr<DictionaryValue> GetSigninStatus();
 
+  // Returns the time of the last fetch/refresh for the token specified by
+  // |token_name|. See signin_internals_util::kTokenPrefsArray for valid token
+  // names. If |token_name| is invalid, returns base::Time().
+  base::Time GetTokenTime(const std::string& token_name) const;
+
  private:
   void NotifyObservers();
 

chrome/browser/signin/about_signin_internals_factory.cc

@@ -67,6 +67,7 @@ void AboutSigninInternalsFactory::RegisterUserPrefs(
     const std::string value = pref + ".value";
     const std::string status = pref + ".status";
     const std::string time = pref + ".time";
+    const std::string time_internal = pref + ".time_internal";
     user_prefs->RegisterStringPref(
         value.c_str(),
         std::string(),
@@ -79,6 +80,10 @@ void AboutSigninInternalsFactory::RegisterUserPrefs(
         time.c_str(),
         std::string(),
         user_prefs::PrefRegistrySyncable::UNSYNCABLE_PREF);
+    user_prefs->RegisterInt64Pref(
+        time_internal.c_str(),
+        0,
+        user_prefs::PrefRegistrySyncable::UNSYNCABLE_PREF);
   }
 }
 

chrome/browser/signin/signin_internals_util.cc

@@ -67,10 +67,12 @@ std::string GetTruncatedHash(const std::string& str) {
 TokenInfo::TokenInfo(const std::string& token,
                      const std::string& status,
                      const std::string& time,
+                     const int64& time_internal,
                      const std::string& service)
     : token(token),
       status(status),
       time(time),
+      time_internal(time_internal),
       service(service) {
 }
 

chrome/browser/signin/signin_internals_util.h

@@ -64,14 +64,16 @@ enum {
 // values, we replicate the service name within this struct for a cleaner
 // serialization (with ToValue()).
 struct TokenInfo {
-  std::string token;  // The actual token.
-  std::string status;  // Status of the last token fetch.
-  std::string time;  // Timestamp of the last token fetch.
+  std::string token;    // The actual token.
+  std::string status;   // Status of the last token fetch.
+  std::string time;     // Timestamp of the last token fetch
+  int64 time_internal;  // Same as |time|, but in base::Time internal format.
   std::string service;  // The service that this token is for.
 
   TokenInfo(const std::string& token,
             const std::string& status,
             const std::string& time,
+            const int64& time_internal,
             const std::string& service);
   TokenInfo();
   ~TokenInfo();
@@ -88,7 +90,7 @@ typedef std::map<std::string, TokenInfo> TokenInfoMap;
 std::string TokenPrefPath(const std::string& service_name);
 
 // Many values in SigninStatus are also associated with a timestamp.
-// This makes it easier to keep values and their assoicated times together.
+// This makes it easier to keep values and their associated times together.
 typedef std::pair<std::string, std::string> TimedSigninStatusValue;
 
 // Returns the name of a SigninStatus field.

chrome/browser/sync/profile_sync_service.cc

@@ -28,6 +28,8 @@
 #include "chrome/browser/net/chrome_cookie_notification_details.h"
 #include "chrome/browser/prefs/pref_service_syncable.h"
 #include "chrome/browser/profiles/profile.h"
+#include "chrome/browser/signin/about_signin_internals.h"
+#include "chrome/browser/signin/about_signin_internals_factory.h"
 #include "chrome/browser/signin/signin_manager.h"
 #include "chrome/browser/signin/signin_manager_factory.h"
 #include "chrome/browser/signin/token_service.h"
@@ -422,8 +424,11 @@ SyncCredentials ProfileSyncService::GetCredentials() {
   DCHECK(!credentials.email.empty());
   TokenService* service = TokenServiceFactory::GetForProfile(profile_);
   if (service->HasTokenForService(GaiaConstants::kSyncService)) {
-      credentials.sync_token = service->GetTokenForService(
-          GaiaConstants::kSyncService);
+    credentials.sync_token = service->GetTokenForService(
+        GaiaConstants::kSyncService);
+    credentials.sync_token_time =
+        AboutSigninInternalsFactory::GetForProfile(profile_)->
+            GetTokenTime(GaiaConstants::kSyncService);
     UMA_HISTOGRAM_BOOLEAN("Sync.CredentialsLost", false);
   } else {
     // We've lost our sync credentials (crbug.com/121755), so just make up some

sync/engine/net/server_connection_manager.cc

@@ -11,6 +11,7 @@
 #include <vector>
 
 #include "base/command_line.h"
+#include "base/metrics/histogram.h"
 #include "build/build_config.h"
 #include "googleurl/src/gurl.h"
 #include "net/base/net_errors.h"
@@ -212,7 +213,31 @@ void ServerConnectionManager::OnConnectionDestroyed(Connection* connection) {
   active_connection_ = NULL;
 }
 
+bool ServerConnectionManager::SetAuthToken(const std::string& auth_token,
+                                           const base::Time& auth_token_time) {
+  DCHECK(thread_checker_.CalledOnValidThread());
+  if (previously_invalidated_token != auth_token) {
+    auth_token_.assign(auth_token);
+    auth_token_time_ = auth_token_time;
+    previously_invalidated_token = std::string();
+    return true;
+  }
+  return false;
+}
+
 void ServerConnectionManager::OnInvalidationCredentialsRejected() {
+  if (!auth_token_time_.is_null()) {
+    base::TimeDelta age = base::Time::Now() - auth_token_time_;
+    if (age < base::TimeDelta::FromHours(1)) {
+      UMA_HISTOGRAM_CUSTOM_TIMES("Sync.AuthInvalidationRejectedTokenAgeShort",
+                                 age,
+                                 base::TimeDelta::FromSeconds(1),
+                                 base::TimeDelta::FromHours(1),
+                                 50);
+    }
+    UMA_HISTOGRAM_COUNTS("Sync.AuthInvalidationRejectedTokenAgeLong",
+                         age.InDays());
+  }
   InvalidateAndClearAuthToken();
   SetServerStatus(HttpResponse::SYNC_AUTH_ERROR);
 }
@@ -223,6 +248,7 @@ void ServerConnectionManager::InvalidateAndClearAuthToken() {
   if (!auth_token_.empty()) {
     previously_invalidated_token.assign(auth_token_);
     auth_token_ = std::string();
+    auth_token_time_ = base::Time();
   }
 }
 
@@ -273,8 +299,21 @@ bool ServerConnectionManager::PostBufferToPath(PostBufferParams* params,
   bool ok = post.get()->Init(
       path.c_str(), auth_token, params->buffer_in, &params->response);
 
-  if (params->response.server_status == HttpResponse::SYNC_AUTH_ERROR)
+  if (params->response.server_status == HttpResponse::SYNC_AUTH_ERROR) {
+    if (!auth_token_time_.is_null()) {
+      base::TimeDelta age = base::Time::Now() - auth_token_time_;
+      if (age < base::TimeDelta::FromHours(1)) {
+        UMA_HISTOGRAM_CUSTOM_TIMES("Sync.AuthServerRejectedTokenAgeShort",
+                                   age,
+                                   base::TimeDelta::FromSeconds(1),
+                                   base::TimeDelta::FromHours(1),
+                                   50);
+      }
+      UMA_HISTOGRAM_COUNTS("Sync.AuthServerRejectedTokenAgeLong",
+                           age.InDays());
+    }
     InvalidateAndClearAuthToken();
+  }
 
   if (!ok || net::HTTP_OK != params->response.response_code)
     return false;

sync/engine/net/server_connection_manager.h

@@ -224,16 +224,11 @@ class SYNC_EXPORT_PRIVATE ServerConnectionManager {
     client_id_.assign(client_id);
   }
 
-  // Returns true if the auth token is succesfully set and false otherwise.
-  bool set_auth_token(const std::string& auth_token) {
-    DCHECK(thread_checker_.CalledOnValidThread());
-    if (previously_invalidated_token != auth_token) {
-      auth_token_.assign(auth_token);
-      previously_invalidated_token = std::string();
-      return true;
-    }
-    return false;
-  }
+  // Sets a new auth token and time. |auth_token_time| is an optional parameter
+  // that contains the date the auth token was fetched/refreshed, and is used
+  // for histogramms/logging only.
+  bool SetAuthToken(const std::string& auth_token,
+                    const base::Time& auth_token_time);
 
   // Our out-of-band invalidations channel can encounter auth errors,
   // and when it does so it tells us via this method to prevent making more
@@ -299,6 +294,10 @@ class SYNC_EXPORT_PRIVATE ServerConnectionManager {
   // The auth token to use in authenticated requests.
   std::string auth_token_;
 
+  // The time at which this auth token was last created/refreshed.
+  // Used for histogramming.
+  base::Time auth_token_time_;
+
   // The previous auth token that is invalid now.
   std::string previously_invalidated_token;
 

sync/internal_api/public/sync_manager.h

@@ -61,8 +61,12 @@ enum ConnectionStatus {
 
 // Contains everything needed to talk to and identify a user account.
 struct SyncCredentials {
+  // The email associated with this account.
   std::string email;
+  // The raw authentication token's bytes.
   std::string sync_token;
+  // (optional) The time at which the token was fetched/refreshed.
+  base::Time sync_token_time;
 };
 
 // SyncManager encapsulates syncable::Directory and serves as the parent of all

sync/internal_api/sync_manager_impl.cc

@@ -598,11 +598,14 @@ void SyncManagerImpl::UpdateCredentials(const SyncCredentials& credentials) {
   DCHECK(!credentials.sync_token.empty());
 
   observing_network_connectivity_changes_ = true;
-  if (!connection_manager_->set_auth_token(credentials.sync_token))
+  if (!connection_manager_->SetAuthToken(credentials.sync_token,
+                                         credentials.sync_token_time))
     return;  // Auth token is known to be invalid, so exit early.
 
   invalidator_->UpdateCredentials(credentials.email, credentials.sync_token);
   scheduler_->OnCredentialsUpdated();
+
+  // TODO(zea): pass the credential age to the debug info event listener.
 }
 
 void SyncManagerImpl::UpdateEnabledTypes(ModelTypeSet enabled_types) {

sync/test/engine/mock_connection_manager.cc

@@ -55,7 +55,7 @@ MockConnectionManager::MockConnectionManager(syncable::Directory* directory)
       use_legacy_bookmarks_protocol_(false),
       num_get_updates_requests_(0) {
   SetNewTimestamp(0);
-  set_auth_token(kValidAuthToken);
+  SetAuthToken(kValidAuthToken, base::Time());
 }
 
 MockConnectionManager::~MockConnectionManager() {