Extend logging for password manager 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 <stddef.h>
 
 #include <memory>
+#include <string>
 #include <utility>
 
 #include "base/bind.h"
 #include "base/command_line.h"
 #include "base/i18n/case_conversion.h"
 #include "base/memory/linked_ptr.h"
 #include "base/message_loop/message_loop.h"
 #include "base/metrics/field_trial.h"
 #include "base/metrics/histogram_macros.h"
 #include "base/strings/utf_string_conversions.h"
@@ skipping 406 matching lines @@
 // value through |registration_callback|. If a match is found, return true and
 // |nonscript_modified_values| will be modified with the autofilled credentials.
 bool FillUserNameAndPassword(
     blink::WebInputElement* username_element,
     blink::WebInputElement* password_element,
     const PasswordFormFillData& fill_data,
     bool exact_username_match,
     bool set_selection,
     std::map<const blink::WebInputElement, blink::WebString>*
         nonscript_modified_values,
-    base::Callback<void(blink::WebInputElement*)> registration_callback) {
+    base::Callback<void(blink::WebInputElement*)> registration_callback,
+    RendererSavePasswordProgressLogger* logger) {
+  if (logger)
+    logger->LogMessage(Logger::STRING_FILL_USERNAME_AND_PASSWORD_METHOD);
+
   // Don't fill username if password can't be set.
   if (!IsElementAutocompletable(*password_element))
     return false;
 
   base::string16 current_username;
   if (!username_element->isNull()) {
     current_username = username_element->value();
   }
 
   // username and password will contain the match found if any.
   base::string16 username;
   base::string16 password;
 
   // Look for any suitable matches to current field text.
   if (DoUsernamesMatch(fill_data.username_field.value, current_username,
                        exact_username_match)) {
     username = fill_data.username_field.value;
     password = fill_data.password_field.value;
+    if (logger)
+      logger->LogMessage(Logger::STRING_USERNAMES_MATCH);
   } else {
     // Scan additional logins for a match.
     for (const auto& it : fill_data.additional_logins) {
       if (DoUsernamesMatch(it.first, current_username, exact_username_match)) {
         username = it.first;
         password = it.second.password;
         break;
       }
     }
+    if (logger) {
+      logger->LogBoolean(Logger::STRING_MATCH_IN_ADDITIONAL,
+                         !(username.empty() && password.empty()));
+    }
 
     // Check possible usernames.
     if (username.empty() && password.empty()) {
       for (const auto& it : fill_data.other_possible_usernames) {
         for (size_t i = 0; i < it.second.size(); ++i) {
           if (DoUsernamesMatch(
                   it.second[i], current_username, exact_username_match)) {
             username = it.second[i];
             password = it.first.password;
             break;
           }
         }
         if (!username.empty() && !password.empty())
           break;
       }
     }
   }
   if (password.empty())
     return false;
 
   // TODO(tkent): Check maxlength and pattern for both username and password
   // fields.
 
   // Input matches the username, fill in required values.
   if (!username_element->isNull() &&
       IsElementAutocompletable(*username_element)) {
-    // TODO(vabr): Why not setSuggestedValue? http://crbug.com/507714
+    // TODO(crbug.com/507714): Why not setSuggestedValue?
     username_element->setValue(username, true);
     (*nonscript_modified_values)[*username_element] = username;
     username_element->setAutofilled(true);
+    if (logger)
+      logger->LogMessage(Logger::STRING_USERNAME_FILLED);

[dvadym, 2016/04/26 14:47:34]

It seems that it would be helpful to log also nameForAutofill() of a username
field, then we will know from log, whether we fill incorrectly. WDYT?

[vabr (Chromium), 2016/04/26 16:55:41]

While I agree, this would need some more changes to the
SavePasswordProgressLogger. Currently, no free strings are allowed, for security
reasons. The only exception is the element names as captured in a PasswordForm,
there the code does some processing to avoid exploits. So what we'd need is to
add a method similar to SavePasswordProgressLogger::LogPasswordForm, but just
logging element names. It's not a lot of work, but I wanted to keep this CL
small.

My suggestion is to do a follow-up CL for the logging of element names.

     if (set_selection) {
       form_util::PreviewSuggestion(username, current_username,
                                    username_element);
     }
   } else if (current_username != username) {
     // If the username can't be filled and it doesn't match a saved password
     // as is, don't autofill a password.
     return false;
   }
 
   // Wait to fill in the password until a user gesture occurs. This is to make
   // sure that we do not fill in the DOM with a password until we believe the
   // user is intentionally interacting with the page.
   password_element->setSuggestedValue(password);
   (*nonscript_modified_values)[*password_element] = password;
   registration_callback.Run(password_element);
 
   password_element->setAutofilled(true);
+  if (logger)
+    logger->LogMessage(Logger::STRING_PASSWORD_FILLED);

[dvadym, 2016/04/26 14:47:34]

It seems that it would be helpful to log also nameForAutofill() of a password
field, then we will know from log, whether we fill incorrectly. WDYT?

[vabr (Chromium), 2016/04/26 16:55:41]

Ditto.

   return true;
 }
 
 // Attempts to fill |username_element| and |password_element| with the
 // |fill_data|. Will use the data corresponding to the preferred username,
 // unless the |username_element| already has a value set. In that case,
 // attempts to fill the password matching the already filled username, if
 // such a password exists. The |password_element| will have the
 // |suggestedValue| set, and |suggestedValue| will be registered for copying to
 // the real value through |registration_callback|. Returns true if the password
 // is filled.
 bool FillFormOnPasswordReceived(
     const PasswordFormFillData& fill_data,
     blink::WebInputElement username_element,
     blink::WebInputElement password_element,
     std::map<const blink::WebInputElement, blink::WebString>*
         nonscript_modified_values,
-    base::Callback<void(blink::WebInputElement*)> registration_callback) {
+    base::Callback<void(blink::WebInputElement*)> registration_callback,
+    RendererSavePasswordProgressLogger* logger) {
   // Do not fill if the password field is in a chain of iframes not having
   // identical origin.
   blink::WebFrame* cur_frame = password_element.document().frame();
   blink::WebString bottom_frame_origin =
       cur_frame->getSecurityOrigin().toString();
 
   DCHECK(cur_frame);
 
   while (cur_frame->parent()) {
     cur_frame = cur_frame->parent();
@@ skipping 47 matching lines @@
     return false;
   }
 
   if (form_has_fillable_username && username_element.value().isEmpty()) {
     // TODO(tkent): Check maxlength and pattern.
     username_element.setValue(fill_data.username_field.value, true);
   }
 
   // Fill if we have an exact match for the username. Note that this sets
   // username to autofilled.
-  return FillUserNameAndPassword(&username_element,
-                                 &password_element,
-                                 fill_data,
-                                 true /* exact_username_match */,
-                                 false /* set_selection */,
-                                 nonscript_modified_values,
-                                 registration_callback);
+  return FillUserNameAndPassword(
+      &username_element, &password_element, fill_data,
+      true /* exact_username_match */, false /* set_selection */,
+      nonscript_modified_values, registration_callback, logger);
 }
 
 // Takes a |map| with pointers as keys and linked_ptr as values, and returns
 // true if |key| is not NULL and  |map| contains a non-NULL entry for |key|.
 // Makes sure not to create an entry as a side effect of using the operator [].
 template <class Key, class Value>
 bool ContainsNonNullEntryForNonNullKey(
     const std::map<Key*, linked_ptr<Value>>& map,
     Key* key) {
   if (!key)
@@ skipping 73 matching lines @@
     return false;
 
   blink::WebInputElement password = password_info.password_field;
   if (!IsElementEditable(password))
     return false;
 
   blink::WebInputElement username = element;  // We need a non-const.
 
   // Do not set selection when ending an editing session, otherwise it can
   // mess with focus.
-  FillUserNameAndPassword(
-      &username, &password, fill_data, true, false,
-      &nonscript_modified_values_,
-      base::Bind(&PasswordValueGatekeeper::RegisterElement,
-                 base::Unretained(&gatekeeper_)));
+  FillUserNameAndPassword(&username, &password, fill_data, true, false,
+                          &nonscript_modified_values_,
+                          base::Bind(&PasswordValueGatekeeper::RegisterElement,
+                                     base::Unretained(&gatekeeper_)),
+                          nullptr);
   return true;
 }
 
 bool PasswordAutofillAgent::TextDidChangeInTextField(
     const blink::WebInputElement& element) {
   // TODO(vabr): Get a mutable argument instead. http://crbug.com/397083
   blink::WebInputElement mutable_element = element;  // We need a non-const.
   mutable_element.setAutofilled(false);
 
   WebInputToPasswordInfoMap::iterator iter =
@@ skipping 592 matching lines @@
   }
 
   // This is a new navigation, so require a new user gesture before filling in
   // passwords.
   gatekeeper_.Reset();
 }
 
 void PasswordAutofillAgent::OnFillPasswordForm(
     int key,
     const PasswordFormFillData& form_data) {
+  std::unique_ptr<RendererSavePasswordProgressLogger> logger;
+  if (logging_state_active_) {
+    logger.reset(new RendererSavePasswordProgressLogger(this, routing_id()));
+    logger->LogMessage(Logger::STRING_ON_FILL_PASSWORD_FORM_METHOD);
+  }
+
   bool ambiguous_or_empty_names =
       DoesFormContainAmbiguousOrEmptyNames(form_data);
   FormElementsList forms;
   FindFormElements(render_frame(), form_data, ambiguous_or_empty_names, &forms);
+  if (logger) {
+    logger->LogBoolean(Logger::STRING_AMBIGUOUS_OR_EMPTY_NAMES,
+                       ambiguous_or_empty_names);
+    logger->LogNumber(Logger::STRING_NUMBER_OF_POTENTIAL_FORMS_TO_FILL,
+                      forms.size());
+    logger->LogBoolean(Logger::STRING_FORM_DATA_WAIT,
+                       form_data.wait_for_username);
+  }
   for (const auto& form : forms) {
     base::string16 username_field_name;
     base::string16 password_field_name =
         FieldName(form_data.password_field, ambiguous_or_empty_names);
     bool form_contains_fillable_username_field =
         FillDataContainsFillableUsername(form_data);
     if (form_contains_fillable_username_field) {
       username_field_name =
           FieldName(form_data.username_field, ambiguous_or_empty_names);
     }
+    if (logger) {
+      logger->LogBoolean(Logger::STRING_CONTAINS_FILLABLE_USERNAME_FIELD,
+                         form_contains_fillable_username_field);
+      logger->LogBoolean(Logger::STRING_USERNAME_FIELD_NAME_EMPTY,
+                         username_field_name.empty());
+      logger->LogBoolean(Logger::STRING_PASSWORD_FIELD_NAME_EMPTY,
+                         password_field_name.empty());
+    }
 
     // Attach autocomplete listener to enable selecting alternate logins.
     blink::WebInputElement username_element;
     blink::WebInputElement password_element;
 
     // Check whether the password form has a username input field.
     if (!username_field_name.empty()) {
       const auto it = form.find(username_field_name);
       DCHECK(it != form.end());
       username_element = it->second;
@@ skipping 17 matching lines @@
     // We might have already filled this form if there are two <form> elements
     // with identical markup.
     if (web_input_to_password_info_.find(main_element) !=
         web_input_to_password_info_.end())
       continue;
 
     // If wait_for_username is true, we don't want to initially fill the form
     // until the user types in a valid username.
     if (!form_data.wait_for_username) {
       FillFormOnPasswordReceived(
-          form_data,
-          username_element,
-          password_element,
+          form_data, username_element, password_element,
           &nonscript_modified_values_,
           base::Bind(&PasswordValueGatekeeper::RegisterElement,
-                     base::Unretained(&gatekeeper_)));
+                     base::Unretained(&gatekeeper_)),
+          logger.get());
     }
 
     PasswordInfo password_info;
     password_info.fill_data = form_data;
     password_info.key = key;
     password_info.password_field = password_element;
     web_input_to_password_info_[main_element] = password_info;
     if (!main_element.isPasswordField())
       password_to_username_[password_element] = username_element;
   }
@@ skipping 120 matching lines @@
 }
 
 bool PasswordAutofillAgent::ProvisionallySavedPasswordIsValid() {
   return provisionally_saved_form_ &&
          !provisionally_saved_form_->username_value.empty() &&
          !(provisionally_saved_form_->password_value.empty() &&
          provisionally_saved_form_->new_password_value.empty());
 }
 
 }  // namespace autofill