[Sync] Log age of auth tokens on authentication failure

sync/engine/net/server_connection_manager.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 "sync/engine/net/server_connection_manager.h"
 
 #include <errno.h>
 
 #include <ostream>
 #include <string>
 #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"
 #include "net/http/http_status_code.h"
 #include "sync/engine/net/url_translator.h"
 #include "sync/engine/syncer.h"
 #include "sync/protocol/sync.pb.h"
 #include "sync/syncable/directory.h"
 
 namespace syncer {
@@ skipping 182 matching lines @@
   // |active_connection_| can be NULL already if it was aborted. Also,
   // it can legitimately be a different Connection object if a new Connection
   // was created after a previous one was Aborted and destroyed.
   if (active_connection_ != connection)
     return;
 
   active_connection_ = NULL;
 }
 
 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.InvalidationRejectionAuthAgeShort",

[tim (not reviewing), 2013/05/03 00:46:43]

nit - might be nice to group auth related things in a Sync.Auth.* prefix.

[Nicolas Zea, 2013/05/03 01:31:41]

Done.

+                                 age,
+                                 base::TimeDelta::FromSeconds(1),
+                                 base::TimeDelta::FromHours(1),
+                                 50);
+    }
+    UMA_HISTOGRAM_COUNTS("Sync.InvalidationRejectionAuthAgeLong", age.InDays());
+  }
   InvalidateAndClearAuthToken();
   SetServerStatus(HttpResponse::SYNC_AUTH_ERROR);
 }
 
 void ServerConnectionManager::InvalidateAndClearAuthToken() {
   DCHECK(thread_checker_.CalledOnValidThread());
   // Copy over the token to previous invalid token.
   if (!auth_token_.empty()) {
     previously_invalidated_token.assign(auth_token_);
     auth_token_ = std::string();
+    auth_token_time_ = base::Time();
   }
 }
 
 void ServerConnectionManager::SetServerStatus(
     HttpResponse::ServerConnectionCode server_status) {
   if (server_status_ == server_status)
     return;
   server_status_ = server_status;
   NotifyStatusChanged();
 }
@@ skipping 30 matching lines @@
   if (!post.get()) {
     params->response.server_status = HttpResponse::CONNECTION_UNAVAILABLE;
     return false;
   }
 
   // Note that |post| may be aborted by now, which will just cause Init to fail
   // with CONNECTION_UNAVAILABLE.
   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.ServerRejectionAuthAgeShort",
+                                   age,
+                                   base::TimeDelta::FromSeconds(1),
+                                   base::TimeDelta::FromHours(1),
+                                   50);
+      }
+      UMA_HISTOGRAM_COUNTS("Sync.ServerRejectionAuthAgeLong",

[tim (not reviewing), 2013/05/03 00:46:43]

So no breakdown between 1 hour and 24 hours? I guess I was expecting an 'else'
and then a second histogram covering things > 1 hour.

[Nicolas Zea, 2013/05/03 01:31:41]

Well, this is going to cover those, they'll simply be in the first bucket. I
think it's useful to have a histogram that lets you see the total breakdown in
days.

+                           age.InDays());
+    }
     InvalidateAndClearAuthToken();
+  }
 
   if (!ok || net::HTTP_OK != params->response.response_code)
     return false;
 
   if (post.get()->ReadBufferResponse(
       &params->buffer_out, &params->response, true)) {
     params->response.server_status = HttpResponse::SERVER_CONNECTION_OK;
     return true;
   }
   return false;
@@ skipping 56 matching lines @@
 
 std::ostream& operator << (std::ostream& s, const struct HttpResponse& hr) {
   s << " Response Code (bogus on error): " << hr.response_code;
   s << " Content-Length (bogus on error): " << hr.content_length;
   s << " Server Status: "
     << HttpResponse::GetServerConnectionCodeString(hr.server_status);
   return s;
 }
 
 }  // namespace syncer