Closed Bug 1726270 Opened 3 years ago Closed 1 year ago

Intermittent devtools/shared/commands/target/tests/browser_target_command_service_workers_navigation.js | Test timed out -

Categories

(DevTools :: General, defect, P5)

defect

Tracking

(firefox-esr78 unaffected, firefox-esr91 unaffected, firefox91 unaffected, firefox92 unaffected, firefox93 affected)

RESOLVED DUPLICATE of bug 1651522
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 - 

I'm going to investigate

Assignee: nobody → nchevobbe
Status: NEW → ASSIGNED
Flags: needinfo?(nchevobbe)

There are 70 total failures in the last 7 days on

[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?

Flags: needinfo?(nchevobbe)
Whiteboard: [stockwell needswork:owner]
Pushed by abutkovits@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/13228973a49f disable browser_target_command_service_workers_navigation.js on Linux_64_opt and Win_64 for frequent failures. r=intermittent-reviewers,MasterWayZ DONTBUILD
Keywords: leave-open
Whiteboard: [stockwell needswork:owner] → [stockwell disabled]

There are 51 total failures in the last 7 days on

[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
Whiteboard: [stockwell disabled] → [stockwell disabled][stockwell needswork:owner]
Pushed by imoraru@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/45aac00150f8 update disabling condition to include linux debug r=intermittent-reviewers,MasterWayZ DONTBUILD

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.

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());
Flags: needinfo?(nchevobbe)

I'll fix and re-enable this test in bug 1651522.

Status: ASSIGNED → RESOLVED
Closed: 1 year ago
Duplicate of bug: 1651522
Resolution: --- → DUPLICATE
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: