From 788eb651ccdae701f4b7fe07ee8bb01835071dc9 Mon Sep 17 00:00:00 2001 From: Gregory Szorc Date: Fri, 28 Mar 2014 11:20:31 -0700 Subject: [PATCH] Bug 989137 - Part 2: Don't use a global logger; r=gfritzsche As part of debugging subsequent patches, I ran into issues debugging the interaction between multiple Experiments instances. To get to the bottom of the problem, I had to make some changes to the logging framework. This is the first patch in a sub-series dealing with logging. This patch stops relying on the global logger. Subsequent patches will make the logging output aid debugging. --HG-- extra : rebase_source : 40b34a1444ff3fb70a9da7cf242ee522d6ec07ea extra : source : 61877a5f15aa01dec05fe1882eae6ad9f18f81a0 --- browser/experiments/Experiments.jsm | 143 ++++++++++++++-------------- 1 file changed, 74 insertions(+), 69 deletions(-) diff --git a/browser/experiments/Experiments.jsm b/browser/experiments/Experiments.jsm index 50713beb5c4..b699119bf35 100644 --- a/browser/experiments/Experiments.jsm +++ b/browser/experiments/Experiments.jsm @@ -236,6 +236,7 @@ let Experiments = { */ Experiments.Policy = function () { + this._log = Log.repository.getLogger("Browser.Experiments.Policy"); }; Experiments.Policy.prototype = { @@ -247,7 +248,7 @@ Experiments.Policy.prototype = { let pref = gPrefs.get(PREF_FORCE_SAMPLE); if (pref !== undefined) { let val = Number.parseFloat(pref); - gLogger.debug("Experiments::Policy::random sample forced: " + val); + this._log.debug("Experiments::Policy::random sample forced: " + val); if (IsNaN(val) || val < 0) { return 0; } @@ -301,6 +302,8 @@ Experiments.Policy.prototype = { */ Experiments.Experiments = function (policy=new Experiments.Policy()) { + this._log = Log.repository.getLogger("Browser.Experiments.Experiments"); + this._policy = policy; // This is a Map of (string -> ExperimentEntry), keyed with the experiment id. @@ -340,7 +343,7 @@ Experiments.Experiments.prototype = { configureLogging(); gExperimentsEnabled = gPrefs.get(PREF_ENABLED, false); - gLogger.trace("enabled="+gExperimentsEnabled+", "+this.enabled); + this._log.trace("enabled=" + gExperimentsEnabled + ", " + this.enabled); gPrefs.observe(PREF_LOGGING, configureLogging); gPrefs.observe(PREF_MANIFEST_URI, this.updateManifest, this); @@ -357,12 +360,12 @@ Experiments.Experiments.prototype = { this._loadTask = Task.spawn(this._loadFromCache.bind(this)); this._loadTask.then( () => { - gLogger.trace("Experiments::_loadTask finished ok"); + this._log.trace("Experiments::_loadTask finished ok"); this._loadTask = null; this._run(); }, (e) => { - gLogger.error("Experiments::_loadFromCache caught error: " + e); + this._log.error("Experiments::_loadFromCache caught error: " + e); } ); }, @@ -414,12 +417,12 @@ Experiments.Experiments.prototype = { * Toggle whether the experiments feature is enabled or not. */ set enabled(enabled) { - gLogger.trace("Experiments::set enabled(" + enabled + ")"); + this._log.trace("Experiments::set enabled(" + enabled + ")"); gPrefs.set(PREF_ENABLED, enabled); }, _toggleExperimentsEnabled: function (enabled) { - gLogger.trace("Experiments::_toggleExperimentsEnabled(" + enabled + ")"); + this._log.trace("Experiments::_toggleExperimentsEnabled(" + enabled + ")"); let wasEnabled = gExperimentsEnabled; gExperimentsEnabled = enabled && telemetryEnabled(); @@ -525,18 +528,18 @@ Experiments.Experiments.prototype = { }, _run: function() { - gLogger.trace("Experiments::_run"); + this._log.trace("Experiments::_run"); this._checkForShutdown(); if (!this._mainTask) { this._mainTask = Task.spawn(this._main.bind(this)); this._mainTask.then( () => { - gLogger.trace("Experiments::_main finished, scheduling next run"); + this._log.trace("Experiments::_main finished, scheduling next run"); this._mainTask = null; this._scheduleNextRun(); }, (e) => { - gLogger.error("Experiments::_main caught error: " + e); + this._log.error("Experiments::_main caught error: " + e); this._mainTask = null; } ); @@ -546,7 +549,7 @@ Experiments.Experiments.prototype = { _main: function*() { do { - gLogger.trace("Experiments::_main iteration"); + this._log.trace("Experiments::_main iteration"); yield this._loadTask; if (this._refresh) { yield this._loadManifest(); @@ -562,7 +565,7 @@ Experiments.Experiments.prototype = { }, _loadManifest: function*() { - gLogger.trace("Experiments::_loadManifest"); + this._log.trace("Experiments::_loadManifest"); let uri = Services.urlFormatter.formatURLPref(PREF_BRANCH + PREF_MANIFEST_URI); this._checkForShutdown(); @@ -570,7 +573,7 @@ Experiments.Experiments.prototype = { this._refresh = false; try { let responseText = yield this._httpGetRequest(uri); - gLogger.trace("Experiments::_loadManifest() - responseText=\"" + responseText + "\""); + this._log.trace("Experiments::_loadManifest() - responseText=\"" + responseText + "\""); if (this._shutdown) { return; @@ -579,7 +582,7 @@ Experiments.Experiments.prototype = { let data = JSON.parse(responseText); this._updateExperiments(data); } catch (e) { - gLogger.error("Experiments::_loadManifest - failure to fetch/parse manifest (continuing anyway): " + e); + this._log.error("Experiments::_loadManifest - failure to fetch/parse manifest (continuing anyway): " + e); } }, @@ -591,7 +594,7 @@ Experiments.Experiments.prototype = { * The promise is resolved when the manifest and experiment list is updated. */ updateManifest: function () { - gLogger.trace("Experiments::updateManifest()"); + this._log.trace("Experiments::updateManifest()"); if (!gExperimentsEnabled) { return Promise.reject(new Error("experiments are disabled")); @@ -606,7 +609,7 @@ Experiments.Experiments.prototype = { }, notify: function (timer) { - gLogger.trace("Experiments::notify()"); + this._log.trace("Experiments::notify()"); this._checkForShutdown(); return this._run(); }, @@ -614,7 +617,7 @@ Experiments.Experiments.prototype = { // START OF ADD-ON LISTENERS onDisabled: function (addon) { - gLogger.trace("Experiments::onDisabled() - addon id: " + addon.id); + this._log.trace("Experiments::onDisabled() - addon id: " + addon.id); if (addon.id == this._pendingUninstall) { return; } @@ -626,9 +629,9 @@ Experiments.Experiments.prototype = { }, onUninstalled: function (addon) { - gLogger.trace("Experiments::onUninstalled() - addon id: " + addon.id); + this._log.trace("Experiments::onUninstalled() - addon id: " + addon.id); if (addon.id == this._pendingUninstall) { - gLogger.trace("onUninstalled: matches pending uninstall"); + this._log.trace("onUninstalled: matches pending uninstall"); return; } let activeExperiment = this._getActiveExperiment(); @@ -655,25 +658,26 @@ Experiments.Experiments.prototype = { * the responseText when the request is complete. */ _httpGetRequest: function (url) { - gLogger.trace("Experiments::httpGetRequest(" + url + ")"); + this._log.trace("Experiments::httpGetRequest(" + url + ")"); let xhr = Cc["@mozilla.org/xmlextras/xmlhttprequest;1"].createInstance(Ci.nsIXMLHttpRequest); try { xhr.open("GET", url); } catch (e) { - gLogger.error("Experiments::httpGetRequest() - Error opening request to " + url + ": " + e); + this._log.error("Experiments::httpGetRequest() - Error opening request to " + url + ": " + e); return Promise.reject(new Error("Experiments - Error opening XHR for " + url)); } let deferred = Promise.defer(); + let log = this._log; xhr.onerror = function (e) { - gLogger.error("Experiments::httpGetRequest::onError() - Error making request to " + url + ": " + e.error); + log.error("Experiments::httpGetRequest::onError() - Error making request to " + url + ": " + e.error); deferred.reject(new Error("Experiments - XHR error for " + url + " - " + e.error)); }; xhr.onload = function (event) { if (xhr.status !== 200 && xhr.state !== 0) { - gLogger.error("Experiments::httpGetRequest::onLoad() - Request to " + url + " returned status " + xhr.status); + log.error("Experiments::httpGetRequest::onLoad() - Request to " + url + " returned status " + xhr.status); deferred.reject(new Error("Experiments - XHR status for " + url + " is " + xhr.status)); return; } @@ -687,7 +691,7 @@ Experiments.Experiments.prototype = { CertUtils.checkCert(xhr.channel, allowNonBuiltin, certs); } catch (e) { - gLogger.error("Experiments: manifest fetch failed certificate checks", [e]); + log.error("Experiments: manifest fetch failed certificate checks", [e]); deferred.reject(new Error("Experiments - manifest fetch failed certificate checks: " + e)); return; } @@ -714,7 +718,7 @@ Experiments.Experiments.prototype = { * Part of the main task to save the cache to disk, called from _main. */ _saveToCache: function* () { - gLogger.trace("Experiments::_saveToCache"); + this._log.trace("Experiments::_saveToCache"); let path = this._cacheFilePath; let textData = JSON.stringify({ version: CACHE_VERSION, @@ -726,14 +730,14 @@ Experiments.Experiments.prototype = { let options = { tmpPath: path + ".tmp", compression: "lz4" }; yield OS.File.writeAtomic(path, data, options); this._dirty = false; - gLogger.debug("Experiments._saveToCache saved to " + path); + this._log.debug("Experiments._saveToCache saved to " + path); }, /* * Task function, load the cached experiments manifest file from disk. */ _loadFromCache: function*() { - gLogger.trace("Experiments::_loadFromCache"); + this._log.trace("Experiments::_loadFromCache"); let path = this._cacheFilePath; try { let result = yield loadJSONAsync(path, { compression: "lz4" }); @@ -745,7 +749,7 @@ Experiments.Experiments.prototype = { }, _populateFromCache: function (data) { - gLogger.trace("Experiments::populateFromCache() - data: " + JSON.stringify(data)); + this._log.trace("Experiments::populateFromCache() - data: " + JSON.stringify(data)); // If the user has a newer cache version than we can understand, we fail // hard; no experiments should be active in this older client. @@ -770,10 +774,10 @@ Experiments.Experiments.prototype = { * array in the manifest */ _updateExperiments: function (manifestObject) { - gLogger.trace("Experiments::_updateExperiments() - experiments: " + JSON.stringify(manifestObject)); + this._log.trace("Experiments::_updateExperiments() - experiments: " + JSON.stringify(manifestObject)); if (manifestObject.version !== MANIFEST_VERSION) { - gLogger.warning("Experiments::updateExperiments() - unsupported version " + manifestObject.version); + this._log.warning("Experiments::updateExperiments() - unsupported version " + manifestObject.version); } let experiments = new Map(); // The new experiments map @@ -784,7 +788,7 @@ Experiments.Experiments.prototype = { if (entry) { if (!entry.updateFromManifestData(data)) { - gLogger.error("Experiments::updateExperiments() - Invalid manifest data for " + data.id); + this._log.error("Experiments::updateExperiments() - Invalid manifest data for " + data.id); continue; } } else { @@ -805,7 +809,7 @@ Experiments.Experiments.prototype = { // We remove them after KEEP_HISTORY_N_DAYS. for (let [id, entry] of this._experiments) { if (experiments.has(id) || !entry.startDate || entry.shouldDiscard()) { - gLogger.trace("Experiments::updateExperiments() - discarding entry for " + id); + this._log.trace("Experiments::updateExperiments() - discarding entry for " + id); continue; } @@ -824,7 +828,7 @@ Experiments.Experiments.prototype = { } if (enabled.length > 1) { - gLogger.error("Experiments::getActiveExperimentId() - should not have more than 1 active experiment"); + this._log.error("Experiments::getActiveExperimentId() - should not have more than 1 active experiment"); throw new Error("have more than 1 active experiment"); } @@ -838,7 +842,7 @@ Experiments.Experiments.prototype = { * @return Promise<> Promise that will get resolved once the task is done or failed. */ disableExperiment: function (userDisabled=true) { - gLogger.trace("Experiments::disableExperiment()"); + this._log.trace("Experiments::disableExperiment()"); this._terminateReason = userDisabled ? TELEMETRY_LOG.TERMINATION.USERDISABLED : TELEMETRY_LOG.TERMINATION.FROM_API; return this._run(); @@ -849,7 +853,7 @@ Experiments.Experiments.prototype = { * experiment if needed and activate the first applicable candidate. */ _evaluateExperiments: function*() { - gLogger.trace("Experiments::_evaluateExperiments"); + this._log.trace("Experiments::_evaluateExperiments"); this._checkForShutdown(); @@ -871,8 +875,8 @@ Experiments.Experiments.prototype = { let expectedAddonIds = new Set([e._addonId for ([,e] of this._experiments)]); let unknownAddons = [a for (a of installedExperiments) if (!expectedAddonIds.has(a.id))]; if (unknownAddons.length) { - gLogger.warn("Experiments::_evaluateExperiments() - unknown add-ons in AddonManager: " + - [a.id for (a of unknownAddons)].join(", ")); + this._log.warn("Experiments::_evaluateExperiments() - unknown add-ons in AddonManager: " + + [a.id for (a of unknownAddons)].join(", ")); yield uninstallAddons(unknownAddons); } @@ -893,18 +897,18 @@ Experiments.Experiments.prototype = { } if (wasStopped) { this._dirty = true; - gLogger.debug("Experiments::evaluateExperiments() - stopped experiment " + this._log.debug("Experiments::evaluateExperiments() - stopped experiment " + activeExperiment.id); activeExperiment = null; activeChanged = true; } else if (activeExperiment.needsUpdate) { - gLogger.debug("Experiments::evaluateExperiments() - updating experiment " + this._log.debug("Experiments::evaluateExperiments() - updating experiment " + activeExperiment.id); try { yield activeExperiment.stop(); yield activeExperiment.start(); } catch (e) { - gLogger.error(e); + this._log.error(e); // On failure try the next experiment. activeExperiment = null; } @@ -938,7 +942,7 @@ Experiments.Experiments.prototype = { } if (applicable) { - gLogger.debug("Experiments::evaluateExperiments() - activating experiment " + id); + this._log.debug("Experiments::evaluateExperiments() - activating experiment " + id); try { yield experiment.start(); activeChanged = true; @@ -996,7 +1000,7 @@ Experiments.Experiments.prototype = { return; } - gLogger.trace("Experiments::scheduleExperimentEvaluation() - scheduling for "+time+", now: "+now); + this._log.trace("Experiments::scheduleExperimentEvaluation() - scheduling for "+time+", now: "+now); this._policy.oneshotTimer(this.notify, time - now, this, "_timer"); }, }; @@ -1008,6 +1012,7 @@ Experiments.Experiments.prototype = { Experiments.ExperimentEntry = function (policy) { this._policy = policy || new Experiments.Policy(); + this._log = policy._log; // Is this experiment running? this._enabled = false; @@ -1140,7 +1145,7 @@ Experiments.ExperimentEntry.prototype = { initFromCacheData: function (data) { for (let key of this.SERIALIZE_KEYS) { if (!(key in data) && !this.DATE_KEYS.has(key)) { - gLogger.error("ExperimentEntry::initFromCacheData() - missing required key " + key); + this._log.error("ExperimentEntry::initFromCacheData() - missing required key " + key); return false; } }; @@ -1247,9 +1252,9 @@ Experiments.ExperimentEntry.prototype = { let maxActive = data.maxActiveSeconds || 0; let startSec = (this.startDate || 0) / 1000; - gLogger.trace("ExperimentEntry::isApplicable() - now=" + now - + ", randomValue=" + this._randomValue - + ", data=" + JSON.stringify(this._manifestData)); + this._log.trace("ExperimentEntry::isApplicable() - now=" + now + + ", randomValue=" + this._randomValue + + ", data=" + JSON.stringify(this._manifestData)); // Not applicable if it already ran. @@ -1301,8 +1306,8 @@ Experiments.ExperimentEntry.prototype = { for (let check of simpleChecks) { let result = check.condition(); if (!result) { - gLogger.debug("ExperimentEntry::isApplicable() - id=" - + data.id + " - test '" + check.name + "' failed"); + this._log.debug("ExperimentEntry::isApplicable() - id=" + + data.id + " - test '" + check.name + "' failed"); return Promise.reject([check.name]); } } @@ -1319,7 +1324,7 @@ Experiments.ExperimentEntry.prototype = { * result (forced to boolean). */ _runFilterFunction: function (jsfilter) { - gLogger.trace("ExperimentEntry::runFilterFunction() - filter: " + jsfilter); + this._log.trace("ExperimentEntry::runFilterFunction() - filter: " + jsfilter); return Task.spawn(function ExperimentEntry_runFilterFunction_task() { const nullprincipal = Cc["@mozilla.org/nullprincipal;1"].createInstance(Ci.nsIPrincipal); @@ -1336,7 +1341,7 @@ Experiments.ExperimentEntry.prototype = { try { Cu.evalInSandbox(jsfilter, sandbox); } catch (e) { - gLogger.error("ExperimentEntry::runFilterFunction() - failed to eval jsfilter: " + e.message); + this._log.error("ExperimentEntry::runFilterFunction() - failed to eval jsfilter: " + e.message); throw ["jsfilter-evalfailed"]; } @@ -1351,7 +1356,7 @@ Experiments.ExperimentEntry.prototype = { result = !!Cu.evalInSandbox("filter({healthReportPayload: JSON.parse(_hr), telemetryPayload: JSON.parse(_t)})", sandbox); } catch (e) { - gLogger.debug("ExperimentEntry::runFilterFunction() - filter function failed: " + this._log.debug("ExperimentEntry::runFilterFunction() - filter function failed: " + e.message + ", " + e.stack); throw ["jsfilter-threw", e.message]; } @@ -1372,13 +1377,13 @@ Experiments.ExperimentEntry.prototype = { * @return Promise<> Resolved when the operation is complete. */ start: function () { - gLogger.trace("ExperimentEntry::start() for " + this.id); + this._log.trace("ExperimentEntry::start() for " + this.id); return Task.spawn(function* ExperimentEntry_start_task() { let addons = yield installedExperimentAddons(); if (addons.length > 0) { - gLogger.error("ExperimentEntry::start() - there are already " - + addons.length + " experiment addons installed"); + this._log.error("ExperimentEntry::start() - there are already " + + addons.length + " experiment addons installed"); yield uninstallAddons(addons); } @@ -1395,7 +1400,7 @@ Experiments.ExperimentEntry.prototype = { let failureHandler = (install, handler) => { let message = "AddonInstall " + handler + " for " + this.id + ", state=" + (install.state || "?") + ", error=" + install.error; - gLogger.error("ExperimentEntry::_installAddon() - " + message); + this._log.error("ExperimentEntry::_installAddon() - " + message); this._failedStart = true; TelemetryLog.log(TELEMETRY_LOG.ACTIVATION_KEY, @@ -1406,27 +1411,27 @@ Experiments.ExperimentEntry.prototype = { let listener = { onDownloadEnded: install => { - gLogger.trace("ExperimentEntry::_installAddon() - onDownloadEnded for " + this.id); + this._log.trace("ExperimentEntry::_installAddon() - onDownloadEnded for " + this.id); if (install.existingAddon) { - gLogger.warn("ExperimentEntry::_installAddon() - onDownloadEnded, addon already installed"); + this._log.warn("ExperimentEntry::_installAddon() - onDownloadEnded, addon already installed"); } if (install.addon.type !== "experiment") { - gLogger.error("ExperimentEntry::_installAddon() - onDownloadEnded, wrong addon type"); + this._log.error("ExperimentEntry::_installAddon() - onDownloadEnded, wrong addon type"); install.cancel(); } }, onInstallStarted: install => { - gLogger.trace("ExperimentEntry::_installAddon() - onInstallStarted for " + this.id); + this._log.trace("ExperimentEntry::_installAddon() - onInstallStarted for " + this.id); if (install.existingAddon) { - gLogger.warn("ExperimentEntry::_installAddon() - onInstallStarted, addon already installed"); + this._log.warn("ExperimentEntry::_installAddon() - onInstallStarted, addon already installed"); } if (install.addon.type !== "experiment") { - gLogger.error("ExperimentEntry::_installAddon() - onInstallStarted, wrong addon type"); + this._log.error("ExperimentEntry::_installAddon() - onInstallStarted, wrong addon type"); return false; } @@ -1435,7 +1440,7 @@ Experiments.ExperimentEntry.prototype = { }, onInstallEnded: install => { - gLogger.trace("ExperimentEntry::_installAddon() - install ended for " + this.id); + this._log.trace("ExperimentEntry::_installAddon() - install ended for " + this.id); this._lastChangedDate = this._policy.now(); this._startDate = this._policy.now(); this._enabled = true; @@ -1472,9 +1477,9 @@ Experiments.ExperimentEntry.prototype = { * @return Promise<> Resolved when the operation is complete. */ stop: function (terminationKind, terminationReason) { - gLogger.trace("ExperimentEntry::stop() - id=" + this.id + ", terminationKind=" + terminationKind); + this._log.trace("ExperimentEntry::stop() - id=" + this.id + ", terminationKind=" + terminationKind); if (!this._enabled) { - gLogger.warning("ExperimentEntry::stop() - experiment not enabled: " + id); + this._log.warning("ExperimentEntry::stop() - experiment not enabled: " + id); return Promise.reject(); } @@ -1489,7 +1494,7 @@ Experiments.ExperimentEntry.prototype = { AddonManager.getAddonByID(this._addonId, addon => { if (!addon) { let message = "could not get Addon for " + this.id; - gLogger.warn("ExperimentEntry::stop() - " + message); + this._log.warn("ExperimentEntry::stop() - " + message); updateDates(); deferred.resolve(); return; @@ -1509,7 +1514,7 @@ Experiments.ExperimentEntry.prototype = { } if (!(terminationKind in TELEMETRY_LOG.TERMINATION)) { - gLogger.warn("ExperimentEntry::stop() - unknown terminationKind " + terminationKind); + this._log.warn("ExperimentEntry::stop() - unknown terminationKind " + terminationKind); return; } @@ -1527,7 +1532,7 @@ Experiments.ExperimentEntry.prototype = { * the value indicates whether it was stopped. */ maybeStop: function () { - gLogger.trace("ExperimentEntry::maybeStop()"); + this._log.trace("ExperimentEntry::maybeStop()"); return Task.spawn(function ExperimentEntry_maybeStop_task() { let result = yield this._shouldStop(); @@ -1594,11 +1599,11 @@ Experiments.ExperimentEntry.prototype = { * Perform sanity checks on the experiment data. */ _isManifestDataValid: function (data) { - gLogger.trace("ExperimentEntry::isManifestDataValid() - data: " + JSON.stringify(data)); + this._log.trace("ExperimentEntry::isManifestDataValid() - data: " + JSON.stringify(data)); for (let key of this.MANIFEST_REQUIRED_FIELDS) { if (!(key in data)) { - gLogger.error("ExperimentEntry::isManifestDataValid() - missing required key: " + key); + this._log.error("ExperimentEntry::isManifestDataValid() - missing required key: " + key); return false; } } @@ -1606,7 +1611,7 @@ Experiments.ExperimentEntry.prototype = { for (let key in data) { if (!this.MANIFEST_OPTIONAL_FIELDS.has(key) && !this.MANIFEST_REQUIRED_FIELDS.has(key)) { - gLogger.error("ExperimentEntry::isManifestDataValid() - unknown key: " + key); + this._log.error("ExperimentEntry::isManifestDataValid() - unknown key: " + key); return false; } }