Closed Bug 1442894 Opened 6 years ago Closed 6 years ago

Intermittent dom/serviceworkers/test/test_self_update_worker.html | Test timed out.

Categories

(Core :: DOM: Service Workers, defect, P2)

Product:
Core
Component:
DOM: Service Workers
Type:
defect

Tracking

()

Status:
RESOLVED FIXED
Milestone:
mozilla60
Tracking Flags:
Tracking Status
firefox60 --- fixed

People

(Reporter: intermittent-bug-filer, Assigned: catalinb)

References

(Blocks 1 open bug)

Details

(Keywords: intermittent-failure)

Attachments

(1 file, 1 obsolete file)

Avoid race in test_self_update_worker.html
3.19 KB, patch
Details | Diff | Splinter Review 
Filed by: archaeopteryx [at] coole-files.de

https://treeherder.mozilla.org/logviewer.html#?job_id=165745736&repo=try

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

[task 2018-03-03T11:39:23.822Z] 11:39:23     INFO - TEST-START | dom/serviceworkers/test/test_self_update_worker.html
[task 2018-03-03T11:39:23.907Z] 11:39:23     INFO - GECKO(1229) | ++DOMWINDOW == 26 (0xe1d70800) [pid = 1274] [serial = 642] [outer = 0xe36d70c0]
[task 2018-03-03T11:39:25.058Z] 11:39:25     INFO - GECKO(1229) | --DOMWINDOW == 25 (0xe0b0ff80) [pid = 1274] [serial = 637] [outer = (nil)] [url = http://mochi.test:8888/tests/dom/serviceworkers/test/file_js_cache_save_after_load.html]
[task 2018-03-03T11:39:25.060Z] 11:39:25     INFO - GECKO(1229) | --DOMWINDOW == 24 (0xe0b0f080) [pid = 1274] [serial = 633] [outer = (nil)] [url = http://mochi.test:8888/tests/dom/serviceworkers/test/file_js_cache_with_sri.html]
[task 2018-03-03T11:39:25.060Z] 11:39:25     INFO - GECKO(1229) | --DOMWINDOW == 23 (0xe0b0f940) [pid = 1274] [serial = 627] [outer = (nil)] [url = http://mochi.test:8888/tests/dom/serviceworkers/test/file_js_cache.html]
[task 2018-03-03T11:39:25.062Z] 11:39:25     INFO - GECKO(1229) | --DOMWINDOW == 22 (0xe0b0fe40) [pid = 1274] [serial = 631] [outer = (nil)] [url = http://mochi.test:8888/tests/dom/serviceworkers/test/file_js_cache_with_sri.html]
[task 2018-03-03T11:39:25.062Z] 11:39:25     INFO - GECKO(1229) | --DOMWINDOW == 21 (0xe0c6c5c0) [pid = 1274] [serial = 635] [outer = (nil)] [url = http://mochi.test:8888/tests/dom/serviceworkers/test/file_js_cache.html]
[task 2018-03-03T11:39:25.063Z] 11:39:25     INFO - GECKO(1229) | --DOMWINDOW == 20 (0xe0b0fbc0) [pid = 1274] [serial = 629] [outer = (nil)] [url = http://mochi.test:8888/tests/dom/serviceworkers/test/file_js_cache.html]
[task 2018-03-03T11:39:25.100Z] 11:39:25     INFO - GECKO(1229) | [Child 1274, Main Thread] WARNING: A runnable was posted to a worker that is already shutting down!: file /builds/worker/workspace/build/src/dom/workers/WorkerPrivate.cpp, line 1584
[task 2018-03-03T11:39:25.101Z] 11:39:25     INFO - GECKO(1229) | [Child 1274, Main Thread] WARNING: '!r->Dispatch()', file /builds/worker/workspace/build/src/dom/serviceworkers/ServiceWorkerRegistrationImpl.cpp, line 1067
[task 2018-03-03T11:39:28.802Z] 11:39:28     INFO - GECKO(1229) | --DOMWINDOW == 19 (0xe1d39000) [pid = 1274] [serial = 625] [outer = (nil)] [url = http://mochi.test:8888/tests/SimpleTest/iframe-between-tests.html]
[task 2018-03-03T11:39:28.803Z] 11:39:28     INFO - GECKO(1229) | --DOMWINDOW == 18 (0xe1d6e000) [pid = 1274] [serial = 628] [outer = (nil)] [url = about:blank]
[task 2018-03-03T11:39:28.803Z] 11:39:28     INFO - GECKO(1229) | --DOMWINDOW == 17 (0xe1ea5c00) [pid = 1274] [serial = 636] [outer = (nil)] [url = about:blank]
[task 2018-03-03T11:39:28.804Z] 11:39:28     INFO - GECKO(1229) | --DOMWINDOW == 16 (0xe1ea3c00) [pid = 1274] [serial = 634] [outer = (nil)] [url = about:blank]
[task 2018-03-03T11:39:28.805Z] 11:39:28     INFO - GECKO(1229) | --DOMWINDOW == 15 (0xe0ca8800) [pid = 1274] [serial = 623] [outer = (nil)] [url = http://mochi.test:8888/tests/SimpleTest/iframe-between-tests.html]
[task 2018-03-03T11:39:28.805Z] 11:39:28     INFO - GECKO(1229) | --DOMWINDOW == 14 (0xe1fd3800) [pid = 1274] [serial = 638] [outer = (nil)] [url = about:blank]
[task 2018-03-03T11:39:28.806Z] 11:39:28     INFO - GECKO(1229) | --DOMWINDOW == 13 (0xe1d6f800) [pid = 1274] [serial = 630] [outer = (nil)] [url = about:blank]
[task 2018-03-03T11:39:28.807Z] 11:39:28     INFO - GECKO(1229) | --DOMWINDOW == 12 (0xe0f89000) [pid = 1274] [serial = 632] [outer = (nil)] [url = about:blank]
[task 2018-03-03T11:39:32.937Z] 11:39:32     INFO - GECKO(1229) | --DOMWINDOW == 11 (0xe0b0f580) [pid = 1274] [serial = 639] [outer = (nil)] [url = http://mochi.test:8888/tests/dom/serviceworkers/test/file_js_cache_syntax_error.html]
[task 2018-03-03T11:39:42.441Z] 11:39:42     INFO - GECKO(1229) | --DOMWINDOW == 10 (0xe1d6a400) [pid = 1274] [serial = 641] [outer = (nil)] [url = http://mochi.test:8888/tests/SimpleTest/iframe-between-tests.html]
[task 2018-03-03T11:39:42.442Z] 11:39:42     INFO - GECKO(1229) | --DOMWINDOW == 9 (0xe1fce800) [pid = 1274] [serial = 640] [outer = (nil)] [url = about:blank]
[task 2018-03-03T11:39:50.195Z] 11:39:50     INFO - GECKO(1229) | --DOMWINDOW == 7 (0xca72d480) [pid = 1229] [serial = 46] [outer = (nil)] [url = chrome://browser/content/browser.xul]
[task 2018-03-03T11:39:57.360Z] 11:39:57     INFO - GECKO(1229) | --DOMWINDOW == 6 (0xcfb73000) [pid = 1229] [serial = 47] [outer = (nil)] [url = about:blank]
[task 2018-03-03T11:40:19.451Z] 11:40:19     INFO - GECKO(1229) | --DOCSHELL 0xe1d6dc00 == 9 [pid = 1274] [id = {5952c8b7-f1e8-4e85-88e8-2de2dc333ca9}]
[task 2018-03-03T11:40:19.451Z] 11:40:19     INFO - GECKO(1229) | --DOCSHELL 0xe1d45c00 == 8 [pid = 1274] [id = {7e6823a3-54ae-41d6-ad0a-a0b8102273da}]
[task 2018-03-03T11:40:19.451Z] 11:40:19     INFO - GECKO(1229) | --DOCSHELL 0xe0f87800 == 7 [pid = 1274] [id = {83775113-c944-418e-ad44-91ed900c22bc}]
[task 2018-03-03T11:40:19.451Z] 11:40:19     INFO - GECKO(1229) | --DOCSHELL 0xe1e9f000 == 6 [pid = 1274] [id = {b05cd257-cb96-493d-99db-0dbef148d666}]
[task 2018-03-03T11:40:19.451Z] 11:40:19     INFO - GECKO(1229) | --DOCSHELL 0xe0ca7c00 == 5 [pid = 1274] [id = {91571f53-9c28-4118-b465-cddd0bde22b9}]
[task 2018-03-03T11:40:19.451Z] 11:40:19     INFO - GECKO(1229) | --DOCSHELL 0xe0c9dc00 == 4 [pid = 1274] [id = {e088011d-6c61-46d5-b135-e23c462f4ae0}]
[task 2018-03-03T11:40:19.452Z] 11:40:19     INFO - GECKO(1229) | --DOCSHELL 0xe1ea5800 == 3 [pid = 1274] [id = {43f73620-3ba0-48b3-b718-044875a67e40}]
[task 2018-03-03T11:40:23.665Z] 11:40:23     INFO - GECKO(1229) | --DOMWINDOW == 8 (0xe0f89800) [pid = 1274] [serial = 626] [outer = (nil)] [url = http://mochi.test:8888/tests/dom/serviceworkers/test/test_script_loader_intercepted_js_cache.html]
[task 2018-03-03T11:40:23.666Z] 11:40:23     INFO - GECKO(1229) | --DOMWINDOW == 7 (0xe0ca8c00) [pid = 1274] [serial = 607] [outer = (nil)] [url = http://mochi.test:8888/tests/dom/serviceworkers/test/test_sanitize_domain.html]
[task 2018-03-03T11:40:23.667Z] 11:40:23     INFO - GECKO(1229) | --DOMWINDOW == 6 (0xe0ca4400) [pid = 1274] [serial = 624] [outer = (nil)] [url = http://mochi.test:8888/tests/dom/serviceworkers/test/test_scopes.html]
[task 2018-03-03T11:44:24.264Z] 11:44:24     INFO - TEST-INFO | started process screentopng
[task 2018-03-03T11:44:24.536Z] 11:44:24     INFO - TEST-INFO | screentopng: exit 0
[task 2018-03-03T11:44:24.537Z] 11:44:24     INFO - Buffered messages logged at 11:39:24
[task 2018-03-03T11:44:24.538Z] 11:44:24     INFO - SpawnTask.js | Entering test setupPrefs
[task 2018-03-03T11:44:24.539Z] 11:44:24     INFO - SpawnTask.js | Leaving test setupPrefs
[task 2018-03-03T11:44:24.539Z] 11:44:24     INFO - SpawnTask.js | Entering test test_update
[task 2018-03-03T11:44:24.540Z] 11:44:24     INFO - Buffered messages logged at 11:39:25
[task 2018-03-03T11:44:24.541Z] 11:44:24     INFO - TEST-PASS | dom/serviceworkers/test/test_self_update_worker.html | Service worker updated too many times.1 
[task 2018-03-03T11:44:24.541Z] 11:44:24     INFO - TEST-PASS | dom/serviceworkers/test/test_self_update_worker.html | Service worker updated too many times.2 
[task 2018-03-03T11:44:24.542Z] 11:44:24     INFO - Buffered messages finished
[task 2018-03-03T11:44:24.542Z] 11:44:24     INFO - TEST-UNEXPECTED-FAIL | dom/serviceworkers/test/test_self_update_worker.html | Test timed out. 
[task 2018-03-03T11:44:24.543Z] 11:44:24     INFO -     reportError@SimpleTest/TestRunner.js:121:7
[task 2018-03-03T11:44:24.543Z] 11:44:24     INFO -     TestRunner._checkForHangs@SimpleTest/TestRunner.js:142:7
[task 2018-03-03T11:44:25.270Z] 11:44:25     INFO - Not taking screenshot here: see the one that was previously logged
[task 2018-03-03T11:44:25.272Z] 11:44:25     INFO - TEST-UNEXPECTED-FAIL | dom/serviceworkers/test/test_self_update_worker.html | This test left a service worker registered without cleaning it up 
[task 2018-03-03T11:44:25.272Z] 11:44:25     INFO -     afterCleanup@SimpleTest/SimpleTest.js:1189:17
[task 2018-03-03T11:44:25.274Z] 11:44:25     INFO -     executeCleanupFunction@SimpleTest/SimpleTest.js:1211:13
[task 2018-03-03T11:44:25.275Z] 11:44:25     INFO -     SimpleTest.finish@SimpleTest/SimpleTest.js:1230:5
[task 2018-03-03T11:44:25.276Z] 11:44:25     INFO -     killTest@SimpleTest/TestRunner.js:130:7
[task 2018-03-03T11:44:25.277Z] 11:44:25     INFO -     delayedKillTest@SimpleTest/TestRunner.js:157:47
Catalin, please take a look at this code which landed yesterday.
Flags: needinfo?(catalin.badea392)
Assignee: nobody → catalin.badea392
Flags: needinfo?(catalin.badea392)
The test gets stuck on waiting for the empty worker. For some reason, it fails to unregister even the first empty worker. I wonder if this is another gc bug where we drop the registration.installing object.
1. Wait for 'activating' state, since it's possible never to reach
'activated'.
2. nit change: Don't set the grace timeout to zero. This makes the test
run faster.
Attachment #8956914 - Flags: review?(bugmail)
It all boils down to self.registration.update() promise sometimes killing the worker before being resolved, thus we never get to change the state to 'activated', causing the test to get stuck.

Spec issue and probably a better explanation: https://github.com/w3c/ServiceWorker/issues/1285
Comment on attachment 8956914 [details] [diff] [review]
Avoid race in test_self_update_worker.html

Review of attachment 8956914 [details] [diff] [review]:
-----------------------------------------------------------------

Thanks for the excellent description on the github issue!  This patch definitely fixes the issue at hand, although it looks like the test could benefit from either clarification or enhancements to its consistency; see below.

Restating:
- self_update_worker.sjs is a stateful server-side JS script that returns a SW script with an incremented version every time it's invoked because it differs by a byte each time (modulo the reset logic with version=1).  The contents of the script re-trigger the update algorithm when the script reaches the "activating" state, resulting in an iterative cycle if left un-mitigated.
- The update() promise delays reaching the "activated" state, and because of how the spec and our implementation work, the SW may never advance to the "activated" state, hanging the test.
- The test itself is concerned about the update delay mechanism for SW's that are not controlling any clients.  The desire seems to be to verify that the self-updating SW is able to reach its initial "activating" state, then trigger a subsequent update which should also be able to reach activating state, but that no third update ever reaches the "activating" stage.  The test does not verify that a 2nd update begins, but does try to provide time to make sure that if the iteration was going to continue, un-mitigated, it would have that chance.
- The opportunity is provided by repeatedly registering and un-registering an empty worker using a fresh scope each time.  "activated" is still checked for in that case, as-is appropriate.  The use of separate scopes means that separate job queues are used, so there's not job queue ordering guarantees being leveraged, just a way to scale how long we wait with the effective throughput of the machine running the test, rather than depending on a hard-coded timeout.
Attachment #8956914 - Flags: review?(bugmail) → review+
Thanks for the review!
Added comments better explaining the purpose of the test.

1. Wait for 'activating' state, since it's possible never to reach
'activated'.
2. nit change: Don't set the grace timeout to zero. This makes the test
run faster.
Attachment #8956914 - Attachment is obsolete: true
Pushed by catalin.badea392@gmail.com:
https://hg.mozilla.org/integration/mozilla-inbound/rev/2131fe299b28
Avoid race in test_self_update_worker.html r=asuth
Priority: P5 → P2
https://hg.mozilla.org/mozilla-central/rev/2131fe299b28
Status: NEW → RESOLVED
Closed: 6 years ago
status-firefox60: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla60
You need to log in before you can comment on or make changes to this bug.