Bug 770418 - Improve identity logging output. r=dolske,jparsons
authorMatthew Noorenberghe <mozilla@noorenberghe.ca>
Tue, 10 Jul 2012 23:54:27 -0700
changeset 98936 c84e7d4fb37ab852fd2d5debf3cf926650cb95c6
parent 98935 aba424421b31a50670e49609cfd096eeaf7184ad
child 98937 a335f5f3e103bd5d034c9e315e4f99f302dfb9a2
push idunknown
push userunknown
push dateunknown
reviewersdolske, jparsons
bugs770418
milestone16.0a1
Bug 770418 - Improve identity logging output. r=dolske,jparsons
toolkit/identity/Identity.jsm
toolkit/identity/IdentityProvider.jsm
toolkit/identity/LogUtils.jsm
toolkit/identity/RelyingParty.jsm
toolkit/identity/Sandbox.jsm
toolkit/identity/jwcrypto.jsm
toolkit/identity/tests/unit/head_identity.js
toolkit/identity/tests/unit/test_crypto_service.js
toolkit/identity/tests/unit/test_log_utils.js
--- a/toolkit/identity/Identity.jsm
+++ b/toolkit/identity/Identity.jsm
@@ -20,20 +20,20 @@ Cu.import("resource://gre/modules/identi
 Cu.import("resource://gre/modules/identity/RelyingParty.jsm");
 Cu.import("resource://gre/modules/identity/IdentityProvider.jsm");
 
 XPCOMUtils.defineLazyModuleGetter(this,
                                   "jwcrypto",
                                   "resource://gre/modules/identity/jwcrypto.jsm");
 
 function log(...aMessageArgs) {
-  Logger.log([null].concat(aMessageArgs));
+  Logger.log.apply(Logger, ["core"].concat(aMessageArgs));
 }
 function reportError(...aMessageArgs) {
-  Logger.reportError([null].concat(aMessageArgs));
+  Logger.reportError.apply(Logger, ["core"].concat(aMessageArgs));
 }
 
 function IDService() {
   Services.obs.addObserver(this, "quit-application-granted", false);
   Services.obs.addObserver(this, "identity-auth-complete", false);
 
   this._store = IdentityStore;
   this.RP = RelyingParty;
@@ -48,17 +48,17 @@ IDService.prototype = {
       case "quit-application-granted":
         Services.obs.removeObserver(this, "quit-application-granted");
         this.shutdown();
         break;
       case "identity-auth-complete":
         if (!aSubject || !aSubject.wrappedJSObject)
           break;
         let subject = aSubject.wrappedJSObject;
-        log("NOW SELECT", aSubject.wrappedJSObject);
+        log("Auth complete:", aSubject.wrappedJSObject);
         // We have authenticated in order to provision an identity.
         // So try again.
         this.selectIdentity(subject.rpId, subject.identity);
         break;
     }
   },
 
   reset: function reset() {
--- a/toolkit/identity/IdentityProvider.jsm
+++ b/toolkit/identity/IdentityProvider.jsm
@@ -19,20 +19,20 @@ Cu.import("resource://gre/modules/identi
 const EXPORTED_SYMBOLS = ["IdentityProvider"];
 const FALLBACK_PROVIDER = "browserid.org";
 
 XPCOMUtils.defineLazyModuleGetter(this,
                                   "jwcrypto",
                                   "resource://gre/modules/identity/jwcrypto.jsm");
 
 function log(...aMessageArgs) {
-  Logger.log(["IDP"].concat(aMessageArgs));
+  Logger.log.apply(Logger, ["IDP"].concat(aMessageArgs));
 }
 function reportError(...aMessageArgs) {
-  Logger.reportError(["IDP"].concat(aMessageArgs));
+  Logger.reportError.apply(Logger, ["IDP"].concat(aMessageArgs));
 }
 
 
 function IdentityProviderService() {
   XPCOMUtils.defineLazyModuleGetter(this,
                                     "_store",
                                     "resource://gre/modules/identity/IdentityStore.jsm",
                                     "IdentityStore");
@@ -227,17 +227,17 @@ IdentityProviderService.prototype = {
       provFlow.callback(errStr);
       return;
     }
 
     // Ok generate a keypair
     jwcrypto.generateKeyPair(jwcrypto.ALGORITHMS.DS160, function gkpCb(err, kp) {
       log("in gkp callback");
       if (err) {
-        log("ERROR: genKeyPair:" + err);
+        log("ERROR: genKeyPair:", err);
         provFlow.callback(err);
         return;
       }
 
       provFlow.kp = kp;
 
       // Serialize the publicKey of the keypair and send it back to the
       // sandbox.
--- a/toolkit/identity/LogUtils.jsm
+++ b/toolkit/identity/LogUtils.jsm
@@ -37,17 +37,17 @@ IdentityLogger.prototype = {
         break;
 
       default:
         this.log("Logger observer", "Unknown topic:", aTopic);
         break;
     }
   },
 
-  _generateLogMessage: function _generateLogMessage(aPrefix, ...args) {
+  _generateLogMessage: function _generateLogMessage(aPrefix, args) {
     // create a string representation of a list of arbitrary things
     let strings = [];
 
     // XXX bug 770418 - args look like flattened array, not list of strings
 
     args.forEach(function(arg) {
       if (typeof arg === 'string') {
         strings.push(arg);
@@ -58,49 +58,46 @@ IdentityLogger.prototype = {
       } else {
         try {
           strings.push(JSON.stringify(arg, null, 2));
         } catch(err) {
           strings.push("<<something>>");
         }
       }
     });
-    return 'Identity ' + aPrefix + ': ' + strings.join(' : ');
+    return 'Identity ' + aPrefix + ': ' + strings.join(' ');
   },
 
   /**
    * log() - utility function to print a list of arbitrary things
-   * Depends on IdentityStore (bottom of this file) for _debug.
    *
    * Enable with about:config pref toolkit.identity.debug
    */
   log: function log(aPrefix, ...args) {
     if (!this._debug) {
       return;
     }
-    if (typeof this === 'undefined') {
-      for (var frame=Components.stack; frame; frame = frame.caller) {
-        dump (frame + "\n");
-      }
-    }
     let output = this._generateLogMessage(aPrefix, args);
     dump(output + "\n");
 
     // Additionally, make the output visible in the Error Console
     Services.console.logStringMessage(output);
   },
 
   /**
    * reportError() - report an error through component utils as well as
    * our log function
    */
   reportError: function reportError(aPrefix, ...aArgs) {
     let prefix = aPrefix + ' ERROR';
 
     // Report the error in the browser
     let output = this._generateLogMessage(aPrefix, aArgs);
-    Cu.reportError("Identity: " + output);
-    dump(output + "\n");
+    Cu.reportError(output);
+    dump("ERROR: " + output + "\n");
+    for (let frame = Components.stack.caller; frame; frame = frame.caller) {
+      dump(frame + "\n");
+    }
   }
 
 };
 
 let Logger = new IdentityLogger();
--- a/toolkit/identity/RelyingParty.jsm
+++ b/toolkit/identity/RelyingParty.jsm
@@ -18,20 +18,20 @@ Cu.import("resource://gre/modules/identi
 
 const EXPORTED_SYMBOLS = ["RelyingParty"];
 
 XPCOMUtils.defineLazyModuleGetter(this,
                                   "jwcrypto",
                                   "resource://gre/modules/identity/jwcrypto.jsm");
 
 function log(...aMessageArgs) {
-  Logger.log(["RP"].concat(aMessageArgs));
+  Logger.log.apply(Logger, ["RP"].concat(aMessageArgs));
 }
 function reportError(...aMessageArgs) {
-  Logger.reportError(["RP"].concat(aMessageArgs));
+  Logger.reportError.apply(Logger, ["RP"].concat(aMessageArgs));
 }
 
 function IdentityRelyingParty() {
   // The store is a singleton shared among Identity, RelyingParty, and
   // IdentityProvider.  The Identity module takes care of resetting
   // state in the _store on shutdown.
   this._store = IdentityStore;
 
--- a/toolkit/identity/Sandbox.jsm
+++ b/toolkit/identity/Sandbox.jsm
@@ -4,21 +4,24 @@
 
 "use strict";
 
 const EXPORTED_SYMBOLS = ["Sandbox"];
 
 const {classes: Cc, interfaces: Ci, utils: Cu} = Components;
 
 const XHTML_NS = "http://www.w3.org/1999/xhtml";
-const PREF_DEBUG = "toolkit.identity.debug";
 
 Cu.import("resource://gre/modules/XPCOMUtils.jsm");
 Cu.import("resource://gre/modules/Services.jsm");
 
+XPCOMUtils.defineLazyModuleGetter(this,
+                                  "Logger",
+                                  "resource://gre/modules/identity/LogUtils.jsm");
+
 /**
  * An object that represents a sandbox in an iframe loaded with aURL. The
  * callback provided to the constructor will be invoked when the sandbox is
  * ready to be used. The callback will receive this object as its only argument.
  *
  * You must call free() when you are finished with the sandbox to explicitly
  * free up all associated resources.
  *
@@ -26,18 +29,17 @@ Cu.import("resource://gre/modules/Servic
  *        (string) URL to load in the sandbox.
  *
  * @param aCallback
  *        (function) Callback to be invoked with a Sandbox, when ready.
  */
 function Sandbox(aURL, aCallback) {
   // Normalize the URL so the comparison in _makeSandboxContentLoaded works
   this._url = Services.io.newURI(aURL, null, null).spec;
-  this._debug = Services.prefs.getBoolPref(PREF_DEBUG);
-  this._log("Creating sandbox for: " + this._url);
+  this._log("Creating sandbox for:", this._url);
   this._createFrame();
   this._createSandbox(aCallback);
 }
 
 Sandbox.prototype = {
 
   /**
    * Use the outer window ID as the identifier of the sandbox.
@@ -47,28 +49,28 @@ Sandbox.prototype = {
                .getInterface(Ci.nsIDOMWindowUtils).outerWindowID;
   },
 
   /**
    * Reload the URL in the sandbox. This is useful to reuse a Sandbox (same
    * id and URL).
    */
   reload: function Sandbox_reload(aCallback) {
-    this._log("reload: " + this.id + " : " + this._url);
+    this._log("reload:", this.id, ":", this._url);
     this._createSandbox(function createdSandbox(aSandbox) {
-      this._log("reloaded sandbox id: ", aSandbox.id);
+      this._log("reloaded sandbox id:", aSandbox.id);
       aCallback(aSandbox);
     }.bind(this));
   },
 
   /**
    * Frees the sandbox and releases the iframe created to host it.
    */
   free: function Sandbox_free() {
-    this._log("free: " + this.id);
+    this._log("free:", this.id);
     this._container.removeChild(this._frame);
     this._frame = null;
     this._container = null;
     this._url = null;
   },
 
   /**
    * Creates an empty, hidden iframe and sets it to the _frame
@@ -111,18 +113,18 @@ Sandbox.prototype = {
     // Set instance properties.
     this._frame = frame;
     this._container = doc.documentElement;
   },
 
   _createSandbox: function Sandbox__createSandbox(aCallback) {
     let self = this;
     function _makeSandboxContentLoaded(event) {
-      self._log("_makeSandboxContentLoaded : " + self.id + " : "
-                + event.target.location.toString());
+      self._log("_makeSandboxContentLoaded:", self.id,
+                event.target.location.toString());
       if (event.target != self._frame.contentDocument) {
         return;
       }
       self._frame.removeEventListener(
         "DOMWindowCreated", _makeSandboxContentLoaded, true
       );
 
       aCallback(self);
@@ -143,15 +145,12 @@ Sandbox.prototype = {
       null, // referrer
       null, // postData
       null  // headers
     );
 
   },
 
   _log: function Sandbox__log(...aMessageArgs) {
-    if (!this._debug) {
-      return;
-    }
-    dump("Sandbox: " + aMessageArgs.join(" : ") + "\n");
+    Logger.log.apply(Logger, ["sandbox"].concat(aMessageArgs));
   },
 
 };
--- a/toolkit/identity/jwcrypto.jsm
+++ b/toolkit/identity/jwcrypto.jsm
@@ -11,31 +11,27 @@ const Cu = Components.utils;
 const Ci = Components.interfaces;
 const Cc = Components.classes;
 const Cr = Components.results;
 
 Cu.import("resource://gre/modules/XPCOMUtils.jsm");
 Cu.import("resource://gre/modules/Services.jsm");
 Cu.import("resource://gre/modules/identity/LogUtils.jsm");
 
-XPCOMUtils.defineLazyModuleGetter(this,
-                                  "IDLog",
-                                  "resource://gre/modules/identity/IdentityStore.jsm");
-
 XPCOMUtils.defineLazyServiceGetter(this,
                                    "IdentityCryptoService",
                                    "@mozilla.org/identity/crypto-service;1",
                                    "nsIIdentityCryptoService");
 
 const EXPORTED_SYMBOLS = ["jwcrypto"];
 
 const ALGORITHMS = { RS256: "RS256", DS160: "DS160" };
 
 function log(...aMessageArgs) {
-  Logger.log(["jwcrypto"].concat(aMessageArgs));
+  Logger.log.apply(Logger, ["jwcrypto"].concat(aMessageArgs));
 }
 
 function generateKeyPair(aAlgorithmName, aCallback) {
   log("Generate key pair; alg =", aAlgorithmName);
 
   IdentityCryptoService.generateKeyPair(aAlgorithmName, function(rv, aKeyPair) {
     if (!Components.isSuccessCode(rv)) {
       return aCallback("key generation failed");
--- a/toolkit/identity/tests/unit/head_identity.js
+++ b/toolkit/identity/tests/unit/head_identity.js
@@ -69,17 +69,17 @@ let XULAppInfoFactory = {
 let registrar = Components.manager.QueryInterface(Ci.nsIComponentRegistrar);
 registrar.registerFactory(Components.ID("{fbfae60b-64a4-44ef-a911-08ceb70b9f31}"),
                           "XULAppInfo", "@mozilla.org/xre/app-info;1",
                           XULAppInfoFactory);
 
 // The following are utility functions for Identity testing
 
 function log(...aMessageArgs) {
-  Logger.log(["test"].concat(aMessageArgs));
+  Logger.log.apply(Logger, ["test"].concat(aMessageArgs));
 }
 
 function get_idstore() {
   return IdentityStore;
 }
 
 function partial(fn) {
   let args = Array.prototype.slice.call(arguments, 1);
--- a/toolkit/identity/tests/unit/test_crypto_service.js
+++ b/toolkit/identity/tests/unit/test_crypto_service.js
@@ -15,50 +15,50 @@ const ALG_RSA = "RS256";
 
 // When the output of an operation is a
 function do_check_eq_or_slightly_less(x, y) {
   do_check_true(x >= y - (3 * 8));
 }
 
 function test_dsa() {
   idService.generateKeyPair(ALG_DSA, function (rv, keyPair) {
-    log("DSA generateKeyPair finished " + rv);
+    log("DSA generateKeyPair finished ", rv);
     do_check_true(Components.isSuccessCode(rv));
     do_check_eq(typeof keyPair.sign, "function");
     do_check_eq(keyPair.keyType, ALG_DSA);
     do_check_eq_or_slightly_less(keyPair.hexDSAGenerator.length, 1024 / 8 * 2);
     do_check_eq_or_slightly_less(keyPair.hexDSAPrime.length, 1024 / 8 * 2);
     do_check_eq_or_slightly_less(keyPair.hexDSASubPrime.length, 160 / 8 * 2);
     do_check_eq_or_slightly_less(keyPair.hexDSAPublicValue.length, 1024 / 8 * 2);
     // XXX: test that RSA parameters throw the correct error
 
     log("about to sign with DSA key");
     keyPair.sign("foo", function (rv, signature) {
-      log("DSA sign finished " + rv + " " + signature);
+      log("DSA sign finished ", rv, signature);
       do_check_true(Components.isSuccessCode(rv));
       do_check_true(signature.length > 1);
       // TODO: verify the signature with the public key
       run_next_test();
     });
   });
 }
 
 function test_rsa() {
   idService.generateKeyPair(ALG_RSA, function (rv, keyPair) {
-    log("RSA generateKeyPair finished " + rv);
+    log("RSA generateKeyPair finished ", rv);
     do_check_true(Components.isSuccessCode(rv));
     do_check_eq(typeof keyPair.sign, "function");
     do_check_eq(keyPair.keyType, ALG_RSA);
     do_check_eq_or_slightly_less(keyPair.hexRSAPublicKeyModulus.length,
                                  2048 / 8);
     do_check_true(keyPair.hexRSAPublicKeyExponent.length > 1);
 
     log("about to sign with RSA key");
     keyPair.sign("foo", function (rv, signature) {
-      log("RSA sign finished " + rv + " " + signature);
+      log("RSA sign finished ", rv, signature);
       do_check_true(Components.isSuccessCode(rv));
       do_check_true(signature.length > 1);
       run_next_test();
     });
   });
 }
 
 add_test(test_dsa);
--- a/toolkit/identity/tests/unit/test_log_utils.js
+++ b/toolkit/identity/tests/unit/test_log_utils.js
@@ -12,17 +12,16 @@ function toggle_debug() {
     Services.prefs.addObserver('toolkit.identity.debug', this, false);
   }
   Wrapper.prototype = {
     QueryInterface: XPCOMUtils.generateQI([ci.nsISupports, Ci.nsIObserver]),
 
     observe: function observe(aSubject, aTopic, aData) {
       if (aTopic === "nsPref:changed") {
         // race condition?
-dump("WOOT! it changed");
         do_check_eq(Logger._debug, true);
         do_test_finished();
         run_next_test();
       }
     }
   };
 
   var wrapper = new Wrapper();
@@ -30,17 +29,17 @@ dump("WOOT! it changed");
 }
 
 // test that things don't break
 
 function logAlias(...args) {
   Logger.log.call(["log alias"].concat(args));
 }
 function reportErrorAlias(...args) {
-  Loggerl.reportError.call(["report error alias"].concat(args));
+  Logger.reportError.call(["report error alias"].concat(args));
 }
 
 function test_log() {
   Logger.log("log test", "I like pie");
   do_test_finished();
   run_next_test();
 }