Bug 1339515 - [Form Autofill] Add built-in debug logging to ease debugging. r=steveck
authorMatthew Noorenberghe <mozilla@noorenberghe.ca>
Wed, 15 Feb 2017 16:22:38 +0800
changeset 391973 365ed2bc91f669d6a1bdbdd1c125bc01050409cc
parent 391972 e4a7236353863d494ebdb1de67ded9efada58d12
child 391974 2ae8554e0989e12e9ef5755a4171841b02df7f11
push id1468
push userasasaki@mozilla.com
push dateMon, 05 Jun 2017 19:31:07 +0000
treeherdermozilla-release@0641fc6ee9d1 [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewerssteveck
bugs1339515
milestone54.0a1
first release with
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
last release without
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
Bug 1339515 - [Form Autofill] Add built-in debug logging to ease debugging. r=steveck MozReview-Commit-ID: F4w2CzdWdrI
browser/app/profile/firefox.js
browser/extensions/formautofill/FormAutofillContent.jsm
browser/extensions/formautofill/FormAutofillHandler.jsm
browser/extensions/formautofill/FormAutofillParent.jsm
browser/extensions/formautofill/FormAutofillUtils.jsm
browser/extensions/formautofill/ProfileAutoCompleteResult.jsm
browser/extensions/formautofill/ProfileStorage.jsm
--- a/browser/app/profile/firefox.js
+++ b/browser/app/profile/firefox.js
@@ -1575,14 +1575,15 @@ pref("browser.crashReports.unsubmittedCh
 // Enable the (fairly costly) client/server validation on nightly only. The other prefs
 // controlling validation are located in /services/sync/services-sync.js
 pref("services.sync.validation.enabled", true);
 #endif
 
 // Preferences for the form autofill system extension
 pref("browser.formautofill.experimental", false);
 pref("browser.formautofill.enabled", false);
+pref("browser.formautofill.loglevel", "Warn");
 
 // Enable safebrowsing v4 tables (suffixed by "-proto") update.
 #ifdef NIGHTLY_BUILD
 pref("urlclassifier.malwareTable", "goog-malware-shavar,goog-unwanted-shavar,goog-malware-proto,goog-unwanted-proto,test-malware-simple,test-unwanted-simple");
 pref("urlclassifier.phishTable", "goog-phish-shavar,goog-phish-proto,test-phish-simple");
 #endif
--- a/browser/extensions/formautofill/FormAutofillContent.jsm
+++ b/browser/extensions/formautofill/FormAutofillContent.jsm
@@ -11,16 +11,17 @@
 "use strict";
 
 this.EXPORTED_SYMBOLS = ["FormAutofillContent"];
 
 const {classes: Cc, interfaces: Ci, utils: Cu, results: Cr, manager: Cm} = Components;
 
 Cu.import("resource://gre/modules/Services.jsm");
 Cu.import("resource://gre/modules/XPCOMUtils.jsm");
+Cu.import("resource://formautofill/FormAutofillUtils.jsm");
 
 XPCOMUtils.defineLazyModuleGetter(this, "ProfileAutoCompleteResult",
                                   "resource://formautofill/ProfileAutoCompleteResult.jsm");
 XPCOMUtils.defineLazyModuleGetter(this, "FormAutofillHandler",
                                   "resource://formautofill/FormAutofillHandler.jsm");
 XPCOMUtils.defineLazyModuleGetter(this, "FormLikeFactory",
                                   "resource://gre/modules/FormLikeFactory.jsm");
 
@@ -62,17 +63,17 @@ AutocompleteFactory.prototype = {
 
 
 /**
  * @constructor
  *
  * @implements {nsIAutoCompleteSearch}
  */
 function AutofillProfileAutoCompleteSearch() {
-
+  FormAutofillUtils.defineLazyLogGetter(this, "AutofillProfileAutoCompleteSearch");
 }
 AutofillProfileAutoCompleteSearch.prototype = {
   classID: Components.ID("4f9f1e4c-7f2c-439e-9c9e-566b68bc187d"),
   contractID: "@mozilla.org/autocomplete/search;1?name=autofill-profiles",
   classDescription: "AutofillProfileAutoCompleteSearch",
   QueryInterface: XPCOMUtils.generateQI([Ci.nsIAutoCompleteSearch]),
 
   // Begin nsIAutoCompleteSearch implementation
@@ -82,16 +83,17 @@ AutofillProfileAutoCompleteSearch.protot
    * or asynchronously) of the result
    *
    * @param {string} searchString the string to search for
    * @param {string} searchParam
    * @param {Object} previousResult a previous result to use for faster searchinig
    * @param {Object} listener the listener to notify when the search is complete
    */
   startSearch(searchString, searchParam, previousResult, listener) {
+    this.log.debug("startSearch: for", searchString, "with input", formFillController.focusedInput);
     let focusedInput = formFillController.focusedInput;
     this.forceStop = false;
     let info = this._serializeInfo(FormAutofillContent.getInputDetails(focusedInput));
 
     this._getProfiles({info, searchString}).then((profiles) => {
       if (this.forceStop) {
         return;
       }
@@ -125,16 +127,17 @@ AutofillProfileAutoCompleteSearch.protot
    * @param  {string} data.searchString
    *         The typed string for filtering out the matched profile.
    * @param  {string} data.info
    *         The input autocomplete property's information.
    * @returns {Promise}
    *          Promise that resolves when profiles returned from parent process.
    */
   _getProfiles(data) {
+    this.log.debug("_getProfiles with data:", data);
     return new Promise((resolve) => {
       Services.cpmm.addMessageListener("FormAutofill:Profiles", function getResult(result) {
         Services.cpmm.removeMessageListener("FormAutofill:Profiles", getResult);
         resolve(result.data);
       });
 
       Services.cpmm.sendAsyncMessage("FormAutofill:GetProfiles", data);
     });
@@ -156,28 +159,31 @@ let ProfileAutocomplete = {
   _registered: false,
   _factory: null,
 
   ensureRegistered() {
     if (this._registered) {
       return;
     }
 
+    FormAutofillUtils.defineLazyLogGetter(this, "ProfileAutocomplete");
+    this.log.debug("ensureRegistered");
     this._factory = new AutocompleteFactory();
     this._factory.register(AutofillProfileAutoCompleteSearch);
     this._registered = true;
 
     Services.obs.addObserver(this, "autocomplete-will-enter-text", false);
   },
 
   ensureUnregistered() {
     if (!this._registered) {
       return;
     }
 
+    this.log.debug("ensureUnregistered");
     this._factory.unregister();
     this._factory = null;
     this._registered = false;
     this._lastAutoCompleteResult = null;
 
     Services.obs.removeObserver(this, "autocomplete-will-enter-text");
   },
 
@@ -201,16 +207,17 @@ let ProfileAutocomplete = {
   _frameMMFromWindow(contentWindow) {
     return contentWindow.QueryInterface(Ci.nsIInterfaceRequestor)
                         .getInterface(Ci.nsIDocShell)
                         .QueryInterface(Ci.nsIInterfaceRequestor)
                         .getInterface(Ci.nsIContentFrameMessageManager);
   },
 
   _fillFromAutocompleteRow(focusedInput) {
+    this.log.debug("_fillFromAutocompleteRow:", focusedInput);
     let formDetails = FormAutofillContent.getFormDetails(focusedInput);
     if (!formDetails) {
       // The observer notification is for a different frame.
       return;
     }
 
     let mm = this._frameMMFromWindow(focusedInput.ownerGlobal);
     let selectedIndexResult = mm.sendSyncMessage("FormAutoComplete:GetSelectedIndex", {});
@@ -245,21 +252,23 @@ let ProfileAutocomplete = {
 
 /**
  * Handles content's interactions for the process.
  *
  * NOTE: Declares it by "var" to make it accessible in unit tests.
  */
 var FormAutofillContent = {
   /**
-   * @type {WeakMap} mapping FormLike root HTML elements to form details.
+   * @type {WeakMap} mapping FormLike root HTML elements to FormAutofillHandler objects.
    */
   _formsDetails: new WeakMap(),
 
   init() {
+    FormAutofillUtils.defineLazyLogGetter(this, "FormAutofillContent");
+
     Services.cpmm.addMessageListener("FormAutofill:enabledStatus", (result) => {
       if (result.data) {
         ProfileAutocomplete.ensureRegistered();
       } else {
         ProfileAutocomplete.ensureUnregistered();
       }
     });
     Services.cpmm.sendAsyncMessage("FormAutofill:getEnabledStatus");
@@ -301,44 +310,49 @@ var FormAutofillContent = {
   },
 
   getAllFieldNames(element) {
     let formDetails = this.getFormDetails(element);
     return formDetails.map(record => record.fieldName);
   },
 
   _identifyAutofillFields(doc) {
+    this.log.debug("_identifyAutofillFields:", "" + doc.location);
     let forms = [];
 
     // Collects root forms from inputs.
     for (let field of doc.getElementsByTagName("input")) {
       // We only consider text-like fields for now until we support radio and
       // checkbox buttons in the future.
       if (!field.mozIsTextField(true)) {
         continue;
       }
 
       let formLike = FormLikeFactory.createFromField(field);
       if (!forms.some(form => form.rootElement === formLike.rootElement)) {
         forms.push(formLike);
       }
     }
 
+    this.log.debug("Found", forms.length, "forms");
+
     // Collects the fields that can be autofilled from each form and marks them
     // as autofill fields if the amount is above the threshold.
     forms.forEach(form => {
       let formHandler = new FormAutofillHandler(form);
       formHandler.collectFormFields();
       if (formHandler.fieldDetails.length < AUTOFILL_FIELDS_THRESHOLD) {
+        this.log.debug("Ignoring form since it has only", formHandler.fieldDetails.length,
+                       "field(s)");
         return;
       }
 
       this._formsDetails.set(form.rootElement, formHandler);
-      formHandler.fieldDetails.forEach(
-        detail => this._markAsAutofillField(detail.element));
+      this.log.debug("Adding form handler to _formsDetails:", formHandler);
+      formHandler.fieldDetails.forEach(detail => this._markAsAutofillField(detail.element));
     });
   },
 
   _markAsAutofillField(field) {
     formFillController.markAsAutofillField(field);
   },
 };
 
--- a/browser/extensions/formautofill/FormAutofillHandler.jsm
+++ b/browser/extensions/formautofill/FormAutofillHandler.jsm
@@ -9,19 +9,24 @@
 "use strict";
 
 this.EXPORTED_SYMBOLS = ["FormAutofillHandler"];
 
 const {classes: Cc, interfaces: Ci, utils: Cu, results: Cr} = Components;
 
 Cu.import("resource://gre/modules/XPCOMUtils.jsm");
 
+Cu.import("resource://formautofill/FormAutofillUtils.jsm");
+
 XPCOMUtils.defineLazyModuleGetter(this, "FormAutofillHeuristics",
                                   "resource://formautofill/FormAutofillHeuristics.jsm");
 
+this.log = null;
+FormAutofillUtils.defineLazyLogGetter(this, this.EXPORTED_SYMBOLS[0]);
+
 /**
  * Handles profile autofill for a DOM Form element.
  * @param {FormLike} form Form that need to be auto filled
  */
 function FormAutofillHandler(form) {
   this.form = form;
   this.fieldDetails = [];
 }
@@ -66,16 +71,17 @@ FormAutofillHandler.prototype = {
       }
 
       // Store the association between the field metadata and the element.
       if (this.fieldDetails.some(f => f.section == info.section &&
                                       f.addressType == info.addressType &&
                                       f.contactType == info.contactType &&
                                       f.fieldName == info.fieldName)) {
         // A field with the same identifier already exists.
+        log.debug("Not collecting a field matching another with the same info:", info);
         return null;
       }
 
       let inputFormat = {
         section: info.section,
         addressType: info.addressType,
         contactType: info.contactType,
         fieldName: info.fieldName,
@@ -85,16 +91,18 @@ FormAutofillHandler.prototype = {
 
       inputFormat.index = autofillData.length;
       autofillData.push(inputFormat);
 
       formatWithElement.element = element;
       this.fieldDetails.push(formatWithElement);
     }
 
+    log.debug("Collected details on", autofillData.length, "fields");
+
     return autofillData;
   },
 
   /**
    * Processes form fields that can be autofilled, and populates them with the
    * data provided by backend.
    *
    * @param {Array<Object>} autofillResult
@@ -105,16 +113,17 @@ FormAutofillHandler.prototype = {
    *          contactType: Value originally provided to the user interface.
    *          fieldName: Value originally provided to the user interface.
    *          value: String with which the field should be updated.
    *          index: Index to match the input in fieldDetails
    *        }],
    *        }
    */
   autofillFormFields(autofillResult) {
+    log.debug("autofillFormFields:", autofillResult);
     for (let field of autofillResult) {
       // TODO: Skip filling the value of focused input which is filled in
       // FormFillController.
 
       // Get the field details, if it was processed by the user interface.
       let fieldDetail = this.fieldDetails[field.index];
 
       // Avoid the invalid value set
--- a/browser/extensions/formautofill/FormAutofillParent.jsm
+++ b/browser/extensions/formautofill/FormAutofillParent.jsm
@@ -24,29 +24,36 @@
  *   }
  * ]
  */
 
 /* exported FormAutofillParent */
 
 "use strict";
 
+this.EXPORTED_SYMBOLS = ["FormAutofillParent"];
+
 const {classes: Cc, interfaces: Ci, utils: Cu, results: Cr} = Components;
 
 Cu.import("resource://gre/modules/Services.jsm");
 Cu.import("resource://gre/modules/XPCOMUtils.jsm");
 Cu.import("resource://gre/modules/Services.jsm");
 
+Cu.import("resource://formautofill/FormAutofillUtils.jsm");
+
 XPCOMUtils.defineLazyModuleGetter(this, "OS",
                                   "resource://gre/modules/osfile.jsm");
 XPCOMUtils.defineLazyModuleGetter(this, "ProfileStorage",
                                   "resource://formautofill/ProfileStorage.jsm");
 XPCOMUtils.defineLazyModuleGetter(this, "FormAutofillPreferences",
                                   "resource://formautofill/FormAutofillPreferences.jsm");
 
+this.log = null;
+FormAutofillUtils.defineLazyLogGetter(this, this.EXPORTED_SYMBOLS[0]);
+
 const PROFILE_JSON_FILE_NAME = "autofill-profiles.json";
 const ENABLED_PREF = "browser.formautofill.enabled";
 
 function FormAutofillParent() {
 }
 
 FormAutofillParent.prototype = {
   QueryInterface: XPCOMUtils.generateQI([Ci.nsISupports, Ci.nsIObserver]),
@@ -58,32 +65,34 @@ FormAutofillParent.prototype = {
    * Caches the latest value of this._getStatus().
    */
   _enabled: false,
 
   /**
    * Initializes ProfileStorage and registers the message handler.
    */
   init() {
+    log.debug("init");
     let storePath = OS.Path.join(OS.Constants.Path.profileDir, PROFILE_JSON_FILE_NAME);
     this._profileStore = new ProfileStorage(storePath);
     this._profileStore.initialize();
 
     Services.obs.addObserver(this, "advanced-pane-loaded", false);
 
     // Observing the pref (and storage) changes
     Services.prefs.addObserver(ENABLED_PREF, this, false);
     this._enabled = this._getStatus();
     // Force to trigger the onStatusChanged function for setting listeners properly
     // while initizlization
     this._onStatusChanged();
     Services.ppmm.addMessageListener("FormAutofill:getEnabledStatus", this);
   },
 
   observe(subject, topic, data) {
+    log.debug("observe:", topic, "with data:", data);
     switch (topic) {
       case "advanced-pane-loaded": {
         let formAutofillPreferences = new FormAutofillPreferences();
         let document = subject.document;
         let prefGroup = formAutofillPreferences.init(document);
         let parentNode = document.getElementById("mainPrefPane");
         let insertBeforeNode = document.getElementById("locationBarGroup");
         parentNode.insertBefore(prefGroup, insertBeforeNode);
@@ -106,16 +115,17 @@ FormAutofillParent.prototype = {
     }
   },
 
   /**
    * Add/remove message listener and broadcast the status to frames while the
    * form autofill status changed.
    */
   _onStatusChanged() {
+    log.debug("_onStatusChanged: Status changed to", this._enabled);
     if (this._enabled) {
       Services.ppmm.addMessageListener("FormAutofill:GetProfiles", this);
     } else {
       Services.ppmm.removeMessageListener("FormAutofill:GetProfiles", this);
     }
 
     Services.ppmm.broadcastAsyncMessage("FormAutofill:enabledStatus", this._enabled);
   },
@@ -194,10 +204,8 @@ FormAutofillParent.prototype = {
       profiles = this._profileStore.getByFilter({searchString, info});
     } else {
       profiles = this._profileStore.getAll();
     }
 
     target.sendAsyncMessage("FormAutofill:Profiles", profiles);
   },
 };
-
-this.EXPORTED_SYMBOLS = ["FormAutofillParent"];
--- a/browser/extensions/formautofill/FormAutofillUtils.jsm
+++ b/browser/extensions/formautofill/FormAutofillUtils.jsm
@@ -1,17 +1,31 @@
 /* This Source Code Form is subject to the terms of the Mozilla Public
  * License, v. 2.0. If a copy of the MPL was not distributed with this
  * file, You can obtain one at http://mozilla.org/MPL/2.0/. */
 
 "use strict";
 
 this.EXPORTED_SYMBOLS = ["FormAutofillUtils"];
 
+const {classes: Cc, interfaces: Ci, utils: Cu, results: Cr} = Components;
+
+Cu.import("resource://gre/modules/XPCOMUtils.jsm");
+
 this.FormAutofillUtils = {
+  defineLazyLogGetter(scope, logPrefix) {
+    XPCOMUtils.defineLazyGetter(scope, "log", () => {
+      let ConsoleAPI = Cu.import("resource://gre/modules/Console.jsm", {}).ConsoleAPI;
+      return new ConsoleAPI({
+        maxLogLevelPref: "browser.formautofill.loglevel",
+        prefix: logPrefix,
+      });
+    });
+  },
+
   generateFullName(firstName, lastName, middleName) {
     // TODO: The implementation should depend on the L10N spec, but a simplified
     // rule is used here.
     let fullName = firstName;
     if (middleName) {
       fullName += " " + middleName;
     }
     if (lastName) {
--- a/browser/extensions/formautofill/ProfileAutoCompleteResult.jsm
+++ b/browser/extensions/formautofill/ProfileAutoCompleteResult.jsm
@@ -4,25 +4,28 @@
 
 "use strict";
 
 this.EXPORTED_SYMBOLS = ["ProfileAutoCompleteResult"];
 
 const {classes: Cc, interfaces: Ci, utils: Cu, results: Cr} = Components;
 
 Cu.import("resource://gre/modules/XPCOMUtils.jsm");
+Cu.import("resource://formautofill/FormAutofillUtils.jsm");
 
-XPCOMUtils.defineLazyModuleGetter(this, "FormAutofillUtils",
-                                  "resource://formautofill/FormAutofillUtils.jsm");
+this.log = null;
+FormAutofillUtils.defineLazyLogGetter(this, this.EXPORTED_SYMBOLS[0]);
+
 
 this.ProfileAutoCompleteResult = function(searchString,
                                           focusedFieldName,
                                           allFieldNames,
                                           matchingProfiles,
                                           {resultCode = null}) {
+  log.debug("Constructing new ProfileAutoCompleteResult:", [...arguments]);
   this.searchString = searchString;
   this._focusedFieldName = focusedFieldName;
   this._allFieldNames = allFieldNames;
   this._matchingProfiles = matchingProfiles;
 
   if (resultCode) {
     this.searchResult = resultCode;
   } else if (matchingProfiles.length > 0) {
--- a/browser/extensions/formautofill/ProfileStorage.jsm
+++ b/browser/extensions/formautofill/ProfileStorage.jsm
@@ -34,29 +34,36 @@
  *       // ...
  *     }
  *   ]
  * }
  */
 
 "use strict";
 
+this.EXPORTED_SYMBOLS = ["ProfileStorage"];
+
 const {classes: Cc, interfaces: Ci, utils: Cu, results: Cr} = Components;
 
 Cu.import("resource://gre/modules/XPCOMUtils.jsm");
 Cu.import("resource://gre/modules/Services.jsm");
 Cu.import("resource://gre/modules/Task.jsm");
 
+Cu.import("resource://formautofill/FormAutofillUtils.jsm");
+
 XPCOMUtils.defineLazyModuleGetter(this, "JSONFile",
                                   "resource://gre/modules/JSONFile.jsm");
 
 XPCOMUtils.defineLazyServiceGetter(this, "gUUIDGenerator",
                                    "@mozilla.org/uuid-generator;1",
                                    "nsIUUIDGenerator");
 
+this.log = null;
+FormAutofillUtils.defineLazyLogGetter(this, this.EXPORTED_SYMBOLS[0]);
+
 const SCHEMA_VERSION = 1;
 
 // Name-related fields will be handled in follow-up bugs due to the complexity.
 const VALID_FIELDS = [
   "organization",
   "street-address",
   "address-level2",
   "address-level1",
@@ -102,16 +109,17 @@ ProfileStorage.prototype = {
 
   /**
    * Adds a new profile.
    *
    * @param {Profile} profile
    *        The new profile for saving.
    */
   add(profile) {
+    log.debug("add:", profile);
     this._store.ensureDataReady();
 
     let profileToSave = this._normalizeProfile(profile);
 
     profileToSave.guid = gUUIDGenerator.generateUUID().toString()
                                        .replace(/[{}-]/g, "").substring(0, 12);
 
     // Metadata
@@ -130,16 +138,17 @@ ProfileStorage.prototype = {
    * Update the specified profile.
    *
    * @param  {string} guid
    *         Indicates which profile to update.
    * @param  {Profile} profile
    *         The new profile used to overwrite the old one.
    */
   update(guid, profile) {
+    log.debug("update:", guid, profile);
     this._store.ensureDataReady();
 
     let profileFound = this._findByGUID(guid);
     if (!profileFound) {
       throw new Error("No matching profile.");
     }
 
     let profileToUpdate = this._normalizeProfile(profile);
@@ -179,32 +188,34 @@ ProfileStorage.prototype = {
 
   /**
    * Removes the specified profile. No error occurs if the profile isn't found.
    *
    * @param  {string} guid
    *         Indicates which profile to remove.
    */
   remove(guid) {
+    log.debug("remove:", guid);
     this._store.ensureDataReady();
 
     this._store.data.profiles =
       this._store.data.profiles.filter(profile => profile.guid != guid);
     this._store.saveSoon();
   },
 
   /**
    * Returns the profile with the specified GUID.
    *
    * @param   {string} guid
    *          Indicates which profile to retrieve.
    * @returns {Profile}
    *          A clone of the profile.
    */
   get(guid) {
+    log.debug("get:", guid);
     this._store.ensureDataReady();
 
     let profileFound = this._findByGUID(guid);
     if (!profileFound) {
       throw new Error("No matching profile.");
     }
 
     // Profile is cloned to avoid accidental modifications from outside.
@@ -213,33 +224,37 @@ ProfileStorage.prototype = {
 
   /**
    * Returns all profiles.
    *
    * @returns {Array.<Profile>}
    *          An array containing clones of all profiles.
    */
   getAll() {
+    log.debug("getAll");
     this._store.ensureDataReady();
 
     // Profiles are cloned to avoid accidental modifications from outside.
     return this._store.data.profiles.map(this._clone);
   },
 
   /**
    * Returns the filtered profiles based on input's information and searchString.
    *
    * @returns {Array.<Profile>}
    *          An array containing clones of matched profiles.
    */
   getByFilter({info, searchString}) {
+    log.debug("getByFilter:", info, searchString);
     this._store.ensureDataReady();
 
     // Profiles are cloned to avoid accidental modifications from outside.
-    return this._findByFilter({info, searchString}).map(this._clone);
+    let result = this._findByFilter({info, searchString}).map(this._clone);
+    log.debug("getByFilter: Returning", result.length, "result(s)");
+    return result;
   },
 
   _clone(profile) {
     return Object.assign({}, profile);
   },
 
   _findByGUID(guid) {
     return this._store.data.profiles.find(profile => profile.guid == guid);
@@ -286,10 +301,8 @@ ProfileStorage.prototype = {
     return data;
   },
 
   // For test only.
   _saveImmediately() {
     return this._store._save();
   },
 };
-
-this.EXPORTED_SYMBOLS = ["ProfileStorage"];