Closed Bug 1584678 Opened 5 years ago Closed 3 years ago

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

Categories

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

defect

Tracking

()

RESOLVED FIXED
96 Branch
Tracking Status
firefox-esr91 --- wontfix
firefox93 --- wontfix
firefox94 --- wontfix
firefox95 --- wontfix
firefox96 --- fixed

People

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

References

Details

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

Attachments

(3 files)

Filed by: malexandru [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=268872038&repo=autoland
Full log: https://queue.taskcluster.net/v1/task/eS1QYVt_T3-qRPLEWtGWsg/runs/0/artifacts/public/logs/live_backing.log


[task 2019-09-27T23:48:23.369Z] 23:48:23 INFO - TEST-START | toolkit/content/tests/browser/browser_delay_autoplay_multipleMedia.js
[task 2019-09-27T23:48:23.427Z] 23:48:23 INFO - GECKO(2140) | --DOCSHELL 0x11176b800 == 2 [pid = 2144] [id = {b14616d5-a9af-e348-8910-e390f603f7c5}] [url = about:blank]
[task 2019-09-27T23:48:23.427Z] 23:48:23 INFO - GECKO(2140) | ++DOCSHELL 0x15085c800 == 4 [pid = 2148] [id = {9fbf8a76-af4c-f34b-a90c-af78e8ef8a52}]
[task 2019-09-27T23:48:23.427Z] 23:48:23 INFO - GECKO(2140) | ++DOMWINDOW == 27 (0x10fed1980) [pid = 2148] [serial = 37] [outer = 0x0]
[task 2019-09-27T23:48:23.427Z] 23:48:23 INFO - GECKO(2140) | ++DOMWINDOW == 28 (0x150bc3c00) [pid = 2148] [serial = 38] [outer = 0x10fed1980]
[task 2019-09-27T23:48:23.454Z] 23:48:23 INFO - GECKO(2140) | ++DOMWINDOW == 29 (0x150bcd800) [pid = 2148] [serial = 39] [outer = 0x10fed1980]
[task 2019-09-27T23:48:23.562Z] 23:48:23 INFO - GECKO(2140) | ++DOMWINDOW == 30 (0x151051800) [pid = 2148] [serial = 40] [outer = 0x10fed1980]
[task 2019-09-27T23:48:23.926Z] 23:48:23 INFO - GECKO(2140) | --DOMWINDOW == 13 (0x1485947a0) [pid = 2144] [serial = 167] [outer = 0x0] [url = about:blank]
[task 2019-09-27T23:48:23.926Z] 23:48:23 INFO - GECKO(2140) | --DOMWINDOW == 12 (0x11d741e20) [pid = 2144] [serial = 164] [outer = 0x0] [url = data:text/html, <input type="date" value="0001-01-01">]
[task 2019-09-27T23:48:23.926Z] 23:48:23 INFO - GECKO(2140) | --DOMWINDOW == 11 (0x11d7403e0) [pid = 2144] [serial = 161] [outer = 0x0] [url = data:text/html, <input type="date" value="2016-12-15" min="2016-12-05" max="2016-12-25">]
[task 2019-09-27T23:48:24.724Z] 23:48:24 INFO - GECKO(2140) | --DOCSHELL 0x10a63f800 == 0 [pid = 2150] [id = {b5098e89-62ba-984a-9e30-81feb5bce2f0}] [url = about:blank]
[task 2019-09-27T23:48:25.102Z] 23:48:25 INFO - GECKO(2140) | --DOMWINDOW == 29 (0x14bf20000) [pid = 2148] [serial = 5] [outer = 0x0] [url = data:text/html, <input type="date" value="2016-12-15">]
[task 2019-09-27T23:48:25.102Z] 23:48:25 INFO - GECKO(2140) | --DOMWINDOW == 28 (0x15037b000) [pid = 2148] [serial = 14] [outer = 0x0] [url = data:text/html, <input type="date" value="2016-12-15" step="5">]
[task 2019-09-27T23:48:25.102Z] 23:48:25 INFO - GECKO(2140) | --DOMWINDOW == 27 (0x14f4ee400) [pid = 2148] [serial = 11] [outer = 0x0] [url = data:text/html, <input type="date" value="2016-12-15">]
<...>
[task 2019-09-27T23:49:53.686Z] 23:49:53 INFO - TEST-INFO | screencapture: exit 0
[task 2019-09-27T23:49:53.686Z] 23:49:53 INFO - Buffered messages logged at 23:48:23
[task 2019-09-27T23:49:53.687Z] 23:49:53 INFO - Entering test bound setup_test_preference
[task 2019-09-27T23:49:53.687Z] 23:49:53 INFO - Leaving test bound setup_test_preference
[task 2019-09-27T23:49:53.687Z] 23:49:53 INFO - Entering test bound block_multiple_media
[task 2019-09-27T23:49:53.687Z] 23:49:53 INFO - - open new background tab -
[task 2019-09-27T23:49:53.687Z] 23:49:53 INFO - - tab should be blocked -
[task 2019-09-27T23:49:53.687Z] 23:49:53 INFO - Block state doens't match, wait for attributes changes.
[task 2019-09-27T23:49:53.687Z] 23:49:53 INFO - Buffered messages finished
[task 2019-09-27T23:49:53.687Z] 23:49:53 INFO - TEST-UNEXPECTED-FAIL | toolkit/content/tests/browser/browser_delay_autoplay_multipleMedia.js | Test timed out -
[task 2019-09-27T23:49:53.688Z] 23:49:53 INFO - GECKO(2140) | MEMORY STAT | vsize 7700MB | residentFast 412MB | heapAllocated 106MB
[task 2019-09-27T23:49:53.688Z] 23:49:53 INFO - TEST-OK | toolkit/content/tests/browser/browser_delay_autoplay_multipleMedia.js | took 90163ms
[task 2019-09-27T23:49:53.688Z] 23:49:53 INFO - Not taking screenshot here: see the one that was previously logged
[task 2019-09-27T23:49:53.688Z] 23:49:53 INFO - TEST-UNEXPECTED-FAIL | toolkit/content/tests/browser/browser_delay_autoplay_multipleMedia.js | Found a tab after previous test timed out: https://example.com/browser/toolkit/content/tests/browser/file_multipleAudio.html -
[task 2019-09-27T23:49:53.688Z] 23:49:53 INFO - GECKO(2140) | ++DOCSHELL 0x10f83c800 == 1 [pid = 2149] [id = {2913e6ca-2a1e-6545-bb4f-7865b9b0c0e9}]
[task 2019-09-27T23:49:53.688Z] 23:49:53 INFO - GECKO(2140) | ++DOMWINDOW == 1 (0x127e41020) [pid = 2149] [serial = 13] [outer = 0x0]
[task 2019-09-27T23:49:53.688Z] 23:49:53 INFO - GECKO(2140) | ++DOMWINDOW == 2 (0x11021d000) [pid = 2149] [serial = 14] [outer = 0x127e41020]
[task 2019-09-27T23:49:53.688Z] 23:49:53 INFO - GECKO(2140) | ++DOMWINDOW == 3 (0x112239800) [pid = 2149] [serial = 15] [outer = 0x127e41020]
[task 2019-09-27T23:49:53.688Z] 23:49:53 INFO - checking window state
[task 2019-09-27T23:49:53.689Z] 23:49:53 INFO - GECKO(2140) | JavaScript error: resource://gre/actors/AudioPlaybackParent.jsm, line 19: TypeError: browser is null
[task 2019-09-27T23:49:53.689Z] 23:49:53 INFO - GECKO(2140) | [Parent 2140, Main Thread] WARNING: 'error.Failed()', file /builds/worker/workspace/build/src/dom/ipc/JSWindowActor.cpp, line 198
[task 2019-09-27T23:49:53.689Z] 23:49:53 INFO - GECKO(2140) | JavaScript error: , line 0: NS_ERROR_UNEXPECTED:
[task 2019-09-27T23:49:53.718Z] 23:49:53 INFO - TEST-START | toolkit/content/tests/browser/browser_delay_autoplay_notInTreeAudio.js

Component: General → Audio/Video: Playback
Product: Toolkit → Core
See Also: → 1585836
See Also: → 1585231

In the last 7 days there have been 27 occurrences, most on linux 64 debug.

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

[task 2019-12-12T19:32:45.275Z] 19:32:45 INFO - TEST-START | toolkit/content/tests/browser/browser_delay_autoplay_multipleMedia.js
[task 2019-12-12T19:32:45.282Z] 19:32:45 INFO - GECKO(9611) | [Child 11379: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 0x7f3d94cd3000 == 0 [pid = 11379] [id = {5b75bf4d-a062-4024-8dd5-b2e54cbd49f1}] [url = https://example.com/browser/toolkit/content/tests/browser/file_multipleAudio.html]
[task 2019-12-12T19:32:45.318Z] 19:32:45 INFO - GECKO(9611) | [Child 11379, Main Thread] WARNING: Wrong inner/outer window combination!: file /builds/worker/workspace/build/src/dom/base/Document.cpp, line 6818
[task 2019-12-12T19:32:45.319Z] 19:32:45 INFO - GECKO(9611) | [Child 11379, Main Thread] WARNING: Wrong inner/outer window combination!: file /builds/worker/workspace/build/src/dom/base/Document.cpp, line 6818
[task 2019-12-12T19:32:45.320Z] 19:32:45 INFO - GECKO(9611) | [Child 11379, Main Thread] WARNING: Wrong inner/outer window combination!: file /builds/worker/workspace/build/src/dom/base/Document.cpp, line 6818
[task 2019-12-12T19:32:45.320Z] 19:32:45 INFO - GECKO(9611) | [Child 11379, Main Thread] WARNING: Wrong inner/outer window combination!: file /builds/worker/workspace/build/src/dom/base/Document.cpp, line 6818
[task 2019-12-12T19:32:45.342Z] 19:32:45 INFO - GECKO(9611) | [Child 11379: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 3 (0x7f3d95bf4f20) [pid = 11379] [serial = 1] [outer = (nil)] [url = https://example.com/browser/toolkit/content/tests/browser/file_multipleAudio.html]
[task 2019-12-12T19:32:45.346Z] 19:32:45 INFO - GECKO(9611) | [Child 11379: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 2 (0x7f3d9486f400) [pid = 11379] [serial = 2] [outer = (nil)] [url = about:blank]
[task 2019-12-12T19:32:45.347Z] 19:32:45 INFO - GECKO(9611) | [Child 11379: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 1 (0x7f3d95b94800) [pid = 11379] [serial = 4] [outer = (nil)] [url = https://example.com/browser/toolkit/content/tests/browser/file_multipleAudio.html]
[task 2019-12-12T19:32:45.348Z] 19:32:45 INFO - GECKO(9611) | [Child 11379: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 0 (0x7f3d9487a000) [pid = 11379] [serial = 3] [outer = (nil)] [url = https://example.com/browser/toolkit/content/tests/browser/file_multipleAudio.html]
[task 2019-12-12T19:32:45.364Z] 19:32:45 INFO - GECKO(9611) | [Child 9743: Main Thread]: I/DocShellAndDOMWindowLeak ++DOCSHELL 0x7eff5c591000 == 2 [pid = 9743] [id = {673d0abb-8074-4d4c-b998-fd46a2b245b8}]
[task 2019-12-12T19:32:45.364Z] 19:32:45 INFO - GECKO(9611) | [Child 9743: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 6 (0x7eff5bf65d40) [pid = 9743] [serial = 74] [outer = (nil)]
[task 2019-12-12T19:32:45.364Z] 19:32:45 INFO - GECKO(9611) | [Child 9743: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 7 (0x7eff5bf6a400) [pid = 9743] [serial = 75] [outer = 0x7eff5bf65d40]
[task 2019-12-12T19:32:45.367Z] 19:32:45 INFO - GECKO(9611) | [Child 11379, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/workspace/build/src/xpcom/base/nsCycleCollector.cpp, line 3361
[task 2019-12-12T19:32:45.404Z] 19:32:45 INFO - GECKO(9611) | nsStringStats
[task 2019-12-12T19:32:45.404Z] 19:32:45 INFO - GECKO(9611) | => mAllocCount: 9154
[task 2019-12-12T19:32:45.404Z] 19:32:45 INFO - GECKO(9611) | => mReallocCount: 0
[task 2019-12-12T19:32:45.404Z] 19:32:45 INFO - GECKO(9611) | => mFreeCount: 9154
[task 2019-12-12T19:32:45.404Z] 19:32:45 INFO - GECKO(9611) | => mShareCount: 7378
[task 2019-12-12T19:32:45.404Z] 19:32:45 INFO - GECKO(9611) | => mAdoptCount: 358
[task 2019-12-12T19:32:45.404Z] 19:32:45 INFO - GECKO(9611) | => mAdoptFreeCount: 366
[task 2019-12-12T19:32:45.404Z] 19:32:45 INFO - GECKO(9611) | => Process ID: 11379, Thread ID: 139902926718784
[task 2019-12-12T19:32:45.432Z] 19:32:45 INFO - GECKO(9611) | [Child 9743: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 8 (0x7eff5bf73c00) [pid = 9743] [serial = 76] [outer = 0x7eff5bf65d40]
[task 2019-12-12T19:32:45.593Z] 19:32:45 INFO - GECKO(9611) | [11421, Unnamed thread 7fb64538d4c0] WARNING: XPCOM objects created/destroyed from static ctor/dtor: file /builds/worker/workspace/build/src/xpcom/base/nsTraceRefcnt.cpp, line 198
[task 2019-12-12T19:32:45.593Z] 19:32:45 INFO - GECKO(9611) | ### XPCOM_MEM_BLOAT_LOG defined -- logging bloat/leaks to /tmp/tmpuqSJ0z.mozrunner/runtests_leaks.log
[task 2019-12-12T19:32:45.594Z] 19:32:45 INFO - GECKO(9611) | [11421, Unnamed thread 7fb64538d4c0] WARNING: XPCOM objects created/destroyed from static ctor/dtor: file /builds/worker/workspace/build/src/xpcom/base/nsTraceRefcnt.cpp, line 198
[task 2019-12-12T19:32:45.615Z] 19:32:45 INFO - GECKO(9611) | [Child 11421, Main Thread] WARNING: No CID found when attempting to map contract ID: file /builds/worker/workspace/build/src/xpcom/components/nsComponentManager.cpp, line 727
[task 2019-12-12T19:32:45.756Z] 19:32:45 INFO - GECKO(9611) | Couldn't convert chrome URL: chrome://branding/locale/brand.properties
[task 2019-12-12T19:32:45.920Z] 19:32:45 INFO - GECKO(9611) | [Child 11421, Main Thread] WARNING: could not set real-time limit at process startup: file /builds/worker/workspace/build/src/dom/ipc/ContentChild.cpp, line 1819
[task 2019-12-12T19:32:45.927Z] 19:32:45 INFO - GECKO(9611) | [Child 11421: Main Thread]: I/DocShellAndDOMWindowLeak ++DOCSHELL 0x7fb62b1d2000 == 1 [pid = 11421] [id = {673d0abb-8074-4d4c-b998-fd46a2b245b8}]
[task 2019-12-12T19:32:46.003Z] 19:32:46 INFO - GECKO(9611) | [Child 11421: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 1 (0x7fb62c1e0f20) [pid = 11421] [serial = 1] [outer = (nil)]
[task 2019-12-12T19:32:46.004Z] 19:32:46 INFO - GECKO(9611) | [Child 11421, Main Thread] WARNING: NS_ENSURE_TRUE(mPresShell) failed: file /builds/worker/workspace/build/src/layout/base/nsPresContext.cpp, line 847
[task 2019-12-12T19:32:46.005Z] 19:32:46 INFO - GECKO(9611) | [Child 11421: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 2 (0x7fb62ad6f000) [pid = 11421] [serial = 2] [outer = 0x7fb62c1e0f20]
[task 2019-12-12T19:32:46.165Z] 19:32:46 INFO - GECKO(9611) | [Parent 9611, Main Thread] WARNING: we only accept nsIURI interface type, patch welcome: file /builds/worker/workspace/build/src/dom/ipc/PropertyBagUtils.cpp, line 112
[task 2019-12-12T19:32:46.166Z] 19:32:46 INFO - GECKO(9611) | [Child 11421, Main Thread] WARNING: Trying to request nsIHttpChannel from DocumentChannelChild, this is likely broken: file /builds/worker/workspace/build/src/netwerk/ipc/DocumentChannelChild.cpp, line 63
[task 2019-12-12T19:32:46.182Z] 19:32:46 INFO - GECKO(9611) | [Parent 9611, Main Thread] WARNING: Wrong button set to eContextMenu event?: 'mMessage != eContextMenu || mButton == ((mContextMenuTrigger == eNormal) ? MouseButton::eRight : MouseButton::eLeft)', file /builds/worker/workspace/build/src/obj-firefox/dist/include/mozilla/MouseEvents.h, line 246
[task 2019-12-12T19:32:46.186Z] 19:32:46 INFO - GECKO(9611) | [Child 11421: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 3 (0x7fb62ad7ac00) [pid = 11421] [serial = 3] [outer = 0x7fb62c1e0f20]
[task 2019-12-12T19:32:46.187Z] 19:32:46 INFO - GECKO(9611) | [Parent 9611: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 36 (0x7f1e30e92400) [pid = 9611] [serial = 32] [outer = (nil)] [url = about:tabcrashed?e=tabcrashed&u=https%3A//example.com/browser/toolkit/content/tests/browser/file_redirect_to.html&c=UTF-8&f=regular&d=redirected%21]
[task 2019-12-12T19:32:46.243Z] 19:32:46 INFO - GECKO(9611) | [Parent 9611: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 35 (0x7f1e2fcee800) [pid = 9611] [serial = 34] [outer = (nil)] [url = about:blank]
...
[task 2019-12-12T19:33:00.290Z] 19:33:00 INFO - GECKO(9611) | [Child 11421: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 2 (0x7fb62ad6f000) [pid = 11421] [serial = 2] [outer = (nil)] [url = about:blank]
[task 2019-12-12T19:34:15.286Z] 19:34:15 INFO - TEST-INFO | started process screentopng
[task 2019-12-12T19:34:15.952Z] 19:34:15 INFO - TEST-INFO | screentopng: exit 0
[task 2019-12-12T19:34:15.952Z] 19:34:15 INFO - Buffered messages logged at 19:32:45
[task 2019-12-12T19:34:15.952Z] 19:34:15 INFO - Entering test bound setup_test_preference
[task 2019-12-12T19:34:15.952Z] 19:34:15 INFO - Leaving test bound setup_test_preference
[task 2019-12-12T19:34:15.952Z] 19:34:15 INFO - Entering test bound block_multiple_media
[task 2019-12-12T19:34:15.952Z] 19:34:15 INFO - - open new background tab -
[task 2019-12-12T19:34:15.952Z] 19:34:15 INFO - - tab should be blocked -
[task 2019-12-12T19:34:15.956Z] 19:34:15 INFO - Block state doens't match, wait for attributes changes.
[task 2019-12-12T19:34:15.957Z] 19:34:15 INFO - Buffered messages finished
[task 2019-12-12T19:34:15.957Z] 19:34:15 INFO - TEST-UNEXPECTED-FAIL | toolkit/content/tests/browser/browser_delay_autoplay_multipleMedia.js | Test timed out -
[task 2019-12-12T19:34:15.958Z] 19:34:15 INFO - GECKO(9611) | MEMORY STAT | vsize 3333MB | residentFast 368MB | heapAllocated 122MB
[task 2019-12-12T19:34:15.959Z] 19:34:15 INFO - TEST-OK | toolkit/content/tests/browser/browser_delay_autoplay_multipleMedia.js | took 90037ms
[task 2019-12-12T19:34:15.959Z] 19:34:15 INFO - Not taking screenshot here: see the one that was previously logged
[task 2019-12-12T19:34:15.960Z] 19:34:15 INFO - TEST-UNEXPECTED-FAIL | toolkit/content/tests/browser/browser_delay_autoplay_multipleMedia.js | Found a tab after previous test timed out: https://example.com/browser/toolkit/content/tests/browser/file_multipleAudio.html -
[task 2019-12-12T19:34:15.960Z] 19:34:15 INFO - GECKO(9611) | [Child 9743: Main Thread]: I/DocShellAndDOMWindowLeak ++DOCSHELL 0x7eff5c58f000 == 1 [pid = 9743] [id = {b71ae258-7f94-44b6-a949-62aa57520b46}]
[task 2019-12-12T19:34:15.961Z] 19:34:15 INFO - GECKO(9611) | [Child 9743: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 1 (0x7eff5bf65200) [pid = 9743] [serial = 77] [outer = (nil)]
[task 2019-12-12T19:34:15.961Z] 19:34:15 INFO - GECKO(9611) | [Child 9743: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 2 (0x7eff5bf68400) [pid = 9743] [serial = 78] [outer = 0x7eff5bf65200]
[task 2019-12-12T19:34:15.962Z] 19:34:15 INFO - checking window state
[task 2019-12-12T19:34:15.963Z] 19:34:15 INFO - GECKO(9611) | JavaScript error: resource://gre/actors/AudioPlaybackParent.jsm, line 19: TypeError: browser is null
[task 2019-12-12T19:34:15.964Z] 19:34:15 INFO - GECKO(9611) | [Parent 9611, Main Thread] WARNING: 'error.Failed()', file /builds/worker/workspace/build/src/dom/ipc/JSWindowActor.cpp, line 250
[task 2019-12-12T19:34:15.965Z] 19:34:15 INFO - GECKO(9611) | JavaScript error: , line 0: NS_ERROR_UNEXPECTED:

There are 27 failures associated to this bug in the last 7 days. These are occurring on macosx1014-64-shippable opt.

recent log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=296309846&repo=autoland&lineNumber=6378
[task 2020-04-05T01:05:21.788Z] 01:05:21 INFO - TEST-START | toolkit/content/tests/browser/browser_delay_autoplay_multipleMedia.js
[task 2020-04-05T01:06:06.784Z] 01:06:06 INFO - TEST-INFO | started process screencapture
[task 2020-04-05T01:06:06.943Z] 01:06:06 INFO - TEST-INFO | screencapture: exit 0
[task 2020-04-05T01:06:06.943Z] 01:06:06 INFO - Buffered messages logged at 01:05:21
[task 2020-04-05T01:06:06.943Z] 01:06:06 INFO - Entering test bound setup_test_preference
[task 2020-04-05T01:06:06.944Z] 01:06:06 INFO - Leaving test bound setup_test_preference
[task 2020-04-05T01:06:06.944Z] 01:06:06 INFO - Entering test bound block_multiple_media
[task 2020-04-05T01:06:06.944Z] 01:06:06 INFO - - open new background tab -
[task 2020-04-05T01:06:06.944Z] 01:06:06 INFO - - tab should be blocked -
[task 2020-04-05T01:06:06.944Z] 01:06:06 INFO - Block state doens't match, wait for attributes changes.
[task 2020-04-05T01:06:06.947Z] 01:06:06 INFO - Buffered messages finished
[task 2020-04-05T01:06:06.947Z] 01:06:06 INFO - TEST-UNEXPECTED-FAIL | toolkit/content/tests/browser/browser_delay_autoplay_multipleMedia.js | Test timed out -
[task 2020-04-05T01:06:06.947Z] 01:06:06 INFO - GECKO(2941) | MEMORY STAT | vsize 7692MB | residentFast 377MB | heapAllocated 120MB
[task 2020-04-05T01:06:06.947Z] 01:06:06 INFO - TEST-OK | toolkit/content/tests/browser/browser_delay_autoplay_multipleMedia.js | took 45011ms
[task 2020-04-05T01:06:06.947Z] 01:06:06 INFO - Not taking screenshot here: see the one that was previously logged
[task 2020-04-05T01:06:06.947Z] 01:06:06 INFO - TEST-UNEXPECTED-FAIL | toolkit/content/tests/browser/browser_delay_autoplay_multipleMedia.js | Found a tab after previous test timed out: https://example.com/browser/toolkit/content/tests/browser/file_multipleAudio.html -
[task 2020-04-05T01:06:06.948Z] 01:06:06 INFO - checking window state
[task 2020-04-05T01:06:06.948Z] 01:06:06 INFO - GECKO(2941) | JavaScript error: resource://gre/actors/AudioPlaybackParent.jsm, line 19: TypeError: can't access property "audioPlaybackStopped", browser is null

:bryce can you take a look?

Flags: needinfo?(bvandyk)
Whiteboard: [retriggered] → [retriggered][stockwell needswork]

Alastor, is this something you could take a look at?

Flags: needinfo?(bvandyk) → needinfo?(alwu)
Assignee: nobody → alwu
Flags: needinfo?(alwu)
Status: NEW → RESOLVED
Closed: 4 years ago
Resolution: --- → INCOMPLETE
Status: REOPENED → RESOLVED
Closed: 4 years ago3 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---

There are 41 total failures in the last 7 days on

[task 2021-09-24T15:24:12.050Z] 15:24:12     INFO - TEST-START | toolkit/content/tests/browser/browser_delay_autoplay_multipleMedia.js
[task 2021-09-24T15:24:12.060Z] 15:24:12     INFO - GECKO(5786) | [Child 5792: Main Thread]: I/DocShellAndDOMWindowLeak ++DOCSHELL 11aaeb800 == 6 [pid = 5792] [id = 20]
[task 2021-09-24T15:24:12.061Z] 15:24:12     INFO - GECKO(5786) | [Child 5792: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 13 (111630040) [pid = 5792] [serial = 48] [outer = 0]
[task 2021-09-24T15:24:12.061Z] 15:24:12     INFO - GECKO(5786) | [Child 5792: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 14 (11aaec800) [pid = 5792] [serial = 49] [outer = 111630040]
[task 2021-09-24T15:24:12.062Z] 15:24:12     INFO - GECKO(5786) | [Child 5794: Main Thread]: I/DocShellAndDOMWindowLeak ++DOCSHELL 10ce1dc00 == 2 [pid = 5794] [id = 30]
[task 2021-09-24T15:24:12.062Z] 15:24:12     INFO - GECKO(5786) | [Child 5794: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 11 (1234433c0) [pid = 5794] [serial = 80] [outer = 0]
[task 2021-09-24T15:24:12.063Z] 15:24:12     INFO - GECKO(5786) | [Child 5794: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 12 (10ce1ec00) [pid = 5794] [serial = 81] [outer = 1234433c0]
[task 2021-09-24T15:24:12.071Z] 15:24:12     INFO - GECKO(5786) | [Child 5859: Main Thread]: I/DocShellAndDOMWindowLeak ++DOCSHELL 11f763c00 == 1 [pid = 5859] [id = 0]
[task 2021-09-24T15:24:12.072Z] 15:24:12     INFO - GECKO(5786) | [Child 5859: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 1 (108dc0e40) [pid = 5859] [serial = 1] [outer = 0]
[task 2021-09-24T15:24:12.073Z] 15:24:12     INFO - GECKO(5786) | [Child 5859: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 2 (10930b000) [pid = 5859] [serial = 2] [outer = 108dc0e40]
[task 2021-09-24T15:24:12.093Z] 15:24:12     INFO - GECKO(5786) | [Parent 5786, Main Thread] WARNING: WebProgress Ignored: no longer current window global: file /builds/worker/checkouts/gecko/dom/ipc/BrowserParent.cpp:2979
[task 2021-09-24T15:24:20.829Z] 15:24:20     INFO - GECKO(5786) | [Child 5792: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 5 (111315400) [pid = 5792] [serial = 39] [outer = 0] [url = about:blank]
[task 2021-09-24T15:24:20.829Z] 15:24:20     INFO - GECKO(5786) | [Child 5792: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 4 (11aaeb000) [pid = 5792] [serial = 45] [outer = 0] [url = about:blank]
[task 2021-09-24T15:24:20.831Z] 15:24:20     INFO - GECKO(5786) | [Child 5792: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 3 (11abca000) [pid = 5792] [serial = 40] [outer = 0] [url = data:audio/mpeg;base64,//tAxAAABvhjIgSxKQEFCi009CDgFQlHhw2YJxQXGTI1QVJ8WRkDAPBHKiG0yuPRcfEiOvayEXHyQnQLqJrMnjbEwTBMIN//8279Bv86QAAiCXbbgbotwRxCSFkvPxUgvmJ3iYWrqAoCs5buniYp/chXmj6wI6c0ILg/qAbENxV4RiApBAEHKD+U//1vkMWgAAAAXJJQ7CSK1lN3jhQIGtJsc/1mY13o/H2DFvCa0JLC4koaBRX/+0LEFAAIDElpp6TGwQaN7LWDFSAAAsKziRUMG0Cx+ZO03eBVJIS/r/6er/r1sAFAAAFtyCPInCApfqXtMafCH4l5Fws6rufUiy3yiYaLKcWLMKq9V7lbuMlIxZUkD72tRFvqJj3pNhu+h+j/fxSJIAAAA13i4R47FCkjw6iOeU4w7xSnggQI/gnyAAdDlwl1nf3n97uZvzrEglCsOSx+cz+bek4VOBxDVMr+xnuqyJApAAEpxtj/+0LEJAAIBG1lh5jJAQuLLfT2JOB+X+EE+bxPBYTSF7q9o1vZw7vGjRKI0Y9vCyA8lcPsdvfSq4nUmcFdATAwuoTD31EhITjEFy4gC79/662wGQAAm44x1TRwFXrpaMzgUkWiscPpglgQqnkQcIO1BsF4eYZhB9ImQfeQuAL18MtHMItQSYpptaRYHVK/17UUVJgAAABJyRiUWqCUx7PyXq4iDjYrwsbhUu6YgwjKohzhF2UAwNX/+0LEM4AIJENzrDzGwQeIbnT3mNgbYEDQBNsCYsfsOHaWAScIIROCc4OrKu5043XorYAAAACbcjGwHQyi9K43TKUqNLAaDqdkydra8PkT02zR1MqFidt+xldbdTutkmokxovBUiODVB0DChhYdFNFkm1P7EL5wgAAAJyS2BeANnooRJTfRqRLAEjxW02wzR3HuGxpXcX6TZNClIxQQqggFTwrOrvcHCCHsaLJKP72NBwRrYVe5///+]
[task 2021-09-24T15:24:20.832Z] 15:24:20     INFO - GECKO(5786) | [Child 5792: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 2 (11ad8d000) [pid = 5792] [serial = 43] [outer = 0] [url = data:audio/mpeg;base64,//tAxAAABvhjIgSxKQEFCi009CDgFQlHhw2YJxQXGTI1QVJ8WRkDAPBHKiG0yuPRcfEiOvayEXHyQnQLqJrMnjbEwTBMIN//8279Bv86QAAiCXbbgbotwRxCSFkvPxUgvmJ3iYWrqAoCs5buniYp/chXmj6wI6c0ILg/qAbENxV4RiApBAEHKD+U//1vkMWgAAAAXJJQ7CSK1lN3jhQIGtJsc/1mY13o/H2DFvCa0JLC4koaBRX/+0LEFAAIDElpp6TGwQaN7LWDFSAAAsKziRUMG0Cx+ZO03eBVJIS/r/6er/r1sAFAAAFtyCPInCApfqXtMafCH4l5Fws6rufUiy3yiYaLKcWLMKq9V7lbuMlIxZUkD72tRFvqJj3pNhu+h+j/fxSJIAAAA13i4R47FCkjw6iOeU4w7xSnggQI/gnyAAdDlwl1nf3n97uZvzrEglCsOSx+cz+bek4VOBxDVMr+xnuqyJApAAEpxtj/+0LEJAAIBG1lh5jJAQuLLfT2JOB+X+EE+bxPBYTSF7q9o1vZw7vGjRKI0Y9vCyA8lcPsdvfSq4nUmcFdATAwuoTD31EhITjEFy4gC79/662wGQAAm44x1TRwFXrpaMzgUkWiscPpglgQqnkQcIO1BsF4eYZhB9ImQfeQuAL18MtHMItQSYpptaRYHVK/17UUVJgAAABJyRiUWqCUx7PyXq4iDjYrwsbhUu6YgwjKohzhF2UAwNX/+0LEM4AIJENzrDzGwQeIbnT3mNgbYEDQBNsCYsfsOHaWAScIIROCc4OrKu5043XorYAAAACbcjGwHQyi9K43TKUqNLAaDqdkydra8PkT02zR1MqFidt+xldbdTutkmokxovBUiODVB0DChhYdFNFkm1P7EL5wgAAAJyS2BeANnooRJTfRqRLAEjxW02wzR3HuGxpXcX6TZNClIxQQqggFTwrOrvcHCCHsaLJKP72NBwRrYVe5///+]
[task 2021-09-24T15:24:24.819Z] 15:24:24     INFO - GECKO(5786) | [Child 5859: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 2 (10930b000) [pid = 5859] [serial = 2] [outer = 0] [url = about:blank]
[task 2021-09-24T15:25:42.071Z] 15:25:42     INFO - TEST-INFO | started process screencapture
[task 2021-09-24T15:25:42.191Z] 15:25:42     INFO - TEST-INFO | screencapture: exit 0
[task 2021-09-24T15:25:42.191Z] 15:25:42     INFO - Buffered messages logged at 15:24:12
[task 2021-09-24T15:25:42.191Z] 15:25:42     INFO - Entering test bound setup_test_preference
[task 2021-09-24T15:25:42.192Z] 15:25:42     INFO - Leaving test bound setup_test_preference
[task 2021-09-24T15:25:42.192Z] 15:25:42     INFO - Entering test bound block_multiple_media
[task 2021-09-24T15:25:42.193Z] 15:25:42     INFO - - open new background tab -
[task 2021-09-24T15:25:42.193Z] 15:25:42     INFO - - tab should be blocked -
[task 2021-09-24T15:25:42.194Z] 15:25:42     INFO - Block state doens't match, wait for attributes changes.
[task 2021-09-24T15:25:42.194Z] 15:25:42     INFO - Buffered messages finished
[task 2021-09-24T15:25:42.194Z] 15:25:42     INFO - TEST-UNEXPECTED-FAIL | toolkit/content/tests/browser/browser_delay_autoplay_multipleMedia.js | Test timed out - 
[task 2021-09-24T15:25:42.195Z] 15:25:42     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-09-24T15:25:42.196Z] 15:25:42     INFO - TEST-UNEXPECTED-FAIL | toolkit/content/tests/browser/browser_delay_autoplay_multipleMedia.js | Uncaught exception received from previously timed out test - TabAttrModified listener not removed before the end of test
[task 2021-09-24T15:25:42.196Z] 15:25:42     INFO - GECKO(5786) | MEMORY STAT | vsize 16293MB | residentFast 438MB | heapAllocated 132MB
[task 2021-09-24T15:25:42.196Z] 15:25:42     INFO - TEST-OK | toolkit/content/tests/browser/browser_delay_autoplay_multipleMedia.js | took 90030ms
[task 2021-09-24T15:25:42.197Z] 15:25:42     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-09-24T15:25:42.197Z] 15:25:42     INFO - TEST-UNEXPECTED-FAIL | toolkit/content/tests/browser/browser_delay_autoplay_multipleMedia.js | Found a tab after previous test timed out: https://example.com/browser/toolkit/content/tests/browser/file_multipleAudio.html - 
[task 2021-09-24T15:25:42.198Z] 15:25:42     INFO - GECKO(5786) | [Child 5794: Main Thread]: I/DocShellAndDOMWindowLeak ++DOCSHELL 10ca0b400 == 1 [pid = 5794] [id = 31]
[task 2021-09-24T15:25:42.198Z] 15:25:42     INFO - GECKO(5786) | [Child 5794: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 1 (10c8bfac0) [pid = 5794] [serial = 82] [outer = 0]
[task 2021-09-24T15:25:42.199Z] 15:25:42     INFO - GECKO(5786) | [Child 5794: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 2 (10ca16c00) [pid = 5794] [serial = 83] [outer = 10c8bfac0]
[task 2021-09-24T15:25:42.199Z] 15:25:42     INFO - checking window state
[task 2021-09-24T15:25:42.200Z] 15:25:42     INFO - GECKO(5786) | JavaScript error: resource://gre/actors/AudioPlaybackParent.jsm, line 24: TypeError: can't access property "audioPlaybackStopped", browser is null

Alastor, are there any updates here? Are you still working on this?

Flags: needinfo?(alwu)
Whiteboard: [retriggered][stockwell unknown] → [retriggered][stockwell needswork:owner]

We haven't modified this component for a while, not sure what happened. I just pushed a patch onto the try server, let's see if log shows anything suspious.

Flags: needinfo?(alwu)

From the log I captured from the try server,

nsPIDOMWindowOuter, MaybeActiveMediaComponents, resume the window from blocked, this = 7f0f0bc12440

This shows that the document has been resumed before starting playing media, so we would never receive block event for the tab. However, the tab should be in the background at that time, so it seems that the document's visibility got changed incorrectly.


Hi, Emilio,
Do you know if there is any recent change which could affect the document's visibility state? Do you have any thought about why document would become visible even if it's still a background tab?
Thank you so much.

Flags: needinfo?(emilio)

I'm not aware about any related change... Maybe bug 1727514, does it match the increase? With a pernosco trace this should be really easy to figure out.

Flags: needinfo?(emilio) → needinfo?(alwu)

I have tried to reproduce it on pernosco, but still no luck so far. I will keep trying to see if I can reproduce it on pernosoco. Thanks!

Flags: needinfo?(alwu)
Attached image pernosco.png

Here is the pernosco trace (I've shared it with the current view, but I don't know if you can see that. Because I know sometime even if I share the current view, other people still can't see the views which I set)

In case of the views doesn't get preserved, here is the screenshot for the views. After this Document::UpdateVisibilityState call, it triggered nsPIDOMWindowOuter::MaybeActiveMediaComponents and continues triggering following calls. (eg. nsPIDOMWindowOuter::RefreshMediaElementsSuspend) That was happening when the tab was still in the background.

Emilio,
Would you mind to help me check this again? I wonder if this is a race between setting the background attrbute and checking the visibility? (but from pernosco, it shows they were running in the same thread...) That Document::UpdateVisibilityState call was called in a runnable stack, which should be triggered by this.
Thank you so much.

Flags: needinfo?(emilio)

oh, wait, I see. I saw this nsGlobalWindowOuter::SetIsBackgroundInternal (this=0x7f15347f0420, aIsBackground=false) which explicitly changed the window to foreground, which seems wrong. And it was called from nsDocShell::ActivenessMaybeChanged().

And that comes because the browser front-end explicitly calls browser.docShellIsActive=true (here) as a result of the process switch:

0 set docShellIsActive(val = "true") ["chrome://global/content/elements/browser-custom-element.js":407:6]
    this = [object XULFrameElement]
1 didChange(didChangeEvent = "[object Event]") ["chrome://browser/content/tabbrowser.js":6020:42]
2 finishChangeRemoteness(redirectLoadSwitchId = "35") ["chrome://global/content/elements/browser-custom-element.js":1866:11]
    this = [object XULFrameElement]
3 getInterfaceProxy/get/<(args = "35") ["chrome://global/content/customElements.js":696:34]
    this = [object XULFrameElement]

Which just assigns the result of this function, which means the tab is probably actually in the foreground?

Flags: needinfo?(emilio)

If it is, then it's a bug. Because we only change it to foreground in near the end of the test. The situation I mentioned was happening before media started playing, which is around here.

From the pernosco you linked in comment102, there is a log message showing in stdout/stderr column "open new background tab" which is just above the place where this SetIsActivae happened. That shows the tab should be in background, not foreground.

Sorry to bother again, do you know who might be the right person to ask about this issue? Per my comment103, I'm pretty sure the tab should be in the background at that moment when it got incorrectly changed to "visible". Thank you.

Flags: needinfo?(emilio)

I guess I wrote this chunk of code, however it seems that the tab switcher is confused and thinks it should activate a tab when it really shouldn't. Mike, do you know how that could possibly happen?

We could try to work around it easily, patch incoming.

Flags: needinfo?(emilio) → needinfo?(mconley)

The tab switcher seems confused, sometimes?

However this seems a better approach regardless.

Pushed by emilio@crisal.io:
https://hg.mozilla.org/integration/autoland/rev/a456dfbc4abd
Ensure we don't change activeness when remoteness changes. r=mconley!
Pushed by emilio@crisal.io:
https://hg.mozilla.org/integration/autoland/rev/840fbb5adaa1
Revert patch that landed accidentally.

Thank for helping!

Assignee: alwu → emilio
Status: REOPENED → RESOLVED
Closed: 3 years ago3 years ago
Resolution: --- → FIXED
Target Milestone: --- → 95 Branch

Leaving needinfo - will look at this tomorrow.

Status: RESOLVED → REOPENED
Resolution: FIXED → ---
Target Milestone: 95 Branch → ---

(In reply to Emilio Cobos Álvarez (:emilio) from comment #106)

Mike, do you know how that could possibly happen?

In theory, the only way that the tab could be in a state such that shouldActivateDocShell(browser) returns true is that we had requested that it send its displaylist to the compositor. The only ways I think this can happen without switching the tab to the foreground is if the tab is being warmed up (because the mouse is hovering it), or it's a browser being used for print preview (which isn't happening in this case).

What I'd be interested in getting is a log from the AsyncTabSwitcher from this test failure to try to pin down what's happening. How easy is this failure to reproduce? If possible, could a try build be pushed that sets this flag to true?: https://searchfox.org/mozilla-central/rev/477950cf9ca9c9bb5ff6f34e0d0f6ca4718ea798/browser/modules/AsyncTabSwitcher.jsm#150

the log that it produces could help us understand how this background tab is being made active when it shouldn't.

Flags: needinfo?(mconley) → needinfo?(alwu)

I have pushed a patch to the try server and set that flag to true, but haven't been able to reproduce the issue yet. I will let you know when I reproduce it successfully. Keep NI.

Here is the one, and I'm still running the pernosco to capture the new trace.

Flags: needinfo?(alwu)

Here is the new trace from the failure above, the tab still became visible incorrectly.

Here's the relevant part of the test log:

[task 2021-10-14T18:14:08.996Z] 18:14:08     INFO - TEST-OK | toolkit/content/tests/browser/browser_delay_autoplay_media_pausedAfterPlay.js | took 1726ms
[task 2021-10-14T18:14:09.008Z] 18:14:09     INFO - GECKO(1537) | Initial tab is loaded?: true
[task 2021-10-14T18:14:09.009Z] 18:14:09     INFO - GECKO(1537) | ATS: 0:VRM(AR)(loaded) 1:(unloaded) cached: 0 {requestTab 1(about:blank)}
[task 2021-10-14T18:14:09.009Z] 18:14:09     INFO - GECKO(1537) | Loading tab 1(about:blank)
[task 2021-10-14T18:14:09.010Z] 18:14:09     INFO - GECKO(1537) | Switch to tab 2 - 1(about:blank)
[task 2021-10-14T18:14:09.012Z] 18:14:09     INFO - GECKO(1537) | DEBUG: tab switch time = 5
[task 2021-10-14T18:14:09.013Z] 18:14:09     INFO - GECKO(1537) | ATS: 0:M(AR)(loaded) 1:VLRBM(AR)(loading) cached: 0 [blank(01010),isRemote] {/queueUnload}
[task 2021-10-14T18:14:09.024Z] 18:14:09     INFO - checking window state
[task 2021-10-14T18:14:09.035Z] 18:14:09     INFO - TEST-START | toolkit/content/tests/browser/browser_delay_autoplay_multipleMedia.js
[task 2021-10-14T18:14:09.056Z] 18:14:09     INFO - GECKO(1537) | ATS: 0:VLRB(AR)(loading) 1:(unloaded) cached: 0 [onPaint(01),blank(01010),isRemote] {/MozAfterPaint}
[task 2021-10-14T18:14:09.066Z] 18:14:09     INFO - GECKO(1537) | ATS: 0:VLRB(AR)(loading) 1:(AR)(loading) cached: 0 {onRemotenessChange(1, true)}
[task 2021-10-14T18:14:09.067Z] 18:14:09     INFO - GECKO(1537) | ATS: 0:VLRB(AR)(loading) 1:(AR)(loading) cached: 0 [blank(01010),isRemote] {/TabRemotenessChange}
[task 2021-10-14T18:14:09.076Z] 18:14:09     INFO - GECKO(1537) | ATS: 0:VLRB(AR)(loading) 1:(AR)(loading) cached: 0 [onPaint(01),blank(01010),isRemote] {/MozAfterPaint}
[task 2021-10-14T18:14:09.078Z] 18:14:09     INFO - GECKO(1537) | ATS: unchanged{/MozAfterPaint}
[task 2021-10-14T18:14:09.133Z] 18:14:09     INFO - GECKO(1537) | ATS: 0:VLRB(AR)(loading) 1:(AR)(loading) cached: 0 {onLayersReady(0, true)}
[task 2021-10-14T18:14:09.135Z] 18:14:09     INFO - GECKO(1537) | ATS: 0:VR(AR)(loaded) 1:(AR)(loading) cached: 0 [nonblank(01011),isRemote] {/MozLayerTreeReady}
[task 2021-10-14T18:14:09.168Z] 18:14:09     INFO - GECKO(1537) | ATS: 0:VR(AR)(loaded) 1:(AR)(loading) cached: 0 [onPaint(01),nonblank(01011),isRemote] {/MozAfterPaint}
[task 2021-10-14T18:14:09.186Z] 18:14:09     INFO - GECKO(1537) | ATS: unchanged{/MozAfterPaint}
[task 2021-10-14T18:14:09.191Z] 18:14:09     INFO - GECKO(1537) | ATS: 0:VR(AR)(loaded) 1:(AR)(loading) cached: 0 {onLayersReady(1, true)}
[task 2021-10-14T18:14:09.195Z] 18:14:09     INFO - GECKO(1537) | ATS: 0:VR(AR)(loaded) 1:(AR)(loaded) cached: 0 [nonblank(01011),isRemote] {/MozLayerTreeReady}
[task 2021-10-14T18:14:09.229Z] 18:14:09     INFO - GECKO(1537) | ATS: 0:VR(AR)(loaded) 1:(AR)(loaded) cached: 0 [onPaint(01),nonblank(01011),isRemote] {/MozAfterPaint}
[task 2021-10-14T18:14:09.308Z] 18:14:09     INFO - GECKO(1537) | ATS: 0:VR(AR)(loaded) 1:(unloading) cached: 0 [nonblank(01011),isRemote] {/unloadTimeout}
[task 2021-10-14T18:14:09.361Z] 18:14:09     INFO - GECKO(1537) | ATS: 0:VR(AR)(loaded) 1:(unloading) cached: 0 {onLayersCleared(1)}
[task 2021-10-14T18:14:09.363Z] 18:14:09     INFO - GECKO(1537) | FINISH

I've been staring at this log for about 30 minutes, and I think I'm starting to see what's happening.

When the previous test ends, the test framework clears out all of the original tabs, and replaces the last remaining tab with a new blank one: https://searchfox.org/mozilla-central/rev/0ec81de2037cb0a0701d5d316f42763230b3a142/testing/mochitest/browser-test.js#417-424

We do an optimization for about:blank tabs, where we fill the content area with white and consider the tab switch "done" even though the AsyncTabSwitcher is still alive. That's, I think, what's happening here: in some cases during the test, the about:blank tab that the test harness puts in doesn't paint itself in time, so the AsyncTabSwitcher keeps itself alive waiting for that blank area to get sent to the compositor.

Then toolkit/content/tests/browser/browser_delay_autoplay_multipleMedia.js starts, and the first thing it does is tries to open an about:blank tab. This creates a new frameloader, which has its own BrowserParent, and critically, every BrowserParent starts its life with mRenderLayers set to true: https://searchfox.org/mozilla-central/rev/0ec81de2037cb0a0701d5d316f42763230b3a142/dom/ipc/BrowserParent.cpp#234

This puts this new frameloader in the STATE_LOADING state by default, and the AsyncTabSwitcher hasn't yet had the opportunity to tell it to unload, because the unloadTimer hasn't yet fired.

Then, when navigating that about:blank tab to file_multipleAudio.html, we do a process flip. This causes us to eventually get to here, which is where emilio's patch touches: https://searchfox.org/mozilla-central/rev/0ec81de2037cb0a0701d5d316f42763230b3a142/browser/base/content/tabbrowser.js#1941-1946

And because the switcher is still alive and waiting for that first about:blank to properly render, we get diverted and ask the switcher if we should activate the DocShell of the newly opened tab: https://searchfox.org/mozilla-central/rev/0ec81de2037cb0a0701d5d316f42763230b3a142/browser/base/content/tabbrowser.js#5126. Because the switcher sees that the newly opened tab is still loading, it goes "sure, why not"

In the "good" case, the AsyncTabSwitcher is not alive when we do the remoteness flip, so we normally fall through here: https://searchfox.org/mozilla-central/rev/0ec81de2037cb0a0701d5d316f42763230b3a142/browser/base/content/tabbrowser.js#5128-5133

So emilio's approach seems solid - we don't want to defer to the AsyncTabSwitcher in the remoteness flip case: the activation state should stay the same.

Pushed by ealvarez@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/077d32687ef8
Ensure we don't change activeness when remoteness changes. r=mconley
Status: REOPENED → RESOLVED
Closed: 3 years ago3 years ago
Resolution: --- → FIXED
Target Milestone: --- → 95 Branch
Status: RESOLVED → REOPENED
Resolution: FIXED → ---
Target Milestone: 95 Branch → ---

Emilio, please take a look.

Flags: needinfo?(emilio)

The bug observed previously on pernosco should've been fixed by comment 121. Alastor do you think you could try to get another pernosco recording in case there's some other lingering issue?

Flags: needinfo?(emilio) → needinfo?(alwu)

Here is the trace. I can see the document still changed its visibility and activated the whole page before media started, which can be found after "action":"log","time":1634350740890,"thread":null,"pid":null,"source":"mochitest","level":"INFO","message":"- open new background tab -","js_source":"TestRunner.js" (where we started a background tab).

Flags: needinfo?(alwu)

That doesn't seem to have debug info? Or at least I can't print / watch members from the gdb terminal...

yep me too, I am not sure why. I will try to see if I can get another trace from pernosco.

There are 28 total failures in the last 7 days on

[task 2021-10-23T15:51:09.274Z] 15:51:09     INFO - TEST-START | toolkit/content/tests/browser/browser_delay_autoplay_multipleMedia.js
[task 2021-10-23T15:51:09.306Z] 15:51:09     INFO - GECKO(13483) | [Child 13555: Main Thread]: I/DocShellAndDOMWindowLeak ++DOCSHELL 7f19569aa400 == 2 [pid = 13555] [id = 36]
[task 2021-10-23T15:51:09.307Z] 15:51:09     INFO - GECKO(13483) | [Child 13555: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 6 (7f1956c7e3c0) [pid = 13555] [serial = 91] [outer = 0]
[task 2021-10-23T15:51:09.308Z] 15:51:09     INFO - GECKO(13483) | [Child 13555: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 7 (7f19569aa800) [pid = 13555] [serial = 92] [outer = 7f1956c7e3c0]
[task 2021-10-23T15:51:09.337Z] 15:51:09     INFO - GECKO(13483) | [Child 14434, Main Thread] WARNING: IPC message discarded: actor cannot send: file /builds/worker/checkouts/gecko/ipc/glue/ProtocolUtils.cpp:531
[task 2021-10-23T15:51:09.338Z] 15:51:09     INFO - GECKO(13483) | [Child 14434, Main Thread] WARNING: IPC message discarded: actor cannot send: file /builds/worker/checkouts/gecko/ipc/glue/ProtocolUtils.cpp:531
[task 2021-10-23T15:51:09.345Z] 15:51:09     INFO - GECKO(13483) | [Child 14490: Main Thread]: I/DocShellAndDOMWindowLeak ++DOCSHELL 7fd3f59cdc00 == 1 [pid = 14490] [id = 0]
[task 2021-10-23T15:51:09.346Z] 15:51:09     INFO - GECKO(13483) | [Child 14490: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 1 (7fd40fa7c740) [pid = 14490] [serial = 1] [outer = 0]
[task 2021-10-23T15:51:09.347Z] 15:51:09     INFO - GECKO(13483) | [Child 14490: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 2 (7fd3f59ce000) [pid = 14490] [serial = 2] [outer = 7fd40fa7c740]
[task 2021-10-23T15:51:09.429Z] 15:51:09     INFO - GECKO(13483) | [Child 14434, Main Thread] WARNING: IPC message discarded: actor cannot send: file /builds/worker/checkouts/gecko/ipc/glue/ProtocolUtils.cpp:531
[task 2021-10-23T15:51:09.489Z] 15:51:09     INFO - GECKO(13483) | [Child 14434: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 7fb55abcec00 == 0 [pid = 14434] [id = 0] [url = https://example.com/browser/toolkit/content/tests/browser/file_nonAutoplayAudio.html]
[task 2021-10-23T15:51:09.577Z] 15:51:09     INFO - GECKO(13483) | [Parent 13483, Main Thread] WARNING: WebProgress Ignored: no longer current window global: file /builds/worker/checkouts/gecko/dom/ipc/BrowserParent.cpp:2983
[task 2021-10-23T15:51:09.579Z] 15:51:09     INFO - GECKO(13483) | [Parent 13483, Main Thread] WARNING: '!loadingContext->IsOwnedByProcess( GetContentProcessId(aContentParent))', file /builds/worker/checkouts/gecko/netwerk/ipc/DocumentLoadListener.cpp:562
[task 2021-10-23T15:51:09.581Z] 15:51:09     INFO - GECKO(13483) | [Parent 13483, Main Thread] WARNING: WebProgress Ignored: no longer current window global: file /builds/worker/checkouts/gecko/dom/ipc/BrowserParent.cpp:2983
[task 2021-10-23T15:51:09.582Z] 15:51:09     INFO - GECKO(13483) | [Parent 13483, Main Thread] WARNING: WebProgress Ignored: no longer current window global: file /builds/worker/checkouts/gecko/dom/ipc/BrowserParent.cpp:2983
[task 2021-10-23T15:51:09.587Z] 15:51:09     INFO - GECKO(13483) | [Child 14434, Main Thread] WARNING: IPC message discarded: actor cannot send: file /builds/worker/checkouts/gecko/ipc/glue/ProtocolUtils.cpp:531
[task 2021-10-23T15:51:09.620Z] 15:51:09     INFO - GECKO(13483) | [Child 14490, Main Thread] WARNING: NS_ENSURE_TRUE(info) failed: file /builds/worker/checkouts/gecko/extensions/permissions/PermissionDelegateHandler.cpp:348
[task 2021-10-23T15:51:09.620Z] 15:51:09     INFO - GECKO(13483) | [Child 14490, Main Thread] WARNING: NS_ENSURE_TRUE(info) failed: file /builds/worker/checkouts/gecko/extensions/permissions/PermissionDelegateHandler.cpp:348
[task 2021-10-23T15:51:09.624Z] 15:51:09     INFO - GECKO(13483) | [Child 14434, Main Thread] WARNING: IPC message discarded: actor cannot send: file /builds/worker/checkouts/gecko/ipc/glue/ProtocolUtils.cpp:531
[task 2021-10-23T15:51:09.631Z] 15:51:09     INFO - GECKO(13483) | [Child 14490: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 3 (7fd3f59d1000) [pid = 14490] [serial = 3] [outer = 7fd40fa7c740]
[task 2021-10-23T15:51:09.642Z] 15:51:09     INFO - GECKO(13483) | [Child 14434: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 2 (7fb574c7c580) [pid = 14434] [serial = 1] [outer = 0] [url = https://example.com/browser/toolkit/content/tests/browser/file_nonAutoplayAudio.html]
[task 2021-10-23T15:51:09.645Z] 15:51:09     INFO - GECKO(13483) | [Child 14434: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 1 (7fb55abcf000) [pid = 14434] [serial = 2] [outer = 0] [url = about:blank]
[task 2021-10-23T15:51:09.645Z] 15:51:09     INFO - GECKO(13483) | [Child 14434: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 0 (7fb55abd2000) [pid = 14434] [serial = 3] [outer = 0] [url = https://example.com/browser/toolkit/content/tests/browser/file_nonAutoplayAudio.html]
[task 2021-10-23T15:51:09.647Z] 15:51:09     INFO - GECKO(13483) | [Child 14434, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.cpp:3353
[task 2021-10-23T15:51:09.660Z] 15:51:09     INFO - GECKO(13483) | [Child 14434, Main Thread] WARNING: IPC message discarded: actor cannot send: file /builds/worker/checkouts/gecko/ipc/glue/ProtocolUtils.cpp:531
[task 2021-10-23T15:51:09.684Z] 15:51:09     INFO - GECKO(13483) | [Child 14434, Main Thread] WARNING: IPC message discarded: actor cannot send: file /builds/worker/checkouts/gecko/ipc/glue/ProtocolUtils.cpp:531
[task 2021-10-23T15:51:09.684Z] 15:51:09     INFO - GECKO(13483) | [Child 14434, Main Thread] WARNING: IPC message discarded: actor cannot send: file /builds/worker/checkouts/gecko/ipc/glue/ProtocolUtils.cpp:531
[task 2021-10-23T15:51:09.687Z] 15:51:09     INFO - GECKO(13483) | [Child 14434, Main Thread] WARNING: IPC message discarded: actor cannot send: file /builds/worker/checkouts/gecko/ipc/glue/ProtocolUtils.cpp:531
[task 2021-10-23T15:51:09.706Z] 15:51:09     INFO - GECKO(13483) | [Child 14434, Main Thread] WARNING: NS_ENSURE_TRUE(Preferences::InitStaticMembers()) failed: file /builds/worker/checkouts/gecko/modules/libpref/Preferences.cpp:4439
[task 2021-10-23T15:51:09.897Z] 15:51:09     INFO - GECKO(13483) | [2021-10-23T15:51:09Z WARN  audioipc_server::server] Promotion of content process thread to real-time error
[task 2021-10-23T15:51:10.367Z] 15:51:10     INFO - GECKO(13483) | [Child 13555: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 7f19569b5000 == 1 [pid = 13555] [id = 35] [url = about:blank]
[task 2021-10-23T15:51:10.369Z] 15:51:10     INFO - GECKO(13483) | [Child 13555: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 6 (7f19569ad000) [pid = 13555] [serial = 88] [outer = 0] [url = about:blank]
[task 2021-10-23T15:51:10.369Z] 15:51:10     INFO - GECKO(13483) | [Child 13555: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 5 (7f19569ab000) [pid = 13555] [serial = 87] [outer = 0] [url = about:blank]
[task 2021-10-23T15:51:10.372Z] 15:51:10     INFO - GECKO(13483) | [Child 13555: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 4 (7f1956c9dc00) [pid = 13555] [serial = 80] [outer = 0] [url = data:audio/mpeg;base64,//tAxAAABvhjIgSxKQEFCi009CDgFQlHhw2YJxQXGTI1QVJ8WRkDAPBHKiG0yuPRcfEiOvayEXHyQnQLqJrMnjbEwTBMIN//8279Bv86QAAiCXbbgbotwRxCSFkvPxUgvmJ3iYWrqAoCs5buniYp/chXmj6wI6c0ILg/qAbENxV4RiApBAEHKD+U//1vkMWgAAAAXJJQ7CSK1lN3jhQIGtJsc/1mY13o/H2DFvCa0JLC4koaBRX/+0LEFAAIDElpp6TGwQaN7LWDFSAAAsKziRUMG0Cx+ZO03eBVJIS/r/6er/r1sAFAAAFtyCPInCApfqXtMafCH4l5Fws6rufUiy3yiYaLKcWLMKq9V7lbuMlIxZUkD72tRFvqJj3pNhu+h+j/fxSJIAAAA13i4R47FCkjw6iOeU4w7xSnggQI/gnyAAdDlwl1nf3n97uZvzrEglCsOSx+cz+bek4VOBxDVMr+xnuqyJApAAEpxtj/+0LEJAAIBG1lh5jJAQuLLfT2JOB+X+EE+bxPBYTSF7q9o1vZw7vGjRKI0Y9vCyA8lcPsdvfSq4nUmcFdATAwuoTD31EhITjEFy4gC79/662wGQAAm44x1TRwFXrpaMzgUkWiscPpglgQqnkQcIO1BsF4eYZhB9ImQfeQuAL18MtHMItQSYpptaRYHVK/17UUVJgAAABJyRiUWqCUx7PyXq4iDjYrwsbhUu6YgwjKohzhF2UAwNX/+0LEM4AIJENzrDzGwQeIbnT3mNgbYEDQBNsCYsfsOHaWAScIIROCc4OrKu5043XorYAAAACbcjGwHQyi9K43TKUqNLAaDqdkydra8PkT02zR1MqFidt+xldbdTutkmokxovBUiODVB0DChhYdFNFkm1P7EL5wgAAAJyS2BeANnooRJTfRqRLAEjxW02wzR3HuGxpXcX6TZNClIxQQqggFTwrOrvcHCCHsaLJKP72NBwRrYVe5///+]
[task 2021-10-23T15:51:10.372Z] 15:51:10     INFO - GECKO(13483) | [Child 13555: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 7f19569aa400 == 0 [pid = 13555] [id = 36] [url = about:blank]
[task 2021-10-23T15:51:10.390Z] 15:51:10     INFO - GECKO(13483) | ### XPCOM_MEM_BLOAT_LOG defined -- logging bloat/leaks to /tmp/tmpudkry0zq.mozrunner/runtests_leaks_tab_pid14600.log
[task 2021-10-23T15:51:10.393Z] 15:51:10     INFO - GECKO(13483) | [14600, Main Thread] WARNING: XPCOM_MEM_BLOAT_LOG is set, disabling native allocations.: file /builds/worker/checkouts/gecko/tools/profiler/core/platform.cpp:251
[task 2021-10-23T15:51:10.423Z] 15:51:10     INFO - GECKO(13483) | [Child 14600, Main Thread] WARNING: could not set real-time limit in CubebUtils::InitLibrary: file /builds/worker/checkouts/gecko/dom/media/CubebUtils.cpp:639
[task 2021-10-23T15:51:10.430Z] 15:51:10     INFO - GECKO(13483) | [Child 13555: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 3 (7f1956c7e3c0) [pid = 13555] [serial = 91] [outer = 0] [url = about:blank]
[task 2021-10-23T15:51:10.431Z] 15:51:10     INFO - GECKO(13483) | [Child 13555: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 2 (7f1956c7e900) [pid = 13555] [serial = 89] [outer = 0] [url = about:blank]
[task 2021-10-23T15:51:10.743Z] 15:51:10     INFO - GECKO(13483) | [Child 13659: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 4 (7f395522e000) [pid = 13659] [serial = 85] [outer = 0] [url = data:image/gif;base64,R0lGODlhEAAOALMAAOazToeHh0tLS/7LZv/0jvb29t/f3//Ub//ge8WSLf/rhf/3kdbW1mxsbP//mf///yH5BAAAAAAALAAAAAAQAA4AAARe8L1Ekyky67QZ1hLnjM5UUde0ECwLJoExKcppV0aCcGCmTIHEIUEqjgaORCMxIC6e0CcguWw6aFjsVMkkIr7g77ZKPJjPZqIyd7sJAgVGoEGv2xsBxqNgYPj/gAwXEQA7]
[task 2021-10-23T15:51:11.312Z] 15:51:11     INFO - GECKO(13483) | [Child 13659: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 3 (7f395524c580) [pid = 13659] [serial = 86] [outer = 0] [url = about:blank]
[task 2021-10-23T15:51:12.614Z] 15:51:12     INFO - GECKO(13483) | [Parent 13483: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 22 (7f7df5853400) [pid = 13483] [serial = 52] [outer = 0] [url = chrome://global/content/datepicker.xhtml]
[task 2021-10-23T15:51:12.616Z] 15:51:12     INFO - GECKO(13483) | [Parent 13483: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 21 (7f7df3ae0000) [pid = 13483] [serial = 58] [outer = 0] [url = chrome://global/content/datepicker.xhtml]
[task 2021-10-23T15:51:12.617Z] 15:51:12     INFO - GECKO(13483) | [Parent 13483: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 20 (7f7df17e8400) [pid = 13483] [serial = 63] [outer = 0] [url = chrome://global/content/datepicker.xhtml]
[task 2021-10-23T15:51:12.620Z] 15:51:12     INFO - GECKO(13483) | [Parent 13483: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 19 (7f7df8c8f400) [pid = 13483] [serial = 79] [outer = 0] [url = chrome://global/content/datepicker.xhtml]
[task 2021-10-23T15:51:12.620Z] 15:51:12     INFO - GECKO(13483) | [Parent 13483: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 18 (7f7df87b0400) [pid = 13483] [serial = 67] [outer = 0] [url = chrome://global/content/datepicker.xhtml]
[task 2021-10-23T15:51:12.623Z] 15:51:12     INFO - GECKO(13483) | [Parent 13483: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 17 (7f7df06c7c00) [pid = 13483] [serial = 61] [outer = 0] [url = chrome://global/content/datepicker.xhtml]
[task 2021-10-23T15:51:12.623Z] 15:51:12     INFO - GECKO(13483) | [Parent 13483: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 16 (7f7ddbe51c00) [pid = 13483] [serial = 73] [outer = 0] [url = chrome://global/content/datepicker.xhtml]
[task 2021-10-23T15:51:12.623Z] 15:51:12     INFO - GECKO(13483) | [Parent 13483: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 15 (7f7ddbe45c00) [pid = 13483] [serial = 75] [outer = 0] [url = chrome://global/content/datepicker.xhtml]
[task 2021-10-23T15:51:12.623Z] 15:51:12     INFO - GECKO(13483) | [Parent 13483: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 14 (7f7df5a72c00) [pid = 13483] [serial = 54] [outer = 0] [url = chrome://global/content/datepicker.xhtml]
[task 2021-10-23T15:51:12.623Z] 15:51:12     INFO - GECKO(13483) | [Parent 13483: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 13 (7f7df584ec00) [pid = 13483] [serial = 65] [outer = 0] [url = chrome://global/content/datepicker.xhtml]
[task 2021-10-23T15:51:12.625Z] 15:51:12     INFO - GECKO(13483) | [Parent 13483: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 12 (7f7df17e2c00) [pid = 13483] [serial = 42] [outer = 0] [url = chrome://global/content/datepicker.xhtml]
[task 2021-10-23T15:51:12.626Z] 15:51:12     INFO - GECKO(13483) | [Parent 13483: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 11 (7f7df17e7c00) [pid = 13483] [serial = 69] [outer = 0] [url = chrome://global/content/datepicker.xhtml]
[task 2021-10-23T15:51:12.626Z] 15:51:12     INFO - GECKO(13483) | [Parent 13483: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 10 (7f7df54aa800) [pid = 13483] [serial = 50] [outer = 0] [url = chrome://global/content/datepicker.xhtml]
[task 2021-10-23T15:51:14.487Z] 15:51:14     INFO - GECKO(13483) | [Child 13555: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 1 (7f19569b5800) [pid = 13555] [serial = 90] [outer = 0] [url = about:blank]
[task 2021-10-23T15:51:14.487Z] 15:51:14     INFO - GECKO(13483) | [Child 13555: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 0 (7f19569aa800) [pid = 13555] [serial = 92] [outer = 0] [url = about:blank]
[task 2021-10-23T15:51:15.100Z] 15:51:15     INFO - GECKO(13483) | [Child 13659: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 2 (7f395522d000) [pid = 13659] [serial = 87] [outer = 0] [url = about:blank]
[task 2021-10-23T15:51:21.799Z] 15:51:21     INFO - GECKO(13483) | [Child 14490: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 2 (7fd3f59ce000) [pid = 14490] [serial = 2] [outer = 0] [url = about:blank]
[task 2021-10-23T15:52:39.289Z] 15:52:39     INFO - TEST-INFO | started process screentopng
[task 2021-10-23T15:52:39.630Z] 15:52:39     INFO - TEST-INFO | screentopng: exit 0
[task 2021-10-23T15:52:39.630Z] 15:52:39     INFO - Buffered messages logged at 15:51:09
[task 2021-10-23T15:52:39.630Z] 15:52:39     INFO - Entering test bound setup_test_preference
[task 2021-10-23T15:52:39.630Z] 15:52:39     INFO - Leaving test bound setup_test_preference
[task 2021-10-23T15:52:39.630Z] 15:52:39     INFO - Entering test bound block_multiple_media
[task 2021-10-23T15:52:39.630Z] 15:52:39     INFO - - open new background tab -
[task 2021-10-23T15:52:39.630Z] 15:52:39     INFO - - tab should be blocked -
[task 2021-10-23T15:52:39.630Z] 15:52:39     INFO - Block state doens't match, wait for attributes changes.
[task 2021-10-23T15:52:39.630Z] 15:52:39     INFO - Buffered messages finished
[task 2021-10-23T15:52:39.630Z] 15:52:39     INFO - TEST-UNEXPECTED-FAIL | toolkit/content/tests/browser/browser_delay_autoplay_multipleMedia.js | Test timed out - 
[task 2021-10-23T15:52:39.630Z] 15:52:39     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-10-23T15:52:39.630Z] 15:52:39     INFO - TEST-UNEXPECTED-FAIL | toolkit/content/tests/browser/browser_delay_autoplay_multipleMedia.js | Uncaught exception received from previously timed out test - TabAttrModified listener not removed before the end of test
[task 2021-10-23T15:52:39.630Z] 15:52:39     INFO - GECKO(13483) | MEMORY STAT | vsize 12050MB | residentFast 545MB | heapAllocated 263MB
[task 2021-10-23T15:52:39.635Z] 15:52:39     INFO - TEST-OK | toolkit/content/tests/browser/browser_delay_autoplay_multipleMedia.js | took 90032ms
[task 2021-10-23T15:52:39.635Z] 15:52:39     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-10-23T15:52:39.637Z] 15:52:39     INFO - TEST-UNEXPECTED-FAIL | toolkit/content/tests/browser/browser_delay_autoplay_multipleMedia.js | Found a tab after previous test timed out: https://example.com/browser/toolkit/content/tests/browser/file_multipleAudio.html - 
[task 2021-10-23T15:52:39.638Z] 15:52:39     INFO - GECKO(13483) | [Child 13555: Main Thread]: I/DocShellAndDOMWindowLeak ++DOCSHELL 7f19569aa400 == 1 [pid = 13555] [id = 37]
[task 2021-10-23T15:52:39.639Z] 15:52:39     INFO - GECKO(13483) | [Child 13555: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 1 (7f1956c7e3c0) [pid = 13555] [serial = 93] [outer = 0]
[task 2021-10-23T15:52:39.641Z] 15:52:39     INFO - GECKO(13483) | [Child 13555: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 2 (7f19569aa800) [pid = 13555] [serial = 94] [outer = 7f1956c7e3c0]
[task 2021-10-23T15:52:39.642Z] 15:52:39     INFO - checking window state
[task 2021-10-23T15:52:39.643Z] 15:52:39     INFO - GECKO(13483) | JavaScript error: resource://gre/actors/AudioPlaybackParent.jsm, line 24: TypeError: can't access property "audioPlaybackStopped", browser is null

Okay I finally got another pernosco trace (I tried to grap one before my PTO, but they all captured the wrong failure...) From the stacks, the backgorund document still changed to visible incorrectly. This trace is captured based on the failure happened on Nov 1.
Thank you.

Flags: needinfo?(emilio)
Flags: needinfo?(emilio)

We apparently have this code copy-pasted in two places? :(

Pushed by ealvarez@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/ab27c06e27cf
Ensure we don't change activeness when remoteness changes for real. r=mconley
Status: REOPENED → RESOLVED
Closed: 3 years ago3 years ago
Resolution: --- → FIXED
Target Milestone: --- → 96 Branch
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: