Bug 1339515 - [Form Autofill] Add built-in debug logging to ease debugging. r=steveck draft
authorMatthew Noorenberghe <mozilla@noorenberghe.ca>
Wed, 15 Feb 2017 16:22:38 +0800
changeset 484366 33ea952b4d3d28013d9d9efaa1fc0efe57d3956f
parent 483698 15aaabd6d6d626dfd20a69d4b21ac1736a3d4e68
child 545769 459223d06d9bf236c2fa59c76a67abd31e012c09
push id45458
push usermozilla@noorenberghe.ca
push dateWed, 15 Feb 2017 08:23:46 +0000
reviewerssteveck
bugs1339515
milestone54.0a1
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"];