1677899 - Permafail browser/base/content/test/fullscreen/browser_fullscreen_window_focus.js | Test timed out - | Found a tab after previous test timed out: http://example.com/browser/browser/base/content/test/fullscreen/open_and_focus_helper.html

Status: RESOLVED FIXED

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

Description

[Treeherder Bug Filer]

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

---

[task 2020-11-18T01:12:40.821Z] 01:12:40     INFO - TEST-START | browser/base/content/test/fullscreen/browser_fullscreen_window_focus.js
[task 2020-11-18T01:12:40.845Z] 01:12:40     INFO - GECKO(2246) | [Child 2812, Main Thread] WARNING: NS_ENSURE_TRUE(Preferences::InitStaticMembers()) failed: file /builds/worker/checkouts/gecko/modules/libpref/Preferences.cpp:4287
[task 2020-11-18T01:12:40.904Z] 01:12:40     INFO - GECKO(2246) | [Child 2879: Main Thread]: I/DocShellAndDOMWindowLeak ++DOCSHELL 0x7febe7f45400 == 1 [pid = 2879] [id = 0]
[task 2020-11-18T01:12:40.905Z] 01:12:40     INFO - GECKO(2246) | [Child 2879: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 1 (0x7fec044b0040) [pid = 2879] [serial = 1] [outer = (nil)]
[task 2020-11-18T01:12:40.906Z] 01:12:40     INFO - GECKO(2246) | [Child 2879: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 2 (0x7febe7f46800) [pid = 2879] [serial = 2] [outer = 0x7fec044b0040]
[task 2020-11-18T01:12:41.084Z] 01:12:41     INFO - GECKO(2246) | [Child 2879, Main Thread] WARNING: NS_ENSURE_TRUE(info) failed: file /builds/worker/checkouts/gecko/extensions/permissions/PermissionDelegateHandler.cpp:348
[task 2020-11-18T01:12:41.105Z] 01:12:41     INFO - GECKO(2246) | [Child 2879: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 3 (0x7febee34f800) [pid = 2879] [serial = 3] [outer = 0x7fec044b0040]
[task 2020-11-18T01:12:41.362Z] 01:12:41     INFO - GECKO(2246) | [Child 2879: Main Thread]: I/DocShellAndDOMWindowLeak ++DOCSHELL 0x7febe7f99c00 == 2 [pid = 2879] [id = 1]
[task 2020-11-18T01:12:41.362Z] 01:12:41     INFO - GECKO(2246) | [Child 2879: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 4 (0x7fec04464ac0) [pid = 2879] [serial = 4] [outer = (nil)]
[task 2020-11-18T01:12:41.362Z] 01:12:41     INFO - GECKO(2246) | [Child 2879: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 5 (0x7febe7f9ac00) [pid = 2879] [serial = 5] [outer = 0x7fec04464ac0]
[task 2020-11-18T01:12:41.365Z] 01:12:41     INFO - GECKO(2246) | ### XPCOM_MEM_BLOAT_LOG defined -- logging bloat/leaks to /tmp/tmpNDkNYA.mozrunner/runtests_leaks_tab_pid2973.log
[task 2020-11-18T01:12:41.366Z] 01:12:41     INFO - GECKO(2246) | [2973, Main Thread] WARNING: XPCOM_MEM_BLOAT_LOG is set, disabling native allocations.: file /builds/worker/checkouts/gecko/tools/profiler/core/platform.cpp:251
[task 2020-11-18T01:12:41.446Z] 01:12:41     INFO - GECKO(2246) | [Parent 2246: Main Thread]: I/DocShellAndDOMWindowLeak ++DOCSHELL 0x7f2115a4ec00 == 8 [pid = 2246] [id = 7]
[task 2020-11-18T01:12:41.446Z] 01:12:41     INFO - GECKO(2246) | [Parent 2246: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 15 (0x7f210e864e40) [pid = 2246] [serial = 16] [outer = (nil)]
[task 2020-11-18T01:12:41.448Z] 01:12:41     INFO - GECKO(2246) | [Parent 2246: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 16 (0x7f2115a4f800) [pid = 2246] [serial = 17] [outer = 0x7f210e864e40]
[task 2020-11-18T01:12:41.471Z] 01:12:41     INFO - GECKO(2246) | [Child 2973, Main Thread] WARNING: could not set real-time limit in CubebUtils::InitLibrary: file /builds/worker/checkouts/gecko/dom/media/CubebUtils.cpp:629
[task 2020-11-18T01:12:41.479Z] 01:12:41     INFO - GECKO(2246) | [Parent 2246, Main Thread] WARNING: NS_ENSURE_TRUE(rootFrame) failed: file /builds/worker/checkouts/gecko/dom/base/nsGlobalWindowOuter.cpp:4289
[task 2020-11-18T01:12:41.782Z] 01:12:41     INFO - GECKO(2246) | [Parent 2246: Main Thread]: I/DocShellAndDOMWindowLeak ++DOCSHELL 0x7f211cc88c00 == 9 [pid = 2246] [id = 8]
[task 2020-11-18T01:12:41.782Z] 01:12:41     INFO - GECKO(2246) | [Parent 2246: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 17 (0x7f2112a8c580) [pid = 2246] [serial = 18] [outer = (nil)]
[task 2020-11-18T01:12:41.979Z] 01:12:41     INFO - GECKO(2246) | [Parent 2246, Main Thread] WARNING: NS_ENSURE_TRUE(presShell) failed: file /builds/worker/checkouts/gecko/dom/base/nsGlobalWindowOuter.cpp:4287
[task 2020-11-18T01:12:41.994Z] 01:12:41     INFO - GECKO(2246) | [Parent 2246: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 18 (0x7f20fc203800) [pid = 2246] [serial = 19] [outer = 0x7f2112a8c580]
[task 2020-11-18T01:12:42.082Z] 01:12:42     INFO - GECKO(2246) | [Child 2879: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 6 (0x7febe7f9dc00) [pid = 2879] [serial = 6] [outer = 0x7fec04464ac0]
[task 2020-11-18T01:12:42.205Z] 01:12:42     INFO - GECKO(2246) | [Child 2487: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 0x7f272989e400 == 1 [pid = 2487] [id = 1] [url = about:blank]
[task 2020-11-18T01:12:42.490Z] 01:12:42     INFO - GECKO(2246) | [Child 2906: Main Thread]: I/DocShellAndDOMWindowLeak ++DOCSHELL 0x7f9af5145c00 == 1 [pid = 2906] [id = 0]
[task 2020-11-18T01:12:42.492Z] 01:12:42     INFO - GECKO(2246) | [Child 2906: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 1 (0x7f9af51e9040) [pid = 2906] [serial = 1] [outer = (nil)]
[task 2020-11-18T01:12:42.493Z] 01:12:42     INFO - GECKO(2246) | [Child 2906: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 2 (0x7f9af5146c00) [pid = 2906] [serial = 2] [outer = 0x7f9af51e9040]
[task 2020-11-18T01:12:42.519Z] 01:12:42     INFO - GECKO(2246) | [Child 2487: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 5 (0x7f27298ba3c0) [pid = 2487] [serial = 3] [outer = (nil)] [url = about:blank]
[task 2020-11-18T01:12:42.524Z] 01:12:42     INFO - GECKO(2246) | [Child 2487: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 4 (0x7f27298ba200) [pid = 2487] [serial = 1] [outer = (nil)] [url = about:blank]
[task 2020-11-18T01:12:42.684Z] 01:12:42     INFO - GECKO(2246) | [Child 2906, Main Thread] WARNING: NS_ENSURE_TRUE(info) failed: file /builds/worker/checkouts/gecko/extensions/permissions/PermissionDelegateHandler.cpp:348
[task 2020-11-18T01:12:42.721Z] 01:12:42     INFO - GECKO(2246) | [Child 2906: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 3 (0x7f9af5467000) [pid = 2906] [serial = 3] [outer = 0x7f9af51e9040]
[task 2020-11-18T01:12:42.722Z] 01:12:42     INFO - GECKO(2246) | ### XPCOM_MEM_BLOAT_LOG defined -- logging bloat/leaks to /tmp/tmpNDkNYA.mozrunner/runtests_leaks_tab_pid2998.log
[task 2020-11-18T01:12:42.722Z] 01:12:42     INFO - GECKO(2246) | [2998, Main Thread] WARNING: XPCOM_MEM_BLOAT_LOG is set, disabling native allocations.: file /builds/worker/checkouts/gecko/tools/profiler/core/platform.cpp:251
[task 2020-11-18T01:12:42.806Z] 01:12:42     INFO - GECKO(2246) | JavaScript error: , line 0: TypeError: Fullscreen request denied
[task 2020-11-18T01:12:42.962Z] 01:12:42     INFO - GECKO(2246) | [Child 2998, Main Thread] WARNING: could not set real-time limit in CubebUtils::InitLibrary: file /builds/worker/checkouts/gecko/dom/media/CubebUtils.cpp:629
[task 2020-11-18T01:12:46.292Z] 01:12:46     INFO - GECKO(2246) | [Child 2487: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 3 (0x7f2729848800) [pid = 2487] [serial = 2] [outer = (nil)] [url = about:blank]
[task 2020-11-18T01:12:46.293Z] 01:12:46     INFO - GECKO(2246) | [Child 2487: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 2 (0x7f272989f800) [pid = 2487] [serial = 4] [outer = (nil)] [url = about:blank]
[task 2020-11-18T01:12:47.534Z] 01:12:47     INFO - GECKO(2246) | [Parent 2246: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 0x7f20fea9b000 == 8 [pid = 2246] [id = 4] [url = about:blank]
[task 2020-11-18T01:12:47.534Z] 01:12:47     INFO - GECKO(2246) | [Parent 2246: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 0x7f20fea9cc00 == 7 [pid = 2246] [id = 5] [url = about:blank]
[task 2020-11-18T01:12:48.062Z] 01:12:48     INFO - GECKO(2246) | [Parent 2246: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 17 (0x7f20feab6740) [pid = 2246] [serial = 10] [outer = (nil)] [url = about:blank]
[task 2020-11-18T01:12:48.063Z] 01:12:48     INFO - GECKO(2246) | [Parent 2246: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 16 (0x7f20feab6ac0) [pid = 2246] [serial = 11] [outer = (nil)] [url = about:blank]
[task 2020-11-18T01:12:48.801Z] 01:12:48     INFO - GECKO(2246) | [Child 2385: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 0x7f4216749c00 == 0 [pid = 2385] [id = 3] [url = about:blank]
[task 2020-11-18T01:12:49.137Z] 01:12:49     INFO - GECKO(2246) | [Child 2879: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 0x7febe7f99c00 == 1 [pid = 2879] [id = 1] [url = about:blank]
[task 2020-11-18T01:12:51.864Z] 01:12:51     INFO - GECKO(2246) | [Parent 2246: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 15 (0x7f20feaa0000) [pid = 2246] [serial = 12] [outer = (nil)] [url = about:blank]
[task 2020-11-18T01:12:51.864Z] 01:12:51     INFO - GECKO(2246) | [Parent 2246: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 14 (0x7f20feaa0400) [pid = 2246] [serial = 13] [outer = (nil)] [url = about:blank]
[task 2020-11-18T01:12:52.872Z] 01:12:52     INFO - GECKO(2246) | [Child 2385: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 1 (0x7f42167c2040) [pid = 2385] [serial = 10] [outer = (nil)] [url = about:blank]
[task 2020-11-18T01:12:53.235Z] 01:12:53     INFO - GECKO(2246) | [Child 2879: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 5 (0x7febe7f46800) [pid = 2879] [serial = 2] [outer = (nil)] [url = about:blank]
[task 2020-11-18T01:12:53.235Z] 01:12:53     INFO - GECKO(2246) | [Child 2879: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 4 (0x7febe7f9ac00) [pid = 2879] [serial = 5] [outer = (nil)] [url = about:blank]
[task 2020-11-18T01:12:53.255Z] 01:12:53     INFO - GECKO(2246) | [Child 2879: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 3 (0x7fec04464ac0) [pid = 2879] [serial = 4] [outer = (nil)] [url = about:blank]
[task 2020-11-18T01:12:54.796Z] 01:12:54     INFO - GECKO(2246) | [Child 2385: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 0 (0x7f4216794000) [pid = 2385] [serial = 11] [outer = (nil)] [url = about:blank]
[task 2020-11-18T01:12:54.864Z] 01:12:54     INFO - GECKO(2246) | [Child 2906: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 2 (0x7f9af5146c00) [pid = 2906] [serial = 2] [outer = (nil)] [url = about:blank]
[task 2020-11-18T01:12:56.145Z] 01:12:56     INFO - GECKO(2246) | [Parent 2246, Main Thread] WARNING: Not implemented in the parent process!: file /builds/worker/checkouts/gecko/docshell/shistory/SessionHistoryEntry.cpp:506
[task 2020-11-18T01:12:57.309Z] 01:12:57     INFO - GECKO(2246) | [Child 2879: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 2 (0x7febe7f9dc00) [pid = 2879] [serial = 6] [outer = (nil)] [url = about:blank]
[task 2020-11-18T01:12:57.993Z] 01:12:57     INFO - GECKO(2246) | [Parent 2246, Main Thread] WARNING: Not implemented in the parent process!: file /builds/worker/checkouts/gecko/docshell/shistory/SessionHistoryEntry.cpp:506
[task 2020-11-18T01:14:10.837Z] 01:14:10     INFO - TEST-INFO | started process screentopng
[task 2020-11-18T01:14:11.062Z] 01:14:11     INFO - TEST-INFO | screentopng: exit 0
[task 2020-11-18T01:14:11.062Z] 01:14:11     INFO - Buffered messages logged at 01:12:40
[task 2020-11-18T01:14:11.062Z] 01:14:11     INFO - Entering test bound setup
[task 2020-11-18T01:14:11.063Z] 01:14:11     INFO - Leaving test bound setup
[task 2020-11-18T01:14:11.063Z] 01:14:11     INFO - Entering test bound test_parentWindowFocus
[task 2020-11-18T01:14:11.063Z] 01:14:11     INFO - Buffered messages logged at 01:12:41
[task 2020-11-18T01:14:11.063Z] 01:14:11     INFO - Calling window.open()
[task 2020-11-18T01:14:11.063Z] 01:14:11     INFO - Buffered messages logged at 01:12:42
[task 2020-11-18T01:14:11.063Z] 01:14:11     INFO - re-focusing main window
[task 2020-11-18T01:14:11.063Z] 01:14:11     INFO - must wait for focus
[task 2020-11-18T01:14:11.063Z] 01:14:11     INFO - Entering full-screen
[task 2020-11-18T01:14:11.063Z] 01:14:11     INFO - Console message: [JavaScript Warning: "Request for fullscreen was denied because requesting element is not in the currently focused tab." {file: "http://example.com/browser/browser/base/content/test/fullscreen/open_and_focus_helper.html" line: 0}]
[task 2020-11-18T01:14:11.063Z] 01:14:11     INFO - Console message: [JavaScript Error: "TypeError: Fullscreen request denied"]
[task 2020-11-18T01:14:11.064Z] 01:14:11     INFO - Buffered messages finished
[task 2020-11-18T01:14:11.066Z] 01:14:11     INFO - TEST-UNEXPECTED-FAIL | browser/base/content/test/fullscreen/browser_fullscreen_window_focus.js | Test timed out - 
[task 2020-11-18T01:14:11.069Z] 01:14:11     INFO - GECKO(2246) | MEMORY STAT | vsize 3310MB | residentFast 349MB | heapAllocated 99MB
[task 2020-11-18T01:14:11.085Z] 01:14:11     INFO - TEST-OK | browser/base/content/test/fullscreen/browser_fullscreen_window_focus.js | took 90026ms
[task 2020-11-18T01:14:11.086Z] 01:14:11     INFO - Not taking screenshot here: see the one that was previously logged
[task 2020-11-18T01:14:11.087Z] 01:14:11     INFO - TEST-UNEXPECTED-FAIL | browser/base/content/test/fullscreen/browser_fullscreen_window_focus.js | Found a tab after previous test timed out: http://example.com/browser/browser/base/content/test/fullscreen/open_and_focus_helper.html - 
[task 2020-11-18T01:14:11.088Z] 01:14:11     INFO - GECKO(2246) | [Child 2385: Main Thread]: I/DocShellAndDOMWindowLeak ++DOCSHELL 0x7f4216746800 == 1 [pid = 2385] [id = 4]
[task 2020-11-18T01:14:11.089Z] 01:14:11     INFO - GECKO(2246) | [Child 2385: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 1 (0x7f42167c2040) [pid = 2385] [serial = 12] [outer = (nil)]
[task 2020-11-18T01:14:11.090Z] 01:14:11     INFO - GECKO(2246) | [Child 2385: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 2 (0x7f4216793c00) [pid = 2385] [serial = 13] [outer = 0x7f42167c2040]
[task 2020-11-18T01:14:11.092Z] 01:14:11     INFO - checking window state
[task 2020-11-18T01:14:11.093Z] 01:14:11     INFO - Not taking screenshot here: see the one that was previously logged
[task 2020-11-18T01:14:11.094Z] 01:14:11     INFO - TEST-UNEXPECTED-FAIL | browser/base/content/test/fullscreen/browser_fullscreen_window_focus.js | Found a browser window after previous test timed out - 

Comment 1

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

Issue from bug 1618386 persists.

Comment 2

[Henri Sivonen (:hsivonen)]

Sigh. Let's see if at least the frequency gets lower, since at least it went from easily reproducible to not reproducing locally.

One thing to try would be to apply the mechanism that bug 1618386 applied to the active browsing context to focused browsing context as well. So far testing hasn't implicated focused browsing context, but reasoning suggests that it should get the same treatment.

Comment 3

[Intermittent Failures Robot]

8 failures in 4810 pushes (0.002 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 6
• try: 1
• mozilla-central: 1

Platform breakdown:

• linux1804-64: 8

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1677899&startday=2020-11-16&endday=2020-11-22&tree=all

Comment 4

[Intermittent Failures Robot]

6 failures in 1479 pushes (0.004 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 5
• mozilla-central: 1

Platform breakdown:

• linux1804-64: 6

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1677899&startday=2020-11-23&endday=2020-11-29&tree=all

Comment 5

[Henri Sivonen (:hsivonen)]

Attachment: Bug 1677899 - Ensure parent-managed order of setting the focused browsing context.

Comment 6

[Henri Sivonen (:hsivonen)]

At least the failure rate is now very low. The attached patch implements the idea from comment 2. I have no idea if it fixes the problem. Let's see if breaks anything:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=f068766797ae0e4d3cdbd498aa0f0da9e2554fdc

Comment 7

[Henri Sivonen (:hsivonen)]

The failure of dom/base/test/browser_bug1303838.js looks like it might be caused by the patch.

Comment 8

[Henri Sivonen (:hsivonen)]

(In reply to Henri Sivonen (:hsivonen) from comment #7)

The failure of dom/base/test/browser_bug1303838.js looks like it might be caused by the patch.

Can't repro locally, but a respin on try repros.

Also, browser/extensions/formautofill/test/browser/browser_remoteiframe.js looks like it could be caused by this patch.

Comment 9

[Henri Sivonen (:hsivonen)]

(In reply to Henri Sivonen (:hsivonen) from comment #8)

(In reply to Henri Sivonen (:hsivonen) from comment #7)

The failure of dom/base/test/browser_bug1303838.js looks like it might be caused by the patch.

Can't repro locally, but a respin on try repros.

Also, browser/extensions/formautofill/test/browser/browser_remoteiframe.js looks like it could be caused by this patch.

Sadly, the subject matter of the tests suggests that the breakage is related to what this patch is trying to do.

Relative to the situation without the patch, this patch makes racing content processes to take their place in the ordering at an earlier point than without the patch. The expected upside of the patch is that the ordering taken by active browsing context should be the same as the ordering taken by focused browsing context, which I hope to fix stuff.

Still unclear to me how exactly the breakage with the patch happens.

Comment 10

[Henri Sivonen (:hsivonen)]

(In reply to Henri Sivonen (:hsivonen) from comment #7)

The failure of dom/base/test/browser_bug1303838.js looks like it might be caused by the patch.

Let's see if Pernosco can repro this in the cloud.

Comment 11

[Intermittent Failures Robot]

11 failures in 3712 pushes (0.003 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 6
• try: 1
• mozilla-central: 4

Platform breakdown:

• linux1804-64: 10
• linux1804-64-shippable: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1677899&startday=2020-11-30&endday=2020-12-06&tree=all

Comment 12

[Intermittent Failures Robot]

10 failures in 4060 pushes (0.002 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 5
• try: 1
• autoland: 4

Platform breakdown:

• linux1804-64: 9
• linux1804-64-shippable: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1677899&startday=2020-12-07&endday=2020-12-13&tree=all

Comment 13

[Intermittent Failures Robot]

10 failures in 3421 pushes (0.003 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 3
• autoland: 5
• try: 2

Platform breakdown:

• linux1804-64-shippable: 1
• linux1804-64: 9

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1677899&startday=2020-12-14&endday=2020-12-20&tree=all

Comment 14

[Intermittent Failures Robot]

11 failures in 1450 pushes (0.008 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 7
• mozilla-central: 4

Platform breakdown:

• linux1804-64: 11

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1677899&startday=2020-12-21&endday=2020-12-27&tree=all

Comment 15

[Intermittent Failures Robot]

3 failures in 525 pushes (0.006 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 3

Platform breakdown:

• linux1804-64: 3

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1677899&startday=2020-12-28&endday=2021-01-03&tree=all

Comment 16

[Intermittent Failures Robot]

2 failures in 2956 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 1
• autoland: 1

Platform breakdown:

• linux1804-64-shippable: 1
• linux1804-64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1677899&startday=2021-01-04&endday=2021-01-10&tree=all

Comment 17

[Intermittent Failures Robot]

2 failures in 3810 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 2

Platform breakdown:

• linux1804-64: 1
• linux1804-64-shippable: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1677899&startday=2021-01-11&endday=2021-01-17&tree=all

Comment 18

[Bogdan Tara[:bogdan_tara | bogdant]]

The current spike seems to have been caused by bug 1659383.

Comment 19

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

Attachment: Bug 1677899 - disable browser_fullscreen_window_focus.js on Linux Fission as suggested by hsivonen. r=jmaher

Failures started after bug 1659383 had landed.

Comment 20

[Intermittent Failures Robot]

50 failures in 587 pushes (0.085 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 22
• mozilla-central: 28

Platform breakdown:

• linux1804-64: 36
• windows10-64-shippable-qr: 4
• windows10-64-shippable: 4
• linux1804-64-shippable: 6

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1677899&startday=2021-01-19&endday=2021-01-19&tree=all

Comment 21

[Intermittent Failures Robot]

27 failures in 649 pushes (0.042 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 14
• mozilla-central: 12
• try: 1

Platform breakdown:

• linux1804-64: 18
• linux1804-64-shippable: 3
• windows10-64-shippable-qr: 3
• windows10-64-shippable: 3

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1677899&startday=2021-01-20&endday=2021-01-20&tree=all

Comment 22

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/ec74c1b52c53
disable browser_fullscreen_window_focus.js on Linux Fission as suggested by hsivonen. r=jmaher

Comment 23

[Sandor Molnar[:smolnar]]

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

Comment 24

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

Attachment: Bug 1677899 - disable browser_fullscreen_window_focus.js also on Windows Fission. r=jmaher DONTBUILD

Only runs on central, so got missed when autoland got checked.

Comment 25

[Chris Peterson [:cpeterson]]

Bug 1677899 - disable browser_fullscreen_window_focus.js on Linux Fission as suggested by hsivonen. r=jmaher

Henri, this test is now disabled on macOS and Fission Linux. Do you think we need to debug and re-enable this test before we ship Fission MVP?

Comment 26

[Intermittent Failures Robot]

25 failures in 720 pushes (0.035 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 5
• mozilla-central: 18
• try: 2

Platform and build breakdown:

• linux1804-64: 9
  • debug: 9
• windows10-64-shippable-qr: 7
  • opt: 7
• windows10-64-shippable: 7
  • opt: 7
• linux1804-64-shippable: 2
  • opt: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1677899&startday=2021-01-21&endday=2021-01-21&tree=all

Comment 27

[Henri Sivonen (:hsivonen)]

(In reply to Chris Peterson [:cpeterson] from comment #25)

Bug 1677899 - disable browser_fullscreen_window_focus.js on Linux Fission as suggested by hsivonen. r=jmaher

Henri, this test is now disabled on macOS and Fission Linux. Do you think we need to debug and re-enable this test before we ship Fission MVP?

Neha already targeted this to M7. I'm starting the trace collection now.

Comment 28

[Henri Sivonen (:hsivonen)]

(In reply to Sebastian Hengst [:aryx] (needinfo on intermittent or backout) from comment #19)

Created attachment 9197872 [details]
Bug 1677899 - disable browser_fullscreen_window_focus.js on Linux Fission as suggested by hsivonen. r=jmaher

Failures started after bug 1659383 had landed.

Notably, the permission check added in that bug does not block anything when this test case runs.

Also, it looks like the two windows that leak are an inner window and an outer window that were created together even though the log shows different URLs for them.

Comment 29

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/1bf076c3f271
disable browser_fullscreen_window_focus.js also on Windows Fission. r=jmaher DONTBUILD

Comment 30

[Andreea Pavel [:apavel]]

https://hg.mozilla.org/mozilla-central/rev/1bf076c3f271

Comment 31

[Intermittent Failures Robot]

130 failures in 3488 pushes (0.037 failures/push) were associated with this bug in the last 7 days.

This is the #3 most frequent failure this week.

** This failure happened more than 75 times this week! Resolving this bug is a very high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 1 week, the affected test(s) may be disabled. **

Repository breakdown:

• autoland: 61
• mozilla-central: 66
• try: 3

Platform and build breakdown:

• linux1804-64: 83
  • debug: 83
• windows10-64-shippable-qr: 18
  • opt: 18
• windows10-64-shippable: 18
  • opt: 18
• linux1804-64-shippable: 11
  • opt: 11

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1677899&startday=2021-01-18&endday=2021-01-24&tree=all

Comment 32

[Henri Sivonen (:hsivonen)]

This is what I get out of the CC log:

known edges:
   0x7fc537e1d910 [Promise] --[mGlobal]--> 0x7fc533743000
   0x7fc5339e3100 [AnimationTimeline] --[mWindow]--> 0x7fc533743000
   0x7fc51b8d3c40 [Promise] --[mGlobal]--> 0x7fc533743000
   0x7fc533755c70 [Promise] --[mGlobal]--> 0x7fc533743000
   0x7fc51c483c60 [CustomElementRegistry] --[mWindow]--> 0x7fc533743000
   0x8945927c880 [JS Object (Window)] --[UnwrapDOMObject(obj)]--> 0x7fc533743000
   0x7fc528c6ee80 [Promise] --[mGlobal]--> 0x7fc533743000
   0x7fc53396f460 [DOMParser] --[mOwner]--> 0x7fc533743000
   0x7fc533480180 [PerformanceEntry] --[mParent]--> 0x7fc533743000
   0x7fc533743000 [nsGlobalWindowInner # 44 inner ] --[mTopInnerWindow]--> 0x7fc533743000
   0x7fc51b8d3280 [Promise] --[mGlobal]--> 0x7fc533743000
   0x7fc528ca2850 [Promise] --[mGlobal]--> 0x7fc533743000
   0x7fc51b871280 [Location] --[mInnerWindow]--> 0x7fc533743000
   0x7fc53375b3d0 [Localization] --[mGlobal]--> 0x7fc533743000
   0x7fc50f7b63c0 [PerformanceEntry] --[mParent]--> 0x7fc533743000
   0x7fc528c6e8b0 [Promise] --[mGlobal]--> 0x7fc533743000
   0x7fc51b8a9b80 [Promise] --[mGlobal]--> 0x7fc533743000

Comment 33

[Olli Pettay [:smaug][[e-mail]]]

is that concise or verbose log?

It is a tiny bit surprising to see all those promises. Why do we have them all alive?
Hmm, perhaps the log was concise and the relevant JS side is alive because they just are in the same page, which hasn't been GCed.

Or does FocusManager just keep stuff alive too long? It does explicitly clean up stuff during xpcom-shutdown.

Comment 34

[Henri Sivonen (:hsivonen)]

(In reply to Olli Pettay [:smaug] from comment #33)

is that concise or verbose log?

Whatever MOZ_CC_LOG_SHUTDOWN=1 MOZ_CC_ALL_TRACES=shutdown does.

It is a tiny bit surprising to see all those promises. Why do we have them all alive?

I'll try to see what I can find in Pernosco.

Or does FocusManager just keep stuff alive too long? It does explicitly clean up stuff during xpcom-shutdown.

These fields are all nullptr by the time of xpcom-shutdown, so it's not nsFocusManager keeping them alive until then.

Comment 35

[Henri Sivonen (:hsivonen)]

(In reply to Henri Sivonen (:hsivonen) from comment #32)

This is what I get out of the CC log:

known edges:
   0x7fc537e1d910 [Promise] --[mGlobal]--> 0x7fc533743000

From DocumentL10n::Init()

   0x7fc51b8d3c40 [Promise] --[mGlobal]--> 0x7fc533743000

From Document::GetDocumentReadyForIdle (from Document::EndLoad of a DOMParser-created doc.)

   0x7fc533755c70 [Promise] --[mGlobal]--> 0x7fc533743000

Likewise.

   0x7fc528c6ee80 [Promise] --[mGlobal]--> 0x7fc533743000

Likewise.

   0x7fc51b8d3280 [Promise] --[mGlobal]--> 0x7fc533743000

Likewise.

   0x7fc528ca2850 [Promise] --[mGlobal]--> 0x7fc533743000

Likewise.

   0x7fc528c6e8b0 [Promise] --[mGlobal]--> 0x7fc533743000

Likewise.

   0x7fc51b8a9b80 [Promise] --[mGlobal]--> 0x7fc533743000

Likewise.

Clearly, the next step is to figure out what's going on with that localization promise (which stays alive until shutdown), but I'm surprised that parsing something with DOMParser can spawn promises.

Comment 36

[Henri Sivonen (:hsivonen)]

Random remark:

The Promise created here: https://searchfox.org/mozilla-central/rev/0dfbe5a699cc6c73cf8c14d1aa10ba10ef3ec8fa/dom/l10n/DocumentL10n.cpp#151
...gets dropped here: https://searchfox.org/mozilla-central/rev/0dfbe5a699cc6c73cf8c14d1aa10ba10ef3ec8fa/dom/l10n/DocumentL10n.cpp#227
...but doesn't appear to destruct immediately but destructs later from cycle collection.

Comment 37

[Henri Sivonen (:hsivonen)]

(In reply to Henri Sivonen (:hsivonen) from comment #35)

(In reply to Henri Sivonen (:hsivonen) from comment #32)

This is what I get out of the CC log:

known edges:
   0x7fc537e1d910 [Promise] --[mGlobal]--> 0x7fc533743000

From DocumentL10n::Init()

This promise does get resolved by the l10n code.

Comment 38

[Henri Sivonen (:hsivonen)]

(In reply to Henri Sivonen (:hsivonen) from comment #37)

(In reply to Henri Sivonen (:hsivonen) from comment #35)

(In reply to Henri Sivonen (:hsivonen) from comment #32)

This is what I get out of the CC log:

known edges:
   0x7fc537e1d910 [Promise] --[mGlobal]--> 0x7fc533743000

From DocumentL10n::Init()

This promise does get resolved by the l10n code.

But DocumentL10n::mReady holds onto the Promise for the life time of DocumentL10n.

mReady is used here:
https://searchfox.org/mozilla-central/rev/0dfbe5a699cc6c73cf8c14d1aa10ba10ef3ec8fa/xpfe/appshell/AppWindow.cpp#3145

It gets used here: https://searchfox.org/mozilla-central/rev/0dfbe5a699cc6c73cf8c14d1aa10ba10ef3ec8fa/xpfe/appshell/AppWindow.cpp#3145

But that case is ifdefed out in the scenario that I'm debugging. (Still, what if that code runs later than the Promise is resolved?)

Comment 39

[Henri Sivonen (:hsivonen)]

(In reply to Henri Sivonen (:hsivonen) from comment #38)

But DocumentL10n::mReady holds onto the Promise for the life time of DocumentL10n.

This is not the problem.

Comment 40

[Henri Sivonen (:hsivonen)]

The most interesting finding so far is that a Document holds a weak ref to its scope object, but via Document::mDocumentL10n the ref is strong, which defeats the purpose of the weak ref, whatever the original design idea was relative to CC.

Comment 41

[Henri Sivonen (:hsivonen)]

Zibi, is a window leak due to DocumentL10n a known pattern with a known cure?

Comment 42

[Zibi Braniecki [:zbraniecki][:gandalf]]

it is not! Should we switch to weak ref?

Comment 43

[Olli Pettay [:smaug][[e-mail]]]

Each event listener on Document would keep a strong pointer to the scope object too, and I assume some other member variables too.

It seems like it is some missed edge which is the interesting piece here. Something which CC doesn't know about and thus it isn't in the log.

Comment 44

[Henri Sivonen (:hsivonen)]

(In reply to Olli Pettay [:smaug] from comment #43)

It seems like it is some missed edge which is the interesting piece here. Something which CC doesn't know about and thus it isn't in the log.

Yeah. Unfortunately, the custom elements cause so much refcount spam that it's hard to notice what else is going on.

Comment 45

[Henri Sivonen (:hsivonen)]

Without bug 1659383, the test relies on a hack that checks that the caller isn't JS (because the JS was in the other process) and the test passes that way.

Comment 46

[Henri Sivonen (:hsivonen)]

Attachment: Bug 1677899 - Trust the process where where focus() is called for focusability.

Comment 47

[Henri Sivonen (:hsivonen)]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=003e00814516e6664c91f6b5643136463dc224d2

Comment 48

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/8f5274b317cc
Trust the process where where focus() is called for focusability. r=nika

Comment 49

[Henri Sivonen (:hsivonen)]

Note to sheriff: The patch fixes the permafail. If this test comes back yet again as a low-frequency intermittent, let's mint yet another bug number for that.

Comment 50

[Atila Butkovits]

https://hg.mozilla.org/mozilla-central/rev/8f5274b317cc

Comment 51

[Natalia Csoregi [:nataliaCs]]

Still failing: https://treeherder.mozilla.org/logviewer?job_id=329454042&repo=autoland&lineNumber=4754

Comment 52

[Henri Sivonen (:hsivonen)]

(In reply to Natalia Csoregi [:nataliaCs] from comment #51)

Still failing: https://treeherder.mozilla.org/logviewer?job_id=329454042&repo=autoland&lineNumber=4754

Per comment 22, filed as bug 1691892. Let's close this one as fixing the permafail.

Comment 53

[Intermittent Failures Robot]

11 failures in 4322 pushes (0.003 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 11

Platform and build breakdown:

• windows7-32: 2
  • debug: 2
• windows10-64: 5
  • asan: 3
  • opt: 1
  • debug: 1
• windows10-64-qr: 2
  • opt: 1
  • debug: 1
• linux1804-64: 2
  • debug: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1677899&startday=2021-02-08&endday=2021-02-14&tree=all