1411746 - service worker mochitests can call clients.claim() before the worker is activated

Status: RESOLVED FIXED

(Core :: DOM: Service Workers, enhancement)

Description

[Ben Kelly [:bkelly, not reviewing]]

We have some tests that use this style of initialization:

  let reg = await navigator.serviceWorker.register(script);
  let worker = reg.installing || reg.active;
  worker.postMessage('claim');
  await waitForControlled(window);

This has a race condition because clients.claim() should throw if the SW is not active yet.  Currently we happen to win these races, but in bug 1293277 this state check will be strict.

We just need to fix these tests to do waitForState() on the worker.

Comment 1

[Ben Kelly [:bkelly, not reviewing]]

Attachment: Make tests that wait for controller change also wait for SW activation before claim(). r=tt

Tom, do you mind reviewing this test patch?  It just makes us wait for the service workers to activate before triggering the claim().  I also made these tests all use the utils.js version of waitForControlled().

https://treeherder.mozilla.org/#/jobs?repo=try&revision=c9b73469ecab2da99649a674a322629047ec10ba

Comment 2

[Tom Tung [:tt, :ttung]]

Comment on attachment 8922083 [details] [diff] [review]
Make tests that wait for controller change also wait for SW activation before claim(). r=tt

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

Oh, I didn't notice that claim will reject the promise if the service worker is not an active worker. Thanks for correcting this!

Comment 3

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/651339b407c2
Make tests that wait for controller change also wait for SW activation before claim(). r=tt

Comment 4

[Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)]

Backed out for failing mochitest dom/workers/test/serviceworkers/test_unresolved_fetch_interception.html on Windows 7 debug without e10s:

https://hg.mozilla.org/integration/mozilla-inbound/rev/e863dc231d0095d0cc7bc1ddbf83a51c6958c343

Push with failure: https://treeherder.mozilla.org/#/jobs?repo=mozilla-inbound&revision=651339b407c222f1689b7d444e7deeca1229e676&filter-resultStatus=usercancel&filter-resultStatus=runnable&filter-resultStatus=testfailed&filter-resultStatus=busted&filter-resultStatus=exception
Failure log: https://treeherder.mozilla.org/logviewer.html#?job_id=139887817&repo=mozilla-inbound

15:28:04     INFO -  1262 INFO monitorConsole | [1] did not match {"message":"[JavaScript Error: \"1509031680806\tBrowser.Experiments.Experiments\tERROR\tExperiments #0::_loadManifest - failure to fetch/parse manifest (continuing anyway): Error: Experiments - XHR status for http://127.0.0.1:8888/experiments-dummy/manifest is 404\" {file: \"resource://gre/modules/Log.jsm\" line: 752}]\nApp_append@resource://gre/modules/Log.jsm:752:9\nlog@resource://gre/modules/Log.jsm:390:7\ngetLoggerWithMessagePrefix/proxy.log@resource://gre/modules/Log.jsm:505:44\nExperiments.Experiments/this._log.log@resource:///modules/experiments/Experiments.jsm:328:5\nerror@resource://gre/modules/Log.jsm:398:5\n_loadManifest@resource:///modules/experiments/Experiments.jsm:845:7\nasync*_main@resource:///modules/experiments/Experiments.jsm:815:15\nasync*_run/this._mainTask<@resource:///modules/experiments/Experiments.jsm:782:17\nasync*_run@resource:///modules/experiments/Experiments.jsm:780:25\nupdateManifest@resource:///modules/experiments/Experiments.jsm:868:12\nnotify@jar:file:///Z:/task_1509029945/build/application/firefox/browser/omni.ja!/components/ExperimentsService.js:51:7\nTM_notify/<@jar:file:///Z:/task_1509029945/build/application/firefox/omni.ja!/components/nsUpdateTimerManager.js:217:11\nTM_notify@jar:file:///Z:/task_1509029945/build/application/firefox/omni.ja!/components/nsUpdateTimerManager.js:262:7\n","errorMessage":"1509031680806\tBrowser.Experiments.Experiments\tERROR\tExperiments #0::_loadManifest - failure to fetch/parse manifest (continuing anyway): Error: Experiments - XHR status for http://127.0.0.1:8888/experiments-dummy/manifest is 404","sourceName":"resource://gre/modules/Log.jsm","sourceLine":"","lineNumber":752,"columnNumber":0,"category":"XPConnect JavaScript","windowID":0,"isScriptError":true,"isWarning":false,"isException":false,"isStrict":false,"innerWindowID":0}
15:28:04     INFO -  Buffered messages finished
15:28:04    ERROR -  1263 INFO TEST-UNEXPECTED-FAIL | dom/workers/test/serviceworkers/test_unresolved_fetch_interception.html | Test timed out.
15:28:04     INFO -      reportError@SimpleTest/TestRunner.js:121:7
15:28:04     INFO -      TestRunner._checkForHangs@SimpleTest/TestRunner.js:142:7
15:28:04     INFO -      setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
15:28:04     INFO -      setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
15:28:04     INFO -      setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
15:28:04     INFO -      setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
15:28:04     INFO -      setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
15:28:04     INFO -      setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
15:28:04     INFO -      setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
15:28:04     INFO -      setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
15:28:04     INFO -      setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
15:28:04     INFO -      setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
15:28:04     INFO -      setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
15:28:04     INFO -      setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
15:28:04     INFO -      setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
15:28:04     INFO -      TestRunner.runTests@SimpleTest/TestRunner.js:380:5
15:28:04     INFO -      RunSet.runtests@SimpleTest/setup.js:194:3
15:28:04     INFO -      RunSet.runall@SimpleTest/setup.js:173:5
15:28:04     INFO -      hookupTests@SimpleTest/setup.js:266:5
15:28:04     INFO -  parseTestManifest@http://mochi.test:8888/manifestLibrary.js:36:5
15:28:04     INFO -  getTestManifest/req.onload@http://mochi.test:8888/manifestLibrary.js:49:11
15:28:04     INFO -  EventHandlerNonNull*getTestManifest@http://mochi.test:8888/manifestLibrary.js:45:3
15:28:04     INFO -      hookup@SimpleTest/setup.js:246:5
15:28:04     INFO -  EventHandlerNonNull*@http://mochi.test:8888/tests?autorun=1&closeWhenDone=1&consoleLevel=INFO&manifestFile=tests.json&dumpOutputDirectory=c%3A%5Cusers%5Cgenericworker%5Cappdata%5Clocal%5Ctemp&cleanupCrashes=true:11:1
15:28:05     INFO -  Not taking screenshot here: see the one that was previously logged

Comment 5

[Ben Kelly [:bkelly, not reviewing]]

Attachment: Make tests that wait for controller change also wait for SW activation before claim(). r=tt

Fix test_unresolved_fetch_interception.html.  This passes a --verify locally.

Leaving NI until the tree opens and I can re-land the patch.

Comment 6

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/1ce6d2b0a418
Make tests that wait for controller change also wait for SW activation before claim(). r=tt

Comment 7

[Phil Ringnalda (:philor)]

Same again, https://treeherder.mozilla.org/logviewer.html#?job_id=140088285&repo=mozilla-inbound. Backed out in https://hg.mozilla.org/integration/mozilla-inbound/rev/613356d1cb69

Comment 8

[Tom Tung [:tt, :ttung]]

Sorry for not catching this :(

Does "claim()" make the service worker live longer than expected? 

"test_unresolved_fetch_interception.html" post a message to the service worker [1] and it'll trigger client.claim after applying the patch. 

[1] http://searchfox.org/mozilla-central/source/dom/workers/test/serviceworkers/test_unresolved_fetch_interception.html#85

Comment 9

[Tom Tung [:tt, :ttung]]

(In reply to Tom Tung [:tt] from comment #8)
Eden and I test it locally on MacBookPro. Somehow |self.onmessage = null| doesn't cancel the message listener.

We can make the test pass by adding a if-statement to client.claim() (like: if (event.data === "claim") { event.waitUntil(client.claim()); } ).

Comment 10

[Eden Chuang[:edenchuang]]

The test case can be passed in e10s mode, it fails only under non-e10s.

Comment 11

[Ben Kelly [:bkelly, not reviewing]]

I'll just drop the changes to this particular test case if I can.  It's doing some weird stuff the other tests aren't.

Comment 12

[Ben Kelly [:bkelly, not reviewing]]

Actually, checking for `event.data === 'claim'` in the message handler fixes the problem.  I verified it works now in non-e10s locally.

Sorry I didn't catch this before.  I thought --verify ran non-e10s and e10s checks.

Comment 13

[Ben Kelly [:bkelly, not reviewing]]

Attachment: Make tests that wait for controller change also wait for SW activation before claim(). r=tt

Comment 14

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/ee9f3f7292f4
Make tests that wait for controller change also wait for SW activation before claim(). r=tt

Comment 15

[Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)]

https://hg.mozilla.org/mozilla-central/rev/ee9f3f7292f4

Comment 16

[Intermittent Failures Robot]

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

Repository breakdown:
* mozilla-inbound: 5

Platform breakdown:
* windows7-32: 4
* osx-10-10: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1411746&startday=2017-10-23&endday=2017-10-29&tree=all

Comment 17

[Pulsebot]

https://hg.mozilla.org/releases/mozilla-esr140/rev/bf516965ea5c