Bug 966674: #3 Add parameter substitution in log messages; r=gps,rnewman
authorIrving Reid <irving@mozilla.com>
Tue, 29 Apr 2014 10:09:29 -0400
changeset 181230 b106aad655ad43d334e9d7593a57511918975f47
parent 181229 ea70694f55c81a214f6208a79700c69f496057c6
child 181231 16ad8026a23ae150ef2962d56202511e9f0073d2
push id272
push userpvanderbeken@mozilla.com
push dateMon, 05 May 2014 16:31:18 +0000
reviewersgps, rnewman
bugs966674
milestone32.0a1
Bug 966674: #3 Add parameter substitution in log messages; r=gps,rnewman
services/metrics/tests/xpcshell/test_metrics_provider_manager.js
toolkit/modules/Log.jsm
toolkit/modules/tests/xpcshell/test_Log.js
--- a/services/metrics/tests/xpcshell/test_metrics_provider_manager.js
+++ b/services/metrics/tests/xpcshell/test_metrics_provider_manager.js
@@ -291,18 +291,19 @@ add_task(function test_category_manager_
     deferred.resolve(msg);
   };
 
   yield manager.registerProvidersFromCategoryManager("registration-errors");
   do_check_eq(manager.providers.length, 0);
   do_check_eq(errorCount, 1);
 
   let msg = yield deferred.promise;
-  do_check_true(msg.contains("Provider error: DummyThrowOnInitProvider: " +
-                             "Error registering provider from category manager: Dummy Error"));
+  do_check_true(msg.contains("Provider error: DummyThrowOnInitProvider: "
+                             + "Error registering provider from category manager: "
+                             + "Error: Dummy Error"));
 
   yield storage.close();
 });
 
 add_task(function test_pull_only_registration_error() {
   let storage = yield Metrics.Storage(REGISTRATION_ERRORS_DB);
   let manager = new Metrics.ProviderManager(storage);
 
@@ -317,17 +318,17 @@ add_task(function test_pull_only_registr
   yield manager.registerProviderFromType(DummyPullOnlyThrowsOnInitProvider);
   do_check_eq(errorCount, 0);
 
   yield manager.ensurePullOnlyProvidersRegistered();
   do_check_eq(errorCount, 1);
 
   let msg = yield deferred.promise;
   do_check_true(msg.contains("Provider error: DummyPullOnlyThrowsOnInitProvider: " +
-                             "Error registering pull-only provider: Dummy Error"));
+                             "Error registering pull-only provider: Error: Dummy Error"));
 
   yield storage.close();
 });
 
 add_task(function test_error_during_shutdown() {
   let storage = yield Metrics.Storage(REGISTRATION_ERRORS_DB);
   let manager = new Metrics.ProviderManager(storage);
 
@@ -345,12 +346,12 @@ add_task(function test_error_during_shut
   do_check_eq(manager.providers.length, 1);
 
   yield manager.ensurePullOnlyProvidersRegistered();
   do_check_eq(errorCount, 0);
   yield manager.ensurePullOnlyProvidersUnregistered();
   do_check_eq(errorCount, 1);
   let msg = yield deferred.promise;
   do_check_true(msg.contains("Provider error: DummyThrowOnShutdownProvider: " +
-                             "Error when shutting down provider: Dummy shutdown error"));
+                             "Error when shutting down provider: Error: Dummy shutdown error"));
 
   yield storage.close();
 });
--- a/toolkit/modules/Log.jsm
+++ b/toolkit/modules/Log.jsm
@@ -15,16 +15,26 @@ const ONE_MEGABYTE = 1024 * ONE_KILOBYTE
 const STREAM_SEGMENT_SIZE = 4096;
 const PR_UINT32_MAX = 0xffffffff;
 
 Cu.import("resource://gre/modules/XPCOMUtils.jsm");
 XPCOMUtils.defineLazyModuleGetter(this, "OS",
                                   "resource://gre/modules/osfile.jsm");
 XPCOMUtils.defineLazyModuleGetter(this, "Task",
                                   "resource://gre/modules/Task.jsm");
+const INTERNAL_FIELDS = new Set(["_level", "_message", "_time", "_namespace"]);
+
+
+/*
+ * Dump a message everywhere we can if we have a failure.
+ */
+function dumpError(text) {
+  dump(text + "\n");
+  Cu.reportError(text);
+}
 
 this.Log = {
   Level: {
     Fatal:  70,
     Error:  60,
     Warn:   50,
     Info:   40,
     Config: 30,
@@ -75,16 +85,17 @@ this.Log = {
   Appender: Appender,
   DumpAppender: DumpAppender,
   ConsoleAppender: ConsoleAppender,
   StorageStreamAppender: StorageStreamAppender,
 
   FileAppender: FileAppender,
   BoundedFileAppender: BoundedFileAppender,
 
+  ParameterFormatter: ParameterFormatter,
   // Logging helper:
   // let logger = Log.repository.getLogger("foo");
   // logger.info(Log.enumerateInterfaces(someObject).join(","));
   enumerateInterfaces: function Log_enumerateInterfaces(aObject) {
     let interfaces = [];
 
     for (i in Ci) {
       try {
@@ -95,24 +106,23 @@ this.Log = {
     }
 
     return interfaces;
   },
 
   // Logging helper:
   // let logger = Log.repository.getLogger("foo");
   // logger.info(Log.enumerateProperties(someObject).join(","));
-  enumerateProperties: function Log_enumerateProps(aObject,
-                                                       aExcludeComplexTypes) {
+  enumerateProperties: function (aObject, aExcludeComplexTypes) {
     let properties = [];
 
     for (p in aObject) {
       try {
         if (aExcludeComplexTypes &&
-            (typeof aObject[p] == "object" || typeof aObject[p] == "function"))
+            (typeof(aObject[p]) == "object" || typeof(aObject[p]) == "function"))
           continue;
         properties.push(p + " = " + aObject[p]);
       }
       catch(ex) {
         properties.push(p + " = " + ex);
       }
     }
 
@@ -129,17 +139,17 @@ this.Log = {
       if (e.columnNumber) {
         result += ":" + e.columnNumber;
       }
       result += ")";
     }
     return result + " " + Log.stackTrace(e);
   },
 
-  // This is for back compatibility with toolkit/services/utils.js; we duplicate
+  // This is for back compatibility with services/common/utils.js; we duplicate
   // some of the logic in ParameterFormatter
   exceptionStr: function exceptionStr(e) {
     if (!e) {
       return "" + e;
     }
     if (e instanceof Ci.nsIException) {
       return e.toString() + " " + Log.stackTrace(e);
     }
@@ -194,18 +204,31 @@ this.Log = {
 
 /*
  * LogMessage
  * Encapsulates a single log event's data
  */
 function LogMessage(loggerName, level, message, params) {
   this.loggerName = loggerName;
   this.level = level;
-  this.message = message;
-  this.params = params;
+  /*
+   * Special case to handle "log./level/(object)", for example logging a caught exception
+   * without providing text or params like: catch(e) { logger.warn(e) }
+   * Treating this as an empty text with the object in the 'params' field causes the
+   * object to be formatted properly by BasicFormatter.
+   */
+  if (!params && message && (typeof(message) == "object") &&
+      (typeof(message.valueOf()) != "string")) {
+    this.message = null;
+    this.params = message;
+  } else {
+    // If the message text is empty, or a string, or a String object, normal handling
+    this.message = message;
+    this.params = params;
+  }
 
   // The _structured field will correspond to whether this message is to
   // be interpreted as a structured message.
   this._structured = this.params && this.params.action;
   this.time = Date.now();
 }
 LogMessage.prototype = {
   get levelDesc() {
@@ -244,17 +267,17 @@ Logger.prototype = {
   },
 
   _level: null,
   get level() {
     if (this._level != null)
       return this._level;
     if (this.parent)
       return this.parent.level;
-    dump("Log warning: root logger configuration error: no level defined\n");
+    dumpError("Log warning: root logger configuration error: no level defined");
     return Log.Level.All;
   },
   set level(level) {
     this._level = level;
   },
 
   _parent: null,
   get parent() this._parent,
@@ -312,37 +335,37 @@ Logger.prototype = {
    *
    * @param action
    *        (string) A message action, one of a set of actions known to the
    *          log consumer.
    * @param params
    *        (object) Parameters to be included in the message.
    *          If _level is included as a key and the corresponding value
    *          is a number or known level name, the message will be logged
-   *          at the indicated level.
+   *          at the indicated level. If _message is included as a key, the
+   *          value is used as the descriptive text for the message.
    */
   logStructured: function (action, params) {
     if (!action) {
       throw "An action is required when logging a structured message.";
     }
     if (!params) {
       return this.log(this.level, undefined, {"action": action});
     }
-    if (typeof params != "object") {
+    if (typeof(params) != "object") {
       throw "The params argument is required to be an object.";
     }
 
     let level = params._level;
     if (level) {
       let ulevel = level.toUpperCase();
       if (ulevel in Log.Level.Numbers) {
         level = Log.Level.Numbers[ulevel];
       }
-    }
-    else {
+    } else {
       level = this.level;
     }
 
     params.action = action;
     this.log(level, params._message, params);
   },
 
   log: function (level, string, params) {
@@ -500,27 +523,79 @@ LoggerRepository.prototype = {
 // Abstract formatter
 function Formatter() {}
 Formatter.prototype = {
   format: function Formatter_format(message) {}
 };
 
 // Basic formatter that doesn't do anything fancy.
 function BasicFormatter(dateFormat) {
-  if (dateFormat)
+  if (dateFormat) {
     this.dateFormat = dateFormat;
+  }
+  this.parameterFormatter = new ParameterFormatter();
 }
 BasicFormatter.prototype = {
   __proto__: Formatter.prototype,
 
+  /**
+   * Format the text of a message with optional parameters.
+   * If the text contains ${identifier}, replace that with
+   * the value of params[identifier]; if ${}, replace that with
+   * the entire params object. If no params have been substituted
+   * into the text, format the entire object and append that
+   * to the message.
+   */
+  formatText: function (message) {
+    let params = message.params;
+    if (!params) {
+      return message.message || "";
+    }
+    // Defensive handling of non-object params
+    // We could add a special case for NSRESULT values here...
+    let pIsObject = (typeof(params) == 'object' || typeof(params) == 'function');
+
+    // if we have params, try and find substitutions.
+    if (message.params && this.parameterFormatter) {
+      // have we successfully substituted any parameters into the message?
+      // in the log message
+      let subDone = false;
+      let regex = /\$\{(\S*)\}/g;
+      let textParts = [];
+      if (message.message) {
+        textParts.push(message.message.replace(regex, (_, sub) => {
+          // ${foo} means use the params['foo']
+          if (sub) {
+            if (pIsObject && sub in message.params) {
+              subDone = true;
+              return this.parameterFormatter.format(message.params[sub]);
+            }
+            return '${' + sub + '}';
+          }
+          // ${} means use the entire params object.
+          subDone = true;
+          return this.parameterFormatter.format(message.params);
+        }));
+      }
+      if (!subDone) {
+        // There were no substitutions in the text, so format the entire params object
+        let rest = this.parameterFormatter.format(message.params);
+        if (rest !== null && rest != "{}") {
+          textParts.push(rest);
+        }
+      }
+      return textParts.join(': ');
+    }
+  },
+
   format: function BF_format(message) {
     return message.time + "\t" +
       message.loggerName + "\t" +
       message.levelDesc + "\t" +
-      message.message;
+      this.formatText(message);
   }
 };
 
 /**
  * A formatter that only formats the string message component.
  */
 function MessageOnlyFormatter() {
 }
@@ -557,16 +632,77 @@ StructuredFormatter.prototype = {
     if (!output._message && logMessage.message) {
       output._message = logMessage.message;
     }
 
     return JSON.stringify(output);
   }
 }
 
+/**
+ * Test an object to see if it is a Mozilla JS Error.
+ */
+function isError(aObj) {
+  return (aObj && typeof(aObj) == 'object' && "name" in aObj && "message" in aObj &&
+          "fileName" in aObj && "lineNumber" in aObj && "stack" in aObj);
+};
+
+/*
+ * Parameter Formatters
+ * These massage an object used as a parameter for a LogMessage into
+ * a string representation of the object.
+ */
+
+function ParameterFormatter() {
+  this._name = "ParameterFormatter"
+}
+ParameterFormatter.prototype = {
+  format: function(ob) {
+    try {
+      if (ob === undefined) {
+        return "undefined";
+      }
+      if (ob === null) {
+        return "null";
+      }
+      // Pass through primitive types and objects that unbox to primitive types.
+      if ((typeof(ob) != "object" || typeof(ob.valueOf()) != "object") &&
+          typeof(ob) != "function") {
+        return ob;
+      }
+      if (ob instanceof Ci.nsIException) {
+        return ob.toString() + " " + Log.stackTrace(ob);
+      }
+      else if (isError(ob)) {
+        return Log._formatError(ob);
+      }
+      // Just JSONify it. Filter out our internal fields and those the caller has
+      // already handled.
+      return JSON.stringify(ob, (key, val) => {
+        if (INTERNAL_FIELDS.has(key)) {
+          return undefined;
+        }
+        return val;
+      });
+    }
+    catch (e) {
+      dumpError("Exception trying to format object for log message: " + Log.exceptionStr(e));
+    }
+    // Fancy formatting failed. Just toSource() it - but even this may fail!
+    try {
+      return ob.toSource();
+    } catch (_) { }
+    try {
+      return "" + ob;
+    } catch (_) {
+      return "[object]"
+    }
+  }
+}
+
 /*
  * Appenders
  * These can be attached to Loggers to log to different places
  * Simply subclass and override doAppend to implement a new one
  */
 
 function Appender(formatter) {
   this._name = "Appender";
--- a/toolkit/modules/tests/xpcshell/test_Log.js
+++ b/toolkit/modules/tests/xpcshell/test_Log.js
@@ -27,35 +27,33 @@ MockAppender.prototype = {
     this.messages.push(message);
   }
 };
 
 function run_test() {
   run_next_test();
 }
 
-add_test(function test_Logger() {
+add_task(function test_Logger() {
   let log = Log.repository.getLogger("test.logger");
   let appender = new MockAppender(new Log.BasicFormatter());
 
   log.level = Log.Level.Debug;
   appender.level = Log.Level.Info;
   log.addAppender(appender);
   log.info("info test");
   log.debug("this should be logged but not appended.");
 
   do_check_eq(appender.messages.length, 1);
 
   let msgRe = /\d+\ttest.logger\t\INFO\tinfo test/;
   do_check_true(msgRe.test(appender.messages[0]));
-
-  run_next_test();
 });
 
-add_test(function test_Logger_parent() {
+add_task(function test_Logger_parent() {
   // Check whether parenting is correct
   let grandparentLog = Log.repository.getLogger("grandparent");
   let childLog = Log.repository.getLogger("grandparent.parent.child");
   do_check_eq(childLog.parent.name, "grandparent");
 
   let parentLog = Log.repository.getLogger("grandparent.parent");
   do_check_eq(childLog.parent.name, "grandparent.parent");
 
@@ -63,18 +61,16 @@ add_test(function test_Logger_parent() {
   let gpAppender = new MockAppender(new Log.BasicFormatter());
   gpAppender.level = Log.Level.Info;
   grandparentLog.addAppender(gpAppender);
   childLog.info("child info test");
   Log.repository.rootLogger.info("this shouldn't show up in gpAppender");
 
   do_check_eq(gpAppender.messages.length, 1);
   do_check_true(gpAppender.messages[0].indexOf("child info test") > 0);
-
-  run_next_test();
 });
 
 add_test(function test_LoggerWithMessagePrefix() {
   let log = Log.repository.getLogger("test.logger.prefix");
   let appender = new MockAppender(new Log.MessageOnlyFormatter());
   log.addAppender(appender);
 
   let prefixed = Log.repository.getLoggerWithMessagePrefix(
@@ -87,20 +83,22 @@ add_test(function test_LoggerWithMessage
   Assert.deepEqual(appender.messages, [
     "no prefix",
     "prefix: with prefix",
   ], "Prefix logger works.");
 
   run_next_test();
 });
 
-// A utility method for checking object equivalence.
-// Fields with a reqular expression value in expected will be tested
-// against the corresponding value in actual. Otherwise objects
-// are expected to have the same keys and equal values.
+/*
+ * A utility method for checking object equivalence.
+ * Fields with a reqular expression value in expected will be tested
+ * against the corresponding value in actual. Otherwise objects
+ * are expected to have the same keys and equal values.
+ */
 function checkObjects(expected, actual) {
   do_check_true(expected instanceof Object);
   do_check_true(actual instanceof Object);
   for (let key in expected) {
     do_check_neq(actual[key], undefined);
     if (expected[key] instanceof RegExp) {
       do_check_true(expected[key].test(actual[key].toString()));
     } else {
@@ -112,17 +110,17 @@ function checkObjects(expected, actual) 
     }
   }
 
   for (let key in actual) {
     do_check_neq(expected[key], undefined);
   }
 }
 
-add_test(function test_StructuredLogCommands() {
+add_task(function test_StructuredLogCommands() {
   let appender = new MockAppender(new Log.StructuredFormatter());
   let logger = Log.repository.getLogger("test.StructuredOutput");
   logger.addAppender(appender);
   logger.level = Log.Level.Info;
 
   logger.logStructured("test_message", {_message: "message string one"});
   logger.logStructured("test_message", {_message: "message string two",
                                         _level: "ERROR",
@@ -190,21 +188,19 @@ add_test(function test_StructuredLogComm
   logger.addAppender(appender);
   logger.level = Log.Level.All;
   logger.info("message string one", {action: "test_message"});
   logger.error("message string two", {action: "test_message",
                                       source_file: "test_Log.js"});
 
   checkObjects(messageOne, JSON.parse(appender.messages[0]));
   checkObjects(messageTwo, JSON.parse(appender.messages[1]));
-
-  run_next_test();
 });
 
-add_test(function test_StorageStreamAppender() {
+add_task(function test_StorageStreamAppender() {
   let appender = new Log.StorageStreamAppender(testFormatter);
   do_check_eq(appender.getInputStream(), null);
 
   // Log to the storage stream and verify the log was written and can be
   // read back.
   let logger = Log.repository.getLogger("test.StorageStreamAppender");
   logger.addAppender(appender);
   logger.info("OHAI");
@@ -222,18 +218,16 @@ add_test(function test_StorageStreamAppe
   // Reset the appender and log some more.
   appender.reset();
   do_check_eq(appender.getInputStream(), null);
   logger.debug("wut?!?");
   inputStream = appender.getInputStream();
   data = NetUtil.readInputStreamToString(inputStream,
                                          inputStream.available());
   do_check_eq(data, "test.StorageStreamAppender\tDEBUG\twut?!?\n");
-
-  run_next_test();
 });
 
 function fileContents(path) {
   let decoder = new TextDecoder();
   return OS.File.read(path).then(array => {
     return decoder.decode(array);
   });
 }
@@ -330,8 +324,249 @@ add_task(function test_BoundedFileAppend
   yield appender._lastWritePromise;
 
   do_check_eq((yield fileContents(path)),
               "test.BoundedFileAppender\tINFO\tTHREE\n" +
               "test.BoundedFileAppender\tINFO\tFOUR\n");
 
 });
 
+/*
+ * Test parameter formatting.
+ */
+add_task(function log_message_with_params() {
+  let formatter = new Log.BasicFormatter();
+
+  function formatMessage(text, params) {
+    let full = formatter.format(new Log.LogMessage("test.logger", Log.Level.Warn, text, params));
+    return full.split("\t")[3];
+  }
+
+  // Strings are substituted directly.
+  do_check_eq(formatMessage("String is ${foo}", {foo: "bar"}),
+              "String is bar");
+
+  // Numbers are substituted.
+  do_check_eq(formatMessage("Number is ${number}", {number: 47}),
+              "Number is 47")
+
+  // The entire params object is JSON-formatted and substituted.
+  do_check_eq(formatMessage("Object is ${}", {foo: "bar"}),
+              'Object is {"foo":"bar"}');
+
+  // An object nested inside params is JSON-formatted and substituted.
+  do_check_eq(formatMessage("Sub object is ${sub}", {sub: {foo: "bar"}}),
+                'Sub object is {"foo":"bar"}');
+
+  // The substitution field is missing from params. Leave the placeholder behind
+  // to make the mistake obvious.
+  do_check_eq(formatMessage("Missing object is ${missing}", {}),
+              'Missing object is ${missing}');
+
+  // Make sure we don't treat the parameter name 'false' as a falsey value.
+  do_check_eq(formatMessage("False is ${false}", {false: true}),
+              'False is true');
+
+  // If an object has a .toJSON method, the formatter uses it.
+  let ob = function() {};
+  ob.toJSON = function() {return {sneaky: "value"}};
+  do_check_eq(formatMessage("JSON is ${sub}", {sub: ob}),
+              'JSON is {"sneaky":"value"}');
+
+  // Fall back to .toSource() if JSON.stringify() fails on an object.
+  let ob = function() {};
+  ob.toJSON = function() {throw "oh noes JSON"};
+  do_check_eq(formatMessage("Fail is ${sub}", {sub: ob}),
+              'Fail is (function () {})');
+
+  // Fall back to .toString if both .toJSON and .toSource fail.
+  ob.toSource = function() {throw "oh noes SOURCE"};
+  do_check_eq(formatMessage("Fail is ${sub}", {sub: ob}),
+              'Fail is function () {}');
+
+  // Fall back to '[object]' if .toJSON, .toSource and .toString fail.
+  ob.toString = function() {throw "oh noes STRING"};
+  do_check_eq(formatMessage("Fail is ${sub}", {sub: ob}),
+              'Fail is [object]');
+
+  // If params are passed but there are no substitution in the text
+  // we JSON format and append the entire parameters object.
+  do_check_eq(formatMessage("Text with no subs", {a: "b", c: "d"}),
+              'Text with no subs: {"a":"b","c":"d"}');
+
+  // If we substitute one parameter but not the other,
+  // we ignore any params that aren't substituted.
+  do_check_eq(formatMessage("Text with partial sub ${a}", {a: "b", c: "d"}),
+              'Text with partial sub b');
+
+  // We don't format internal fields stored in params.
+  do_check_eq(formatMessage("Params with _ ${}", {a: "b", _c: "d", _level:20, _message:"froo",
+                                                  _time:123456, _namespace:"here.there"}),
+              'Params with _ {"a":"b","_c":"d"}');
+
+  // Don't print an empty params holder if all params are internal.
+  do_check_eq(formatMessage("All params internal", {_level:20, _message:"froo",
+                                                    _time:123456, _namespace:"here.there"}),
+              'All params internal');
+
+  // Format params with null and undefined values.
+  do_check_eq(formatMessage("Null ${n} undefined ${u}", {n: null, u: undefined}),
+              'Null null undefined undefined');
+
+  // Format params with number, bool, and Object/String type.
+  do_check_eq(formatMessage("number ${n} boolean ${b} boxed Boolean ${bx} String ${s}",
+                            {n: 45, b: false, bx: new Boolean(true), s: new String("whatevs")}),
+              'number 45 boolean false boxed Boolean true String whatevs');
+
+  /*
+   * Check that errors get special formatting if they're formatted directly as
+   * a named param or they're the only param, but not if they're a field in a
+   * larger structure.
+   */
+  let err = Components.Exception("test exception", Components.results.NS_ERROR_FAILURE);
+  let str = formatMessage("Exception is ${}", err);
+  do_check_true(str.contains('Exception is [Exception... "test exception"'));
+  do_check_true(str.contains("(NS_ERROR_FAILURE)"));
+  let str = formatMessage("Exception is", err);
+  do_check_true(str.contains('Exception is: [Exception... "test exception"'));
+  let str = formatMessage("Exception is ${error}", {error: err});
+  do_check_true(str.contains('Exception is [Exception... "test exception"'));
+  let str = formatMessage("Exception is", {_error: err});
+  do_print(str);
+  // Exceptions buried inside objects are formatted badly.
+  do_check_true(str.contains('Exception is: {"_error":{}'));
+  // If the message text is null, the message contains only the formatted params object.
+  let str = formatMessage(null, err);
+  do_check_true(str.startsWith('[Exception... "test exception"'));
+  // If the text is null and 'params' is a String object, the message is exactly that string.
+  let str = formatMessage(null, new String("String in place of params"));
+  do_check_eq(str, "String in place of params");
+
+  // We use object.valueOf() internally; make sure a broken valueOf() method
+  // doesn't cause the logger to fail.
+  let vOf = {a: 1, valueOf: function() {throw "oh noes valueOf"}};
+  do_check_eq(formatMessage("Broken valueOf ${}", vOf),
+              'Broken valueOf ({a:1, valueOf:(function () {throw "oh noes valueOf"})})');
+
+  // Test edge cases of bad data to formatter:
+  // If 'params' is not an object, format it as a basic type.
+  do_check_eq(formatMessage("non-object no subst", 1),
+              'non-object no subst: 1');
+  do_check_eq(formatMessage("non-object all subst ${}", 2),
+              'non-object all subst 2');
+  // If 'params' is not an object, no named substitutions can succeed;
+  // therefore we leave the placeholder and append the formatted params.
+  do_check_eq(formatMessage("non-object named subst ${junk} space", 3),
+              'non-object named subst ${junk} space: 3');
+  // If there are no params, we leave behind the placeholders in the text.
+  do_check_eq(formatMessage("no params ${missing}", undefined),
+              'no params ${missing}');
+  // If params doesn't contain any of the tags requested in the text,
+  // we leave them all behind and append the formatted params.
+  do_check_eq(formatMessage("object missing tag ${missing} space", {mising: "not here"}),
+              'object missing tag ${missing} space: {"mising":"not here"}');
+  // If we are given null text and no params, the resulting formatted message is empty.
+  do_check_eq(formatMessage(null), '');
+});
+
+/*
+ * If we call a log function with a non-string object in place of the text
+ * argument, and no parameters, treat that the same as logging empty text
+ * with the object argument as parameters. This makes the log useful when the
+ * caller does "catch(err) {logger.error(err)}"
+ */
+add_task(function test_log_err_only() {
+  let log = Log.repository.getLogger("error.only");
+  let testFormatter = { format: msg => msg };
+  let appender = new MockAppender(testFormatter);
+  log.addAppender(appender);
+
+  /*
+   * Check that log.error(err) is treated the same as
+   * log.error(null, err) by the logMessage constructor; the formatMessage()
+   * tests above ensure that the combination of null text and an error object
+   * is formatted correctly.
+   */
+  try {
+    eval("javascript syntax error");
+  }
+  catch (e) {
+    log.error(e);
+    msg = appender.messages.pop();
+    do_check_eq(msg.message, null);
+    do_check_eq(msg.params, e);
+  }
+});
+
+/*
+ * Test logStructured() messages through basic formatter.
+ */
+add_task(function test_structured_basic() {
+  let log = Log.repository.getLogger("test.logger");
+  let appender = new MockAppender(new Log.BasicFormatter());
+
+  log.level = Log.Level.Info;
+  appender.level = Log.Level.Info;
+  log.addAppender(appender);
+
+  // A structured entry with no _message is treated the same as log./level/(null, params)
+  // except the 'action' field is added to the object.
+  log.logStructured("action", {data: "structure"});
+  do_check_eq(appender.messages.length, 1);
+  do_check_true(appender.messages[0].contains('{"data":"structure","action":"action"}'));
+
+  // A structured entry with _message and substitution is treated the same as
+  // log./level/(null, params).
+  log.logStructured("action", {_message: "Structured sub ${data}", data: "structure"});
+  do_check_eq(appender.messages.length, 2);
+  do_print(appender.messages[1]);
+  do_check_true(appender.messages[1].contains('Structured sub structure'));
+});
+
+/*
+ * Test that all the basic logger methods pass the message and params through to the appender.
+ */
+add_task(function log_message_with_params() {
+  let log = Log.repository.getLogger("error.logger");
+  let testFormatter = { format: msg => msg };
+  let appender = new MockAppender(testFormatter);
+  log.addAppender(appender);
+
+  let testParams = {a:1, b:2};
+  log.fatal("Test fatal", testParams);
+  log.error("Test error", testParams);
+  log.warn("Test warn", testParams);
+  log.info("Test info", testParams);
+  log.config("Test config", testParams);
+  log.debug("Test debug", testParams);
+  log.trace("Test trace", testParams);
+  do_check_eq(appender.messages.length, 7);
+  for (let msg of appender.messages) {
+    do_check_true(msg.params === testParams);
+    do_check_true(msg.message.startsWith("Test "));
+  }
+});
+
+/*
+ * Check that we format JS Errors reasonably.
+ */
+add_task(function format_errors() {
+  let pFormat = new Log.ParameterFormatter();
+
+  // Test that subclasses of Error are recognized as errors.
+  err = new ReferenceError("Ref Error", "ERROR_FILE", 28);
+  str = pFormat.format(err);
+  do_check_true(str.contains("ReferenceError"));
+  do_check_true(str.contains("ERROR_FILE:28"));
+  do_check_true(str.contains("Ref Error"));
+
+  // Test that JS-generated Errors are recognized and formatted.
+  try {
+    eval("javascript syntax error");
+  }
+  catch (e) {
+    str = pFormat.format(e);
+    do_check_true(str.contains("SyntaxError: missing ;"));
+    // Make sure we identified it as an Error and formatted the error location as
+    // lineNumber:columnNumber.
+    do_check_true(str.contains(":1:11)"));
+  }
+});