Intermittent accessible/tests/mochitest/states/test_docarticle.html | Test timed out.
Categories
(Core :: Disability Access APIs, defect, P5)
Tracking
()
Tracking | Status | |
---|---|---|
firefox79 | --- | fixed |
People
(Reporter: intermittent-bug-filer, Assigned: Jamie)
References
(Blocks 1 open bug)
Details
(Keywords: intermittent-failure, Whiteboard: [stockwell disable-recommended])
Attachments
(2 files)
Filed by: dvarga [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=295834159&repo=mozilla-central
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/P5tcJFrrSwyDtq2Xfvzn9w/runs/0/artifacts/public/logs/live_backing.log
[task 2020-04-01T21:53:48.844Z] 21:53:48 INFO - TEST-START | accessible/tests/mochitest/states/test_docarticle.html
[task 2020-04-01T21:53:49.610Z] 21:53:49 INFO - GECKO(1230) | [2020-04-01T21:53:49Z WARN webrender::device::gl] Attribute VertexAttribute { name: "aUvRect0", count: 4, kind: F32 } is not found in the shader composite. Expected at 5, found at -1
[task 2020-04-01T21:53:49.612Z] 21:53:49 INFO - GECKO(1230) | [2020-04-01T21:53:49Z WARN webrender::device::gl] Attribute VertexAttribute { name: "aUvRect1", count: 4, kind: F32 } is not found in the shader composite. Expected at 6, found at -1
[task 2020-04-01T21:53:49.613Z] 21:53:49 INFO - GECKO(1230) | [2020-04-01T21:53:49Z WARN webrender::device::gl] Attribute VertexAttribute { name: "aUvRect2", count: 4, kind: F32 } is not found in the shader composite. Expected at 7, found at -1
[task 2020-04-01T21:53:50.440Z] 21:53:50 INFO - GECKO(1230) | [1230, Main Thread] WARNING: 'NS_FAILED(rv)', file /builds/worker/checkouts/gecko/extensions/spellcheck/src/mozSpellChecker.cpp, line 127
[task 2020-04-01T21:53:50.441Z] 21:53:50 INFO - GECKO(1230) | [1230, Main Thread] WARNING: 'NS_FAILED(rv)', file /builds/worker/checkouts/gecko/extensions/spellcheck/src/mozSpellChecker.cpp, line 127
[task 2020-04-01T21:53:50.441Z] 21:53:50 INFO - GECKO(1230) | [1230, Main Thread] WARNING: 'NS_FAILED(rv)', file /builds/worker/checkouts/gecko/extensions/spellcheck/src/mozSpellChecker.cpp, line 127
[task 2020-04-01T21:53:50.441Z] 21:53:50 INFO - GECKO(1230) | [1230, Main Thread] WARNING: 'NS_FAILED(rv)', file /builds/worker/checkouts/gecko/extensions/spellcheck/src/mozSpellChecker.cpp, line 127
[task 2020-04-01T21:53:50.442Z] 21:53:50 INFO - GECKO(1230) | [1230, Main Thread] WARNING: 'NS_FAILED(rv)', file /builds/worker/checkouts/gecko/extensions/spellcheck/src/mozSpellChecker.cpp, line 127
[task 2020-04-01T21:56:21.974Z] 21:56:21 INFO - GECKO(1230) | [2020-04-01T21:56:21Z WARN rkv::backend::impl_safe::environment] Ignoring `map_size=16777216`
[task 2020-04-01T21:56:21.982Z] 21:56:21 INFO - GECKO(1230) | [1230, QuotaManager IO] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80630001: file /builds/worker/checkouts/gecko/storage/mozStorageConnection.cpp, line 701
[task 2020-04-01T21:56:21.983Z] 21:56:21 INFO - GECKO(1230) | [1230, QuotaManager IO] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80630001: file /builds/worker/checkouts/gecko/storage/mozStorageService.cpp, line 640
[task 2020-04-01T21:56:21.983Z] 21:56:21 INFO - GECKO(1230) | [1230, QuotaManager IO] WARNING: Received NS_ERROR_STORAGE_BUSY when attempting to open database '3870112724rsegmnoittet-es.sqlite', retrying for up to 10 seconds: file /builds/worker/checkouts/gecko/dom/indexedDB/ActorsParent.cpp, line 4140
[task 2020-04-01T21:59:05.124Z] 21:59:05 INFO - TEST-INFO | started process screentopng
[task 2020-04-01T21:59:05.282Z] 21:59:05 INFO - TEST-INFO | screentopng: exit 0
[task 2020-04-01T21:59:05.283Z] 21:59:05 INFO - Buffered messages logged at 21:53:50
[task 2020-04-01T21:59:05.283Z] 21:59:05 INFO - must wait for load
[task 2020-04-01T21:59:05.283Z] 21:59:05 INFO - must wait for focus
[task 2020-04-01T21:59:05.283Z] 21:59:05 INFO - Buffered messages finished
[task 2020-04-01T21:59:05.286Z] 21:59:05 INFO - TEST-UNEXPECTED-FAIL | accessible/tests/mochitest/states/test_docarticle.html | Test timed out.
[task 2020-04-01T21:59:05.286Z] 21:59:05 INFO - SimpleTest.ok@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:299:16
[task 2020-04-01T21:59:05.286Z] 21:59:05 INFO - reportError@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:128:22
[task 2020-04-01T21:59:05.287Z] 21:59:05 INFO - TestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:150:18
[task 2020-04-01T21:59:05.287Z] 21:59:05 INFO - setTimeout handler*TestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:184:15
[task 2020-04-01T21:59:05.287Z] 21:59:05 INFO - setTimeout handler*TestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:184:15
[task 2020-04-01T21:59:05.287Z] 21:59:05 INFO - setTimeout handler*TestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:184:15
[task 2020-04-01T21:59:05.288Z] 21:59:05 INFO - setTimeout handler*TestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:184:15
[task 2020-04-01T21:59:05.288Z] 21:59:05 INFO - setTimeout handler*TestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:184:15
[task 2020-04-01T21:59:05.288Z] 21:59:05 INFO - setTimeout handler*TestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:184:15
[task 2020-04-01T21:59:05.288Z] 21:59:05 INFO - setTimeout handler*TestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:184:15
[task 2020-04-01T21:59:05.288Z] 21:59:05 INFO - setTimeout handler*TestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:184:15
[task 2020-04-01T21:59:05.289Z] 21:59:05 INFO - setTimeout handler*TestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:184:15
[task 2020-04-01T21:59:05.289Z] 21:59:05 INFO - setTimeout handler*TestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:184:15
[task 2020-04-01T21:59:05.289Z] 21:59:05 INFO - setTimeout handler*TestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:184:15
[task 2020-04-01T21:59:05.289Z] 21:59:05 INFO - setTimeout handler*TestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:184:15
[task 2020-04-01T21:59:05.290Z] 21:59:05 INFO - setTimeout handler*TestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:184:15
[task 2020-04-01T21:59:05.290Z] 21:59:05 INFO - setTimeout handler*TestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:184:15
[task 2020-04-01T21:59:05.290Z] 21:59:05 INFO - setTimeout handler*TestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:184:15
[task 2020-04-01T21:59:05.290Z] 21:59:05 INFO - setTimeout handler*TestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:184:15
[task 2020-04-01T21:59:05.290Z] 21:59:05 INFO - setTimeout handler*TestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:184:15
[task 2020-04-01T21:59:05.290Z] 21:59:05 INFO - setTimeout handler*TestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:184:15
[task 2020-04-01T21:59:05.290Z] 21:59:05 INFO - TestRunner.runTests/<@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:420:16
[task 2020-04-01T21:59:05.290Z] 21:59:05 INFO - promise callback*TestRunner.runTests@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:407:48
[task 2020-04-01T21:59:05.290Z] 21:59:05 INFO - RunSet.runtests@chrome://mochikit/content/tests/SimpleTest/setup.js:218:14
[task 2020-04-01T21:59:05.291Z] 21:59:05 INFO - RunSet.runall@chrome://mochikit/content/tests/SimpleTest/setup.js:197:12
[task 2020-04-01T21:59:05.291Z] 21:59:05 INFO - hookupTests@chrome://mochikit/content/tests/SimpleTest/setup.js:294:12
[task 2020-04-01T21:59:05.291Z] 21:59:05 INFO - parseTestManifest@chrome://mochikit/content/manifestLibrary.js:50:13
[task 2020-04-01T21:59:05.291Z] 21:59:05 INFO - getTestManifest/req.onload@chrome://mochikit/content/manifestLibrary.js:61:28
[task 2020-04-01T21:59:05.292Z] 21:59:05 INFO - EventHandlerNonNull*getTestManifest@chrome://mochikit/content/manifestLibrary.js:57:3
[task 2020-04-01T21:59:05.292Z] 21:59:05 INFO - hookup@chrome://mochikit/content/tests/SimpleTest/setup.js:270:20
[task 2020-04-01T21:59:05.292Z] 21:59:05 INFO - linkAndHookup@chrome://mochikit/content/harness.xhtml:45:3
[task 2020-04-01T21:59:05.292Z] 21:59:05 INFO - parseTestManifest@chrome://mochikit/content/manifestLibrary.js:50:13
[task 2020-04-01T21:59:05.293Z] 21:59:05 INFO - getTestManifest/req.onload@chrome://mochikit/content/manifestLibrary.js:61:28
[task 2020-04-01T21:59:05.293Z] 21:59:05 INFO - EventHandlerNonNull*getTestManifest@chrome://mochikit/content/manifestLibrary.js:57:3
[task 2020-04-01T21:59:05.293Z] 21:59:05 INFO - getTestList@chrome://mochikit/content/chrome-harness.js:258:18
[task 2020-04-01T21:59:05.293Z] 21:59:05 INFO - loadTests@chrome://mochikit/content/harness.xhtml:24:14
[task 2020-04-01T21:59:05.294Z] 21:59:05 INFO - EventListener.handleEvent*@chrome://mochikit/content/harness.xhtml:48:12
[task 2020-04-01T21:59:06.133Z] 21:59:06 INFO - Not taking screenshot here: see the one that was previously logged
[task 2020-04-01T21:59:06.134Z] 21:59:06 INFO - TEST-UNEXPECTED-FAIL | accessible/tests/mochitest/states/test_docarticle.html | [SimpleTest.finish()] waitForFocus() was called a different number of times from the number of callbacks run. Maybe the test terminated prematurely -- be sure to use SimpleTest.waitForExplicitFinish(). - got 1, expected +0
[task 2020-04-01T21:59:06.134Z] 21:59:06 INFO - SimpleTest.is@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:383:14
[task 2020-04-01T21:59:06.134Z] 21:59:06 INFO - afterCleanup@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1398:18
[task 2020-04-01T21:59:06.135Z] 21:59:06 INFO - executeCleanupFunction@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1474:7
[task 2020-04-01T21:59:06.135Z] 21:59:06 INFO - SimpleTest.finish@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1494:3
[task 2020-04-01T21:59:06.136Z] 21:59:06 INFO - killTest@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:137:22
[task 2020-04-01T21:59:06.136Z] 21:59:06 INFO - async*delayedKillTest@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:173:17
[task 2020-04-01T21:59:06.137Z] 21:59:06 INFO - setTimeout handler*TestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:171:17
[task 2020-04-01T21:59:06.137Z] 21:59:06 INFO - setTimeout handler*TestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:184:15
[task 2020-04-01T21:59:06.138Z] 21:59:06 INFO - setTimeout handler*TestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:184:15
[task 2020-04-01T21:59:06.138Z] 21:59:06 INFO - setTimeout handler*TestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:184:15
[task 2020-04-01T21:59:06.138Z] 21:59:06 INFO - setTimeout handler*TestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:184:15
[task 2020-04-01T21:59:06.138Z] 21:59:06 INFO - setTimeout handler*TestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:184:15
[task 2020-04-01T21:59:06.138Z] 21:59:06 INFO - setTimeout handler*TestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:184:15
[task 2020-04-01T21:59:06.139Z] 21:59:06 INFO - setTimeout handler*TestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:184:15
[task 2020-04-01T21:59:06.139Z] 21:59:06 INFO - setTimeout handler*TestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:184:15
[task 2020-04-01T21:59:06.140Z] 21:59:06 INFO - setTimeout handler*TestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:184:15
[task 2020-04-01T21:59:06.140Z] 21:59:06 INFO - setTimeout handler*TestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:184:15
[task 2020-04-01T21:59:06.141Z] 21:59:06 INFO - setTimeout handler*TestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:184:15
[task 2020-04-01T21:59:06.141Z] 21:59:06 INFO - setTimeout handler*TestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:184:15
[task 2020-04-01T21:59:06.141Z] 21:59:06 INFO - setTimeout handler*TestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:184:15
[task 2020-04-01T21:59:06.142Z] 21:59:06 INFO - setTimeout handler*TestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:184:15
[task 2020-04-01T21:59:06.142Z] 21:59:06 INFO - setTimeout handler*TestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:184:15
[task 2020-04-01T21:59:06.143Z] 21:59:06 INFO - setTimeout handler*TestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:184:15
[task 2020-04-01T21:59:06.143Z] 21:59:06 INFO - setTimeout handler*TestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:184:15
[task 2020-04-01T21:59:06.143Z] 21:59:06 INFO - setTimeout handler*TestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:184:15
[task 2020-04-01T21:59:06.143Z] 21:59:06 INFO - TestRunner.runTests/<@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:420:16
[task 2020-04-01T21:59:06.145Z] 21:59:06 INFO - promise callback*TestRunner.runTests@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:407:48
[task 2020-04-01T21:59:06.145Z] 21:59:06 INFO - RunSet.runtests@chrome://mochikit/content/tests/SimpleTest/setup.js:218:14
[task 2020-04-01T21:59:06.145Z] 21:59:06 INFO - RunSet.runall@chrome://mochikit/content/tests/SimpleTest/setup.js:197:12
[task 2020-04-01T21:59:06.146Z] 21:59:06 INFO - hookupTests@chrome://mochikit/content/tests/SimpleTest/setup.js:294:12
[task 2020-04-01T21:59:06.146Z] 21:59:06 INFO - parseTestManifest@chrome://mochikit/content/manifestLibrary.js:50:13
[task 2020-04-01T21:59:06.147Z] 21:59:06 INFO - getTestManifest/req.onload@chrome://mochikit/content/manifestLibrary.js:61:28
[task 2020-04-01T21:59:06.147Z] 21:59:06 INFO - EventHandlerNonNull*getTestManifest@chrome://mochikit/content/manifestLibrary.js:57:3
[task 2020-04-01T21:59:06.147Z] 21:59:06 INFO - hookup@chrome://mochikit/content/tests/SimpleTest/setup.js:270:20
[task 2020-04-01T21:59:06.148Z] 21:59:06 INFO - linkAndHookup@chrome://mochikit/content/harness.xhtml:45:3
[task 2020-04-01T21:59:06.148Z] 21:59:06 INFO - parseTestManifest@chrome://mochikit/content/manifestLibrary.js:50:13
[task 2020-04-01T21:59:06.149Z] 21:59:06 INFO - getTestManifest/req.onload@chrome://mochikit/content/manifestLibrary.js:61:28
[task 2020-04-01T21:59:06.149Z] 21:59:06 INFO - EventHandlerNonNull*getTestManifest@chrome://mochikit/content/manifestLibrary.js:57:3
[task 2020-04-01T21:59:06.149Z] 21:59:06 INFO - getTestList@chrome://mochikit/content/chrome-harness.js:258:18
[task 2020-04-01T21:59:06.150Z] 21:59:06 INFO - loadTests@chrome://mochikit/content/harness.xhtml:24:14
[task 2020-04-01T21:59:06.150Z] 21:59:06 INFO - EventListener.handleEvent*@chrome://mochikit/content/harness.xhtml:48:12
[task 2020-04-01T21:59:06.150Z] 21:59:06 INFO - GECKO(1230) | MEMORY STAT | vsize 4026MB | residentFast 546MB | heapAllocated 211MB
Comment hidden (Intermittent Failures Robot) |
Comment 2•5 years ago
|
||
https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.
Comment 3•4 years ago
|
||
New occurrence: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=301606883&repo=autoland&lineNumber=3382
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment 9•4 years ago
|
||
There are 73 failures in the last 7 days.
Most of them are on Linux1804-64bits and Windows 10-64bits.
Jamie, can you please take a look?
Assignee | ||
Comment 10•4 years ago
|
||
I've spent a couple hours looking into this, but I can't see anything wrong. I also can't reproduce it locally no matter what I do (single test, single test with --verify, single test with --run-until-failure, all tests in the directory, etc.).
From the log, it looks like SimpleTest.waitForFocus gets stuck waiting for a focus event which never arrives. I don't know why the document wouldn't get focus, though.
Comment hidden (Intermittent Failures Robot) |
Comment 12•4 years ago
|
||
(In reply to James Teh [:Jamie] from comment #10)
From the log, it looks like SimpleTest.waitForFocus gets stuck waiting for a focus event which never arrives. I don't know why the document wouldn't get focus, though.
According to the screenshot on the failures there's a download dialog over top of the main browser window for a "dumbfile.zip". Presumably that comes from the previous test (test_doc_busy.html) and is preventing the main browser window from getting focus.
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Assignee | ||
Comment 17•4 years ago
|
||
Thanks Kats. That's hugely helpful; I would never have been aware of that (given I'm blind and can't see the screenshots). Now I just have to figure out how to make sure that download dialog gets closed in the previous test. Curious that it's started failing more recently; that tested has been there forever.
I'll try to look into this next week.
Comment 18•4 years ago
|
||
Removing the disable-recommended tag as it is going to be worked on.
Comment hidden (Intermittent Failures Robot) |
Assignee | ||
Comment 20•4 years ago
|
||
It's just too difficult/confusing to mix a11y and non-a11y async stuff using eventQueue.
This patch should be functionally equivalent; it doesn't fix the bug.
Updated•4 years ago
|
Assignee | ||
Comment 21•4 years ago
|
||
This is the actual fix.
Previously, we opened a download prompt, but we didn't close it.
This download prompt could sometimes get focus and prevent subsequent tests from getting focus.
Explicitly closing it should prevent this from happening.
Assignee | ||
Updated•4 years ago
|
Assignee | ||
Comment 22•4 years ago
|
||
Comment hidden (Intermittent Failures Robot) |
Comment 24•4 years ago
|
||
Comment 25•4 years ago
|
||
bugherder |
https://hg.mozilla.org/mozilla-central/rev/e1f348eddac5
https://hg.mozilla.org/mozilla-central/rev/319002038939
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Description
•