Identity API TRACE_EVENT logging

This change adds "identity" events to chrome://tracing, mostly for
getAuthToken calls. This will allow users or developers to capture
traces to debug identity API issues.

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

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

5 files changed, 130 insertions, 5 deletions

diff --git a/chrome/browser/extensions/api/identity/gaia_web_auth_flow.cc b/chrome/browser/extensions/api/identity/gaia_web_auth_flow.cc
index e30a3df..5235845 100644
--- a/chrome/browser/extensions/api/identity/gaia_web_auth_flow.cc
+++ b/chrome/browser/extensions/api/identity/gaia_web_auth_flow.cc
@@ -4,6 +4,7 @@
 
 #include "chrome/browser/extensions/api/identity/gaia_web_auth_flow.h"
 
+#include "base/debug/trace_event.h"
 #include "base/strings/string_number_conversions.h"
 #include "base/strings/string_split.h"
 #include "base/strings/string_util.h"
@@ -26,6 +27,14 @@ GaiaWebAuthFlow::GaiaWebAuthFlow(Delegate* delegate,
     : delegate_(delegate),
       profile_(profile),
       account_id_(token_key->account_id) {
+  TRACE_EVENT_ASYNC_BEGIN2("identity",
+                           "GaiaWebAuthFlow",
+                           this,
+                           "extension_id",
+                           token_key->extension_id,
+                           "account_id",
+                           token_key->account_id);
+
   const char kOAuth2RedirectPathFormat[] = "/%s#";
   const char kOAuth2AuthorizeFormat[] =
       "?response_type=token&approval_prompt=force&authuser=0&"
@@ -57,6 +66,8 @@ GaiaWebAuthFlow::GaiaWebAuthFlow(Delegate* delegate,
 }
 
 GaiaWebAuthFlow::~GaiaWebAuthFlow() {
+  TRACE_EVENT_ASYNC_END0("identity", "GaiaWebAuthFlow", this);
+
   if (web_flow_)
     web_flow_.release()->DetachDelegateAndDelete();
 }
@@ -71,6 +82,9 @@ void GaiaWebAuthFlow::Start() {
 }
 
 void GaiaWebAuthFlow::OnUbertokenSuccess(const std::string& token) {
+  TRACE_EVENT_ASYNC_STEP_PAST0(
+      "identity", "GaiaWebAuthFlow", this, "OnUbertokenSuccess");
+
   const char kMergeSessionQueryFormat[] = "?uberauth=%s&"
                                           "continue=%s&"
                                           "source=appsv2";
@@ -87,6 +101,13 @@ void GaiaWebAuthFlow::OnUbertokenSuccess(const std::string& token) {
 }
 
 void GaiaWebAuthFlow::OnUbertokenFailure(const GoogleServiceAuthError& error) {
+  TRACE_EVENT_ASYNC_STEP_PAST1("identity",
+                               "GaiaWebAuthFlow",
+                               this,
+                               "OnUbertokenSuccess",
+                               "error",
+                               error.ToString());
+
   DVLOG(1) << "OnUbertokenFailure: " << error.error_message();
   delegate_->OnGaiaFlowFailure(
       GaiaWebAuthFlow::SERVICE_AUTH_ERROR, error, std::string());
@@ -109,6 +130,13 @@ void GaiaWebAuthFlow::OnAuthFlowFailure(WebAuthFlow::Failure failure) {
       break;
   }
 
+  TRACE_EVENT_ASYNC_STEP_PAST1("identity",
+                               "GaiaWebAuthFlow",
+                               this,
+                               "OnAuthFlowFailure",
+                               "error",
+                               gaia_failure);
+
   delegate_->OnGaiaFlowFailure(
       gaia_failure,
       GoogleServiceAuthError(GoogleServiceAuthError::NONE),
@@ -116,6 +144,11 @@ void GaiaWebAuthFlow::OnAuthFlowFailure(WebAuthFlow::Failure failure) {
 }
 
 void GaiaWebAuthFlow::OnAuthFlowURLChange(const GURL& url) {
+  TRACE_EVENT_ASYNC_STEP_PAST0("identity",
+                               "GaiaWebAuthFlow",
+                               this,
+                               "OnAuthFlowURLChange");
+
   const char kOAuth2RedirectAccessTokenKey[] = "access_token";
   const char kOAuth2RedirectErrorKey[] = "error";
   const char kOAuth2ExpiresInKey[] = "expires_in";
diff --git a/chrome/browser/extensions/api/identity/identity_api.cc b/chrome/browser/extensions/api/identity/identity_api.cc
index 37bc4e0..26c54c1 100644
--- a/chrome/browser/extensions/api/identity/identity_api.cc
+++ b/chrome/browser/extensions/api/identity/identity_api.cc
@@ -9,6 +9,7 @@
 #include <utility>
 #include <vector>
 
+#include "base/debug/trace_event.h"
 #include "base/lazy_instance.h"
 #include "base/prefs/pref_service.h"
 #include "base/strings/string_number_conversions.h"
@@ -286,9 +287,17 @@ ExtensionFunction::ResponseAction IdentityGetAccountsFunction::Run() {
 IdentityGetAuthTokenFunction::IdentityGetAuthTokenFunction()
     : OAuth2TokenService::Consumer("extensions_identity_api"),
       should_prompt_for_scopes_(false),
-      should_prompt_for_signin_(false) {}
+      should_prompt_for_signin_(false) {
+  TRACE_EVENT_ASYNC_BEGIN1("identity",
+                           "IdentityGetAuthTokenFunction",
+                           this,
+                           "extension",
+                           extension()->id());
+}
 
-IdentityGetAuthTokenFunction::~IdentityGetAuthTokenFunction() {}
+IdentityGetAuthTokenFunction::~IdentityGetAuthTokenFunction() {
+  TRACE_EVENT_ASYNC_END0("identity", "IdentityGetAuthTokenFunction", this);
+}
 
 bool IdentityGetAuthTokenFunction::RunAsync() {
   if (GetProfile()->IsOffTheRecord()) {
@@ -405,6 +414,12 @@ void IdentityGetAuthTokenFunction::CompleteFunctionWithResult(
 
 void IdentityGetAuthTokenFunction::CompleteFunctionWithError(
     const std::string& error) {
+  TRACE_EVENT_ASYNC_STEP_PAST1("identity",
+                               "IdentityGetAuthTokenFunction",
+                               this,
+                               "CompleteFunctionWithError",
+                               "error",
+                               error);
   error_ = error;
   CompleteAsyncRun(false);
 }
@@ -458,6 +473,13 @@ void IdentityGetAuthTokenFunction::CompleteMintTokenFlow() {
 
 void IdentityGetAuthTokenFunction::StartMintToken(
     IdentityMintRequestQueue::MintType type) {
+  TRACE_EVENT_ASYNC_STEP_PAST1("identity",
+                               "IdentityGetAuthTokenFunction",
+                               this,
+                               "StartMintToken",
+                               "type",
+                               type);
+
   const OAuth2Info& oauth2_info = OAuth2Info::GetOAuth2Info(extension());
   IdentityAPI* id_api = IdentityAPI::GetFactoryInstance()->Get(GetProfile());
   IdentityTokenCacheValue cache_entry = id_api->GetCachedToken(*token_key_);
@@ -519,6 +541,11 @@ void IdentityGetAuthTokenFunction::StartMintToken(
 
 void IdentityGetAuthTokenFunction::OnMintTokenSuccess(
     const std::string& access_token, int time_to_live) {
+  TRACE_EVENT_ASYNC_STEP_PAST0("identity",
+                               "IdentityGetAuthTokenFunction",
+                               this,
+                               "OnMintTokenSuccess");
+
   IdentityTokenCacheValue token(access_token,
                                 base::TimeDelta::FromSeconds(time_to_live));
   IdentityAPI::GetFactoryInstance()->Get(GetProfile())->SetCachedToken(
@@ -530,6 +557,12 @@ void IdentityGetAuthTokenFunction::OnMintTokenSuccess(
 
 void IdentityGetAuthTokenFunction::OnMintTokenFailure(
     const GoogleServiceAuthError& error) {
+  TRACE_EVENT_ASYNC_STEP_PAST1("identity",
+                               "IdentityGetAuthTokenFunction",
+                               this,
+                               "OnMintTokenFailure",
+                               "error",
+                               error.ToString());
   CompleteMintTokenFlow();
 
   switch (error.state()) {
@@ -554,6 +587,11 @@ void IdentityGetAuthTokenFunction::OnMintTokenFailure(
 
 void IdentityGetAuthTokenFunction::OnIssueAdviceSuccess(
     const IssueAdviceInfo& issue_advice) {
+  TRACE_EVENT_ASYNC_STEP_PAST0("identity",
+                               "IdentityGetAuthTokenFunction",
+                               this,
+                               "OnIssueAdviceSuccess");
+
   IdentityAPI::GetFactoryInstance()->Get(GetProfile())->SetCachedToken(
       *token_key_, IdentityTokenCacheValue(issue_advice));
   CompleteMintTokenFlow();
@@ -566,6 +604,11 @@ void IdentityGetAuthTokenFunction::OnIssueAdviceSuccess(
 }
 
 void IdentityGetAuthTokenFunction::SigninSuccess() {
+  TRACE_EVENT_ASYNC_STEP_PAST0("identity",
+                               "IdentityGetAuthTokenFunction",
+                               this,
+                               "SigninSuccess");
+
   // If there was no account associated this profile before the
   // sign-in, we may not have an account_id in the token_key yet.
   if (token_key_->account_id.empty()) {
@@ -576,6 +619,10 @@ void IdentityGetAuthTokenFunction::SigninSuccess() {
 }
 
 void IdentityGetAuthTokenFunction::SigninFailed() {
+  TRACE_EVENT_ASYNC_STEP_PAST0("identity",
+                               "IdentityGetAuthTokenFunction",
+                               this,
+                               "SigninFailed");
   CompleteFunctionWithError(identity_constants::kUserNotSignedIn);
 }
 
@@ -620,7 +667,10 @@ void IdentityGetAuthTokenFunction::OnGaiaFlowFailure(
 void IdentityGetAuthTokenFunction::OnGaiaFlowCompleted(
     const std::string& access_token,
     const std::string& expiration) {
-
+  TRACE_EVENT_ASYNC_STEP_PAST0("identity",
+                               "IdentityGetAuthTokenFunction",
+                               this,
+                               "OnGaiaFlowCompleted");
   int time_to_live;
   if (!expiration.empty() && base::StringToInt(expiration, &time_to_live)) {
     IdentityTokenCacheValue token_value(
@@ -637,6 +687,12 @@ void IdentityGetAuthTokenFunction::OnGetTokenSuccess(
     const OAuth2TokenService::Request* request,
     const std::string& access_token,
     const base::Time& expiration_time) {
+  TRACE_EVENT_ASYNC_STEP_PAST1("identity",
+                               "IdentityGetAuthTokenFunction",
+                               this,
+                               "OnGetTokenSuccess",
+                               "account",
+                               request->GetAccountId());
   login_token_request_.reset();
   StartGaiaRequest(access_token);
 }
@@ -644,6 +700,12 @@ void IdentityGetAuthTokenFunction::OnGetTokenSuccess(
 void IdentityGetAuthTokenFunction::OnGetTokenFailure(
     const OAuth2TokenService::Request* request,
     const GoogleServiceAuthError& error) {
+  TRACE_EVENT_ASYNC_STEP_PAST1("identity",
+                               "IdentityGetAuthTokenFunction",
+                               this,
+                               "OnGetTokenFailure",
+                               "error",
+                               error.ToString());
   login_token_request_.reset();
   OnGaiaFlowFailure(GaiaWebAuthFlow::SERVICE_AUTH_ERROR, error, std::string());
 }
diff --git a/chrome/browser/extensions/api/identity/identity_mint_queue.cc b/chrome/browser/extensions/api/identity/identity_mint_queue.cc
index a6131ab..5103e02 100644
--- a/chrome/browser/extensions/api/identity/identity_mint_queue.cc
+++ b/chrome/browser/extensions/api/identity/identity_mint_queue.cc
@@ -4,6 +4,7 @@
 
 #include "chrome/browser/extensions/api/identity/identity_mint_queue.h"
 
+#include "base/debug/trace_event.h"
 #include "base/logging.h"
 #include "base/stl_util.h"
 
@@ -31,28 +32,40 @@ void IdentityMintRequestQueue::RequestStart(
     IdentityMintRequestQueue::MintType type,
     const ExtensionTokenKey& key,
     IdentityMintRequestQueue::Request* request) {
+  TRACE_EVENT_ASYNC_BEGIN1(
+      "identity", "IdentityMintRequestQueue", request, "type", type);
   RequestQueue& request_queue = GetRequestQueueMap(type)[key];
   request_queue.push_back(request);
   // If this is the first request, start it now. RequestComplete will start
   // all other requests.
   if (request_queue.size() == 1)
-    request_queue.front()->StartMintToken(type);
+    RunRequest(type, request_queue);
 }
 
 void IdentityMintRequestQueue::RequestComplete(
     IdentityMintRequestQueue::MintType type,
     const ExtensionTokenKey& key,
     IdentityMintRequestQueue::Request* request) {
+  TRACE_EVENT_ASYNC_END1("identity",
+                         "IdentityMintRequestQueue",
+                         request,
+                         "completed",
+                         "RequestComplete");
   RequestQueue& request_queue = GetRequestQueueMap(type)[key];
   CHECK_EQ(request_queue.front(), request);
   request_queue.pop_front();
   if (request_queue.size() > 0)
-    request_queue.front()->StartMintToken(type);
+    RunRequest(type, request_queue);
 }
 
 void IdentityMintRequestQueue::RequestCancel(
     const ExtensionTokenKey& key,
     IdentityMintRequestQueue::Request* request) {
+  TRACE_EVENT_ASYNC_END1("identity",
+                         "IdentityMintRequestQueue",
+                         request,
+                         "completed",
+                         "RequestCancel");
   GetRequestQueueMap(MINT_TYPE_INTERACTIVE)[key].remove(request);
   GetRequestQueueMap(MINT_TYPE_NONINTERACTIVE)[key].remove(request);
 }
@@ -71,4 +84,12 @@ IdentityMintRequestQueue::GetRequestQueueMap(
                                          : noninteractive_request_queue_map_;
 }
 
+void IdentityMintRequestQueue::RunRequest(
+    IdentityMintRequestQueue::MintType type,
+    RequestQueue& request_queue) {
+  TRACE_EVENT_ASYNC_STEP_INTO0(
+      "identity", "IdentityMintRequestQueue", request_queue.front(), "RUNNING");
+  request_queue.front()->StartMintToken(type);
+}
+
 }  // namespace extensions
diff --git a/chrome/browser/extensions/api/identity/identity_mint_queue.h b/chrome/browser/extensions/api/identity/identity_mint_queue.h
index dc6c406..e2a0b01 100644
--- a/chrome/browser/extensions/api/identity/identity_mint_queue.h
+++ b/chrome/browser/extensions/api/identity/identity_mint_queue.h
@@ -61,6 +61,8 @@ class IdentityMintRequestQueue {
   typedef std::map<const ExtensionTokenKey, RequestQueue> RequestQueueMap;
 
   RequestQueueMap& GetRequestQueueMap(IdentityMintRequestQueue::MintType type);
+  void RunRequest(IdentityMintRequestQueue::MintType type,
+                  RequestQueue& request_queue);
 
   RequestQueueMap interactive_request_queue_map_;
   RequestQueueMap noninteractive_request_queue_map_;
diff --git a/chrome/browser/extensions/api/identity/web_auth_flow.cc b/chrome/browser/extensions/api/identity/web_auth_flow.cc
index 0619381..fcba514 100644
--- a/chrome/browser/extensions/api/identity/web_auth_flow.cc
+++ b/chrome/browser/extensions/api/identity/web_auth_flow.cc
@@ -6,6 +6,7 @@
 
 #include "apps/app_window.h"
 #include "base/base64.h"
+#include "base/debug/trace_event.h"
 #include "base/location.h"
 #include "base/message_loop/message_loop.h"
 #include "base/strings/string_util.h"
@@ -221,6 +222,12 @@ void WebAuthFlow::DidFailProvisionalLoad(
     const GURL& validated_url,
     int error_code,
     const base::string16& error_description) {
+  TRACE_EVENT_ASYNC_STEP_PAST1("identity",
+                               "WebAuthFlow",
+                               this,
+                               "DidFailProvisionalLoad",
+                               "error_code",
+                               error_code);
   if (delegate_)
     delegate_->OnAuthFlowFailure(LOAD_FAILED);
 }