Bug 1122049 - Add logging to Telemetry. r=gfritzsche

toolkit/components/telemetry/TelemetryPing.jsm

@@ -10,6 +10,7 @@ const Ci = Components.interfaces;
 const Cr = Components.results;
 const Cu = Components.utils;
 
+Cu.import("resource://gre/modules/Log.jsm");
 Cu.import("resource://gre/modules/debug.js", this);
 Cu.import("resource://gre/modules/Services.jsm", this);
 Cu.import("resource://gre/modules/XPCOMUtils.jsm", this);
@@ -17,9 +18,15 @@ Cu.import("resource://gre/modules/Promise.jsm", this);
 Cu.import("resource://gre/modules/DeferredTask.jsm", this);
 Cu.import("resource://gre/modules/Preferences.jsm");
 
+const LOGGER_NAME = "Toolkit.Telemetry";
+const LOGGER_PREFIX = "TelemetryPing::";
+
 const PREF_BRANCH = "toolkit.telemetry.";
+const PREF_BRANCH_LOG = PREF_BRANCH + "log.";
 const PREF_SERVER = PREF_BRANCH + "server";
 const PREF_ENABLED = PREF_BRANCH + "enabled";
+const PREF_LOG_LEVEL = PREF_BRANCH_LOG + "level";
+const PREF_LOG_DUMP = PREF_BRANCH_LOG + "dump";
 const PREF_CACHED_CLIENTID = PREF_BRANCH + "cachedClientID"
 const PREF_FHR_UPLOAD_ENABLED = "datareporting.healthreport.uploadEnabled";
 
@@ -40,6 +47,39 @@ XPCOMUtils.defineLazyModuleGetter(this, "TelemetryLog",
 XPCOMUtils.defineLazyModuleGetter(this, "ThirdPartyCookieProbe",
                                   "resource://gre/modules/ThirdPartyCookieProbe.jsm");
 
+/**
+ * Setup Telemetry logging. This function also gets called when loggin related
+ * preferences change.
+ */
+let gLogger = null;
+let gLogAppenderDump = null;
+function configureLogging() {
+  if (!gLogger) {
+    gLogger = Log.repository.getLogger(LOGGER_NAME);
+
+    // Log messages need to go to the browser console.
+    let consoleAppender = new Log.ConsoleAppender(new Log.BasicFormatter());
+    gLogger.addAppender(consoleAppender);
+
+    Preferences.observe(PREF_BRANCH_LOG, configureLogging);
+  }
+
+  // Make sure the logger keeps up with the logging level preference.
+  gLogger.level = Log.Level[Preferences.get(PREF_LOG_LEVEL, "Warn")];
+
+  // If enabled in the preferences, add a dump appender.
+  let logDumping = Preferences.get(PREF_LOG_DUMP, false);
+  if (logDumping != !!gLogAppenderDump) {
+    if (logDumping) {
+      gLogAppenderDump = new Log.DumpAppender(new Log.BasicFormatter());
+      gLogger.addAppender(gLogAppenderDump);
+    } else {
+      gLogger.removeAppender(gLogAppenderDump);
+      gLogAppenderDump = null;
+    }
+  }
+}
+
 function generateUUID() {
   let str = Cc["@mozilla.org/uuid-generator;1"].getService(Ci.nsIUUIDGenerator).generateUUID().toString();
   // strip {}
@@ -51,8 +91,16 @@ this.EXPORTED_SYMBOLS = ["TelemetryPing"];
 this.TelemetryPing = Object.freeze({
   Constants: Object.freeze({
     PREF_ENABLED: PREF_ENABLED,
+    PREF_LOG_LEVEL: PREF_LOG_LEVEL,
+    PREF_LOG_DUMP: PREF_LOG_DUMP,
     PREF_SERVER: PREF_SERVER,
   }),
+  /**
+   * Used only for testing purposes.
+   */
+  initLogging: function() {
+    configureLogging();
+  },
   /**
    * Used only for testing purposes.
    */
@@ -100,6 +148,7 @@ this.TelemetryPing = Object.freeze({
 
 let Impl = {
   _initialized: false,
+  _log: null,
   _prevValues: {},
   // The previous build ID, if this is the first run with a new build.
   // Undefined if this is not the first run, or the previous build ID is unknown.
@@ -132,6 +181,7 @@ let Impl = {
    * Send data to the server. Record success/send-time in histograms
    */
   send: function send(reason, aPayload) {
+    this._log.trace("send - Reason " + reason + ", Server " + this._server);
     return this.sendPingsFromIterator(this._server, reason,
                                       Iterator(this.popPayloads(reason, aPayload)));
   },
@@ -172,6 +222,7 @@ let Impl = {
   },
 
   doPing: function doPing(server, ping) {
+    this._log.trace("doPing - Server " + server);
     let deferred = Promise.defer();
     let url = server + this.submissionPath(ping);
     let request = Cc["@mozilla.org/xmlextras/xmlhttprequest;1"]
@@ -245,6 +296,7 @@ let Impl = {
       // Only do this for official builds so that e.g. developer builds
       // still enable Telemetry based on prefs.
       Telemetry.canRecord = false;
+      this._log.config("enableTelemetryRecording - Can't send data, disabling Telemetry recording.");
       return false;
     }
 #endif
@@ -255,6 +307,7 @@ let Impl = {
       // Turn off local telemetry if telemetry is disabled.
       // This may change once about:telemetry is added.
       Telemetry.canRecord = false;
+      this._log.config("enableTelemetryRecording - Telemetry is disabled, turning off Telemetry recording.");
       return false;
     }
 
@@ -265,11 +318,18 @@ let Impl = {
    * Initializes telemetry within a timer. If there is no PREF_SERVER set, don't turn on telemetry.
    */
   setupTelemetry: function setupTelemetry(testing) {
+    if (testing && !this._log) {
+      this._log = Log.repository.getLoggerWithMessagePrefix(LOGGER_NAME, LOGGER_PREFIX);
+    }
+
+    this._log.trace("setupTelemetry");
+
     // Initialize some probes that are kept in their own modules
     this._thirdPartyCookies = new ThirdPartyCookieProbe();
     this._thirdPartyCookies.init();
 
     if (!this.enableTelemetryRecording(testing)) {
+      this._log.config("setupTelemetry - Telemetry recording is disabled, skipping Telemetry setup.");
       return Promise.resolve();
     }
 
@@ -290,6 +350,8 @@ let Impl = {
       // If we have any TelemetryPings lying around, we'll be aggressive
       // and try to send them all off ASAP.
       if (TelemetryFile.pingsOverdue > 0) {
+        this._log.trace("setupChromeProcess - Sending " + TelemetryFile.pingsOverdue +
+                        " overdue pings now.");
         // It doesn't really matter what we pass to this.send as a reason,
         // since it's never sent to the server. All that this.send does with
         // the reason is check to make sure it's not a test-ping.
@@ -321,10 +383,29 @@ let Impl = {
    * This observer drives telemetry.
    */
   observe: function (aSubject, aTopic, aData) {
+    // The logger might still be not available at this point.
+    if (!this._log) {
+      // If we don't have a logger, we need to make sure |Log.repository.getLogger()| is
+      // called before |getLoggerWithMessagePrefix|. Otherwise logging won't work.
+      configureLogging();
+      this._log = Log.repository.getLoggerWithMessagePrefix(LOGGER_NAME, LOGGER_PREFIX);
+    }
+
+    this._log.trace("observe - " + aTopic + " notified.");
+
     switch (aTopic) {
     case "profile-after-change":
       // profile-after-change is only registered for chrome processes.
       return this.setupTelemetry();
+    case "app-startup":
+      // app-startup is only registered for content processes.
+      Services.obs.addObserver(this, "content-child-shutdown");
+      break;
+    case "content-child-shutdown":
+      // content-child-shutdown is only registered for content processes.
+      Services.obs.removeObserver(this, "content-child-shutdown");
+      Preferences.ignore(PREF_BRANCH_LOG, configureLogging);
+      break;
     }
   },
 

toolkit/components/telemetry/TelemetrySession.jsm

@@ -11,6 +11,7 @@ const Cr = Components.results;
 const Cu = Components.utils;
 
 Cu.import("resource://gre/modules/debug.js", this);
+Cu.import("resource://gre/modules/Log.jsm");
 Cu.import("resource://gre/modules/Services.jsm", this);
 Cu.import("resource://gre/modules/XPCOMUtils.jsm", this);
 Cu.import("resource://gre/modules/Promise.jsm", this);
@@ -31,6 +32,9 @@ const PAYLOAD_VERSION = 1;
 // submitted ping data with its histogram definition (bug 832007)
 #expand const HISTOGRAMS_FILE_VERSION = "__HISTOGRAMS_FILE_VERSION__";
 
+const LOGGER_NAME = "Toolkit.Telemetry";
+const LOGGER_PREFIX = "TelemetrySession::";
+
 const PREF_BRANCH = "toolkit.telemetry.";
 const PREF_SERVER = PREF_BRANCH + "server";
 const PREF_ENABLED = PREF_BRANCH + "enabled";
@@ -261,6 +265,7 @@ this.TelemetrySession = Object.freeze({
 let Impl = {
   _histograms: {},
   _initialized: false,
+  _log: null,
   _prevValues: {},
   // Generate a unique id once per session so the server can cope with
   // duplicate submissions.
@@ -289,6 +294,8 @@ let Impl = {
    * @return simple measurements as a dictionary.
    */
   getSimpleMeasurements: function getSimpleMeasurements(forSavedSession) {
+    this._log.trace("getSimpleMeasurements");
+
     let si = Services.startup.getStartupInfo();
 
     // Measurements common to chrome and content processes.
@@ -451,6 +458,8 @@ let Impl = {
   },
 
   getHistograms: function getHistograms(hls) {
+    this._log.trace("getHistograms");
+
     let registered = Telemetry.registeredHistograms([]);
     let ret = {};
 
@@ -466,6 +475,8 @@ let Impl = {
   },
 
   getAddonHistograms: function getAddonHistograms() {
+    this._log.trace("getAddonHistograms");
+
     let ahs = Telemetry.addonHistogramSnapshots;
     let ret = {};
 
@@ -483,6 +494,8 @@ let Impl = {
   },
 
   getKeyedHistograms: function() {
+    this._log.trace("getKeyedHistograms");
+
     let registered = Telemetry.registeredKeyedHistograms([]);
     let ret = {};
 
@@ -499,6 +512,8 @@ let Impl = {
   },
 
   getThreadHangStats: function getThreadHangStats(stats) {
+    this._log.trace("getThreadHangStats");
+
     stats.forEach((thread) => {
       thread.activity = this.packHistogram(thread.activity);
       thread.hangs.forEach((hang) => {
@@ -517,6 +532,8 @@ let Impl = {
    * @return The metadata as a JS object
    */
   getMetadata: function getMetadata(reason) {
+    this._log.trace("getMetadata - Reason " + reason);
+
     let ai = Services.appinfo;
     let ret = {
       reason: reason,
@@ -628,6 +645,8 @@ let Impl = {
    * Pull values from about:memory into corresponding histograms
    */
   gatherMemory: function gatherMemory() {
+    this._log.trace("gatherMemory");
+
     let mgr;
     try {
       mgr = Cc["@mozilla.org/memory-reporter-manager;1"].
@@ -750,6 +769,8 @@ let Impl = {
    * Make a copy of interesting histograms at startup.
    */
   gatherStartupHistograms: function gatherStartupHistograms() {
+    this._log.trace("gatherStartupHistograms");
+
     let info = Telemetry.registeredHistograms([]);
     let snapshots = Telemetry.histogramSnapshots;
     for (let name of info) {
@@ -767,6 +788,8 @@ let Impl = {
    * respectively.
    */
   assemblePayloadWithMeasurements: function assemblePayloadWithMeasurements(simpleMeasurements, info) {
+    this._log.trace("assemblePayloadWithMeasurements");
+
     // Payload common to chrome and content processes.
     let payloadObj = {
       ver: PAYLOAD_VERSION,
@@ -809,6 +832,7 @@ let Impl = {
   },
 
   getSessionPayload: function getSessionPayload(reason) {
+    this._log.trace("getSessionPayload - Reason " + reason);
     let measurements = this.getSimpleMeasurements(reason == "saved-session");
     let info = !IS_CONTENT_PROCESS ? this.getMetadata(reason) : null;
     return this.assemblePayloadWithMeasurements(measurements, info);
@@ -820,6 +844,7 @@ let Impl = {
   },
 
   getSessionPayloadAndSlug: function getSessionPayloadAndSlug(reason) {
+    this._log.trace("getSessionPayloadAndSlug - Reason " + reason);
     return this.assemblePing(this.getSessionPayload(reason), reason);
   },
 
@@ -827,6 +852,7 @@ let Impl = {
    * Send data to the server. Record success/send-time in histograms
    */
   send: function send(reason) {
+    this._log.trace("send - Reason " + reason);
     // populate histograms one last time
     this.gatherMemory();
     return TelemetryPing.send(reason, this.getSessionPayloadAndSlug(reason));
@@ -875,6 +901,7 @@ let Impl = {
       // Only do this for official builds so that e.g. developer builds
       // still enable Telemetry based on prefs.
       Telemetry.canRecord = false;
+      this._log.config("enableTelemetryRecording - Can't send data, disabling Telemetry recording.");
       return false;
     }
 #endif
@@ -885,6 +912,7 @@ let Impl = {
       // Turn off local telemetry if telemetry is disabled.
       // This may change once about:telemetry is added.
       Telemetry.canRecord = false;
+      this._log.config("enableTelemetryRecording - Telemetry is disabled, turning off Telemetry recording.");
       return false;
     }
 
@@ -895,6 +923,12 @@ let Impl = {
    * Initializes telemetry within a timer. If there is no PREF_SERVER set, don't turn on telemetry.
    */
   setupChromeProcess: function setupChromeProcess(testing) {
+    if (testing && !this._log) {
+      this._log = Log.repository.getLoggerWithMessagePrefix(LOGGER_NAME, LOGGER_PREFIX);
+    }
+
+    this._log.trace("setupChromeProcess");
+
     // Initialize some probes that are kept in their own modules
     this._thirdPartyCookies = new ThirdPartyCookieProbe();
     this._thirdPartyCookies.init();
@@ -911,6 +945,7 @@ let Impl = {
     }
 
     if (!this.enableTelemetryRecording(testing)) {
+      this._log.config("setupChromeProcess - Telemetry recording is disabled, skipping Chrome process setup.");
       return Promise.resolve();
     }
 
@@ -956,6 +991,8 @@ let Impl = {
    * Initializes telemetry for a content process.
    */
   setupContentProcess: function setupContentProcess() {
+    this._log.trace("setupContentProcess");
+
     if (!this.enableTelemetryRecording()) {
       return;
     }
@@ -979,6 +1016,7 @@ let Impl = {
   },
 
   getFlashVersion: function getFlashVersion() {
+    this._log.trace("getFlashVersion");
     let host = Cc["@mozilla.org/plugin/host;1"].getService(Ci.nsIPluginHost);
     let tags = host.getPluginTags();
 
@@ -991,6 +1029,7 @@ let Impl = {
   },
 
   receiveMessage: function receiveMessage(message) {
+    this._log.trace("receiveMessage - Message name " + message.name);
     switch (message.name) {
     case MESSAGE_TELEMETRY_PAYLOAD:
     {
@@ -1015,11 +1054,13 @@ let Impl = {
   },
 
   sendContentProcessPing: function sendContentProcessPing(reason) {
+    this._log.trace("sendContentProcessPing - Reason " + reason);
     let payload = this.getSessionPayload(reason);
     cpmm.sendAsyncMessage(MESSAGE_TELEMETRY_PAYLOAD, payload);
   },
 
   savePendingPings: function savePendingPings() {
+    this._log.trace("savePendingPings");
     let sessionPing = this.getSessionPayloadAndSlug("saved-session");
     return TelemetryFile.savePendingPings(sessionPing);
   },
@@ -1048,6 +1089,7 @@ let Impl = {
   },
 
   getPayload: function getPayload() {
+    this._log.trace("getPayload");
     // This function returns the current Telemetry payload to the caller.
     // We only gather startup info once.
     if (Object.keys(this._slowSQLStartup).length == 0) {
@@ -1059,6 +1101,7 @@ let Impl = {
   },
 
   gatherStartup: function gatherStartup() {
+    this._log.trace("gatherStartup");
     let counters = processInfo.getCounters();
     if (counters) {
       [this._startupIO.startupSessionRestoreReadBytes,
@@ -1073,6 +1116,7 @@ let Impl = {
   },
 
   sendIdlePing: function sendIdlePing(aTest) {
+    this._log.trace("sendIdlePing");
     if (this._isIdleObserver) {
       idleService.removeIdleObserver(this, IDLE_TIMEOUT_SECONDS);
       this._isIdleObserver = false;
@@ -1092,6 +1136,12 @@ let Impl = {
    * This observer drives telemetry.
    */
   observe: function (aSubject, aTopic, aData) {
+    if (!this._log) {
+      this._log = Log.repository.getLoggerWithMessagePrefix(LOGGER_NAME, LOGGER_PREFIX);
+    }
+
+    this._log.trace("observe - " + aTopic + " notified.");
+
     switch (aTopic) {
     case "profile-after-change":
       // profile-after-change is only registered for chrome processes.

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

@@ -1,6 +1,8 @@
 /* Any copyright is dedicated to the Public Domain.
    http://creativecommons.org/publicdomain/zero/1.0/ */
 
+Components.utils.import("resource://gre/modules/TelemetryPing.jsm", this);
+Components.utils.import("resource://gre/modules/Services.jsm", this);
 
 // copied from toolkit/mozapps/extensions/test/xpcshell/head_addons.js
 const XULAPPINFO_CONTRACTID = "@mozilla.org/xre/app-info;1";
@@ -55,3 +57,8 @@ function createAppInfo(id, name, version, platformVersion) {
   registrar.registerFactory(XULAPPINFO_CID, "XULAppInfo",
                             XULAPPINFO_CONTRACTID, XULAppInfoFactory);
 }
+
+// Set logging preferences for all the tests.
+Services.prefs.setCharPref("toolkit.telemetry.log.level", "Trace");
+Services.prefs.setBoolPref("toolkit.telemetry.log.dump", true);
+TelemetryPing.initLogging();

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

@@ -1,9 +1,6 @@
 /* Any copyright is dedicated to the Public Domain.
    http://creativecommons.org/publicdomain/zero/1.0/ */
 
-const Cu = Components.utils;
-const {Services} = Cu.import("resource://gre/modules/Services.jsm", {});
-
 function run_test()
 {
   let testFlag = Services.telemetry.getHistogramById("TELEMETRY_TEST_FLAG");