Closed Bug 1515970 Opened 5 years ago Closed 5 years ago

Perma <randomtest> | A promise chain failed to handle a rejection: CreditCards is not initialized. Please restart if you flip the pref manually. - stack: get@resource://formautofill/FormAutofillStorage.jsm:1956:23

Categories

(Toolkit :: Form Autofill, defect)

defect
Not set
normal

Tracking

()

VERIFIED FIXED
mozilla66
Tracking Status
firefox-esr60 --- unaffected
firefox64 --- unaffected
firefox65 + verified
firefox66 + verified
firefox67 --- verified

People

(Reporter: RaulG, Assigned: timdream)

References

Details

Attachments

(1 file)

[Tracking Requested - why for this release]:

Central as Beta simulation: https://treeherder.mozilla.org/#/jobs?repo=try&resultStatus=testfailed%2Cbusted%2Cexception&revision=7badb73c08b83b8a94d39b13b5cb7d79a294e63a

Log link: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=218327268&repo=try&lineNumber=23600

Log snippet: 

[task 2018-12-21T12:24:13.871Z] 12:24:13     INFO - TEST-START | toolkit/components/satchel/test/browser/browser_close_tab.js
[task 2018-12-21T12:24:13.874Z] 12:24:13     INFO - GECKO(4088) | Chrome file doesn't exist: /builds/worker/workspace/build/tests/mochitest/browser/toolkit/components/satchel/test/browser/head.js
[task 2018-12-21T12:24:13.875Z] 12:24:13     INFO - GECKO(4088) | ++DOMWINDOW == 7 (0xe7caa800) [pid = 4180] [serial = 7] [outer = 0xe7cd0300]
[task 2018-12-21T12:24:14.018Z] 12:24:14     INFO - GECKO(4088) | ### XPCOM_MEM_BLOAT_LOG defined -- logging bloat/leaks to /tmp/tmpXSAUk4.mozrunner/runtests_leaks_tab_pid4262.log
[task 2018-12-21T12:24:14.443Z] 12:24:14     INFO - GECKO(4088) | [Parent 4088, Main Thread] WARNING: '!mSelection', file /builds/worker/workspace/build/src/editor/libeditor/EditorBase.cpp, line 4813
[task 2018-12-21T12:24:14.446Z] 12:24:14     INFO - GECKO(4088) | [Parent 4088, Main Thread] WARNING: '!editActionData.CanHandle()', file /builds/worker/workspace/build/src/editor/libeditor/EditorBase.cpp, line 1250
[task 2018-12-21T12:24:14.543Z] 12:24:14     INFO - GECKO(4088) | Couldn't convert chrome URL: chrome://branding/locale/brand.properties
[task 2018-12-21T12:24:14.867Z] 12:24:14     INFO - GECKO(4088) | ++DOCSHELL 0xe7d4f400 == 1 [pid = 4262] [id = {b62b1715-9ad7-49a1-b26c-4d9a787879c4}]
[task 2018-12-21T12:24:15.050Z] 12:24:15     INFO - GECKO(4088) | ++DOMWINDOW == 1 (0xf7069940) [pid = 4262] [serial = 1] [outer = (nil)]
[task 2018-12-21T12:24:15.341Z] 12:24:15     INFO - GECKO(4088) | ++DOMWINDOW == 2 (0xe8922400) [pid = 4262] [serial = 2] [outer = 0xf7069940]
[task 2018-12-21T12:24:15.487Z] 12:24:15     INFO - GECKO(4088) | ++DOMWINDOW == 3 (0xe7d8d400) [pid = 4262] [serial = 3] [outer = 0xf7069940]
[task 2018-12-21T12:24:15.972Z] 12:24:15     INFO - GECKO(4088) | ### XPCOM_MEM_BLOAT_LOG defined -- logging bloat/leaks to /tmp/tmpXSAUk4.mozrunner/runtests_leaks_tab_pid4288.log
[task 2018-12-21T12:24:16.260Z] 12:24:16     INFO - GECKO(4088) | Couldn't convert chrome URL: chrome://branding/locale/brand.properties
[task 2018-12-21T12:24:16.540Z] 12:24:16     INFO - GECKO(4088) | ++DOCSHELL 0xe7923800 == 1 [pid = 4288] [id = {d1973a18-d801-4373-b961-7f7773b9626a}]
[task 2018-12-21T12:24:16.596Z] 12:24:16     INFO - GECKO(4088) | ++DOMWINDOW == 1 (0xf7169940) [pid = 4288] [serial = 1] [outer = (nil)]
[task 2018-12-21T12:24:16.706Z] 12:24:16     INFO - GECKO(4088) | ++DOMWINDOW == 2 (0xe8923800) [pid = 4288] [serial = 2] [outer = 0xf7169940]
[task 2018-12-21T12:24:16.804Z] 12:24:16     INFO - GECKO(4088) | ++DOMWINDOW == 3 (0xe8161800) [pid = 4288] [serial = 3] [outer = 0xf7169940]
[task 2018-12-21T12:24:17.366Z] 12:24:17     INFO - GECKO(4088) | JavaScript error: resource://formautofill/FormAutofillStorage.jsm, line 1956: Error: CreditCards is not initialized. Please restart if you flip the pref manually.
[task 2018-12-21T12:24:17.566Z] 12:24:17     INFO - GECKO(4088) | --DOCSHELL 0xe8177000 == 3 [pid = 4161] [id = {da5e0fd1-1dce-434e-bbda-f9ea9fc4c1d1}]
[task 2018-12-21T12:24:17.831Z] 12:24:17     INFO - GECKO(4088) | [Child 4288, Main Thread] WARNING: SendNotifyIMEFocus got rejected.: file /builds/worker/workspace/build/src/widget/PuppetWidget.cpp, line 779
[task 2018-12-21T12:24:17.908Z] 12:24:17     INFO - GECKO(4088) | --DOCSHELL 0xe7c4d000 == 1 [pid = 4180] [id = {adca8b0e-081c-4ab6-b01c-aea55434a9c5}]
[task 2018-12-21T12:24:17.969Z] 12:24:17     INFO - TEST-INFO | started process screentopng
[task 2018-12-21T12:24:18.701Z] 12:24:18     INFO - TEST-INFO | screentopng: exit 0
[task 2018-12-21T12:24:18.703Z] 12:24:18     INFO - Buffered messages logged at 12:24:13
[task 2018-12-21T12:24:18.705Z] 12:24:18     INFO - Entering test bound test
[task 2018-12-21T12:24:18.706Z] 12:24:18     INFO - Buffered messages logged at 12:24:15
[task 2018-12-21T12:24:18.709Z] 12:24:18     INFO - Console message: [JavaScript Error: "The character encoding of the HTML document was not declared. The document will render with garbled text in some browser configurations if the document contains characters from outside the US-ASCII range. The character encoding of the page must be declared in the document or in the transfer protocol." {file: "data:text/html,<input type="text" name="field1">" line: 0}]
[task 2018-12-21T12:24:18.711Z] 12:24:18     INFO - Buffered messages logged at 12:24:17
[task 2018-12-21T12:24:18.713Z] 12:24:18     INFO - Console message: [JavaScript Error: "The character encoding of the HTML document was not declared. The document will render with garbled text in some browser configurations if the document contains characters from outside the US-ASCII range. The character encoding of the page must be declared in the document or in the transfer protocol." {file: "data:text/html,<input type="text" name="field1">" line: 0}]
[task 2018-12-21T12:24:18.715Z] 12:24:18     INFO - Console message: [JavaScript Error: "Error: CreditCards is not initialized. Please restart if you flip the pref manually." {file: "resource://formautofill/FormAutofillStorage.jsm" line: 1956}]
[task 2018-12-21T12:24:18.717Z] 12:24:18     INFO - TEST-PASS | toolkit/components/satchel/test/browser/browser_close_tab.js | Ensure the popup is closed. - true == true - 
[task 2018-12-21T12:24:18.718Z] 12:24:18     INFO - Console message: [JavaScript Error: "AutoCompletePopup: No messageManager for message "FormAutoComplete:PopupClosed"" {file: "resource://gre/modules/AutoCompletePopup.jsm" line: 339}]
[task 2018-12-21T12:24:18.720Z] 12:24:18     INFO - sendMessageToBrowser@resource://gre/modules/AutoCompletePopup.jsm:339:7
[task 2018-12-21T12:24:18.721Z] 12:24:18     INFO - handleEvent@resource://gre/modules/AutoCompletePopup.jsm:137:9
[task 2018-12-21T12:24:18.723Z] 12:24:18     INFO - closePopup@chrome://global/content/bindings/autocomplete.xml:683:13
[task 2018-12-21T12:24:18.724Z] 12:24:18     INFO - observe@resource://gre/modules/AutoCompletePopup.jsm:119:11
[task 2018-12-21T12:24:18.726Z] 12:24:18     INFO - 
[task 2018-12-21T12:24:18.727Z] 12:24:18     INFO - TEST-PASS | toolkit/components/satchel/test/browser/browser_close_tab.js | Got the error message for inexistent messageManager. - true == true - 
[task 2018-12-21T12:24:18.729Z] 12:24:18     INFO - Buffered messages finished
[task 2018-12-21T12:24:18.731Z] 12:24:18     INFO - TEST-UNEXPECTED-FAIL | toolkit/components/satchel/test/browser/browser_close_tab.js | A promise chain failed to handle a rejection: CreditCards is not initialized. Please restart if you flip the pref manually. - stack: get@resource://formautofill/FormAutofillStorage.jsm:1956:23
[task 2018-12-21T12:24:18.732Z] 12:24:18     INFO - _updateSavedFieldNames@resource://formautofill/FormAutofillParent.jsm:358:9
[task 2018-12-21T12:24:18.734Z] 12:24:18     INFO - FormAutofillParent/</<@resource://formautofill/FormAutofillParent.jsm:70:7
[task 2018-12-21T12:24:18.735Z] 12:24:18     INFO - Rejection date: Fri Dec 21 2018 12:24:17 GMT+0000 (Coordinated Universal Time) - false == true - JS frame :: resource://testing-common/PromiseTestUtils.jsm :: assertNoUncaughtRejections :: line 257
[task 2018-12-21T12:24:18.737Z] 12:24:18     INFO - Stack trace:
[task 2018-12-21T12:24:18.738Z] 12:24:18     INFO - resource://testing-common/PromiseTestUtils.jsm:assertNoUncaughtRejections:257
[task 2018-12-21T12:24:18.740Z] 12:24:18     INFO - chrome://mochikit/content/browser-test.js:Tester_execTest/<:1131
[task 2018-12-21T12:24:18.741Z] 12:24:18     INFO - Leaving test bound test
[task 2018-12-21T12:24:18.743Z] 12:24:18     INFO - Console message: BrowserTestUtils.withNewTab: Tab was already closed before removeTab would have been called
[task 2018-12-21T12:24:18.744Z] 12:24:18     INFO - GECKO(4088) | MEMORY STAT vsizeMaxContiguous not supported in this build configuration.
[task 2018-12-21T12:24:18.746Z] 12:24:18     INFO - GECKO(4088) | MEMORY STAT | vsize 617MB | residentFast 306MB | heapAllocated 109MB
[task 2018-12-21T12:24:18.747Z] 12:24:18     INFO - TEST-OK | toolkit/components/satchel/test/browser/browser_close_tab.js | took 4178ms
Bisection shows this starts with the landing of bug 1498775:

Beta simulation for its parent: https://treeherder.mozilla.org/#/jobs?repo=try&revision=9cb9b666cbb05c9dcdbd0fdbc424b0973daa3925
Beta simulation for the patch for 1498775: https://treeherder.mozilla.org/#/jobs?repo=try&revision=94183596ec3349ba9c574553cd3ef3270b60d5ce

Tooru, can you take a look at this, please (also in the general sense if it's possible to search for similar issues in the codebase)? Thank you in advance.
Blocks: 1498775
Flags: needinfo?(arai.unmht)
https://searchfox.org/mozilla-central/rev/413dd3a1fab3446749f3690d93ee17e3196f8c37/browser/extensions/formautofill/FormAutofillStorage.jsm#1954-1959
> FormAutofillStorage.prototype = {
> ...
>   initialize() {
>     if (!this._initializePromise) {
>       this._store = new JSONFile({
>         path: this._path,
>         dataPostProcessor: this._dataPostProcessor.bind(this),
>       });
>       this._initializePromise = this._store.load()
>         .then(() => {
>           let initializeAutofillRecords = [this.addresses.initialize()];
>           if (FormAutofill.isAutofillCreditCardsAvailable) {
>             initializeAutofillRecords.push(this.creditCards.initialize());
>           } else {
>             // Make creditCards records unavailable to other modules
>             // because we never initialize it.
>             Object.defineProperty(this, "creditCards", {
>               get() {
>                 throw new Error("CreditCards is not initialized. " +
>                                 "Please restart if you flip the pref manually.");
>               },

FormAutofillStorage#creditCards getter throws if it's preffed of


https://searchfox.org/mozilla-central/rev/413dd3a1fab3446749f3690d93ee17e3196f8c37/browser/extensions/formautofill/FormAutofillParent.jsm#353-359
> FormAutofillParent.prototype = {
> ...
>   _updateSavedFieldNames() {
>     log.debug("_updateSavedFieldNames");
> 
>     Services.ppmm.initialProcessData.autofillSavedFieldNames =
>       new Set([...this.formAutofillStorage.addresses.getSavedFieldNames(),
>         ...this.formAutofillStorage.creditCards.getSavedFieldNames()]);

FormAutofillStorage#creditCards getter is called here


https://searchfox.org/mozilla-central/rev/413dd3a1fab3446749f3690d93ee17e3196f8c37/browser/extensions/formautofill/FormAutofillParent.jsm#68-71
> function FormAutofillParent() {
>   // Lazily load the storage JSM to avoid disk I/O until absolutely needed.
>   // Once storage is loaded we need to update saved field names and inform content processes.
>   XPCOMUtils.defineLazyGetter(this, "formAutofillStorage", () => {
>     let {formAutofillStorage} = ChromeUtils.import("resource://formautofill/FormAutofillStorage.jsm", {});
>     log.debug("Loading formAutofillStorage");
> 
>     formAutofillStorage.initialize().then(() => {
>       // Update the saved field names to compute the status and update child processes.
>       this._updateSavedFieldNames();
>     });

FormAutofillParent#_updateSavedFieldNames method is called here, which is inside the Promise#then call.
the return value is not used, which results in overlooking the error (bug 1498775 fixed the missing error report)

the possible solution is one of the following:
  * Handle the error in FormAutofillParent#_updateSavedFieldNames
  * Check the preference in FormAutofillParent#_updateSavedFieldNames and abort initialization
  * Handle the error in formAutofillStorage global lazy getter
  * Check the preference in formAutofillStorage global lazy getter and abort initialization
  * Allow the exception in automation
Flags: needinfo?(arai.unmht)
timdream, how do you think about the solutions in comment #2 ?
Flags: needinfo?(timdream)
Have the _updateSavedFieldNames check the pref sounds reasonable.

I can come up with the fix after Christmas.
Assignee: nobody → timdream
Status: NEW → ASSIGNED
Flags: needinfo?(timdream)
Tracking to make sure we resolve before the merge.
Pushed by tchien@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/606aa2a9d0b2
Don't access creditCards store in _updateSavedFieldNames unless it is enabled r=MattN
https://hg.mozilla.org/mozilla-central/rev/606aa2a9d0b2
Status: ASSIGNED → RESOLVED
Closed: 5 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla66
Status: RESOLVED → VERIFIED

This root issue seems to be affecting 65. See bug 1520224 comment 14 (attachment 9037557 [details]).

Blocks: 1520224

Comment on attachment 9033362 [details]
Bug 1515970 - Don't access creditCards store in _updateSavedFieldNames unless it is enabled r=MattN

[Beta/Release Uplift Approval Request]

Feature/Bug causing the regression: Bug 1486954

User impact if declined: Form autofill autocomplete dropdowns will not open which will affect en-US users located in the U.S. See https://wiki.mozilla.org/Firefox/Features/Form_Autofill#Release

Is this code covered by automated tests?: Yes

Has the fix been verified in Nightly?: Yes

Needs manual test from QE?: Yes

If yes, steps to reproduce: I'm getting manual testing in bug 1520224 where the user-facing impact was reported.

List of other uplifts needed: None

Risk to taking this patch: Low

Why is the change risky/not risky? (and alternatives if risky): Straightforward change and we haven't had bug reports on Nightly since this was fixed there. One risk and reason why this wasn't caught by automation is that we test with credit card support available but that's not what we ship anymore (we pulled CC autofill off of Beta after the team was dissolved).

String changes made/needed: None

Attachment #9033362 - Flags: approval-mozilla-beta?
Flags: qe-verify+

I asked in bug 1520224 comment 21 for verification of the fix with a try build of beta with the patch: https://queue.taskcluster.net/v1/task/DjZh3n_bRGilIoYbzV_m4Q/runs/0/artifacts/public/build/target.dmg (macOS)

Comment on attachment 9033362 [details]
Bug 1515970 - Don't access creditCards store in _updateSavedFieldNames unless it is enabled r=MattN

[Triage Comment]
Simple fix to not attempt to access the creditCards store if the feature isn't enabled. Believe to also fix bug 1520224. We should have QA try to verify that as well, especially if nobody's looked at the Try builds. Approved for 65.0rc1.

Attachment #9033362 - Flags: approval-mozilla-beta? → approval-mozilla-beta+

Considering that this bug needs manual verification, I need to ask you how to reproduce the issue and how to verify the fix.
I am missing some parts of information before I get to verify the bug. Thank you!

Flags: needinfo?(rgurzau)

Using the STR described here (https://bugzilla.mozilla.org/show_bug.cgi?id=1520224#c4), the issue is NOT fixed on Nightly v66.0a1 from 20190123, not it is on Beta v65.0 RC.

STR:

  1. Open page: https://luke-chang.github.io/autofill-demo/basic.html
  2. Insert values for each of input fields;
  3. Click on "Submit".
  4. Click on any of the input fields again.

Actual: No auto-complete information is displayed, even if the previous values are being entered again.

Expected: The previously entered and submitted information should be displayed on a drop-down when an input field is selected.

Am I using the right STR?

Flags: needinfo?(timdream)

I agree with comment 20 that a restart would be required after changing prefs which affect availability. If you do step 2, you shouldn't need step 3 though and we should QA what we ship, not a non-default pref value. For step 5 the country field must either be for the United States or else empty, we don't save non-US addresses anymore. You also shouldn't expect a doorhanger after step 6 unless this is the first address saved in the profile.

I will re-write the verification steps:

  1. Open about:config in an en-US build
  2. Set browser.search.region to "US"
  3. Restart the browser
  4. Open page: https://luke-chang.github.io/autofill-demo/basic.html
  5. Insert values for a US address in each of input fields;
  6. Click on "Submit".
    The address should have been saved in the address autofill section of preferences.
    A doorhanger may be shown and inform about the address autofill feature but only if this is the first saved addresses.
  7. Click twice on any of the input fields again or type the same letter into a field like the saved address uses for it.
    Dropdown should be shown. (Clicking twice may only work on some OS).
    If step 7 doesn't work, try reload the page and try again to get the autocomplete dropdown to show.
Flags: needinfo?(MattN+bmo)

See bug 1520224 comment 6 for debugging instructions and logs to provide if comment 21 fails.

Actually, I'm not even sure if it's fixed correctly on firefox66.

The steps to reproduce are taken from:
https://bugzilla.mozilla.org/show_bug.cgi?id=1520224#c0
with extra information from
https://bugzilla.mozilla.org/show_bug.cgi?id=1520224#c6
OR from this bug, comment 21.

To make it clearer, the exact steps used to attempt issue reproduction/fix validation are the following:
Precondition1: en-US build is installed;
Prexondition2: pref "extensions.formautofill.available" has string value "on";
Precondition3: pref "extensions.formautofill.addresses.enabled" has boolean value "true";
Precondition4: pref "extensions.formautofill.loglevel" is changed to string value "Debug";
Precondition5: pref "browser.search.region" is changed to string value "US";
Precondition6: RESTART BROWSER!

Step1: Open page: https://luke-chang.github.io/autofill-demo/basic.html
Observation: The Browser Console shows the error:
"[Exception... "Favicon at "https://luke-chang.github.io/favicon.ico" failed to load: Not Found." nsresult: "0x80004005
(NS_ERROR_FAILURE)" location: "JS frame :: resource:///modules/FaviconLoader.jsm :: onStopRequest :: line 199" data: no]"

Step2: Input values in every input box;
Values used for test:
Name:Dani
Organization:Organization
Street Address:Street
Address Level 2:Address1
Address Level 1:Address2
Postal Code:123456
Country (Code):+1
Telephone:202-555-0000
Email: dani@mail.com
Observation: Errors displayed when entering any input field:
"this._recipeManager is null LoginManagerParent.jsm:85
FormAutofillContent: identifyAutofillFields: https://luke-chang.github.io/autofill-demo/basic.html FormAutofill.jsm:36
FormAutofillContent: No control is removed or inserted since last collection. FormAutofill.jsm:36"

Step3: Click the "Submit" button.
Observation: Browser console shows:
"this._recipeManager is null LoginManagerParent.jsm:85
FormAutofillContent: Notifying form early submission FormAutofill.jsm:36
FormAutofillHandler: isRecordCreatable: Country not supported: +1 FormAutofillHandler.jsm:568
FormAutofillHandler: Create records: <unavailable> FormAutofillHandler.jsm:1130
[Exception... "Favicon at "https://luke-chang.github.io/favicon.ico" failed to load: Not Found." nsresult: "0x80004005
(NS_ERROR_FAILURE)" location: "JS frame :: resource:///modules/FaviconLoader.jsm :: onStopRequest :: line 199" data: no]"
NOTICE ERROR: <<isRecordCreatable: Country not supported: +1>>

Step4: Go to the Saved Addresses modal from preferences (about:preferences#privacy-form-autofill)

EXPECTED: The Previously submitted address should be saved to Saved Addresses.

ACTUAL: The previously submitted address is NOT saved to Saved Addresses.

Conclusion:
I could not get the browser to save the input information in any way (not on Nightly v67.0a1 from 2019-01-30, neither on Beta v65.0RC while testing on Windows 10 x64). Am I missing something here or is it incorrectly fixed?

Flags: needinfo?(timdream)

(In reply to Bodea Daniel [:danibodea] from comment #23)

Actually, I'm not even sure if it's fixed correctly on firefox66.

Country (Code):+1

This is the issue but it's not your fault, the page is poorly labelled. This field is for the country abbreviation / name and it must represent the United States so try using "US".

(In reply to Tim Guan-tin Chien [:timdream] (please needinfo) from comment #24)

Reading into LoginManagerParent.jsm, I don't think this is related. Could you file another bug for this? Would you be able to find the regression range?

That was filed multiple times already (e.g. bug 1167872) so doesn't need to be filed again.

Using the tip above, I could properly reverify Nightly v67.0a1 from 2019-01-30 and Beta v66.0b3. because this fix has been riding the train, I have also verified Firefox Release v65.0.
This issue is now fixed. Marking as Verified. Thank you!

Flags: qe-verify+
You need to log in before you can comment on or make changes to this bug.