Closed
Bug 1339739
Opened 8 years ago
Closed 8 years ago
Intermittent browser/components/extensions/test/browser/browser_ext_sidebarAction.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. -
Categories
(WebExtensions :: General, defect, P1)
WebExtensions
General
Tracking
(firefox-esr52 unaffected, firefox53 unaffected, firefox54 fixed, firefox55 fixed)
RESOLVED
FIXED
mozilla55
Tracking | Status | |
---|---|---|
firefox-esr52 | --- | unaffected |
firefox53 | --- | unaffected |
firefox54 | --- | fixed |
firefox55 | --- | fixed |
People
(Reporter: intermittent-bug-filer, Assigned: mixedpuppy)
References
Details
(Keywords: intermittent-failure, Whiteboard: [stockwell fixed])
Attachments
(1 file)
Comment hidden (Intermittent Failures Robot) |
Updated•8 years ago
|
Flags: needinfo?(mixedpuppy)
Comment hidden (Intermittent Failures Robot) |
Updated•8 years ago
|
Severity: normal → major
Priority: -- → P1
Comment hidden (Intermittent Failures Robot) |
Comment 4•8 years ago
|
||
this spiked tuesday afternoon/evening. I am working on backfilling data- so far 45 failures in two days and this test is only run once every 5th push during peak load, so the real failure rate is much higher. I see in a successful case this takes 61.x seconds to run for linux64 debug- that is already a long time, but in the failure case it took 98.x seconds.
I am narrowing it down to this range:
https://treeherder.mozilla.org/#/jobs?repo=mozilla-inbound&filter-searchStr=linux%20debug%20e10s%20bc10&tochange=fed3397d5988bc178b1fe865297f2d2a25c11e13&fromchange=cfe4b63ed4f7486877d268e1d78325c11e0eaa2a&selectedJob=83100814
here is part of a failure log:
[task 2017-03-08T01:40:40.456996Z] 01:40:40 INFO - TEST-PASS | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_sidebarAction.js | sidebar box is visible in first window -
[task 2017-03-08T01:40:40.459598Z] 01:40:40 INFO - TEST-PASS | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_sidebarAction.js | unable to set empty panel -
[task 2017-03-08T01:40:40.462208Z] 01:40:40 INFO - Buffered messages logged at 01:40:21
[task 2017-03-08T01:40:40.463532Z] 01:40:40 INFO - Leaving test bound sidebar_empty_panel
[task 2017-03-08T01:40:40.465436Z] 01:40:40 INFO - Entering test bound sidebar_tab_query_bug_1340739
[task 2017-03-08T01:40:40.465781Z] 01:40:40 INFO - Extension loaded
[task 2017-03-08T01:40:40.482300Z] 01:40:40 INFO - Console message: 1488937220915 addons.manager WARN AddonListener threw exception when calling onUninstalled: TypeError: Services.domStorageManager.getStorage(...) is null (resource://gre/modules/Extension.jsm:201:7) JS Stack trace: onUninstalled@Extension.jsm:201:7 < callAddonListeners@AddonManager.jsm:1693:11 < callAddonListeners@AddonManager.jsm:3153:5 < uninstallAddon@XPIProvider.jsm:5259:7 < uninstall@XPIProvider.jsm:7618:5 < shutdown@ExtensionTestCommon.jsm:130:5 < _receiveMessageAPI@SpecialPowersObserverAPI.js:588:9 < ChromePowers.prototype._receiveMessage@ChromePowers.js:83:14 < ChromePowers.prototype._sendAsyncMessage@ChromePowers.js:45:3 < unload@specialpowersAPI.js:1976:9 < sidebar_empty_panel@browser_ext_sidebarAction.js:126:9 < TaskImpl_run@Task.jsm:319:42 < promise callback*TaskImpl_handleResultValue@Task.jsm:396:7 < TaskImpl_run@Task.jsm:327:15 < promise callback*TaskImpl_handleResultValue@Task.jsm:396:7 < TaskImpl_run@Task.jsm:327:15 < promise callback*TaskImpl_handleResultValue@Task.jsm:396:7 < TaskImpl_run@Task.jsm:327:15 < TaskImpl@Task.jsm:277:3 < asyncFunction@Task.jsm:252:14 < Task_spawn@Task.jsm:166:12 < TaskImpl_handleResultValue@Task.jsm:389:16 < TaskImpl_run@Task.jsm:327:15 < process@Promise-backend.js:922:23 < walkerLoop@Promise-backend.js:806:7 < Promise*scheduleWalkerLoop@Promise-backend.js:739:11 < schedulePromise@Promise-backend.js:770:7 < completePromise@Promise-backend.js:707:7 < TaskImpl_run@Task.jsm:324:15 < promise callback*TaskImpl_handleResultValue@Task.jsm:396:7 < TaskImpl_run@Task.jsm:327:15 < promise callback*TaskImpl_handleResultValue@Task.jsm:396:7 < TaskImpl_run@Task.jsm:327:15 < promise callback*TaskImpl_handleResultValue@Task.jsm:396:7 < TaskImpl_run@Task.jsm:327:15 < process@Promise-backend.js:922:23 < walkerLoop@Promise-backend.js:806:7 < Promise*scheduleWalkerLoop@Promise-backend.js:739:11 < schedulePromise@Promise-backend.js:770:7 < completePromise@Promise-backend.js:707:7 < TaskImpl_run@Task.jsm:324:15 < promise callback*TaskImpl_handleResultValue@Task.jsm:396:7 < TaskImpl_run@Task.jsm:327:15 < promise callback*TaskImpl_handleResultValue@Task.jsm:396:7 < TaskImpl_run@Task.jsm:327:15 < TaskImpl@Task.jsm:277:3 < asyncFunction@Task.jsm:252:14 < sidebar_windows@browser_ext_sidebarAction.js:104:19 < TaskImpl_run@Task.jsm:319:42 < promise callback*TaskImpl_handleResultValue@Task.jsm:396:7 < TaskImpl_run@Task.jsm:327:15 < promise callback*TaskImpl_handleResultValue@Task.jsm:396:7 < TaskImpl_run@Task.jsm:327:15 < TaskImpl@Task.jsm:277:3 < asyncFunction@Task.jsm:252:14 < Task_spawn@Task.jsm:166:12 < TaskImpl_handleResultValue@Task.jsm:389:16 < TaskImpl_run@Task.jsm:327:15 < process@Promise-backend.js:922:23
[task 2017-03-08T01:40:40.483051Z] 01:40:40 INFO - Buffered messages logged at 01:40:34
[task 2017-03-08T01:40:40.485411Z] 01:40:40 INFO - TEST-PASS | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_sidebarAction.js | got tab without currentWindow - Expected: 1, Actual: 1 -
[task 2017-03-08T01:40:40.488696Z] 01:40:40 INFO - TEST-PASS | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_sidebarAction.js | got tab with currentWindow - Expected: 1, Actual: 1 -
[task 2017-03-08T01:40:40.488994Z] 01:40:40 INFO - Buffered messages logged at 01:40:35
[task 2017-03-08T01:40:40.489243Z] 01:40:40 INFO - Leaving test bound sidebar_tab_query_bug_1340739
[task 2017-03-08T01:40:40.492543Z] 01:40:40 INFO - Entering test bound cleanup
[task 2017-03-08T01:40:40.495208Z] 01:40:40 INFO - Leaving test bound cleanup
[task 2017-03-08T01:40:40.506392Z] 01:40:40 INFO - Console message: 1488937235262 addons.manager WARN AddonListener threw exception when calling onUninstalled: TypeError: Services.domStorageManager.getStorage(...) is null (resource://gre/modules/Extension.jsm:201:7) JS Stack trace: onUninstalled@Extension.jsm:201:7 < callAddonListeners@AddonManager.jsm:1693:11 < callAddonListeners@AddonManager.jsm:3153:5 < uninstallAddon@XPIProvider.jsm:5259:7 < uninstall@XPIProvider.jsm:7618:5 < shutdown@ExtensionTestCommon.jsm:130:5 < _receiveMessageAPI@SpecialPowersObserverAPI.js:588:9 < ChromePowers.prototype._receiveMessage@ChromePowers.js:83:14 < ChromePowers.prototype._sendAsyncMessage@ChromePowers.js:45:3 < unload@specialpowersAPI.js:1976:9 < sidebar_tab_query_bug_1340739@browser_ext_sidebarAction.js:169:9 < TaskImpl_run@Task.jsm:319:42 < promise callback*TaskImpl_handleResultValue@Task.jsm:396:7 < TaskImpl_run@Task.jsm:327:15 < promise callback*TaskImpl_handleResultValue@Task.jsm:396:7 < TaskImpl_run@Task.jsm:327:15 < TaskImpl@Task.jsm:277:3 < asyncFunction@Task.jsm:252:14 < Task_spawn@Task.jsm:166:12 < TaskImpl_handleResultValue@Task.jsm:389:16 < TaskImpl_run@Task.jsm:327:15 < process@Promise-backend.js:922:23 < walkerLoop@Promise-backend.js:806:7 < Promise*scheduleWalkerLoop@Promise-backend.js:739:11 < walkerLoop@Promise-backend.js:799:7 < Promise*scheduleWalkerLoop@Promise-backend.js:739:11 < schedulePromise@Promise-backend.js:770:7 < Promise.prototype.then@Promise-backend.js:455:5 < getAddonList@XPIProviderUtils.js:1046:5 < getVisibleAddons@XPIProviderUtils.js:1129:5 < getAddonsByTypes@XPIProvider.jsm:4205:5 < callProviderAsync@AddonManager.jsm:294:12 < promiseCallProvider/<@AddonManager.jsm:318:53 < Promise@Promise-backend.js:390:5 < promiseCallProvider@AddonManager.jsm:317:10 < getAddonsByTypes/<@AddonManager.jsm:2503:36 < TaskImpl_run@Task.jsm:319:42 < TaskImpl@Task.jsm:277:3 < asyncFunction@Task.jsm:252:14 < Task_spawn@Task.jsm:166:12 < getAddonsByTypes@AddonManager.jsm:2499:12 < getAddonsByTypes@AddonManager.jsm:3572:7 < EnvironmentAddonBuilder.prototype._getActiveAddons<@TelemetryEnvironment.jsm:560:27 < TaskImpl_run@Task.jsm:319:42 < TaskImpl@Task.jsm:277:3 < asyncFunction@Task.jsm:252:14 < EnvironmentAddonBuilder.prototype._updateAddons<@TelemetryEnvironment.jsm:532:27 < TaskImpl_run@Task.jsm:319:42 < TaskImpl@Task.jsm:277:3 < asyncFunction@Task.jsm:252:14 < _checkForChanges@TelemetryEnvironment.jsm:490:25 < _onAddonChange@TelemetryEnvironment.jsm:475:5 < onUninstalling@TelemetryEnvironment.jsm:470:5 < callAddonListeners@AddonManager.jsm:1693:11 < callAddonListeners@AddonManager.jsm:3153:5 < uninstallAddon@XPIProvider.jsm:5205:7 < uninstall@XPIProvider.jsm:7618:5 < shutdown@ExtensionTestCommon.jsm:130:5 < _receiveMessageAPI@SpecialPowersObserverAPI.js:588:9 < ChromePowers.prototype._receiveMessage@ChromePowers.js:83:14 < ChromePowers.prototype._sendAsyncMessage@ChromePowers.js:45:3 < unload@specialpowersAPI.js:1976:9 < sidebar_empty_panel@browser_ext_sidebarAction.js:126:9 < TaskImpl_run@Task.jsm:319:42
[task 2017-03-08T01:40:40.510330Z] 01:40:40 INFO - Buffered messages finished
[task 2017-03-08T01:40:40.512498Z] 01:40:40 INFO - TEST-UNEXPECTED-FAIL | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_sidebarAction.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 2017-03-08T01:40:40.512831Z] 01:40:40 INFO - MEMORY STAT | vsize 2461MB | residentFast 359MB | heapAllocated 144MB
[task 2017-03-08T01:40:40.515350Z] 01:40:40 INFO - TEST-OK | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_sidebarAction.js | took 98593ms
and the log is here:
https://public-artifacts.taskcluster.net/FJ2X7IYHTjWMwVHLgad8oQ/0/public/logs/live_backing.log
and a related screenshot:
https://public-artifacts.taskcluster.net/FJ2X7IYHTjWMwVHLgad8oQ/0/public/test_info//mozilla-test-fail-screenshot_EbYqZ4.png (sort of a blank browser page)
:kmag, thanks for getting on this early on, hopefully the retriggers will help point to the root cause soon!
Whiteboard: [stockwell needswork]
Comment 5•8 years ago
|
||
retriggers are not showing a clear root cause of this, lets stick to looking at the test.
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment 9•8 years ago
|
||
this is >75 failures/week, we will disable this by Friday if we don't have a fix in progress.
ni? myself to remember to do this.
Flags: needinfo?(jmaher)
![]() |
||
Comment 10•8 years ago
|
||
This is a relatively new test, added in bug 1208596. It looks like it started failing at a low frequency as soon as it was introduced.
Here is a summary of recent run times for this test:
Test durations for browser/components/extensions/test/browser/browser_ext_sidebarAction.js on mozilla-central,mozilla-inbound,autoland between 2017-03-07 and 2017-03-14
linux32-nightly/opt-chunked: 8.83 s (6.47 s - 10.64 s over 11 runs)
linux32-nightly/opt-e10s: 8.69 s (6.47 s - 9.63 s over 6 runs)
linux32/debug-chunked: 70.41 s (41.29 s - 90.76 s over 358 runs)
linux32/debug-e10s: 75.04 s (43.52 s - 90.76 s over 182 runs)
linux32/opt-chunked: 10.95 s (6.76 s - 27.60 s over 464 runs)
linux32/opt-e10s: 12.08 s (7.21 s - 27.60 s over 174 runs)
linux64-ccov/opt-chunked: 6.06 s (4.80 s - 7.25 s over 4 runs)
linux64-jsdcov/opt: 13.36 s (12.07 s - 14.09 s over 4 runs)
linux64-nightly/opt-chunked: 9.42 s (7.52 s - 10.75 s over 11 runs)
linux64-nightly/opt-e10s: 9.70 s (7.76 s - 10.75 s over 5 runs)
linux64/asan-chunked: 24.33 s (16.94 s - 31.95 s over 452 runs)
linux64/asan-e10s: 24.90 s (16.99 s - 31.95 s over 261 runs)
linux64/debug-chunked: 74.09 s (43.17 s - 90.72 s over 406 runs)
linux64/debug-e10s: 75.92 s (48.04 s - 90.72 s over 230 runs)
linux64/opt-chunked: 11.02 s (6.92 s - 19.17 s over 346 runs)
linux64/opt-e10s: 11.67 s (7.37 s - 18.14 s over 173 runs)
linux64/pgo-chunked: 9.65 s (6.31 s - 23.90 s over 419 runs)
linux64/pgo-e10s: 10.04 s (6.39 s - 20.28 s over 243 runs)
macosx64/debug-e10s: 18.47 s (16.05 s - 20.38 s over 4 runs)
macosx64/opt-e10s: 5.23 s (4.01 s - 7.77 s over 245 runs)
macosx64/opt: 4.92 s (3.71 s - 6.87 s over 305 runs)
win32/debug-e10s: 27.65 s (17.77 s - 35.21 s over 164 runs)
win32/debug: 21.50 s (14.62 s - 28.87 s over 165 runs)
win32/opt-e10s: 4.87 s (3.62 s - 12.33 s over 232 runs)
win32/opt: 5.09 s (3.66 s - 10.91 s over 176 runs)
win32/pgo-e10s: 4.47 s (2.99 s - 9.92 s over 107 runs)
win32/pgo: 4.17 s (2.99 s - 10.00 s over 107 runs)
win64/debug-e10s: 27.38 s (18.50 s - 40.53 s over 327 runs)
win64/debug: 19.67 s (13.41 s - 27.94 s over 155 runs)
win64/opt-e10s: 5.18 s (3.71 s - 12.99 s over 156 runs)
win64/opt: 5.04 s (3.80 s - 11.55 s over 155 runs)
win64/pgo-e10s: 4.34 s (2.91 s - 12.88 s over 110 runs)
win64/pgo: 4.38 s (3.19 s - 9.76 s over 104 runs)
I think this is simply a long-running test (on linux32/64-debug sometimes exceeding the 90 second limit) that just requires a little more time to complete. Can we simply requestLongerTimeout(2)?
Comment 11•8 years ago
|
||
It would probably make more sense to split it, but requesting a longer timeout would probably be fine, too.
Updated•8 years ago
|
Severity: major → critical
Assignee | ||
Updated•8 years ago
|
Assignee: nobody → mixedpuppy
Flags: needinfo?(mixedpuppy)
Comment hidden (Intermittent Failures Robot) |
Comment hidden (mozreview-request) |
Comment 14•8 years ago
|
||
mozreview-review |
Comment on attachment 8847743 [details]
Bug 1339739 fix intermittent timeout by splitting browser_ext_sidebarAction.js,
https://reviewboard.mozilla.org/r/120650/#review123098
Please use `hg cp` to create the new test files from the original.
Attachment #8847743 -
Flags: review?(kmaglione+bmo) → review+
Comment 15•8 years ago
|
||
removing ni, thank you for the patch and review- I think this is far enough along that we should see this landed in the next workday or two :)
Flags: needinfo?(jmaher)
Comment hidden (mozreview-request) |
Comment 17•8 years ago
|
||
Pushed by mixedpuppy@gmail.com:
https://hg.mozilla.org/integration/autoland/rev/110f412f85b2
fix intermittent timeout by splitting browser_ext_sidebarAction.js, r=kmag
Comment 18•8 years ago
|
||
bugherder |
Status: NEW → RESOLVED
Closed: 8 years ago
status-firefox55:
--- → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla55
Comment 19•8 years ago
|
||
will check back in if this doesn't reduce as much.
Whiteboard: [stockwell needswork] → [stockwell fixed]
Comment hidden (Intermittent Failures Robot) |
Updated•8 years ago
|
status-firefox53:
--- → unaffected
status-firefox54:
--- → affected
status-firefox-esr52:
--- → unaffected
Comment 21•8 years ago
|
||
bugherder uplift |
Flags: in-testsuite+
Comment hidden (Intermittent Failures Robot) |
Updated•7 years ago
|
Product: Toolkit → WebExtensions
You need to log in
before you can comment on or make changes to this bug.
Description
•