Log parsing aborts

Autofill's form parsing can abort due to a number of reasons (wrong scheme, not
enough fields, form target url matching some suspicious patterns, ...). This CL
introduces logging for these aborts to chrome://autofill-internals to speed up
the understanding why autofill is disabled for a certain form.

Bug: 928595
Change-Id: I754b56bb6b30ab3b2809c8bf508b74f6bbd380c9
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/1804298
Commit-Queue: Dominic Battré <battre@chromium.org>
Reviewed-by: Vadym Doroshenko <dvadym@chromium.org>
Cr-Commit-Position: refs/heads/master@{#697194}

components/autofill/core/browser/autofill_and_password_manager_internals/autofill_and_password_manager_internals.css

@@ -66,6 +66,10 @@
   background-color: #FFECB3;
 }
 
+.log-entry[scope='AbortParsing'] {
+  background-color: #FFCDD2;
+}
+
 .log-entry[scope='Filling'] {
   background-color: #D1C4E9;
 }

components/autofill/core/browser/autofill_handler.cc

@@ -8,6 +8,8 @@
 #include "components/autofill/core/browser/form_structure.h"
 #include "components/autofill/core/browser/logging/log_manager.h"
 #include "components/autofill/core/common/autofill_data_validation.h"
+#include "components/autofill/core/common/autofill_internals/log_message.h"
+#include "components/autofill/core/common/autofill_internals/logging_scope.h"
 #include "components/autofill/core/common/autofill_payments_features.h"
 #include "components/autofill/core/common/signatures_util.h"
 #include "ui/gfx/geometry/rect_f.h"
@@ -267,12 +269,17 @@ bool AutofillHandler::ParseForm(const FormData& form,
                                 const FormStructure* cached_form,
                                 FormStructure** parsed_form_structure) {
   DCHECK(parsed_form_structure);
-  if (form_structures_.size() >= kAutofillHandlerMaxFormCacheSize)
+  if (form_structures_.size() >= kAutofillHandlerMaxFormCacheSize) {
+    if (log_manager_) {
+      log_manager_->Log() << LoggingScope::kAbortParsing
+                          << LogMessage::kAbortParsingTooManyForms << form;
+    }
     return false;
+  }
 
   auto form_structure = std::make_unique<FormStructure>(form);
   form_structure->ParseFieldTypesFromAutocompleteAttributes();
-  if (!form_structure->ShouldBeParsed())
+  if (!form_structure->ShouldBeParsed(log_manager_))
     return false;
 
   if (cached_form) {
@@ -284,9 +291,8 @@ bool AutofillHandler::ParseForm(const FormData& form,
     if (observer_for_testing_)
       observer_for_testing_->OnFormParsed();
 
-    if (form_structure.get()->value_from_dynamic_change_form()) {
+    if (form_structure.get()->value_from_dynamic_change_form())
       value_from_dynamic_change_form_ = true;
-    }
   }
 
   form_structure->DetermineHeuristicTypes(log_manager_);

components/autofill/core/browser/form_structure.cc

@@ -35,12 +35,15 @@
 #include "components/autofill/core/browser/field_types.h"
 #include "components/autofill/core/browser/form_parsing/field_candidates.h"
 #include "components/autofill/core/browser/form_parsing/form_field.h"
+#include "components/autofill/core/browser/logging/log_manager.h"
 #include "components/autofill/core/browser/proto/legacy_proto_bridge.h"
 #include "components/autofill/core/browser/randomized_encoder.h"
 #include "components/autofill/core/browser/rationalization_util.h"
 #include "components/autofill/core/browser/validation.h"
 #include "components/autofill/core/common/autofill_constants.h"
 #include "components/autofill/core/common/autofill_features.h"
+#include "components/autofill/core/common/autofill_internals/log_message.h"
+#include "components/autofill/core/common/autofill_internals/logging_scope.h"
 #include "components/autofill/core/common/autofill_payments_features.h"
 #include "components/autofill/core/common/autofill_regex_constants.h"
 #include "components/autofill/core/common/autofill_regexes.h"
@@ -951,10 +954,15 @@ void FormStructure::UpdateAutofillCount() {
   }
 }
 
-bool FormStructure::ShouldBeParsed() const {
+bool FormStructure::ShouldBeParsed(LogManager* log_manager) const {
   // Exclude URLs not on the web via HTTP(S).
-  if (!HasAllowedScheme(source_url_))
+  if (!HasAllowedScheme(source_url_)) {
+    if (log_manager) {
+      log_manager->Log() << LoggingScope::kAbortParsing
+                         << LogMessage::kAbortParsingNotAllowedScheme << *this;
+    }
     return false;
+  }
 
   size_t min_required_fields =
       std::min({MinRequiredFieldsForHeuristics(), MinRequiredFieldsForQuery(),
@@ -963,6 +971,11 @@ bool FormStructure::ShouldBeParsed() const {
       (!all_fields_are_passwords() ||
        active_field_count() < kRequiredFieldsForFormsWithOnlyPasswordFields) &&
       !has_author_specified_types_) {
+    if (log_manager) {
+      log_manager->Log() << LoggingScope::kAbortParsing
+                         << LogMessage::kAbortParsingNotEnoughFields
+                         << active_field_count() << *this;
+    }
     return false;
   }
 
@@ -971,6 +984,11 @@ bool FormStructure::ShouldBeParsed() const {
       base::UTF8ToUTF16(kUrlSearchActionRe);
   if (MatchesPattern(base::UTF8ToUTF16(target_url_.path_piece()),
                      kUrlSearchActionPattern)) {
+    if (log_manager) {
+      log_manager->Log() << LoggingScope::kAbortParsing
+                         << LogMessage::kAbortParsingUrlMatchesSearchRegex
+                         << *this;
+    }
     return false;
   }
 
@@ -979,6 +997,11 @@ bool FormStructure::ShouldBeParsed() const {
     has_text_field |= it->form_control_type != "select-one";
   }
 
+  if (!has_text_field && log_manager) {
+    log_manager->Log() << LoggingScope::kAbortParsing
+                       << LogMessage::kAbortParsingFormHasNoTextfield << *this;
+  }
+
   return has_text_field;
 }
 
@@ -2192,6 +2215,7 @@ LogBuffer& operator<<(LogBuffer& buffer, const FormStructure& form) {
                           base::NumberToString(
                               HashFormSignature(form.form_signature()))});
   buffer << Tr{} << "Form name:" << form.form_name();
+  buffer << Tr{} << "Unique renderer Id:" << form.unique_renderer_id();
   buffer << Tr{} << "Target URL:" << form.target_url();
   for (size_t i = 0; i < form.field_count(); ++i) {
     buffer << Tag{"tr"};

components/autofill/core/browser/form_structure.h

@@ -130,7 +130,7 @@ class FormStructure {
   void UpdateAutofillCount();
 
   // Returns true if this form matches the structural requirements for Autofill.
-  bool ShouldBeParsed() const;
+  bool ShouldBeParsed(LogManager* log_manager = nullptr) const;
 
   // Returns true if heuristic autofill type detection should be attempted for
   // this form.

components/autofill/core/common/autofill_internals/log_message.h

@@ -14,10 +14,21 @@ class LogBuffer;
 // Generator for log message. If you need to find the call site for a log
 // message, take the first parameter (e.g. ParsedForms) and search for
 // that name prefixed with a k (e.g. kParsedForms) in code search.
-#define AUTOFILL_LOG_MESSAGE_TEMPLATES(T)                   \
-  T(ParsedForms, "Parsed forms:")                           \
-  T(SendAutofillUpload, "Sending Autofill Upload Request:") \
-  T(LocalHeuristicRegExMatched, "RegEx of local heuristic matched:")
+#define AUTOFILL_LOG_MESSAGE_TEMPLATES(T)                                      \
+  T(ParsedForms, "Parsed forms:")                                              \
+  T(SendAutofillUpload, "Sending Autofill Upload Request:")                    \
+  T(LocalHeuristicRegExMatched, "RegEx of local heuristic matched:")           \
+  T(AbortParsingTooManyForms, "Abort parsing form: Too many forms in cache: ") \
+  T(AbortParsingNotAllowedScheme,                                              \
+    "Abort parsing form: Ignoring form because the source url has no allowed " \
+    "scheme")                                                                  \
+  T(AbortParsingNotEnoughFields,                                               \
+    "Abort parsing form: Not enough fields in form: ")                         \
+  T(AbortParsingUrlMatchesSearchRegex,                                         \
+    "Abort parsing form: Action URL matches kUrlSearchActionRe, indicating "   \
+    "that the form may lead to a search.")                                     \
+  T(AbortParsingFormHasNoTextfield,                                            \
+    "Abort parsing form: Form has no text field.")
 
 // Log messages for chrome://autofill-internals.
 #define AUTOFILL_TEMPLATE(NAME, MESSAGE) k##NAME,

components/autofill/core/common/autofill_internals/logging_scope.h

@@ -18,6 +18,8 @@ class LogBuffer;
   T(Context)                                                           \
   /* Log messages related to the discovery and parsing of forms. */    \
   T(Parsing)                                                           \
+  /* Log messages related to reasons to stop parsing a form. */        \
+  T(AbortParsing)                                                      \
   /* Log messages related to filling of forms. */                      \
   T(Filling)                                                           \
   /* Log messages related to the submission of forms. */               \

components/autofill/core/common/form_data.cc

@@ -12,6 +12,7 @@
 #include "base/strings/string_util.h"
 #include "base/strings/utf_string_conversions.h"
 #include "components/autofill/core/common/form_field_data.h"
+#include "components/autofill/core/common/logging/log_buffer.h"
 
 namespace autofill {
 
@@ -250,4 +251,25 @@ bool DeserializeFormDataFromBase64String(const base::StringPiece& input,
   return DeserializeFormData(&iter, form_data);
 }
 
+LogBuffer& operator<<(LogBuffer& buffer, const FormData& form) {
+  buffer << Tag{"div"} << Attrib{"class", "form"};
+  buffer << Tag{"table"};
+  buffer << Tr{} << "Form name:" << form.name;
+  buffer << Tr{} << "Unique renderer Id:" << form.unique_renderer_id;
+  buffer << Tr{} << "URL:" << form.url;
+  buffer << Tr{} << "Action:" << form.action;
+  buffer << Tr{} << "Is <form> tag:" << form.is_form_tag;
+  for (size_t i = 0; i < form.fields.size(); ++i) {
+    buffer << Tag{"tr"};
+    buffer << Tag{"td"} << "Field " << i << ": " << CTag{};
+    buffer << Tag{"td"};
+    buffer << Tag{"table"} << form.fields.at(i) << CTag{"table"};
+    buffer << CTag{"td"};
+    buffer << CTag{"tr"};
+  }
+  buffer << CTag{"table"};
+  buffer << CTag{"div"};
+  return buffer;
+}
+
 }  // namespace autofill

components/autofill/core/common/form_data.h

@@ -18,6 +18,8 @@
 
 namespace autofill {
 
+class LogBuffer;
+
 // Pair of a button title (e.g. "Register") and its type (e.g.
 // INPUT_ELEMENT_SUBMIT_TYPE).
 using ButtonTitleInfo = std::pair<base::string16, mojom::ButtonTitleType>;
@@ -120,6 +122,8 @@ void SerializeFormDataToBase64String(const FormData& form_data,
 bool DeserializeFormDataFromBase64String(const base::StringPiece& input,
                                          FormData* form_data);
 
+LogBuffer& operator<<(LogBuffer& buffer, const FormData& form);
+
 }  // namespace autofill
 
 #endif  // COMPONENTS_AUTOFILL_CORE_COMMON_FORM_DATA_H_

components/autofill/core/common/form_field_data.cc

@@ -8,6 +8,7 @@
 #include "base/strings/string_util.h"
 #include "components/autofill/core/common/autofill_features.h"
 #include "components/autofill/core/common/autofill_util.h"
+#include "components/autofill/core/common/logging/log_buffer.h"
 
 // TODO(crbug/897756): Clean up the (de)serialization code.
 
@@ -468,4 +469,26 @@ std::ostream& operator<<(std::ostream& os, const FormFieldData& field) {
             << "label_source=" << field.label_source;
 }
 
+LogBuffer& operator<<(LogBuffer& buffer, const FormFieldData& field) {
+  buffer << Tag{"table"};
+  buffer << Tr{} << "Name:" << field.name;
+  buffer << Tr{} << "Unique renderer Id:" << field.unique_renderer_id;
+  buffer << Tr{} << "Name attribute:" << field.name_attribute;
+  buffer << Tr{} << "Id attribute:" << field.id_attribute;
+  constexpr size_t kMaxLabelSize = 100;
+  const base::string16 truncated_label =
+      field.label.substr(0, std::min(field.label.length(), kMaxLabelSize));
+  buffer << Tr{} << "Label:" << truncated_label;
+  buffer << Tr{} << "Form control type:" << field.form_control_type;
+  buffer << Tr{} << "Autocomplete attribute:" << field.autocomplete_attribute;
+  buffer << Tr{} << "Aria label:" << field.aria_label;
+  buffer << Tr{} << "Aria description:" << field.aria_description;
+  buffer << Tr{} << "Section:" << field.section;
+  buffer << Tr{} << "Is focusable:" << field.is_focusable;
+  buffer << Tr{} << "Is enabled:" << field.is_enabled;
+  buffer << Tr{} << "Is readonly:" << field.is_readonly;
+  buffer << CTag{"table"};
+  return buffer;
+}
+
 }  // namespace autofill

components/autofill/core/common/form_field_data.h

@@ -22,6 +22,8 @@ class PickleIterator;
 
 namespace autofill {
 
+class LogBuffer;
+
 // The flags describing form field properties.
 enum FieldPropertiesFlags {
   NO_FLAGS = 0u,
@@ -202,6 +204,9 @@ std::ostream& operator<<(std::ostream& os, const FormFieldData& field);
     EXPECT_EQ(expected.name_attribute, actual.name_attribute);                 \
   } while (0)
 
+// Produces a <table> element with information about the form.
+LogBuffer& operator<<(LogBuffer& buffer, const FormFieldData& form);
+
 }  // namespace autofill
 
 #endif  // COMPONENTS_AUTOFILL_CORE_COMMON_FORM_FIELD_DATA_H_