Bug 1419102 - Add proper logging. r=Mossop draft
authorFelipe Gomes <felipc@gmail.com>
Fri, 19 Jan 2018 12:49:11 -0200
changeset 722688 6f86932d308f1fdf08982f1c611aefdca81db6d1
parent 722687 8e36f77b1c8fd2cc3b4889ab978f45de6b7afde8
child 722689 8c65f8bd586dfb3b7ee98e6fbecdc14248eec68d
push id96199
push userfelipc@gmail.com
push dateFri, 19 Jan 2018 15:05:44 +0000
reviewersMossop
bugs1419102
milestone59.0a1
Bug 1419102 - Add proper logging. r=Mossop MozReview-Commit-ID: DFAJYReNfmv
browser/components/enterprisepolicies/EnterprisePolicies.js
browser/components/enterprisepolicies/EnterprisePoliciesContent.js
browser/components/enterprisepolicies/Policies.jsm
browser/components/enterprisepolicies/PoliciesValidator.jsm
--- a/browser/components/enterprisepolicies/EnterprisePolicies.js
+++ b/browser/components/enterprisepolicies/EnterprisePolicies.js
@@ -13,34 +13,41 @@ Cu.import("resource://gre/modules/AppCon
 Cu.import("resource://gre/modules/osfile.jsm");
 
 XPCOMUtils.defineLazyModuleGetters(this, {
   NetUtil: "resource://gre/modules/NetUtil.jsm",
   Policies: "resource:///modules/policies/Policies.jsm",
   PoliciesValidator: "resource:///modules/policies/PoliciesValidator.jsm",
 });
 
-function LOG(s) {
-  Services.console.logStringMessage("$ POLICIES $: " + s + "\n");
-  dump("% POLICIES %: " + s + "\n");
-}
-
 // This is the file that will be searched for in the
 // ${InstallDir}/distribution folder.
 const POLICIES_FILENAME = "policies.json";
 
 // For easy testing, modify the helpers/sample.json file,
 // and set PREF_ALTERNATE_PATH in firefox.js as:
 // /your/repo/browser/components/enterprisepolicies/helpers/sample.json
 const PREF_ALTERNATE_PATH     = "browser.policies.alternatePath";
 
 // This pref is meant to be temporary: it will only be used while we're
 // testing this feature without rolling it out officially. When the
 // policy engine is released, this pref should be removed.
 const PREF_ENABLED            = "browser.policies.enabled";
+const PREF_LOGLEVEL           = "browser.policies.loglevel";
+
+XPCOMUtils.defineLazyGetter(this, "log", () => {
+  let { ConsoleAPI } = Cu.import("resource://gre/modules/Console.jsm", {});
+  return new ConsoleAPI({
+    prefix: "Enterprise Policies",
+    // tip: set maxLogLevel to "debug" and use log.debug() to create detailed
+    // messages during development. See LOG_LEVELS in Console.jsm for details.
+    maxLogLevel: "error",
+    maxLogLevelPref: PREF_LOGLEVEL,
+  });
+});
 
 // File mode constants
 const MODE_RDONLY   = 0x01;
 const PERMS_FILE    = 0o644;
 
 // ==== Start XPCOM Boilerplate ==== \\
 
 // Factory object
@@ -53,18 +60,16 @@ const EnterprisePoliciesFactory = {
       this._instance = new EnterprisePoliciesManager() : this._instance;
   }
 };
 
 // ==== End XPCOM Boilerplate ==== //
 
 // Constructor
 function EnterprisePoliciesManager() {
-  LOG("STARTING CONSTRUCTOR");
-
   Services.obs.addObserver(this, "profile-after-change", true);
   Services.obs.addObserver(this, "final-ui-startup", true);
   Services.obs.addObserver(this, "sessionstore-windows-restored", true);
   Services.obs.addObserver(this, "EnterprisePolicies:Restart", true);
 }
 
 EnterprisePoliciesManager.prototype = {
   // for XPCOM
@@ -103,26 +108,26 @@ EnterprisePoliciesManager.prototype = {
     let { schema } = Cu.import("resource:///modules/policies/schema.jsm", {});
     let json = this._file.json;
 
     for (let policyName of Object.keys(json.policies)) {
       let policySchema = schema.properties[policyName];
       let policyParameters = json.policies[policyName];
 
       if (!policySchema) {
-        LOG("This policy is not defined in the schema.");
+        log.error(`Unknown policy: ${policyName}`);
         continue;
       }
 
       let [parametersAreValid, parsedParameters] =
         PoliciesValidator.validateAndParseParameters(policyParameters,
                                                      policySchema);
 
       if (!parametersAreValid) {
-        LOG(`Invalid parameters specified for ${policyName}.`);
+        log.error(`Invalid parameters specified for ${policyName}.`);
         continue;
       }
 
       let policyImpl = Policies[policyName];
 
       for (let timing of Object.keys(this._callbacks)) {
         let policyCallback = policyImpl["on" + timing];
         if (policyCallback) {
@@ -147,25 +152,26 @@ EnterprisePoliciesManager.prototype = {
   },
 
   _runPoliciesCallbacks(timing) {
     let callbacks = this._callbacks[timing];
     while (callbacks.length > 0) {
       let callback = callbacks.shift();
       try {
         callback();
-      } catch (ex) {}
+      } catch (ex) {
+        log.error("Error running ", callback, `for ${timing}:`, ex);
+      }
     }
   },
 
   _restart() {
     if (!Cu.isInAutomation) {
       return;
     }
-    LOG("Restarting");
 
     DisallowedFeatures = {};
 
     this._status = Ci.nsIEnterprisePolicies.UNINITIALIZED;
     for (let timing of Object.keys(this._callbacks)) {
       this._callbacks[timing] = [];
     }
     delete Services.ppmm.initialProcessData.policies;
@@ -220,17 +226,16 @@ EnterprisePoliciesManager.prototype = {
 
     // NOTE: For optimization purposes, only features marked as needed
     // on content process will be passed onto the child processes.
     if (neededOnContentProcess) {
       Services.ppmm.initialProcessData.policies
                                       .disallowedFeatures.push(feature);
 
       if (Services.ppmm.childCount > 1) {
-        LOG("sending disallow feature for " + feature);
         // If there has been a content process already initialized, let's
         // broadcast the newly disallowed feature.
         Services.ppmm.broadcastAsyncMessage(
           "EnterprisePolicies:DisallowFeature", {feature}
         );
       }
     }
   },
@@ -308,20 +313,20 @@ JSONFileReader.prototype = {
 
       let bytes = NetUtil.readInputStream(inputStream, inputStream.available());
       this._data.json = JSON.parse(new TextDecoder().decode(bytes));
     } catch (ex) {
       if (ex instanceof Components.Exception &&
           ex.result == Cr.NS_ERROR_FILE_NOT_FOUND) {
         this._data.exists = false;
       } else if (ex instanceof SyntaxError) {
-        LOG("Error parsing JSON file");
+        log.error("Error parsing JSON file");
         this._data.failed = true;
       } else {
-        LOG("Error reading file");
+        log.error("Error reading file");
         this._data.failed = true;
       }
     } finally {
       inputStream.close();
     }
   }
 };
 
--- a/browser/components/enterprisepolicies/EnterprisePoliciesContent.js
+++ b/browser/components/enterprisepolicies/EnterprisePoliciesContent.js
@@ -5,20 +5,29 @@
 const Ci = Components.interfaces;
 const Cc = Components.classes;
 const Cr = Components.results;
 const Cu = Components.utils;
 
 Cu.import("resource://gre/modules/XPCOMUtils.jsm");
 Cu.import("resource://gre/modules/Services.jsm");
 
-function LOG(s) {
-  Services.console.logStringMessage("$ POLICIES CHILD $: " + s + "\n");
-  dump("% POLICIES CHILD %: " + s + "\n");
-}
+const PREF_LOGLEVEL           = "browser.policies.loglevel";
+
+XPCOMUtils.defineLazyGetter(this, "log", () => {
+  let { ConsoleAPI } = Cu.import("resource://gre/modules/Console.jsm", {});
+  return new ConsoleAPI({
+    prefix: "Enterprise Policies Child",
+    // tip: set maxLogLevel to "debug" and use log.debug() to create detailed
+    // messages during development. See LOG_LEVELS in Console.jsm for details.
+    maxLogLevel: "error",
+    maxLogLevelPref: PREF_LOGLEVEL,
+  });
+});
+
 
 // ==== Start XPCOM Boilerplate ==== \\
 
 // Factory object
 const EnterprisePoliciesFactory = {
   _instance: null,
   createInstance: function BGSF_createInstance(outer, iid) {
     if (outer != null)
@@ -27,17 +36,16 @@ const EnterprisePoliciesFactory = {
       this._instance = new EnterprisePoliciesManagerContent() : this._instance;
   }
 };
 
 // ==== End XPCOM Boilerplate ==== //
 
 
 function EnterprisePoliciesManagerContent() {
-  LOG("STARTING CONSTRUCTOR");
   let policies = Services.cpmm.initialProcessData.policies;
   if (policies) {
     this._status = policies.status;
     // make a copy of the array so that we can keep adding to it
     // in a way that is not confusing.
     this._disallowedFeatures = policies.disallowedFeatures.slice();
   }
 
--- a/browser/components/enterprisepolicies/Policies.jsm
+++ b/browser/components/enterprisepolicies/Policies.jsm
@@ -7,42 +7,50 @@
 const Ci = Components.interfaces;
 const Cc = Components.classes;
 const Cr = Components.results;
 const Cu = Components.utils;
 
 Cu.import("resource://gre/modules/XPCOMUtils.jsm");
 Cu.import("resource://gre/modules/Services.jsm");
 
-function LOG(s) {
-  Services.console.logStringMessage("$ POLICIES CHILD $: " + s + "\n");
-  dump("% POLICIES.JSM %: " + s + "\n");
-}
+const PREF_LOGLEVEL           = "browser.policies.loglevel";
+
+XPCOMUtils.defineLazyGetter(this, "log", () => {
+  let { ConsoleAPI } = Cu.import("resource://gre/modules/Console.jsm", {});
+  return new ConsoleAPI({
+    prefix: "Policies.jsm",
+    // tip: set maxLogLevel to "debug" and use log.debug() to create detailed
+    // messages during development. See LOG_LEVELS in Console.jsm for details.
+    maxLogLevel: "error",
+    maxLogLevelPref: PREF_LOGLEVEL,
+  });
+});
 
 this.EXPORTED_SYMBOLS = ["Policies"];
 
 this.Policies = {
   "block_about_config": {
     onBeforeUIStartup(manager, param) {
       if (param == true) {
-        LOG("BLOCKING ABOUT:CONFIG");
+        log.debug("BLOCKING ABOUT:CONFIG");
         manager.disallowFeature("about:config", true);
       }
     }
   },
 
   "block_devtools": {
     onProfileAfterChange(manager, param) {
       if (param == true) {
         manager.disallowFeature("devtools");
       }
     }
   },
 
   "bookmarks_on_menu": {
     onProfileAfterChange(manager, param) {
-      LOG("Bookmarks to add: ");
+      log.debug("Bookmarks to add: ");
       for (let bookmark of param) {
-        LOG("  -> " + bookmark.spec);
+        log.debug("  -> " + bookmark.spec);
       }
     }
   },
 };
--- a/browser/components/enterprisepolicies/PoliciesValidator.jsm
+++ b/browser/components/enterprisepolicies/PoliciesValidator.jsm
@@ -7,20 +7,28 @@
 const Ci = Components.interfaces;
 const Cc = Components.classes;
 const Cr = Components.results;
 const Cu = Components.utils;
 
 Cu.import("resource://gre/modules/XPCOMUtils.jsm");
 Cu.import("resource://gre/modules/Services.jsm");
 
-function LOG(s) {
-  Services.console.logStringMessage("$ POLICIES CHILD $: " + s + "\n");
-  dump("% POLICIES.JSM %: " + s + "\n");
-}
+const PREF_LOGLEVEL           = "browser.policies.loglevel";
+
+XPCOMUtils.defineLazyGetter(this, "log", () => {
+  let { ConsoleAPI } = Cu.import("resource://gre/modules/Console.jsm", {});
+  return new ConsoleAPI({
+    prefix: "PoliciesValidator.jsm",
+    // tip: set maxLogLevel to "debug" and use log.debug() to create detailed
+    // messages during development. See LOG_LEVELS in Console.jsm for details.
+    maxLogLevel: "error",
+    maxLogLevelPref: PREF_LOGLEVEL,
+  });
+});
 
 this.EXPORTED_SYMBOLS = ["PoliciesValidator"];
 
 this.PoliciesValidator = {
   validateAndParseParameters(param, properties) {
     return validateAndParseParamRecursive(param, properties);
   }
 };
@@ -28,53 +36,54 @@ this.PoliciesValidator = {
 function validateAndParseParamRecursive(param, properties) {
   if (properties.enum) {
     if (properties.enum.includes(param)) {
       return [true, param];
     }
     return [false, null];
   }
 
-  LOG(`checking @${param}@ for type ${properties.type}`);
+  log.debug(`checking @${param}@ for type ${properties.type}`);
   switch (properties.type) {
     case "boolean":
     case "number":
     case "integer":
     case "string":
     case "URL":
     case "origin":
       return validateAndParseSimpleParam(param, properties.type);
 
     case "array":
       if (!Array.isArray(param)) {
-        LOG("bail early");
+        log.error("Array expected but not received");
         return [false, null];
       }
 
       let parsedArray = [];
       for (let item of param) {
-        LOG(`in array, checking @${item}@ for type ${properties.items.type}`);
+        log.debug(`in array, checking @${item}@ for type ${properties.items.type}`);
         let [valid, parsedValue] = validateAndParseParamRecursive(item, properties.items);
         if (!valid) {
           return [false, null];
         }
 
         parsedArray.push(parsedValue);
       }
 
       return [true, parsedArray];
 
     case "object": {
       if (typeof(param) != "object") {
+        log.error("Object expected but not received");
         return [false, null];
       }
 
       let parsedObj = {};
       for (let property of Object.keys(properties.properties)) {
-        LOG(`in object, for property ${property} checking @${param[property]}@ for type ${properties.properties[property].type}`);
+        log.debug(`in object, for property ${property} checking @${param[property]}@ for type ${properties.properties[property].type}`);
         let [valid, parsedValue] = validateAndParseParamRecursive(param[property], properties.properties[property]);
         if (!valid) {
           return [false, null];
         }
 
         parsedObj[property] = parsedValue;
       }