Closed Bug 1473920 Opened 6 years ago Closed 4 years ago

Intermittent toolkit/components/extensions/test/browser/browser_ext_themes_ntp_colors_perwindow.js | Test timed out -

Categories

(WebExtensions :: General, defect, P5)

Product:
WebExtensions
Component:
General
Type:
defect

Tracking

(firefox63 fixed)

Status:
RESOLVED WORKSFORME
Milestone:
mozilla63
Tracking Flags:
Tracking Status
firefox63 --- fixed

People

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

References

Details

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

Attachments

(1 file)

Bug 1473920 - Fix browser_ext_themes_ntp_colors_perwindow failures when running on Linux.
59 bytes, text/x-review-board-request
mixedpuppy
: review+
Details 
Filed by: ebalazs [at] mozilla.com

https://treeherder.mozilla.org/logviewer.html#?job_id=186819202&repo=try

https://queue.taskcluster.net/v1/task/PECUb-02TQCqCZbkQ56GjQ/runs/0/artifacts/public/logs/live_backing.log

INFO - TEST-PASS | toolkit/components/extensions/test/browser/browser_ext_themes_ntp_colors_perwindow.js | New tab page text color should be set. - "rgb(173, 216, 230)" == "rgb(173, 216, 230)" - 
[task 2018-07-06T11:28:40.142Z] 11:28:40     INFO - Buffered messages finished
[task 2018-07-06T11:28:40.143Z] 11:28:40     INFO - TEST-UNEXPECTED-FAIL | toolkit/components/extensions/test/browser/browser_ext_themes_ntp_colors_perwindow.js | Test timed out - 
[task 2018-07-06T11:28:40.144Z] 11:28:40     INFO - Not taking screenshot here: see the one that was previously logged
[task 2018-07-06T11:28:40.145Z] 11:28:40     INFO - TEST-UNEXPECTED-FAIL | toolkit/components/extensions/test/browser/browser_ext_themes_ntp_colors_perwindow.js | Extension left running at test shutdown - 
[task 2018-07-06T11:28:40.145Z] 11:28:40     INFO - Stack trace:
[task 2018-07-06T11:28:40.151Z] 11:28:40     INFO - chrome://mochikit/content/tests/SimpleTest/ExtensionTestUtils.js:ExtensionTestUtils.loadExtension/<:109
[task 2018-07-06T11:28:40.152Z] 11:28:40     INFO - chrome://mochikit/content/browser-test.js:nextTest:699
[task 2018-07-06T11:28:40.152Z] 11:28:40     INFO - Console message: [JavaScript Error: "Invalid window ID: 95" {file: "chrome://extensions/content/parent/ext-tabs-base.js" line: 1440}]
[task 2018-07-06T11:28:40.152Z] 11:28:40     INFO - ExtensionError@resource://gre/modules/ExtensionUtils.jsm:840:19
[task 2018-07-06T11:28:40.152Z] 11:28:40     INFO - getWindow@chrome://extensions/content/parent/ext-tabs-base.js:1440:13
[task 2018-07-06T11:28:40.152Z] 11:28:40     INFO - unload@chrome://extensions/content/parent/ext-theme.js:311:38
[task 2018-07-06T11:28:40.153Z] 11:28:40     INFO - onShutdown@chrome://extensions/content/parent/ext-theme.js:356:9
[task 2018-07-06T11:28:40.153Z] 11:28:40     INFO - ExtensionAPI/<@resource://gre/modules/ExtensionCommon.jsm:328:9
[task 2018-07-06T11:28:40.154Z] 11:28:40     INFO - wrapper@resource://gre/modules/ExtensionCommon.jsm:271:23
[task 2018-07-06T11:28:40.155Z] 11:28:40     INFO - emit@resource://gre/modules/ExtensionCommon.jsm:299:40
[task 2018-07-06T11:28:40.156Z] 11:28:40     INFO - emit@resource://gre/modules/Extension.jsm:1404:37
[task 2018-07-06T11:28:40.156Z] 11:28:40     INFO - shutdown@resource://gre/modules/Extension.jsm:1823:5
[task 2018-07-06T11:28:40.158Z] 11:28:40     INFO - _receiveMessageAPI@chrome://mochikit/content/tests/SimpleTest/SpecialPowersObserverAPI.js:647:9
[task 2018-07-06T11:28:40.159Z] 11:28:40     INFO - ChromePowers.prototype._receiveMessage@chrome://mochikit/content/tests/SimpleTest/ChromePowers.js:83:14
[task 2018-07-06T11:28:40.159Z] 11:28:40     INFO - ChromePowers.prototype._sendAsyncMessage@chrome://mochikit/content/tests/SimpleTest/ChromePowers.js:45:3
[task 2018-07-06T11:28:40.161Z] 11:28:40     INFO - unload@chrome://mochikit/content/tests/SimpleTest/specialpowersAPI.js:2043:9
[task 2018-07-06T11:28:40.161Z] 11:28:40     INFO - ExtensionTestUtils.loadExtension/<@chrome://mochikit/content/tests/SimpleTest/ExtensionTestUtils.js:110:14
[task 2018-07-06T11:28:40.162Z] 11:28:40     INFO - nextTest@chrome://mochikit/content/browser-test.js:699:30
Blocks: 1347204
This showed up in a beta simulation once, retriggers were green.
Flags: needinfo?(ntim.bugs)
This bug failed 38 times in the last 7 days. Most failure happen on linux64, linux32 and on linux32-nightly. Build types pgo and opt.

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

NFO - TEST-PASS | toolkit/components/extensions/test/browser/browser_ext_themes_ntp_colors_perwindow.js | New tab page text color should be set. - "rgb(173, 216, 230)" == "rgb(173, 216, 230)" - 
[task 2018-07-27T13:31:33.726Z] 13:31:33     INFO - Console message: [JavaScript Error: "this.chromeGlobal.content is null" {file: "resource:///modules/ContentLinkHandler.jsm" line: 461}]
[task 2018-07-27T13:31:33.726Z] 13:31:33     INFO - loadIcons@resource:///modules/ContentLinkHandler.jsm:461:9
[task 2018-07-27T13:31:33.728Z] 13:31:33     INFO - ContentLinkHandler/this.iconTask<@resource:///modules/ContentLinkHandler.jsm:457:44
[task 2018-07-27T13:31:33.728Z] 13:31:33     INFO - idleDispatch/</<@resource://gre/modules/PromiseUtils.jsm:40:21
[task 2018-07-27T13:31:33.728Z] 13:31:33     INFO - 
[task 2018-07-27T13:31:33.728Z] 13:31:33     INFO - Buffered messages finished
[task 2018-07-27T13:31:33.729Z] 13:31:33     INFO - TEST-UNEXPECTED-FAIL | toolkit/components/extensions/test/browser/browser_ext_themes_ntp_colors_perwindow.js | Test timed out - 
[task 2018-07-27T13:31:33.729Z] 13:31:33     INFO - Not taking screenshot here: see the one that was previously logged
[task 2018-07-27T13:31:33.731Z] 13:31:33     INFO - TEST-UNEXPECTED-FAIL | toolkit/components/extensions/test/browser/browser_ext_themes_ntp_colors_perwindow.js | Extension left running at test shutdown - 
[task 2018-07-27T13:31:33.731Z] 13:31:33     INFO - Stack trace:
[task 2018-07-27T13:31:33.731Z] 13:31:33     INFO - chrome://mochikit/content/tests/SimpleTest/ExtensionTestUtils.js:ExtensionTestUtils.loadExtension/<:109
[task 2018-07-27T13:31:33.732Z] 13:31:33     INFO - chrome://mochikit/content/browser-test.js:nextTest:705
[task 2018-07-27T13:31:33.733Z] 13:31:33     INFO - chrome://mochikit/content/browser-test.js:timeoutFn:1200
[task 2018-07-27T13:31:33.734Z] 13:31:33     INFO - setTimeout handler*chrome://mochikit/content/browser-test.js:Tester_execTest:1162
[task 2018-07-27T13:31:33.734Z] 13:31:33     INFO - chrome://mochikit/content/browser-test.js:nextTest/<:996
[task 2018-07-27T13:31:33.735Z] 13:31:33     INFO - chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<:795
[task 2018-07-27T13:31:33.736Z] 13:31:33     INFO - Console message: [JavaScript Error: "Invalid window ID: 71" {file: "chrome://extensions/content/parent/ext-tabs-base.js" line: 1440}]
[task 2018-07-27T13:31:33.737Z] 13:31:33     INFO - ExtensionError@resource://gre/modules/ExtensionUtils.jsm:840:19
[task 2018-07-27T13:31:33.738Z] 13:31:33     INFO - getWindow@chrome://extensions/content/parent/ext-tabs-base.js:1440:13
[task 2018-07-27T13:31:33.739Z] 13:31:33     INFO - unload@chrome://extensions/content/parent/ext-theme.js:298:36
[task 2018-07-27T13:31:33.739Z] 13:31:33     INFO - onShutdown@chrome://extensions/content/parent/ext-theme.js:332:9
[task 2018-07-27T13:31:33.740Z] 13:31:33     INFO - ExtensionAPI/<@resource://gre/modules/ExtensionCommon.jsm:328:9
[task 2018-07-27T13:31:33.741Z] 13:31:33     INFO - wrapper@resource://gre/modules/ExtensionCommon.jsm:271:23
[task 2018-07-27T13:31:33.742Z] 13:31:33     INFO - emit@resource://gre/modules/ExtensionCommon.jsm:299:40
[task 2018-07-27T13:31:33.743Z] 13:31:33     INFO - emit@resource://gre/modules/Extension.jsm:1416:37
[task 2018-07-27T13:31:33.743Z] 13:31:33     INFO - shutdown@resource://gre/modules/Extension.jsm:1867:5
[task 2018-07-27T13:31:33.745Z] 13:31:33     INFO - async*_receiveMessageAPI@chrome://mochikit/content/tests/SimpleTest/SpecialPowersObserverAPI.js:648:9
[task 2018-07-27T13:31:33.745Z] 13:31:33     INFO - ChromePowers.prototype._receiveMessage@chrome://mochikit/content/tests/SimpleTest/ChromePowers.js:83:14
[task 2018-07-27T13:31:33.746Z] 13:31:33     INFO - ChromePowers.prototype._sendAsyncMessage@chrome://mochikit/content/tests/SimpleTest/ChromePowers.js:45:3
[task 2018-07-27T13:31:33.747Z] 13:31:33     INFO - unload@chrome://mochikit/content/tests/SimpleTest/specialpowersAPI.js:2071:9
[task 2018-07-27T13:31:33.748Z] 13:31:33     INFO - ExtensionTestUtils.loadExtension/<@chrome://mochikit/content/tests/SimpleTest/ExtensionTestUtils.js:110:14
[task 2018-07-27T13:31:33.748Z] 13:31:33     INFO - nextTest@chrome://mochikit/content/browser-test.js:705:30
[task 2018-07-27T13:31:33.749Z] 13:31:33     INFO - async*timeoutFn@chrome://mochikit/content/browser-test.js:1200:9
[task 2018-07-27T13:31:33.750Z] 13:31:33     INFO - setTimeout handler*Tester_execTest@chrome://mochikit/content/browser-test.js:1162:9
[task 2018-07-27T13:31:33.751Z] 13:31:33     INFO - nextTest/<@chrome://mochikit/content/browser-test.js:996:9
[task 2018-07-27T13:31:33.751Z] 13:31:33     INFO - SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:795:59
[task 2018-07-27T13:31:33.752Z] 13:31:33     INFO - 
[task 2018-07-27T13:31:33.753Z] 13:31:33     INFO - GECKO(6857) | MEMORY STAT | vsize 1930MB | residentFast 272MB | heapAllocated 97MB
[task 2018-07-27T13:31:33.754Z] 13:31:33     INFO - TEST-OK | toolkit/components/extensions/test/browser/browser_ext_themes_ntp_colors_perwindow.js | took 45057ms
[task 2018-07-27T13:31:33.755Z] 13:31:33     INFO - checking window state

:ddurst: Can you please take a look at this bug?
Flags: needinfo?(ddurst)
Whiteboard: [stockwell needswork]
I took a brief look at this test failures and for me, when I run it locally on linux, it is not timing out intermittently, but failing consistently.

The failures that I've been able to see locally seems to be related to the second window opened by the test, which becomes the "most recent window" while the test case expects that the first window is the most recent one (right after being focused by the test extension code).

To make the test to complete successfully locally, I had to change the test case to retrieve the target window using the windowId, instead of just assuming that it is the most recent one (as currently done here [1]).

Even if the failures that I have been experiencing locally seem to be different from the timeouts that I saw in the failures on the infrastructure, I tried to push on try the modified version of the test and it seems to be green and stable:

https://treeherder.mozilla.org/#/jobs?repo=try&revision=51ac1cf5f10fdf8dd2b63694faab929ed701fb95

I'm going to attach the patch with the changes described above, the failures from this intermittent may still be another manifestation of the issue that I saw locally.

[1]: https://searchfox.org/mozilla-central/rev/033d45ca70ff32acf04286244644d19308c359d5/toolkit/components/extensions/test/browser/browser_ext_themes_ntp_colors_perwindow.js#167
Flags: needinfo?(ntim.bugs)
Flags: needinfo?(ddurst)
Attachment #8996258 - Flags: review?(mixedpuppy)
Assignee: nobody → lgreco
Status: NEW → ASSIGNED
See Also: → 1474041
Comment on attachment 8996258 [details]
Bug 1473920 - Fix browser_ext_themes_ntp_colors_perwindow failures when running on Linux.

https://reviewboard.mozilla.org/r/260436/#review268012
Attachment #8996258 - Flags: review?(mixedpuppy) → review+
Pushed by luca.greco@alcacoop.it:
https://hg.mozilla.org/integration/autoland/rev/8c730b453929
Fix browser_ext_themes_ntp_colors_perwindow failures when running on Linux. r=mixedpuppy
https://hg.mozilla.org/mozilla-central/rev/8c730b453929
Status: ASSIGNED → RESOLVED
Closed: 5 years ago
status-firefox63: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla63
We are trying to build a tool to automatically classify intermittent failures, which would provide a starting point for fixing the bug, reducing the manual work for the developers.
We are collecting some feedback on the results, to see if they’re good enough and where we need to improve.
    
For this bug, the tool says that the intermittent failure is most likely a:
Concurrency Issue: This includes tests in which failures occur due to thread management issues (different threads or their outcomes depending on an implicit ordering), race conditions and/or deadlocks, and issues related to an asynchronous waits (e.g. a process trying to access an external resource or continuing before the external resource is available).


Once you’re done investigating and/or fixing the bug, could you tell me:
- Did the tool correctly recognize the type of intermittent failure?
- Did the information from the tool help your analysis, the bug fixing process, or anything in the process? (please also let us know how the tool was useful and/or what would improve the tool's usefulness for you)
Flags: needinfo?(lgreco)
(In reply to meck93 from comment #18)
> We are trying to build a tool to automatically classify intermittent
> failures, which would provide a starting point for fixing the bug, reducing
> the manual work for the developers.
> We are collecting some feedback on the results, to see if they’re good
> enough and where we need to improve.
>     
> For this bug, the tool says that the intermittent failure is most likely a:
> Concurrency Issue: This includes tests in which failures occur due to thread
> management issues (different threads or their outcomes depending on an
> implicit ordering), race conditions and/or deadlocks, and issues related to
> an asynchronous waits (e.g. a process trying to access an external resource
> or continuing before the external resource is available).
> 
> 
> Once you’re done investigating and/or fixing the bug, could you tell me:
> - Did the tool correctly recognize the type of intermittent failure?

Yes, it looks correct, the failures was definitely related to a concurrency issue.

> - Did the information from the tool help your analysis, the bug fixing
> process, or anything in the process? (please also let us know how the tool
> was useful and/or what would improve the tool's usefulness for you)

Yes, I think that the hint would have been helpful to quickly direct the analysis in the right direction.
Flags: needinfo?(lgreco)
Flags: qe-verify-
Whiteboard: [stockwell disable-recommended] → [stockwell fixed]

New failure: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=243578259&repo=autoland&lineNumber=5729

Status: RESOLVED → REOPENED
Resolution: FIXED → ---

The new failures do not seem related to the reasons for the previous intermittency of this test, which was a race and not a crash of the child process as these last failures, e.g.: from https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=250646248&repo=try&lineNumber=36968

18:26:01     INFO - TEST-PASS | toolkit/components/extensions/test/browser/browser_ext_themes_ntp_colors_perwindow.js | New tab page text color should be set. - "rgb(173, 216, 230)" == "rgb(173, 216, 230)" - 
18:26:01     INFO - Opening url: about:newtab
18:26:01     INFO - Console message: [JavaScript Error: "remote browser crashed while on about:blank
18:26:01     INFO - " {file: "chrome://mochikit/content/mochitest-e10s-utils.js" line: 8}]
18:26:01     INFO - e10s_init/<@chrome://mochikit/content/mochitest-e10s-utils.js:8:8
18:26:01     INFO - EventListener.handleEvent*e10s_init@chrome://mochikit/content/mochitest-e10s-utils.js:6:10
18:26:01     INFO - testInit@chrome://mochikit/content/browser-test.js:105:5
18:26:01     INFO - setTimeout handler*@chrome://mochikit/content/browser-test.js:23:1
18:26:01     INFO - loadChromeScripts@jar:file:///C:/Users/task_1559929891/AppData/Local/Temp/tmpsxioro.mozrunner/extensions/mochikit@mozilla.org.xpi!/api.js:13:25
18:26:01     INFO - loadMochitest@jar:file:///C:/Users/task_1559929891/AppData/Local/Temp/tmpsxioro.mozrunner/extensions/mochikit@mozilla.org.xpi!/api.js:112:3
18:26:01     INFO - @Z:\task_1559929891\build\tests\mochitest\runtests.py:1783:5
18:26:01     INFO - @Z:\task_1559929891\build\tests\mochitest\runtests.py:1784:8
18:26:01     INFO - evaluate.sandbox/promise<@chrome://marionette/content/evaluate.js:128:10
18:26:01     INFO - evaluate.sandbox@chrome://marionette/content/evaluate.js:106:17
18:26:01     INFO - GeckoDriver.prototype.execute_@chrome://marionette/content/driver.js:1029:28
18:26:01     INFO - async*GeckoDriver.prototype.executeScript@chrome://marionette/content/driver.js:911:29
18:26:01     INFO - despatch@chrome://marionette/content/server.js:289:40
18:26:01     INFO - execute@chrome://marionette/content/server.js:262:16
18:26:01     INFO - onPacket/<@chrome://marionette/content/server.js:235:20
18:26:01     INFO - onPacket@chrome://marionette/content/server.js:236:9
18:26:01     INFO - _onJSONObjectReady/<@chrome://marionette/content/transport.js:492:20

Confirmed also by the screenshot took on the above failure:

Hey Raul,
this intermittent doesn't seem to have new failures tracked on orangefactor for 1 year (and, as I mentioned in Comment 24, the last failure was unrelated to the original intermittent), and so I was wondering if this bugzilla issue can be closed.

Assignee: lgreco → nobody
Flags: needinfo?(rgurzau)

Also checked for new failures but can't find any. I'm closing this bug.
Thank you.

Status: REOPENED → RESOLVED
Closed: 5 years ago → 4 years ago
Flags: needinfo?(rgurzau)
Resolution: --- → FIXED
Assignee: nobody → lgreco
Resolution: FIXED → WORKSFORME
You need to log in before you can comment on or make changes to this bug.