Closed Bug 1343463 Opened 7 years ago Closed 7 years ago

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

Categories

(Core :: DOM: Service Workers, defect)

Product:
Core
Component:
DOM: Service Workers
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

()

Status:
RESOLVED FIXED
Milestone:
mozilla55
Tracking Flags:
Tracking Status
firefox55 --- fixed

People

(Reporter: shawnjohnjr, Assigned: shawnjohnjr)

References

(Blocks 1 open bug)

Details

(Whiteboard: [storage-v1])

Attachments

(1 file, 1 obsolete file)

Bug 1343463 - Move indexeddb service worker test to serviceworkers folder
3.35 KB, patch
Details | Diff | Splinter Review 
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
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?
Blocks: ServiceWorkers-tests
Flags: needinfo?(ehsan)
(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 !!!!!!!!!!!!!!!!!!!!!
Flags: needinfo?(ehsan) → needinfo?(shuang)
(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.)
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.
(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.
Whiteboard: [storage-v1]
Assignee: nobody → shuang
Flags: needinfo?(shuang)
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.
Attachment #8843679 - Flags: review?(bugmail)
(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 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.)
Attachment #8843679 - Flags: review?(bugmail) → review?(amarchesini)
Attachment #8843679 - Flags: review?(amarchesini) → review+
Pushed by shuang@mozilla.com:
https://hg.mozilla.org/integration/mozilla-inbound/rev/271dd75925bd
Move indexeddb service worker test to workers folder, r=baku
Move to dom/workers/test is not enough.
This could cause test_navigator_secureContext.html fail.
backout for test failures (as shawn mentioned) in https://treeherder.mozilla.org/logviewer.html#?job_id=81839638&repo=mozilla-inbound
Flags: needinfo?(shuang)
Backout by cbook@mozilla.com:
https://hg.mozilla.org/integration/mozilla-inbound/rev/ca8a1212ff8c
Backed out changeset 271dd75925bd for causing test failures in test_navigator_secureContext.html
Attachment #8843679 - Attachment is obsolete: true
Flags: needinfo?(shuang)
Pushed by shuang@mozilla.com:
https://hg.mozilla.org/integration/mozilla-inbound/rev/5e9a92053f10
Move indexeddb service worker test to serviceworkers folder, r=baku
https://hg.mozilla.org/mozilla-central/rev/5e9a92053f10
Status: NEW → RESOLVED
Closed: 7 years ago
status-firefox55: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla55
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: