wine/gecko
0
0
Fork 0
mirror of https://gitlab.winehq.org/wine/wine-gecko.git synced 2024-09-13 09:24:08 -07:00
Code Issues Packages Projects Releases Wiki Activity

Bug 989137 - Part 2: Don't use a global logger; r=gfritzsche

Browse Source 
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
This commit is contained in:
Gregory Szorc 2014-03-28 11:20:31 -07:00
parent 6b11c6bff9
commit 788eb651cc
1 changed files with 74 additions and 69 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

143
browser/experiments/Experiments.jsm
View File

@ -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;
}
}