Open Bug 1877642 Opened 1 year ago Updated 2 days ago

Intermittent dom/base/test/fullscreen/browser_fullscreen-tab-close-race.js | single tracking bug

Categories

(Core :: DOM: Core & HTML, defect)

Product:
Core
Component:
DOM: Core & HTML
Type:
defect

Tracking

()

Status:
REOPENED

People

(Reporter: intermittent-bug-filer, Unassigned)

References

Details

(Keywords: intermittent-failure, intermittent-testcase, Whiteboard: [stockwell disabled])

Attachments

(1 file, 1 obsolete file)

Bug 1877642 - Disable browser_fullscreen-tab-close-race.js on apple_silicon !debug for frequent failures. r=#intermittent-reviewers
48 bytes, text/x-phabricator-request
Details | Review

Filed by: ncsoregi [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=445296925&repo=mozilla-central
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/BiUVxCDTTtmFZkg0EiXGVQ/runs/0/artifacts/public/logs/live_backing.log

[task 2024-01-31T09:05:34.830Z] 09:05:34     INFO - TEST-START | dom/base/test/fullscreen/browser_fullscreen-tab-close-race.js
[task 2024-01-31T09:05:34.882Z] 09:05:34     INFO - GECKO(6874) | JavaScript error: resource:///actors/DOMFullscreenParent.sys.mjs, line 218: Error: TelemetryStopwatch: key "FULLSCREEN_CHANGE_MS" was already initialized
[task 2024-01-31T09:05:34.929Z] 09:05:34     INFO - GECKO(6874) | console.error: "not able to get browsingContext for chrome window."
[task 2024-01-31T09:07:04.944Z] 09:07:04     INFO - TEST-INFO | started process screencapture
[task 2024-01-31T09:07:05.065Z] 09:07:05     INFO - TEST-INFO | screencapture: exit 0
[task 2024-01-31T09:07:05.065Z] 09:07:05     INFO - Buffered messages logged at 09:05:34
[task 2024-01-31T09:07:05.065Z] 09:07:05     INFO - Entering setup bound 
[task 2024-01-31T09:07:05.066Z] 09:07:05     INFO - Leaving setup bound 
[task 2024-01-31T09:07:05.066Z] 09:07:05     INFO - Entering test bound 
[task 2024-01-31T09:07:05.066Z] 09:07:05     INFO - Test tab_close_toplevel, url: data:text/html,
[task 2024-01-31T09:07:05.066Z] 09:07:05     INFO -     <div name="div" id="div" style="width: 100px; height: 100px; background: red;">
[task 2024-01-31T09:07:05.066Z] 09:07:05     INFO -     <iframe id="iframe" allowfullscreen="yes"
[task 2024-01-31T09:07:05.066Z] 09:07:05     INFO -      src="http://mochi.test:8888/browser/dom/base/test/fullscreen/file_fullscreen-iframe-middle.html"></iframe>
[task 2024-01-31T09:07:05.066Z] 09:07:05     INFO -     </div>
[task 2024-01-31T09:07:05.067Z] 09:07:05     INFO - Console message: [JavaScript Warning: "This page is in Quirks Mode. Page layout may be impacted. For Standards Mode use “<!DOCTYPE html>”." {file: "data:text/html,    <div name="div" id="div" style="width: 100px; height: 100px; background: red;">    <iframe id="iframe" allowfullscreen="yes"     src="http://mochi.test:8888/browser/dom/base/test/fullscreen/file_fullscreen-iframe-middle.html"></iframe>    </div>" line: 0}]
[task 2024-01-31T09:07:05.067Z] 09:07:05     INFO - Console message: [JavaScript Warning: "Partitioned cookie or storage access was provided to “http://mochi.test:8888/browser/dom/base/test/fullscreen/file_fullscreen-iframe-middle.html” because it is loaded in the third-party context and dynamic state partitioning is enabled."]
[task 2024-01-31T09:07:05.067Z] 09:07:05     INFO - Console message: [JavaScript Warning: "This page is in Quirks Mode. Page layout may be impacted. For Standards Mode use “<!DOCTYPE html>”." {file: "http://mochi.test:8888/browser/dom/base/test/fullscreen/file_fullscreen-iframe-middle.html" line: 0}]
[task 2024-01-31T09:07:05.068Z] 09:07:05     INFO - Console message: [JavaScript Warning: "This page is in Quirks Mode. Page layout may be impacted. For Standards Mode use “<!DOCTYPE html>”." {file: "http://example.org/browser/dom/base/test/fullscreen/file_fullscreen-iframe-inner.html" line: 0}]
[task 2024-01-31T09:07:05.068Z] 09:07:05     INFO - Console message: [JavaScript Warning: "Partitioned cookie or storage access was provided to “http://example.org/browser/dom/base/test/fullscreen/file_fullscreen-iframe-inner.html” because it is loaded in the third-party context and dynamic state partitioning is enabled."]
[task 2024-01-31T09:07:05.068Z] 09:07:05     INFO - waitForFullscreenExit
[task 2024-01-31T09:07:05.068Z] 09:07:05     INFO - Console message: [JavaScript Error: "Error: TelemetryStopwatch: key "FULLSCREEN_CHANGE_MS" was already initialized" {file: "resource:///actors/DOMFullscreenParent.sys.mjs" line: 218}]
[task 2024-01-31T09:07:05.068Z] 09:07:05     INFO - handleEvent@resource:///actors/DOMFullscreenParent.sys.mjs:218:28
[task 2024-01-31T09:07:05.069Z] 09:07:05     INFO - receiveMessage@resource:///actors/DOMFullscreenParent.sys.mjs:139:28
[task 2024-01-31T09:07:05.069Z] 09:07:05     INFO - JSActor query*handleEvent@resource:///actors/DOMFullscreenChild.sys.mjs:96:14
[task 2024-01-31T09:07:05.069Z] 09:07:05     INFO - 
[task 2024-01-31T09:07:05.069Z] 09:07:05     INFO - Console message: [JavaScript Warning: "Exited fullscreen because fullscreen element was removed from document." {file: "chrome://browser/content/tabbrowser.js" line: 4370}]
[task 2024-01-31T09:07:05.069Z] 09:07:05     INFO - Buffered messages logged at 09:06:19
[task 2024-01-31T09:07:05.069Z] 09:07:05     INFO - Longer timeout required, waiting longer...  Remaining timeouts: 1
[task 2024-01-31T09:07:05.069Z] 09:07:05     INFO - Buffered messages finished
[task 2024-01-31T09:07:05.070Z] 09:07:05     INFO - TEST-UNEXPECTED-FAIL | dom/base/test/fullscreen/browser_fullscreen-tab-close-race.js | Test timed out - 
[task 2024-01-31T09:07:05.070Z] 09:07:05     INFO - GECKO(6874) | Completed ShutdownLeaks collections in process 6874

Hi Martin! Can you please take a look at this? I think this might be something regressed by Bug 1539998.
Thank you!

This seems to only affect OS X 11 WebRender Shippable opt.

Flags: needinfo?(stransky)

This appears to be high frequency, 3 out of 4 retriggers failed, please see here.

Summary: Intermittent dom/base/test/fullscreen/browser_fullscreen-tab-close-race.js | single tracking bug → High Frequency dom/base/test/fullscreen/browser_fullscreen-tab-close-race.js | single tracking bug

Hello, Bug 1539998 affects Linux only and doesn't touch any Mac OS code so I don't think it's related.

Flags: needinfo?(stransky)
Attachment #9387498 - Attachment is obsolete: true

Update

There have been 36 failures within the last 7 days:

  • 1 failure on Windows 11 x64 22H2 CCov WebRender opt
  • 35 failures on OS X 11 WebRender Shippable opt

Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=448704923&repo=autoland&lineNumber=10010

[task 2024-02-28T01:54:21.963Z] 01:54:21     INFO - TEST-START | dom/base/test/fullscreen/browser_fullscreen-tab-close-race.js
[task 2024-02-28T01:54:22.017Z] 01:54:22     INFO - GECKO(5997) | JavaScript error: resource:///actors/DOMFullscreenParent.sys.mjs, line 218: Error: TelemetryStopwatch: key "FULLSCREEN_CHANGE_MS" was already initialized
[task 2024-02-28T01:54:22.049Z] 01:54:22     INFO - GECKO(5997) | console.error: "not able to get browsingContext for chrome window."
[task 2024-02-28T01:55:52.150Z] 01:55:52     INFO - TEST-INFO | started process screencapture
[task 2024-02-28T01:55:52.268Z] 01:55:52     INFO - TEST-INFO | screencapture: exit 0
[task 2024-02-28T01:55:52.268Z] 01:55:52     INFO - Buffered messages logged at 01:54:21
[task 2024-02-28T01:55:52.268Z] 01:55:52     INFO - Entering setup bound 
[task 2024-02-28T01:55:52.268Z] 01:55:52     INFO - Leaving setup bound 
[task 2024-02-28T01:55:52.269Z] 01:55:52     INFO - Entering test bound 
[task 2024-02-28T01:55:52.269Z] 01:55:52     INFO - Test tab_close_toplevel, url: data:text/html,
[task 2024-02-28T01:55:52.269Z] 01:55:52     INFO -     <div name="div" id="div" style="width: 100px; height: 100px; background: red;">
[task 2024-02-28T01:55:52.269Z] 01:55:52     INFO -     <iframe id="iframe" allowfullscreen="yes"
[task 2024-02-28T01:55:52.269Z] 01:55:52     INFO -      src="http://mochi.test:8888/browser/dom/base/test/fullscreen/file_fullscreen-iframe-middle.html"></iframe>
[task 2024-02-28T01:55:52.269Z] 01:55:52     INFO -     </div>
[task 2024-02-28T01:55:52.269Z] 01:55:52     INFO - Console message: [JavaScript Warning: "This page is in Quirks Mode. Page layout may be impacted. For Standards Mode use “<!DOCTYPE html>”." {file: "data:text/html,    <div name="div" id="div" style="width: 100px; height: 100px; background: red;">    <iframe id="iframe" allowfullscreen="yes"     src="http://mochi.test:8888/browser/dom/base/test/fullscreen/file_fullscreen-iframe-middle.html"></iframe>    </div>" line: 0}]
[task 2024-02-28T01:55:52.269Z] 01:55:52     INFO - Console message: [JavaScript Warning: "This page is in Quirks Mode. Page layout may be impacted. For Standards Mode use “<!DOCTYPE html>”." {file: "http://mochi.test:8888/browser/dom/base/test/fullscreen/file_fullscreen-iframe-middle.html" line: 0}]
[task 2024-02-28T01:55:52.270Z] 01:55:52     INFO - Console message: [JavaScript Warning: "This page is in Quirks Mode. Page layout may be impacted. For Standards Mode use “<!DOCTYPE html>”." {file: "http://example.org/browser/dom/base/test/fullscreen/file_fullscreen-iframe-inner.html" line: 0}]
[task 2024-02-28T01:55:52.270Z] 01:55:52     INFO - Console message: [JavaScript Warning: "Partitioned cookie or storage access was provided to “http://example.org/browser/dom/base/test/fullscreen/file_fullscreen-iframe-inner.html” because it is loaded in the third-party context and dynamic state partitioning is enabled."]
[task 2024-02-28T01:55:52.270Z] 01:55:52     INFO - Console message: [JavaScript Warning: "Partitioned cookie or storage access was provided to “http://mochi.test:8888/browser/dom/base/test/fullscreen/file_fullscreen-iframe-middle.html” because it is loaded in the third-party context and dynamic state partitioning is enabled."]
[task 2024-02-28T01:55:52.270Z] 01:55:52     INFO - waitForFullscreenExit
[task 2024-02-28T01:55:52.270Z] 01:55:52     INFO - Buffered messages logged at 01:54:22
[task 2024-02-28T01:55:52.271Z] 01:55:52     INFO - Console message: [JavaScript Error: "Error: TelemetryStopwatch: key "FULLSCREEN_CHANGE_MS" was already initialized" {file: "resource:///actors/DOMFullscreenParent.sys.mjs" line: 218}]
[task 2024-02-28T01:55:52.271Z] 01:55:52     INFO - handleEvent@resource:///actors/DOMFullscreenParent.sys.mjs:218:28
[task 2024-02-28T01:55:52.271Z] 01:55:52     INFO - receiveMessage@resource:///actors/DOMFullscreenParent.sys.mjs:139:28
[task 2024-02-28T01:55:52.271Z] 01:55:52     INFO - JSActor query*handleEvent@resource:///actors/DOMFullscreenChild.sys.mjs:96:14
[task 2024-02-28T01:55:52.271Z] 01:55:52     INFO - 
[task 2024-02-28T01:55:52.271Z] 01:55:52     INFO - Console message: [JavaScript Warning: "Exited fullscreen because fullscreen element was removed from document." {file: "chrome://browser/content/tabbrowser.js" line: 4362}]
[task 2024-02-28T01:55:52.271Z] 01:55:52     INFO - Buffered messages logged at 01:55:07
[task 2024-02-28T01:55:52.271Z] 01:55:52     INFO - Longer timeout required, waiting longer...  Remaining timeouts: 1
[task 2024-02-28T01:55:52.272Z] 01:55:52     INFO - Buffered messages finished
[task 2024-02-28T01:55:52.272Z] 01:55:52     INFO - TEST-UNEXPECTED-FAIL | dom/base/test/fullscreen/browser_fullscreen-tab-close-race.js | Test timed out -

Andreas, can you please help us assign this to someone?
Thank you.

Flags: needinfo?(afarre)

Edgar, you know about fullscreen, do you have an idea?

Flags: needinfo?(afarre) → needinfo?(echen)

This test is to test whether chrome document exit fullscreen properly after tab that requests DOM fullscreen is closed.
Looked several failures,

All of them stuck on waiting for fullscreenchange event fired on chrome document.
The failures started on 2024-01-31 and all occurred on macOS opt build. IIRC, there were some change in cocoa widget for using native fullscreen for DOM fullscreen on Mac. :bradwerth, do you recall any changes landed before 2024-01-31 might be related? Thanks!

Flags: needinfo?(echen) → needinfo?(bwerth)

Edgar, sorry this is happening. Most assuredly this became more sensitive after the landing of Bug 1865372, which changed the timing of when the native window is destroyed on closing. Whenever there is a test where a Promise fails on a fullscreenchange event, that indicates that the promises are being triggered before the previous request has been completed. In such a case, the fullscreenchange event will never fire because the underlying macOS call to [window toggleFullscreen] fails silently (not even a notification to the window delegate). There's lots of code in nsCocoaWindow that tries to prevent this from happening for calls made on the same window, but there are less protections for this kind of failure between multiple windows. So the fix in this case will be ensuring that whatever function brings the window in or out of fullscreen is waiting for a sane window state before proceeding.

Generally this can be done by waiting for the browsing context to become active. An example is https://phabricator.services.mozilla.com/D202759. From quickly looking at the browser_fullscreen-tab-close-race.js test, I haven't been able to find the enterFullscreen invocation, but that's where you'd need to add something like a check for the browsing context to become active, and it's probably also a good idea to add it to the exitFullscreen invocation, too.

Flags: needinfo?(bwerth)

Update

There have been 35 total failures within the last 7 days:

  • 34 failures on OS X 11 WebRender Shippable opt
  • 1 failure on Windows 11 x64 22H2 CCov WebRender opt

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

Assignee: nobody → csabou
Status: NEW → ASSIGNED
Duplicate of this bug: 1784875
Pushed by csabou@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/77aa1bc49bd0 Disable browser_fullscreen-tab-close-race.js on apple_silicon !debug for frequent failures. r=intermittent-reviewers,ahal
Assignee: csabou → nobody
Status: ASSIGNED → NEW
Keywords: leave-open
Whiteboard: [stockwell disable-recommended] → [stockwell disabled]
Summary: High Frequency dom/base/test/fullscreen/browser_fullscreen-tab-close-race.js | single tracking bug → Intermittent dom/base/test/fullscreen/browser_fullscreen-tab-close-race.js | single tracking bug

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

Status: NEW → RESOLVED
Closed: 9 months ago
Resolution: --- → INCOMPLETE

New failure instance: https://treeherder.mozilla.org/logviewer?job_id=506808353&repo=try

Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: