1630320 - Intermittent browser/extensions/formautofill/test/browser/browser_autocomplete_footer.js | Uncaught exception - The popup should be a form autofill one - timed out after 50 tries.

Status: RESOLVED FIXED

(Toolkit :: Form Autofill, defect, P5)

Description

[Treeherder Bug Filer]

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

---

[task 2020-04-15T14:30:49.712Z] 14:30:49 INFO - TEST-START | browser/extensions/formautofill/test/browser/browser_autocomplete_footer.js
[task 2020-04-15T14:30:58.612Z] 14:30:58 INFO - TEST-INFO | started process screencapture
[task 2020-04-15T14:30:58.972Z] 14:30:58 INFO - TEST-INFO | screencapture: exit 0
[task 2020-04-15T14:30:58.972Z] 14:30:58 INFO - Buffered messages logged at 14:30:49
[task 2020-04-15T14:30:58.972Z] 14:30:58 INFO - Entering test bound setup
[task 2020-04-15T14:30:58.973Z] 14:30:58 INFO - Leaving test bound setup
[task 2020-04-15T14:30:58.973Z] 14:30:58 INFO - Entering test bound setup_storage
[task 2020-04-15T14:30:58.973Z] 14:30:58 INFO - expecting address saved
[task 2020-04-15T14:30:58.973Z] 14:30:58 INFO - expecting address saved
[task 2020-04-15T14:30:58.973Z] 14:30:58 INFO - expecting address saved
[task 2020-04-15T14:30:58.973Z] 14:30:58 INFO - expecting address saved
[task 2020-04-15T14:30:58.974Z] 14:30:58 INFO - Leaving test bound setup_storage
[task 2020-04-15T14:30:58.974Z] 14:30:58 INFO - Entering test bound test_press_enter_on_footer
[task 2020-04-15T14:30:58.974Z] 14:30:58 INFO - Console message: [JavaScript Error: "[Exception... "Component returned failure code: 0x80520001 (NS_ERROR_FILE_UNRECOGNIZED_PATH) [nsIXPCComponents_Utils.readUTF8URI]" nsresult: "0x80520001 (NS_ERROR_FILE_UNRECOGNIZED_PATH)" location: "JS frame :: resource://gre/modules/L10nRegistry.jsm :: L10nRegistry.loadSync :: line 658" data: no]"]
[task 2020-04-15T14:30:58.974Z] 14:30:58 INFO - L10nRegistry.loadSync@resource://gre/modules/L10nRegistry.jsm:658:19
[task 2020-04-15T14:30:58.974Z] 14:30:58 INFO - fetchFile@resource://gre/modules/L10nRegistry.jsm:573:31
[task 2020-04-15T14:30:58.975Z] 14:30:58 INFO - generateResourceSetSync/<@resource://gre/modules/L10nRegistry.jsm:478:19
[task 2020-04-15T14:30:58.975Z] 14:30:58 INFO - generateResourceSetSync@resource://gre/modules/L10nRegistry.jsm:473:22
[task 2020-04-15T14:30:58.975Z] 14:30:58 INFO - generateResourceSetsForLocaleSync@resource://gre/modules/L10nRegistry.jsm:415:44
[task 2020-04-15T14:30:58.975Z] 14:30:58 INFO - generateBundlesSync@resource://gre/modules/L10nRegistry.jsm:177:7
[task 2020-04-15T14:30:58.975Z] 14:30:58 INFO - touchNext@resource://gre/modules/Localization.jsm:167:37
[task 2020-04-15T14:30:58.975Z] 14:30:58 INFO - onChange@resource://gre/modules/Localization.jsm:510:20
[task 2020-04-15T14:30:58.975Z] 14:30:58 INFO - init@resource://gre/modules/Localization.jsm:237:10
[task 2020-04-15T14:30:58.975Z] 14:30:58 INFO - getRegionDisplayNames@resource://gre/modules/mozIntl.jsm:732:19
[task 2020-04-15T14:30:58.975Z] 14:30:58 INFO - _normalizeCountry@resource://formautofill/FormAutofillStorage.jsm:1625:43
[task 2020-04-15T14:30:58.975Z] 14:30:58 INFO - _normalizeFields@resource://formautofill/FormAutofillStorage.jsm:1567:10
[task 2020-04-15T14:30:58.975Z] 14:30:58 INFO - _normalizeRecord@resource://formautofill/FormAutofillStorage.jsm:1321:10
[task 2020-04-15T14:30:58.975Z] 14:30:58 INFO - add@resource://formautofill/FormAutofillStorage.jsm:388:12
[task 2020-04-15T14:30:58.975Z] 14:30:58 INFO - receiveMessage@resource://formautofill/FormAutofillParent.jsm:339:48
[task 2020-04-15T14:30:58.976Z] 14:30:58 INFO - emulateMessageToBrowser@chrome://mochitests/content/browser/browser/extensions/formautofill/test/browser/head.js:334:16
[task 2020-04-15T14:30:58.976Z] 14:30:58 INFO - saveAddress@chrome://mochitests/content/browser/browser/extensions/formautofill/test/browser/head.js:353:9
[task 2020-04-15T14:30:58.976Z] 14:30:58 INFO - setup_storage@chrome://mochitests/content/browser/browser/extensions/formautofill/test/browser/browser_autocomplete_footer.js:7:9
[task 2020-04-15T14:30:58.976Z] 14:30:58 INFO - Tester_execTest/<@chrome://mochikit/content/browser-test.js:1039:34
[task 2020-04-15T14:30:58.976Z] 14:30:58 INFO - async*Tester_execTest@chrome://mochikit/content/browser-test.js:1074:11
[task 2020-04-15T14:30:58.976Z] 14:30:58 INFO - nextTest/<@chrome://mochikit/content/browser-test.js:904:14
[task 2020-04-15T14:30:58.976Z] 14:30:58 INFO - SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:918:23
[task 2020-04-15T14:30:58.976Z] 14:30:58 INFO -
[task 2020-04-15T14:30:58.976Z] 14:30:58 INFO - Buffered messages logged at 14:30:50
[task 2020-04-15T14:30:58.976Z] 14:30:58 INFO - expecting the target input being focused and identified
[task 2020-04-15T14:30:58.977Z] 14:30:58 INFO - !previouslyFocused
[task 2020-04-15T14:30:58.977Z] 14:30:58 INFO - FieldsIdentified
[task 2020-04-15T14:30:58.977Z] 14:30:58 INFO - Buffered messages logged at 14:30:51
[task 2020-04-15T14:30:58.977Z] 14:30:58 INFO - openPopupOn: before VK_DOWN
[task 2020-04-15T14:30:58.977Z] 14:30:58 INFO - expectPopupOpen
[task 2020-04-15T14:30:58.978Z] 14:30:58 INFO - getDisplayedPopupItems
[task 2020-04-15T14:30:58.978Z] 14:30:58 INFO - getDisplayedPopupItems
[task 2020-04-15T14:30:58.978Z] 14:30:58 INFO - getDisplayedPopupItems
[task 2020-04-15T14:30:58.978Z] 14:30:58 INFO - getDisplayedPopupItems
[task 2020-04-15T14:30:58.978Z] 14:30:58 INFO - Buffered messages logged at 14:30:52
[task 2020-04-15T14:30:58.979Z] 14:30:58 INFO - getDisplayedPopupItems
[task 2020-04-15T14:30:58.979Z] 14:30:58 INFO - getDisplayedPopupItems
[task 2020-04-15T14:30:58.979Z] 14:30:58 INFO - getDisplayedPopupItems
[task 2020-04-15T14:30:58.979Z] 14:30:58 INFO - getDisplayedPopupItems
[task 2020-04-15T14:30:58.979Z] 14:30:58 INFO - getDisplayedPopupItems
[task 2020-04-15T14:30:58.980Z] 14:30:58 INFO - getDisplayedPopupItems
[task 2020-04-15T14:30:58.980Z] 14:30:58 INFO - getDisplayedPopupItems
[task 2020-04-15T14:30:58.980Z] 14:30:58 INFO - Buffered messages logged at 14:30:53
[task 2020-04-15T14:30:58.980Z] 14:30:58 INFO - getDisplayedPopupItems
[task 2020-04-15T14:30:58.980Z] 14:30:58 INFO - getDisplayedPopupItems
[task 2020-04-15T14:30:58.980Z] 14:30:58 INFO - getDisplayedPopupItems
[task 2020-04-15T14:30:58.981Z] 14:30:58 INFO - getDisplayedPopupItems
[task 2020-04-15T14:30:58.981Z] 14:30:58 INFO - getDisplayedPopupItems
[task 2020-04-15T14:30:58.981Z] 14:30:58 INFO - getDisplayedPopupItems
[task 2020-04-15T14:30:58.981Z] 14:30:58 INFO - getDisplayedPopupItems
[task 2020-04-15T14:30:58.982Z] 14:30:58 INFO - Buffered messages logged at 14:30:54
[task 2020-04-15T14:30:58.982Z] 14:30:58 INFO - getDisplayedPopupItems
[task 2020-04-15T14:30:58.982Z] 14:30:58 INFO - getDisplayedPopupItems
[task 2020-04-15T14:30:58.983Z] 14:30:58 INFO - getDisplayedPopupItems
[task 2020-04-15T14:30:58.983Z] 14:30:58 INFO - getDisplayedPopupItems
[task 2020-04-15T14:30:58.983Z] 14:30:58 INFO - getDisplayedPopupItems
[task 2020-04-15T14:30:58.983Z] 14:30:58 INFO - getDisplayedPopupItems
[task 2020-04-15T14:30:58.984Z] 14:30:58 INFO - Buffered messages logged at 14:30:55
[task 2020-04-15T14:30:58.984Z] 14:30:58 INFO - getDisplayedPopupItems
[task 2020-04-15T14:30:58.985Z] 14:30:58 INFO - getDisplayedPopupItems
[task 2020-04-15T14:30:58.985Z] 14:30:58 INFO - getDisplayedPopupItems
[task 2020-04-15T14:30:58.985Z] 14:30:58 INFO - getDisplayedPopupItems
[task 2020-04-15T14:30:58.985Z] 14:30:58 INFO - getDisplayedPopupItems
[task 2020-04-15T14:30:58.985Z] 14:30:58 INFO - getDisplayedPopupItems
[task 2020-04-15T14:30:58.986Z] 14:30:58 INFO - getDisplayedPopupItems
[task 2020-04-15T14:30:58.988Z] 14:30:58 INFO - getDisplayedPopupItems
[task 2020-04-15T14:30:58.989Z] 14:30:58 INFO - Buffered messages logged at 14:30:56
[task 2020-04-15T14:30:58.989Z] 14:30:58 INFO - getDisplayedPopupItems
[task 2020-04-15T14:30:58.989Z] 14:30:58 INFO - getDisplayedPopupItems
[task 2020-04-15T14:30:58.990Z] 14:30:58 INFO - getDisplayedPopupItems
[task 2020-04-15T14:30:58.990Z] 14:30:58 INFO - getDisplayedPopupItems
[task 2020-04-15T14:30:58.990Z] 14:30:58 INFO - getDisplayedPopupItems
[task 2020-04-15T14:30:58.990Z] 14:30:58 INFO - getDisplayedPopupItems
[task 2020-04-15T14:30:58.990Z] 14:30:58 INFO - getDisplayedPopupItems
[task 2020-04-15T14:30:58.991Z] 14:30:58 INFO - Buffered messages logged at 14:30:57
[task 2020-04-15T14:30:58.991Z] 14:30:58 INFO - getDisplayedPopupItems
[task 2020-04-15T14:30:58.991Z] 14:30:58 INFO - getDisplayedPopupItems
[task 2020-04-15T14:30:58.991Z] 14:30:58 INFO - getDisplayedPopupItems
[task 2020-04-15T14:30:58.991Z] 14:30:58 INFO - getDisplayedPopupItems
[task 2020-04-15T14:30:58.992Z] 14:30:58 INFO - getDisplayedPopupItems
[task 2020-04-15T14:30:58.992Z] 14:30:58 INFO - getDisplayedPopupItems
[task 2020-04-15T14:30:58.992Z] 14:30:58 INFO - getDisplayedPopupItems
[task 2020-04-15T14:30:58.992Z] 14:30:58 INFO - getDisplayedPopupItems
[task 2020-04-15T14:30:58.992Z] 14:30:58 INFO - Buffered messages logged at 14:30:58
[task 2020-04-15T14:30:58.993Z] 14:30:58 INFO - getDisplayedPopupItems
[task 2020-04-15T14:30:58.995Z] 14:30:58 INFO - getDisplayedPopupItems
[task 2020-04-15T14:30:58.995Z] 14:30:58 INFO - getDisplayedPopupItems
[task 2020-04-15T14:30:58.995Z] 14:30:58 INFO - Buffered messages finished
[task 2020-04-15T14:30:58.995Z] 14:30:58 INFO - TEST-UNEXPECTED-FAIL | browser/extensions/formautofill/test/browser/browser_autocomplete_footer.js | Uncaught exception - The popup should be a form autofill one - timed out after 50 tries.
[task 2020-04-15T14:30:58.995Z] 14:30:58 INFO - Leaving test bound test_press_enter_on_footer
[task 2020-04-15T14:30:58.996Z] 14:30:58 INFO - Entering test bound test_click_on_footer
[task 2020-04-15T14:30:59.277Z] 14:30:59 INFO - expecting the target input being focused and identified
[task 2020-04-15T14:30:59.278Z] 14:30:59 INFO - !previouslyFocused
[task 2020-04-15T14:30:59.278Z] 14:30:59 INFO - FieldsIdentified
[task 2020-04-15T14:30:59.775Z] 14:30:59 INFO - openPopupOn: before VK_DOWN
[task 2020-04-15T14:30:59.775Z] 14:30:59 INFO - expectPopupOpen
[task 2020-04-15T14:30:59.978Z] 14:30:59 INFO - GECKO(2270) | JavaScript error: chrome://global/content/elements/autocomplete-popup.js, line 482: TypeError: item._adjustAcItem is not a function
[task 2020-04-15T14:30:59.978Z] 14:30:59 INFO - Console message: [JavaScript Error: "TypeError: item._adjustAcItem is not a function" {file: "chrome://global/content/elements/autocomplete-popup.js" line: 482}]

Comment 1

[Intermittent Failures Robot]

3 failures in 4528 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 3

Platform breakdown:

• macosx1014-64-shippable: 3

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1630320&startday=2020-04-13&endday=2020-04-19&tree=all

Comment 2

[Cristina Coroiu [:ccoroiu]]

Retriggered on this range:
https://treeherder.mozilla.org/#/jobs?repo=autoland&searchStr=OS%2CX%2C10.14%2CShippable%2Copt%2CMochitests%2Ctest-macosx1014-64-shippable%2Fopt-mochitest-browser-chrome-e10s-6%2CM%28bc6%29&tochange=43b914eee3e3e9fca5986ce6791d35939905f50f&fromchange=16800c586d6f98aa84ea1e714fe5eccd802c99eb&selectedJob=299358230

The culprit seems to be https://hg.mozilla.org/integration/autoland/rev/43b914eee3e3e9fca5986ce6791d35939905f50f

Jean, can you please take a look?

Comment 3

[Jean-Yves Avenard [:jya]]

Another test not waiting for the load event to start.

Comment 4

[Jean-Yves Avenard [:jya]]

Attachment: Bug 1630320 - in browser_autocomplete_footer.js wait for the tab to load before attempting to retrieve its content. r?Gijs,mccr8

Comment 6

[Intermittent Failures Robot]

57 failures in 1125 pushes (0.051 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 57

Platform breakdown:

• macosx1014-64-shippable: 56
• macosx1014-64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1630320&startday=2020-04-24&endday=2020-04-24&tree=all

Comment 7

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/f3323f5ac02c
in browser_autocomplete_footer.js wait for the tab to load before attempting to retrieve its content. r=Gijs

Comment 8

[Pulsebot]

Backout by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/646b2f07e398
Backed out 2 changesets (bug 1630320, bug 1632098) for causing high frequency mochitest failures.

Comment 9

[Arthur Iakab [arthur_iakab]]

Backed out 2 changesets (bug 1630320, bug 1632098) for causing high frequency mochitest failures.

Backout revision https://hg.mozilla.org/integration/autoland/rev/646b2f07e39803242f0cb0b04c17bec6f0282b10

Failure logs https://treeherder.mozilla.org/logviewer.html#?job_id=299413576&repo=autoland
https://treeherder.mozilla.org/logviewer.html#?job_id=299420693&repo=autoland
https://treeherder.mozilla.org/logviewer.html#?job_id=299416687&repo=autoland

Failures:

• https://treeherder.mozilla.org/#/jobs?repo=autoland&resultStatus=success%2Ctestfailed%2Cbusted%2Cexception&fromchange=15f28d419ea6ee19c8e3a8f6f2cd7017ef42c4c5&searchStr=fed6b3e8caf13ec384525781b6a461448420d66f&selectedJob=299413576
• https://treeherder.mozilla.org/#/jobs?repo=autoland&resultStatus=success%2Ctestfailed%2Cbusted%2Cexception&fromchange=15f28d419ea6ee19c8e3a8f6f2cd7017ef42c4c5&searchStr=9ab9662defc13edcd6d1689d11b5b7692977ec05&selectedJob=299416687

Jean can you please take a look?

Comment 10

[Natalia Csoregi [:nataliaCs]]

https://hg.mozilla.org/mozilla-central/rev/f3323f5ac02c

Comment 11

[Intermittent Failures Robot]

52 failures in 230 pushes (0.226 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 46
• mozilla-central: 1
• try: 5

Platform breakdown:

• macosx1014-64-shippable: 49
• macosx1014-64-devedition: 2
• windows10-64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1630320&startday=2020-04-25&endday=2020-04-25&tree=all

Comment 12

[Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)]

Backout merged: https://hg.mozilla.org/mozilla-central/rev/646b2f07e398

Comment 13

[Intermittent Failures Robot]

109 failures in 5582 pushes (0.02 failures/push) were associated with this bug in the last 7 days.

This is the #15 most frequent failure this week.

** This failure happened more than 75 times this week! Resolving this bug is a very high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 1 week, the affected test(s) may be disabled. **

Repository breakdown:

• autoland: 103
• mozilla-central: 1
• try: 5

Platform breakdown:

• macosx1014-64-shippable: 105
• macosx1014-64: 1
• macosx1014-64-devedition: 2
• windows10-64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1630320&startday=2020-04-20&endday=2020-04-26&tree=all

Comment 14

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/6d4c25a9758f
in browser_autocomplete_footer.js wait for the tab to load before attempting to retrieve its content. r=Gijs

Comment 15

[Stefan Hindli [:stefan_hindli]]

https://hg.mozilla.org/mozilla-central/rev/6d4c25a9758f

Comment 16

[Intermittent Failures Robot]

1 failures in 4310 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-esr68: 1

Platform breakdown:

• macosx1014-64-shippable: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1630320&startday=2020-07-20&endday=2020-07-26&tree=all