Bug 1188999 - LogShake does not fetch about:memory reports. r=gerard-majax

commit a4a4e4216c8b7ca06bfe1d5ceeaecd54abc1a7d1
Author: James Hobin <hobinjk@gmail.com>

Fixes issue where LogShake would race in its reading code. Adds basic test
which should detect this specific race condition.

b2g/components/LogCapture.jsm

@@ -194,17 +194,26 @@ let LogCapture = {
    * as an ArrayBuffer.
    */
   getScreenshot: function() {
-    this.ensureLoaded();
     let deferred = Promise.defer();
+    try {
+      this.ensureLoaded();
 
-    let fr = Cc["@mozilla.org/files/filereader;1"]
-                .createInstance(Ci.nsIDOMFileReader);
+      let fr = Cc["@mozilla.org/files/filereader;1"]
+                  .createInstance(Ci.nsIDOMFileReader);
 
-    fr.onload = function(evt) {
-      deferred.resolve(new Uint8Array(evt.target.result));
-    };
+      fr.onload = function(evt) {
+        deferred.resolve(new Uint8Array(evt.target.result));
+      };
 
-    fr.readAsArrayBuffer(Screenshot.get());
+      fr.onerror = function(evt) {
+        deferred.reject(evt);
+      };
+
+      fr.readAsArrayBuffer(Screenshot.get());
+    } catch(e) {
+      // We pass any errors through to the deferred Promise
+      deferred.reject(e);
+    }
 
     return deferred.promise;
   }

b2g/components/LogParser.jsm

@@ -16,10 +16,14 @@ function parseLogArray(array) {
   let data = new DataView(array.buffer);
   let byteString = String.fromCharCode.apply(null, array);
 
+  // Length of bytes that precede the payload of a log message
+  // From the 5 Uint32 and 1 Uint8 reads
+  const HEADER_LENGTH = 21;
+
   let logMessages = [];
   let pos = 0;
 
-  while (pos < byteString.length) {
+  while (pos + HEADER_LENGTH < byteString.length) {
     // Parse a single log entry
 
     // Track current offset from global position

b2g/components/LogShake.jsm

@@ -277,15 +277,18 @@ let LogShake = {
    * resolve to an array of log filenames.
    */
   captureLogs: function() {
-    let logArrays = this.readLogs();
-    return this.saveLogs(logArrays);
+    return this.readLogs().then(logArrays => {
+      return this.saveLogs(logArrays);
+    });
   },
 
   /**
    * Read in all log files, returning their formatted contents
+   * @return {Promise<Array>}
    */
   readLogs: function() {
     let logArrays = {};
+    let readPromises = [];
 
     try {
       logArrays["properties"] =
@@ -295,14 +298,15 @@ let LogShake = {
     }
 
     // Let Gecko perfom the dump to a file, and just collect it
-    try {
+    let readAboutMemoryPromise = new Promise(resolve => {
+      // Wrap the readAboutMemory promise to make it infallible
       LogCapture.readAboutMemory().then(aboutMemory => {
         let file = OS.Path.basename(aboutMemory);
         let logArray;
         try {
           logArray = LogCapture.readLogFile(aboutMemory);
           if (!logArray) {
-            debug("LogCapture.readLogFile() returned nothing about:memory ");
+            debug("LogCapture.readLogFile() returned nothing for about:memory");
           }
           // We need to remove the dumped file, now that we have it in memory
           OS.File.remove(aboutMemory);
@@ -310,18 +314,25 @@ let LogShake = {
           Cu.reportError("Unable to handle about:memory dump: " + ex);
         }
         logArrays[file] = LogParser.prettyPrintArray(logArray);
+        resolve();
+      }, ex => {
+        Cu.reportError("Unable to get about:memory dump: " + ex);
+        resolve();
       });
-    } catch (ex) {
-      Cu.reportError("Unable to get about:memory dump: " + ex);
-    }
+    });
+    readPromises.push(readAboutMemoryPromise);
 
-    try {
+    // Wrap the promise to make it infallible
+    let readScreenshotPromise = new Promise(resolve => {
       LogCapture.getScreenshot().then(screenshot => {
         logArrays["screenshot.png"] = screenshot;
+        resolve();
+      }, ex => {
+        Cu.reportError("Unable to get screenshot dump: " + ex);
+        resolve();
       });
-    } catch (ex) {
-      Cu.reportError("Unable to get screenshot dump: " + ex);
-    }
+    });
+    readPromises.push(readScreenshotPromise);
 
     for (let loc in this.LOGS_WITH_PARSERS) {
       let logArray;
@@ -343,7 +354,12 @@ let LogShake = {
         continue;
       }
     }
-    return logArrays;
+
+    // Because the promises we depend upon can't fail this means that the
+    // blocking log reads will always be honored.
+    return Promise.all(readPromises).then(() => {
+      return logArrays;
+    });
   },
 
   /**

b2g/components/test/unit/head_logshake_gonk.js

@@ -0,0 +1,58 @@
+/**
+ * Boostrap LogShake's tests that need gonk support.
+ * This is creating a fake sdcard for LogShake tests and importing LogShake and
+ * osfile
+ */
+
+/* jshint moz: true */
+/* global Components, LogCapture, LogShake, ok, add_test, run_next_test, dump,
+   do_get_profile, OS, volumeService, equal, XPCOMUtils */
+/* exported setup_logshake_mocks */
+
+/* disable use strict warning */
+/* jshint -W097 */
+
+"use strict";
+
+const Cu = Components.utils;
+const Ci = Components.interfaces;
+const Cc = Components.classes;
+
+Cu.import("resource://gre/modules/XPCOMUtils.jsm");
+Cu.import("resource://gre/modules/osfile.jsm");
+
+XPCOMUtils.defineLazyServiceGetter(this, "volumeService",
+                                   "@mozilla.org/telephony/volume-service;1",
+                                   "nsIVolumeService");
+
+let sdcard;
+
+function setup_logshake_mocks() {
+  do_get_profile();
+  setup_fs();
+}
+
+function setup_fs() {
+  OS.File.makeDir("/data/local/tmp/sdcard/", {from: "/data"}).then(function() {
+    setup_sdcard();
+  });
+}
+
+function setup_sdcard() {
+  let volName = "sdcard";
+  let mountPoint = "/data/local/tmp/sdcard";
+  volumeService.createFakeVolume(volName, mountPoint);
+
+  let vol = volumeService.getVolumeByName(volName);
+  ok(vol, "volume shouldn't be null");
+  equal(volName, vol.name, "name");
+  equal(Ci.nsIVolume.STATE_MOUNTED, vol.state, "state");
+
+  ensure_sdcard();
+}
+
+function ensure_sdcard() {
+  sdcard = volumeService.getVolumeByName("sdcard").mountPoint;
+  ok(sdcard, "Should have a valid sdcard mountpoint");
+  run_next_test();
+}

b2g/components/test/unit/test_logshake_gonk.js

@@ -3,8 +3,9 @@
  * for Gonk-specific parts
  */
 
-/* jshint moz: true */
-/* global Components, LogCapture, LogShake, ok, add_test, run_next_test, dump */
+/* jshint moz: true, esnext: true */
+/* global Cu, LogCapture, LogShake, ok, add_test, run_next_test, dump,
+   setup_logshake_mocks, OS, sdcard */
 /* exported run_test */
 
 /* disable use strict warning */
@@ -12,56 +13,14 @@
 
 "use strict";
 
-const Cu = Components.utils;
-const Ci = Components.interfaces;
-const Cc = Components.classes;
-
-Cu.import("resource://gre/modules/XPCOMUtils.jsm");
-
-XPCOMUtils.defineLazyServiceGetter(this, "volumeService",
-                                   "@mozilla.org/telephony/volume-service;1",
-                                   "nsIVolumeService");
-
-let sdcard;
+Cu.import("resource://gre/modules/Promise.jsm");
 
 function run_test() {
   Cu.import("resource://gre/modules/LogShake.jsm");
-  Cu.import("resource://gre/modules/Promise.jsm");
-  Cu.import("resource://gre/modules/osfile.jsm");
-  do_get_profile();
-  debug("Starting");
   run_next_test();
 }
 
-function debug(msg) {
-  var timestamp = Date.now();
-  dump("LogShake: " + timestamp + ": " + msg + "\n");
-}
-
-add_test(function setup_fs() {
-  OS.File.makeDir("/data/local/tmp/sdcard/", {from: "/data"}).then(function() {
-    run_next_test();
-  });
-});
-
-add_test(function setup_sdcard() {
-  let volName = "sdcard";
-  let mountPoint = "/data/local/tmp/sdcard";
-  volumeService.createFakeVolume(volName, mountPoint);
-
-  let vol = volumeService.getVolumeByName(volName);
-  ok(vol, "volume shouldn't be null");
-  equal(volName, vol.name, "name");
-  equal(Ci.nsIVolume.STATE_MOUNTED, vol.state, "state");
-
-  run_next_test();
-});
-
-add_test(function test_ensure_sdcard() {
-  sdcard = volumeService.getVolumeByName("sdcard").mountPoint;
-  ok(sdcard, "Should have a valid sdcard mountpoint");
-  run_next_test();
-});
+add_test(setup_logshake_mocks);
 
 add_test(function test_logShake_captureLogs_writes() {
   // Enable LogShake

b2g/components/test/unit/test_logshake_gonk_compression.js

@@ -3,8 +3,9 @@
  * for Gonk-specific parts
  */
 
-/* jshint moz: true */
-/* global Components, LogCapture, LogShake, ok, add_test, run_next_test, dump */
+/* jshint moz: true, esnext: true */
+/* global Cc, Ci, Cu, LogCapture, LogShake, ok, add_test, run_next_test, dump,
+   setup_logshake_mocks, OS, sdcard, FileUtils */
 /* exported run_test */
 
 /* disable use strict warning */
@@ -12,57 +13,15 @@
 
 "use strict";
 
-const Cu = Components.utils;
-const Ci = Components.interfaces;
-const Cc = Components.classes;
-
-Cu.import("resource://gre/modules/XPCOMUtils.jsm");
-
-XPCOMUtils.defineLazyServiceGetter(this, "volumeService",
-                                   "@mozilla.org/telephony/volume-service;1",
-                                   "nsIVolumeService");
-
-let sdcard;
+Cu.import("resource://gre/modules/Promise.jsm");
+Cu.import("resource://gre/modules/FileUtils.jsm");
 
 function run_test() {
   Cu.import("resource://gre/modules/LogShake.jsm");
-  Cu.import("resource://gre/modules/Promise.jsm");
-  Cu.import("resource://gre/modules/osfile.jsm");
-  Cu.import("resource://gre/modules/FileUtils.jsm");
-  do_get_profile();
-  debug("Starting");
   run_next_test();
 }
 
-function debug(msg) {
-  var timestamp = Date.now();
-  dump("LogShake: " + timestamp + ": " + msg + "\n");
-}
-
-add_test(function setup_fs() {
-  OS.File.makeDir("/data/local/tmp/sdcard/", {from: "/data"}).then(function() {
-    run_next_test();
-  });
-});
-
-add_test(function setup_sdcard() {
-  let volName = "sdcard";
-  let mountPoint = "/data/local/tmp/sdcard";
-  volumeService.createFakeVolume(volName, mountPoint);
-
-  let vol = volumeService.getVolumeByName(volName);
-  ok(vol, "volume shouldn't be null");
-  equal(volName, vol.name, "name");
-  equal(Ci.nsIVolume.STATE_MOUNTED, vol.state, "state");
-
-  run_next_test();
-});
-
-add_test(function test_ensure_sdcard() {
-  sdcard = volumeService.getVolumeByName("sdcard").mountPoint;
-  ok(sdcard, "Should have a valid sdcard mountpoint");
-  run_next_test();
-});
+add_test(setup_logshake_mocks);
 
 add_test(function test_logShake_captureLogs_writes_zip() {
   // Enable LogShake

b2g/components/test/unit/test_logshake_readLog_gonk.js

@@ -0,0 +1,65 @@
+/**
+ * Test the log capturing capabilities of LogShake.jsm under conditions that
+ * could cause races
+ */
+
+/* jshint moz: true, esnext: true */
+/* global Cu, LogCapture, LogShake, ok, add_test, run_next_test, dump,
+   XPCOMUtils, do_get_profile, OS, volumeService, Promise, equal,
+   setup_logshake_mocks */
+/* exported run_test */
+
+/* disable use strict warning */
+/* jshint -W097 */
+
+"use strict";
+
+function run_test() {
+  Cu.import("resource://gre/modules/LogShake.jsm");
+  run_next_test();
+}
+
+add_test(setup_logshake_mocks);
+
+add_test(function test_logShake_captureLogs_waits_to_read() {
+  // Enable LogShake
+  LogShake.init();
+
+  // Save no logs synchronously (except properties)
+  LogShake.LOGS_WITH_PARSERS = {};
+
+  LogShake.captureLogs().then(logResults => {
+    LogShake.uninit();
+
+    ok(logResults.logFilenames.length > 0, "Should have filenames");
+    ok(logResults.logPaths.length > 0, "Should have paths");
+    ok(!logResults.compressed, "Should not be compressed");
+
+    // This assumes that the about:memory reading will only fail under abnormal
+    // circumstances. It does not check for screenshot.png because
+    // systemAppFrame is unavailable during xpcshell tests.
+    let hasAboutMemory = false;
+
+    logResults.logFilenames.forEach(filename => {
+      // Because the about:memory log's filename has the PID in it we can not
+      // use simple equality but instead search for the "about_memory" part of
+      // the filename which will look like logshake-about_memory-{PID}.json.gz
+      if (filename.indexOf("about_memory") < 0) {
+        return;
+      }
+      hasAboutMemory = true;
+    });
+
+    ok(hasAboutMemory,
+       "LogShake's asynchronous read of about:memory should have succeeded.");
+
+    run_next_test();
+  },
+  error => {
+    LogShake.uninit();
+
+    ok(false, "Should not have received error: " + error);
+
+    run_next_test();
+  });
+});

b2g/components/test/unit/xpcshell.ini

@@ -26,10 +26,17 @@ skip-if = toolkit != "gonk"
 [test_logshake.js]
 
 [test_logshake_gonk.js]
+head = head_logshake_gonk.js
 # only run on b2g builds due to requiring b2g-specific log files to exist
 skip-if = (toolkit != "gonk")
 
 [test_logshake_gonk_compression.js]
+head = head_logshake_gonk.js
+# only run on b2g builds due to requiring b2g-specific log files to exist
+skip-if = (toolkit != "gonk")
+
+[test_logshake_readLog_gonk.js]
+head = head_logshake_gonk.js
 # only run on b2g builds due to requiring b2g-specific log files to exist
 skip-if = (toolkit != "gonk")