1652352 - Intermittent TEST-UNEXPECTED-TIMEOUT | /fullscreen/api/document-exit-fullscreen-nested-shadow-dom.html | Exiting fullscreen from a nested shadow root works correctly. - Test timed out

Status: RESOLVED INCOMPLETE

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

Description

[Treeherder Bug Filer]

Filed by: malexandru [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=309512628&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/D1lD7NjeTi6swWNb6Rp6Og/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/D1lD7NjeTi6swWNb6Rp6Og/runs/0/artifacts/public/logs/live_backing.log&only_show_unexpected=1

---

[task 2020-07-12T17:21:26.879Z] 17:21:26     INFO - TEST-OK | /fullscreen/api/document-exit-fullscreen-nested-shadow-dom.html | took 1644ms
[task 2020-07-12T17:21:26.880Z] 17:21:26     INFO - TEST-START | /fullscreen/api/document-exit-fullscreen-nested-shadow-dom.html
[task 2020-07-12T17:21:26.880Z] 17:21:26     INFO - Run 1/10
[task 2020-07-12T17:21:26.953Z] 17:21:26     INFO - Closing window 42
[task 2020-07-12T17:21:27.036Z] 17:21:27     INFO - PID 1805 | [Parent 1805, Main Thread] WARNING: NS_ENSURE_TRUE(mPresShell) failed: file /builds/worker/checkouts/gecko/layout/generic/nsFrameSelection.cpp, line 1605
[task 2020-07-12T17:21:27.391Z] 17:21:27     INFO - PID 1805 | JavaScript error: resource://gre/modules/URIFixup.jsm, line 284: NS_ERROR_FAILURE: Should pass a non-null uri
[task 2020-07-12T17:21:27.753Z] 17:21:27     INFO - PID 1805 | [Child 1809, Main Thread] WARNING: NS_ENSURE_TRUE(info) failed: file /builds/worker/checkouts/gecko/extensions/permissions/PermissionDelegateHandler.cpp, line 351
[task 2020-07-12T17:21:27.754Z] 17:21:27     INFO - PID 1805 | [Child 1809, Main Thread] WARNING: NS_ENSURE_TRUE(wc) failed: file /builds/worker/checkouts/gecko/extensions/permissions/PermissionDelegateHandler.cpp, line 347
[task 2020-07-12T17:21:27.754Z] 17:21:27     INFO - PID 1805 | [Child 1811, Main Thread] WARNING: NS_ENSURE_TRUE(info) failed: file /builds/worker/checkouts/gecko/extensions/permissions/PermissionDelegateHandler.cpp, line 351
[task 2020-07-12T17:21:27.754Z] 17:21:27     INFO - PID 1805 | JavaScript error: , line 0: TypeError: Fullscreen request denied
[task 2020-07-12T17:21:28.262Z] 17:21:28     INFO - PID 1805 | 1594574488244	Marionette	WARN	TimedPromise timed out after 500 ms: stacktrace:
[task 2020-07-12T17:21:28.262Z] 17:21:28     INFO - PID 1805 | TimedPromise/<@chrome://marionette/content/sync.js:245:13
[task 2020-07-12T17:21:28.262Z] 17:21:28     INFO - PID 1805 | TimedPromise@chrome://marionette/content/sync.js:230:10
[task 2020-07-12T17:21:28.262Z] 17:21:28     INFO - PID 1805 | interaction.flushEventLoop@chrome://marionette/content/interaction.js:416:10
[task 2020-07-12T17:21:28.262Z] 17:21:28     INFO - PID 1805 | webdriverClickElement@chrome://marionette/content/interaction.js:182:31
[task 2020-07-12T17:21:49.058Z] 17:21:49     INFO - PID 1805 | 2020-07-12 17:21:49.024 firefox[1805:15041] Persistent UI failed to open file file:///Users/cltbld/Library/Saved%20Application%20State/org.mozilla.nightlydebug.savedState/window_1.data: No such file or directory (2)
[task 2020-07-12T17:21:57.849Z] 17:21:57     INFO - 
[task 2020-07-12T17:21:57.849Z] 17:21:57     INFO - TEST-UNEXPECTED-TIMEOUT | /fullscreen/api/document-exit-fullscreen-nested-shadow-dom.html | Exiting fullscreen from a nested shadow root works correctly. - Test timed out
[task 2020-07-12T17:21:57.849Z] 17:21:57     INFO - TEST-UNEXPECTED-ERROR | /fullscreen/api/document-exit-fullscreen-nested-shadow-dom.html | Unhandled rejection: Fullscreen request denied
[task 2020-07-12T17:21:57.849Z] 17:21:57     INFO - TEST-INFO took 30970ms
[task 2020-07-12T17:21:57.876Z] 17:21:57     INFO - PID 1805 | 1594574517866	Marionette	INFO	Stopped listening on port 50112
[task 2020-07-12T17:21:58.150Z] 17:21:58     INFO - PID 1805 | [Child 1808, Main Thread] WARNING: nsAppShell::Exit() called redundantly: file /builds/worker/checkouts/gecko/widget/cocoa/nsAppShell.mm, line 714
[task 2020-07-12T17:21:58.150Z] 17:21:58     INFO - PID 1805 | [Child 1809, Main Thread] WARNING: nsAppShell::Exit() called redundantly: file /builds/worker/checkouts/gecko/widget/cocoa/nsAppShell.mm, line 714
[task 2020-07-12T17:21:58.151Z] 17:21:58     INFO - PID 1805 | [Child 1811, Main Thread] WARNING: IPC message discarded: actor cannot send: file /builds/worker/checkouts/gecko/ipc/glue/ProtocolUtils.cpp, line 470
[task 2020-07-12T17:21:58.152Z] 17:21:58     INFO - PID 1805 | [Child 1811, Main Thread] WARNING: nsAppShell::Exit() called redundantly: file /builds/worker/checkouts/gecko/widget/cocoa/nsAppShell.mm, line 714
[task 2020-07-12T17:21:58.152Z] 17:21:58     INFO - PID 1805 | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2020-07-12T17:21:58.152Z] 17:21:58     INFO - PID 1805 | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2020-07-12T17:21:58.266Z] 17:21:58     INFO - PID 1805 | [Child 1809, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.cpp, line 3359
[task 2020-07-12T17:21:58.266Z] 17:21:58     INFO - PID 1805 | [Child 1809, Main Thread] WARNING: NS_ENSURE_TRUE(Preferences::InitStaticMembers()) failed: file /builds/worker/checkouts/gecko/modules/libpref/Preferences.cpp, line 4382
[task 2020-07-12T17:21:58.301Z] 17:21:58     INFO - PID 1805 | [Child 1808, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.cpp, line 3359
[task 2020-07-12T17:21:58.320Z] 17:21:58     INFO - PID 1805 | [Child 1808, Main Thread] WARNING: NS_ENSURE_TRUE(Preferences::InitStaticMembers()) failed: file /builds/worker/checkouts/gecko/modules/libpref/Preferences.cpp, line 4382
[task 2020-07-12T17:21:58.368Z] 17:21:58     INFO - PID 1805 | [Child 1811, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.cpp, line 3359
[task 2020-07-12T17:21:58.368Z] 17:21:58     INFO - PID 1805 | [Child 1811, Main Thread] WARNING: NS_ENSURE_TRUE(Preferences::InitStaticMembers()) failed: file /builds/worker/checkouts/gecko/modules/libpref/Preferences.cpp, line 4382
[task 2020-07-12T17:21:58.825Z] 17:21:58     INFO - PID 1805 | [2020-07-12T17:21:58Z WARN  xulstore::persist] tried to remove key that isn't in the store
[task 2020-07-12T17:21:58.825Z] 17:21:58     INFO - PID 1805 | [2020-07-12T17:21:58Z WARN  xulstore::persist] tried to remove key that isn't in the store
[task 2020-07-12T17:21:58.859Z] 17:21:58     INFO - PID 1805 | [Child 1810, Main Thread] WARNING: nsAppShell::Exit() called redundantly: file /builds/worker/checkouts/gecko/widget/cocoa/nsAppShell.mm, line 714
[task 2020-07-12T17:21:58.859Z] 17:21:58     INFO - PID 1805 | [Child 1812, Main Thread] WARNING: nsAppShell::Exit() called redundantly: file /builds/worker/checkouts/gecko/widget/cocoa/nsAppShell.mm, line 714
[task 2020-07-12T17:21:58.859Z] 17:21:58     INFO - PID 1805 | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2020-07-12T17:21:58.886Z] 17:21:58     INFO - PID 1805 | [Child 1812, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.cpp, line 3359
[task 2020-07-12T17:21:58.886Z] 17:21:58     INFO - PID 1805 | [Child 1812, Main Thread] WARNING: NS_ENSURE_TRUE(Preferences::InitStaticMembers()) failed: file /builds/worker/checkouts/gecko/modules/libpref/Preferences.cpp, line 4382
[task 2020-07-12T17:21:59.046Z] 17:21:59     INFO - PID 1805 | [Child 1810, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.cpp, line 3359
[task 2020-07-12T17:21:59.069Z] 17:21:59     INFO - PID 1805 | [Parent 1805, Main Thread] WARNING: NS_ENSURE_TRUE(mDB) failed: file /builds/worker/checkouts/gecko/netwerk/cache/nsDiskCacheDeviceSQL.cpp, line 1277
[task 2020-07-12T17:21:59.069Z] 17:21:59     INFO - PID 1805 | [Child 1810, Main Thread] WARNING: NS_ENSURE_TRUE(Preferences::InitStaticMembers()) failed: file /builds/worker/checkouts/gecko/modules/libpref/Preferences.cpp, line 4382
[task 2020-07-12T17:21:59.071Z] 17:21:59     INFO - PID 1805 | [Parent 1805, Main Thread] WARNING: nsAppShell::Exit() called redundantly: file /builds/worker/checkouts/gecko/widget/cocoa/nsAppShell.mm, line 714
[task 2020-07-12T17:21:59.118Z] 17:21:59     INFO - PID 1805 | [Parent 1805, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005 (NS_ERROR_FAILURE): file /builds/worker/checkouts/gecko/js/xpconnect/loader/mozJSComponentLoader.cpp, line 228
[task 2020-07-12T17:21:59.118Z] 17:21:59     INFO - PID 1805 | [Parent 1805, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005 (NS_ERROR_FAILURE): file /builds/worker/checkouts/gecko/js/xpconnect/loader/mozJSComponentLoader.cpp, line 255
[task 2020-07-12T17:21:59.868Z] 17:21:59     INFO - PID 1805 | [Parent 1805, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.cpp, line 3359
[task 2020-07-12T17:21:59.912Z] 17:21:59     INFO - PID 1805 | [Parent 1805, Main Thread] WARNING: NS_ENSURE_TRUE(Preferences::InitStaticMembers()) failed: file /builds/worker/checkouts/gecko/modules/libpref/Preferences.cpp, line 4382
[task 2020-07-12T17:22:00.094Z] 17:22:00     INFO - Browser exited with return code 0
[task 2020-07-12T17:22:00.094Z] 17:22:00     INFO - PROCESS LEAKS /var/folders/xv/3xxj0xb94_n925ll_qw2y67w000017/T/tmppq9P8S/runtests_leaks_1781.log
[task 2020-07-12T17:22:00.094Z] 17:22:00     INFO - leakcheck | Processing log file /var/folders/xv/3xxj0xb94_n925ll_qw2y67w000017/T/tmppq9P8S/runtests_leaks_1781.log for scope /
[task 2020-07-12T17:22:00.094Z] 17:22:00     INFO - TEST-INFO | leakcheck | default process: leak threshold set at 2100 bytes
[task 2020-07-12T17:22:00.094Z] 17:22:00     INFO - TEST-INFO | leakcheck | forkserver process: leak threshold set at 0 bytes
[task 2020-07-12T17:22:00.094Z] 17:22:00     INFO - TEST-INFO | leakcheck | gmplugin process: leak threshold set at 20000 bytes
[task 2020-07-12T17:22:00.095Z] 17:22:00     INFO - TEST-INFO | leakcheck | gpu process: leak threshold set at 0 bytes
[task 2020-07-12T17:22:00.095Z] 17:22:00     INFO - TEST-INFO | leakcheck | plugin process: leak threshold set at 0 bytes
[task 2020-07-12T17:22:00.095Z] 17:22:00     INFO - TEST-INFO | leakcheck | rdd process: leak threshold set at 400 bytes
[task 2020-07-12T17:22:00.095Z] 17:22:00     INFO - TEST-INFO | leakcheck | socket process: leak threshold set at 0 bytes
[task 2020-07-12T17:22:00.095Z] 17:22:00     INFO - TEST-INFO | leakcheck | tab process: leak threshold set at 10000 bytes
[task 2020-07-12T17:22:00.095Z] 17:22:00     INFO - TEST-INFO | leakcheck | vr process: leak threshold set at 0 bytes
[task 2020-07-12T17:22:00.096Z] 17:22:00     INFO - leakcheck | Processing leak log file /var/folders/xv/3xxj0xb94_n925ll_qw2y67w000017/T/tmppq9P8S/runtests_leaks_1781_tab_pid1812.log
[task 2020-07-12T17:22:00.096Z] 17:22:00     INFO - 
[task 2020-07-12T17:22:00.096Z] 17:22:00     INFO - == BloatView: ALL (cumulative) LEAK AND BLOAT STATISTICS, tab process 1812
[task 2020-07-12T17:22:00.096Z] 17:22:00     INFO - 
[task 2020-07-12T17:22:00.097Z] 17:22:00     INFO -      |<----------------Class--------------->|<-----Bytes------>|<----Objects---->|
[task 2020-07-12T17:22:00.097Z] 17:22:00     INFO -      |                                      | Per-Inst   Leaked|   Total      Rem|
[task 2020-07-12T17:22:00.097Z] 17:22:00     INFO -    0 |TOTAL                                 |       35        0|   16422        0|
[task 2020-07-12T17:22:00.097Z] 17:22:00     INFO - 
[task 2020-07-12T17:22:00.097Z] 17:22:00     INFO - nsTraceRefcnt::DumpStatistics: 392 entries
[task 2020-07-12T17:22:00.098Z] 17:22:00     INFO - TEST-PASS | leakcheck | tab no leaks detected!
[task 2020-07-12T17:22:00.098Z] 17:22:00     INFO - leakcheck | Processing leak log file /var/folders/xv/3xxj0xb94_n925ll_qw2y67w000017/T/tmppq9P8S/runtests_leaks_1781_tab_pid1811.log
[task 2020-07-12T17:22:00.098Z] 17:22:00     INFO - 
[task 2020-07-12T17:22:00.098Z] 17:22:00     INFO - == BloatView: ALL (cumulative) LEAK AND BLOAT STATISTICS, tab process 1811
[task 2020-07-12T17:22:00.098Z] 17:22:00     INFO - 
[task 2020-07-12T17:22:00.099Z] 17:22:00     INFO -      |<----------------Class--------------->|<-----Bytes------>|<----Objects---->|
[task 2020-07-12T17:22:00.099Z] 17:22:00     INFO -      |                                      | Per-Inst   Leaked|   Total      Rem|
[task 2020-07-12T17:22:00.099Z] 17:22:00     INFO -    0 |TOTAL                                 |       37        0|  130368        0|
[task 2020-07-12T17:22:00.099Z] 17:22:00     INFO - 
[task 2020-07-12T17:22:00.099Z] 17:22:00     INFO - nsTraceRefcnt::DumpStatistics: 974 entries
[task 2020-07-12T17:22:00.100Z] 17:22:00     INFO - TEST-PASS | leakcheck | tab no leaks detected!
[task 2020-07-12T17:22:00.102Z] 17:22:00     INFO - leakcheck | Processing leak log file /var/folders/xv/3xxj0xb94_n925ll_qw2y67w000017/T/tmppq9P8S/runtests_leaks_1781_tab_pid1810.log
[task 2020-07-12T17:22:00.102Z] 17:22:00     INFO - 
[task 2020-07-12T17:22:00.102Z] 17:22:00     INFO - == BloatView: ALL (cumulative) LEAK AND BLOAT STATISTICS, tab process 1810
[task 2020-07-12T17:22:00.102Z] 17:22:00     INFO - 
[task 2020-07-12T17:22:00.103Z] 17:22:00     INFO -      |<----------------Class--------------->|<-----Bytes------>|<----Objects---->|
[task 2020-07-12T17:22:00.103Z] 17:22:00     INFO -      |                                      | Per-Inst   Leaked|   Total      Rem|
[task 2020-07-12T17:22:00.103Z] 17:22:00     INFO -    0 |TOTAL                                 |       29        0|  361041        0|
[task 2020-07-12T17:22:00.105Z] 17:22:00     INFO - 
[task 2020-07-12T17:22:00.105Z] 17:22:00     INFO - nsTraceRefcnt::DumpStatistics: 1014 entries
[task 2020-07-12T17:22:00.105Z] 17:22:00     INFO - TEST-PASS | leakcheck | tab no leaks detected!
[task 2020-07-12T17:22:00.105Z] 17:22:00     INFO - leakcheck | Processing leak log file /var/folders/xv/3xxj0xb94_n925ll_qw2y67w000017/T/tmppq9P8S/runtests_leaks_1781.log

Comment 1

[Intermittent Failures Robot]

1 failures in 5265 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 1

Platform breakdown:

• macosx1014-64: 1

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

Comment 2

[Emilio Cobos Álvarez [:emilio]]

We get a "Fullscreen request denied"... I wonder what's up with that...

James, when fullscreen is denied we reject a promise with a generic message ("Fullscreen request denied"), and then send a more detailed message to devtools via the console service.

I think mochitests do print the console.log lines and other messages in the test... It seems WPT doesn't? That could help figure out stuff like this... I'm happy to help out implementing it if worthwhile, if you give me pointers.

Comment 3

[BugBot [:suhaib / :marco]]

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

Comment 4

[James Graham [:jgraham]]

I'm not sure what mochitest does, but it maybe it would work to just set user_pref("devtools.console.stdout.content", true) either in testing/profiles/web-platform/user.js or in the firefox.py file.

Comment 5

[Intermittent Failures Robot]

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

Repository breakdown:

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

Platform breakdown:

• macosx1014-64: 5
• macosx1014-64-shippable: 5

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

Comment 6

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 2

Platform breakdown:

• macosx1014-64-shippable: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1652352&startday=2020-07-20&endday=2020-07-26&tree=all

Comment 7

[BugBot [:suhaib / :marco]]

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

Comment 8

[Intermittent Failures Robot]

1 failures in 4195 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 1

Platform breakdown:

• macosx1014-64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1652352&startday=2020-09-28&endday=2020-10-04&tree=all

Comment 9

[BugBot [:suhaib / :marco]]

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

Comment 10

[Cristian Brindusan [:cbrindusan]]

New occurrence:
https://treeherder.mozilla.org/logviewer?job_id=325371625&repo=mozilla-central&lineNumber=13851

Comment 11

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-central: 1

Platform breakdown:

• macosx1014-64-qr: 1

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

Comment 12

[BugBot [:suhaib / :marco]]

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

Comment 13

[Noemi Erli[:noemi_erli]]

recent failure: https://treeherder.mozilla.org/logviewer?job_id=333783205&repo=autoland&lineNumber=8991

Comment 14

[Intermittent Failures Robot]

1 failures in 4257 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 1

Platform and build breakdown:

• macosx1014-64-qr: 1
  • debug: 1

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

Comment 15

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 2

Platform and build breakdown:

• macosx1014-64-qr: 2
  • debug: 2

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

Comment 16

[BugBot [:suhaib / :marco]]

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