Open Bug 1352668 Opened 7 years ago Updated 4 days ago

Intermittent browser_ext_browserAction_popup_preload.js | Test timed out

Categories

(WebExtensions :: General, defect, P5)

Unspecified
Windows
defect

Tracking

(Not tracked)

People

(Reporter: aryx, Unassigned)

Details

(Keywords: intermittent-failure, leave-open, Whiteboard: [stockwell unknown])

https://treeherder.mozilla.org/logviewer.html#?job_id=88043999&repo=autoland

06:29:06     INFO -  128 INFO Entering test bound testBrowserActionDisabled
06:29:06     INFO -  129 INFO Extension loaded
06:29:06     INFO -  Buffered messages logged at 06:28:22
06:29:06     INFO -  130 INFO TEST-PASS | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_browserAction_popup_preload.js | Button is disabled -
06:29:06     INFO -  131 INFO TEST-PASS | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_browserAction_popup_preload.js | Have no pending popup prior to click -
06:29:06     INFO -  132 INFO TEST-PASS | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_browserAction_popup_preload.js | Have no pending popup -
06:29:06     INFO -  133 INFO TEST-PASS | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_browserAction_popup_preload.js | Have no pending popup timeout -
06:29:06     INFO -  134 INFO TEST-PASS | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_browserAction_popup_preload.js | Have no pending popup -
06:29:06     INFO -  135 INFO TEST-PASS | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_browserAction_popup_preload.js | Have no pending popup timeout -
06:29:06     INFO -  136 INFO TEST-PASS | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_browserAction_popup_preload.js | Have no pending popup -
06:29:06     INFO -  137 INFO TEST-PASS | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_browserAction_popup_preload.js | Have no pending popup timeout -
06:29:06     INFO -  138 INFO TEST-PASS | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_browserAction_popup_preload.js | Have no pending popup -
06:29:06     INFO -  139 INFO TEST-PASS | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_browserAction_popup_preload.js | Have no pending popup timeout -
06:29:06     INFO -  140 INFO TEST-PASS | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_browserAction_popup_preload.js | Have no pending popup -
06:29:06     INFO -  141 INFO TEST-PASS | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_browserAction_popup_preload.js | Have no pending popup timeout -
06:29:06     INFO -  142 INFO Leaving test bound testBrowserActionDisabled
06:29:06     INFO -  143 INFO Entering test bound testBrowserActionTabPopulation
06:29:06     INFO -  144 INFO Extension loaded
06:29:06     INFO -  145 INFO Console message: [JavaScript Error: "Error: Popup destroyed" {file: "resource://app/modules/ExtensionPopups.jsm" line: 120}]
06:29:06     INFO -  Buffered messages finished
06:29:06    ERROR -  146 INFO TEST-UNEXPECTED-FAIL | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_browserAction_popup_preload.js | Test timed out -
06:29:06     INFO -  Not taking screenshot here: see the one that was previously logged
06:29:06    ERROR -  147 INFO TEST-UNEXPECTED-FAIL | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_browserAction_popup_preload.js | no tasks awaiting on messages - Got ["tabTitle"], expected []
06:29:06     INFO -  Stack trace:
06:29:06     INFO -      chrome://mochikit/content/browser-test.js:test_is:911
06:29:06     INFO -      chrome://mochikit/content/tests/SimpleTest/ExtensionTestUtils.js:ExtensionTestUtils.loadExtension/<:31
06:29:06     INFO -      chrome://mochikit/content/browser-test.js:Tester.prototype.nextTest<:437
06:29:06     INFO -      timeoutFn@chrome://mochikit/content/browser-test.js:817:9
06:29:06     INFO -      setTimeout handler*Tester_execTest@chrome://mochikit/content/browser-test.js:779:9
06:29:06     INFO -      Tester.prototype.nextTest</<@chrome://mochikit/content/browser-test.js:655:7
06:29:06     INFO -      SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:791:59
06:29:06     INFO -  Not taking screenshot here: see the one that was previously logged
06:29:06    ERROR -  148 INFO TEST-UNEXPECTED-FAIL | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_browserAction_popup_preload.js | Extension left running at test shutdown -
06:29:06     INFO -  Stack trace:
06:29:06     INFO -      chrome://mochikit/content/tests/SimpleTest/ExtensionTestUtils.js:ExtensionTestUtils.loadExtension/<:109
06:29:06     INFO -      chrome://mochikit/content/browser-test.js:Tester.prototype.nextTest<:437
06:29:06     INFO -      timeoutFn@chrome://mochikit/content/browser-test.js:817:9
06:29:06     INFO -      setTimeout handler*Tester_execTest@chrome://mochikit/content/browser-test.js:779:9
06:29:06     INFO -      Tester.prototype.nextTest</<@chrome://mochikit/content/browser-test.js:655:7
06:29:06     INFO -      SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:791:59
06:29:06     INFO -  GECKO(4072) | JavaScript error: resource://app/modules/ExtensionPopups.jsm, line 120: Error: Popup destroyed
06:29:06     INFO -  GECKO(4072) | MEMORY STAT | vsize 683MB | vsizeMaxContiguous 611MB | residentFast 230MB | heapAllocated 94MB
06:29:06     INFO -  149 INFO TEST-OK | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_browserAction_popup_preload.js | took 45064ms
Summary: Intermittent browser/components/extensions/test/browser/test-oop-extensions/browser_ext_browserAction_popup_preload.js | Test timed out - → Intermittent browser_ext_browserAction_popup_preload.js | Test timed out
All failures are win7-opt. Failure frequency seemed to increase around May 12.

:kmag - Any thoughts on making this more reliable? Could it be skipped on win7-opt?
Flags: needinfo?(kmaglione+bmo)
Pushed by gbrown@mozilla.com:
https://hg.mozilla.org/integration/mozilla-inbound/rev/3320e2c5c0b4
Skip test browser_ext_browserAction_popup_preload.js on win-opt; r=me,test-only
Whiteboard: [stockwell disabled]
Keywords: leave-open
now we have a lot of failures on osx/opt, :kmag, can we look into these or should we skip osx as well?
Whiteboard: [stockwell disabled] → [stockwell needswork]
Hrm. So prior to May 31st, all of the failures were on Windows 7-32. Then there were no failures for a week, and all of the failures since been on OS-X.

And in nearly all of the failure screenshots on OS-X, there's a "What's New in OS X Yosemite" popup over the toolbar button we're testing:

http://mozilla-releng-blobs.s3.amazonaws.com/blobs/autoland/sha512/72b85c96e1b1c86dbf084187aff8db927cdcb9cf0938cd317ffc2fa688ea27794f7538dd1624bf47e9f12a2a402d9f71c92a76be466e3b0f67422e2626620437

which is suspicious.
Flags: needinfo?(kmaglione+bmo)
I have seen this in many screenshots before, but we have determined this is there most if not all the time and is not a concern- possibly this is a wrong conclusion.

Keep in mind the earlier failures were win7 and we disabled the test on that platform.
Whiteboard: [stockwell needswork] → [stockwell unknown]
Priority: -- → P5
Product: Toolkit → WebExtensions
This bug failed 55 times in the last 7 days. Failures are present on windows10-64, windows7-32 and on osx-10-10. Build types are debug and opt.

Here is a recent log of the failure:
https://treeherder.mozilla.org/logviewer.html#?job_id=190212736&repo=mozilla-inbound&lineNumber=9086

 ERROR -  164 INFO TEST-UNEXPECTED-FAIL | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_browserAction_popup_preload.js | Test timed out -
10:13:13     INFO -  Not taking screenshot here: see the one that was previously logged
10:13:13    ERROR -  165 INFO TEST-UNEXPECTED-FAIL | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_browserAction_popup_preload.js | no tasks awaiting on messages - Got ["tabTitle"], expected []
10:13:13     INFO -  Stack trace:
10:13:13     INFO -  chrome://mochikit/content/browser-test.js:test_is:1305
10:13:13     INFO -  chrome://mochikit/content/tests/SimpleTest/ExtensionTestUtils.js:ExtensionTestUtils.loadExtension/<:31
10:13:13     INFO -  chrome://mochikit/content/browser-test.js:nextTest:705
10:13:13     INFO -  chrome://mochikit/content/browser-test.js:timeoutFn:1200
10:13:13     INFO -  setTimeout handler*chrome://mochikit/content/browser-test.js:Tester_execTest:1162
10:13:13     INFO -  chrome://mochikit/content/browser-test.js:nextTest/<:996
10:13:13     INFO -  chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<:795
10:13:13     INFO -  Not taking screenshot here: see the one that was previously logged
10:13:13    ERROR -  166 INFO TEST-UNEXPECTED-FAIL | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_browserAction_popup_preload.js | Extension left running at test shutdown -
10:13:13     INFO -  Stack trace:
10:13:13     INFO -  chrome://mochikit/content/tests/SimpleTest/ExtensionTestUtils.js:ExtensionTestUtils.loadExtension/<:109
10:13:13     INFO -  chrome://mochikit/content/browser-test.js:nextTest:705
10:13:13     INFO -  chrome://mochikit/content/browser-test.js:timeoutFn:1200
10:13:13     INFO -  setTimeout handler*chrome://mochikit/content/browser-test.js:Tester_execTest:1162
10:13:13     INFO -  chrome://mochikit/content/browser-test.js:nextTest/<:996
10:13:13     INFO -  chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<:795
10:13:13     INFO -  167 INFO TEST-FAIL | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_browserAction_popup_preload.js | Assertion count 1 is greater than expected range 0-0 assertions. -
10:13:13     INFO -  GECKO(5880) | MEMORY STAT | vsize 876MB | vsizeMaxContiguous 335MB | residentFast 339MB | heapAllocated 91MB
10:13:13     INFO -  168 INFO TEST-OK | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_browserAction_popup_preload.js | took 90127ms
10:13:13     INFO -  GECKO(5880) | ++DOCSHELL 008D1800 == 1 [pid = 4192] [id = {78fc1ea7-0644-44a5-9aca-9ef3c76be292}]
10:13:13     INFO -  GECKO(5880) | ++DOMWINDOW == 1 (008A9410) [pid = 4192] [serial = 19] [outer = 00000000]
10:13:13     INFO -  GECKO(5880) | ++DOMWINDOW == 2 (09005800) [pid = 4192] [serial = 20] [outer = 008A9410]
10:13:13     INFO -  169 INFO checking window state
10:13:13     INFO -  Not taking screenshot here: see the one that was previously logged
10:13:13    ERROR -  170 INFO TEST-UNEXPECTED-FAIL | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_browserAction_popup_preload.js | Found a browser window after previous test timed out -
10:13:13     INFO -  GECKO(5880) | must wait for focus

:ddurst: Can you please take a look at this bug?
Flags: needinfo?(ddurst)
Whiteboard: [stockwell unknown] → [stockwell needswork]
Failure rate seems to have increased since bug 1357487 has been pushed to inbound. 

Kris,  can you provide some insight here?
Flags: needinfo?(kmaglione+bmo)
As far as I can tell, the failures were concentrated over a few hours and then stopped.
Flags: needinfo?(kmaglione+bmo)
Whiteboard: [stockwell disable-recommended] → [stockwell unknown]
Flags: needinfo?(thedurst)
Severity: normal → S2
Component: Untriaged → General
OS: Unspecified → Windows
Priority: -- → P3
Severity: S2 → S3
Priority: P3 → P5
You need to log in before you can comment on or make changes to this bug.