Intermittent toolkit/content/tests/browser/browser_delay_autoplay_multipleMedia.js | Test timed out -
Categories
(Core :: Audio/Video: Playback, defect, P5)
Tracking
()
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
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Updated•5 years ago
|
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment 15•4 years ago
|
||
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:
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment 32•4 years ago
|
||
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?
Alastor, is this something you could take a look at?
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Updated•4 years ago
|
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment 53•4 years ago
|
||
https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.
Comment hidden (Intermittent Failures Robot) |
Comment 55•4 years ago
|
||
New occurrence:
https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=317680321&repo=mozilla-central&lineNumber=4870
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment 72•3 years ago
|
||
https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.
Comment 73•3 years ago
|
||
Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=336419663&repo=mozilla-central&lineNumber=9085
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment 92•3 years ago
|
||
There are 41 total failures in the last 7 days on
- linux1804-64-asan-qr opt
- linux1804-64-qr opt and debug
- macosx1100-64-shippable-qr opt
Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=352664069&repo=autoland&lineNumber=65967
[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?
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment 95•3 years ago
|
||
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.
Comment 96•3 years ago
|
||
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.
Assignee | ||
Comment 97•3 years ago
|
||
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.
Comment 98•3 years ago
|
||
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!
Comment 99•3 years ago
|
||
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.
Comment 100•3 years ago
|
||
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.
Comment 101•3 years ago
|
||
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()
.
Assignee | ||
Comment 102•3 years ago
|
||
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?
Comment 103•3 years ago
|
||
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.
Comment hidden (Intermittent Failures Robot) |
Comment 105•3 years ago
|
||
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.
Assignee | ||
Comment 106•3 years ago
|
||
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.
Assignee | ||
Comment 107•3 years ago
|
||
The tab switcher seems confused, sometimes?
However this seems a better approach regardless.
Comment 108•3 years ago
|
||
Pushed by emilio@crisal.io: https://hg.mozilla.org/integration/autoland/rev/a456dfbc4abd Ensure we don't change activeness when remoteness changes. r=mconley!
Comment 109•3 years ago
|
||
Pushed by emilio@crisal.io: https://hg.mozilla.org/integration/autoland/rev/840fbb5adaa1 Revert patch that landed accidentally.
Assignee | ||
Comment 110•3 years ago
|
||
Comment 112•3 years ago
|
||
bugherder |
https://hg.mozilla.org/mozilla-central/rev/a456dfbc4abd
https://hg.mozilla.org/mozilla-central/rev/840fbb5adaa1
Comment 113•3 years ago
|
||
Leaving needinfo - will look at this tomorrow.
Comment 114•3 years ago
|
||
Still appearing: https://treeherder.mozilla.org/logviewer?job_id=354585302&repo=autoland&lineNumber=12131
Comment 115•3 years ago
|
||
(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.
Comment 116•3 years ago
|
||
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.
Comment 117•3 years ago
|
||
Here is the one, and I'm still running the pernosco to capture the new trace.
Comment 118•3 years ago
|
||
Here is the new trace from the failure above, the tab still became visible incorrectly.
Comment 119•3 years ago
|
||
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.
Comment 120•3 years ago
|
||
Pushed by ealvarez@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/077d32687ef8 Ensure we don't change activeness when remoteness changes. r=mconley
Comment 121•3 years ago
|
||
bugherder |
Comment 122•3 years ago
|
||
Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=354939562&repo=autoland&lineNumber=8153
Assignee | ||
Comment 124•3 years ago
|
||
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?
Comment hidden (Intermittent Failures Robot) |
Comment 126•3 years ago
|
||
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).
Assignee | ||
Comment 127•3 years ago
|
||
That doesn't seem to have debug info? Or at least I can't print / watch members from the gdb terminal...
Comment 128•3 years ago
|
||
yep me too, I am not sure why. I will try to see if I can get another trace from pernosco.
Comment 129•3 years ago
•
|
||
There are 28 total failures in the last 7 days on
- linux1804-64-asan-qr opt
- linux1804-64-qr opt and debug
Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=355843047&repo=autoland&lineNumber=25663
[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
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment 132•3 years ago
|
||
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.
Assignee | ||
Updated•3 years ago
|
Assignee | ||
Comment 133•3 years ago
|
||
We apparently have this code copy-pasted in two places? :(
Comment 134•3 years ago
|
||
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
Comment 135•3 years ago
|
||
bugherder |
Comment hidden (Intermittent Failures Robot) |
Updated•3 years ago
|
Description
•