Closed Bug 1465333 Opened 7 years ago Closed 3 years ago

Intermittent accessible/tests/browser/e10s/browser_events_statechange.js | Test timed out -

Categories

(Core :: Disability Access APIs, defect, P5)

defect

Tracking

()

RESOLVED DUPLICATE of bug 1784643

People

(Reporter: intermittent-bug-filer, Unassigned)

References

Details

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

Filed by: archaeopteryx [at] coole-files.de https://treeherder.mozilla.org/logviewer.html#?job_id=180730100&repo=autoland https://queue.taskcluster.net/v1/task/d0E0dSrzQAe9StF0TyFBUw/runs/0/artifacts/public/logs/live_backing.log 15:20:19 INFO - 29 INFO TEST-START | accessible/tests/browser/e10s/browser_events_statechange.js 15:21:04 INFO - TEST-INFO | started process screenshot 15:21:04 INFO - TEST-INFO | screenshot: exit 0 15:21:04 INFO - Buffered messages logged at 15:20:19 15:21:04 INFO - 30 INFO Entering test bound 15:21:04 INFO - Buffered messages finished 15:21:04 ERROR - 31 INFO TEST-UNEXPECTED-FAIL | accessible/tests/browser/e10s/browser_events_statechange.js | Test timed out -
Status: NEW → RESOLVED
Closed: 6 years ago
Resolution: --- → INCOMPLETE
Status: REOPENED → RESOLVED
Closed: 6 years ago6 years ago
Resolution: --- → INCOMPLETE

Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=244792168&repo=autoland&lineNumber=1837

04:18:18     INFO - TEST-PASS | accessible/tests/browser/e10s/browser_events_statechange.js | Checked element cannot be state mixed! - 
04:18:18     INFO - Buffered messages finished
04:18:18     INFO - TEST-UNEXPECTED-FAIL | accessible/tests/browser/e10s/browser_events_statechange.js | Test timed out - 
04:18:18     INFO - GECKO(8444) | [Child 3728, Main Thread] WARNING: No active window: file z:/build/build/src/js/xpconnect/src/XPCJSContext.cpp, line 662
04:18:18     INFO - GECKO(8444) | MEMORY STAT | vsize 2104195MB | vsizeMaxContiguous 66011977MB | residentFast 245MB | heapAllocated 65MB
04:18:18     INFO - TEST-OK | accessible/tests/browser/e10s/browser_events_statechange.js | took 90140ms
04:18:18     INFO - GECKO(8444) | ++DOCSHELL 0000022618E3F000 == 1 [pid = 7420] [id = {95d6163b-bca8-4f87-a0da-91a1fb2ff34e}]
04:18:18     INFO - GECKO(8444) | ++DOMWINDOW == 1 (000002261EAF7020) [pid = 7420] [serial = 13] [outer = 0000000000000000]
04:18:18     INFO - GECKO(8444) | [Child 7420, Main Thread] WARNING: No active window: file z:/build/build/src/js/xpconnect/src/XPCJSContext.cpp, line 662
04:18:18     INFO - GECKO(8444) | [Child 7420, Main Thread] WARNING: No active window: file z:/build/build/src/js/xpconnect/src/XPCJSContext.cpp, line 662
04:18:18     INFO - GECKO(8444) | ++DOMWINDOW == 2 (0000022618EADC00) [pid = 7420] [serial = 14] [outer = 000002261EAF7020]
04:18:18     INFO - checking window state
04:18:18     INFO - TEST-START | accessible/tests/browser/e10s/browser_events_textchange.js
04:18:18     INFO - GECKO(8444) | [Child 7420, Main Thread] WARNING: Resource acquired is being released in non-LIFO order; why?
04:18:18     INFO - GECKO(8444) | : file z:/build/build/src/xpcom/threads/BlockingResourceBase.cpp, line 329
04:18:18     INFO - GECKO(8444) | --- Mutex : mozilla::mscom::LiveSet::mMutex (currently acquired)
04:18:18     INFO - GECKO(8444) |  calling context
04:18:18     INFO - GECKO(8444) |   [stack trace unavailable]
04:18:18     INFO - GECKO(8444) | ++DOCSHELL 00000211BD44E800 == 3 [pid = 7784] [id = {3144ed2d-3ea0-4ef6-a30b-55d9ecb1607b}]
04:18:18     INFO - GECKO(8444) | ++DOMWINDOW == 5 (00000211C3F09020) [pid = 7784] [serial = 19] [outer = 0000000000000000]
04:18:18     INFO - GECKO(8444) | [Child 7784, Main Thread] WARNING: No active window: file z:/build/build/src/js/xpconnect/src/XPCJSContext.cpp, line 662
04:18:18     INFO - GECKO(8444) | [Child 7784, Main Thread] WARNING: No active window: file z:/build/build/src/js/xpconnect/src/XPCJSContext.cpp, line 662
04:18:18     INFO - GECKO(8444) | ++DOMWINDOW == 6 (00000211C3270800) [pid = 7784] [serial = 20] [outer = 00000211C3F09020]
04:18:18     INFO - GECKO(8444) | ++DOMWINDOW == 7 (00000211C3F2A400) [pid = 7784] [serial = 21] [outer = 00000211C3F09020]
04:18:18     INFO - GECKO(8444) | [Child 7784, Main Thread] WARNING: Resource acquired is being released in non-LIFO order; why?
04:18:18     INFO - GECKO(8444) | : file z:/build/build/src/xpcom/threads/BlockingResourceBase.cpp, line 329
04:18:18     INFO - GECKO(8444) | --- Mutex : mozilla::mscom::LiveSet::mMutex (currently acquired)
04:18:18     INFO - GECKO(8444) |  calling context
04:18:18     INFO - GECKO(8444) |   [stack trace unavailable]
04:18:18     INFO - GECKO(8444) | [Child 7784, Unnamed thread 211c3ff7800] WARNING: Resource acquired is being released in non-LIFO order; why?
04:18:18     INFO - GECKO(8444) | : file z:/build/build/src/xpcom/threads/BlockingResourceBase.cpp, line 329
04:18:18     INFO - GECKO(8444) | --- Mutex : mozilla::mscom::LiveSet::mMutex (currently acquired)
04:18:18     INFO - GECKO(8444) |  calling context
04:18:18     INFO - GECKO(8444) |   [stack trace unavailable]
04:18:18     INFO - GECKO(8444) | [Child 7784, Unnamed thread 211c3ff7800] WARNING: Resource acquired is being released in non-LIFO order; why?
04:18:18     INFO - GECKO(8444) | : file z:/build/build/src/xpcom/threads/BlockingResourceBase.cpp, line 329
04:18:18     INFO - GECKO(8444) | --- Mutex : mozilla::mscom::LiveSet::mMutex (currently acquired)
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Flags: needinfo?(jteh)
Whiteboard: [stockwell needswork:owner]

Update:
There have been 41 failures within the last 7 days:

  • 3 failures on windows 10 x64 quantumrender opt
  • 38 failures on windows 10 x64 quantumrender shippable opt

Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=264188613&repo=mozilla-central&lineNumber=1348

[task 2019-08-30T05:58:41.537Z] 05:58:41 INFO - TEST-START | accessible/tests/browser/e10s/browser_events_statechange.js
[task 2019-08-30T05:59:26.568Z] 05:59:26 INFO - TEST-INFO | started process screenshot
[task 2019-08-30T05:59:26.635Z] 05:59:26 INFO - TEST-INFO | screenshot: exit 0
[task 2019-08-30T05:59:26.636Z] 05:59:26 INFO - Buffered messages logged at 05:58:41
[task 2019-08-30T05:59:26.636Z] 05:59:26 INFO - Entering test bound
[task 2019-08-30T05:59:26.637Z] 05:59:26 INFO - TEST-PASS | accessible/tests/browser/e10s/browser_events_statechange.js | Recieved document load complete event -
[task 2019-08-30T05:59:26.637Z] 05:59:26 INFO - TEST-PASS | accessible/tests/browser/e10s/browser_events_statechange.js | Recieved state change event -
[task 2019-08-30T05:59:26.637Z] 05:59:26 INFO - TEST-PASS | accessible/tests/browser/e10s/browser_events_statechange.js | Correct state of the statechange event. -
[task 2019-08-30T05:59:26.638Z] 05:59:26 INFO - TEST-PASS | accessible/tests/browser/e10s/browser_events_statechange.js | Correct extra state bit of the statechange event. -
[task 2019-08-30T05:59:26.638Z] 05:59:26 INFO - TEST-PASS | accessible/tests/browser/e10s/browser_events_statechange.js | Correct state of statechange event state -
[task 2019-08-30T05:59:26.638Z] 05:59:26 INFO - TEST-PASS | accessible/tests/browser/e10s/browser_events_statechange.js | wrong state bits for [DOM node id: checkbox, role: checkbutton, address: [xpconnect wrapped nsIAccessible]]! -
[task 2019-08-30T05:59:26.638Z] 05:59:26 INFO - TEST-PASS | accessible/tests/browser/e10s/browser_events_statechange.js | Checked or mixed element must be checkable! -
[task 2019-08-30T05:59:26.638Z] 05:59:26 INFO - TEST-PASS | accessible/tests/browser/e10s/browser_events_statechange.js | Checked element cannot be state mixed! -
[task 2019-08-30T05:59:26.639Z] 05:59:26 INFO - Buffered messages finished
[task 2019-08-30T05:59:26.639Z] 05:59:26 INFO - TEST-UNEXPECTED-FAIL | accessible/tests/browser/e10s/browser_events_statechange.js | Test timed out -
[task 2019-08-30T05:59:26.639Z] 05:59:26 INFO - GECKO(10536) | JavaScript error: resource://testing-common/PromiseTestUtils.jsm, line 112: uncaught exception: Object
[task 2019-08-30T05:59:26.639Z] 05:59:26 INFO - Console message: [JavaScript Error: "uncaught exception: Object" {file: "resource://testing-common/PromiseTestUtils.jsm" line: 112}]
[task 2019-08-30T05:59:26.639Z] 05:59:26 INFO - GECKO(10536) | MEMORY STAT | vsize 2104102MB | vsizeMaxContiguous 66611094MB | residentFast 227MB | heapAllocated 80MB
[task 2019-08-30T05:59:26.639Z] 05:59:26 INFO - TEST-OK | accessible/tests/browser/e10s/browser_events_statechange.js | took 45084ms

Yura, would you mind investigating? Thanks.

Flags: needinfo?(jteh) → needinfo?(yzenevich)

Hmm. This seems to pretty much stop after August 30, perhaps something has landed in that time frame that helped alleviate the failures..

Flags: needinfo?(yzenevich) → needinfo?(jteh)
Assignee: nobody → yzenevich
Status: REOPENED → ASSIGNED

There were quite a few landings around that time, but nothing stands out as being an obvious fix for this. Some of Eitan's follow-up work for accessible re-creation did land around that time and some of those bugs did cause breakage in the tree, so I guess it's possible this could be related, though I'm by no means certain. Closing as worksforme for now.

Status: ASSIGNED → RESOLVED
Closed: 6 years ago6 years ago
Flags: needinfo?(jteh)
Resolution: --- → WORKSFORME

Looks like it timed out on waiting for a state change event when changing designMode to "on". Doesn't look like it's run with fission. Frequency is really low, not sure if you might have any ideas, Jamie?

Flags: needinfo?(jteh)

I'm somewhat bothered by the fact that this test relies on an id of "iframe" to match events, but that id is used twice: once for the iframe itself and once for the body of the iframe document. However, I don't think that could be the cause of the failure; if anything, it'd cause false positive successes, not failures.

I don't know why we wouldn't fire a state change here. I'm not overly familiar with this code, but it looks like we fire a state change for designMode here:
https://searchfox.org/mozilla-central/rev/c61720a7d0c094d772059f9d6a7844eb7619f107/accessible/generic/DocAccessible.cpp#598
The only thing that just occurred to me is that it doesn't look like we explicitly wait for the iframe to be loaded. If we haven't yet built the tree for the iframe doc when designMode is set, we wouldn't fire a state change event, since the tree isn't built yet. That seems very unlikely given that it's a data URL, but I guess maybe it's possible?

Flags: needinfo?(jteh)
Status: REOPENED → RESOLVED
Closed: 6 years ago5 years ago
Resolution: --- → INCOMPLETE

This is still happening.

Recent failure: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=287186817&repo=mozilla-central&lineNumber=2142

[task 2020-02-01T22:49:23.126Z] 22:49:23 INFO - TEST-START | accessible/tests/browser/e10s/browser_events_statechange.js
[task 2020-02-01T22:49:23.165Z] 22:49:23 INFO - GECKO(10028) | [Parent 11260, Gecko_IOThread] WARNING: file z:/build/build/src/ipc/chromium/src/base/process_util_win.cc, line 160
[task 2020-02-01T22:50:08.158Z] 22:50:08 INFO - TEST-INFO | started process screenshot
[task 2020-02-01T22:50:08.223Z] 22:50:08 INFO - TEST-INFO | screenshot: exit 0
[task 2020-02-01T22:50:08.223Z] 22:50:08 INFO - Buffered messages logged at 22:49:23
[task 2020-02-01T22:50:08.223Z] 22:50:08 INFO - Entering test bound
[task 2020-02-01T22:50:08.223Z] 22:50:08 INFO - TEST-PASS | accessible/tests/browser/e10s/browser_events_statechange.js | Recieved document load complete event -
[task 2020-02-01T22:50:08.223Z] 22:50:08 INFO - TEST-PASS | accessible/tests/browser/e10s/browser_events_statechange.js | e10s enabled -
[task 2020-02-01T22:50:08.224Z] 22:50:08 INFO - TEST-PASS | accessible/tests/browser/e10s/browser_events_statechange.js | Actually remote browser -
[task 2020-02-01T22:50:08.224Z] 22:50:08 INFO - TEST-PASS | accessible/tests/browser/e10s/browser_events_statechange.js | Recieved state change event -
[task 2020-02-01T22:50:08.224Z] 22:50:08 INFO - TEST-PASS | accessible/tests/browser/e10s/browser_events_statechange.js | Correct state of the statechange event. -
[task 2020-02-01T22:50:08.224Z] 22:50:08 INFO - TEST-PASS | accessible/tests/browser/e10s/browser_events_statechange.js | Correct extra state bit of the statechange event. -
[task 2020-02-01T22:50:08.224Z] 22:50:08 INFO - TEST-PASS | accessible/tests/browser/e10s/browser_events_statechange.js | Correct state of statechange event state -
[task 2020-02-01T22:50:08.224Z] 22:50:08 INFO - TEST-PASS | accessible/tests/browser/e10s/browser_events_statechange.js | wrong state bits for [DOM node id: checkbox, role: checkbutton, address: [xpconnect wrapped nsIAccessible]]! -
[task 2020-02-01T22:50:08.224Z] 22:50:08 INFO - TEST-PASS | accessible/tests/browser/e10s/browser_events_statechange.js | Checked or mixed element must be checkable! -
[task 2020-02-01T22:50:08.224Z] 22:50:08 INFO - TEST-PASS | accessible/tests/browser/e10s/browser_events_statechange.js | Checked element cannot be state mixed! -
[task 2020-02-01T22:50:08.224Z] 22:50:08 INFO - TEST-PASS | accessible/tests/browser/e10s/browser_events_statechange.js | Recieved state change event -
[task 2020-02-01T22:50:08.225Z] 22:50:08 INFO - TEST-PASS | accessible/tests/browser/e10s/browser_events_statechange.js | Correct state of the statechange event. -
[task 2020-02-01T22:50:08.225Z] 22:50:08 INFO - TEST-PASS | accessible/tests/browser/e10s/browser_events_statechange.js | Correct extra state bit of the statechange event. -
[task 2020-02-01T22:50:08.225Z] 22:50:08 INFO - TEST-PASS | accessible/tests/browser/e10s/browser_events_statechange.js | Correct state of statechange event state -
[task 2020-02-01T22:50:08.225Z] 22:50:08 INFO - TEST-PASS | accessible/tests/browser/e10s/browser_events_statechange.js | wrong extra state bits for [DOM node id: iframe, role: document, name: 'Inner Iframe', address: [xpconnect wrapped (nsISupports, nsIAccessible, nsIAccessibleDocument)]]! -
[task 2020-02-01T22:50:08.225Z] 22:50:08 INFO - Leaving test bound
[task 2020-02-01T22:50:08.225Z] 22:50:08 INFO - Entering test bound
[task 2020-02-01T22:50:08.225Z] 22:50:08 INFO - TEST-PASS | accessible/tests/browser/e10s/browser_events_statechange.js | Recieved document load complete event -
[task 2020-02-01T22:50:08.225Z] 22:50:08 INFO - TEST-PASS | accessible/tests/browser/e10s/browser_events_statechange.js | e10s enabled -
[task 2020-02-01T22:50:08.226Z] 22:50:08 INFO - TEST-PASS | accessible/tests/browser/e10s/browser_events_statechange.js | Actually remote browser -
[task 2020-02-01T22:50:08.226Z] 22:50:08 INFO - TEST-PASS | accessible/tests/browser/e10s/browser_events_statechange.js | IFRAME is in the same process. -
[task 2020-02-01T22:50:08.226Z] 22:50:08 INFO - TEST-PASS | accessible/tests/browser/e10s/browser_events_statechange.js | Recieved state change event -
[task 2020-02-01T22:50:08.226Z] 22:50:08 INFO - TEST-PASS | accessible/tests/browser/e10s/browser_events_statechange.js | Correct state of the statechange event. -
[task 2020-02-01T22:50:08.226Z] 22:50:08 INFO - TEST-PASS | accessible/tests/browser/e10s/browser_events_statechange.js | Correct extra state bit of the statechange event. -
[task 2020-02-01T22:50:08.226Z] 22:50:08 INFO - TEST-PASS | accessible/tests/browser/e10s/browser_events_statechange.js | Correct state of statechange event state -
[task 2020-02-01T22:50:08.226Z] 22:50:08 INFO - TEST-PASS | accessible/tests/browser/e10s/browser_events_statechange.js | wrong state bits for [DOM node id: checkbox, role: checkbutton, address: [xpconnect wrapped nsIAccessible]]! -
[task 2020-02-01T22:50:08.227Z] 22:50:08 INFO - TEST-PASS | accessible/tests/browser/e10s/browser_events_statechange.js | Checked or mixed element must be checkable! -
[task 2020-02-01T22:50:08.227Z] 22:50:08 INFO - TEST-PASS | accessible/tests/browser/e10s/browser_events_statechange.js | Checked element cannot be state mixed! -
[task 2020-02-01T22:50:08.227Z] 22:50:08 INFO - Buffered messages finished
[task 2020-02-01T22:50:08.227Z] 22:50:08 INFO - TEST-UNEXPECTED-FAIL | accessible/tests/browser/e10s/browser_events_statechange.js | Test timed out -
[task 2020-02-01T22:50:08.227Z] 22:50:08 INFO - GECKO(10028) | MEMORY STAT | vsize 2104125MB | vsizeMaxContiguous 67345278MB | residentFast 232MB | heapAllocated 78MB
[task 2020-02-01T22:50:08.227Z] 22:50:08 INFO - TEST-OK | accessible/tests/browser/e10s/browser_events_statechange.js | took 45107ms

Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 5 years ago5 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Assignee: yzenevich → nobody
Status: REOPENED → RESOLVED
Closed: 5 years ago5 years ago
Resolution: --- → INCOMPLETE
Status: REOPENED → RESOLVED
Closed: 5 years ago4 years ago
Resolution: --- → INCOMPLETE
Status: REOPENED → RESOLVED
Closed: 4 years ago4 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 4 years ago4 years ago
Resolution: --- → INCOMPLETE
Status: VERIFIED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 4 years ago4 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 4 years ago3 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 3 years ago3 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 3 years ago3 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 3 years ago3 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 3 years ago3 years ago
Resolution: --- → DUPLICATE
You need to log in before you can comment on or make changes to this bug.