1523454 - Perma devtools/client/aboutdebugging-new/test/browser/browser_aboutdebugging_serviceworker_status.js | leaked 2 window(s) until shutdown [url = about:debugging] after timeout

Status: RESOLVED FIXED

(DevTools :: about:debugging, defect, P5)

Description

[Treeherder Bug Filer]

#[markdown(off)]
Filed by: rmaries [at] mozilla.com

https://treeherder.mozilla.org/logviewer.html#?job_id=224551938&repo=mozilla-central

https://queue.taskcluster.net/v1/task/VZ9xC_GdT0u7apPps3dthA/runs/0/artifacts/public/logs/live_backing.log

[task 2019-01-28T22:57:58.069Z] 22:57:58 INFO - TEST-START | Shutdown
[task 2019-01-28T22:57:58.070Z] 22:57:58 INFO - Browser Chrome Test Summary
[task 2019-01-28T22:57:58.071Z] 22:57:58 INFO - Passed: 251
[task 2019-01-28T22:57:58.071Z] 22:57:58 INFO - Failed: 1
[task 2019-01-28T22:57:58.072Z] 22:57:58 INFO - Todo: 0
[task 2019-01-28T22:57:58.073Z] 22:57:58 INFO - Mode: e10s
[task 2019-01-28T22:57:58.073Z] 22:57:58 INFO - *** End BrowserChrome Test Results ***

[task 2019-01-28T22:58:10.333Z] 22:58:10 INFO - GECKO(1084) | => Process ID: 1084, Thread ID: 139876985521984
[task 2019-01-28T22:58:10.391Z] 22:58:10 INFO - TEST-INFO | Main app process: exit 0
[task 2019-01-28T22:58:10.392Z] 22:58:10 ERROR - TEST-UNEXPECTED-FAIL | devtools/client/aboutdebugging-new/test/browser/browser_aboutdebugging_serviceworker_status.js | leaked 2 window(s) until shutdown [url = about:debugging]
[task 2019-01-28T22:58:10.394Z] 22:58:10 INFO - TEST-INFO | devtools/client/aboutdebugging-new/test/browser/browser_aboutdebugging_serviceworker_status.js | windows(s) leaked: [pid = 1084] [serial = 246], [pid = 1084] [serial = 248]
[task 2019-01-28T22:58:10.395Z] 22:58:10 ERROR - TEST-UNEXPECTED-FAIL | devtools/client/aboutdebugging-new/test/browser/browser_aboutdebugging_serviceworker_status.js | leaked 1 docShell(s) until shutdown
[task 2019-01-28T22:58:10.397Z] 22:58:10 INFO - TEST-INFO | devtools/client/aboutdebugging-new/test/browser/browser_aboutdebugging_serviceworker_status.js | docShell(s) leaked: [pid = 1084] [id = {a49839d2-f346-47a7-841e-0c374d8a2b3e}]
[task 2019-01-28T22:58:10.398Z] 22:58:10 INFO - runtests.py | Application ran for: 0:17:45.093815
[task 2019-01-28T22:58:10.400Z] 22:58:10 INFO - zombiecheck | Reading PID log: /tmp/tmpST848rpidlog
[task 2019-01-28T22:58:10.401Z] 22:58:10 INFO - ==> process 1084 launched child process 1114
[task 2019-01-28T22:58:10.402Z] 22:58:10 INFO - ==> process 1084 launched child process 1176
[task 2019-01-28T22:58:10.408Z] 22:58:10 INFO - ==> process 1084 launched child process 1195
[task 2019-01-28T22:58:10.409Z] 22:58:10 INFO - ==> process 1084 launched child process 1251
[task 2019-01-28T22:58:10.418Z] 22:58:10 INFO - ==> process 1084 launched child process 1279
[task 2019-01-28T22:58:10.418Z] 22:58:10 INFO - ==> process 1084 launched child process 1310
[task 2019-01-28T22:58:10.418Z] 22:58:10 INFO - ==> process 1332 launched child process 1351
[task 2019-01-28T22:58:10.418Z] 22:58:10 INFO - ==> process 1332 launched child process 1404
[task 2019-01-28T22:58:10.418Z] 22:58:10 INFO - ==> process 1332 launched child process 1439
[task 2019-01-28T22:58:10.418Z] 22:58:10 INFO - ==> process 1084 launched child process 1489
[task 2019-01-28T22:58:10.418Z] 22:58:10 INFO - ==> process 1084 launched child process 1510
[task 2019-01-28T22:58:10.418Z] 22:58:10 INFO - ==> process 1084 launched child process 1523
[task 2019-01-28T22:58:10.418Z] 22:58:10 INFO - ==> process 1084 launched child process 1542
[task 2019-01-28T22:58:10.418Z] 22:58:10 INFO - ==> process 1084 launched child process 1566
[task 2019-01-28T22:58:10.418Z] 22:58:10 INFO - ==> process 1084 launched child process 1594
[task 2019-01-28T22:58:10.420Z] 22:58:10 INFO - ==> process 1084 launched child process 1624
[task 2019-01-28T22:58:10.421Z] 22:58:10 INFO - ==> process 1084 launched child process 1686
[task 2019-01-28T22:58:10.421Z] 22:58:10 INFO - ==> process 1084 launched child process 1714
[task 2019-01-28T22:58:10.422Z] 22:58:10 INFO - ==> process 1084 launched child process 1742
[task 2019-01-28T22:58:10.423Z] 22:58:10 INFO - ==> process 1084 launched child process 1769
[task 2019-01-28T22:58:10.423Z] 22:58:10 INFO - ==> process 1084 launched child process 1799
[task 2019-01-28T22:58:10.424Z] 22:58:10 INFO - ==> process 1084 launched child process 1837
[task 2019-01-28T22:58:10.424Z] 22:58:10 INFO - ==> process 1084 launched child process 1862
[task 2019-01-28T22:58:10.424Z] 22:58:10 INFO - ==> process 1084 launched child process 1881
[task 2019-01-28T22:58:10.425Z] 22:58:10 INFO - ==> process 1084 launched child process 1900
[task 2019-01-28T22:58:10.426Z] 22:58:10 INFO - ==> process 1084 launched child process 1920
[task 2019-01-28T22:58:10.427Z] 22:58:10 INFO - ==> process 1084 launched child process 1939
[task 2019-01-28T22:58:10.427Z] 22:58:10 INFO - ==> process 1084 launched child process 1958
[task 2019-01-28T22:58:10.427Z] 22:58:10 INFO - ==> process 1084 launched child process 1977
[task 2019-01-28T22:58:10.428Z] 22:58:10 INFO - ==> process 1084 launched child process 1997
[task 2019-01-28T22:58:10.428Z] 22:58:10 INFO - ==> process 1084 launched child process 2009
[task 2019-01-28T22:58:10.429Z] 22:58:10 INFO - ==> process 1084 launched child process 2014
[task 2019-01-28T22:58:10.430Z] 22:58:10 INFO - ==> process 1084 launched child process 2022
[task 2019-01-28T22:58:10.430Z] 22:58:10 INFO - zombiecheck | Checking for orphan process with PID: 1920
[task 2019-01-28T22:58:10.431Z] 22:58:10 INFO - zombiecheck | Checking for orphan process with PID: 1542
[task 2019-01-28T22:58:10.432Z] 22:58:10 INFO - zombiecheck | Checking for orphan process with PID: 1799
[task 2019-01-28T22:58:10.433Z] 22:58:10 INFO - zombiecheck | Checking for orphan process with PID: 1939
[task 2019-01-28T22:58:10.434Z] 22:58:10 INFO - zombiecheck | Checking for orphan process with PID: 1686
[task 2019-01-28T22:58:10.434Z] 22:58:10 INFO - zombiecheck | Checking for orphan process with PID: 2009
[task 2019-01-28T22:58:10.435Z] 22:58:10 INFO - zombiecheck | Checking for orphan process with PID: 1176
[task 2019-01-28T22:58:10.441Z] 22:58:10 INFO - zombiecheck | Checking for orphan process with PID: 1566
[task 2019-01-28T22:58:10.442Z] 22:58:10 INFO - zombiecheck | Checking for orphan process with PID: 1439
[task 2019-01-28T22:58:10.443Z] 22:58:10 INFO - zombiecheck | Checking for orphan process with PID: 1958
[task 2019-01-28T22:58:10.443Z] 22:58:10 INFO - zombiecheck | Checking for orphan process with PID: 1195
[task 2019-01-28T22:58:10.444Z] 22:58:10 INFO - zombiecheck | Checking for orphan process with PID: 1837
[task 2019-01-28T22:58:10.445Z] 22:58:10 INFO - zombiecheck | Checking for orphan process with PID: 1714
[task 2019-01-28T22:58:10.446Z] 22:58:10 INFO - zombiecheck | Checking for orphan process with PID: 1310
[task 2019-01-28T22:58:10.447Z] 22:58:10 INFO - zombiecheck | Checking for orphan process with PID: 1977
[task 2019-01-28T22:58:10.448Z] 22:58:10 INFO - zombiecheck | Checking for orphan process with PID: 1594
[task 2019-01-28T22:58:10.449Z] 22:58:10 INFO - zombiecheck | Checking for orphan process with PID: 1862
[task 2019-01-28T22:58:10.450Z] 22:58:10 INFO - zombiecheck | Checking for orphan process with PID: 1351
[task 2019-01-28T22:58:10.450Z] 22:58:10 INFO - zombiecheck | Checking for orphan process with PID: 1997
[task 2019-01-28T22:58:10.451Z] 22:58:10 INFO - zombiecheck | Checking for orphan process with PID: 1742
[task 2019-01-28T22:58:10.451Z] 22:58:10 INFO - zombiecheck | Checking for orphan process with PID: 1489
[task 2019-01-28T22:58:10.452Z] 22:58:10 INFO - zombiecheck | Checking for orphan process with PID: 1624
[task 2019-01-28T22:58:10.453Z] 22:58:10 INFO - zombiecheck | Checking for orphan process with PID: 1881
[task 2019-01-28T22:58:10.454Z] 22:58:10 INFO - zombiecheck | Checking for orphan process with PID: 1114
[task 2019-01-28T22:58:10.455Z] 22:58:10 INFO - zombiecheck | Checking for orphan process with PID: 2014
[task 2019-01-28T22:58:10.455Z] 22:58:10 INFO - zombiecheck | Checking for orphan process with PID: 1251
[task 2019-01-28T22:58:10.457Z] 22:58:10 INFO - zombiecheck | Checking for orphan process with PID: 2022
[task 2019-01-28T22:58:10.457Z] 22:58:10 INFO - zombiecheck | Checking for orphan process with PID: 1510
[task 2019-01-28T22:58:10.458Z] 22:58:10 INFO - zombiecheck | Checking for orphan process with PID: 1769
[task 2019-01-28T22:58:10.459Z] 22:58:10 INFO - zombiecheck | Checking for orphan process with PID: 1900
[task 2019-01-28T22:58:10.460Z] 22:58:10 INFO - zombiecheck | Checking for orphan process with PID: 1523
[task 2019-01-28T22:58:10.461Z] 22:58:10 INFO - zombiecheck | Checking for orphan process with PID: 1404
[task 2019-01-28T22:58:10.461Z] 22:58:10 INFO - zombiecheck | Checking for orphan process with PID: 1279
[task 2019-01-28T22:58:10.461Z] 22:58:10 INFO - Stopping web server
[task 2019-01-28T22:58:10.471Z] 22:58:10 INFO - Stopping web socket server
[task 2019-01-28T22:58:10.492Z] 22:58:10 INFO - Stopping ssltunnel
[task 2019-01-28T22:58:10.515Z] 22:58:10 INFO - leakcheck | Processing log file /tmp/tmp5gnlsQ.mozrunner/runtests_leaks.log
[task 2019-01-28T22:58:10.515Z] 22:58:10 INFO - TEST-INFO | leakcheck | default process: leak threshold set at 0 bytes
[task 2019-01-28T22:58:10.515Z] 22:58:10 INFO - TEST-INFO | leakcheck | plugin process: leak threshold set at 0 bytes
[task 2019-01-28T22:58:10.515Z] 22:58:10 INFO - TEST-INFO | leakcheck | tab process: leak threshold set at 0 bytes
[task 2019-01-28T22:58:10.515Z] 22:58:10 INFO - TEST-INFO | leakcheck | gmplugin process: leak threshold set at 20000 bytes
[task 2019-01-28T22:58:10.515Z] 22:58:10 INFO - TEST-INFO | leakcheck | gpu process: leak threshold set at 0 bytes
[task 2019-01-28T22:58:10.515Z] 22:58:10 INFO - TEST-INFO | leakcheck | rdd process: leak threshold set at 400 bytes
[task 2019-01-28T22:58:10.516Z] 22:58:10 INFO - TEST-INFO | leakcheck | vr process: leak threshold set at 0 bytes
[task 2019-01-28T22:58:10.517Z] 22:58:10 INFO - TEST-INFO | leakcheck | socket process: leak threshold set at 0 bytes
[task 2019-01-28T22:58:10.518Z] 22:58:10 INFO - leakcheck | Processing leak log file /tmp/tmp5gnlsQ.mozrunner/runtests_leaks_tab_pid1310.log
[task 2019-01-28T22:58:10.520Z] 22:58:10 INFO -
[task 2019-01-28T22:58:10.520Z] 22:58:10 INFO - == BloatView: ALL (cumulative) LEAK AND BLOAT STATISTICS, tab process 1310
[task 2019-01-28T22:58:10.521Z] 22:58:10 INFO -
[task 2019-01-28T22:58:10.522Z] 22:58:10 INFO - |<----------------Class--------------->|<-----Bytes------>|<----Objects---->|
[task 2019-01-28T22:58:10.523Z] 22:58:10 INFO - | | Per-Inst Leaked| Total Rem|
[task 2019-01-28T22:58:10.524Z] 22:58:10 INFO - 0 |TOTAL | 39 0| 137198 0|
[task 2019-01-28T22:58:10.529Z] 22:58:10 INFO -
[task 2019-01-28T22:58:10.530Z] 22:58:10 INFO - nsTraceRefcnt::DumpStatistics: 790 entries
[task 2019-01-28T22:58:10.531Z] 22:58:10 INFO - TEST-PASS | leakcheck | tab no leaks detected!
[task 2019-01-28T22:58:10.532Z] 22:58:10 INFO - leakcheck | Processing leak log file /tmp/tmp5gnlsQ.mozrunner/runtests_leaks_tab_pid1769.log
[task 2019-01-28T22:58:10.533Z] 22:58:10 INFO -

Comment 1

[Julian Descottes [:jdescottes]]

The logic in devtools for detecting the "registering" status of a service worker was relying on the limitations of the previous service worker platform implementation. Consequently the refactor "breaks" the devtools test that checks for service worker status.

We can either disable the test for the refactor (skip-if = serviceworker_e10s) or we can try fixing it.

Comment 2

[Julian Descottes [:jdescottes]]

Attachment: Bug 1523454 - Fix service worker active status for sw refactor;r=daisuke

This will fix the test browser_aboutdebugging_serviceworker_status.js when running with dom.serviceWorkers.parent_intercept=true

Comment 3

[Julian Descottes [:jdescottes]]

Attachment: Bug 1523454 - Remove isActive and isRunning from worker details;r=daisuke

Depends on D18365.

Not mandatory, but relying on the computed state seems better than duplicating the logic around isActive/isRunning.

Comment 4

[Intermittent Failures Robot]

23 failures in 2628 pushes (0.009 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• try: 1
• mozilla-central: 22

Platform breakdown:

• linux64: 23

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1523454&startday=2019-01-28&endday=2019-02-03&tree=all

Comment 5

[Julian Descottes [:jdescottes]]

Andrew, a question about how to detect if we are using the sw refactor or not. You can read the review and discussion at https://phabricator.services.mozilla.com/D18365#inline-100033

We are reading the preference dom.serviceWorkers.parent_intercept to know if the refactor is on or not. The concern is that if the preference is flipped by the user after starting the browser, we might read an incorrect value and won't really know the state. Do we have an alternate way of checking if the browser is currently running with the refactor, or should we assume users will not flip the preference?

Comment 6

[Andrew Sutherland [:asuth] (he/him)]

We can expose the value of ServiceWorkerParentInterceptEnabled() on nsIServiceWorkerManager if that helps. It would only be okay to check in the parent process, however. Does that sound good? I'll file a spin-off and put a patch up if it does.

Comment 7

[Julian Descottes [:jdescottes]]

Yes that sounds good, thanks Andrew!
It won't work with the approach used in my current patch, but I can move part of the logic to the parent process.

Comment 8

[Julian Descottes [:jdescottes]]

Let us know when the other bug has been created.
I think I will skip-if = serviceworker_e10s the test in the meantime to avoid the "intermittent" failures.

Comment 9

[Julian Descottes [:jdescottes]]

Attachment: Bug 1523454 - Expose isParentInterceptEnabled in nsIServiceWorkerManager;r=asuth

Feel free to cancel the review if you already have a patch or if you wanted another approach.
Mostly wrote this patch to make sure the DevTools patch on top of it would work.

Comment 10

[Andrew Sutherland [:asuth] (he/him)]

Your most excellent patch accomplishes the goal nicely, thank you! (No need for a separate bug for that now!)

Comment 11

[Intermittent Failures Robot]

45 failures in 2658 pushes (0.017 failures/push) were associated with this bug in the last 7 days.

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

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

Repository breakdown:

• try: 9
• mozilla-central: 36

Platform breakdown:

• linux64: 45

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

Comment 12

[Julian Descottes [:jdescottes]]

Thanks for the nice words :)

Pushed to try at https://treeherder.mozilla.org/#/jobs?repo=try&revision=2a8b0168680d7af69ec80889f1140ddbd5d8ecd0

Comment 13

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/0dca936d2e9e
Expose isParentInterceptEnabled in nsIServiceWorkerManager;r=asuth
https://hg.mozilla.org/integration/autoland/rev/1d79453b1f68
Fix service worker active status for sw refactor;r=daisuke
https://hg.mozilla.org/integration/autoland/rev/1a88323932cb
Remove isActive and isRunning from worker details;r=daisuke

Comment 14

[Stefan Hindli [:stefan_hindli]]

https://hg.mozilla.org/mozilla-central/rev/0dca936d2e9e
https://hg.mozilla.org/mozilla-central/rev/1d79453b1f68
https://hg.mozilla.org/mozilla-central/rev/1a88323932cb

Comment 15

[Intermittent Failures Robot]

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

Repository breakdown:

• try: 1
• mozilla-central: 4

Platform breakdown:

• linux64: 5

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1523454&startday=2019-02-11&endday=2019-02-17&tree=all