Bug 603009: Catch and report all exceptions thrown during test pilot study execution. r=dtownsend

Bug 646122: Holding on to Exception objects causes crash in garbage collector. r=dtownsend
Bug 645092: Stop using [deprecated] Storage methods (testpilot). r=mfinkle
DONTBUILD as it is NPOTB on m-c

browser/app/profile/extensions/testpilot@labs.mozilla.com/content/debug.html

@@ -20,7 +20,20 @@
 
   function reloadAllExperiments() {
     Components.utils.import("resource://testpilot/modules/setup.js");
-    TestPilotSetup.reloadRemoteExperiments();
+    TestPilotSetup.reloadRemoteExperiments(function(success) {
+      let errors = TestPilotSetup._remoteExperimentLoader.getLoadErrors();
+      let str;
+      if (errors.length > 0) {
+        str = "<ul>";
+        for each (let errStr in errors) {
+          str += "<li>" + errStr + "</li>";          
+        }
+        str += "</ul>";
+      } else {
+        str = "All experiments reloaded, no errors.";
+      }
+      document.getElementById("debug").innerHTML = str;
+    });
   }
 
   function runUnitTests() {
@@ -81,8 +94,7 @@
     var path = codeStore.resolveModule(null, filename);
     var textArea = document.getElementById("experiment-code-area");
     codeStore.setLocalOverride(path, textArea.value);
-    reloadAllExperiments(function(success) {
-      document.getElementById("debug").innerHTML = "Success? " + success;});
+    reloadAllExperiments();
   }
 
   function showMetaData() {

browser/app/profile/extensions/testpilot@labs.mozilla.com/modules/experiment_data_store.js

@@ -54,6 +54,8 @@ const TYPE_INT_32 = 0;
 const TYPE_DOUBLE = 1;
 const TYPE_STRING = 2;
 
+const EXCEPTION_TABLE_NAME = "exceptions";
+
 function ExperimentDataStore(fileName, tableName, columns) {
   this._init(fileName, tableName, columns);
 }
@@ -87,9 +89,17 @@ ExperimentDataStore.prototype = {
                   + schemaClauses.join(", ") + ");";
     // CreateTable creates the table only if it does not already exist:
     try {
-      this._connection = DbUtils.createTable(this._connection,
-                                             this._tableName,
-                                             schema);
+      DbUtils.createTable(this._connection, this._tableName, schema);
+    } catch(e) {
+      logger.warn("Error in createTable: " + e + "\n");
+    }
+
+    // Create a second table for storing exceptions for this study.  It has a fixed
+    // name and schema:
+    let exceptionTableSchema = "CREATE TABLE " + EXCEPTION_TABLE_NAME +
+      " (time INTEGER, trace TEXT);";
+    try {
+      DbUtils.createTable(this._connection, "exceptions", exceptionTableSchema);
     } catch(e) {
       logger.warn("Error in createTable: " + e + "\n");
     }
@@ -150,8 +160,21 @@ ExperimentDataStore.prototype = {
     insStmt.finalize();
   },
 
+  logException: function EDS_logException(exception) {
+    let insertSql = "INSERT INTO " + EXCEPTION_TABLE_NAME + " VALUES (?1, ?2);";
+    let insStmt =  this._createStatement(insertSql);
+    // Even though the SQL says ?1 and ?2, the param indices count from 0.
+    insStmt.params[0] = Date.now();
+    let txt = exception.message ? exception.message : exception.toString();
+    insStmt.params[1] = txt;
+    insStmt.executeAsync();
+    insStmt.finalize(); // TODO Is this the right thing to do when calling asynchronously?
+  },
+
   getJSONRows: function EDS_getJSONRows(callback) {
-        let selectSql = "SELECT * FROM " + this._tableName;
+    // TODO why do both this function and getAllDataAsJSON exist when they both do
+    // the same thing?
+    let selectSql = "SELECT * FROM " + this._tableName;
     let selStmt = this._createStatement(selectSql);
     let records = [];
     let self = this;
@@ -255,33 +278,61 @@ ExperimentDataStore.prototype = {
     selStmt.finalize();
   },
 
-  wipeAllData: function EDS_wipeAllData(callback) {
-    let logger = Log4Moz.repository.getLogger("TestPilot.Database");
-    logger.trace("ExperimentDataStore.wipeAllData called.\n");
-    let wipeSql = "DELETE FROM " + this._tableName;
-    let wipeStmt = this._createStatement(wipeSql);
-    wipeStmt.executeAsync({
+  getExceptionsAsJson: function(callback) {
+    let selectSql = "SELECT * FROM " + EXCEPTION_TABLE_NAME;
+    let selStmt = this._createStatement(selectSql);
+    let records = [];
+    let self = this;
+
+    selStmt.executeAsync({
       handleResult: function(aResultSet) {
-      },
-      handleError: function(aError) {
-        if (callback) {
-          callback(false);
+        for (let row = aResultSet.getNextRow(); row;
+             row = aResultSet.getNextRow()) {
+          records.push({ time: row.getDouble(0),
+                         exception: row.getString(1)});
         }
       },
+      handleError: function(aError) {
+        callback(records);
+      },
+      handleCompletion: function(aReason) {
+        callback(records);
+      }
+    });
+  },
+
+  wipeAllData: function EDS_wipeAllData(callback) {
+    // Wipe both the data table and the exception table; call callback when both
+    // are wiped.
+    let logger = Log4Moz.repository.getLogger("TestPilot.Database");
+    logger.trace("ExperimentDataStore.wipeAllData called.\n");
+    let wipeDataStmt = this._createStatement("DELETE FROM " + this._tableName);
+    let wipeExcpStmt = this._createStatement("DELETE FROM " + EXCEPTION_TABLE_NAME);
+
+    let numberWiped = 0;
+    let onComplete = function() {
+      numberWiped ++;
+      if (numberWiped == 2 && callback) {
+        callback();
+      }
+    };
+    wipeDataStmt.executeAsync({
+      handleResult: function(aResultSet) {},
+      handleError: function(aError) { onComplete(); },
       handleCompletion: function(aReason) {
         if (aReason == Ci.mozIStorageStatementCallback.REASON_FINISHED) {
           logger.trace("ExperimentDataStore.wipeAllData complete.\n");
-          if (callback) {
-            callback(true);
-          }
-        } else {
-          if (callback) {
-            callback(false);
-          }
         }
+        onComplete();
       }
     });
-    wipeStmt.finalize();
+    wipeExcpStmt.executeAsync({
+      handleResult: function(aResultSet) {},
+      handleError: function(aError) {  onComplete(); },
+      handleCompletion: function(aReason) { onComplete(); }
+    });
+    wipeDataStmt.finalize();
+    wipeExcpStmt.finalize();
   },
 
   nukeTable: function EDS_nukeTable() {

browser/app/profile/extensions/testpilot@labs.mozilla.com/modules/remote-experiment-loader.js

@@ -219,6 +219,7 @@ exports.RemoteExperimentLoader.prototype = {
     this._studyResults = [];
     this._legacyStudies = [];
     this._experimentFileNames = [];
+    this._loadErrors = [];
   },
 
   getLocalizedStudyInfo: function(studiesIndex) {
@@ -504,12 +505,20 @@ exports.RemoteExperimentLoader.prototype = {
      * the module name and value = the module object. */
     this._logger.trace("GetExperiments called.");
     let remoteExperiments = {};
+    this._loadErrors = [];
     for each (filename in this._experimentFileNames) {
       this._logger.debug("GetExperiments is loading " + filename);
       try {
         remoteExperiments[filename] = this._loader.require(filename);
         this._logger.info("Loaded " + filename + " OK.");
       } catch(e) {
+      /* Turn the load-time errors into strings and store them, so we can display
+       * them on a debug page or include them with a data upload!  (Don't store
+       * exception objects directly as that causes garbage collector problems-
+       * aka bug 646122) */
+      let errStr = e.name + " on line " + e.lineNumber + " of file " +
+        e.fileName + ": " + e.message;
+        this._loadErrors.push(errStr);
         this._logger.warn("Error loading " + filename);
         this._logger.warn(e);
       }
@@ -523,6 +532,10 @@ exports.RemoteExperimentLoader.prototype = {
 
   getLegacyStudies: function() {
     return this._legacyStudies;
+  },
+
+  getLoadErrors: function() {
+    return this._loadErrors;
   }
 };
 

browser/app/profile/extensions/testpilot@labs.mozilla.com/modules/tasks.js

@@ -487,29 +487,44 @@ TestPilotExperiment.prototype = {
   onNewWindow: function TestPilotExperiment_onNewWindow(window) {
     this._logger.trace("Experiment.onNewWindow called.");
     if (this.experimentIsRunning()) {
-      this._handlers.onNewWindow(window);
+      try {
+        this._handlers.onNewWindow(window);
+      } catch(e) {
+        this._dataStore.logException("onNewWindow: " + e);
+      }
     }
   },
 
   onWindowClosed: function TestPilotExperiment_onWindowClosed(window) {
     this._logger.trace("Experiment.onWindowClosed called.");
     if (this.experimentIsRunning()) {
-      this._handlers.onWindowClosed(window);
+      try {
+        this._handlers.onWindowClosed(window);
+      } catch(e) {
+        this._dataStore.logException("onWindowClosed: " + e);
+      }
     }
   },
 
   onAppStartup: function TestPilotExperiment_onAppStartup() {
     this._logger.trace("Experiment.onAppStartup called.");
     if (this.experimentIsRunning()) {
-      this._handlers.onAppStartup();
+      try {
+        this._handlers.onAppStartup();
+      } catch(e) {
+        this._dataStore.logException("onAppStartup: " + e);
+      }
     }
   },
 
   onAppShutdown: function TestPilotExperiment_onAppShutdown() {
     this._logger.trace("Experiment.onAppShutdown called.");
-    // TODO the caller for this is not yet implemented
     if (this.experimentIsRunning()) {
-      this._handlers.onAppShutdown();
+      try {
+        this._handlers.onAppShutdown();
+      } catch(e) {
+        this._dataStore.logException("onAppShutdown: " + e);
+      }
     }
   },
 
@@ -518,7 +533,11 @@ TestPilotExperiment.prototype = {
     // Make sure not to call this if it's already been called:
     if (this.experimentIsRunning() && !this._startedUpHandlers) {
       this._logger.trace("  ... starting up handlers!");
-      this._handlers.onExperimentStartup(this._dataStore);
+      try {
+        this._handlers.onExperimentStartup(this._dataStore);
+      } catch(e) {
+        this._dataStore.logException("onExperimentStartup: " + e);
+      }
       this._startedUpHandlers = true;
     }
   },
@@ -526,7 +545,11 @@ TestPilotExperiment.prototype = {
   onExperimentShutdown: function TestPilotExperiment_onShutdown() {
     this._logger.trace("Experiment.onExperimentShutdown called.");
     if (this.experimentIsRunning() && this._startedUpHandlers) {
-      this._handlers.onExperimentShutdown();
+      try {
+        this._handlers.onExperimentShutdown();
+      } catch(e) {
+        this._dataStore.logException("onExperimentShutdown: " + e);
+      }
       this._startedUpHandlers = false;
     }
   },
@@ -534,21 +557,33 @@ TestPilotExperiment.prototype = {
   doExperimentCleanup: function TestPilotExperiment_doExperimentCleanup() {
     if (this._handlers.doExperimentCleanup) {
       this._logger.trace("Doing experiment cleanup.");
-      this._handlers.doExperimentCleanup();
+      try {
+        this._handlers.doExperimentCleanup();
+      } catch(e) {
+        this._dataStore.logException("doExperimentCleanup: " + e);
+      }
     }
   },
 
   onEnterPrivateBrowsing: function TestPilotExperiment_onEnterPrivate() {
     this._logger.trace("Task is entering private browsing.");
     if (this.experimentIsRunning()) {
-      this._handlers.onEnterPrivateBrowsing();
+      try {
+        this._handlers.onEnterPrivateBrowsing();
+      } catch(e) {
+        this._dataStore.logException("onEnterPrivateBrowsing: " + e);
+      }
     }
   },
 
   onExitPrivateBrowsing: function TestPilotExperiment_onExitPrivate() {
     this._logger.trace("Task is exiting private browsing.");
     if (this.experimentIsRunning()) {
-      this._handlers.onExitPrivateBrowsing();
+      try {
+        this._handlers.onExitPrivateBrowsing();
+      } catch(e) {
+        this._dataStore.logException("onExitPrivateBrowsing: " + e);
+      }
     }
   },
 
@@ -778,9 +813,12 @@ TestPilotExperiment.prototype = {
         }
       }
       self._dataStore.getJSONRows(function(rows) {
-                                    json.events = rows;
-                                    callback( JSON.stringify(json) );
-                                  });
+        json.events = rows;
+        self._dataStore.getExceptionsAsJson(function(errs) {
+          json.exceptions = errs;
+          callback( JSON.stringify(json) );
+        });
+      });
     });
   },