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 e84e546c6a9ddab9684dc1d2dc0c2e52651184f5..d2606757a12f3f1d38386114e179a62b14b27209 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 {
@@ -201,6 +203,16 @@ bool PasswordValueIsDefault(const PasswordForm& form,
   return false;
 }
 
+void LogHTMLForm(SavePasswordProgressLogger* logger,

[Ilya Sherman, 2014/04/23 05:19:56]

nit: Docs, please.

[vabr (Chromium), 2014/04/23 18:15:35]

Done.

+                 SavePasswordProgressLogger::StringID message_id,
+                 const blink::WebFormElement& form) {
+  DCHECK(logger);

[Ilya Sherman, 2014/04/23 05:19:56]

nit: No need for this DCHECK, since you immediately use the logger below.

[vabr (Chromium), 2014/04/23 18:15:35]

Done.

+  logger->LogHTMLForm(message_id,
+                      form.name().utf8(),
+                      form.method().utf8(),
+                      GURL(form.action().utf8()));
+}
+
 }  // namespace
 
 ////////////////////////////////////////////////////////////////////////////////
@@ -210,8 +222,8 @@ PasswordAutofillAgent::PasswordAutofillAgent(content::RenderView* render_view)
     : content::RenderViewObserver(render_view),
       usernames_usage_(NOTHING_TO_AUTOFILL),
       web_view_(render_view->GetWebView()),
-      weak_ptr_factory_(this) {
-}
+      logging_state_active_(false),
+      weak_ptr_factory_(this) {}
 
 PasswordAutofillAgent::~PasswordAutofillAgent() {}
 
@@ -397,30 +409,67 @@ void PasswordAutofillAgent::OnDynamicFormsSeen(blink::WebFrame* frame) {
 
 void PasswordAutofillAgent::SendPasswordForms(blink::WebFrame* frame,
                                               bool only_visible) {
+  scoped_ptr<RendererSavePasswordProgressLogger> logger;
+  if (only_visible && logging_state_active_) {

[Ilya Sherman, 2014/04/23 05:19:56]

nit: Why does the value of |only_visible| matter w.r.t. logging?  Worth
documenting, if this logic is accurate.

[vabr (Chromium), 2014/04/23 18:15:35]

Done.

+    logger.reset(new RendererSavePasswordProgressLogger(this, routing_id()));
+    logger->LogMessage(
+        SavePasswordProgressLogger::STRING_SEND_PASSWORD_FORMS_METHOD);

[Ilya Sherman, 2014/04/23 05:19:56]

The "SavePasswordProgressLogger::" is unfortunately long enough to cause most
logging lines to wrap.  What do you think of aliasing this name to something
shorter via a typedef at the top of the file?  Normally I'm not much of a fan of
that, but in this case, I think the string provides very little semantic context
relative to the code that already has to be present around it.

[vabr (Chromium), 2014/04/23 18:15:35]

I like the idea, super-long lines bothered me as I wrote this up.
I also considered shortening RendererSavePasswordProgressLogger to
RendererLogger, but that is not justified by un-breaking lines, so I did not do
that. Happy to do so if you thinks it improves consistency.

I also did the typedef in the PasswordManager code. Let me know if that's not
OK. The login_prompt.cc file contains only two mentions, so I left the typename
long there.

+  }
+
   // Make sure that this security origin is allowed to use password manager.
   blink::WebSecurityOrigin origin = frame->document().securityOrigin();
-  if (!OriginCanAccessPasswordManager(origin))
+  if (logger)

[Ilya Sherman, 2014/04/23 05:19:56]

nit: Needs curly braces.

[vabr (Chromium), 2014/04/23 18:15:35]

Done.

+    logger->LogURL(SavePasswordProgressLogger::STRING_SECURITY_ORIGIN,
+                   GURL(origin.toString().utf8()));

[Ilya Sherman, 2014/04/23 05:19:56]

The WebUrl class defines a conversion operator to a GURL.  Can you convert the
origin to a WebURL, rather than to a GURL directly?  That would feel more
natural in this code.  This applies also to the form.action() conversion that
you have above.

[vabr (Chromium), 2014/04/23 18:15:35]

I'm afraid I found no way to get a WebURL from a WebSecurityOrigin or a
WebString. Please let me know if I missed something, but the current way is the
only I know to work.
form.action() is a WebString, I don't think there is a direct conversion to GURL
from that. Am I wrong?

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

Hmm, seems that you're right.  Ok, nevermind then.

+  if (!OriginCanAccessPasswordManager(origin)) {
+    if (logger) {
+      logger->LogMessage(
+          SavePasswordProgressLogger::STRING_SECURITY_ORIGIN_FAILURE);
+      logger->LogMessage(SavePasswordProgressLogger::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(SavePasswordProgressLogger::STRING_WEBPAGE_EMPTY);
+      logger->LogMessage(SavePasswordProgressLogger::STRING_DECISION_DROP);
+    }
     return;
+  }
 
   blink::WebVector<blink::WebFormElement> forms;
   frame->document().forms(forms);
+  if (logger)
+    logger->LogNumber(SavePasswordProgressLogger::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(),
+                  SavePasswordProgressLogger::STRING_FORM_FOUND_ON_PAGE,
+                  form);
+      logger->LogBoolean(SavePasswordProgressLogger::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)

[Ilya Sherman, 2014/04/23 05:19:56]

nit: Needs curly braces.

[vabr (Chromium), 2014/04/23 18:15:35]

Done.
Sorry about these. I now went through the code looking for more and fixed those
places as well.

+        logger->LogPasswordForm(
+            SavePasswordProgressLogger::STRING_FORM_IS_PASSWORD,
+            *password_form);
       password_forms.push_back(*password_form);
+    }
   }
 
   if (password_forms.empty() && !only_visible) {
@@ -442,6 +491,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;
@@ -492,6 +542,16 @@ 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(
+        SavePasswordProgressLogger::STRING_WILL_SUBMIT_FORM_METHOD);
+    LogHTMLForm(logger.get(),
+                SavePasswordProgressLogger::STRING_HTML_FORM_FOR_SUBMIT,
+                form);
+  }
+
   scoped_ptr<PasswordForm> submitted_form = CreatePasswordForm(form);
 
   // If there is a provisionally saved password, copy over the previous
@@ -500,8 +560,15 @@ 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(
+          SavePasswordProgressLogger::STRING_CREATED_PASSWORD_FORM,
+          *submitted_form);
     if (provisionally_saved_forms_[frame].get() &&
         submitted_form->action == provisionally_saved_forms_[frame]->action) {
+      if (logger)
+        logger->LogMessage(
+            SavePasswordProgressLogger::STRING_SUBMITTED_PASSWORD_REPLACED);
       submitted_form->password_value =
           provisionally_saved_forms_[frame]->password_value;
     }
@@ -514,6 +581,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(SavePasswordProgressLogger::STRING_DECISION_DROP);
   }
 }
 
@@ -544,6 +613,13 @@ 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(
+        SavePasswordProgressLogger::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
@@ -551,9 +627,16 @@ 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(SavePasswordProgressLogger::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(SavePasswordProgressLogger::
+                                      STRING_PROVISIONALLY_SAVED_FORM_FOR_FRAME,
+                                  *provisionally_saved_forms_[form_frame]);
         Send(new AutofillHostMsg_PasswordFormSubmitted(
             routing_id(),
             *provisionally_saved_forms_[form_frame]));
@@ -564,18 +647,31 @@ 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(),
+                        SavePasswordProgressLogger::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(SavePasswordProgressLogger::
+                                          STRING_PASSWORD_FORM_FOUND_ON_PAGE,
+                                      *password_form);
             Send(new AutofillHostMsg_PasswordFormSubmitted(
                 routing_id(), *password_form));
           }
         }
+        if (!password_forms_found && logger) {
+          logger->LogMessage(SavePasswordProgressLogger::STRING_DECISION_DROP);
+        }
       }
     }
     // Clear the whole map during main frame navigation.
@@ -584,6 +680,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(SavePasswordProgressLogger::STRING_DECISION_DROP);
   }
 }
 
@@ -640,6 +739,10 @@ void PasswordAutofillAgent::OnFillPasswordForm(
   }
 }
 
+void PasswordAutofillAgent::OnChangeLoggingState(bool active) {
+  logging_state_active_ = active;
+}
+
 ////////////////////////////////////////////////////////////////////////////////
 // PasswordAutofillAgent, private: