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;
 
+// 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
 // to fill the form, the FindFormElements function stores the pointers
 // in a FormElements* result, referenced to ensure they are safe to use.
 struct FormElements {
   blink::WebFormElement form_element;
   FormInputElementMap input_elements;
 };
 
@@ skipping 139 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;
 }
 
+// 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
 
 ////////////////////////////////////////////////////////////////////////////////
 // PasswordAutofillAgent, public:
 
 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) {
 }
 
 PasswordAutofillAgent::~PasswordAutofillAgent() {
 }
 
 PasswordAutofillAgent::PasswordValueGatekeeper::PasswordValueGatekeeper()
     : was_user_gesture_seen_(false) {
 }
 
@@ skipping 176 matching lines @@
 void PasswordAutofillAgent::OnDynamicFormsSeen(blink::WebFrame* frame) {
   SendPasswordForms(frame, false /* only_visible */);
 }
 
 void PasswordAutofillAgent::FirstUserGestureObserved() {
   gatekeeper_.OnUserGesture();
 }
 
 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) {
     // 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);
@@ skipping 31 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(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
   // 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(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;
     }
 
     // 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(Logger::STRING_DECISION_DROP);
   }
 }
 
 blink::WebFrame* PasswordAutofillAgent::CurrentOrChildFrameWithSavedForms(
     const blink::WebFrame* current_frame) {
   for (FrameToPasswordFormMap::const_iterator it =
            provisionally_saved_forms_.begin();
        it != provisionally_saved_forms_.end();
        ++it) {
     blink::WebFrame* form_frame = it->first;
     // The check that the returned frame is related to |current_frame| is mainly
     // for double-checking. There should not be any unrelated frames in
     // |provisionally_saved_forms_|, because the map is cleared after
     // navigation. If there are reasons to remove this check in the future and
     // keep just the first frame found, it might be a good idea to add a UMA
     // statistic or a similar check on how many frames are here to choose from.
     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(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
     // 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(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);
       } 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(), 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.
     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(Logger::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 34 matching lines @@
 
     FormData form;
     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 242 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