Bug 1467352 - Fix test_ext_storage_telemetry intermittency on win64-ccov. r=mixedpuppy
authorLuca Greco <lgreco@mozilla.com>
Thu, 23 Aug 2018 17:50:50 +0000
changeset 433027 0503d6eb70a76db7a941202ae05e1bfc448714b2
parent 433026 a56e76cb2c022213a7bbaa74d32521c2a540600f
child 433028 77c50281ad2b074a52797cba560444a5585d339c
push id34498
push usercsabou@mozilla.com
push dateThu, 23 Aug 2018 21:39:18 +0000
treeherdermozilla-central@7b78aeca32ed [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
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 1467352 - Fix test_ext_storage_telemetry intermittency on win64-ccov. r=mixedpuppy I've been unable to reproduce this intermittent locally (even by creating a "win64 ccov debug" build on Windows 10), but it has been easy enough to trigger on try. The failure is triggered when the test has been completed and it is unloading the test extension1, by the `NS_ERROR_FILE_ACCESS_DENIED` error raised from Extension's `cleanupGeneratedFile` (https://searchfox.org/mozilla-central/rev/f2ac80ab7dbde5400a3400d463e07331194dec94/toolkit/components/extensions/Extension.jsm#1835-1841). By comparing the test behavior when it runs successfully locally and fails on try, I've been finally able to identify what goes wrong when it fails: The reason for the `NS_ERROR_FILE_ACCESS_DENIED` is the ScriptCache entry for the test extension1's content script, which is created when we create and load the test content page which triggers it, this script cache entry should be cleared when the extension shutdown (and it is cleared when the test runs successfully) Then, right after the content script is executed, the contentPage is closed and this is where something goes (intermittently) wrong with the ipc (and the following pipe errors may be related to it: https://treeherder.mozilla.org/logviewer.html#?job_id=194750915&repo=mozilla-central&lineNumber=2692-2702) and, because of that, during the extension shutdown the "Extension:Shutdown" message broadcasted to all the process never reaches the process where the content script cache entry has been created (as well as "Extension:FlushJarCache" message sent to ensure that the jar cache is flushed in every process), and so the XPI file is still kept active by that process and so it fails to be removed on windows (where the usual `NS_ERROR_FILE_ACCESS_DENIED` is raised in this kind of scenarios). The underlying issue doesn't seem to be strictly related to the behavior that this test file is verifying (that is "checking that the expected telemetry data is being collected when the storage APIs are being used"), and so I think that it would be reasonable to prevent the intermittent by fixing the test (and closing the page after we unload the test extension 1 is enough to ensure that the script cache entry is always cleared as expected and the file can be removed successfully when the test is exiting). The following push to try seems to confirm it (the oranges are triggered by another unrelated test which fails intermittently in win64 ccov builds): - https://treeherder.mozilla.org/#/jobs?repo=try&revision=978e21c57ef084c4115703bf827306320e81bcad Differential Revision: https://phabricator.services.mozilla.com/D4067
--- a/toolkit/components/extensions/test/xpcshell/test_ext_storage_telemetry.js
+++ b/toolkit/components/extensions/test/xpcshell/test_ext_storage_telemetry.js
@@ -27,35 +27,31 @@ async function test_telemetry_background
   const server = createHttpServer();
   server.registerDirectory("/data/", do_get_file("data"));
   const BASE_URL = `http://localhost:${server.identity.primaryPort}/data`;
   async function contentScript() {
     await browser.storage.local.set({a: "b"});
     await browser.storage.local.get("a");
-    browser.runtime.sendMessage("contentDone");
+    browser.test.sendMessage("contentDone");
   let baseManifest = {
     permissions: ["storage"],
     content_scripts: [
         "matches": ["http://*/*/file_sample.html"],
         "js": ["content_script.js"],
   let baseExtInfo = {
     async background() {
-      browser.runtime.onMessage.addListener(msg => {
-        browser.test.sendMessage(msg);
-      });
       await browser.storage.local.set({a: "b"});
       await browser.storage.local.get("a");
     files: {
       "content_script.js": contentScript,
@@ -117,20 +113,19 @@ async function test_telemetry_background
           `Additional data recorded for histogram: ${id}.`);
   await extension2.unload();
   // Run a content script.
   process = IS_OOP ? "content" : "parent";
   let expectedCount = IS_OOP ? 1 : 3;
-  let contentScriptPromise = extension1.awaitMessage("contentDone");
   let contentPage = await ExtensionTestUtils.loadContentPage(`${BASE_URL}/file_sample.html`);
-  await contentScriptPromise;
-  await contentPage.close();
+  await extension1.awaitMessage("contentDone");
   for (let id of expectedNonEmptyHistograms) {
     await promiseTelemetryRecorded(id, process, expectedCount);
   // Telemetry from extension1's content script should be recorded.
   snapshots = getSnapshots(process);
   for (let id of expectedNonEmptyHistograms) {
@@ -139,16 +134,18 @@ async function test_telemetry_background
   await extension1.unload();
   // Telemetry for histograms that we expect to be empty.
   for (let id of expectedEmptyHistograms) {
     ok(!(id in snapshots), `No data recorded for histogram: ${id}.`);
+  await contentPage.close();
 add_task(function test_telemetry_background_file_backend() {
   return runWithPrefs([[ExtensionStorageIDB.BACKEND_ENABLED_PREF, false]],
 add_task(function test_telemetry_background_idb_backend() {