Bug 1167553 - Timeout-related Service Worker shutdowns should be reported. r=bkelly
authorAndrew Sutherland <asutherland@asutherland.org>
Wed, 06 Jul 2016 16:34:19 -0400
changeset 344443 f3a1648af4e852c60f879ca8c7f83e8342e214ab
parent 344442 b8ca65757e7c645d759afe80d0fb8fd3f15d80d6
child 344444 1bee8d2da23ec894980fb14f516210fd83e5b9f9
child 344480 a22656e76df720def44b182a645f9ba78dc085d6
push id6389
push userraliiev@mozilla.com
push dateMon, 19 Sep 2016 13:38:22 +0000
treeherdermozilla-beta@01d67bfe6c81 [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersbkelly
bugs1167553
milestone50.0a1
first release with
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
last release without
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
Bug 1167553 - Timeout-related Service Worker shutdowns should be reported. r=bkelly Log a message when shutting down a service worker with pending promises. Looks like: Terminating ServiceWorker for scope ‘http://mochi.test:8888/tests/dom/workers/test/serviceworkers/’ with pending waitUntil/respondWith promises because of grace timeout.
dom/locales/en-US/chrome/dom/dom.properties
dom/workers/ServiceWorkerPrivate.cpp
dom/workers/test/serviceworkers/error_reporting_helpers.js
dom/workers/test/serviceworkers/mochitest.ini
dom/workers/test/serviceworkers/test_error_reporting.html
dom/workers/test/serviceworkers/test_unresolved_fetch_interception.html
dom/workers/test/serviceworkers/unresolved_fetch_worker.js
--- a/dom/locales/en-US/chrome/dom/dom.properties
+++ b/dom/locales/en-US/chrome/dom/dom.properties
@@ -207,16 +207,18 @@ InterceptionRejectedResponseWithURL=Failed to load ‘%1$S’. A ServiceWorker passed a promise to FetchEvent.respondWith() that rejected with ‘%2$S’.
 # LOCALIZATION NOTE: Do not translate "ServiceWorker", "promise", "FetchEvent.respondWith()", or "Response". %1$S is a URL. %2$S is an error string.
 InterceptedNonResponseWithURL=Failed to load ‘%1$S’. A ServiceWorker passed a promise to FetchEvent.respondWith() that resolved with non-Response value ‘%2$S’.
 # LOCALIZATION NOTE: Do not translate "ServiceWorker", "Service-Worker-Allowed" or "HTTP". %1$S and %2$S are URLs.
 ServiceWorkerScopePathMismatch=Failed to register a ServiceWorker: The path of the provided scope ‘%1$S’ is not under the max scope allowed ‘%2$S’. Adjust the scope, move the Service Worker script, or use the Service-Worker-Allowed HTTP header to allow the scope.
 # LOCALIZATION NOTE: Do not translate "ServiceWorker". %1$S is a URL representing the scope of the ServiceWorker, %2$S is a stringified numeric HTTP status code like "404" and %3$S is a URL.
 ServiceWorkerRegisterNetworkError=Failed to register/update a ServiceWorker for scope ‘%1$S’: Load failed with status %2$S for script ‘%3$S’.
 # LOCALIZATION NOTE: Do not translate "ServiceWorker". %1$S is a URL representing the scope of the ServiceWorker, %2$S is a MIME Media Type like "text/plain" and %3$S is a URL.
 ServiceWorkerRegisterMimeTypeError=Failed to register/update a ServiceWorker for scope ‘%1$S’: Bad Content-Type of ‘%2$S’ received for script ‘%3$S’.  Must be ‘text/javascript’, ‘application/x-javascript’, or ‘application/javascript’.
+# LOCALIZATION NOTE: Do not translate "ServiceWorker". %1$S is a URL representing the scope of the ServiceWorker.
+ServiceWorkerGraceTimeoutTermination=Terminating ServiceWorker for scope ‘%1$S’ with pending waitUntil/respondWith promises because of grace timeout.
 ExecCommandCutCopyDeniedNotInputDriven=document.execCommand(‘cut’/‘copy’) was denied because it was not called from inside a short running user-generated event handler.
 ManifestShouldBeObject=Manifest should be an object.
 ManifestScopeURLInvalid=The scope URL is invalid.
 ManifestScopeNotSameOrigin=The scope URL must be same origin as document.
 ManifestStartURLOutsideScope=The start URL is outside the scope, so the scope is invalid.
 ManifestStartURLInvalid=The start URL is invalid.
 ManifestStartURLShouldBeSameOrigin=The start URL must be same origin as document.
 # LOCALIZATION NOTE: %1$S is the name of the object whose property is invalid. %2$S is the name of the invalid property. %3$S is the expected type of the property value. E.g. "Expected the manifest's start_url member to be a string."
--- a/dom/workers/ServiceWorkerPrivate.cpp
+++ b/dom/workers/ServiceWorkerPrivate.cpp
@@ -1892,16 +1892,24 @@ ServiceWorkerPrivate::TerminateWorkerCal
   MOZ_ASSERT(aPrivate);
 
   RefPtr<ServiceWorkerPrivate> serviceWorkerPrivate =
     static_cast<ServiceWorkerPrivate*>(aPrivate);
 
   MOZ_ASSERT(aTimer == serviceWorkerPrivate->mIdleWorkerTimer,
       "Invalid timer!");
 
+  // mInfo must be non-null at this point because NoteDeadServiceWorkerInfo
+  // which zeroes it calls TerminateWorker which cancels our timer which will
+  // ensure we don't get invoked even if the nsTimerEvent is in the event queue.
+  ServiceWorkerManager::LocalizeAndReportToAllClients(
+    serviceWorkerPrivate->mInfo->Scope(),
+    "ServiceWorkerGraceTimeoutTermination",
+    nsTArray<nsString> { NS_ConvertUTF8toUTF16(serviceWorkerPrivate->mInfo->Scope()) });
+
   serviceWorkerPrivate->TerminateWorker();
 }
 
 void
 ServiceWorkerPrivate::RenewKeepAliveToken(WakeUpReason aWhy)
 {
   // We should have an active worker if we're renewing the keep alive token.
   MOZ_ASSERT(mWorkerPrivate);
new file mode 100644
--- /dev/null
+++ b/dom/workers/test/serviceworkers/error_reporting_helpers.js
@@ -0,0 +1,68 @@
+"use strict";
+
+/**
+ * Helpers for use in tests that want to verify that localized error messages
+ * are logged during the test.  Because most of our errors (ex:
+ * ServiceWorkerManager) generate nsIScriptError instances with flattened
+ * strings (the interpolated arguments aren't kept around), we load the string
+ * bundle and use it to derive the exact string message we expect for the given
+ * payload.
+ **/
+
+let stringBundleService =
+  SpecialPowers.Cc["@mozilla.org/intl/stringbundle;1"]
+               .getService(SpecialPowers.Ci.nsIStringBundleService);
+let localizer =
+  stringBundleService.createBundle("chrome://global/locale/dom/dom.properties");
+
+/**
+ * Start monitoring the console for the given localized error message string(s)
+ * with the given arguments to be logged.  Call before running code that will
+ * generate the console message.  Pair with a call to
+ * `wait_for_expected_message` invoked after the message should have been
+ * generated.
+ *
+ * Multiple error messages can be expected, just repeat the msgId and args
+ * argument pair as needed.
+ *
+ * @param {String} msgId
+ *   The localization message identifier used in the properties file.
+ * @param {String[]} args
+ *   The list of formatting arguments we expect the error to be generated with.
+ * @return {Object} Promise/handle to pass to wait_for_expected_message.
+ */
+function expect_console_message(/* msgId, args, ... */) {
+  let expectations = [];
+  // process repeated paired arguments of: msgId, args
+  for (let i = 0; i < arguments.length; i += 2) {
+    let msgId = arguments[i];
+    let args = arguments[i + 1];
+    expectations.push({
+      errorMessage: localizer.formatStringFromName(msgId, args, args.length)
+    });
+  }
+  return new Promise(resolve => {
+    SimpleTest.monitorConsole(resolve, expectations);
+  });
+}
+let expect_console_messages = expect_console_message;
+
+/**
+ * Stop monitoring the console, returning a Promise that will be resolved when
+ * the sentinel console message sent through the async data path has been
+ * received.  The Promise will not reject on failure; instead a mochitest
+ * failure will have been generated by ok(false)/equivalent by the time it is
+ * resolved.
+ */
+function wait_for_expected_message(expectedPromise) {
+  SimpleTest.endMonitorConsole();
+  return expectedPromise;
+}
+
+/**
+ * Derive an absolute URL string from a relative URL to simplify error message
+ * argument generation.
+ */
+function make_absolute_url(relUrl) {
+  return new URL(relUrl, window.location).href;
+}
--- a/dom/workers/test/serviceworkers/mochitest.ini
+++ b/dom/workers/test/serviceworkers/mochitest.ini
@@ -203,16 +203,17 @@ support-files =
   lorem_script.js
   file_blob_response_worker.js
   !/dom/security/test/cors/file_CrossSiteXHR_server.sjs
   !/dom/tests/mochitest/notification/MockServices.js
   !/dom/tests/mochitest/notification/NotificationTest.js
   blocking_install_event_worker.js
   sw_bad_mime_type.js
   sw_bad_mime_type.js^headers^
+  error_reporting_helpers.js
 
 [test_bug1151916.html]
 [test_bug1240436.html]
 [test_claim.html]
 [test_claim_fetch.html]
 [test_claim_oninstall.html]
 [test_close.html]
 [test_controller.html]
--- a/dom/workers/test/serviceworkers/test_error_reporting.html
+++ b/dom/workers/test/serviceworkers/test_error_reporting.html
@@ -1,81 +1,34 @@
 <!DOCTYPE HTML>
 <html>
 <head>
   <title>Test Error Reporting of Service Worker Failures</title>
   <script src="/tests/SimpleTest/SimpleTest.js"></script>
   <script src="/tests/SimpleTest/SpawnTask.js"></script>
+  <script src="error_reporting_helpers.js"></script>
   <link rel="stylesheet" href="/tests/SimpleTest/test.css"/>
   <meta http-equiv="Content-type" content="text/html;charset=UTF-8">
 </head>
 <body>
 
 <script type="text/javascript">
 "use strict";
+
 /**
  * Test that a bunch of service worker coding errors and failure modes that
  * might otherwise be hard to diagnose are surfaced as console error messages.
  * The driving use-case is minimizing cursing from a developer looking at a
  * document in Firefox testing a page that involves service workers.
  *
  * This test assumes that errors will be reported via
  * ServiceWorkerManager::ReportToAllClients and that that method is reliable and
- * tested via some other file.  Because this generates nsIScriptError instances
- * with flattened strings (the interpolated arguments aren't kept around), we
- * load the string bundle and use it to derive the exact string message we
- * expect for the given payload.
+ * tested via some other file.
  **/
 
-let stringBundleService =
-  SpecialPowers.Cc["@mozilla.org/intl/stringbundle;1"]
-               .getService(SpecialPowers.Ci.nsIStringBundleService);
-let localizer =
-  stringBundleService.createBundle("chrome://global/locale/dom/dom.properties");
-
-/**
- * Start monitoring the console for the given localized error message string
- * with the given arguments to be logged.  Call before running code that will
- * generate the console message.  Pair with a call to
- * `wait_for_expected_message` invoked after the message should have been
- * generated.
- *
- * @param {String} msgId
- *   The localization message identifier used in the properties file.
- * @param {String[]} args
- *   The list of formatting arguments we expect the error to be generated with.
- * @return {Object} Promise/handle to pass to wait_for_expected_message.
- */
-function expect_console_message(msgId, args) {
-  let expectedString = localizer.formatStringFromName(msgId, args, args.length);
-  return new Promise(resolve => {
-    SimpleTest.monitorConsole(resolve, [{ errorMessage: expectedString }])
-  });
-}
-
-/**
- * Stop monitoring the console, returning a Promise that will be resolved when
- * the sentinel console message sent through the async data path has been
- * received.  The Promise will not reject on failure; instead a mochitest
- * failure will have been generated by ok(false)/equivalent by the time it is
- * resolved.
- */
-function wait_for_expected_message(expectedPromise) {
-  SimpleTest.endMonitorConsole();
-  return expectedPromise;
-}
-
-/**
- * Derive an absolute URL string from a relative URL to simplify error message
- * argument generation.
- */
-function make_absolute_url(relUrl) {
-  return new URL(relUrl, window.location).href;
-}
-
 add_task(function setupPrefs() {
   return SpecialPowers.pushPrefEnv({"set": [
     ["dom.serviceWorkers.enabled", true],
     ["dom.serviceWorkers.testing.enabled", true],
     ["dom.caches.testing.enabled", true],
   ]});
 });
 
--- a/dom/workers/test/serviceworkers/test_unresolved_fetch_interception.html
+++ b/dom/workers/test/serviceworkers/test_unresolved_fetch_interception.html
@@ -1,94 +1,100 @@
 <!DOCTYPE HTML>
 <html>
 <!--
   Test that an unresolved respondWith promise will reset the channel when
-  the service worker is terminated due to idling.
+  the service worker is terminated due to idling, and that appropriate error
+  messages are logged for both the termination of the serice worker and the
+  resetting of the channel.
   -->
 <head>
   <title>Test for Bug 1188545</title>
-  <script type="text/javascript" src="/tests/SimpleTest/SimpleTest.js"></script>
+  <script src="/tests/SimpleTest/SimpleTest.js"></script>
+  <script src="/tests/SimpleTest/SpawnTask.js"></script>
+  <script src="error_reporting_helpers.js"></script>
   <link rel="stylesheet" type="text/css" href="/tests/SimpleTest/test.css" />
   <meta http-equiv="Content-type" content="text/html;charset=UTF-8">
 </head>
 <a target="_blank" href="https://bugzilla.mozilla.org/show_bug.cgi?id=1188545">Mozilla Bug 118845</a>
 <p id="display"></p>
 <div id="content" style="display: none">
 
 </div>
 <pre id="test">
 </pre>
 
 <script class="testbody" type="text/javascript">
-
-  function start() {
-    return navigator.serviceWorker.register("unresolved_fetch_worker.js", {scope: "./"})
-    .then((swr) => ({registration: swr}));
-  }
-
-  function waitControlled(ctx) {
-    var p = new Promise(function(res, rej) {
-      if (navigator.serviceWorker.controller) {
-        res(ctx);
-      } else {
-        navigator.serviceWorker.oncontrollerchange = function() {
-          res(ctx);
-          navigator.serviceWorker.oncontrollerchange = null;
-        }
-      }
-    });
-
-    return p;
-  }
-
-  function unregister(ctx) {
-    return ctx.registration.unregister().then(function(result) {
-      ok(result, "Unregister should return true.");
-    }, function(e) {
-      dump("Unregistering the SW failed with " + e + "\n");
-    });
-  }
-
-  function testFetch(ctx) {
-    ok(navigator.serviceWorker.controller, "Controlled");
-
-    var p = fetch("something_that_doesnt_exist_abcd.html")
-      .catch(function() {
-        ok(true, "channel was reset");
-      }).then(function() { return ctx; });
-
-    navigator.serviceWorker.onmessage = function(event) {
-      ok(event.data == "continue", "Got continue message from worker.");
-      // close worker
-      SpecialPowers.pushPrefEnv({"set": [
-        ["dom.serviceWorkers.idle_extended_timeout", 0]
-      ]}, function() {
-        navigator.serviceWorker.controller.postMessage("shutdown");
-      });
-
-      navigator.serviceWorker.onmessage = null;
-    }
-
-    return p;
-  }
-
-  function runTest() {
-    start()
-      .then(waitControlled)
-      .then(testFetch)
-      .then(unregister)
-      .catch(function(e) {
-        ok(false, "Some test failed with error " + e)
-      }).then(SimpleTest.finish);
-  }
-
-  SpecialPowers.pushPrefEnv({"set": [
-    ["dom.serviceWorkers.idle_timeout", 0],
-    ["dom.serviceWorkers.idle_extended_timeout", 299999],
-    ["dom.serviceWorkers.exemptFromPerDomainMax", true],
+// (This doesn't really need to be its own task, but it allows the actual test
+// case to be self-contained.)
+add_task(function setupPrefs() {
+  return SpecialPowers.pushPrefEnv({"set": [
     ["dom.serviceWorkers.enabled", true],
     ["dom.serviceWorkers.testing.enabled", true],
-    ]}, runTest);
-  SimpleTest.waitForExplicitFinish();
+  ]});
+});
+
+add_task(function* grace_timeout_termination_with_interrupted_intercept() {
+  // Setup timeouts so that the service worker will go into grace timeout after
+  // a zero-length idle timeout.
+  yield SpecialPowers.pushPrefEnv({"set": [
+    ["dom.serviceWorkers.idle_timeout", 0],
+    ["dom.serviceWorkers.idle_extended_timeout", 299999]]});
+
+  // The SW will claim us once it activates; this is async, start listening now.
+  let waitForControlled = new Promise((resolve) => {
+    navigator.serviceWorker.oncontrollerchange = resolve;
+  });
+
+  let registration = yield navigator.serviceWorker.register(
+    "unresolved_fetch_worker.js", { scope: "./"} );
+  yield waitForControlled;
+  ok(navigator.serviceWorker.controller, "Controlled"); // double check!
+
+  // We want to make sure the SW is active and processing the fetch before we
+  // try and kill it.  It sends us a message when it has done so.
+  let waitForFetchActive = new Promise((resolve) => {
+    navigator.serviceWorker.onmessage = resolve;
+  });
+
+  // Issue a fetch which the SW will respondWith() a never resolved promise.
+  // The fetch, however, will terminate when the SW is killed, so check that.
+  let hangingFetch = fetch("does_not_exist.html")
+    .then(() => { ok(false, "should have rejected "); },
+          () => { ok(true, "hung fetch terminates when worker dies"); });
+
+  yield waitForFetchActive;
+
+  let expectedMessage = expect_console_message(
+    // Termination error
+    "ServiceWorkerGraceTimeoutTermination",
+    [make_absolute_url("./")],
+    // The interception failure error generated by the RespondWithHandler
+    // destructor when it notices it didn't get a response before being
+    // destroyed.  It logs via the intercepted channel nsIConsoleReportCollector
+    // that is eventually flushed to our document and its console.
+    "InterceptionFailedWithURL",
+    [make_absolute_url("does_not_exist.html")]
+  );
+
+  // Zero out the grace timeout too so the worker will get terminated after two
+  // zero-length timer firings.  Note that we need to do something to get the
+  // SW to renew its keepalive for this to actually cause the timers to be
+  // rescheduled...
+  yield SpecialPowers.pushPrefEnv({"set": [
+    ["dom.serviceWorkers.idle_extended_timeout", 0]]});
+  // ...which we do by postMessaging it.
+  navigator.serviceWorker.controller.postMessage("doomity doom doom");
+
+  // Now wait for signs that the worker was terminated by the fetch failing.
+  yield hangingFetch;
+
+  // The worker should now be dead and the error logged, wait/assert.
+  yield wait_for_expected_message(expectedMessage);
+
+  // roll back all of our test case specific preferences and otherwise cleanup
+  yield SpecialPowers.popPrefEnv();
+  yield SpecialPowers.popPrefEnv();
+  yield registration.unregister();
+});
 </script>
 </body>
 </html>
--- a/dom/workers/test/serviceworkers/unresolved_fetch_worker.js
+++ b/dom/workers/test/serviceworkers/unresolved_fetch_worker.js
@@ -1,17 +1,19 @@
+var keepPromiseAlive;
 onfetch = function(event) {
   event.waitUntil(
     clients.matchAll()
            .then(clients => {
              clients.forEach(client => {
                client.postMessage("continue");
              });
            })
   );
 
-  // never resolve
-  event.respondWith(new Promise(function(res, rej) {}));
+  // Never resolve, and keep it alive on our global so it can't get GC'ed and
+  // make this test weird and intermittent.
+  event.respondWith((keepPromiseAlive = new Promise(function(res, rej) {})));
 }
 
 onactivate = function(event) {
   event.waitUntil(clients.claim());
 }