Open Bug 1585231 Opened 6 months ago Updated 2 days ago

Intermittent toolkit/content/tests/browser/browser_delay_autoplay_media_pausedAfterPlay.js | Test timed out -

Categories

(Core :: Audio/Video: Playback, defect, P3)

defect

Tracking

()

REOPENED
Fission Milestone M4.1

People

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

References

(Blocks 1 open bug)

Details

(Keywords: intermittent-failure, regression, Whiteboard: [stockwell disabled][stockwell needswork:owner])

Attachments

(2 files)

Filed by: aciure [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=269184682&repo=mozilla-inbound
Full log: https://queue.taskcluster.net/v1/task/G5n5-AnySA-WZXcm-8KGfA/runs/0/artifacts/public/logs/live_backing.log


[task 2019-10-01T02:36:05.271Z] 02:36:05 INFO - TEST-PASS | toolkit/content/tests/browser/browser_delay_autoplay_media_pausedAfterPlay.js | The tab should not be blocked -
[task 2019-10-01T02:36:05.271Z] 02:36:05 INFO - - open new background tab2, and tab2 should be blocked -
[task 2019-10-01T02:36:05.272Z] 02:36:05 INFO - Block state doens't match, wait for attributes changes.
[task 2019-10-01T02:36:05.272Z] 02:36:05 INFO - Console message: [JavaScript Error: "AbortError: The fetching process for the media resource was aborted by the user agent at the user's request."]
[task 2019-10-01T02:36:05.272Z] 02:36:05 INFO - Buffered messages finished
[task 2019-10-01T02:36:05.272Z] 02:36:05 INFO - TEST-UNEXPECTED-FAIL | toolkit/content/tests/browser/browser_delay_autoplay_media_pausedAfterPlay.js | Test timed out -
[task 2019-10-01T02:36:05.272Z] 02:36:05 INFO - GECKO(2178) | MEMORY STAT | vsize 7695MB | residentFast 385MB | heapAllocated 119MB
[task 2019-10-01T02:36:05.272Z] 02:36:05 INFO - TEST-OK | toolkit/content/tests/browser/browser_delay_autoplay_media_pausedAfterPlay.js | took 45099ms
[task 2019-10-01T02:36:05.272Z] 02:36:05 INFO - Not taking screenshot here: see the one that was previously logged
[task 2019-10-01T02:36:05.272Z] 02:36:05 INFO - TEST-UNEXPECTED-FAIL | toolkit/content/tests/browser/browser_delay_autoplay_media_pausedAfterPlay.js | Found a tab after previous test timed out: https://example.com/browser/toolkit/content/tests/browser/file_blockMedia_shouldPlay.html -
[task 2019-10-01T02:36:05.272Z] 02:36:05 INFO - Not taking screenshot here: see the one that was previously logged
[task 2019-10-01T02:36:05.273Z] 02:36:05 INFO - TEST-UNEXPECTED-FAIL | toolkit/content/tests/browser/browser_delay_autoplay_media_pausedAfterPlay.js | Found a tab after previous test timed out: https://example.com/browser/toolkit/content/tests/browser/file_blockMedia_shouldNotPlay.html -
[task 2019-10-01T02:36:05.273Z] 02:36:05 INFO - checking window state
[task 2019-10-01T02:36:05.273Z] 02:36:05 INFO - GECKO(2178) | JavaScript error: resource://gre/actors/AudioPlaybackParent.jsm, line 19: TypeError: browser is null
[task 2019-10-01T02:36:05.273Z] 02:36:05 INFO - GECKO(2178) | JavaScript error: , line 0: NS_ERROR_UNEXPECTED:

Component: General → Audio/Video: Playback
Product: Toolkit → Core
See Also: → 1585836
See Also: → 1584678, 1585207, 1586970

Seeing a number of these browser_delay_autoplay* tests failing right now, any idea what might be happening?

Flags: needinfo?(alwu)
Priority: P5 → P3

Bug 1377626 might be a duplicate of this (this is tracking the old name of this test).

See Also: → 1377626

I have added some debug logs and pushed them to the try server, trying to figure out what's happen.

Flags: needinfo?(alwu)
Pushed by apavel@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/4466d109fc51
disable browser_delay_autoplay_media_pausedAfterPlay.js on fission r=mccr8
Keywords: leave-open
Whiteboard: [stockwell disable-recommended] → [stockwell disabled]
Fission Milestone: --- → M4.1

Since this got disabled on fission it's failing on mochitest-browser-chrome-e10s tests.

There are 22 total failures in the last 7 days on macosx1014-64 debug and macosx1014-64-shippable opt.

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

[task 2019-11-26T22:42:46.517Z] 22:42:46 INFO - TEST-START | toolkit/content/tests/browser/browser_delay_autoplay_media_pausedAfterPlay.js
[task 2019-11-26T22:42:47.019Z] 22:42:47 INFO - GECKO(2289) | JavaScript error: , line 0: AbortError: The fetching process for the media resource was aborted by the user agent at the user's request.
[task 2019-11-26T22:43:31.529Z] 22:43:31 INFO - TEST-INFO | started process screencapture
[task 2019-11-26T22:43:31.683Z] 22:43:31 INFO - TEST-INFO | screencapture: exit 0
[task 2019-11-26T22:43:31.683Z] 22:43:31 INFO - Buffered messages logged at 22:42:46
[task 2019-11-26T22:43:31.683Z] 22:43:31 INFO - Entering test bound setup_test_preference
[task 2019-11-26T22:43:31.683Z] 22:43:31 INFO - Leaving test bound setup_test_preference
[task 2019-11-26T22:43:31.684Z] 22:43:31 INFO - Entering test bound block_autoplay_media
[task 2019-11-26T22:43:31.684Z] 22:43:31 INFO - - open new background tab1, and tab1 should not be blocked -
[task 2019-11-26T22:43:31.684Z] 22:43:31 INFO - TEST-PASS | toolkit/content/tests/browser/browser_delay_autoplay_media_pausedAfterPlay.js | The tab should not be blocked -
[task 2019-11-26T22:43:31.684Z] 22:43:31 INFO - - open new background tab2, and tab2 should be blocked -
[task 2019-11-26T22:43:31.684Z] 22:43:31 INFO - Block state doens't match, wait for attributes changes.
[task 2019-11-26T22:43:31.684Z] 22:43:31 INFO - Buffered messages logged at 22:42:47
[task 2019-11-26T22:43:31.684Z] 22:43:31 INFO - Console message: [JavaScript Error: "AbortError: The fetching process for the media resource was aborted by the user agent at the user's request."]
[task 2019-11-26T22:43:31.685Z] 22:43:31 INFO - Buffered messages finished
[task 2019-11-26T22:43:31.685Z] 22:43:31 INFO - TEST-UNEXPECTED-FAIL | toolkit/content/tests/browser/browser_delay_autoplay_media_pausedAfterPlay.js | Test timed out -
[task 2019-11-26T22:43:31.685Z] 22:43:31 INFO - GECKO(2289) | MEMORY STAT | vsize 7662MB | residentFast 378MB | heapAllocated 119MB
[task 2019-11-26T22:43:31.685Z] 22:43:31 INFO - TEST-OK | toolkit/content/tests/browser/browser_delay_autoplay_media_pausedAfterPlay.js | took 45034ms
[task 2019-11-26T22:43:31.685Z] 22:43:31 INFO - Not taking screenshot here: see the one that was previously logged
[task 2019-11-26T22:43:31.685Z] 22:43:31 INFO - TEST-UNEXPECTED-FAIL | toolkit/content/tests/browser/browser_delay_autoplay_media_pausedAfterPlay.js | Found a tab after previous test timed out: https://example.com/browser/toolkit/content/tests/browser/file_blockMedia_shouldPlay.html -
[task 2019-11-26T22:43:31.686Z] 22:43:31 INFO - Not taking screenshot here: see the one that was previously logged
[task 2019-11-26T22:43:31.686Z] 22:43:31 INFO - TEST-UNEXPECTED-FAIL | toolkit/content/tests/browser/browser_delay_autoplay_media_pausedAfterPlay.js | Found a tab after previous test timed out: https://example.com/browser/toolkit/content/tests/browser/file_blockMedia_shouldNotPlay.html -
[task 2019-11-26T22:43:31.686Z] 22:43:31 INFO - checking window state
[task 2019-11-26T22:43:31.686Z] 22:43:31 INFO - GECKO(2289) | JavaScript error: resource://gre/actors/AudioPlaybackParent.jsm, line 19: TypeError: browser is null
[task 2019-11-26T22:43:31.686Z] 22:43:31 INFO - GECKO(2289) | JavaScript error: , line 0: NS_ERROR_UNEXPECTED:

Alastor do you have any updates here? Are you still working on this?

Flags: needinfo?(alwu)
Whiteboard: [stockwell disabled] → [stockwell disabled(fission)][stockwell needswork]

There are 13 total failures in the last 7 days on mac platforms and debug and opt builds.

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

[task 2019-12-09T20:41:01.603Z] 20:41:01 INFO - GECKO(2009) | [Child 2017: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 2 (0x14aa2f000) [pid = 2017] [serial = 33] [outer = 0x0] [url = https://example.com/browser/toolkit/content/tests/browser/file_multipleAudio.html]
[task 2019-12-09T20:41:02.177Z] 20:41:02 INFO - GECKO(2009) | [Child 2048: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 0 (0x12862b400) [pid = 2048] [serial = 2] [outer = 0x0] [url = about:blank]
[task 2019-12-09T20:42:19.348Z] 20:42:19 INFO - TEST-INFO | started process screencapture
[task 2019-12-09T20:42:19.496Z] 20:42:19 INFO - TEST-INFO | screencapture: exit 0
[task 2019-12-09T20:42:19.499Z] 20:42:19 INFO - Buffered messages logged at 20:40:49
[task 2019-12-09T20:42:19.499Z] 20:42:19 INFO - Entering test bound setup_test_preference
[task 2019-12-09T20:42:19.499Z] 20:42:19 INFO - Leaving test bound setup_test_preference
[task 2019-12-09T20:42:19.499Z] 20:42:19 INFO - Entering test bound block_autoplay_media
[task 2019-12-09T20:42:19.499Z] 20:42:19 INFO - - open new background tab1, and tab1 should not be blocked -
[task 2019-12-09T20:42:19.499Z] 20:42:19 INFO - TEST-PASS | toolkit/content/tests/browser/browser_delay_autoplay_media_pausedAfterPlay.js | The tab should not be blocked -
[task 2019-12-09T20:42:19.499Z] 20:42:19 INFO - - open new background tab2, and tab2 should be blocked -
[task 2019-12-09T20:42:19.499Z] 20:42:19 INFO - Block state doens't match, wait for attributes changes.
[task 2019-12-09T20:42:19.499Z] 20:42:19 INFO - Buffered messages logged at 20:40:50
[task 2019-12-09T20:42:19.499Z] 20:42:19 INFO - Console message: [JavaScript Error: "AbortError: The fetching process for the media resource was aborted by the user agent at the user's request."]
[task 2019-12-09T20:42:19.499Z] 20:42:19 INFO - Buffered messages finished
[task 2019-12-09T20:42:19.499Z] 20:42:19 INFO - TEST-UNEXPECTED-FAIL | toolkit/content/tests/browser/browser_delay_autoplay_media_pausedAfterPlay.js | Test timed out -
[task 2019-12-09T20:42:19.499Z] 20:42:19 INFO - GECKO(2009) | MEMORY STAT | vsize 7675MB | residentFast 383MB | heapAllocated 129MB
[task 2019-12-09T20:42:19.499Z] 20:42:19 INFO - TEST-OK | toolkit/content/tests/browser/browser_delay_autoplay_media_pausedAfterPlay.js | took 90079ms
[task 2019-12-09T20:42:19.500Z] 20:42:19 INFO - Not taking screenshot here: see the one that was previously logged
[task 2019-12-09T20:42:19.500Z] 20:42:19 INFO - TEST-UNEXPECTED-FAIL | toolkit/content/tests/browser/browser_delay_autoplay_media_pausedAfterPlay.js | Found a tab after previous test timed out: https://example.com/browser/toolkit/content/tests/browser/file_blockMedia_shouldPlay.html -
[task 2019-12-09T20:42:19.500Z] 20:42:19 INFO - Not taking screenshot here: see the one that was previously logged
[task 2019-12-09T20:42:19.500Z] 20:42:19 INFO - TEST-UNEXPECTED-FAIL | toolkit/content/tests/browser/browser_delay_autoplay_media_pausedAfterPlay.js | Found a tab after previous test timed out: https://example.com/browser/toolkit/content/tests/browser/file_blockMedia_shouldNotPlay.html -
[task 2019-12-09T20:42:19.500Z] 20:42:19 INFO - GECKO(2009) | [Child 2019: Main Thread]: I/DocShellAndDOMWindowLeak ++DOCSHELL 0x10d23b800 == 1 [pid = 2019] [id = {782e7351-ea75-c84b-829d-162f8beee0c4}]
[task 2019-12-09T20:42:19.500Z] 20:42:19 INFO - GECKO(2009) | [Child 2019: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 1 (0x114f5f020) [pid = 2019] [serial = 6] [outer = 0x0]
[task 2019-12-09T20:42:19.500Z] 20:42:19 INFO - GECKO(2009) | [Child 2019, Main Thread] WARNING: NS_ENSURE_TRUE(mPresShell) failed: file /builds/worker/workspace/build/src/layout/base/nsPresContext.cpp, line 847
[task 2019-12-09T20:42:19.501Z] 20:42:19 INFO - GECKO(2009) | [Child 2019: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 2 (0x10f344800) [pid = 2019] [serial = 7] [outer = 0x114f5f020]
[task 2019-12-09T20:42:19.501Z] 20:42:19 INFO - GECKO(2009) | [Child 2019: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 3 (0x10f34a800) [pid = 2019] [serial = 8] [outer = 0x114f5f020]
[task 2019-12-09T20:42:19.501Z] 20:42:19 INFO - checking window state
[task 2019-12-09T20:42:19.502Z] 20:42:19 INFO - GECKO(2009) | JavaScript error: resource://gre/actors/AudioPlaybackParent.jsm, line 19: TypeError: browser is null
[task 2019-12-09T20:42:19.502Z] 20:42:19 INFO - GECKO(2009) | [Parent 2009, Main Thread] WARNING: 'error.Failed()', file /builds/worker/workspace/build/src/dom/ipc/JSWindowActor.cpp, line 250
[task 2019-12-09T20:42:19.502Z] 20:42:19 INFO - GECKO(2009) | JavaScript error: , line 0: NS_ERROR_UNEXPECTED:

Nils can you assign someone to take a look?

Flags: needinfo?(drno)

Sorry, I was working on other stuffs recently, will go back to check this again later.

Assignee: nobody → alwu
Flags: needinfo?(drno)

Thank you.

Hi Alastor, are there updates here?

There are 29 total failures in the last 7 days on linux64, linux64-shippable, macosx debug and macosx-shippable opt

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

[task 2019-12-22T10:50:02.708Z] 10:50:02 INFO - TEST-START | toolkit/content/tests/browser/browser_delay_autoplay_media_pausedAfterPlay.js
[task 2019-12-22T10:50:03.118Z] 10:50:03 INFO - GECKO(12204) | JavaScript error: , line 0: AbortError: The fetching process for the media resource was aborted by the user agent at the user's request.
[task 2019-12-22T10:50:47.720Z] 10:50:47 INFO - TEST-INFO | started process screentopng
[task 2019-12-22T10:50:48.042Z] 10:50:48 INFO - TEST-INFO | screentopng: exit 0
[task 2019-12-22T10:50:48.043Z] 10:50:48 INFO - Buffered messages logged at 10:50:02
[task 2019-12-22T10:50:48.043Z] 10:50:48 INFO - Entering test bound setup_test_preference
[task 2019-12-22T10:50:48.044Z] 10:50:48 INFO - Leaving test bound setup_test_preference
[task 2019-12-22T10:50:48.045Z] 10:50:48 INFO - Entering test bound block_autoplay_media
[task 2019-12-22T10:50:48.046Z] 10:50:48 INFO - - open new background tab1, and tab1 should not be blocked -
[task 2019-12-22T10:50:48.046Z] 10:50:48 INFO - Buffered messages logged at 10:50:03
[task 2019-12-22T10:50:48.046Z] 10:50:48 INFO - TEST-PASS | toolkit/content/tests/browser/browser_delay_autoplay_media_pausedAfterPlay.js | The tab should not be blocked -
[task 2019-12-22T10:50:48.047Z] 10:50:48 INFO - - open new background tab2, and tab2 should be blocked -
[task 2019-12-22T10:50:48.047Z] 10:50:48 INFO - Block state doens't match, wait for attributes changes.
[task 2019-12-22T10:50:48.048Z] 10:50:48 INFO - Console message: [JavaScript Error: "AbortError: The fetching process for the media resource was aborted by the user agent at the user's request."]
[task 2019-12-22T10:50:48.048Z] 10:50:48 INFO - Buffered messages finished
[task 2019-12-22T10:50:48.049Z] 10:50:48 INFO - TEST-UNEXPECTED-FAIL | toolkit/content/tests/browser/browser_delay_autoplay_media_pausedAfterPlay.js | Test timed out -
[task 2019-12-22T10:50:48.049Z] 10:50:48 INFO - GECKO(12204) | MEMORY STAT | vsize 3280MB | residentFast 319MB | heapAllocated 112MB
[task 2019-12-22T10:50:48.050Z] 10:50:48 INFO - TEST-OK | toolkit/content/tests/browser/browser_delay_autoplay_media_pausedAfterPlay.js | took 45012ms
[task 2019-12-22T10:50:48.050Z] 10:50:48 INFO - Not taking screenshot here: see the one that was previously logged
[task 2019-12-22T10:50:48.051Z] 10:50:48 INFO - TEST-UNEXPECTED-FAIL | toolkit/content/tests/browser/browser_delay_autoplay_media_pausedAfterPlay.js | Found a tab after previous test timed out: https://example.com/browser/toolkit/content/tests/browser/file_blockMedia_shouldPlay.html -
[task 2019-12-22T10:50:48.051Z] 10:50:48 INFO - Not taking screenshot here: see the one that was previously logged
[task 2019-12-22T10:50:48.052Z] 10:50:48 INFO - TEST-UNEXPECTED-FAIL | toolkit/content/tests/browser/browser_delay_autoplay_media_pausedAfterPlay.js | Found a tab after previous test timed out: https://example.com/browser/toolkit/content/tests/browser/file_blockMedia_shouldNotPlay.html -
[task 2019-12-22T10:50:48.053Z] 10:50:48 INFO - checking window state
[task 2019-12-22T10:50:48.053Z] 10:50:48 INFO - GECKO(12204) | JavaScript error: resource://gre/actors/AudioPlaybackParent.jsm, line 19: TypeError: browser is null
[task 2019-12-22T10:50:48.054Z] 10:50:48 INFO - GECKO(12204) | JavaScript error: , line 0: NS_ERROR_UNEXPECTED:

Whiteboard: [stockwell disabled(fission)][stockwell needswork] → [stockwell disabled(fission)][stockwell needswork:owner]

We remove file_blockMedia_shouldPlay.html and file_blockMedia_shouldNotPlay.html and do those operations in test directly, and make sure doing so after media fully loading.

Attachment #9117830 - Attachment description: Bug 1585231 - operate media element after it fully loads → Bug 1585231 - refactor test.
Flags: needinfo?(alwu)
Whiteboard: [stockwell disabled(fission)][stockwell needswork:owner] → [stockwell disabled][stockwell needswork:owner]

If next week we still can't see any new failure, then I will close this bug. Add NI as a reminder.

Flags: needinfo?(alwu)
Status: NEW → RESOLVED
Closed: 3 months ago
Flags: needinfo?(alwu)
Resolution: --- → WORKSFORME
Status: RESOLVED → REOPENED
Resolution: WORKSFORME → ---

This failure is not as same as what we got before, from the log, it seems audio decoding failed which cause the fail.

audio.ogg could not be decoded, error: Error Code: NS_ERROR_DOM_MEDIA_MEDIASINK_ERR (0x806e000b)

Regressions: 1628200
You need to log in before you can comment on or make changes to this bug.