Password manager: introduce logging for the internals page

components/autofill/content/renderer/password_autofill_agent.cc

Index: components/autofill/content/renderer/password_autofill_agent.cc
diff --git a/components/autofill/content/renderer/password_autofill_agent.cc b/components/autofill/content/renderer/password_autofill_agent.cc
index 4f25414cbe1a6f9de1852bacf154da3609ac6241..e63c991eadf7627e43f8111eac47f5531db6d9ae 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"
@@ -31,6 +32,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 {
@@ -41,6 +43,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
@@ -200,6 +207,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
 
 ////////////////////////////////////////////////////////////////////////////////
@@ -209,6 +226,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) {
 }
 
@@ -412,30 +430,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) {
@@ -457,6 +512,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;
@@ -508,6 +564,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
@@ -516,8 +579,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;
     }
@@ -530,6 +599,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);
   }
 }
 
@@ -556,6 +627,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
@@ -563,9 +640,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);
@@ -575,17 +661,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.
@@ -594,6 +693,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);
   }
 }
 
@@ -648,6 +750,10 @@ void PasswordAutofillAgent::OnFillPasswordForm(
   }
 }
 
+void PasswordAutofillAgent::OnChangeLoggingState(bool active) {
+  logging_state_active_ = active;
+}
+
 ////////////////////////////////////////////////////////////////////////////////
 // PasswordAutofillAgent, private: