Closed Bug 1626851 Opened 4 years ago Closed 4 years ago

Intermittent accessible/tests/mochitest/states/test_docarticle.html | Test timed out.

Categories

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

Product:
Core
Component:
Disability Access APIs
Type:
defect

Tracking

()

Status:
RESOLVED FIXED
Milestone:
mozilla79
Tracking Flags:
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)

Bug 1626851 part 1: Rewrite test_doc_busy.html to use promises.
(deleted), text/x-phabricator-request
Details
Bug 1626851 part 2: Close the download prompt before finishing the test.
(deleted), text/x-phabricator-request
Details

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

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.

Status: NEW → RESOLVED
Closed: 4 years ago
Resolution: --- → INCOMPLETE

New occurrence: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=301606883&repo=autoland&lineNumber=3382

Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---

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?

Flags: needinfo?(jteh)

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.

(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.

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.

Removing the disable-recommended tag as it is going to be worked on.

Whiteboard: [stockwell disable-recommended]

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.

Assignee: nobody → jteh

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.

Flags: needinfo?(jteh)
Pushed by mzehe@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/e1f348eddac5
part 1: Rewrite test_doc_busy.html to use promises. r=MarcoZ
https://hg.mozilla.org/integration/autoland/rev/319002038939
part 2: Close the download prompt before finishing the test. r=MarcoZ
Regressions: 1647666

https://hg.mozilla.org/mozilla-central/rev/e1f348eddac5
https://hg.mozilla.org/mozilla-central/rev/319002038939

Status: REOPENED → RESOLVED
Closed: 4 years ago → 4 years ago
status-firefox79: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla79
Blocks: 1167937
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: