Password manager: introduce logging for the internals page

components/autofill/content/renderer/password_autofill_agent.cc

 // Copyright 2013 The Chromium Authors. All rights reserved.
 // Use of this source code is governed by a BSD-style license that can be
 // found in the LICENSE file.
 
 #include "components/autofill/content/renderer/password_autofill_agent.h"
 
 #include "base/bind.h"
 #include "base/memory/scoped_ptr.h"
 #include "base/message_loop/message_loop.h"
 #include "base/metrics/histogram.h"
 #include "base/strings/utf_string_conversions.h"
 #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"
 #include "components/autofill/core/common/password_form_fill_data.h"
 #include "content/public/renderer/render_view.h"
 #include "third_party/WebKit/public/platform/WebVector.h"
 #include "third_party/WebKit/public/web/WebAutofillClient.h"
 #include "third_party/WebKit/public/web/WebDocument.h"
 #include "third_party/WebKit/public/web/WebElement.h"
 #include "third_party/WebKit/public/web/WebFormElement.h"
 #include "third_party/WebKit/public/web/WebInputEvent.h"
 #include "third_party/WebKit/public/web/WebLocalFrame.h"
 #include "third_party/WebKit/public/web/WebNode.h"
 #include "third_party/WebKit/public/web/WebNodeList.h"
 #include "third_party/WebKit/public/web/WebPasswordFormData.h"
 #include "third_party/WebKit/public/web/WebSecurityOrigin.h"
 #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 {
 
 // The size above which we stop triggering autocomplete.
 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;
@@ skipping 150 matching lines @@
   // appropriately named elements match the element to be saved. Currently
   // we ignore filling passwords where naming is ambigious anyway.
   for (size_t i = 0; i < temp_elements.size(); ++i) {
     if (temp_elements[i].to<blink::WebElement>().getAttribute("value") ==
         form.password_value)
       return true;
   }
   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
 
 ////////////////////////////////////////////////////////////////////////////////
 // PasswordAutofillAgent, public:
 
 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() {}
 
 PasswordAutofillAgent::PasswordValueGatekeeper::PasswordValueGatekeeper()
     : was_user_gesture_seen_(false) {}
 
 PasswordAutofillAgent::PasswordValueGatekeeper::~PasswordValueGatekeeper() {}
 
 void PasswordAutofillAgent::PasswordValueGatekeeper::RegisterElement(
     blink::WebInputElement* element) {
@@ skipping 165 matching lines @@
     const blink::WebSecurityOrigin& origin) {
   return origin.canAccessPasswordManager();
 }
 
 void PasswordAutofillAgent::OnDynamicFormsSeen(blink::WebFrame* frame) {
   SendPasswordForms(frame, false /* only_visible */);
 }
 
 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) {
     // We need to send the PasswordFormsRendered message regardless of whether
     // there are any forms visible, as this is also the code path that triggers
     // showing the infobar.
     return;
   }
 
   if (only_visible) {
     Send(new AutofillHostMsg_PasswordFormsRendered(routing_id(),
                                                    password_forms));
   } else {
     Send(new AutofillHostMsg_PasswordFormsParsed(routing_id(), password_forms));
   }
 }
 
 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;
 }
 
 void PasswordAutofillAgent::DidStartLoading() {
   if (usernames_usage_ != NOTHING_TO_AUTOFILL) {
     UMA_HISTOGRAM_ENUMERATION("PasswordManager.OtherPossibleUsernamesUsage",
                               usernames_usage_, OTHER_POSSIBLE_USERNAMES_MAX);
     usernames_usage_ = NOTHING_TO_AUTOFILL;
@@ skipping 30 matching lines @@
   // into a hidden field and then clear the password (http://crbug.com/28910).
   // This method gets called before any of those handlers run, so save away
   // a copy of the password in case it gets lost.
   scoped_ptr<PasswordForm> password_form(CreatePasswordForm(form));
   if (password_form)
     provisionally_saved_forms_[frame].reset(password_form.release());
 }
 
 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
   // password value so we get the user's typed password, not the value that
   // may have been transformed for submit.
   // 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;
     }
 
     // Some observers depend on sending this information now instead of when
     // the frame starts loading. If there are redirects that cause a new
     // RenderView to be instantiated (such as redirects to the WebStore)
     // we will never get to finish the load.
     Send(new AutofillHostMsg_PasswordFormSubmitted(routing_id(),
                                                    *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);
   }
 }
 
 void PasswordAutofillAgent::WillProcessUserGesture() {
   gatekeeper_.OnUserGesture();
 }
 
 blink::WebFrame* PasswordAutofillAgent::CurrentOrChildFrameWithSavedForms(
     const blink::WebFrame* current_frame) {
   for (FrameToPasswordFormMap::const_iterator it =
@@ skipping 10 matching lines @@
     if (current_frame == form_frame ||
         current_frame->findChildByName(form_frame->assignedName())) {
       return form_frame;
     }
   }
   return NULL;
 }
 
 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
     // state. This fixes the no password save issue for ajax login, tracked in
     // [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]));
         provisionally_saved_forms_.erase(form_frame);
       } else {
         // Loop through the forms on the page looking for one that has been
         // filled out. If one exists, try and save the credentials.
         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.
     provisionally_saved_forms_.clear();
 
     // 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);
   }
 }
 
 void PasswordAutofillAgent::OnFillPasswordForm(
     const PasswordFormFillData& form_data) {
   if (usernames_usage_ == NOTHING_TO_AUTOFILL) {
     if (form_data.other_possible_usernames.size())
       usernames_usage_ = OTHER_POSSIBLE_USERNAMES_PRESENT;
     else if (usernames_usage_ == NOTHING_TO_AUTOFILL)
       usernames_usage_ = OTHER_POSSIBLE_USERNAMES_ABSENT;
@@ skipping 36 matching lines @@
     FormFieldData field;
     FindFormAndFieldForFormControlElement(
         username_element, &form, &field, REQUIRE_NONE);
     Send(new AutofillHostMsg_AddPasswordFormMapping(
         routing_id(),
         field,
         form_data));
   }
 }
 
+void PasswordAutofillAgent::OnChangeLoggingState(bool active) {
+  logging_state_active_ = active;
+}
+
 ////////////////////////////////////////////////////////////////////////////////
 // PasswordAutofillAgent, private:
 
 void PasswordAutofillAgent::GetSuggestions(
     const PasswordFormFillData& fill_data,
     const base::string16& input,
     std::vector<base::string16>* suggestions,
     std::vector<base::string16>* realms) {
   if (StartsWith(fill_data.basic_data.fields[0].value, input, false)) {
     suggestions->push_back(fill_data.basic_data.fields[0].value);
@@ skipping 243 matching lines @@
   LoginToPasswordInfoMap::iterator iter = login_to_password_info_.find(input);
   if (iter == login_to_password_info_.end())
     return false;
 
   *found_input = input;
   *found_password = iter->second;
   return true;
 }
 
 }  // namespace autofill