Bug 1188999 - LogShake does not fetch about:memory reports. r=gerard-majax
authorJames Hobin <hobinjk>
Tue, 04 Aug 2015 13:47:00 +0200
changeset 288213 216e31f8f1d280dcbb43b22d63bcff7bbbcda2df
parent 288212 8ea5c69ae101d01a32717cd543b7a78596261c17
child 288214 d13b95d2aa59a29878cdf21dde99738d041f34ad
push id5067
push userraliiev@mozilla.com
push dateMon, 21 Sep 2015 14:04:52 +0000
treeherdermozilla-beta@14221ffe5b2f [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersgerard-majax
bugs1188999
milestone42.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 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
b2g/components/LogParser.jsm
b2g/components/LogShake.jsm
b2g/components/test/unit/head_logshake_gonk.js
b2g/components/test/unit/test_logshake_gonk.js
b2g/components/test/unit/test_logshake_gonk_compression.js
b2g/components/test/unit/test_logshake_readLog_gonk.js
b2g/components/test/unit/xpcshell.ini
--- a/b2g/components/LogCapture.jsm
+++ b/b2g/components/LogCapture.jsm
@@ -189,25 +189,34 @@ let LogCapture = {
     return deferred.promise;
   },
 
   /**
    * Dumping screenshot, returning a Promise. Will be resolved with the content
    * 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;
   }
 };
 
 this.LogCapture = LogCapture;
--- a/b2g/components/LogParser.jsm
+++ b/b2g/components/LogParser.jsm
@@ -11,20 +11,24 @@ this.EXPORTED_SYMBOLS = ["LogParser"];
  *
  * @param array {Uint8Array} Array read from /dev/log/ file
  * @return {Array} List of log messages
  */
 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
     let offset = 0;
 
     // Length of the entry, discarded
     let length = data.getUint32(pos + offset, true);
     offset += 4;
--- a/b2g/components/LogShake.jsm
+++ b/b2g/components/LogShake.jsm
@@ -272,61 +272,72 @@ let LogShake = {
     }
   },
 
   /**
    * Captures and saves the current device logs, returning a promise that will
    * 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"] =
         LogParser.prettyPrintPropertiesArray(LogCapture.readProperties());
     } catch (ex) {
       Cu.reportError("Unable to get device properties: " + ex);
     }
 
     // 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);
         } catch (ex) {
           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;
       try {
         logArray = LogCapture.readLogFile(loc);
         if (!logArray) {
           debug("LogCapture.readLogFile() returned nothing for: " + loc);
           continue;
@@ -338,17 +349,22 @@ let LogShake = {
 
       try {
         logArrays[loc] = this.LOGS_WITH_PARSERS[loc](logArray);
       } catch (ex) {
         Cu.reportError("Unable to parse content of '" + loc + "': " + ex);
         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;
+    });
   },
 
   /**
    * Save the formatted arrays of log files to an sdcard if available
    */
   saveLogs: function(logArrays) {
     if (!logArrays || Object.keys(logArrays).length === 0) {
       return Promise.reject("Zero logs saved");
new file mode 100644
--- /dev/null
+++ b/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();
+}
--- a/b2g/components/test/unit/test_logshake_gonk.js
+++ b/b2g/components/test/unit/test_logshake_gonk.js
@@ -1,72 +1,31 @@
 /**
  * Test the log capturing capabilities of LogShake.jsm, checking
  * 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 */
 /* jshint -W097 */
 
 "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
   LogShake.init();
 
   let expectedFiles = [];
 
   LogShake.captureLogs().then(logResults => {
--- a/b2g/components/test/unit/test_logshake_gonk_compression.js
+++ b/b2g/components/test/unit/test_logshake_gonk_compression.js
@@ -1,73 +1,32 @@
 /**
  * Test the log capturing capabilities of LogShake.jsm, checking
  * 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 */
 /* jshint -W097 */
 
 "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
   LogShake.init();
 
   let expectedFiles = [];
 
   LogShake.enableQAMode();
new file mode 100644
--- /dev/null
+++ b/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();
+  });
+});
--- a/b2g/components/test/unit/xpcshell.ini
+++ b/b2g/components/test/unit/xpcshell.ini
@@ -21,16 +21,23 @@ tail =
 # only run on b2g builds due to requiring b2g-specific log files to exist
 skip-if = toolkit != "gonk"
 
 [test_logparser.js]
 
 [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")
 
 [test_aboutserviceworkers.js]