1709597 - Perma [tier 2] macOS shippable fission dom/media/test/browser/browser_tab_visibility_and_play_time.js | invisiblePlayTime/ totalPlayTime keeps unchanged - false == true - got false, expected true (operator ==)

Reporter

Description

•

3 years ago

treeherder

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

[task 2021-05-05T10:02:05.533Z] 10:02:05     INFO - TEST-START | dom/media/test/browser/browser_tab_visibility_and_play_time.js
[task 2021-05-05T10:02:05.533Z] 10:02:05     INFO - GECKO(10848) | Chrome file doesn't exist: Z:\task_1620208267\build\tests\mochitest\browser\dom\media\test\browser\head.js
[task 2021-05-05T10:02:05.542Z] 10:02:05     INFO - GECKO(10848) | [Child 11152: Main Thread]: I/DocShellAndDOMWindowLeak ++DOCSHELL 58ad400 == 2 [pid = 11152] [id = 8]
[task 2021-05-05T10:02:05.542Z] 10:02:05     INFO - GECKO(10848) | [Child 11152: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 3 (c1a6500) [pid = 11152] [serial = 25] [outer = 0]
[task 2021-05-05T10:02:05.542Z] 10:02:05     INFO - GECKO(10848) | [Child 11152: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 4 (c1c0c00) [pid = 11152] [serial = 26] [outer = c1a6500]
[task 2021-05-05T10:02:05.705Z] 10:02:05     INFO - GECKO(10848) | [Child 11152: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 5 (c1ce400) [pid = 11152] [serial = 27] [outer = c1a6500]
[task 2021-05-05T10:02:06.109Z] 10:02:06     INFO - GECKO(10848) | [Child 11152, MediaDecoderStateMachine #1] WARNING: c1bd200 Could not set cubeb stream name.: file /builds/worker/checkouts/gecko/dom/media/AudioStream.cpp:367
[task 2021-05-05T10:02:06.563Z] 10:02:06     INFO - GECKO(10848) | [Child 4004, Main Thread] WARNING: '!aContent->GetComposedDoc()', file /builds/worker/checkouts/gecko/layout/base/nsCSSFrameConstructor.cpp:8427
[task 2021-05-05T10:02:06.621Z] 10:02:06     INFO - GECKO(10848) | [Child 4004, Main Thread] WARNING: '!aContent->GetComposedDoc()', file /builds/worker/checkouts/gecko/layout/base/nsCSSFrameConstructor.cpp:8427
[task 2021-05-05T10:02:06.621Z] 10:02:06     INFO - GECKO(10848) | [Child 4004, Main Thread] WARNING: '!aContent->GetComposedDoc()', file /builds/worker/checkouts/gecko/layout/base/nsCSSFrameConstructor.cpp:8427
[task 2021-05-05T10:02:07.253Z] 10:02:07     INFO - TEST-INFO | started process screenshot
[task 2021-05-05T10:02:07.355Z] 10:02:07     INFO - TEST-INFO | screenshot: exit 0
[task 2021-05-05T10:02:07.356Z] 10:02:07     INFO - Buffered messages logged at 10:02:05
[task 2021-05-05T10:02:07.356Z] 10:02:07     INFO - Entering test bound testChangingTabVisibilityAffectsInvisiblePlayTime
[task 2021-05-05T10:02:07.357Z] 10:02:07     INFO - open tab for media playback
[task 2021-05-05T10:02:07.357Z] 10:02:07     INFO - Console message: [JavaScript Error: "The character encoding of the HTML document was not declared. The document will render with garbled text in some browser configurations if the document contains characters from outside the US-ASCII range. The character encoding of the page must be declared in the document or in the transfer protocol." {file: "https://example.com/browser/dom/media/test/browser/file_media.html" line: 0}]
[task 2021-05-05T10:02:07.357Z] 10:02:07     INFO - Buffered messages logged at 10:02:06
[task 2021-05-05T10:02:07.357Z] 10:02:07     INFO - add content helper functions and variables
[task 2021-05-05T10:02:07.357Z] 10:02:07     INFO - measuring play time when tab is in foreground
[task 2021-05-05T10:02:07.358Z] 10:02:07     INFO - TEST-PASS | dom/media/test/browser/browser_tab_visibility_and_play_time.js | video started playing - true == true - 
[task 2021-05-05T10:02:07.358Z] 10:02:07     INFO - TEST-PASS | dom/media/test/browser/browser_tab_visibility_and_play_time.js | totalPlayTime exists - true == true - 
[task 2021-05-05T10:02:07.358Z] 10:02:07     INFO - TEST-PASS | dom/media/test/browser/browser_tab_visibility_and_play_time.js | totalPlayTime keeps increasing - true == true - 
[task 2021-05-05T10:02:07.358Z] 10:02:07     INFO - TEST-PASS | dom/media/test/browser/browser_tab_visibility_and_play_time.js | invisiblePlayTime exists - true == true - 
[task 2021-05-05T10:02:07.358Z] 10:02:07     INFO - Buffered messages finished
[task 2021-05-05T10:02:07.358Z] 10:02:07     INFO - TEST-UNEXPECTED-FAIL | dom/media/test/browser/browser_tab_visibility_and_play_time.js | invisiblePlayTime keeps unchanged - false == true - got false, expected true (operator ==)
[task 2021-05-05T10:02:07.358Z] 10:02:07     INFO - Stack trace:
[task 2021-05-05T10:02:07.358Z] 10:02:07     INFO - ok@resource://specialpowers/SpecialPowersSandbox.jsm:87:21
[task 2021-05-05T10:02:07.358Z] 10:02:07     INFO - content.assertValueKeptUnchanged@chrome://mochitests/content/browser/dom/media/test/browser/browser_tab_visibility_and_play_time.js:86:9
[task 2021-05-05T10:02:07.358Z] 10:02:07     INFO - TEST-PASS | dom/media/test/browser/browser_tab_visibility_and_play_time.js | video paused - true == true - 
[task 2021-05-05T10:02:07.358Z] 10:02:07     INFO - TEST-PASS | dom/media/test/browser/browser_tab_visibility_and_play_time.js | totalPlayTime exists - true == true - 
[task 2021-05-05T10:02:07.359Z] 10:02:07     INFO - GECKO(10848) | [Child 11080: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 2 (ab5000) [pid = 11080] [serial = 10] [outer = 0] [url = about:blank]
[task 2021-05-05T10:02:07.359Z] 10:02:07     INFO - GECKO(10848) | [Child 11080: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL b4bc400 == 0 [pid = 11080] [id = 4] [url = about:blank]
[task 2021-05-05T10:02:08.263Z] 10:02:08     INFO - TEST-PASS | dom/media/test/browser/browser_tab_visibility_and_play_time.js | totalPlayTime keeps unchanged - true == true - 
[task 2021-05-05T10:02:08.263Z] 10:02:08     INFO - TEST-PASS | dom/media/test/browser/browser_tab_visibility_and_play_time.js | invisiblePlayTime exists - true == true - 
[task 2021-05-05T10:02:08.911Z] 10:02:08     INFO - GECKO(10848) | [Child 11108: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 2 (b9c5400) [pid = 11108] [serial = 11] [outer = 0] [url = about:blank]
[task 2021-05-05T10:02:09.265Z] 10:02:09     INFO - TEST-PASS | dom/media/test/browser/browser_tab_visibility_and_play_time.js | invisiblePlayTime keeps unchanged - true == true - 
[task 2021-05-05T10:02:09.265Z] 10:02:09     INFO - measuring play time when tab is in background
[task 2021-05-05T10:02:09.376Z] 10:02:09     INFO - GECKO(10848) | [Child 11152: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL c1bf400 == 1 [pid = 11152] [id = 7] [url = https://example.com/browser/dom/media/test/browser/file_media.html]
[task 2021-05-05T10:02:09.426Z] 10:02:09     INFO - GECKO(10848) | [Child 11152: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 4 (c1a7b00) [pid = 11152] [serial = 22] [outer = 0] [url = https://example.com/browser/dom/media/test/browser/file_media.html]
[task 2021-05-05T10:02:09.578Z] 10:02:09     INFO - TEST-PASS | dom/media/test/browser/browser_tab_visibility_and_play_time.js | video started playing - true == true - 
[task 2021-05-05T10:02:09.588Z] 10:02:09     INFO - TEST-PASS | dom/media/test/browser/browser_tab_visibility_and_play_time.js | totalPlayTime exists - true == true - 
[task 2021-05-05T10:02:09.674Z] 10:02:09     INFO - GECKO(10848) | [Child 11152, MediaDecoderStateMachine #1] WARNING: c1bec40 Could not set cubeb stream name.: file /builds/worker/checkouts/gecko/dom/media/AudioStream.cpp:367
[task 2021-05-05T10:02:09.717Z] 10:02:09     INFO - TEST-PASS | dom/media/test/browser/browser_tab_visibility_and_play_time.js | totalPlayTime keeps increasing - true == true - 
[task 2021-05-05T10:02:09.717Z] 10:02:09     INFO - TEST-PASS | dom/media/test/browser/browser_tab_visibility_and_play_time.js | invisiblePlayTime exists - true == true - 
[task 2021-05-05T10:02:10.016Z] 10:02:10     INFO - TEST-PASS | dom/media/test/browser/browser_tab_visibility_and_play_time.js | invisiblePlayTime keeps increasing - true == true - 
[task 2021-05-05T10:02:10.016Z] 10:02:10     INFO - TEST-PASS | dom/media/test/browser/browser_tab_visibility_and_play_time.js | video paused - true == true - 
[task 2021-05-05T10:02:10.016Z] 10:02:10     INFO - TEST-PASS | dom/media/test/browser/browser_tab_visibility_and_play_time.js | totalPlayTime exists - true == true - 
[task 2021-05-05T10:02:11.018Z] 10:02:11     INFO - TEST-PASS | dom/media/test/browser/browser_tab_visibility_and_play_time.js | totalPlayTime keeps unchanged - true == true - 
[task 2021-05-05T10:02:11.018Z] 10:02:11     INFO - TEST-PASS | dom/media/test/browser/browser_tab_visibility_and_play_time.js | invisiblePlayTime exists - true == true - 
[task 2021-05-05T10:02:11.348Z] 10:02:11     INFO - GECKO(10848) | [Child 11080, Main Thread] WARNING: early callback, or time went backwards: '!aAllowIdleDispatch', file /builds/worker/checkouts/gecko/xpcom/threads/IdleTaskRunner.cpp:179
[task 2021-05-05T10:02:11.427Z] 10:02:11     INFO - GECKO(10848) | [Child 11080: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 1 (b4f2500) [pid = 11080] [serial = 11] [outer = 0] [url = about:blank]
[task 2021-05-05T10:02:12.020Z] 10:02:12     INFO - TEST-PASS | dom/media/test/browser/browser_tab_visibility_and_play_time.js | invisiblePlayTime keeps unchanged - true == true - 
[task 2021-05-05T10:02:12.025Z] 10:02:12     INFO - GECKO(10848) | [Parent 10204, Main Thread] WARNING: 'aOwner->IsDiscarded()', file /builds/worker/workspace/obj-build/dist/include/mozilla/dom/SyncedContextInlines.h:92
[task 2021-05-05T10:02:12.027Z] 10:02:12     INFO - Leaving test bound testChangingTabVisibilityAffectsInvisiblePlayTime
[task 2021-05-05T10:02:12.065Z] 10:02:12     INFO - GECKO(10848) | MEMORY STAT | vsize 1023MB | vsizeMaxContiguous 1293MB | residentFast 252MB | heapAllocated 72MB
[task 2021-05-05T10:02:12.065Z] 10:02:12     INFO - TEST-OK | dom/media/test/browser/browser_tab_visibility_and_play_time.js | took 6533ms
[task 2021-05-05T10:02:12.075Z] 10:02:12     INFO - GECKO(10848) | [Child 11080: Main Thread]: I/DocShellAndDOMWindowLeak ++DOCSHELL ab2c00 == 1 [pid = 11080] [id = 5]
[task 2021-05-05T10:02:12.075Z] 10:02:12     INFO - GECKO(10848) | [Child 11080: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 2 (a63f00) [pid = 11080] [serial = 13] [outer = 0]
[task 2021-05-05T10:02:12.076Z] 10:02:12     INFO - GECKO(10848) | [Child 11080: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 3 (ab5000) [pid = 11080] [serial = 14] [outer = a63f00]
[task 2021-05-05T10:02:12.094Z] 10:02:12     INFO - checking window state```

Andreea Pavel [:apavel]

Updated

•

3 years ago

Summary: Intermittent [TV] dom/media/test/browser/browser_tab_visibility_and_play_time.js | invisiblePlayTime keeps unchanged - false == true - got false, expected true (operator ==) → Intermittent [TV] dom/media/test/browser/browser_tab_visibility_and_play_time.js | invisiblePlayTime/ totalPlayTime keeps unchanged - false == true - got false, expected true (operator ==)

BugBot [:suhaib / :marco/ :calixte]

Comment 1

•

3 years ago

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

status-firefox88: --- → unaffected

status-firefox89: --- → unaffected

status-firefox90: --- → affected

status-firefox-esr78: --- → unaffected

Comment hidden (Intermittent Failures Robot)

BugBot [:suhaib / :marco/ :calixte]

Comment 3

•

3 years ago

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

Status: NEW → RESOLVED

Closed: 3 years ago

Resolution: --- → INCOMPLETE

Norisz Fay [:noriszfay]

Comment 4

•

3 years ago

Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=355700551&repo=mozilla-central&lineNumber=6304

Status: RESOLVED → REOPENED

Resolution: INCOMPLETE → ---

Summary: Intermittent [TV] dom/media/test/browser/browser_tab_visibility_and_play_time.js | invisiblePlayTime/ totalPlayTime keeps unchanged - false == true - got false, expected true (operator ==) → perma [tier 2] dom/media/test/browser/browser_tab_visibility_and_play_time.js | invisiblePlayTime/ totalPlayTime keeps unchanged - false == true - got false, expected true (operator ==)

Comment hidden (Intermittent Failures Robot)

Cosmin Sabou [:CosminS]

Comment 7

•

3 years ago

•

Edited

This seems to be permafailing under a specific combination of Test Groups, more specific when these are run in a chunk:

    accessible/tests/browser/mac/browser.ini
    browser/base/content/test/alerts/browser.ini
    browser/base/content/test/contextMenu/browser.ini
    browser/base/content/test/historySwipeAnimation/browser.ini
    browser/base/content/test/performance/hidpi/browser.ini
    browser/base/content/test/performance/lowdpi/browser.ini
    browser/base/content/test/popupNotifications/browser.ini
    browser/base/content/test/sanitize/browser.ini
    browser/base/content/test/startup/browser.ini
    browser/base/content/test/statuspanel/browser.ini
    browser/base/content/test/tabMediaIndicator/browser.ini
    browser/base/content/test/touch/browser.ini
    browser/components/aboutlogins/tests/browser/browser.ini
    browser/components/enterprisepolicies/tests/browser/disable_app_update/browser.ini
    browser/components/enterprisepolicies/tests/browser/disable_default_bookmarks/browser.ini
    browser/components/enterprisepolicies/tests/browser/show_home_button/browser.ini
    browser/components/extensions/test/browser/browser-private.ini
    browser/components/newtab/test/browser/browser.ini
    browser/components/payments/test/browser/browser.ini
    browser/components/pocket/test/browser.ini
    browser/components/safebrowsing/content/test/browser.ini
    browser/extensions/formautofill/test/browser/browser.ini
    browser/extensions/formautofill/test/browser/creditCard/browser.ini
    browser/extensions/proxy-failover/tests/browser/browser.ini
    browser/extensions/report-site-issue/test/browser/browser.ini
    dom/crypto/test/browser/browser.ini
    dom/indexedDB/test/browser.ini
    dom/localstorage/test/browser.ini
    dom/media/test/browser/browser.ini
    dom/payments/test/browser.ini
    dom/quota/test/browser/browser.ini
    dom/reporting/tests/browser.ini
    dom/serviceworkers/test/isolated/multi-e10s-update/browser.ini
    image/test/browser/browser_sandbox_headless.ini
    layout/tools/layout-debug/tests/browser/browser.ini
    security/sandbox/test/browser_bug1717599_XDG-CONFIG-DIRS.ini
    security/sandbox/test/browser_bug1717599_XDG-CONFIG-HOME.ini
    security/sandbox/test/browser_snap.ini
    security/sandbox/test/browser_xdg.ini
    startupcache/test/browser/browser.ini
    testing/mochitest/baselinecoverage/browser_chrome/browser.ini
    toolkit/components/alerts/test/browser.ini
    toolkit/components/antitracking/test/browser/browser-blocking.ini
    toolkit/components/mozprotocol/tests/browser.ini
    toolkit/components/normandy/test/browser/browser.ini
    toolkit/components/remotepagemanager/tests/browser/browser.ini
    toolkit/components/satchel/test/browser/browser.ini
    toolkit/components/telemetry/tests/browser/browser.ini
    toolkit/components/tooltiptext/tests/browser.ini
    toolkit/mozapps/update/tests/browser/browser.bits.ini
    toolkit/mozapps/update/tests/browser/manual_app_update_only/browser.ini
    toolkit/xre/test/browser.ini

Test groups from the last green one were:

    accessible/tests/browser/e10s/browser.ini
    accessible/tests/browser/hittest/browser.ini
    browser/base/content/test/general/browser.ini
    dom/base/test/browser.ini
    dom/media/test/browser/browser.ini
    toolkit/components/places/tests/browser/browser.ini
    toolkit/components/reader/test/browser.ini
    toolkit/content/tests/browser/browser.ini

Last time this was green was here. First time it failed was here.
Looks to be permafailing only on macosx1100-64-shippable-qr mochitest-browser-chrome-fis-e10s
Bryce, could you have a look over this one?

Flags: needinfo?(bvandyk)

Summary: perma [tier 2] dom/media/test/browser/browser_tab_visibility_and_play_time.js | invisiblePlayTime/ totalPlayTime keeps unchanged - false == true - got false, expected true (operator ==) → Perma [tier 2] macOS shippable fission dom/media/test/browser/browser_tab_visibility_and_play_time.js | invisiblePlayTime/ totalPlayTime keeps unchanged - false == true - got false, expected true (operator ==)

Bryce Seager van Dyk [:bryce] (he/him) - Not reading bugmail

Comment 8

•

3 years ago

Paul, do you have experience here? Looks like we're accumulating invisible/hidden play time when we shouldn't be.

Bug 1584678 comes to mind as another bug related to test visibility. I'm not sure if there's a connect, but thought it worth mentioning.

Flags: needinfo?(bvandyk) → needinfo?(padenot)

Paul Adenot (:padenot)

Comment 9

•

3 years ago

That's always on a Mac Mini M1 it seems like, which I don't have (nor any other m1-based mac). Is there a way to push to try only on those boxes, or is this going to be impossible to debug ?

Flags: needinfo?(padenot) → needinfo?(csabou)

Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)

Comment 10

•

3 years ago

./mach try fuzzy --full should offer the tasks which had been affected by the failure.

Flags: needinfo?(csabou)

Andreea Pavel [:apavel]

Updated

•

3 years ago

Whiteboard: [stockwell needswork:owner]

Comment hidden (Intermittent Failures Robot)

Alastor Wu [:alwu]

Assignee

Comment 12

•

3 years ago

I can reproduce this on the try server and it seems the visibility of media element changed to invisible incorrectly even if the tab is still on foreground. I might be related with bug 1584678, but I am not sure. I'm going to add more log to see what happen.

Alastor Wu [:alwu]

Assignee

Comment 13

•

3 years ago

In this log we can see that video element become invisble for a short while (which should not happen, because it's on the foreground tab) And that triggers the timer for invisible play time and causes the failure.

The visibility change of media element would be called via video frame, which seems calling from nsIFrame.

I am not sure if this is as same as bug 1584678, so I also enable the log in AsyncTabSwitcher. Emilio, do you have any idea about this weird visibility change? In the test, the video is always on the foreground tab, and we didn't scroll the page. So it should suppose to be in the view port and visible all the time.

Thank you.

Flags: needinfo?(emilio)

Emilio Cobos Álvarez (:emilio)

Comment 14

•

3 years ago

It doesn't seem like the same as the other bug. I'm not the most familiar with the frame visibility tracking bits, but I could think of a few things that could affect it like memory pressure, or maybe another test that runs in parallel and steals focus, occluding the window.

What I'd do to debug this since this seems ~permafailing is to print a stack on the log when the visibility changes (so call MozWalkTheStack(stderr)) and we can probably track down what's going on based on that.

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

Alastor Wu [:alwu]

Assignee

Comment 15

•

3 years ago

•

Edited

Here is the log with the stack. Do you know who I can ask about this frame visibility issue? Thank you.

[task 2021-11-02T00:56:19.035Z] 00:56:19     INFO - GECKO(2421) | [Child 2445: Main Thread]: D/nsMediaElement OnVisibilityChange(): ApproximatelyNonVisible
[task 2021-11-02T00:56:19.038Z] 00:56:19     INFO - GECKO(2421) | [Child 2445: Main Thread]: D/nsMediaElement frame #01: mozilla::dom::HTMLMediaElement::OnVisibilityChange(mozilla::Visibility) [dom/html/HTMLMediaElement.cpp:6837]
[task 2021-11-02T00:56:19.039Z] 00:56:19     INFO - GECKO(2421) | [Child 2445: Main Thread]: D/nsMediaElement frame #02: nsVideoFrame::OnVisibilityChange(mozilla::Visibility, mozilla::Maybe<mozilla::OnNonvisible> const&) [layout/generic/nsVideoFrame.cpp:484]
[task 2021-11-02T00:56:19.040Z] 00:56:19     INFO - GECKO(2421) | [Child 2445: Main Thread]: D/nsMediaElement frame #03: nsIFrame::DisableVisibilityTracking() [layout/generic/nsIFrame.cpp:2226]
[task 2021-11-02T00:56:19.041Z] 00:56:19     INFO - GECKO(2421) | [Child 2445: Main Thread]: D/nsMediaElement frame #04: nsIFrame::DestroyFrom(nsIFrame*, mozilla::layout::PostFrameDestroyData&) [layout/generic/nsIFrame.cpp:881]
[task 2021-11-02T00:56:19.042Z] 00:56:19     INFO - GECKO(2421) | [Child 2445: Main Thread]: D/nsMediaElement frame #05: nsLineBox::DeleteLineList(nsPresContext*, nsLineList&, nsIFrame*, nsFrameList*, mozilla::layout::PostFrameDestroyData&) [layout/generic/nsLineBox.cpp:381]
[task 2021-11-02T00:56:19.042Z] 00:56:19     INFO - GECKO(2421) | [Child 2445: Main Thread]: D/nsMediaElement frame #06: nsBlockFrame::DestroyFrom(nsIFrame*, mozilla::layout::PostFrameDestroyData&) [layout/generic/nsBlockFrame.cpp:472]
[task 2021-11-02T00:56:19.043Z] 00:56:19     INFO - GECKO(2421) | [Child 2445: Main Thread]: D/nsMediaElement frame #07: nsLineBox::DeleteLineList(nsPresContext*, nsLineList&, nsIFrame*, nsFrameList*, mozilla::layout::PostFrameDestroyData&) [layout/generic/nsLineBox.cpp:381]
[task 2021-11-02T00:56:19.044Z] 00:56:19     INFO - GECKO(2421) | [Child 2445: Main Thread]: D/nsMediaElement frame #08: nsBlockFrame::DestroyFrom(nsIFrame*, mozilla::layout::PostFrameDestroyData&) [layout/generic/nsBlockFrame.cpp:472]
[task 2021-11-02T00:56:19.044Z] 00:56:19     INFO - GECKO(2421) | [Child 2445: Main Thread]: D/nsMediaElement frame #09: nsFrameList::DestroyFramesFrom(nsIFrame*, mozilla::layout::PostFrameDestroyData&) [layout/generic/nsFrameList.cpp:48]
[task 2021-11-02T00:56:19.045Z] 00:56:19     INFO - GECKO(2421) | [Child 2445: Main Thread]: D/nsMediaElement frame #10: nsContainerFrame::DestroyFrom(nsIFrame*, mozilla::layout::PostFrameDestroyData&) [layout/generic/nsContainerFrame.cpp:230]
[task 2021-11-02T00:56:19.045Z] 00:56:19     INFO - GECKO(2421) | [Child 2445: Main Thread]: D/nsMediaElement frame #11: nsFrameList::DestroyFramesFrom(nsIFrame*, mozilla::layout::PostFrameDestroyData&) [layout/generic/nsFrameList.cpp:48]
[task 2021-11-02T00:56:19.046Z] 00:56:19     INFO - GECKO(2421) | [Child 2445: Main Thread]: D/nsMediaElement frame #12: nsContainerFrame::DestroyFrom(nsIFrame*, mozilla::layout::PostFrameDestroyData&) [layout/generic/nsContainerFrame.cpp:230]
[task 2021-11-02T00:56:19.047Z] 00:56:19     INFO - GECKO(2421) | [Child 2445: Main Thread]: D/nsMediaElement frame #13: nsContainerFrame::RemoveFrame(mozilla::layout::FrameChildListID, nsIFrame*) [layout/generic/nsContainerFrame.cpp:181]
[task 2021-11-02T00:56:19.047Z] 00:56:19     INFO - GECKO(2421) | [Child 2445: Main Thread]: D/nsMediaElement frame #14: nsCSSFrameConstructor::ContentRemoved(nsIContent*, nsIContent*, nsCSSFrameConstructor::RemoveFlags) [layout/base/nsCSSFrameConstructor.cpp:7697]
[task 2021-11-02T00:56:19.048Z] 00:56:19     INFO - GECKO(2421) | [Child 2445: Main Thread]: D/nsMediaElement frame #15: nsCSSFrameConstructor::RecreateFramesForContent(nsIContent*, nsCSSFrameConstructor::InsertionKind) [layout/base/nsCSSFrameConstructor.cpp:8668]
[task 2021-11-02T00:56:19.048Z] 00:56:19     INFO - GECKO(2421) | [Child 2445: Main Thread]: D/nsMediaElement frame #16: mozilla::RestyleManager::ProcessRestyledFrames(nsStyleChangeList&) [layout/base/RestyleManager.cpp:1388]
[task 2021-11-02T00:56:19.049Z] 00:56:19     INFO - GECKO(2421) | [Child 2445: Main Thread]: D/nsMediaElement frame #17: mozilla::RestyleManager::DoProcessPendingRestyles(mozilla::ServoTraversalFlags) [layout/base/RestyleManager.cpp:3057]
[task 2021-11-02T00:56:19.050Z] 00:56:19     INFO - GECKO(2421) | [Child 2445: Main Thread]: D/nsMediaElement frame #18: mozilla::PresShell::DoFlushPendingNotifications(mozilla::ChangesToFlush) [layout/base/PresShell.cpp:4219]
[task 2021-11-02T00:56:19.051Z] 00:56:19     INFO - GECKO(2421) | [Child 2445: Main Thread]: D/nsMediaElement frame #19: nsRefreshDriver::Tick(mozilla::layers::BaseTransactionId<mozilla::VsyncIdType>, mozilla::TimeStamp, nsRefreshDriver::IsExtraTick) [layout/base/nsRefreshDriver.cpp:2370]
[task 2021-11-02T00:56:19.052Z] 00:56:19     INFO - GECKO(2421) | [Child 2445: Main Thread]: D/nsMediaElement frame #20: mozilla::detail::RunnableFunction<nsRefreshDriver::EnsureTimerStarted(nsRefreshDriver::EnsureTimerStartedFlags)::$_1>::Run() [xpcom/threads/nsThreadUtils.h:532]
[task 2021-11-02T00:56:19.052Z] 00:56:19     INFO - GECKO(2421) | [Child 2445: Main Thread]: D/nsMediaElement frame #21: mozilla::RunnableTask::Run() [xpcom/threads/TaskController.cpp:468]
[task 2021-11-02T00:56:19.053Z] 00:56:19     INFO - GECKO(2421) | [Child 2445: Main Thread]: D/nsMediaElement frame #22: mozilla::TaskController::DoExecuteNextTaskOnlyMainThreadInternal(mozilla::detail::BaseAutoLock<mozilla::Mutex&> const&) [xpcom/threads/TaskController.cpp:770]
[task 2021-11-02T00:56:19.054Z] 00:56:19     INFO - GECKO(2421) | [Child 2445: Main Thread]: D/nsMediaElement frame #23: mozilla::TaskController::ExecuteNextTaskOnlyMainThreadInternal(mozilla::detail::BaseAutoLock<mozilla::Mutex&> const&) [xpcom/threads/TaskController.cpp:606]
[task 2021-11-02T00:56:19.054Z] 00:56:19     INFO - GECKO(2421) | [Child 2445: Main Thread]: D/nsMediaElement frame #24: mozilla::TaskController::ProcessPendingMTTask(bool) [xpcom/threads/TaskController.cpp:390]
[task 2021-11-02T00:56:19.055Z] 00:56:19     INFO - GECKO(2421) | [Child 2445: Main Thread]: D/nsMediaElement frame #25: mozilla::detail::RunnableFunction<mozilla::TaskController::InitializeInternal()::$_0>::Run() [xpcom/threads/nsThreadUtils.h:532]
[task 2021-11-02T00:56:19.055Z] 00:56:19     INFO - GECKO(2421) | [Child 2445: Main Thread]: D/nsMediaElement frame #26: nsThread::ProcessNextEvent(bool, bool*) [xpcom/threads/nsThread.cpp:1155]
[task 2021-11-02T00:56:19.056Z] 00:56:19     INFO - GECKO(2421) | [Child 2445: Main Thread]: D/nsMediaElement frame #27: NS_ProcessNextEvent(nsIThread*, bool) [xpcom/threads/nsThreadUtils.cpp:467]
[task 2021-11-02T00:56:19.057Z] 00:56:19     INFO - GECKO(2421) | [Child 2445: Main Thread]: D/nsMediaElement frame #28: mozilla::ipc::MessagePump::Run(base::MessagePump::Delegate*) [ipc/glue/MessagePump.cpp:85]
[task 2021-11-02T00:56:19.057Z] 00:56:19     INFO - GECKO(2421) | [Child 2445: Main Thread]: D/nsMediaElement frame #29: MessageLoop::Run() [ipc/chromium/src/base/message_loop.cc:307]
[task 2021-11-02T00:56:19.058Z] 00:56:19     INFO - GECKO(2421) | [Child 2445: Main Thread]: D/nsMediaElement frame #30: nsBaseAppShell::Run() [widget/nsBaseAppShell.cpp:139]
[task 2021-11-02T00:56:19.058Z] 00:56:19     INFO - GECKO(2421) | [Child 2445: Main Thread]: D/nsMediaElement frame #31: nsAppShell::Run() [widget/cocoa/nsAppShell.mm:795]
[task 2021-11-02T00:56:19.059Z] 00:56:19     INFO - GECKO(2421) | [Child 2445: Main Thread]: D/nsMediaElement frame #32: XRE_RunAppShell() [toolkit/xre/nsEmbedFunctions.cpp:917]
[task 2021-11-02T00:56:19.059Z] 00:56:19     INFO - GECKO(2421) | [Child 2445: Main Thread]: D/nsMediaElement frame #33: mozilla::ipc::MessagePumpForChildProcess::Run(base::MessagePump::Delegate*) [ipc/glue/MessagePump.cpp:235]
[task 2021-11-02T00:56:19.060Z] 00:56:19     INFO - GECKO(2421) | [Child 2445: Main Thread]: D/nsMediaElement frame #34: MessageLoop::Run() [ipc/chromium/src/base/message_loop.cc:307]
[task 2021-11-02T00:56:19.061Z] 00:56:19     INFO - GECKO(2421) | [Child 2445: Main Thread]: D/nsMediaElement frame #35: XRE_InitChildProcess(int, char**, XREChildData const*) [toolkit/xre/nsEmbedFunctions.cpp:753]
[task 2021-11-02T00:56:19.061Z] 00:56:19     INFO - GECKO(2421) | [Child 2445: Main Thread]: D/nsMediaElement frame #36: main [ipc/app/MozillaRuntimeMain.cpp:72]

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

Emilio Cobos Álvarez (:emilio)

Comment 16

•

3 years ago

So that means that the frame is getting destroyed / reconstructed due to a style change. Can you also print the stack in nsVideoFrame constructor perhaps? Just to confirm it's getting called after that DestroyFrom? If it's not, then something off is going on.

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

Alastor Wu [:alwu]

Assignee

Comment 17

•

3 years ago

Here is the log where I capture stack for nsVideoFrame's ctor, hope it would help!
Thank you so much!

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

Emilio Cobos Álvarez (:emilio)

Comment 18

•

3 years ago

So given how the code is structured, it makes sense that it becomes invisible for a short while while reframed. This is probably a font-loading reframe or something that triggers the frame to be destroyed (become invisible) and then constructed again (become visible)...

Can the test deal with that easily? If not, does setting stuff like gfx.font_loader.delay=0, gfx.font_loader.interval=0 and co in the mochitest.ini / browser.ini help?

Flags: needinfo?(emilio)

Alastor Wu [:alwu]

Assignee

Comment 19

•

3 years ago

Thanks! Changing the pref helps (try result here), I will submit a patch to do that.

Assignee: nobody → alwu

Alastor Wu [:alwu]

Assignee

Comment 20

•

3 years ago

Attached file Bug 1709597 - setting gfx preferences to avoid video frame from becoming invisible a short while during reframe, which would cause intermittent failures. — Details

Setting the prefs based on the suggestion in [1]

[1] https://bugzilla.mozilla.org/show_bug.cgi?id=1709597#c18

Comment hidden (Intermittent Failures Robot)

Pulsebot

Comment 22

•

3 years ago

Pushed by alwu@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/bb3fa7934e3e
setting gfx preferences to avoid video frame from becoming invisible a short while during reframe, which would cause intermittent failures. r=padenot

Iulian Moraru

Comment 23

•

3 years ago

bugherder

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

Status: REOPENED → RESOLVED

Closed: 3 years ago → 3 years ago

status-firefox96: --- → fixed

Resolution: --- → FIXED

Target Milestone: --- → 96 Branch

Ryan VanderMeulen [:RyanVM]

Updated

•

3 years ago

status-firefox90: affected → wontfix

Ryan VanderMeulen [:RyanVM]

Updated

•

3 years ago

status-firefox94: --- → wontfix

status-firefox95: --- → wontfix

status-firefox-esr91: --- → wontfix

Comment hidden (Intermittent Failures Robot)

BMO Automation

Updated

•

3 years ago

Has Regression Range: --- → yes