Closed Bug 1647666 Opened 4 years ago Closed 4 years ago

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

Categories

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

Product:
Core
Component:
Disability Access APIs
Type:
defect

Tracking

()

Status:
RESOLVED FIXED
Milestone:
mozilla80
Tracking Flags:
Tracking Status
firefox-esr68 --- unaffected
firefox77 --- unaffected
firefox78 --- unaffected
firefox79 --- fixed
firefox80 --- fixed

People

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

References

(Blocks 1 open bug, Regression)

Details

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

Attachments

(4 files, 1 obsolete file)

Bug 1647666: test_doc_busy.html: Handle the case where we get a load event for about:blank before the download prompt itself.
(deleted), text/x-phabricator-request
Details
Bug 1647666: test_doc_busy.html: Log the window location so we can try to figure out why this is failing intermittently.
(deleted), text/x-phabricator-request
Details
Bug 1647666: test_doc_busy.html: Log a11y events to help debug the intermittent timeout.
(deleted), text/x-phabricator-request
Details
Bug 1647666: test_doc_busy.html: Handle the case where the busy change and not-busy change events are coalesced out of existence.
(deleted), text/x-phabricator-request
Details

Filed by: ccoroiu [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=307218077&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/KXszJSGORImBPH-sKM6Hyw/runs/0/artifacts/public/logs/live_backing.log
Reftest URL: https://hg.mozilla.org/mozilla-central/raw-file/tip/layout/tools/reftest/reftest-analyzer.xhtml#logurl=https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/KXszJSGORImBPH-sKM6Hyw/runs/0/artifacts/public/logs/live_backing.log&only_show_unexpected=1

task 2020-06-23T09:14:54.563Z] 09:14:54 INFO - TEST-START | accessible/tests/mochitest/states/test_doc_busy.html
[task 2020-06-23T09:14:54.622Z] 09:14:54 INFO - GECKO(2904) | [3228, Main Thread] WARNING: Failed to retarget HTML data delivery to the parser thread.: file /builds/worker/checkouts/gecko/parser/html/nsHtml5StreamParser.cpp, line 1136
[task 2020-06-23T09:14:54.889Z] 09:14:54 INFO - GECKO(2904) | [3228, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80040154 (NS_ERROR_FACTORY_NOT_REGISTERED): file /builds/worker/checkouts/gecko/netwerk/ipc/DocumentLoadListener.cpp, line 137
[task 2020-06-23T09:14:54.916Z] 09:14:54 INFO - GECKO(2904) | [3228, Main Thread] WARNING: NS_ENSURE_TRUE(rootFrame) failed: file /builds/worker/checkouts/gecko/dom/base/nsGlobalWindowOuter.cpp, line 4281
[task 2020-06-23T09:14:54.963Z] 09:14:54 INFO - GECKO(2904) | [3228, Main Thread] WARNING: NS_ENSURE_TRUE(root) failed: file /builds/worker/checkouts/gecko/layout/base/nsDocumentViewer.cpp, line 2921
[task 2020-06-23T09:16:48.034Z] 09:16:48 INFO - GECKO(2904) | [3228, Jump List] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80520012 (NS_ERROR_FILE_NOT_FOUND): file /builds/worker/checkouts/gecko/widget/windows/WinUtils.cpp, line 1360
[task 2020-06-23T09:18:48.043Z] 09:18:48 INFO - GECKO(2904) | [3228, Jump List] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80520012 (NS_ERROR_FILE_NOT_FOUND): file /builds/worker/checkouts/gecko/widget/windows/WinUtils.cpp, line 1360
[task 2020-06-23T09:19:54.631Z] 09:19:54 INFO - TEST-INFO | started process screenshot
[task 2020-06-23T09:19:54.698Z] 09:19:54 INFO - TEST-INFO | screenshot: exit 0
[task 2020-06-23T09:19:54.698Z] 09:19:54 INFO - Buffered messages logged at 09:14:54
[task 2020-06-23T09:19:54.698Z] 09:19:54 INFO - must wait for load
[task 2020-06-23T09:19:54.698Z] 09:19:54 INFO - Clicking link to trigger download
[task 2020-06-23T09:19:54.698Z] 09:19:54 INFO - Waiting for a11y busy events
[task 2020-06-23T09:19:54.699Z] 09:19:54 INFO - Window opened, waiting for load event
[task 2020-06-23T09:19:54.699Z] 09:19:54 INFO - Buffered messages logged at 09:14:55
[task 2020-06-23T09:19:54.699Z] 09:19:54 INFO - Window loaded, checking if download prompt
[task 2020-06-23T09:19:54.699Z] 09:19:54 INFO - Buffered messages finished
[task 2020-06-23T09:19:54.699Z] 09:19:54 INFO - TEST-UNEXPECTED-FAIL | accessible/tests/mochitest/states/test_doc_busy.html | Test timed out.
[task 2020-06-23T09:19:54.699Z] 09:19:54 INFO - SimpleTest.ok@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:409:16
[task 2020-06-23T09:19:54.699Z] 09:19:54 INFO - reportError@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:138:22
[task 2020-06-23T09:19:54.699Z] 09:19:54 INFO - TestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:160:18
[task 2020-06-23T09:19:55.646Z] 09:19:55 INFO - GECKO(2904) | MEMORY STAT | vsize 897MB | vsizeMaxContiguous 322MB | residentFast 298MB | heapAllocated 95MB
[task 2020-06-23T09:19:55.647Z] 09:19:55 INFO - TEST-OK | accessible/tests/mochitest/states/test_doc_busy.html | took 301056ms

Jamie, this looks like a side effect the try run from bug 1626851 didn't catch. We might need help with what the screenshot shows, though.

Flags: needinfo?(jteh)
Has Regression Range: --- → yes
Keywords: regression
Summary: Intermittent TV accessible/tests/mochitest/states/test_doc_busy.html | Test timed out. → Intermittent accessible/tests/mochitest/states/test_doc_busy.html | Test timed out.
Assignee: nobody → jteh
Status: NEW → ASSIGNED
Pushed by jteh@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/ca1b88eb5c90
test_doc_busy.html: Handle the case where we get a load event for about:blank before the download prompt itself. r=MarcoZ

Set release status flags based on info from the regressing bug 1626851

status-firefox77: --- → unaffected
status-firefox78: --- → unaffected
status-firefox79: --- → affected
status-firefox-esr68: --- → unaffected

https://hg.mozilla.org/mozilla-central/rev/ca1b88eb5c90

Status: ASSIGNED → RESOLVED
Closed: 4 years ago
status-firefox79: affected → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla79

Reopening since this is not fixed, retriggered on the push with the patch: :
https://treeherder.mozilla.org/#/jobs?repo=autoland&selectedTaskRun=QQWqvCmDT8uJ-BPWhDrnQA.0&tochange=ca1b88eb5c905f0daf957e4a173137db04fae3c9&fromchange=d5231100ed240653511ce8baa89ba5a95595af77&searchStr=a11y

Status: RESOLVED → REOPENED
status-firefox79: fixed → affected
Flags: needinfo?(jteh)
Resolution: FIXED → ---
Target Milestone: mozilla79 → ---
Flags: needinfo?(jteh)
Keywords: leave-open

I can't seem to repro this on try, so I guess we'll just have to land debug logging so we can catch it on central/autoland.

Pushed by mzehe@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/4025b7f21925
test_doc_busy.html: Log the window location so we can try to figure out why this is failing intermittently. r=MarcoZ

It seems the window location isn't the issue here at all.
Rather, we never get the expected a11y events.
So, let's try to find out what events we do get.

Pushed by mzehe@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/0f09766b6b66
test_doc_busy.html: Log a11y events to help debug the intermittent timeout. r=MarcoZ
Blocks: 1167937

From this log, it looks like busy events are just never fired for the document. There's some talk of the events being coalesced intermittently in bug 446469 and bug 569356, but I don't fully understand some of the discussion. If I understand bug 446469 comment 42 correctly, we previously didn't coalesce the events correctly, but there was concern that when we did, we (rightly) wouldn't get any busy events... which is what we're seeing now. But if that's the case, I don't understand why we weren't seeing this particular failure with the previous (non-promise) version of the test.

Also removed debug logging, as well as about:blank check which turned out not to be the cause of the timeout.

Keywords: leave-open

Note that I'm hoping the patch in comment 23 will finally fix this.

Changing the stockwell tag based on the above.

Whiteboard: [stockwell disable-recommended] → [stockwell needswork:owner]
Whiteboard: [stockwell disable-recommended] → [stockwell needswork:owner]
Whiteboard: [stockwell disable-recommended] → [stockwell disable]
Whiteboard: [stockwell disable] → [stockwell disabled]
Whiteboard: [stockwell disabled] → [stockwell disable-recommended]

Please take a look at this potential fix: https://phabricator.services.mozilla.com/D82137 before landing the disable patch.

Pushed by yura.zenevich@gmail.com:
https://hg.mozilla.org/integration/autoland/rev/3e441eedb657
test_doc_busy.html: Handle the case where the busy change and not-busy change events are coalesced out of existence. r=yzen

Removing the [stockwell disable-recommended] since the fix landed. We'll monitor the failure rate for the next few days.

Whiteboard: [stockwell disable-recommended]

https://hg.mozilla.org/mozilla-central/rev/3e441eedb657

Status: REOPENED → RESOLVED
Closed: 4 years ago → 4 years ago
status-firefox80: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla80
Whiteboard: [stockwell disable-recommended] → [stockwell fixed:patch]
Attachment #9163023 - Attachment is obsolete: true
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: