Password manager: introduce logging for the internals page

Follow-up CL of https://codereview.chromium.org/228263004/

This CL adds instances of SavePasswordProgressLogger into crucial parts of the password manager code. After this CL, the logging should already work, i.e., when the command line flag is enabled, the internals page should show debugging info about saving a password on a website.

More context in the design doc: https://docs.google.com/document/d/1ArDhTo0w-8tOPiTwqM1gG6ZGqODo8UTpXlJjjnCNK4s/edit?usp=sharing

BUG=347927

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

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

5 files changed, 229 insertions, 4 deletions

diff --git a/components/autofill/content/common/autofill_messages.h b/components/autofill/content/common/autofill_messages.h
index d189192..fde4a9f 100644
--- a/components/autofill/content/common/autofill_messages.h
+++ b/components/autofill/content/common/autofill_messages.h
@@ -113,6 +113,10 @@ IPC_MESSAGE_ROUTED2(AutofillMsg_PreviewForm,
 IPC_MESSAGE_ROUTED1(AutofillMsg_FillPasswordForm,
                     autofill::PasswordFormFillData /* the fill form data*/)
 
+// Notification to start (|active| == true) or stop (|active| == false) logging
+// the decisions made about saving the password.
+IPC_MESSAGE_ROUTED1(AutofillMsg_ChangeLoggingState, bool /* active */)
+
 // Send the heuristic and server field type predictions to the renderer.
 IPC_MESSAGE_ROUTED1(
     AutofillMsg_FieldTypePredictionsAvailable,
diff --git a/components/autofill/content/renderer/password_autofill_agent.cc b/components/autofill/content/renderer/password_autofill_agent.cc
index b8b33d3..6667a9d 100644
--- a/components/autofill/content/renderer/password_autofill_agent.cc
+++ b/components/autofill/content/renderer/password_autofill_agent.cc
@@ -12,6 +12,7 @@
 #include "components/autofill/content/common/autofill_messages.h"
 #include "components/autofill/content/renderer/form_autofill_util.h"
 #include "components/autofill/content/renderer/password_form_conversion_utils.h"
+#include "components/autofill/content/renderer/renderer_save_password_progress_logger.h"
 #include "components/autofill/core/common/form_field_data.h"
 #include "components/autofill/core/common/password_autofill_util.h"
 #include "components/autofill/core/common/password_form.h"
@@ -30,6 +31,7 @@
 #include "third_party/WebKit/public/web/WebUserGestureIndicator.h"
 #include "third_party/WebKit/public/web/WebView.h"
 #include "ui/events/keycodes/keyboard_codes.h"
+#include "url/gurl.h"
 
 namespace autofill {
 namespace {
@@ -40,6 +42,11 @@ static const size_t kMaximumTextSizeForAutocomplete = 1000;
 // Maps element names to the actual elements to simplify form filling.
 typedef std::map<base::string16, blink::WebInputElement> FormInputElementMap;
 
+// Use the shorter name when referencing SavePasswordProgressLogger::StringID
+// values to spare line breaks. The code provides enough context for that
+// already.
+typedef SavePasswordProgressLogger Logger;
+
 // Utility struct for form lookup and autofill. When we parse the DOM to look up
 // a form, in addition to action and origin URL's we have to compare all
 // necessary form elements. To avoid having to look these up again when we want
@@ -199,6 +206,16 @@ bool PasswordValueIsDefault(const PasswordForm& form,
   return false;
 }
 
+// Log a message including the name, method and action of |form|.
+void LogHTMLForm(SavePasswordProgressLogger* logger,
+                 SavePasswordProgressLogger::StringID message_id,
+                 const blink::WebFormElement& form) {
+  logger->LogHTMLForm(message_id,
+                      form.name().utf8(),
+                      form.method().utf8(),
+                      GURL(form.action().utf8()));
+}
+
 }  // namespace
 
 ////////////////////////////////////////////////////////////////////////////////
@@ -208,6 +225,7 @@ PasswordAutofillAgent::PasswordAutofillAgent(content::RenderView* render_view)
     : content::RenderViewObserver(render_view),
       usernames_usage_(NOTHING_TO_AUTOFILL),
       web_view_(render_view->GetWebView()),
+      logging_state_active_(false),
       weak_ptr_factory_(this) {
 }
 
@@ -411,30 +429,67 @@ void PasswordAutofillAgent::FirstUserGestureObserved() {
 
 void PasswordAutofillAgent::SendPasswordForms(blink::WebFrame* frame,
                                               bool only_visible) {
+  scoped_ptr<RendererSavePasswordProgressLogger> logger;
+  // From the perspective of saving passwords, only calls with |only_visible|
+  // being true are important -- the decision whether to save the password is
+  // only made after visible forms are known, for failed login detection. Calls
+  // with |only_visible| false are important for password form autofill, which
+  // is currently not part of the logging.
+  if (only_visible && logging_state_active_) {
+    logger.reset(new RendererSavePasswordProgressLogger(this, routing_id()));
+    logger->LogMessage(Logger::STRING_SEND_PASSWORD_FORMS_METHOD);
+  }
+
   // Make sure that this security origin is allowed to use password manager.
   blink::WebSecurityOrigin origin = frame->document().securityOrigin();
-  if (!OriginCanAccessPasswordManager(origin))
+  if (logger) {
+    logger->LogURL(Logger::STRING_SECURITY_ORIGIN,
+                   GURL(origin.toString().utf8()));
+  }
+  if (!OriginCanAccessPasswordManager(origin)) {
+    if (logger) {
+      logger->LogMessage(Logger::STRING_SECURITY_ORIGIN_FAILURE);
+      logger->LogMessage(Logger::STRING_DECISION_DROP);
+    }
     return;
+  }
 
   // Checks whether the webpage is a redirect page or an empty page.
-  if (IsWebpageEmpty(frame))
+  if (IsWebpageEmpty(frame)) {
+    if (logger) {
+      logger->LogMessage(Logger::STRING_WEBPAGE_EMPTY);
+      logger->LogMessage(Logger::STRING_DECISION_DROP);
+    }
     return;
+  }
 
   blink::WebVector<blink::WebFormElement> forms;
   frame->document().forms(forms);
+  if (logger)
+    logger->LogNumber(Logger::STRING_NUMBER_OF_ALL_FORMS, forms.size());
 
   std::vector<PasswordForm> password_forms;
   for (size_t i = 0; i < forms.size(); ++i) {
     const blink::WebFormElement& form = forms[i];
+    bool is_form_visible = IsWebNodeVisible(form);
+    if (logger) {
+      LogHTMLForm(logger.get(), Logger::STRING_FORM_FOUND_ON_PAGE, form);
+      logger->LogBoolean(Logger::STRING_FORM_IS_VISIBLE, is_form_visible);
+    }
 
     // If requested, ignore non-rendered forms, e.g. those styled with
     // display:none.
-    if (only_visible && !IsWebNodeVisible(form))
+    if (only_visible && !is_form_visible)
       continue;
 
     scoped_ptr<PasswordForm> password_form(CreatePasswordForm(form));
-    if (password_form.get())
+    if (password_form.get()) {
+      if (logger) {
+        logger->LogPasswordForm(Logger::STRING_FORM_IS_PASSWORD,
+                                *password_form);
+      }
       password_forms.push_back(*password_form);
+    }
   }
 
   if (password_forms.empty() && !only_visible) {
@@ -456,6 +511,7 @@ bool PasswordAutofillAgent::OnMessageReceived(const IPC::Message& message) {
   bool handled = true;
   IPC_BEGIN_MESSAGE_MAP(PasswordAutofillAgent, message)
     IPC_MESSAGE_HANDLER(AutofillMsg_FillPasswordForm, OnFillPasswordForm)
+    IPC_MESSAGE_HANDLER(AutofillMsg_ChangeLoggingState, OnChangeLoggingState)
     IPC_MESSAGE_UNHANDLED(handled = false)
   IPC_END_MESSAGE_MAP()
   return handled;
@@ -507,6 +563,13 @@ void PasswordAutofillAgent::WillSendSubmitEvent(
 
 void PasswordAutofillAgent::WillSubmitForm(blink::WebLocalFrame* frame,
                                            const blink::WebFormElement& form) {
+  scoped_ptr<RendererSavePasswordProgressLogger> logger;
+  if (logging_state_active_) {
+    logger.reset(new RendererSavePasswordProgressLogger(this, routing_id()));
+    logger->LogMessage(Logger::STRING_WILL_SUBMIT_FORM_METHOD);
+    LogHTMLForm(logger.get(), Logger::STRING_HTML_FORM_FOR_SUBMIT, form);
+  }
+
   scoped_ptr<PasswordForm> submitted_form = CreatePasswordForm(form);
 
   // If there is a provisionally saved password, copy over the previous
@@ -515,8 +578,14 @@ void PasswordAutofillAgent::WillSubmitForm(blink::WebLocalFrame* frame,
   // TODO(gcasto): Do we need to have this action equality check? Is it trying
   // to prevent accidentally copying over passwords from a different form?
   if (submitted_form) {
+    if (logger) {
+      logger->LogPasswordForm(Logger::STRING_CREATED_PASSWORD_FORM,
+                              *submitted_form);
+    }
     if (provisionally_saved_forms_[frame].get() &&
         submitted_form->action == provisionally_saved_forms_[frame]->action) {
+      if (logger)
+        logger->LogMessage(Logger::STRING_SUBMITTED_PASSWORD_REPLACED);
       submitted_form->password_value =
           provisionally_saved_forms_[frame]->password_value;
     }
@@ -529,6 +598,8 @@ void PasswordAutofillAgent::WillSubmitForm(blink::WebLocalFrame* frame,
                                                    *submitted_form));
     // Remove reference since we have already submitted this form.
     provisionally_saved_forms_.erase(frame);
+  } else if (logger) {
+    logger->LogMessage(Logger::STRING_DECISION_DROP);
   }
 }
 
@@ -555,6 +626,12 @@ blink::WebFrame* PasswordAutofillAgent::CurrentOrChildFrameWithSavedForms(
 
 void PasswordAutofillAgent::DidStartProvisionalLoad(
     blink::WebLocalFrame* frame) {
+  scoped_ptr<RendererSavePasswordProgressLogger> logger;
+  if (logging_state_active_) {
+    logger.reset(new RendererSavePasswordProgressLogger(this, routing_id()));
+    logger->LogMessage(Logger::STRING_DID_START_PROVISIONAL_LOAD_METHOD);
+  }
+
   if (!frame->parent()) {
     // If the navigation is not triggered by a user gesture, e.g. by some ajax
     // callback, then inherit the submitted password form from the previous
@@ -562,9 +639,18 @@ void PasswordAutofillAgent::DidStartProvisionalLoad(
     // [http://crbug/43219]. Note that this still fails for sites that use
     // synchonous XHR as isProcessingUserGesture() will return true.
     blink::WebFrame* form_frame = CurrentOrChildFrameWithSavedForms(frame);
+    if (logger) {
+      logger->LogBoolean(Logger::STRING_FORM_FRAME_EQ_FRAME,
+                         form_frame == frame);
+    }
     if (!blink::WebUserGestureIndicator::isProcessingUserGesture()) {
       // If onsubmit has been called, try and save that form.
       if (provisionally_saved_forms_[form_frame].get()) {
+        if (logger) {
+          logger->LogPasswordForm(
+              Logger::STRING_PROVISIONALLY_SAVED_FORM_FOR_FRAME,
+              *provisionally_saved_forms_[form_frame]);
+        }
         Send(new AutofillHostMsg_PasswordFormSubmitted(
             routing_id(), *provisionally_saved_forms_[form_frame]));
         provisionally_saved_forms_.erase(form_frame);
@@ -574,17 +660,30 @@ void PasswordAutofillAgent::DidStartProvisionalLoad(
         blink::WebVector<blink::WebFormElement> forms;
         frame->document().forms(forms);
 
+        bool password_forms_found = false;
         for (size_t i = 0; i < forms.size(); ++i) {
           blink::WebFormElement form_element = forms[i];
+          if (logger) {
+            LogHTMLForm(
+                logger.get(), Logger::STRING_FORM_FOUND_ON_PAGE, form_element);
+          }
           scoped_ptr<PasswordForm> password_form(
               CreatePasswordForm(form_element));
           if (password_form.get() && !password_form->username_value.empty() &&
               !password_form->password_value.empty() &&
               !PasswordValueIsDefault(*password_form, form_element)) {
+            password_forms_found = true;
+            if (logger) {
+              logger->LogPasswordForm(
+                  Logger::STRING_PASSWORD_FORM_FOUND_ON_PAGE, *password_form);
+            }
             Send(new AutofillHostMsg_PasswordFormSubmitted(routing_id(),
                                                            *password_form));
           }
         }
+        if (!password_forms_found && logger) {
+          logger->LogMessage(Logger::STRING_DECISION_DROP);
+        }
       }
     }
     // Clear the whole map during main frame navigation.
@@ -593,6 +692,9 @@ void PasswordAutofillAgent::DidStartProvisionalLoad(
     // This is a new navigation, so require a new user gesture before filling in
     // passwords.
     gatekeeper_.Reset();
+  } else {
+    if (logger)
+      logger->LogMessage(Logger::STRING_DECISION_DROP);
   }
 }
 
@@ -647,6 +749,10 @@ void PasswordAutofillAgent::OnFillPasswordForm(
   }
 }
 
+void PasswordAutofillAgent::OnChangeLoggingState(bool active) {
+  logging_state_active_ = active;
+}
+
 ////////////////////////////////////////////////////////////////////////////////
 // PasswordAutofillAgent, private:
 
diff --git a/components/autofill/content/renderer/password_autofill_agent.h b/components/autofill/content/renderer/password_autofill_agent.h
index 2e45d46..24a7aa9 100644
--- a/components/autofill/content/renderer/password_autofill_agent.h
+++ b/components/autofill/content/renderer/password_autofill_agent.h
@@ -130,6 +130,7 @@ class PasswordAutofillAgent : public content::RenderViewObserver {
 
   // RenderView IPC handlers:
   void OnFillPasswordForm(const PasswordFormFillData& form_data);
+  void OnChangeLoggingState(bool active);
 
   // Scans the given frame for password forms and sends them up to the browser.
   // If |only_visible| is true, only forms visible in the layout are sent.
@@ -195,6 +196,9 @@ class PasswordAutofillAgent : public content::RenderViewObserver {
 
   PasswordValueGatekeeper gatekeeper_;
 
+  // True indicates that user debug information should be logged.
+  bool logging_state_active_;
+
   base::WeakPtrFactory<PasswordAutofillAgent> weak_ptr_factory_;
 
   DISALLOW_COPY_AND_ASSIGN(PasswordAutofillAgent);
diff --git a/components/autofill/core/common/save_password_progress_logger.cc b/components/autofill/core/common/save_password_progress_logger.cc
index 5f051ccf..984a08c 100644
--- a/components/autofill/core/common/save_password_progress_logger.cc
+++ b/components/autofill/core/common/save_password_progress_logger.cc
@@ -87,6 +87,80 @@ std::string GetStringFromID(SavePasswordProgressLogger::StringID id) {
       return "Form name or ID";
     case SavePasswordProgressLogger::STRING_MESSAGE:
       return "Message";
+    case SavePasswordProgressLogger::STRING_SET_AUTH_METHOD:
+      return "LoginHandler::SetAuth";
+    case SavePasswordProgressLogger::STRING_AUTHENTICATION_HANDLED:
+      return "Authentication already handled";
+    case SavePasswordProgressLogger::STRING_LOGINHANDLER_FORM:
+      return "LoginHandler reports this form";
+    case SavePasswordProgressLogger::STRING_SEND_PASSWORD_FORMS_METHOD:
+      return "PasswordAutofillAgent::SendPasswordForms";
+    case SavePasswordProgressLogger::STRING_SECURITY_ORIGIN:
+      return "Security origin";
+    case SavePasswordProgressLogger::STRING_SECURITY_ORIGIN_FAILURE:
+      return "Security origin cannot access password manager.";
+    case SavePasswordProgressLogger::STRING_WEBPAGE_EMPTY:
+      return "Webpage is empty.";
+    case SavePasswordProgressLogger::STRING_NUMBER_OF_ALL_FORMS:
+      return "Number of all forms";
+    case SavePasswordProgressLogger::STRING_FORM_FOUND_ON_PAGE:
+      return "Form found on page";
+    case SavePasswordProgressLogger::STRING_FORM_IS_VISIBLE:
+      return "Form is visible";
+    case SavePasswordProgressLogger::STRING_FORM_IS_PASSWORD:
+      return "Form is a password form";
+    case SavePasswordProgressLogger::STRING_WILL_SUBMIT_FORM_METHOD:
+      return "PasswordAutofillAgent::WillSubmitForm";
+    case SavePasswordProgressLogger::STRING_HTML_FORM_FOR_SUBMIT:
+      return "HTML form for submit";
+    case SavePasswordProgressLogger::STRING_CREATED_PASSWORD_FORM:
+      return "Created PasswordForm";
+    case SavePasswordProgressLogger::STRING_SUBMITTED_PASSWORD_REPLACED:
+      return "Submitted password replaced with the provisionally saved one.";
+    case SavePasswordProgressLogger::STRING_DID_START_PROVISIONAL_LOAD_METHOD:
+      return "PasswordAutofillAgent::DidStartProvisionalLoad";
+    case SavePasswordProgressLogger::STRING_FORM_FRAME_EQ_FRAME:
+      return "form_frame == frame";
+    case SavePasswordProgressLogger::STRING_PROVISIONALLY_SAVED_FORM_FOR_FRAME:
+      return "provisionally_saved_forms_[form_frame]";
+    case SavePasswordProgressLogger::STRING_PASSWORD_FORM_FOUND_ON_PAGE:
+      return "PasswordForm found on the page";
+    case SavePasswordProgressLogger::STRING_PROVISIONALLY_SAVE_PASSWORD_METHOD:
+      return "PasswordManager::ProvisionallySavePassword";
+    case SavePasswordProgressLogger::STRING_PROVISIONALLY_SAVE_PASSWORD_FORM:
+      return "ProvisionallySavePassword form";
+    case SavePasswordProgressLogger::STRING_IS_SAVING_ENABLED:
+      return "IsSavingEnabled";
+    case SavePasswordProgressLogger::STRING_EMPTY_PASSWORD:
+      return "Empty password";
+    case SavePasswordProgressLogger::STRING_EXACT_MATCH:
+      return "Form manager found, exact match.";
+    case SavePasswordProgressLogger::STRING_MATCH_WITHOUT_ACTION:
+      return "Form manager found, match except for action.";
+    case SavePasswordProgressLogger::STRING_NO_FORM_MANAGER:
+      return "No form manager found.";
+    case SavePasswordProgressLogger::STRING_FORM_BLACKLISTED:
+      return "Form blacklisted.";
+    case SavePasswordProgressLogger::STRING_INVALID_FORM:
+      return "Invalid form.";
+    case SavePasswordProgressLogger::STRING_AUTOCOMPLETE_OFF:
+      return "Autocomplete=off.";
+    case SavePasswordProgressLogger::STRING_PROVISIONALLY_SAVED_FORM:
+      return "provisionally_saved_form";
+    case SavePasswordProgressLogger::STRING_IGNORE_POSSIBLE_USERNAMES:
+      return "Ignore other possible usernames";
+    case SavePasswordProgressLogger::STRING_ON_PASSWORD_FORMS_RENDERED_METHOD:
+      return "PasswordManager::OnPasswordFormsRendered";
+    case SavePasswordProgressLogger::STRING_NO_PROVISIONAL_SAVE_MANAGER:
+      return "No provisional save manager";
+    case SavePasswordProgressLogger::STRING_NUMBER_OF_VISIBLE_FORMS:
+      return "Number of visible forms";
+    case SavePasswordProgressLogger::STRING_PASSWORD_FORM_REAPPEARED:
+      return "Password form re-appeared";
+    case SavePasswordProgressLogger::STRING_SAVING_DISABLED:
+      return "Saving disabled";
+    case SavePasswordProgressLogger::STRING_NO_MATCHING_FORM:
+      return "No matching form";
     case SavePasswordProgressLogger::STRING_INVALID:
       return "INVALID";
       // Intentionally no default: clause here -- all IDs need to get covered.
diff --git a/components/autofill/core/common/save_password_progress_logger.h b/components/autofill/core/common/save_password_progress_logger.h
index d5b98ad..c8a4360 100644
--- a/components/autofill/core/common/save_password_progress_logger.h
+++ b/components/autofill/core/common/save_password_progress_logger.h
@@ -62,6 +62,43 @@ class SavePasswordProgressLogger {
     STRING_PSL_MATCH,
     STRING_NAME_OR_ID,
     STRING_MESSAGE,
+    STRING_SET_AUTH_METHOD,
+    STRING_AUTHENTICATION_HANDLED,
+    STRING_LOGINHANDLER_FORM,
+    STRING_SEND_PASSWORD_FORMS_METHOD,
+    STRING_SECURITY_ORIGIN,
+    STRING_SECURITY_ORIGIN_FAILURE,
+    STRING_WEBPAGE_EMPTY,
+    STRING_NUMBER_OF_ALL_FORMS,
+    STRING_FORM_FOUND_ON_PAGE,
+    STRING_FORM_IS_VISIBLE,
+    STRING_FORM_IS_PASSWORD,
+    STRING_WILL_SUBMIT_FORM_METHOD,
+    STRING_HTML_FORM_FOR_SUBMIT,
+    STRING_CREATED_PASSWORD_FORM,
+    STRING_SUBMITTED_PASSWORD_REPLACED,
+    STRING_DID_START_PROVISIONAL_LOAD_METHOD,
+    STRING_FORM_FRAME_EQ_FRAME,
+    STRING_PROVISIONALLY_SAVED_FORM_FOR_FRAME,
+    STRING_PASSWORD_FORM_FOUND_ON_PAGE,
+    STRING_PROVISIONALLY_SAVE_PASSWORD_METHOD,
+    STRING_PROVISIONALLY_SAVE_PASSWORD_FORM,
+    STRING_IS_SAVING_ENABLED,
+    STRING_EMPTY_PASSWORD,
+    STRING_EXACT_MATCH,
+    STRING_MATCH_WITHOUT_ACTION,
+    STRING_NO_FORM_MANAGER,
+    STRING_FORM_BLACKLISTED,
+    STRING_INVALID_FORM,
+    STRING_AUTOCOMPLETE_OFF,
+    STRING_PROVISIONALLY_SAVED_FORM,
+    STRING_IGNORE_POSSIBLE_USERNAMES,
+    STRING_ON_PASSWORD_FORMS_RENDERED_METHOD,
+    STRING_NO_PROVISIONAL_SAVE_MANAGER,
+    STRING_NUMBER_OF_VISIBLE_FORMS,
+    STRING_PASSWORD_FORM_REAPPEARED,
+    STRING_SAVING_DISABLED,
+    STRING_NO_MATCHING_FORM,
     STRING_INVALID,  // Represents a string returned in a case of an error.
     STRING_MAX = STRING_INVALID
   };