1343463 - dom/indexedDB/test/test_storage_manager_estimate.html | This test left a service worker registered without cleaning it up

Status: RESOLVED FIXED

(Core :: DOM: Service Workers, defect)

Description

[Shawn Huang [:shawnjohnjr][:shuang] (as a happy gecko contributor)]

Follow up: When submitting bug 1268804 patches to try server, I hit high frequency intermittent errors, "service worker registered without cleaning it up". bug 1268804 changes mochitest.ini to let test_storage_manager_estimate.html run over https. This might tests loading registrar file after unregister service worker.

Problem:
When running mochitest m-4, dom/indexeddb/test/test_serviceworker.html will be executed, register and unregister service worker. The test case actually unregisters service worker, but however it's possible that test_serviceworker.html writes things (scope: http://mochi.test:8888/tests/dom/indexedDB/test/service_worker_client.html) into serviceworker.txt when unregistering.

After test_serviceworker.html finished, the testing framework continues to execute other test cases over http, browser session shutdown after about 20 seconds then execute test cases over https. So it doesn't look like a race when shutting down too fast.

Before executing test_storage_manager_estimate.html test case, http browser session shutdown first then starts up new https browser session, loading registrar file (serviceworker.txt), test_storage_manager_estimate.html also registers service worker because the file is under the same directory as service_worker_client.html.

For an unknown reason, WriteData() writes suffix/scope/currentWorkerURL even though test_serviceworker.html calls unregister.

try: https://treeherder.mozilla.org/#/jobs?repo=try&revision=2bf82b2ea19ba11194a8223181ece9cfe46b7d4c&selectedJob=80341359

log: https://treeherder.mozilla.org/#/jobs?repo=try&revision=2bf82b2ea19ba11194a8223181ece9cfe46b7d4c&selectedJob=80341359

WriteData()
[task 2017-02-27T10:35:52.801660Z] 10:35:52     INFO - suffix:
[task 2017-02-27T10:35:52.803755Z] 10:35:52     INFO - scope: http://mochi.test:8888/tests/dom/indexedDB/test/service_worker_client.html
[task 2017-02-27T10:35:52.808744Z] 10:35:52     INFO - currentWorkerURL: http://mochi.test:8888/tests/dom/indexedDB/test/service_worker.js
[task 2017-02-27T10:35:52.810731Z] 10:35:52     INFO -  WriteData safeStream->Finish()
[task 2017-02-27T10:35:52.813508Z] 10:35:52     INFO - TEST-OK | dom/indexedDB/test/test_serviceworker.html | took 1228ms
[task 2017-02-27T10:35:52.815675Z] 10:35:52     INFO - DataSaved
[task 2017-02-27T10:35:52.818347Z] 10:35:52     INFO - MaybeScheduleShutdownCompleted

LoadData() before loading test case test_storage_estimate.html.
[task 2017-02-27T10:36:56.083243Z] 10:36:56     INFO - TEST-INFO | started process Main app process
[task 2017-02-27T10:36:57.917797Z] 10:36:57     INFO - ServiceWorkerRegistrar:: LoadData
[task 2017-02-27T10:36:57.918177Z] 10:36:57     INFO - ServiceWorkerRegistrar:: ReadData
[task 2017-02-27T10:36:57.918437Z] 10:36:57     INFO - LoadData suffix:
[task 2017-02-27T10:36:57.918806Z] 10:36:57     INFO - LoadData scope:
[task 2017-02-27T10:36:57.920069Z] 10:36:57     INFO - LoadData currentWorkerURL: http://mochi.test:8888/tests/dom/indexedDB/test/service_worker.js

Comment 1

[Ben Kelly [:bkelly, not reviewing]]

We may need an fflush somewhere.  Also, mochitest could create a new profile when spawning a new browser instance like this.

Ehsan, what do you think?

Comment 2

[(no longer active)]

(In reply to Ben Kelly [not reviewing due to deadline][:bkelly] from comment #1)
> We may need an fflush somewhere.  Also, mochitest could create a new profile
> when spawning a new browser instance like this.
> 
> Ehsan, what do you think?

I don't think there is anything wrong with our registrar writing code or the mochitest detection code.  Something is just writing this registration data *again* after we write to the file to remove it when unregister() is called, and the mochitest harness correctly catches us doing that.  You should figure out where the second write comes from.  From the log linked to from comment 0:

[task 2017-02-27T10:35:52.691402Z] 10:35:52     INFO - #######[Storage] Service worker Unregister

^
This is where unregister() is called in the test.

[task 2017-02-27T10:35:52.693264Z] 10:35:52     INFO - !!!!!!!! ServiceWorkerRegistrar:: UnregisterServiceWorker
[task 2017-02-27T10:35:52.693608Z] 10:35:52     INFO - !!!!!!!!!! mData.Length: 1
[task 2017-02-27T10:35:52.695207Z] 10:35:52     INFO - !!!! UnregisterServiceWorker mData RemoveElement
[task 2017-02-27T10:35:52.698717Z] 10:35:52     INFO - !!!! UnregisterServiceWorker deleted = true

^
Correctly unregistered, good!

[task 2017-02-27T10:35:52.702260Z] 10:35:52     INFO - !!!!!!!! ServiceWorkerRegistrar:: UnregisterServiceWorker deleted ScheduleSaveData
[task 2017-02-27T10:35:52.704321Z] 10:35:52     INFO - #######[Storage] Service worker Unregister mPendingUninstall = true
[task 2017-02-27T10:35:52.707654Z] 10:35:52     INFO - #######[Storage] Service worker Unregister Clear Registration
[task 2017-02-27T10:35:52.710385Z] 10:35:52     INFO - !!!!! SaveData !!!!!!!
[task 2017-02-27T10:35:52.714269Z] 10:35:52     INFO - !!!!! SaveData call WriteData !!!!!!!
[task 2017-02-27T10:35:52.718475Z] 10:35:52     INFO - !!!!!!!!!!!!!!!  WriteData !!!!!!!!!!!!!!!!!!!!!
[task 2017-02-27T10:35:52.720518Z] 10:35:52     INFO - !!!! WriteData mData RemoveElement
[task 2017-02-27T10:35:52.726047Z] 10:35:52     INFO - !!!! WriteData mData RemoveElement, mData size: 0 before
[task 2017-02-27T10:35:52.728936Z] 10:35:52     INFO - !!!! WriteData mData RemoveElement, mData size: 0 after
[task 2017-02-27T10:35:52.731098Z] 10:35:52     INFO - !!!!!!!!!!!!!!!  WriteData safeStream->Finish()!!!!!!!!!!!!!!!!!!!!!

^
Correctly wrote the registration file and it's empty now.

[task 2017-02-27T10:35:52.733325Z] 10:35:52     INFO - !!!!!!!!!!! SimpleTest._expectingRegisteredServiceWorker:  undefined

^
mochitest harness check passes.

[task 2017-02-27T10:35:52.736698Z] 10:35:52     INFO - !!!!!!!!!!!!!  PropagateUnregister
[task 2017-02-27T10:35:52.738639Z] 10:35:52     INFO - !!!!!!!! ServiceWorkerRegistrar:: UnregisterServiceWorker
[task 2017-02-27T10:35:52.744684Z] 10:35:52     INFO - !!!!!!!!!! mData.Length: 0
[task 2017-02-27T10:35:52.746987Z] 10:35:52     INFO - !!!!! DataSaved !!!!!
[task 2017-02-27T10:35:52.751435Z] 10:35:52     INFO - !!!!!!!!!!!!!!!  MaybeScheduleShutdownCompleted !!!!!!!!!!!!!!!!!!!!!
[task 2017-02-27T10:35:52.753315Z] 10:35:52     INFO - !!!!!!!!!!!!!!!!!!!!!!!!! GetAllRegistrations !!!!!!!!!!!!!!!!!!!!!!!!!!!!!
[task 2017-02-27T10:35:52.755390Z] 10:35:52     INFO - #########[Storage] GetAllRegistrations, length: 1

^
Uh-oh, where is this 1 registration coming from?

[task 2017-02-27T10:35:52.757257Z] 10:35:52     INFO - #######[Storage] Service worker Key:http://mochi.test:8888
[task 2017-02-27T10:35:52.761716Z] 10:35:52     INFO - #######[Storage] Service worker ServiceWorkerRegistrationInfo: 0
[task 2017-02-27T10:35:52.763884Z] 10:35:52     INFO - !!!!!!!!!! GetAllRegistrations, Array: 0
[task 2017-02-27T10:35:52.766963Z] 10:35:52     INFO - !!!!!!! isServiceWorkerRegistered, length: 0
[task 2017-02-27T10:35:52.773649Z] 10:35:52     INFO - !!!!!!!!!!!!!!!!!!!!!!!!! GetAllRegistrations !!!!!!!!!!!!!!!!!!!!!!!!!!!!!
[task 2017-02-27T10:35:52.776380Z] 10:35:52     INFO - #########[Storage] GetAllRegistrations, length: 1
[task 2017-02-27T10:35:52.780436Z] 10:35:52     INFO - #######[Storage] Service worker Key:http://mochi.test:8888
[task 2017-02-27T10:35:52.782767Z] 10:35:52     INFO - #######[Storage] Service worker ServiceWorkerRegistrationInfo: 0
[task 2017-02-27T10:35:52.786870Z] 10:35:52     INFO - !!!!!!!!!! GetAllRegistrations, Array: 0
[task 2017-02-27T10:35:52.789888Z] 10:35:52     INFO - MEMORY STAT | vsize 1748MB | residentFast 208MB | heapAllocated 88MB
[task 2017-02-27T10:35:52.793775Z] 10:35:52     INFO - !!!!! DataSaved !!!!!
[task 2017-02-27T10:35:52.798080Z] 10:35:52     INFO - !!!!!!!!!!!!!!!  MaybeScheduleShutdownCompleted !!!!!!!!!!!!!!!!!!!!!
[task 2017-02-27T10:35:52.801660Z] 10:35:52     INFO - !suffix:
[task 2017-02-27T10:35:52.803755Z] 10:35:52     INFO - !scope: http://mochi.test:8888/tests/dom/indexedDB/test/service_worker_client.html
[task 2017-02-27T10:35:52.808744Z] 10:35:52     INFO - !currentWorkerURL: http://mochi.test:8888/tests/dom/indexedDB/test/service_worker.js
[task 2017-02-27T10:35:52.810731Z] 10:35:52     INFO - !!!!!!!!!!!!!!!  WriteData safeStream->Finish()!!!!!!!!!!!!!!!!!!!!!

^
Here is where we write the service_worker_client.html scope registration back to the registration file.  This is the cause of the bug.  The test failure that happens later is the symptom.


[task 2017-02-27T10:35:52.813508Z] 10:35:52     INFO - TEST-OK | dom/indexedDB/test/test_serviceworker.html | took 1228ms
[task 2017-02-27T10:35:52.815675Z] 10:35:52     INFO - !!!!! DataSaved !!!!!
[task 2017-02-27T10:35:52.818347Z] 10:35:52     INFO - !!!!!!!!!!!!!!!  MaybeScheduleShutdownCompleted !!!!!!!!!!!!!!!!!!!!!

Comment 3

[(no longer active)]

(also note that when firefox exits, the OS flushes all pending file buffers for us, so fflushing wouldn't buy us anything across restarts.  Changing the profile directory would mask this bug until someone added a test in the same directory to run after test_serviceworker.html and then that test would fail in the same way.)

Comment 4

[Ben Kelly [:bkelly, not reviewing]]

We know there are races in the propagation code.  That will be fixed as part of our multi-e10s work.

If we're unwilling to use a pristine profile in when starting a mochitest session (seems sane for determinism to me), then I guess we can work around the current state.

Shawn, can you try moving this test into dom/workers/test/serviceworkers?  Then your IDB test run won't have to worry about this issue.  The other test dir already does a ton of service worker stuff, so it shouldn't have any impact there.

Comment 5

[Shawn Huang [:shawnjohnjr][:shuang] (as a happy gecko contributor)]

(In reply to Ben Kelly [not reviewing due to deadline][:bkelly] from comment #4)
> Shawn, can you try moving this test into dom/workers/test/serviceworkers? 
> Then your IDB test run won't have to worry about this issue.  The other test
> dir already does a ton of service worker stuff, so it shouldn't have any
> impact there.
Sure. I will do it today.

Comment 6

[Shawn Huang [:shawnjohnjr][:shuang] (as a happy gecko contributor)]

Attachment: Bug 1343463 - Move indexeddb service worker test to workers folder

Comment 7

[Shawn Huang [:shawnjohnjr][:shuang] (as a happy gecko contributor)]

Comment on attachment 8843679 [details] [diff] [review]
Bug 1343463 - Move indexeddb service worker test to workers folder

Following Comment 4, I move test_serviceworker.html to dom/workers/test folder.

Comment 8

[Shawn Huang [:shawnjohnjr][:shuang] (as a happy gecko contributor)]

try: https://treeherder.mozilla.org/#/jobs?repo=try&revision=65f68f58f4c761fb9d637d7c70b1bac7652533a4&selectedJob=81449813

Comment 9

[Shawn Huang [:shawnjohnjr][:shuang] (as a happy gecko contributor)]

(In reply to :Ehsan Akhgari from comment #2)
> [task 2017-02-27T10:35:52.755390Z] 10:35:52     INFO - #########[Storage]
> GetAllRegistrations, length: 1
> 
> ^
> Uh-oh, where is this 1 registration coming from?
Sorry for misleading here. 
I print |mRegistrationInfos.Count()| in ServiceWorkerManager::GetAllRegistration.
Length value is 1 after calling |unregister|, I guess it's normal here.
So based on Comment 4, races in the propagation code could lead the code call WriteData multiple times?

Comment 10

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

Comment on attachment 8843679 [details] [diff] [review]
Bug 1343463 - Move indexeddb service worker test to workers folder

Redirecting, I'm not able to review code in either of these directories unless review is deferred to me by an owner or peer.  (Redirecting to :baku since :bkelly is not accepting reviews.)

Comment 11

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/271dd75925bd
Move indexeddb service worker test to workers folder, r=baku

Comment 12

[Shawn Huang [:shawnjohnjr][:shuang] (as a happy gecko contributor)]

Move to dom/workers/test is not enough.
This could cause test_navigator_secureContext.html fail.

Comment 13

[Carsten Book [:Tomcat]]

backout for test failures (as shawn mentioned) in https://treeherder.mozilla.org/logviewer.html#?job_id=81839638&repo=mozilla-inbound

Comment 14

[Pulsebot]

Backout by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/ca8a1212ff8c
Backed out changeset 271dd75925bd for causing test failures in test_navigator_secureContext.html

Comment 15

[Shawn Huang [:shawnjohnjr][:shuang] (as a happy gecko contributor)]

Attachment: Bug 1343463 - Move indexeddb service worker test to serviceworkers folder

Comment 16

[Shawn Huang [:shawnjohnjr][:shuang] (as a happy gecko contributor)]

https://treeherder.mozilla.org/#/jobs?repo=try&author=[e-mail]&selectedJob=81906208

Comment 17

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/5e9a92053f10
Move indexeddb service worker test to serviceworkers folder, r=baku

Comment 18

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/5e9a92053f10