Closed Bug 1374523 Opened 7 years ago Closed 7 years ago

Intermittent browser/extensions/formautofill/test/browser/browser_autocomplete_footer.js | Test timed out -

Categories

(Toolkit :: Form Autofill, defect, P3)

Product:
Toolkit
Component:
Form Autofill
Type:
defect

Tracking

()

Status:
RESOLVED FIXED
Milestone:
mozilla58
Tracking Flags:
Tracking Status
firefox58 --- fixed

People

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

References

Details

(Keywords: intermittent-failure, Whiteboard: [form autofill][stockwell fixed:timing])

Attachments

(1 file)

Bug 1374523 - [Form Autofill] Increase timer to wait for dropdown rendering and run keyboard test first in browser_autocomplete_footer.js.
59 bytes, text/x-review-board-request
ralin
: review+
Details
Component: Autocomplete → Form Manager
See Also: → 1401082
Whiteboard: [form autofill]
In the last week there were 37 failures.
Most of the failures occur on Mac (OS X 10.10 and macosx64-stylo-disabled) and the rest of them on Windows 7 x32 and Windows 10 x64.
The affected build types are opt and debug.

Here you have a recent example of the log on OS X 10.10
https://treeherder.mozilla.org/logviewer.html#?repo=autoland&job_id=141057938&lineNumber=12641

And a relevant part of the test failure:

07:18:21     INFO - TEST-START | browser/extensions/formautofill/test/browser/browser_autocomplete_footer.js
12591
07:18:21     INFO - GECKO(895) | ++DOMWINDOW == 6 (0x11eae2800) [pid = 896] [serial = 6] [outer = 0x11db7d800]
12592
07:18:21     INFO - GECKO(895) | ++DOMWINDOW == 7 (0x11ec94800) [pid = 896] [serial = 7] [outer = 0x11db7d800]
12593
07:18:21     INFO - GECKO(895) | [Child 896, Main Thread] WARNING: attempt to modify an immutable nsStandardURL: file /builds/worker/workspace/build/src/netwerk/base/nsStandardURL.cpp, line 1827
12594
07:18:22     INFO - GECKO(895) | ### XPCOM_MEM_BLOAT_LOG defined -- logging bloat/leaks to /var/folders/gn/sc9r1b1x24lgjq6z_dqk79b000000w/T/tmp2Hd1ml.mozrunner/runtests_leaks_tab_pid898.log
12595
07:18:22     INFO - GECKO(895) | Unable to read VR Path Registry from /Users/cltbld/Library/Application Support/OpenVR/.openvr/openvrpaths.vrpath
12596
07:18:22     INFO - GECKO(895) | ++DOCSHELL 0x117db2000 == 1 [pid = 897] [id = {076e58c6-aed2-3444-a57a-f4186745c302}]
12597
07:18:22     INFO - GECKO(895) | ++DOMWINDOW == 1 (0x117db3000) [pid = 897] [serial = 1] [outer = 0x0]
12598
07:18:22     INFO - GECKO(895) | Unable to read VR Path Registry from /Users/cltbld/Library/Application Support/OpenVR/.openvr/openvrpaths.vrpath
12599
07:18:23     INFO - GECKO(895) | ++DOMWINDOW == 2 (0x11e725800) [pid = 897] [serial = 2] [outer = 0x117db3000]
12600
07:18:23     INFO - GECKO(895) | ++DOCSHELL 0x115fb2800 == 1 [pid = 898] [id = {efa9002f-69e1-f34d-afa0-37c270a2d359}]
12601
07:18:23     INFO - GECKO(895) | ++DOMWINDOW == 1 (0x115fb3800) [pid = 898] [serial = 1] [outer = 0x0]
12602
07:18:23     INFO - GECKO(895) | 2017-10-31 07:18:23.326 plugin-container[897:11650] *** CFMessagePort: bootstrap_register(): failed 1100 (0x44c) 'Permission denied', port = 0x9653, name = 'com.apple.tsm.portname'
12603
07:18:23     INFO - GECKO(895) | See /usr/include/servers/bootstrap_defs.h for the error codes.
12604
07:18:23     INFO - GECKO(895) | ++DOMWINDOW == 2 (0x11c91d800) [pid = 898] [serial = 2] [outer = 0x115fb3800]
12605
07:18:23     INFO - GECKO(895) | [Child 898, Main Thread] WARNING: site security information will not be persisted: file /builds/worker/workspace/build/src/security/manager/ssl/nsSiteSecurityService.cpp, line 553
12606
07:18:23     INFO - GECKO(895) | [Parent 895, Main Thread] WARNING: Could not get disk status from nsIDiskSpaceWatcher: file /builds/worker/workspace/build/src/uriloader/prefetch/nsOfflineCacheUpdateService.cpp, line 283
12607
07:18:23     INFO - GECKO(895) | 2017-10-31 07:18:23.502 plugin-container[898:11677] *** CFMessagePort: bootstrap_register(): failed 1100 (0x44c) 'Permission denied', port = 0x9657, name = 'com.apple.tsm.portname'
12608
07:18:23     INFO - GECKO(895) | See /usr/include/servers/bootstrap_defs.h for the error codes.
12609
07:18:23     INFO - GECKO(895) | [Parent 895, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80070057: file /builds/worker/workspace/build/src/netwerk/base/nsChannelClassifier.cpp, line 344
12610
07:18:23     INFO - GECKO(895) | ++DOMWINDOW == 3 (0x11d771800) [pid = 898] [serial = 3] [outer = 0x115fb3800]
12611
07:18:24     INFO - GECKO(895) | ### XPCOM_MEM_BLOAT_LOG defined -- logging bloat/leaks to /var/folders/gn/sc9r1b1x24lgjq6z_dqk79b000000w/T/tmp2Hd1ml.mozrunner/runtests_leaks_tab_pid899.log
12612
07:18:24     INFO - GECKO(895) | [Parent 895, Main Thread] WARNING: NS_ENSURE_TRUE(aSecondURI) failed: file /builds/worker/workspace/build/src/dom/base/ThirdPartyUtil.cpp, line 98
12613
07:18:25     INFO - GECKO(895) | Unable to read VR Path Registry from /Users/cltbld/Library/Application Support/OpenVR/.openvr/openvrpaths.vrpath
12614
07:18:25     INFO - GECKO(895) | 2017-10-31 07:18:25.313 plugin-container[899:11732] *** CFMessagePort: bootstrap_register(): failed 1100 (0x44c) 'Permission denied', port = 0x994f, name = 'com.apple.tsm.portname'
12615
07:18:25     INFO - GECKO(895) | See /usr/include/servers/bootstrap_defs.h for the error codes.
12616
07:18:26     INFO - GECKO(895) | --DOCSHELL 0x123317000 == 4 [pid = 895] [id = {3125f1ba-4bf5-d24f-b47c-2dde0303f8d0}]
12617
07:18:27     INFO - GECKO(895) | --DOCSHELL 0x1166a7000 == 1 [pid = 896] [id = {088147d1-1d3a-0d4f-855a-017271cacc50}]
12618
07:18:32     INFO - GECKO(895) | --DOMWINDOW == 6 (0x11d048000) [pid = 896] [serial = 2] [outer = 0x0] [url = about:blank]
12619
07:18:32     INFO - GECKO(895) | --DOMWINDOW == 5 (0x11eae2800) [pid = 896] [serial = 6] [outer = 0x0] [url = about:blank]
12620
07:18:33     INFO - GECKO(895) | --DOMWINDOW == 9 (0x12331a000) [pid = 895] [serial = 6] [outer = 0x0] [url = about:blank]
12621
07:18:35     INFO - GECKO(895) | --DOMWINDOW == 4 (0x1166a8000) [pid = 896] [serial = 1] [outer = 0x0] [url = about:blank]
12622
07:18:36     INFO - GECKO(895) | --DOMWINDOW == 2 (0x11c91d800) [pid = 898] [serial = 2] [outer = 0x0] [url = about:blank]
12623
07:18:39     INFO - GECKO(895) | [Parent 895, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80520012: file /builds/worker/workspace/build/src/dom/fetch/FetchDriver.cpp, line 417
12624
07:18:39     INFO - GECKO(895) | --DOMWINDOW == 3 (0x11ead1000) [pid = 896] [serial = 4] [outer = 0x0] [url = about:blank]
12625
07:18:39     INFO - GECKO(895) | --DOMWINDOW == 2 (0x11db6c000) [pid = 896] [serial = 3] [outer = 0x0] [url = about:blank]
12626
07:18:39     INFO - GECKO(895) | --DOMWINDOW == 8 (0x12371f000) [pid = 895] [serial = 7] [outer = 0x0] [url = about:blank]
12627
07:19:51     INFO - TEST-INFO | started process screencapture
12628
07:19:51     INFO - TEST-INFO | screencapture: exit 0
12629
07:19:51     INFO - Buffered messages logged at 07:18:21
12630
07:19:51     INFO - Entering test bound setup_storage
12631
07:19:52     INFO - Buffered messages logged at 07:18:22
12632
07:19:52     INFO - Leaving test bound setup_storage
12633
07:19:52     INFO - Entering test bound test_click_on_footer
12634
07:19:52     INFO - Global property added while loading chrome://browser/content/browser-sync.js: UIState
12635
07:19:52     INFO - Global property added while loading chrome://browser/content/browser-sync.js: EnsureFxAccountsWebChannel
12636
07:19:52     INFO - Global property added while loading chrome://browser/content/browser-thumbnails.js: getTopSiteURLs
12637
07:19:52     INFO - Buffered messages logged at 07:18:23
12638
07:19:52     INFO - Console message: [JavaScript Warning: "Use of nsIFile in content process is deprecated." {file: "resource://gre/modules/FileUtils.jsm" line: 174}]
12639
07:19:52     INFO - Console message: [JavaScript Warning: "Use of nsIFile in content process is deprecated." {file: "resource://gre/modules/FileUtils.jsm" line: 174}]
12640
07:19:52     INFO - Buffered messages finished
12641
07:19:52     INFO - TEST-UNEXPECTED-FAIL | browser/extensions/formautofill/test/browser/browser_autocomplete_footer.js | Test timed out - 
12642
07:19:52     INFO - GECKO(895) | MEMORY STAT vsizeMaxContiguous not supported in this build configuration.
12643
07:19:52     INFO - GECKO(895) | MEMORY STAT | vsize 4370MB | residentFast 342MB | heapAllocated 81MB
12644
07:19:52     INFO - TEST-OK | browser/extensions/formautofill/test/browser/browser_autocomplete_footer.js | took 90083ms
12645
07:19:52     INFO - Not taking screenshot here: see the one that was previously logged
12646
07:19:52     INFO - TEST-UNEXPECTED-FAIL | browser/extensions/formautofill/test/browser/browser_autocomplete_footer.js | Found a tab after previous test timed out: http://mochi.test:8888/browser/browser/extensions/formautofill/test/browser/autocomplete_basic.html - 
12647
07:19:52     INFO - GECKO(895) | ++DOCSHELL 0x120725000 == 1 [pid = 899] [id = {9a3a588f-5acc-df48-b9b7-5ece3b18938a}]
12648
07:19:52     INFO - GECKO(895) | ++DOMWINDOW == 1 (0x120726000) [pid = 899] [serial = 1] [outer = 0x0]
12649
07:19:52     INFO - checking window state

:MattN, can you please take a look?
Flags: needinfo?(MattN+bmo)
Whiteboard: [form autofill] → [form autofill] [stockwell needswork]
Luke, can you find someone to look at this?
Flags: needinfo?(MattN+bmo) → needinfo?(lchang)
No problem. I'll look into it.
Assignee: nobody → lchang
Flags: needinfo?(lchang)
Priority: -- → P3
Depends on: 1414740
Blocks: 1415104
I randomly picked a failure log, and observed the last info was:

INFO -  1050 INFO expecting tab: about:preferences#privacy opened

so the timed out occurred due to waiting for the new tab opened: http://searchfox.org/mozilla-central/rev/c99d035f00dd894feff38e4ad28a73fb679c63a6/browser/extensions/formautofill/test/browser/browser_autocomplete_footer.js#35

I would suspect mouse click trigger before the dropdown is fully expanded in debug build, which might has cpu bound dealing with animation, even so, sleep(1000) should be able to mitigate the failure rate is it's really this case. I'll keep watching on the rate next few days.
Component: Form Manager → Form Autofill
Thanks for Ray's investigation and suggestion. Let's see if the patch works.
Status: NEW → ASSIGNED
Comment on attachment 8926773 [details]
Bug 1374523 - [Form Autofill] Increase timer to wait for dropdown rendering and run keyboard test first in browser_autocomplete_footer.js.

https://reviewboard.mozilla.org/r/198014/#review203206

Looks good! Thanks!
Attachment #8926773 - Flags: review?(ralin) → review+
Pushed by lchang@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/8e5b21f2547f
[Form Autofill] Increase timer to wait for dropdown rendering and run keyboard test first in browser_autocomplete_footer.js. r=ralin
https://hg.mozilla.org/mozilla-central/rev/8e5b21f2547f
Status: ASSIGNED → RESOLVED
Closed: 7 years ago
status-firefox58: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla58
Whiteboard: [form autofill] [stockwell needswork] → [form autofill][stockwell fixed:timing]
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: