Bug 1122049 - Add logging to Telemetry. r=gfritzsche
☠☠ backed out by eb6110f55c31 ☠ ☠
authorAlessio Placitelli <alessio.placitelli@gmail.com>
Wed, 21 Jan 2015 03:32:00 +0100
changeset 239760 b07179c96da7dd4bee9628d59c25178474fce888
parent 239759 133d1d99d3e84f8dc80c13959168eac75d73c4bb
child 239761 32ee46cf5eda7bf10609caf36f32d04a013fa737
push id506
push usermleibovic@mozilla.com
push dateThu, 29 Jan 2015 12:40:10 +0000
reviewersgfritzsche
bugs1122049
milestone38.0a1
Bug 1122049 - Add logging to Telemetry. r=gfritzsche
toolkit/components/telemetry/TelemetryPing.jsm
toolkit/components/telemetry/TelemetrySession.jsm
toolkit/components/telemetry/tests/unit/head.js
toolkit/components/telemetry/tests/unit/test_TelemetryFlagClear.js
--- a/toolkit/components/telemetry/TelemetryPing.jsm
+++ b/toolkit/components/telemetry/TelemetryPing.jsm
@@ -5,26 +5,33 @@
 
 "use strict";
 
 const Cc = Components.classes;
 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);
 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";
 
 // Delay before intializing telemetry (ms)
 const TELEMETRY_DELAY = 60000;
 // Delay before initializing telemetry if we're testing (ms)
 const TELEMETRY_TEST_DELAY = 100;
 
@@ -35,32 +42,73 @@ XPCOMUtils.defineLazyModuleGetter(this, 
                                   "resource://gre/modules/AsyncShutdown.jsm");
 XPCOMUtils.defineLazyModuleGetter(this, "TelemetryFile",
                                   "resource://gre/modules/TelemetryFile.jsm");
 XPCOMUtils.defineLazyModuleGetter(this, "TelemetryLog",
                                   "resource://gre/modules/TelemetryLog.jsm");
 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 {}
   return str.substring(1, str.length - 1);
 }
 
 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.
+   */
   reset: function() {
     Impl._clientID = null;
     return this.setup();
   },
   /**
    * Used only for testing purposes.
    */
   setup: function() {
@@ -95,16 +143,17 @@ this.TelemetryPing = Object.freeze({
    */
    get clientID() {
     return Impl.clientID;
    },
 });
 
 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.
   _previousBuildID: undefined,
   _clientID: null,
 
   popPayloads: function popPayloads(reason, externalPayload) {
     function payloadIter() {
@@ -127,16 +176,17 @@ let Impl = {
   setServer: function (aServer) {
     this._server = aServer;
   },
 
   /**
    * 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)));
   },
 
   sendPingsFromIterator: function sendPingsFromIterator(server, reason, i) {
     let p = [data for (data in i)].map((data) =>
       this.doPing(server, data).then(null, () => TelemetryFile.savePing(data, true)));
 
@@ -167,16 +217,17 @@ let Impl = {
                             info.appVersion, info.appUpdateChannel,
                             info.appBuildID];
       slug = pathComponents.join("/");
     }
     return "/submit/telemetry/" + slug;
   },
 
   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"]
                   .createInstance(Ci.nsIXMLHttpRequest);
     request.mozBackgroundRequest = true;
     request.open("POST", url, true);
     request.overrideMimeType("text/plain");
     request.setRequestHeader("Content-Type", "application/json; charset=UTF-8");
@@ -240,41 +291,50 @@ let Impl = {
   enableTelemetryRecording: function enableTelemetryRecording(testing) {
 
 #ifdef MOZILLA_OFFICIAL
     if (!Telemetry.canSend && !testing) {
       // We can't send data; no point in initializing observers etc.
       // 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
 
     let enabled = Preferences.get(PREF_ENABLED, false);
     this._server = Preferences.get(PREF_SERVER, undefined);
     if (!enabled) {
       // 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;
     }
 
     return true;
   },
 
   /**
    * 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();
     }
 
     // For very short session durations, we may never load the client
     // id from disk.
     // We try to cache it in prefs to avoid this, even though this may
     // lead to some stale client ids.
     this._clientID = Preferences.get(PREF_CACHED_CLIENTID, null);
@@ -285,16 +345,18 @@ let Impl = {
     let deferred = Promise.defer();
     let delayedTask = new DeferredTask(function* () {
       this._initialized = true;
 
       yield TelemetryFile.loadSavedPings();
       // 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.
         yield this.send("overdue-flush");
       }
 
       if ("@mozilla.org/datareporting/service;1" in Cc) {
         let drs = Cc["@mozilla.org/datareporting/service;1"]
@@ -316,19 +378,38 @@ let Impl = {
     delayedTask.arm();
     return deferred.promise;
   },
 
   /**
    * 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;
     }
   },
 
   get clientID() {
     return this._clientID;
   },
 };
--- a/toolkit/components/telemetry/TelemetrySession.jsm
+++ b/toolkit/components/telemetry/TelemetrySession.jsm
@@ -6,16 +6,17 @@
 "use strict";
 
 const Cc = Components.classes;
 const Ci = Components.interfaces;
 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);
 Cu.import("resource://gre/modules/DeferredTask.jsm", this);
 Cu.import("resource://gre/modules/Preferences.jsm");
 
 const IS_CONTENT_PROCESS = (function() {
   // We cannot use Services.appinfo here because in telemetry xpcshell tests,
@@ -26,16 +27,19 @@ const IS_CONTENT_PROCESS = (function() {
 
 // When modifying the payload in incompatible ways, please bump this version number
 const PAYLOAD_VERSION = 1;
 
 // This is the HG changeset of the Histogram.json file, used to associate
 // 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";
 const PREF_PREVIOUS_BUILDID = PREF_BRANCH + "previousBuildID";
 const PREF_CACHED_CLIENTID = PREF_BRANCH + "cachedClientID"
 const PREF_FHR_UPLOAD_ENABLED = "datareporting.healthreport.uploadEnabled";
 
 const MESSAGE_TELEMETRY_PAYLOAD = "Telemetry:Payload";
@@ -256,16 +260,17 @@ this.TelemetrySession = Object.freeze({
    get clientID() {
     return Impl.clientID;
    },
 });
 
 let Impl = {
   _histograms: {},
   _initialized: false,
+  _log: null,
   _prevValues: {},
   // Generate a unique id once per session so the server can cope with
   // duplicate submissions.
   _uuid: generateUUID(),
   // Regex that matches histograms we care about during startup.
   // Keep this in sync with gen-histogram-bucket-ranges.py.
   _startupHistogramRegex: /SQLITE|HTTP|SPDY|CACHE|DNS/,
   _slowSQLStartup: {},
@@ -284,16 +289,18 @@ let Impl = {
 
   /**
    * Gets a series of simple measurements (counters). At the moment, this
    * only returns startup data from nsIAppStartup.getStartupInfo().
    *
    * @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.
     var ret = {
       // uptime in minutes
       uptime: Math.round((new Date() - si.process) / 60000)
     }
 
@@ -446,31 +453,35 @@ let Impl = {
 
     // add an upper bound
     if (last && last < c.length)
       retgram.values[r[last]] = 0;
     return retgram;
   },
 
   getHistograms: function getHistograms(hls) {
+    this._log.trace("getHistograms");
+
     let registered = Telemetry.registeredHistograms([]);
     let ret = {};
 
     for (let name of registered) {
       for (let n of [name, "STARTUP_" + name]) {
         if (n in hls) {
           ret[n] = this.packHistogram(hls[n]);
         }
       }
     }
 
     return ret;
   },
 
   getAddonHistograms: function getAddonHistograms() {
+    this._log.trace("getAddonHistograms");
+
     let ahs = Telemetry.addonHistogramSnapshots;
     let ret = {};
 
     for (let addonName in ahs) {
       let addonHistograms = ahs[addonName];
       let packedHistograms = {};
       for (let name in addonHistograms) {
         packedHistograms[name] = this.packHistogram(addonHistograms[name]);
@@ -478,32 +489,36 @@ let Impl = {
       if (Object.keys(packedHistograms).length != 0)
         ret[addonName] = packedHistograms;
     }
 
     return ret;
   },
 
   getKeyedHistograms: function() {
+    this._log.trace("getKeyedHistograms");
+
     let registered = Telemetry.registeredKeyedHistograms([]);
     let ret = {};
 
     for (let id of registered) {
       ret[id] = {};
       let keyed = Telemetry.getKeyedHistogramById(id);
       let snapshot = keyed.snapshot();
       for (let key of Object.keys(snapshot)) {
         ret[id][key] = this.packHistogram(snapshot[key]);
       }
     }
 
     return ret;
   },
 
   getThreadHangStats: function getThreadHangStats(stats) {
+    this._log.trace("getThreadHangStats");
+
     stats.forEach((thread) => {
       thread.activity = this.packHistogram(thread.activity);
       thread.hangs.forEach((hang) => {
         hang.histogram = this.packHistogram(hang.histogram);
       });
     });
     return stats;
   },
@@ -512,16 +527,18 @@ let Impl = {
    * Descriptive metadata
    *
    * @param  reason
    *         The reason for the telemetry ping, this will be included in the
    *         returned metadata,
    * @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,
       OS: ai.OS,
       appID: ai.ID,
       appVersion: ai.version,
       appName: ai.name,
       appBuildID: ai.appBuildID,
@@ -623,16 +640,18 @@ let Impl = {
 
     return ret;
   },
 
   /**
    * 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"].
             getService(Ci.nsIMemoryReporterManager);
     } catch (e) {
       // OK to skip memory reporters in xpcshell
       return;
     }
@@ -745,16 +764,18 @@ let Impl = {
   getChildPayloads: function getChildPayloads() {
     return [for (child of this._childTelemetry) child.payload];
   },
 
   /**
    * 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) {
       // Only duplicate histograms with actual data.
       if (this.isInterestingStartupHistogram(name) && name in snapshots) {
         Telemetry.histogramFrom("STARTUP_" + name, name);
       }
     }
@@ -762,16 +783,18 @@ let Impl = {
 
   /**
    * Get the current session's payload using the provided
    * simpleMeasurements and info, which are typically obtained by a call
    * to |this.getSimpleMeasurements| and |this.getMetadata|,
    * respectively.
    */
   assemblePayloadWithMeasurements: function assemblePayloadWithMeasurements(simpleMeasurements, info) {
+    this._log.trace("assemblePayloadWithMeasurements");
+
     // Payload common to chrome and content processes.
     let payloadObj = {
       ver: PAYLOAD_VERSION,
       simpleMeasurements: simpleMeasurements,
       histograms: this.getHistograms(Telemetry.histogramSnapshots),
       keyedHistograms: this.getKeyedHistograms(),
       chromeHangs: Telemetry.chromeHangs,
       threadHangStats: this.getThreadHangStats(Telemetry.threadHangStats),
@@ -804,34 +827,37 @@ let Impl = {
 
     if (this._childTelemetry.length) {
       payloadObj.childPayloads = this.getChildPayloads();
     }
     return payloadObj;
   },
 
   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);
   },
 
   assemblePing: function assemblePing(payloadObj, reason) {
     let slug = this._uuid;
     return { slug: slug, reason: reason, payload: payloadObj };
   },
 
   getSessionPayloadAndSlug: function getSessionPayloadAndSlug(reason) {
+    this._log.trace("getSessionPayloadAndSlug - Reason " + reason);
     return this.assemblePing(this.getSessionPayload(reason), reason);
   },
 
   /**
    * 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));
   },
 
   submissionPath: function submissionPath(ping) {
     let slug;
     if (!ping) {
@@ -870,52 +896,61 @@ let Impl = {
   enableTelemetryRecording: function enableTelemetryRecording(testing) {
 
 #ifdef MOZILLA_OFFICIAL
     if (!Telemetry.canSend && !testing) {
       // We can't send data; no point in initializing observers etc.
       // 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
 
     let enabled = Preferences.get(PREF_ENABLED, false);
     this._server = Preferences.get(PREF_SERVER, undefined);
     if (!enabled) {
       // 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;
     }
 
     return true;
   },
 
   /**
    * 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();
 
     // Record old value and update build ID preference if this is the first
     // run with a new build ID.
     let previousBuildID = Preferences.get(PREF_PREVIOUS_BUILDID, undefined);
     let thisBuildID = Services.appinfo.appBuildID;
     // If there is no previousBuildID preference, this._previousBuildID remains
     // undefined so no value is sent in the telemetry metadata.
     if (previousBuildID != thisBuildID) {
       this._previousBuildID = previousBuildID;
       Preferences.set(PREF_PREVIOUS_BUILDID, thisBuildID);
     }
 
     if (!this.enableTelemetryRecording(testing)) {
+      this._log.config("setupChromeProcess - Telemetry recording is disabled, skipping Chrome process setup.");
       return Promise.resolve();
     }
 
     AsyncShutdown.sendTelemetry.addBlocker(
       "Telemetry: shutting down",
       function condition(){
         this.uninstall();
         if (Telemetry.canSend) {
@@ -951,16 +986,18 @@ let Impl = {
     delayedTask.arm();
     return deferred.promise;
   },
 
   /**
    * Initializes telemetry for a content process.
    */
   setupContentProcess: function setupContentProcess() {
+    this._log.trace("setupContentProcess");
+
     if (!this.enableTelemetryRecording()) {
       return;
     }
 
     Services.obs.addObserver(this, "content-child-shutdown", false);
 
     this.gatherStartupHistograms();
 
@@ -974,28 +1011,30 @@ let Impl = {
     delayedTask.arm();
   },
 
   testLoadHistograms: function testLoadHistograms(file) {
     return TelemetryFile.testLoadHistograms(file);
   },
 
   getFlashVersion: function getFlashVersion() {
+    this._log.trace("getFlashVersion");
     let host = Cc["@mozilla.org/plugin/host;1"].getService(Ci.nsIPluginHost);
     let tags = host.getPluginTags();
 
     for (let i = 0; i < tags.length; i++) {
       if (tags[i].name == "Shockwave Flash")
         return tags[i].version;
     }
 
     return null;
   },
 
   receiveMessage: function receiveMessage(message) {
+    this._log.trace("receiveMessage - Message name " + message.name);
     switch (message.name) {
     case MESSAGE_TELEMETRY_PAYLOAD:
     {
       let target = message.target;
       for (let child of this._childTelemetry) {
         if (child.source.get() === target) {
           // Update existing telemetry data.
           child.payload = message.data;
@@ -1010,21 +1049,23 @@ let Impl = {
       break;
     }
     default:
       throw new Error("Telemetry.receiveMessage: bad message name");
     }
   },
 
   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);
   },
 
   testSaveHistograms: function testSaveHistograms(file) {
     return TelemetryFile.savePingToFile(this.getSessionPayloadAndSlug("saved-session"),
       file.path, true);
   },
@@ -1043,41 +1084,44 @@ let Impl = {
       this._hasXulWindowVisibleObserver = false;
     }
 #ifdef MOZ_WIDGET_ANDROID
     Services.obs.removeObserver(this, "application-background", false);
 #endif
   },
 
   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) {
       this.gatherStartupHistograms();
       this._slowSQLStartup = Telemetry.slowSQL;
     }
     this.gatherMemory();
     return this.getSessionPayload("gather-payload");
   },
 
   gatherStartup: function gatherStartup() {
+    this._log.trace("gatherStartup");
     let counters = processInfo.getCounters();
     if (counters) {
       [this._startupIO.startupSessionRestoreReadBytes,
         this._startupIO.startupSessionRestoreWriteBytes] = counters;
     }
     this.gatherStartupHistograms();
     this._slowSQLStartup = Telemetry.slowSQL;
   },
 
   setAddOns: function setAddOns(aAddOns) {
     this._addons = aAddOns;
   },
 
   sendIdlePing: function sendIdlePing(aTest) {
+    this._log.trace("sendIdlePing");
     if (this._isIdleObserver) {
       idleService.removeIdleObserver(this, IDLE_TIMEOUT_SECONDS);
       this._isIdleObserver = false;
     }
     if (aTest) {
       return this.send("test-ping");
     } else if (Telemetry.canSend) {
       return this.send("idle-daily");
@@ -1087,16 +1131,22 @@ let Impl = {
   testPing: function testPing() {
     return this.sendIdlePing(true);
   },
 
   /**
    * 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.
       return this.setupChromeProcess();
     case "app-startup":
       // app-startup is only registered for content processes.
       return this.setupContentProcess();
     case "content-child-shutdown":
--- a/toolkit/components/telemetry/tests/unit/head.js
+++ b/toolkit/components/telemetry/tests/unit/head.js
@@ -1,11 +1,13 @@
 /* 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";
 const XULAPPINFO_CID = Components.ID("{c763b610-9d49-455a-bbd2-ede71682a1ac}");
 let gAppInfo;
 let gOldAppInfo = Components.classes[XULAPPINFO_CONTRACTID]
                             .getService(Components.interfaces.nsIXULRuntime);
 
@@ -50,8 +52,13 @@ function createAppInfo(id, name, version
         throw Components.results.NS_ERROR_NO_AGGREGATION;
       return gAppInfo.QueryInterface(iid);
     }
   };
   var registrar = Components.manager.QueryInterface(Ci.nsIComponentRegistrar);
   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();
--- a/toolkit/components/telemetry/tests/unit/test_TelemetryFlagClear.js
+++ b/toolkit/components/telemetry/tests/unit/test_TelemetryFlagClear.js
@@ -1,14 +1,11 @@
 /* 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");
   equal(JSON.stringify(testFlag.snapshot().counts), "[1,0,0]", "Original value is correct");
   testFlag.add(1);
   equal(JSON.stringify(testFlag.snapshot().counts), "[0,1,0]", "Value is correct after ping.");
   testFlag.clear();
   equal(JSON.stringify(testFlag.snapshot().counts), "[1,0,0]", "Value is correct after calling clear()");