Password manager: introduce logging for the internals page

components/password_manager/core/browser/password_manager.cc

Index: components/password_manager/core/browser/password_manager.cc
diff --git a/components/password_manager/core/browser/password_manager.cc b/components/password_manager/core/browser/password_manager.cc
index 1ab931f4684effabaff119fa0b6362237492a0c5..7fdf421f340d641d69a6d56410507867e29662e9 100644
--- a/components/password_manager/core/browser/password_manager.cc
+++ b/components/password_manager/core/browser/password_manager.cc
@@ -12,6 +12,7 @@
 #include "base/strings/utf_string_conversions.h"
 #include "base/threading/platform_thread.h"
 #include "components/autofill/core/common/password_autofill_util.h"
+#include "components/password_manager/core/browser/browser_save_password_progress_logger.h"
 #include "components/password_manager/core/browser/password_form_manager.h"
 #include "components/password_manager/core/browser/password_manager_client.h"
 #include "components/password_manager/core/browser/password_manager_driver.h"
@@ -28,6 +29,10 @@ namespace {
 
 const char kSpdyProxyRealm[] = "/SpdyProxy";
 
+// Shorten the name to spare line breaks. The code provides enough context
+// already.
+typedef autofill::SavePasswordProgressLogger Logger;
+
 // This routine is called when PasswordManagers are constructed.
 //
 // Currently we report metrics only once at startup. We require
@@ -84,9 +89,9 @@ PasswordManager::~PasswordManager() {
 void PasswordManager::SetFormHasGeneratedPassword(const PasswordForm& form) {
   for (ScopedVector<PasswordFormManager>::iterator iter =
            pending_login_managers_.begin();
-       iter != pending_login_managers_.end(); ++iter) {
-    if ((*iter)->DoesManage(
-        form, PasswordFormManager::ACTION_MATCH_REQUIRED)) {
+       iter != pending_login_managers_.end();
+       ++iter) {
+    if ((*iter)->DoesManage(form, PasswordFormManager::ACTION_MATCH_REQUIRED)) {
       (*iter)->SetHasGeneratedPassword();
       return;
     }
@@ -96,8 +101,8 @@ void PasswordManager::SetFormHasGeneratedPassword(const PasswordForm& form) {
   // ability to detect forms.
   bool ssl_valid = (form.origin.SchemeIsSecure() &&
                     !driver_->DidLastPageLoadEncounterSSLErrors());
-  PasswordFormManager* manager = new PasswordFormManager(
-      this, client_, driver_, form, ssl_valid);
+  PasswordFormManager* manager =
+      new PasswordFormManager(this, client_, driver_, form, ssl_valid);
   pending_login_managers_.push_back(manager);
   manager->SetHasGeneratedPassword();
   // TODO(gcasto): Add UMA stats to track this.
@@ -108,14 +113,32 @@ bool PasswordManager::IsSavingEnabled() const {
 }
 
 void PasswordManager::ProvisionallySavePassword(const PasswordForm& form) {
-  if (!IsSavingEnabled()) {
+  bool is_saving_enabled = IsSavingEnabled();
+
+  scoped_ptr<password_manager::BrowserSavePasswordProgressLogger> logger;
+  if (client_->IsLoggingActive()) {
+    logger.reset(
+        new password_manager::BrowserSavePasswordProgressLogger(client_));
+    logger->LogMessage(Logger::STRING_PROVISIONALLY_SAVE_PASSWORD_METHOD);
+    logger->LogPasswordForm(Logger::STRING_PROVISIONALLY_SAVE_PASSWORD_FORM,
+                            form);
+    logger->LogBoolean(Logger::STRING_IS_SAVING_ENABLED, is_saving_enabled);
+  }
+
+  if (!is_saving_enabled) {
     RecordFailure(SAVING_DISABLED, form.origin.host());
+    if (logger)
+      logger->LogMessage(Logger::STRING_DECISION_DROP);
     return;
   }
 
   // No password to save? Then don't.
   if (form.password_value.empty()) {
     RecordFailure(EMPTY_PASSWORD, form.origin.host());
+    if (logger) {
+      logger->LogMessage(Logger::STRING_EMPTY_PASSWORD);
+      logger->LogMessage(Logger::STRING_DECISION_DROP);
+    }
     return;
   }
 
@@ -124,18 +147,23 @@ void PasswordManager::ProvisionallySavePassword(const PasswordForm& form) {
       pending_login_managers_.end();
   for (ScopedVector<PasswordFormManager>::iterator iter =
            pending_login_managers_.begin();
-       iter != pending_login_managers_.end(); ++iter) {
+       iter != pending_login_managers_.end();
+       ++iter) {
     // If we find a manager that exactly matches the submitted form including
     // the action URL, exit the loop.
-    if ((*iter)->DoesManage(
-        form, PasswordFormManager::ACTION_MATCH_REQUIRED)) {
+    if ((*iter)->DoesManage(form, PasswordFormManager::ACTION_MATCH_REQUIRED)) {
+      if (logger)
+        logger->LogMessage(Logger::STRING_EXACT_MATCH);
       matched_manager_it = iter;
       break;
-    // If the current manager matches the submitted form excluding the action
-    // URL, remember it as a candidate and continue searching for an exact
-    // match.
+      // If the current manager matches the submitted form excluding the action
+      // URL, remember it as a candidate and continue searching for an exact
+      // match.

[Ilya Sherman, 2014/04/23 20:21:44]

The previous alignment for this comment was better.  Alternately, we can move
this comment into the else-stmt, or somewhere else reasonable.  But it's not
really within the if-stmt.

[vabr (Chromium), 2014/04/24 10:59:27]

Thanks for catching this.
I moved this comment inside the else-if block, and similarly with the comment
preceding the if block -- that will ensure that running clang-format will not
break this in the future.

     } else if ((*iter)->DoesManage(
-        form, PasswordFormManager::ACTION_MATCH_NOT_REQUIRED)) {
+                   form, PasswordFormManager::ACTION_MATCH_NOT_REQUIRED)) {
+      if (logger) {
+        logger->LogMessage(Logger::STRING_MATCH_WITHOUT_ACTION);
+      }

[Ilya Sherman, 2014/04/23 20:21:44]

nit: No need for curly braces

[vabr (Chromium), 2014/04/24 10:59:27]

Done.

       matched_manager_it = iter;
     }
   }
@@ -158,6 +186,10 @@ void PasswordManager::ProvisionallySavePassword(const PasswordForm& form) {
   // give up.
   if (!manager->HasCompletedMatching()) {
     RecordFailure(MATCHING_NOT_COMPLETE, form.origin.host());
+    if (logger) {
+      logger->LogMessage(Logger::STRING_NO_FORM_MANAGER);
+      logger->LogMessage(Logger::STRING_DECISION_DROP);
+    }
     return;
   }
 
@@ -165,12 +197,20 @@ void PasswordManager::ProvisionallySavePassword(const PasswordForm& form) {
   // this form.
   if (manager->IsBlacklisted()) {
     RecordFailure(FORM_BLACKLISTED, form.origin.host());
+    if (logger) {
+      logger->LogMessage(Logger::STRING_FORM_BLACKLISTED);
+      logger->LogMessage(Logger::STRING_DECISION_DROP);

[Ilya Sherman, 2014/04/23 20:21:44]

nit: Maybe it makes sense to move the logging into RecordFailure?

[vabr (Chromium), 2014/04/24 10:59:27]

That's a great idea! Done.

+    }
     return;
   }
 
   // Bail if we're missing any of the necessary form components.
   if (!manager->HasValidPasswordForm()) {
     RecordFailure(INVALID_FORM, form.origin.host());
+    if (logger) {
+      logger->LogMessage(Logger::STRING_INVALID_FORM);
+      logger->LogMessage(Logger::STRING_DECISION_DROP);
+    }
     return;
   }
 
@@ -178,9 +218,12 @@ void PasswordManager::ProvisionallySavePassword(const PasswordForm& form) {
   // Chrome to manage such passwords. For other passwords, respect the
   // autocomplete attribute if autocomplete='off' is not ignored.
   if (!autofill::ShouldIgnoreAutocompleteOffForPasswordFields() &&
-      !manager->HasGeneratedPassword() &&
-      !form.password_autocomplete_set) {
+      !manager->HasGeneratedPassword() && !form.password_autocomplete_set) {
     RecordFailure(AUTOCOMPLETE_OFF, form.origin.host());
+    if (logger) {
+      logger->LogMessage(Logger::STRING_AUTOCOMPLETE_OFF);
+      logger->LogMessage(Logger::STRING_DECISION_DROP);
+    }
     return;
   }
 
@@ -189,18 +232,27 @@ void PasswordManager::ProvisionallySavePassword(const PasswordForm& form) {
       form.origin.SchemeIsSecure() &&
       !driver_->DidLastPageLoadEncounterSSLErrors();
   provisionally_saved_form.preferred = true;
+  if (logger) {
+    logger->LogPasswordForm(Logger::STRING_PROVISIONALLY_SAVED_FORM,
+                            provisionally_saved_form);
+  }
   PasswordFormManager::OtherPossibleUsernamesAction action =
       PasswordFormManager::IGNORE_OTHER_POSSIBLE_USERNAMES;
   if (OtherPossibleUsernamesEnabled())
     action = PasswordFormManager::ALLOW_OTHER_POSSIBLE_USERNAMES;
+  if (logger) {
+    logger->LogBoolean(
+        Logger::STRING_IGNORE_POSSIBLE_USERNAMES,
+        action == PasswordFormManager::IGNORE_OTHER_POSSIBLE_USERNAMES);
+  }
   manager->ProvisionallySave(provisionally_saved_form, action);
   provisional_save_manager_.swap(manager);
 }
 
 void PasswordManager::RecordFailure(ProvisionalSaveFailure failure,
                                     const std::string& form_origin) {
-  UMA_HISTOGRAM_ENUMERATION("PasswordManager.ProvisionalSaveFailure",
-                            failure, MAX_FAILURE_VALUE);
+  UMA_HISTOGRAM_ENUMERATION(
+      "PasswordManager.ProvisionalSaveFailure", failure, MAX_FAILURE_VALUE);
 
   std::string group_name = metrics_util::GroupIdToString(
       metrics_util::MonitoredDomainGroupId(form_origin, client_->GetPrefs()));
@@ -248,15 +300,16 @@ void PasswordManager::OnPasswordFormsParsed(
   bool had_ssl_error = driver_->DidLastPageLoadEncounterSSLErrors();
 
   for (std::vector<PasswordForm>::const_iterator iter = forms.begin();
-       iter != forms.end(); ++iter) {
+       iter != forms.end();
+       ++iter) {
     // Don't involve the password manager if this form corresponds to
     // SpdyProxy authentication, as indicated by the realm.
     if (EndsWith(iter->signon_realm, kSpdyProxyRealm, true))
       continue;
 
     bool ssl_valid = iter->origin.SchemeIsSecure() && !had_ssl_error;
-    PasswordFormManager* manager = new PasswordFormManager(
-        this, client_, driver_, *iter, ssl_valid);
+    PasswordFormManager* manager =
+        new PasswordFormManager(this, client_, driver_, *iter, ssl_valid);
     pending_login_managers_.push_back(manager);
 
     // Avoid prompting the user for access to a password if they don't have
@@ -277,11 +330,28 @@ bool PasswordManager::ShouldPromptUserToSavePassword() const {
 
 void PasswordManager::OnPasswordFormsRendered(
     const std::vector<PasswordForm>& visible_forms) {
-  if (!provisional_save_manager_.get())
+  scoped_ptr<password_manager::BrowserSavePasswordProgressLogger> logger;
+  if (client_->IsLoggingActive()) {
+    logger.reset(
+        new password_manager::BrowserSavePasswordProgressLogger(client_));
+    logger->LogMessage(Logger::STRING_ON_PASSWORD_FORMS_RENDERED_METHOD);
+  }
+
+  if (!provisional_save_manager_.get()) {
+    if (logger) {
+      logger->LogMessage(Logger::STRING_NO_PROVISIONAL_SAVE_MANAGER);
+      logger->LogMessage(Logger::STRING_DECISION_DROP);
+    }
     return;
+  }
 
   DCHECK(IsSavingEnabled());
 
+  if (logger) {
+    logger->LogNumber(Logger::STRING_NUMBER_OF_VISIBLE_FORMS,
+                      visible_forms.size());
+  }
+
   // If we see the login form again, then the login failed.
   for (size_t i = 0; i < visible_forms.size(); ++i) {
     // TODO(vabr): The similarity check is just action equality for now. If it
@@ -290,6 +360,11 @@ void PasswordManager::OnPasswordFormsRendered(
     if (visible_forms[i].action.is_valid() &&
         provisional_save_manager_->pending_credentials().action ==
             visible_forms[i].action) {
+      if (logger) {
+        logger->LogPasswordForm(Logger::STRING_PASSWORD_FORM_REAPPEARED,
+                                visible_forms[i]);
+        logger->LogMessage(Logger::STRING_DECISION_DROP);
+      }
       provisional_save_manager_->SubmitFailed();
       provisional_save_manager_.reset();
       return;
@@ -303,8 +378,12 @@ void PasswordManager::OnPasswordFormsRendered(
   provisional_save_manager_->SubmitPassed();
 
   if (ShouldPromptUserToSavePassword()) {
+    if (logger)
+      logger->LogMessage(Logger::STRING_DECISION_ASK);
     client_->PromptUserToSavePassword(provisional_save_manager_.release());
   } else {
+    if (logger)
+      logger->LogMessage(Logger::STRING_DECISION_SAVE);
     provisional_save_manager_->Save();
     provisional_save_manager_.reset();
   }
@@ -317,7 +396,8 @@ void PasswordManager::PossiblyInitializeUsernamesExperiment(
 
   bool other_possible_usernames_exist = false;
   for (autofill::PasswordFormMap::const_iterator it = best_matches.begin();
-       it != best_matches.end(); ++it) {
+       it != best_matches.end();
+       ++it) {
     if (!it->second->other_possible_usernames.empty()) {
       other_possible_usernames_exist = true;
       break;
@@ -333,7 +413,9 @@ void PasswordManager::PossiblyInitializeUsernamesExperiment(
           kOtherPossibleUsernamesExperiment,
           kDivisor,
           "Disabled",
-          2013, 12, 31,
+          2013,
+          12,
+          31,

[Ilya Sherman, 2014/04/23 20:21:44]

nit: This seems worse, as it's less obviously a date when spread across three
lines.

[vabr (Chromium), 2014/04/24 10:59:27]

Agreed. Also filed http://b/14285621 to ask if there could be a way to disable
clang-format for particular cases like this.

Also, looks like that trial is past its expiration date. I guess I should file a
bug to get it removed.

           base::FieldTrial::ONE_TIME_RANDOMIZED,
           NULL));
   base::FieldTrial::Probability enabled_probability =
@@ -343,14 +425,13 @@ void PasswordManager::PossiblyInitializeUsernamesExperiment(
 
 bool PasswordManager::OtherPossibleUsernamesEnabled() const {
   return base::FieldTrialList::FindFullName(
-      kOtherPossibleUsernamesExperiment) == "Enabled";
+             kOtherPossibleUsernamesExperiment) == "Enabled";
 }
 
-void PasswordManager::Autofill(
-    const PasswordForm& form_for_autofill,
-    const PasswordFormMap& best_matches,
-    const PasswordForm& preferred_match,
-    bool wait_for_username) const {
+void PasswordManager::Autofill(const PasswordForm& form_for_autofill,
+                               const PasswordFormMap& best_matches,
+                               const PasswordForm& preferred_match,
+                               bool wait_for_username) const {
   PossiblyInitializeUsernamesExperiment(best_matches);
 
   // TODO(tedchoc): Switch to only requesting authentication if the user is
@@ -358,7 +439,8 @@ void PasswordManager::Autofill(
   //                of on page load.
   bool authentication_required = preferred_match.use_additional_authentication;
   for (autofill::PasswordFormMap::const_iterator it = best_matches.begin();
-       !authentication_required && it != best_matches.end(); ++it) {
+       !authentication_required && it != best_matches.end();
+       ++it) {
     if (it->second->use_additional_authentication)
       authentication_required = true;
   }