Intermittent devtools/shared/commands/target/tests/browser_target_command_service_workers_navigation.js | Test timed out -
Categories
(DevTools :: General, defect, P5)
Tracking
(firefox-esr78 unaffected, firefox-esr91 unaffected, firefox91 unaffected, firefox92 unaffected, firefox93 affected)
Tracking | Status | |
---|---|---|
firefox-esr78 | --- | unaffected |
firefox-esr91 | --- | unaffected |
firefox91 | --- | unaffected |
firefox92 | --- | unaffected |
firefox93 | --- | affected |
People
(Reporter: intermittent-bug-filer, Assigned: nchevobbe)
References
(Blocks 1 open bug)
Details
(Keywords: intermittent-failure, Whiteboard: [stockwell disabled][stockwell unknown])
Attachments
(3 files)
Filed by: cbrindusan [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=348754427&repo=mozilla-central
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/LgYOkpEjQk-73_d3QRMehg/runs/0/artifacts/public/logs/live_backing.log
[task 2021-08-17T23:56:00.703Z] 23:56:00 INFO - TEST-START | devtools/shared/commands/target/tests/browser_target_command_service_workers_navigation.js
[task 2021-08-17T23:56:45.718Z] 23:56:45 INFO - TEST-INFO | started process screentopng
[task 2021-08-17T23:56:46.345Z] 23:56:46 INFO - TEST-INFO | screentopng: exit 0
[task 2021-08-17T23:56:46.347Z] 23:56:46 INFO - Buffered messages logged at 23:56:00
[task 2021-08-17T23:56:46.348Z] 23:56:46 INFO - Entering test bound test_NavigationBetweenTwoDomains_NoDestroy
[task 2021-08-17T23:56:46.348Z] 23:56:46 INFO - Adding a new tab with URL: https://example.com/browser/devtools/shared/commands/target/tests/test_sw_page.html
[task 2021-08-17T23:56:46.349Z] 23:56:46 INFO - Buffered messages logged at 23:56:01
[task 2021-08-17T23:56:46.350Z] 23:56:46 INFO - Tab added and finished loading
[task 2021-08-17T23:56:46.353Z] 23:56:46 INFO - Create a target list for a tab target
[task 2021-08-17T23:56:46.353Z] 23:56:46 INFO - Set targetCommand.destroyServiceWorkersOnNavigation to false
[task 2021-08-17T23:56:46.354Z] 23:56:46 INFO - Wait for availableCount=1 and destroyedCount=0
[task 2021-08-17T23:56:46.354Z] 23:56:46 INFO - TEST-PASS | devtools/shared/commands/target/tests/browser_target_command_service_workers_navigation.js | onAvailable was called as expected -
[task 2021-08-17T23:56:46.355Z] 23:56:46 INFO - TEST-PASS | devtools/shared/commands/target/tests/browser_target_command_service_workers_navigation.js | onDestroyed was called as expected -
[task 2021-08-17T23:56:46.355Z] 23:56:46 INFO - TEST-PASS | devtools/shared/commands/target/tests/browser_target_command_service_workers_navigation.js | Expected number of targets -
[task 2021-08-17T23:56:46.356Z] 23:56:46 INFO - TEST-PASS | devtools/shared/commands/target/tests/browser_target_command_service_workers_navigation.js | SW target 0 has the expected url -
[task 2021-08-17T23:56:46.356Z] 23:56:46 INFO - Go to .org page, wait for onAvailable to be called
[task 2021-08-17T23:56:46.356Z] 23:56:46 INFO - Wait for availableCount=2 and destroyedCount=0
[task 2021-08-17T23:56:46.357Z] 23:56:46 INFO - TEST-PASS | devtools/shared/commands/target/tests/browser_target_command_service_workers_navigation.js | onAvailable was called as expected -
[task 2021-08-17T23:56:46.358Z] 23:56:46 INFO - TEST-PASS | devtools/shared/commands/target/tests/browser_target_command_service_workers_navigation.js | onDestroyed was called as expected -
[task 2021-08-17T23:56:46.359Z] 23:56:46 INFO - TEST-PASS | devtools/shared/commands/target/tests/browser_target_command_service_workers_navigation.js | Expected number of targets -
[task 2021-08-17T23:56:46.360Z] 23:56:46 INFO - TEST-PASS | devtools/shared/commands/target/tests/browser_target_command_service_workers_navigation.js | SW target 0 has the expected url -
[task 2021-08-17T23:56:46.364Z] 23:56:46 INFO - TEST-PASS | devtools/shared/commands/target/tests/browser_target_command_service_workers_navigation.js | SW target 1 has the expected url -
[task 2021-08-17T23:56:46.364Z] 23:56:46 INFO - Reload .org page, onAvailable and onDestroyed should not be called
[task 2021-08-17T23:56:46.366Z] 23:56:46 INFO - Wait for availableCount=2 and destroyedCount=0
[task 2021-08-17T23:56:46.367Z] 23:56:46 INFO - TEST-PASS | devtools/shared/commands/target/tests/browser_target_command_service_workers_navigation.js | onAvailable was called as expected -
[task 2021-08-17T23:56:46.367Z] 23:56:46 INFO - TEST-PASS | devtools/shared/commands/target/tests/browser_target_command_service_workers_navigation.js | onDestroyed was called as expected -
[task 2021-08-17T23:56:46.368Z] 23:56:46 INFO - TEST-PASS | devtools/shared/commands/target/tests/browser_target_command_service_workers_navigation.js | Expected number of targets -
[task 2021-08-17T23:56:46.368Z] 23:56:46 INFO - TEST-PASS | devtools/shared/commands/target/tests/browser_target_command_service_workers_navigation.js | SW target 0 has the expected url -
[task 2021-08-17T23:56:46.370Z] 23:56:46 INFO - TEST-PASS | devtools/shared/commands/target/tests/browser_target_command_service_workers_navigation.js | SW target 1 has the expected url -
[task 2021-08-17T23:56:46.370Z] 23:56:46 INFO - Unregister .org service worker and wait until onDestroyed is called.
[task 2021-08-17T23:56:46.371Z] 23:56:46 INFO - Wait for availableCount=2 and destroyedCount=1
[task 2021-08-17T23:56:46.371Z] 23:56:46 INFO - Buffered messages finished
[task 2021-08-17T23:56:46.371Z] 23:56:46 INFO - TEST-UNEXPECTED-FAIL | devtools/shared/commands/target/tests/browser_target_command_service_workers_navigation.js | Test timed out -
Comment 1•3 years ago
|
||
Failure from bug 1702715?
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Assignee | ||
Comment 5•3 years ago
|
||
I'm going to investigate
Assignee | ||
Comment 6•3 years ago
|
||
looks like we're not getting the expected target destruction in https://searchfox.org/mozilla-central/rev/fdcee847713a33b5e2b4175bb3c72d4aa2215515/devtools/shared/commands/target/tests/browser_target_command_service_workers_navigation.js#81-87
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment 11•3 years ago
|
||
There are 70 total failures in the last 7 days on
- linux1804-64-qr debug and opt
- linux1804-64-shippable-qr opt
- windows10-64-2004-qr debug and opt
- windows10-64-2004-shippable-qr opt
Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=352671968&repo=autoland&lineNumber=29451
[task 2021-09-24T19:43:07.090Z] 19:43:07 INFO - TEST-PASS | devtools/shared/commands/target/tests/browser_target_command_service_workers_navigation.js | Expected number of targets -
[task 2021-09-24T19:43:07.090Z] 19:43:07 INFO - TEST-PASS | devtools/shared/commands/target/tests/browser_target_command_service_workers_navigation.js | SW target 0 has the expected url -
[task 2021-09-24T19:43:07.091Z] 19:43:07 INFO - Unregister .com service worker and wait until onDestroyed is called.
[task 2021-09-24T19:43:07.091Z] 19:43:07 INFO - Wait for availableCount=2 and destroyedCount=2
[task 2021-09-24T19:43:07.092Z] 19:43:07 INFO - Buffered messages finished
[task 2021-09-24T19:43:07.092Z] 19:43:07 INFO - TEST-UNEXPECTED-FAIL | devtools/shared/commands/target/tests/browser_target_command_service_workers_navigation.js | Test timed out -
[task 2021-09-24T19:43:07.093Z] 19:43:07 INFO - Removing tab.
[task 2021-09-24T19:43:07.093Z] 19:43:07 INFO - Waiting for event: 'TabClose' on [object XULElement].
[task 2021-09-24T19:43:07.093Z] 19:43:07 INFO - Got event: 'TabClose' on [object XULElement].
[task 2021-09-24T19:43:07.094Z] 19:43:07 INFO - Tab removed and finished closing
[task 2021-09-24T19:43:07.095Z] 19:43:07 INFO - TEST-PASS | devtools/shared/commands/target/tests/browser_target_command_service_workers_navigation.js | The main process DevToolsServer has no pending connection when the test ends -
[task 2021-09-24T19:43:07.095Z] 19:43:07 INFO - GECKO(7328) | MEMORY STAT | vsize 3317MB | residentFast 539MB | heapAllocated 233MB
[task 2021-09-24T19:43:07.096Z] 19:43:07 INFO - TEST-OK | devtools/shared/commands/target/tests/browser_target_command_service_workers_navigation.js | took 90399ms
[task 2021-09-24T19:43:07.096Z] 19:43:07 INFO - GECKO(7328) | [Child 8563, Main Thread] WARNING: NS_ENSURE_TRUE(!mHasOrHasHadOwnerWindow || mOwnerWindow) failed: file /builds/worker/checkouts/gecko/dom/events/DOMEventTargetHelper.cpp:327
[task 2021-09-24T19:43:07.100Z] 19:43:07 INFO - GECKO(7328) | [Child 8507, Main Thread] WARNING: NS_ENSURE_TRUE(!mHasOrHasHadOwnerWindow || mOwnerWindow) failed: file /builds/worker/checkouts/gecko/dom/events/DOMEventTargetHelper.cpp:327
[task 2021-09-24T19:43:07.113Z] 19:43:07 INFO - GECKO(7328) | [Child 8427: Main Thread]: I/DocShellAndDOMWindowLeak ++DOCSHELL 7f7997950000 == 1 [pid = 8427] [id = 2]
[task 2021-09-24T19:43:07.114Z] 19:43:07 INFO - GECKO(7328) | [Child 8427: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 1 (7f79b27643c0) [pid = 8427] [serial = 6] [outer = 0]
[task 2021-09-24T19:43:07.114Z] 19:43:07 INFO - GECKO(7328) | [Child 8427: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 2 (7f7997952000) [pid = 8427] [serial = 7] [outer = 7f79b27643c0]
[task 2021-09-24T19:43:07.199Z] 19:43:07 INFO - checking window state
[task 2021-09-24T19:43:07.251Z] 19:43:07 INFO - GECKO(7328) | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2021-09-24T19:43:07.267Z] 19:43:07 INFO - GECKO(7328) | [Child 8563, Main Thread] WARNING: IPC message discarded: actor cannot send: file /builds/worker/checkouts/gecko/ipc/glue/ProtocolUtils.cpp:527
[task 2021-09-24T19:43:07.274Z] 19:43:07 INFO - GECKO(7328) | [Child 8507: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 7fc7fcd21400 == 0 [pid = 8507] [id = 0] [url = https://example.com/browser/devtools/shared/commands/target/tests/test_sw_page.html]
[task 2021-09-24T19:43:07.275Z] 19:43:07 INFO - GECKO(7328) | [Child 8507, Main Thread] WARNING: IPC message discarded: actor cannot send: file /builds/worker/checkouts/gecko/ipc/glue/ProtocolUtils.cpp:527
[task 2021-09-24T19:43:07.276Z] 19:43:07 INFO - GECKO(7328) | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2021-09-24T19:43:07.290Z] 19:43:07 INFO - GECKO(7328) | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2021-09-24T19:43:07.294Z] 19:43:07 INFO - GECKO(7328) | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2021-09-24T19:43:07.298Z] 19:43:07 INFO - GECKO(7328) | [Child 8535: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 7f65cd621800 == 0 [pid = 8535] [id = 0] [url = https://example.org/browser/devtools/shared/commands/target/tests/test_sw_page.html]
[task 2021-09-24T19:43:07.299Z] 19:43:07 INFO - GECKO(7328) | [Child 8535, Main Thread] WARNING: IPC message discarded: actor cannot send: file /builds/worker/checkouts/gecko/ipc/glue/ProtocolUtils.cpp:527
Nicholas, are you working on this?
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment 14•3 years ago
|
||
Comment 15•3 years ago
|
||
Updated•3 years ago
|
Comment 16•3 years ago
|
||
bugherder |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment 24•3 years ago
|
||
There are 51 total failures in the last 7 days on
- linux1804-64-qr debug
- macosx1015-64-qr debug
- windows10-32-2004-qr opt and debug
Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=359065017&repo=autoland&lineNumber=23691
[task 2021-11-24T04:20:59.626Z] 04:20:59 INFO - Buffered messages logged at 04:19:32
[task 2021-11-24T04:20:59.627Z] 04:20:59 INFO - Wait for availableCount=2 and destroyedCount=1
[task 2021-11-24T04:20:59.628Z] 04:20:59 INFO - TEST-PASS | devtools/shared/commands/target/tests/browser_target_command_service_workers_navigation.js | onAvailable was called as expected -
[task 2021-11-24T04:20:59.629Z] 04:20:59 INFO - TEST-PASS | devtools/shared/commands/target/tests/browser_target_command_service_workers_navigation.js | onDestroyed was called as expected -
[task 2021-11-24T04:20:59.630Z] 04:20:59 INFO - TEST-PASS | devtools/shared/commands/target/tests/browser_target_command_service_workers_navigation.js | Expected number of targets -
[task 2021-11-24T04:20:59.637Z] 04:20:59 INFO - TEST-PASS | devtools/shared/commands/target/tests/browser_target_command_service_workers_navigation.js | SW target 0 has the expected url -
[task 2021-11-24T04:20:59.638Z] 04:20:59 INFO - Go back to .com page
[task 2021-11-24T04:20:59.639Z] 04:20:59 INFO - Wait for availableCount=2 and destroyedCount=1
[task 2021-11-24T04:20:59.640Z] 04:20:59 INFO - TEST-PASS | devtools/shared/commands/target/tests/browser_target_command_service_workers_navigation.js | onAvailable was called as expected -
[task 2021-11-24T04:20:59.641Z] 04:20:59 INFO - TEST-PASS | devtools/shared/commands/target/tests/browser_target_command_service_workers_navigation.js | onDestroyed was called as expected -
[task 2021-11-24T04:20:59.642Z] 04:20:59 INFO - TEST-PASS | devtools/shared/commands/target/tests/browser_target_command_service_workers_navigation.js | Expected number of targets -
[task 2021-11-24T04:20:59.643Z] 04:20:59 INFO - TEST-PASS | devtools/shared/commands/target/tests/browser_target_command_service_workers_navigation.js | SW target 0 has the expected url -
[task 2021-11-24T04:20:59.644Z] 04:20:59 INFO - Unregister .com service worker and wait until onDestroyed is called.
[task 2021-11-24T04:20:59.645Z] 04:20:59 INFO - Wait for availableCount=2 and destroyedCount=2
[task 2021-11-24T04:20:59.648Z] 04:20:59 INFO - Buffered messages finished
[task 2021-11-24T04:20:59.648Z] 04:20:59 INFO - TEST-UNEXPECTED-FAIL | devtools/shared/commands/target/tests/browser_target_command_service_workers_navigation.js | Test timed out -
[task 2021-11-24T04:20:59.648Z] 04:20:59 INFO - Removing tab.
[task 2021-11-24T04:20:59.648Z] 04:20:59 INFO - Waiting for event: 'TabClose' on [object XULElement].
[task 2021-11-24T04:20:59.648Z] 04:20:59 INFO - Got event: 'TabClose' on [object XULElement].
[task 2021-11-24T04:20:59.649Z] 04:20:59 INFO - Tab removed and finished closing
[task 2021-11-24T04:20:59.651Z] 04:20:59 INFO - TEST-PASS | devtools/shared/commands/target/tests/browser_target_command_service_workers_navigation.js | The main process DevToolsServer has no pending connection when the test ends -
[task 2021-11-24T04:20:59.652Z] 04:20:59 INFO - GECKO(3679) | [Child 3866, Main Thread] WARNING: NS_ENSURE_TRUE(!mHasOrHasHadOwnerWindow || mOwnerWindow) failed: file /builds/worker/checkouts/gecko/dom/events/DOMEventTargetHelper.cpp:327
[task 2021-11-24T04:20:59.666Z] 04:20:59 INFO - GECKO(3679) | [Child 3866, Main Thread] WARNING: NS_ENSURE_TRUE(!mHasOrHasHadOwnerWindow || mOwnerWindow) failed: file /builds/worker/checkouts/gecko/dom/events/DOMEventTargetHelper.cpp:327
[task 2021-11-24T04:20:59.666Z] 04:20:59 INFO - GECKO(3679) | MEMORY STAT | vsize 3320MB | residentFast 544MB | heapAllocated 225MB
[task 2021-11-24T04:20:59.667Z] 04:20:59 INFO - TEST-OK | devtools/shared/commands/target/tests/browser_target_command_service_workers_navigation.js | took 90394ms
[task 2021-11-24T04:20:59.668Z] 04:20:59 INFO - GECKO(3679) | [Child 3866: Main Thread]: I/DocShellAndDOMWindowLeak ++DOCSHELL 7f5db70f0400 == 2 [pid = 3866] [id = 11]
[task 2021-11-24T04:20:59.668Z] 04:20:59 INFO - GECKO(3679) | [Child 3866: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 5 (7f5db85e43c0) [pid = 3866] [serial = 32] [outer = 0]
[task 2021-11-24T04:20:59.669Z] 04:20:59 INFO - GECKO(3679) | [Child 3866: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 6 (7f5db70f0800) [pid = 3866] [serial = 33] [outer = 7f5db85e43c0]
[task 2021-11-24T04:20:59.670Z] 04:20:59 INFO - checking window state
Comment hidden (Intermittent Failures Robot) |
Comment 26•3 years ago
|
||
Comment hidden (Intermittent Failures Robot) |
Comment 28•3 years ago
|
||
Comment 29•3 years ago
|
||
bugherder |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment 39•3 years ago
|
||
Bug 1750834 is going to disable this test on OSX, which looks like it already has a high failure rate. It is already disabled on Windows and Linux 64-bit.
Comment hidden (Intermittent Failures Robot) |
Assignee | ||
Comment 41•2 years ago
|
||
So it looks like there's a race condition in the legacy service worker code where we can end up with an unregistered service worker to not trigger a onDestroyed callback
Adding some delays between navigation and sw unregistration does seem to fix the issue
# HG changeset patch
# User Nicolas Chevobbe <nchevobbe@mozilla.com>
# Date 1676293620 -3600
# Mon Feb 13 14:07:00 2023 +0100
# Node ID 349cde7cbed9c4c941fa9bd46176e82d60cbd8e7
# Parent f45ac8766b6167ecd4adc81490f8f9b927472200
Bug 1726270 - [devtools] Re-enable browser_target_command_service_workers_navigation.js. r=ochameau.
diff --git a/devtools/shared/commands/target/tests/browser.ini b/devtools/shared/commands/target/tests/browser.ini
--- a/devtools/shared/commands/target/tests/browser.ini
+++ b/devtools/shared/commands/target/tests/browser.ini
@@ -31,10 +31,6 @@ skip-if = !fission
[browser_target_command_reload.js]
[browser_target_command_service_workers.js]
[browser_target_command_service_workers_navigation.js]
-skip-if =
- os == "linux" && bits == 64 # Bug 1726270
- os == "win" && bits == 64 # Bug 1726270
- os == "mac" && fission # Bug 1726270
[browser_target_command_switchToTarget.js]
[browser_target_command_tab_workers.js]
[browser_target_command_tab_workers_bfcache_navigation.js]
diff --git a/devtools/shared/commands/target/tests/browser_target_command_service_workers_navigation.js b/devtools/shared/commands/target/tests/browser_target_command_service_workers_navigation.js
--- a/devtools/shared/commands/target/tests/browser_target_command_service_workers_navigation.js
+++ b/devtools/shared/commands/target/tests/browser_target_command_service_workers_navigation.js
@@ -70,6 +70,7 @@ add_task(async function test_NavigationB
info("Reload .org page, onAvailable and onDestroyed should not be called");
await BrowserTestUtils.reloadTab(gBrowser.selectedTab);
+ await new Promise(res => setTimeout(res, 1000));
await checkHooks(hooks, {
available: 2,
destroyed: 0,
@@ -90,6 +91,7 @@ add_task(async function test_NavigationB
);
BrowserTestUtils.loadURIString(gBrowser.selectedBrowser, COM_PAGE_URL);
await onBrowserLoaded;
+ await new Promise(res => setTimeout(res, 1000));
await checkHooks(hooks, {
available: 2,
destroyed: 1,
https://treeherder.mozilla.org/jobs?repo=try&revision=7db44f7a00d7c4dc30f6afb596c566f54ce0726b
This is where the onDestroyed callback should be triggered https://searchfox.org/mozilla-central/rev/5ccb73c0217d1710b10d6e6e297cf3396d10ec23/devtools/shared/commands/target/legacy-target-watchers/legacy-serviceworkers-watcher.js#226-243
But in some cases, the call to this._getAllServiceWorkerTargets()
doesn't return any target
this is because the Map we use in https://searchfox.org/mozilla-central/rev/5ccb73c0217d1710b10d6e6e297cf3396d10ec23/devtools/shared/commands/target/legacy-target-watchers/legacy-serviceworkers-watcher.js#288
serviceWorkerTargets.push(...this.targetsByProcess.get(target));
gets overwritten in https://searchfox.org/mozilla-central/rev/5ccb73c0217d1710b10d6e6e297cf3396d10ec23/devtools/shared/commands/target/legacy-target-watchers/legacy-workers-watcher.js#25
this.targetsByProcess.set(targetFront, new Set());
Assignee | ||
Comment 42•2 years ago
|
||
Comment 43•1 year ago
|
||
I'll fix and re-enable this test in bug 1651522.
Updated•1 year ago
|
Description
•