Closed Bug 1655600 Opened 4 years ago Closed 2 years ago

Intermittent browser/extensions/formautofill/test/browser/creditCard/browser_creditCard_doorhanger.js | This test exceeded the timeout threshold. It should be rewritten or split up. If that's not possible, use requestLongerTimeout(N), but only as a last r

Categories

(Toolkit :: Form Autofill, defect, P5)

defect

Tracking

()

RESOLVED FIXED
100 Branch
Tracking Status
firefox100 --- fixed

People

(Reporter: intermittent-bug-filer, Assigned: dlee)

References

(Blocks 1 open bug)

Details

(Keywords: intermittent-failure, Whiteboard: [fxcm-test-refactoring])

Attachments

(9 files, 1 obsolete file)

47 bytes, text/x-phabricator-request
Details | Review
48 bytes, text/x-phabricator-request
Details | Review
48 bytes, text/x-phabricator-request
Details | Review
48 bytes, text/x-phabricator-request
Details | Review
48 bytes, text/x-phabricator-request
Details | Review
48 bytes, text/x-phabricator-request
Details | Review
48 bytes, text/x-phabricator-request
Details | Review
48 bytes, text/x-phabricator-request
Details | Review
48 bytes, text/x-phabricator-request
Details | Review

Filed by: nbeleuzu [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=311186197&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/eTE0B2d2QpGUCFQEToMfSg/runs/0/artifacts/public/logs/live_backing.log


[task 2020-07-27T22:02:34.868Z] 22:02:34 INFO - TEST-PASS | browser/extensions/formautofill/test/browser/creditCard/browser_creditCard_doorhanger.js | at least one notification displayed -
[task 2020-07-27T22:02:34.868Z] 22:02:34 INFO - TEST-PASS | browser/extensions/formautofill/test/browser/creditCard/browser_creditCard_doorhanger.js | 1 notification(s) -
[task 2020-07-27T22:02:34.868Z] 22:02:34 INFO - expecting notification popup hidden
[task 2020-07-27T22:02:34.868Z] 22:02:34 INFO - expecting record retrievals: creditCards
[task 2020-07-27T22:02:34.868Z] 22:02:34 INFO - TEST-PASS | browser/extensions/formautofill/test/browser/creditCard/browser_creditCard_doorhanger.js | 1 credit card in storage -
[task 2020-07-27T22:02:34.868Z] 22:02:34 INFO - TEST-PASS | browser/extensions/formautofill/test/browser/creditCard/browser_creditCard_doorhanger.js | Verify the name field -
[task 2020-07-27T22:02:34.869Z] 22:02:34 INFO - TEST-PASS | browser/extensions/formautofill/test/browser/creditCard/browser_creditCard_doorhanger.js | Invalid network/cc-type was not saved -
[task 2020-07-27T22:02:34.869Z] 22:02:34 INFO - expecting record retrievals: addresses
[task 2020-07-27T22:02:34.869Z] 22:02:34 INFO - expecting record retrievals: creditCards
[task 2020-07-27T22:02:34.869Z] 22:02:34 INFO - expecting credit card removed
[task 2020-07-27T22:02:34.869Z] 22:02:34 INFO - Leaving test bound test_submit_creditCard_with_invalid_network
[task 2020-07-27T22:02:34.869Z] 22:02:34 INFO - expecting record retrievals: addresses
[task 2020-07-27T22:02:34.870Z] 22:02:34 INFO - expecting record retrievals: creditCards
[task 2020-07-27T22:02:34.870Z] 22:02:34 INFO - Buffered messages finished
[task 2020-07-27T22:02:34.870Z] 22:02:34 INFO - TEST-UNEXPECTED-FAIL | browser/extensions/formautofill/test/browser/creditCard/browser_creditCard_doorhanger.js | This test exceeded the timeout threshold. It should be rewritten or split up. If that's not possible, use requestLongerTimeout(N), but only as a last resort. -
[task 2020-07-27T22:02:34.870Z] 22:02:34 INFO - GECKO(1736) | MEMORY STAT vsizeMaxContiguous not supported in this build configuration.
[task 2020-07-27T22:02:34.870Z] 22:02:34 INFO - GECKO(1736) | MEMORY STAT | vsize 7566MB | residentFast 286MB | heapAllocated 117MB
[task 2020-07-27T22:02:34.870Z] 22:02:34 INFO - TEST-OK | browser/extensions/formautofill/test/browser/creditCard/browser_creditCard_doorhanger.js | took 45894ms
[task 2020-07-27T22:02:34.871Z] 22:02:34 INFO - checking window state

(In reply to Alexandru Michis [:malexandru] from comment #3)

This has been permafailing on Windows 10 x64 CCov opt since August 4th:
https://treeherder.mozilla.org/#/jobs?repo=mozilla-central&searchStr=windows%2C10%2Cx64%2Cccov%2Copt%2Cmochitests%2Ctest-windows10-64-ccov%2Fopt-mochitest-browser-chrome-e10s&tochange=7cb90fa4f485fc9dda5c1fef3ae09a826f83774a&fromchange=fdfd1e91d204eac485f83445935ff69c283b9b8d&group_state=expanded&selectedTaskRun=fyVMV9o1TnOXzKXbHQ0W2Q.0

Adam, could this be caused by Part 1 from Bug 1654388 that landed at that time?

Possibly -- the autofill tests are notoriously flaky, which is something Jim Mathies has been looking into. I've ni?'d him on this bug to put it on his radar. For the meanwhile, if it's a permafail on only one platform, I suggest disabling the test for that platform.

Flags: needinfo?(adam) → needinfo?(jmathies)

I'd be find with disabling this for ccov.

Flags: needinfo?(jmathies)
Assignee: nobody → ncsoregi
Status: NEW → ASSIGNED
Pushed by rmaries@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/84ee55cdd91a
Disabled browser_creditCard_doorhanger.js on Win 10 ccov. r=intermittent-reviewers,jmaher DONTBUILD
Assignee: ncsoregi → nobody
Status: ASSIGNED → NEW
Keywords: leave-open
Whiteboard: [stockwell disabled]
Assignee: nobody → ncsoregi
Status: NEW → ASSIGNED

Update:
There have been 40 failures within the last 7 days:
• 1 failures on Linux 18.04 x64 CCov WebRender opt
• 39 failures on Linux 18.04 x64 WebRender opt
Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=367608862&repo=autoland&lineNumber=4519

[task 2022-02-11T20:57:18.884Z] 20:57:18     INFO - TEST-PASS | browser/extensions/formautofill/test/browser/creditCard/browser_creditCard_doorhanger.js | 1 notification(s) - 
[task 2022-02-11T20:57:18.885Z] 20:57:18     INFO - expecting notification popup hidden
[task 2022-02-11T20:57:18.890Z] 20:57:18     INFO - expecting record retrievals: addresses
[task 2022-02-11T20:57:18.897Z] 20:57:18     INFO - expecting record retrievals: creditCards
[task 2022-02-11T20:57:18.898Z] 20:57:18     INFO - expecting credit card removed
[task 2022-02-11T20:57:18.899Z] 20:57:18     INFO - Buffered messages logged at 20:57:18
[task 2022-02-11T20:57:18.901Z] 20:57:18     INFO - Leaving test bound test_update_generic_creditCard_logo
[task 2022-02-11T20:57:18.902Z] 20:57:18     INFO - expecting record retrievals: addresses
[task 2022-02-11T20:57:18.903Z] 20:57:18     INFO - expecting record retrievals: creditCards
[task 2022-02-11T20:57:18.904Z] 20:57:18     INFO - Buffered messages finished
[task 2022-02-11T20:57:18.906Z] 20:57:18     INFO - TEST-UNEXPECTED-FAIL | browser/extensions/formautofill/test/browser/creditCard/browser_creditCard_doorhanger.js | This test exceeded the timeout threshold. It should be rewritten or split up. If that's not possible, use requestLongerTimeout(N), but only as a last resort. - 
[task 2022-02-11T20:57:18.907Z] 20:57:18     INFO - GECKO(13847) | MEMORY STAT | vsize 3567MB | residentFast 509MB | heapAllocated 282MB
[task 2022-02-11T20:57:18.908Z] 20:57:18     INFO - TEST-OK | browser/extensions/formautofill/test/browser/creditCard/browser_creditCard_doorhanger.js | took 45656ms
[task 2022-02-11T20:57:18.909Z] 20:57:18     INFO - checking window state
[task 2022-02-11T20:57:18.910Z] 20:57:18     INFO - TEST-START | browser/extensions/formautofill/test/browser/creditCard/browser_creditCard_telemetry.js
Whiteboard: [stockwell disabled] → [stockwell disabled][stockwell needswork:owner]

Hi Tim! Can you please take a look at this?

Flags: needinfo?(tgiles)

Still looking into this but I think we have a potential solution for this test, will hopefully have the patch updated and reviewed by next week. Keeping NI open so I don't forget.

Hi, I am getting this in some of my try push quite regularly, like: https://treeherder.mozilla.org/logviewer?job_id=369381577&repo=try&lineNumber=6066.

IIUC something is quirky with the lifecycle of gRecipeManager which seems to miss from the very start of the test.

The form autofill tests are incredibly flaky it seems which is why it's taking me so long to figure out a good resolution to this issue. Every test we fix ends up causing one or more other tests to start failing unfortunately.

Sheriffs, give me another week to figure this out. If I can't get it figured out by then, feel free to disable the affected test.

Tim has too many intermittent on his plate right now, I'll take this over.

Assignee: ncsoregi → dlee
Flags: needinfo?(tgiles)

Hi Dimi.
This has 151 total failures in the last 30 days on linux1804-64-qr opt
Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=369859319&repo=autoland&lineNumber=5376

[task 2022-03-03T21:01:47.576Z] 21:01:47     INFO - TEST-START | browser/extensions/formautofill/test/browser/creditCard/browser_creditCard_doorhanger.js
[task 2022-03-03T21:01:48.967Z] 21:01:48     INFO - GECKO(16180) | console.warn: LoginRecipes: "getRecipes: falling back to a synchronous message for:" "https://example.org"
[task 2022-03-03T21:01:48.974Z] 21:01:48     INFO - GECKO(16180) | JavaScript error: resource://gre/modules/LoginManagerParent.jsm, line 136: TypeError: can't access property "getRecipesForHost", gRecipeManager is null
[task 2022-03-03T21:01:49.290Z] 21:01:49     INFO - GECKO(16180) | JavaScript error: resource://devtools/client/jsonview/Sniffer.jsm, line 53: NS_ERROR_NOT_AVAILABLE: Component returned failure code: 0x80040111 (NS_ERROR_NOT_AVAILABLE) [nsIChannel.contentType]
[task 2022-03-03T21:01:51.620Z] 21:01:51     INFO - GECKO(16180) | console.warn: LoginRecipes: "getRecipes: falling back to a synchronous message for:" "https://example.org"
[task 2022-03-03T21:01:51.623Z] 21:01:51     INFO - GECKO(16180) | JavaScript error: resource://gre/modules/LoginManagerParent.jsm, line 136: TypeError: can't access property "getRecipesForHost", gRecipeManager is null
[task 2022-03-03T21:01:52.382Z] 21:01:52     INFO - GECKO(16180) | must wait for focus in content
[task 2022-03-03T21:01:52.983Z] 21:01:52     INFO - GECKO(16180) | JavaScript error: resource://gre/modules/LoginManagerChild.jsm, line 209: NS_ERROR_FAILURE: Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIAutoCompleteController.getStyleAt]
[task 2022-03-03T21:01:54.028Z] 21:01:54     INFO - GECKO(16180) | console.warn: LoginRecipes: "getRecipes: falling back to a synchronous message for:" "https://example.org"
[task 2022-03-03T21:01:54.030Z] 21:01:54     INFO - GECKO(16180) | JavaScript error: resource://gre/modules/LoginManagerParent.jsm, line 136: TypeError: can't access property "getRecipesForHost", gRecipeManager is null
[task 2022-03-03T21:01:55.490Z] 21:01:55     INFO - GECKO(16180) | must wait for focus in content

[task 2022-03-03T21:02:33.515Z] 21:02:33     INFO - TEST-PASS | browser/extensions/formautofill/test/browser/creditCard/browser_creditCard_doorhanger.js | at least one notification displayed - 
[task 2022-03-03T21:02:33.516Z] 21:02:33     INFO - TEST-PASS | browser/extensions/formautofill/test/browser/creditCard/browser_creditCard_doorhanger.js | 1 notification(s) - 
[task 2022-03-03T21:02:33.517Z] 21:02:33     INFO - TEST-PASS | browser/extensions/formautofill/test/browser/creditCard/browser_creditCard_doorhanger.js | CC logo should be generic - 
[task 2022-03-03T21:02:33.521Z] 21:02:33     INFO - TEST-PASS | browser/extensions/formautofill/test/browser/creditCard/browser_creditCard_doorhanger.js | at least one notification displayed - 
[task 2022-03-03T21:02:33.521Z] 21:02:33     INFO - TEST-PASS | browser/extensions/formautofill/test/browser/creditCard/browser_creditCard_doorhanger.js | 1 notification(s) - 
[task 2022-03-03T21:02:33.521Z] 21:02:33     INFO - expecting notification popup hidden
[task 2022-03-03T21:02:33.521Z] 21:02:33     INFO - expecting record retrievals: addresses
[task 2022-03-03T21:02:33.521Z] 21:02:33     INFO - expecting record retrievals: creditCards
[task 2022-03-03T21:02:33.530Z] 21:02:33     INFO - expecting credit card removed
[task 2022-03-03T21:02:33.531Z] 21:02:33     INFO - Leaving test bound test_submit_generic_creditCard_logo
[task 2022-03-03T21:02:33.532Z] 21:02:33     INFO - Entering test bound test_update_generic_creditCard_logo
[task 2022-03-03T21:02:33.534Z] 21:02:33     INFO - expecting credit card saved
[task 2022-03-03T21:02:33.535Z] 21:02:33     INFO - Buffered messages logged at 21:02:32
[task 2022-03-03T21:02:33.536Z] 21:02:33     INFO - expecting record retrievals: creditCards
[task 2022-03-03T21:02:33.537Z] 21:02:33     INFO - TEST-PASS | browser/extensions/formautofill/test/browser/creditCard/browser_creditCard_doorhanger.js | 1 credit card in storage - 
[task 2022-03-03T21:02:33.538Z] 21:02:33     INFO - Console message: [JavaScript Error: "TypeError: can't access property "getRecipesForHost", gRecipeManager is null" {file: "resource://gre/modules/LoginManagerParent.jsm" line: 136}]
[task 2022-03-03T21:02:33.539Z] 21:02:33     INFO - @resource://gre/modules/LoginManagerParent.jsm:136:3
[task 2022-03-03T21:02:33.539Z] 21:02:33     INFO - 
[task 2022-03-03T21:02:33.540Z] 21:02:33     INFO - TEST-PASS | browser/extensions/formautofill/test/browser/creditCard/browser_creditCard_doorhanger.js | at least one notification displayed - 
[task 2022-03-03T21:02:33.541Z] 21:02:33     INFO - TEST-PASS | browser/extensions/formautofill/test/browser/creditCard/browser_creditCard_doorhanger.js | 1 notification(s) - 
[task 2022-03-03T21:02:33.547Z] 21:02:33     INFO - TEST-PASS | browser/extensions/formautofill/test/browser/creditCard/browser_creditCard_doorhanger.js | CC Logo should be generic - 
[task 2022-03-03T21:02:33.548Z] 21:02:33     INFO - TEST-PASS | browser/extensions/formautofill/test/browser/creditCard/browser_creditCard_doorhanger.js | at least one notification displayed - 
[task 2022-03-03T21:02:33.549Z] 21:02:33     INFO - TEST-PASS | browser/extensions/formautofill/test/browser/creditCard/browser_creditCard_doorhanger.js | 1 notification(s) - 
[task 2022-03-03T21:02:33.550Z] 21:02:33     INFO - expecting notification popup hidden
[task 2022-03-03T21:02:33.551Z] 21:02:33     INFO - expecting record retrievals: addresses
[task 2022-03-03T21:02:33.552Z] 21:02:33     INFO - expecting record retrievals: creditCards
[task 2022-03-03T21:02:33.553Z] 21:02:33     INFO - expecting credit card removed
[task 2022-03-03T21:02:33.559Z] 21:02:33     INFO - Leaving test bound test_update_generic_creditCard_logo
[task 2022-03-03T21:02:33.560Z] 21:02:33     INFO - expecting record retrievals: addresses
[task 2022-03-03T21:02:33.561Z] 21:02:33     INFO - expecting record retrievals: creditCards
[task 2022-03-03T21:02:33.562Z] 21:02:33     INFO - Buffered messages finished
[task 2022-03-03T21:02:33.563Z] 21:02:33     INFO - TEST-UNEXPECTED-FAIL | browser/extensions/formautofill/test/browser/creditCard/browser_creditCard_doorhanger.js | This test exceeded the timeout threshold. It should be rewritten or split up. If that's not possible, use requestLongerTimeout(N), but only as a last resort. - 
[task 2022-03-03T21:02:33.564Z] 21:02:33     INFO - GECKO(16180) | MEMORY STAT | vsize 3598MB | residentFast 508MB | heapAllocated 275MB
[task 2022-03-03T21:02:33.565Z] 21:02:33     INFO - TEST-OK | browser/extensions/formautofill/test/browser/creditCard/browser_creditCard_doorhanger.js | took 45301ms
[task 2022-03-03T21:02:33.570Z] 21:02:33     INFO - checking window state

Should we disable this until a fix is ready or leave it?
Thank you!
Flags: needinfo?(dlee)
Pushed by abutkovits@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/bdf1b2aefb0f
disable browser_creditCard_doorhanger.js on Linux_64_opt for frequent failures. r=intermittent-reviewers,MasterWayZ DONTBUILD

This patches adds runAndWaitForAutocompletePopupOpen utility function.
We should use this function when we expect a task will open an
autocomplete popup.

This patch adds an focusUpdateSubmitForm utility function.
We should use this function when we want to update elements in a form
and then submit the form. The function ensures the form is "identified"
by formautofill code while submitting.

Depends on D141481

We should wait for autofill result before continuing executing the task.

Depends on D141484

If a test will add or update cc records in the storage, but don't wait for the completion of the update action,
the remaining task of the test may run prior to the update is commited, which confuses the testcase.
For example, in many tests we call removeAllRecords when the test
ends, but the order might become:

  1. First test runs, triggers an async task that updates the storage
  2. End of the test we remove all records by calling removeAllRecords()
  3. Real update of step1 happens
  4. The next test runs, which doesn't expect there is any data in the
    storage at this point.

This patch fixes this issue by waiting for storage change event for
tests that update the storage.

Depends on D141485

Attachment #9264035 - Attachment is obsolete: true
See Also: → 1760639
Flags: needinfo?(dlee)
Pushed by dlee@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/c1136ff5e55a
P1. Listen to popup open event before running a task that will open a popup. r=sgalich,tgiles
https://hg.mozilla.org/integration/autoland/rev/5ab8fd2e1d1a
P2. Listen to FieldsIdentified event before submitting a form r=sgalich,tgiles
https://hg.mozilla.org/integration/autoland/rev/bd5e4928b39f
P3. Wait for doorhanger shown event before checking doorhanger states r=sgalich,tgiles
https://hg.mozilla.org/integration/autoland/rev/92e518f40e78
P4. Listen to multiple NotifyUsed events if a credit card is used multiple times r=sgalich,tgiles
https://hg.mozilla.org/integration/autoland/rev/fd82923ec606
P5. Wait for autofill result r=sgalich,tgiles
https://hg.mozilla.org/integration/autoland/rev/0535eb0d165c
P6. Wait for "add" or "update" storage event if the test will update the storage. r=sgalich,tgiles
https://hg.mozilla.org/integration/autoland/rev/a3517b3f1e3a
P7. Make `focusUpdateSubmitForm` API easier to use r=sgalich,tgiles
Regressions: 1761381
Blocks: 1761418

Hi Dimi, should we remove the disabling conditions from this test?

Flags: needinfo?(dlee)

(In reply to Andreea Pavel [:apavel] from comment #48)

Hi Dimi, should we remove the disabling conditions from this test?

Yes, I forgot to re-enable it in this patch so I filed another bug.
It was just landed in Bug 1761418.

Flags: needinfo?(dlee)
Status: ASSIGNED → RESOLVED
Closed: 2 years ago
Keywords: leave-open
Resolution: --- → FIXED
Whiteboard: [stockwell disabled][stockwell unknown]
Target Milestone: --- → 100 Branch
See Also: → 1762968
Blocks: 1761446
Whiteboard: [fxcm-test-refactoring]
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: