Bug 981851 - Add a simple JS logging mechanism to telemetry for recording unusual event data, r=taras

toolkit/components/telemetry/Telemetry.cpp

@@ -2558,6 +2558,18 @@ TelemetryImpl::GetFileIOReports(JSContext *cx, JS::MutableHandleValue ret)
   return NS_OK;
 }
 
+NS_IMETHODIMP
+TelemetryImpl::MsSinceProcessStart(double* aResult)
+{
+  bool error;
+  *aResult = (TimeStamp::NowLoRes() -
+              TimeStamp::ProcessCreation(error)).ToMilliseconds();
+  if (error) {
+    return NS_ERROR_NOT_AVAILABLE;
+  }
+  return NS_OK;
+}
+
 size_t
 TelemetryImpl::SizeOfIncludingThis(mozilla::MallocSizeOf aMallocSizeOf)
 {

toolkit/components/telemetry/TelemetryLog.jsm

@@ -0,0 +1,35 @@
+/* This Source Code Form is subject to the terms of the Mozilla Public
+ * License, v. 2.0. If a copy of the MPL was not distributed with this
+ * file, You can obtain one at http://mozilla.org/MPL/2.0/. */
+
+this.EXPORTED_SYMBOLS = ["TelemetryLog"];
+
+const Cc = Components.classes;
+const Ci = Components.interfaces;
+
+const Telemetry = Cc["@mozilla.org/base/telemetry;1"].getService(Ci.nsITelemetry);
+var gLogEntries = [];
+
+this.TelemetryLog = Object.freeze({
+  log: function(id, data) {
+    id = String(id);
+    var ts;
+    try {
+      ts = Math.floor(Telemetry.msSinceProcessStart());
+    } catch(e) {
+      // If timestamp is screwed up, we just give up instead of making up
+      // data.
+      return;
+    }
+
+    var entry = [id, ts];
+    if (data !== undefined) {
+      entry = entry.concat(Array.prototype.map.call(data, String));
+    }
+    gLogEntries.push(entry);
+  },
+
+  entries: function() {
+    return gLogEntries;
+  }
+});

toolkit/components/telemetry/TelemetryPing.jsm

@@ -73,6 +73,8 @@ XPCOMUtils.defineLazyModuleGetter(this, "TelemetryFile",
                                   "resource://gre/modules/TelemetryFile.jsm");
 XPCOMUtils.defineLazyModuleGetter(this, "UITelemetry",
                                   "resource://gre/modules/UITelemetry.jsm");
+XPCOMUtils.defineLazyModuleGetter(this, "TelemetryLog",
+                                  "resource://gre/modules/TelemetryLog.jsm");
 
 function generateUUID() {
   let str = Cc["@mozilla.org/uuid-generator;1"].getService(Ci.nsIUUIDGenerator).generateUUID().toString();
@@ -688,6 +690,7 @@ let Impl = {
       addonHistograms: this.getAddonHistograms(),
       addonDetails: AddonManagerPrivate.getTelemetryDetails(),
       UIMeasurements: UITelemetry.getUIMeasurements(),
+      log: TelemetryLog.entries(),
       info: info
     };
 

toolkit/components/telemetry/moz.build

@@ -29,6 +29,7 @@ EXTRA_COMPONENTS += [
 
 EXTRA_JS_MODULES += [
     'TelemetryFile.jsm',
+    'TelemetryLog.jsm',
     'TelemetryStopwatch.jsm',
     'ThirdPartyCookieProbe.jsm',
 ]

toolkit/components/telemetry/nsITelemetry.idl

@@ -12,7 +12,7 @@ interface nsIFetchTelemetryDataCallback : nsISupports
   void complete();
 };
 
-[scriptable, uuid(6c31f68d-4a54-4dca-b6c8-ddb264d5a154)]
+[scriptable, uuid(4e4bfc35-dac6-4b28-ade4-7e45760051d5)]
 interface nsITelemetry : nsISupports
 {
   /**
@@ -249,4 +249,11 @@ interface nsITelemetry : nsISupports
    */
   [implicit_jscontext]
   readonly attribute jsval fileIOReports;
+
+  /**
+   * Return the number of seconds since process start using monotonic
+   * timestamps (unaffected by system clock changes).
+   * @throws NS_ERROR_NOT_AVAILABLE if TimeStamp doesn't have the data.
+   */
+  double msSinceProcessStart();
 };

toolkit/components/telemetry/tests/unit/test_TelemetryLog.js

@@ -0,0 +1,38 @@
+const Cc = Components.classes;
+const Ci = Components.interfaces;
+const Cu = Components.utils;
+
+Cu.import("resource://gre/modules/TelemetryLog.jsm", this);
+Cu.import("resource://gre/modules/TelemetryPing.jsm", this);
+
+function check_event(event, id, data)
+{
+  do_print("Checking message " + id);
+  do_check_eq(event[0], id);
+  do_check_true(event[1] > 0);
+
+  if (data === undefined) {
+    do_check_true(event.length == 2);
+  } else {
+    do_check_eq(event.length, data.length + 2);
+    for (var i = 0; i < data.length; ++i) {
+      do_check_eq(typeof(event[i + 2]), "string");
+      do_check_eq(event[i + 2], data[i]);
+    }
+  }
+}
+
+function run_test()
+{
+  TelemetryLog.log("test1", ["val", 123, undefined]);
+  TelemetryLog.log("test2", []);
+  TelemetryLog.log("test3");
+
+  var log = TelemetryPing.getPayload().log;
+  do_check_eq(log.length, 3);
+  check_event(log[0], "test1", ["val", "123", "undefined"]);
+  check_event(log[1], "test2", []);
+  check_event(log[2], "test3", undefined);
+  do_check_true(log[0][1] <= log[1][1]);
+  do_check_true(log[1][1] <= log[2][1]);
+}

toolkit/components/telemetry/tests/unit/xpcshell.ini

@@ -5,6 +5,7 @@ tail =
 [test_nsITelemetry.js]
 [test_TelemetryLateWrites.js]
 [test_TelemetryLockCount.js]
+[test_TelemetryLog.js]
 [test_TelemetryPing.js]
 # Bug 676989: test fails consistently on Android
 # fail-if = os == "android"