Closed Bug 966674 Opened 6 years ago Closed 5 years ago

Add a Log.Logger API for logging exceptions/errors

Categories

(Toolkit :: General, defect)

defect
Not set

Tracking

()

RESOLVED FIXED
mozilla32
Tracking Status
firefox31 --- fixed
firefox32 --- fixed

People

(Reporter: gps, Assigned: Irving)

References

(Blocks 1 open bug)

Details

(Keywords: dev-doc-needed)

Attachments

(3 files, 6 obsolete files)

8.21 KB, patch
gps
: review+
Details | Diff | Splinter Review
4.60 KB, patch
rnewman
: review+
Details | Diff | Splinter Review
29.05 KB, patch
Irving
: review+
Details | Diff | Splinter Review
A common use of Log.jsm is to log exceptions/errors. I think it would be beneficial to offer a dedicated API to facilitate logging of exceptions/errors. Said API could automatically format stacks for starters. Eventually, it could even feed into an "exception aggregating service" that saved and even reported exception statistics to Mozilla. But the collection and reporting part is scope bloat. The formatting alone is sufficient justification, IMO.

See Python's http://docs.python.org/2/library/logging.html#logging.Logger.exception for inspiration. It automagically grabs the actively-being-handled exception from the stack and records it.
Duplicate of this bug: 976410
We get exceptions via Promise rejection handlers and various other paths, so I'd rather not build something that only works inside exception handlers.

My first inclination is to do what the old AddonLogging.jsm methods did, which was to assume the second argument to the log method is an exception (or something that duck-type behaves like an exception); see https://hg.mozilla.org/mozilla-central/annotate/c281177594d6/toolkit/mozapps/extensions/AddonLogging.jsm#l26
Assignee: nobody → irving
Status: NEW → ASSIGNED
This basically copies the formatting of errors from AddonLogging.jsm, and moves out the 'structured logging' argument to the log(), warn(), error() etc. methods to make "log(message, exception)" be the easy path.

This code ends up with different output format for nsIException vs. JS Error; it wouldn't be hard to make them more alike if anyone cares.

Not done yet: support for errors in StructuredFormatter.

If we take this, we'll need to update the docs at https://developer.mozilla.org/en-US/docs/Mozilla/JavaScript_code_modules/Log.jsm
Attachment #8383734 - Flags: feedback?(gps)
Attachment #8383734 - Flags: feedback?(bmcbride)
I discussed this a little with Irving on IRC, but general parameter substitution is something I feel is missing from the logging API and is something I feel strongly about - every time I see "log.debug("Have object " + JSON.stringify(object))" I die a little inside, especially when I know the default log level for that log is Error - so we are JSON.stringifying every call, but only rarely will it actually end up in a log.

Here's my take on the problem which also gives us real parameter substitution for non-structured logs.  It does this without changing the signature of any Log function - but it does require a placeholder be put in the message.  Note that I gratefully stole the error-formatting patch from Irving.

With this patch, you can get roughly the same semantics as Irving's patch by saying, eg:

  log.info("Error is ${}", error);

(it does *not* support treating a simple integer as an NS_ERROR code, but you can work around this by constructing a Components.Exception object from the error code.

Note that "${}" means "format the entire params object - but you can also use "${attribute}" - so you can write:

log.info("Name is ${name}, age is ${age}", {name: "Mark", age: "old"});

If the objects have a .toJSON method it will be used.  If it can't be converted to JSON, .toString() will be called.  If that fails we just return "[object]"

This kills 2 birds with one stone - what do you think?
Attachment #8384051 - Flags: feedback?(irving)
Attachment #8384051 - Flags: feedback?(gps)
Attachment #8384051 - Flags: feedback?(bmcbride)
Comment on attachment 8384051 [details] [diff] [review]
0001-proof-of-concept-for-better-param-substitution.patch

Review of attachment 8384051 [details] [diff] [review]:
-----------------------------------------------------------------

At first glance we don't need to do make any changes to the structured message side of things with this approach, which is nice. The existing code would pass the raw message string with no substitutions performed, and all the parameters, and they can substitute later if they want.

::: toolkit/modules/Log.jsm
@@ +383,5 @@
>  
>  // Basic formatter that doesn't do anything fancy.
>  function BasicFormatter(dateFormat) {
>    if (dateFormat)
>      this.dateFormat = dateFormat;

I wish there was an easy way to make the date formatter do HH:mm:ss.xxx (local time down to milliseconds) but I spent a while looking at it, and as far as I can tell, we'd need to manually zero-pad at least the milliseconds field even if we took advantage of every possible variation of our JS Date() class.

@@ +393,5 @@
>    format: function BF_format(message) {
> +    // if we have params, try and find substitutions.
> +    let messageText = message.message;
> +    if (message.params && this.parameterFormatter) {
> +      let regex = /\$\{(\S*)\}/g;

This makes it hard to embed literal ${...} in a log message (other than by passing it in as a parameter), but I'm fine with saying that's unsupported.

@@ +402,5 @@
> +        }
> +        // ${} means use the entire params object.
> +        return this.parameterFormatter.format(message.params);
> +      });
> +    }

To make this less error prone (and more backward compatible), I'd like to have some way of also formatting any parameters that aren't explicitly substituted.

We can't (naively) modify the message.params object in place, because we might be passing it to more than one formatter (and who knows, the caller could be holding on to and re-using it).

let seen = new Set();
let all = false;
let regex = ...
messageText = messageText.replace(...
  if (sub) {
    seen.add(sub);
    return this.param...
  }
  all = true;
  return this.param...
)};

if (!all) {
  let remaining;

  if (seen.size() == 0) {
    // there were no substitutions in the message, so format the
    // entire params as a single object - this conveniently handles
    // existing code like logger.error("message", exception)
    remaining = message.params;
  }
  else {
    for (let key in message.params) {
      if (!(key.startsWith("_") || seen.has(key))) {
        if (!remaining) {
          remaining = {}
        }
        remaining[key] = message.params[key];
      }
    }
  }
  if (remaining) {
    messageText += " " + this.parameterFormatter.format(remaining);
  }
}

@@ +407,4 @@
>      return message.time + "\t" +
>        message.loggerName + "\t" +
>        message.levelDesc + "\t" +
> +      messageText + "\n";

In my patch I moved the "\n" from the formatter to the appender, because it's a feature of how the content is being stored (e.g. newline-separated text in a file vs. newline-less messages in the browser console)

@@ +450,5 @@
> +function ParameterFormatter() {
> +  this._name = "ParameterFormatter"
> +}
> +ParameterFormatter.prototype = {
> +  format: function(ob) {

I wonder if we want to memoize the result of this somehow, so that we only format a given object once no matter how many times it's substituted. This might have too many ugly edge cases, so maybe it's best to live with the inefficiency.

@@ +453,5 @@
> +ParameterFormatter.prototype = {
> +  format: function(ob) {
> +    let result;
> +    // some types get no formatting at all.
> +    if (typeof ob == "string" || typeof ob == "undefined" || typeof ob == "null") {

Probably want to match "number" here too; the format comes out the same but JSON.stringify() is overkill.

I did a quick check in scratchpad, and this will give us a visible difference between raw strings and String objects: "foo" prints as foo, but String("foo") prints as "foo". Not sure if we care much...

@@ +455,5 @@
> +    let result;
> +    // some types get no formatting at all.
> +    if (typeof ob == "string" || typeof ob == "undefined" || typeof ob == "null") {
> +      return ob;
> +    }

If we wanted to be super-fancy we could support passing a function and calling it to generate the value during substitution - up side is flexibility, and we don't do the work if we're not logging that level; down side is possible bugs from side effects that only happen if the message ends up being formatted.

You can already fudge this by putting your function in ob.toJSON, but that's a bit tricksy for my tastes.

@@ +473,5 @@
> +      }
> +      return result;
> +    }
> +    // Just JSONify it.
> +    try {

The structured logging features treat message.params that begin with "_" as internal data - we might want to filter them out here (and not in BasicFormatter.format() as I suggested above)

@@ +483,5 @@
> +    // Just toString() it - but even this may fail!
> +    try {
> +      return ob.toString();
> +    } catch (_) {
> +      return "[object]"

would ob.toSource() risk failing in the same way toString() does? maybe we can use that as the fallback.

::: toolkit/modules/tests/xpcshell/test_Log.js
@@ +328,5 @@
> +  }
> +
> +  // simple string.
> +  log.info("String is ${foo}", {foo: "bar"});
> +  do_check_eq(popFormatted(), "String is bar\n")

These could all be unit tested by calling the BasicFormatter directly, like I did in my WIP tests - there's no need to introduce a dependency on the Appender.

One of the bees in my bonnet is about how few of our unit tests actually focus on a single unit...

@@ +364,5 @@
> +  log.info("Exception is ${}", err);
> +  let str = popFormatted();
> +  do_check_true(str.contains("Exception is"));
> +  do_check_true(str.contains("NS_ERROR_FAILURE"));
> +  do_check_true(str.contains("test exception"));

... And we'd want to replicate my tests for JS Error objects, and leaving out params["_.*"] if we decide to implement that, and any of the other extensions and features I suggested above that end up implemented.
Attachment #8384051 - Flags: feedback?(irving) → feedback+
Thanks for the thoughtful feedback

(In reply to :Irving Reid from comment #5)

> @@ +393,5 @@
> >    format: function BF_format(message) {
> > +    // if we have params, try and find substitutions.
> > +    let messageText = message.message;
> > +    if (message.params && this.parameterFormatter) {
> > +      let regex = /\$\{(\S*)\}/g;
> 
> This makes it hard to embed literal ${...} in a log message (other than by
> passing it in as a parameter), but I'm fine with saying that's unsupported.

Good point - I think the regex could fairly easily prevent "\${...}" from being substituted.

> @@ +402,5 @@
> > +        }
> > +        // ${} means use the entire params object.
> > +        return this.parameterFormatter.format(message.params);
> > +      });
> > +    }
> 
> To make this less error prone (and more backward compatible), I'd like to
> have some way of also formatting any parameters that aren't explicitly
> substituted.

I don't understand this.  Currently no params are used at all by the basic formatter, so formatting and displaying params that aren't substituted would seem to be a backwards incompatible change.

eg, let's say an existing log has *both* a structured formatter and a basic formatter (presumably via different appenders).  This means that some logging calls may pass params, but they are only output by the the structured formatter.  The change you suggest (IIUC) would mean they now suddenly start appearing in log output generated by the basic formatter too, which is almost certainly not what was intended (ie, if the user wanted that stuff in the basic formatter log, they would already be sending it).

My approach will have the same problem if any of those strings happen to have ${...} patterns, but I think that's a fairly low risk.

> In my patch I moved the "\n" from the formatter to the appender, because
> it's a feature of how the content is being stored (e.g. newline-separated
> text in a file vs. newline-less messages in the browser console)

Yeah, I'm inclined to think that is a good idea, but I left it out of my patch so it only deals with the params.  IOW, I think that should be a different (but worthwhile) bug.  Or part of this bug once all the parameter-specific discussion is over :)

> I wonder if we want to memoize the result of this somehow, so that we only
> format a given object once no matter how many times it's substituted. This
> might have too many ugly edge cases, so maybe it's best to live with the
> inefficiency.

Agreed - and it is something we could do later if it can be demonstrated to be a problem.

> Probably want to match "number" here too; the format comes out the same but
> JSON.stringify() is overkill.

Good idea.

> I did a quick check in scratchpad, and this will give us a visible
> difference between raw strings and String objects: "foo" prints as foo, but
> String("foo") prints as "foo". Not sure if we care much...

Interesting - I think we should arrange for them to be the same.

> If we wanted to be super-fancy we could support passing a function and
> calling it to generate the value during substitution - up side is
> flexibility, and we don't do the work if we're not logging that level; down
> side is possible bugs from side effects that only happen if the message ends
> up being formatted.

Agreed.  Unfocused mentioned he'd like something compatible(-ish) with http://wiki.ecmascript.org/doku.php?id=harmony:quasis, and that does allow callables - but IIRC, it also allows params etc to be specified.  I didn't add this as I was concerned with inventing something incompatible with quasis, so while I think this would be good to have, I'd also like to approach that in a followup.

> The structured logging features treat message.params that begin with "_" as
> internal data - we might want to filter them out here (and not in
> BasicFormatter.format() as I suggested above)

I think that only matters when the entire params object is dumped - which as I mention above, I don't think should happen.  So if someone explicitly says "${_foo}", I think it's fine to render params._foo.

(OTOH, I guess I could agree ${} should not render them, but I'm not sure how to best arrange for that to happen.

> would ob.toSource() risk failing in the same way toString() does? maybe we
> can use that as the fallback.

I guess it wouldn't hurt to try that, but still have an exception handler just in case.

> These could all be unit tested by calling the BasicFormatter directly, like
> I did in my WIP tests - there's no need to introduce a dependency on the
> Appender.

Yes, good idea.

> One of the bees in my bonnet is about how few of our unit tests actually
> focus on a single unit...

Yes, agreed :)

> @@ +364,5 @@
> > +  log.info("Exception is ${}", err);
> > +  let str = popFormatted();
> > +  do_check_true(str.contains("Exception is"));
> > +  do_check_true(str.contains("NS_ERROR_FAILURE"));
> > +  do_check_true(str.contains("test exception"));
> 
> ... And we'd want to replicate my tests for JS Error objects, and leaving
> out params["_.*"] if we decide to implement that, and any of the other
> extensions and features I suggested above that end up implemented.

Thanks again!
(In reply to Mark Hammond [:markh] from comment #6)
> > To make this less error prone (and more backward compatible), I'd like to
> > have some way of also formatting any parameters that aren't explicitly
> > substituted.
> 
> I don't understand this.  Currently no params are used at all by the basic
> formatter, so formatting and displaying params that aren't substituted would
> seem to be a backwards incompatible change.

FTR, Irving explained his use-case for dumping params not explicitly specified, and I can't see how it hurts my use-case, so I'm fine with this.  Doubt I'll get to a patch within a couple of weeks though (work-week coming up), so Irving, please feel free to take whatever of my patch was useful if you don't want to wait.
Comment on attachment 8383734 [details] [diff] [review]
Add an 'error' parameter to Log.jsm methods to format exceptions

Review of attachment 8383734 [details] [diff] [review]:
-----------------------------------------------------------------

::: toolkit/modules/Log.jsm
@@ +273,3 @@
>    },
>  
> +  log: function (level, string, error, params) {

I'm not a huge fan of having "error" (an infrequently used argument) taking up space as a positional argument either here or in the more frequently-used level-based APIs (warn(), info(), etc) below.

The JavaScript convention (until JS grows named arguments like Python - I'm not holding my breath) is to favor passing objects with well-defined property names over passing null in positional arguments. This leads to more flexible API changes in the future and increased readability (it's hard to read "(foo, null, null, bar)"). The downside is you create a very short-lived object which adds GC pressure.

I don't believe it is coded anywhere, but we had the intention of establishing the convention that _ prefixed members of params were internal and reserved for special usage. Ultimately, we might be able to switch out the .prototype of the params object passed in, freeze it, and use it as the LogMessage object! (This would lower the overhead of logging structured messages.)

How about this.

We officially adopt the convention that _ prefixed properties of params are special.
We leave the APIs for log(), fatal(), warn(), etc as-is.
We add a logError(level, string, error, params=null) API that adds ._error to params and calls into log().
If we /really/ need it, we can add logWarnError(), etc APIs for convenience.

Will that work?

@@ +416,5 @@
> +          }
> +          if (e.columnNumber) {
> +            line = line + ":" + e.columnNumber;
> +          }
> +          line = line + ")";

There are quite a few places in the tree where we convert Error to strings (I'm partial to the implementation in services/common/utils.js). I wonder if it is worth consolidating that into its own JSM and slowly moving everyone to use it.

::: toolkit/modules/tests/xpcshell/test_Log.js
@@ +315,5 @@
>  
>  });
>  
> +// Test that all the basic logger methods pass an error through to the appender
> +add_test(function log_message_with_error() {

FWIW, there are a number of us who have stopped using add_test() and instead use add_task() regardless of whether the test is a generator or uses promises. The reason is the run_next_test(), do_test_pending(), etc is more prone to issues than add_task().
Attachment #8383734 - Flags: feedback?(gps)
Comment on attachment 8384051 [details] [diff] [review]
0001-proof-of-concept-for-better-param-substitution.patch

Review of attachment 8384051 [details] [diff] [review]:
-----------------------------------------------------------------

This is effectively a rubber stamp f+ as I didn't look at the code too much.

Is it intentional or just a coincidence that you used the same escaping in this proposal as ES6's Template Strings feature? http://tc39wiki.calculist.org/es6/template-strings/

Unless template strings are inherently incompatible, I think we should absolutely design this feature to be compatible with them. If we have to polyfill the implementation (as you have done), such is life.
Attachment #8384051 - Flags: feedback?(gps) → feedback+
jorendorff: I looked for a bug tracking template strings in SpiderMonkey and was unable to find one. What's the current plan for them?
Flags: needinfo?(jorendorff)
(In reply to Gregory Szorc [:gps] from comment #9)
> Is it intentional or just a coincidence that you used the same escaping in
> this proposal as ES6's Template Strings feature?
> http://tc39wiki.calculist.org/es6/template-strings/

Intentional, that was my influence :)
(In reply to Gregory Szorc [:gps] from comment #10)
> jorendorff: I looked for a bug tracking template strings in SpiderMonkey and
> was unable to find one. What's the current plan for them?

Bug 688857?
Comment on attachment 8384051 [details] [diff] [review]
0001-proof-of-concept-for-better-param-substitution.patch

Review of attachment 8384051 [details] [diff] [review]:
-----------------------------------------------------------------

Basically just +1 to everything said in this bug (I think I've said almost as much over IRC).

I also really want to see a stack-trace in the cases where we have an exception, as AddonLogging.jsm had that and it was *incredibly* useful (main reason for pushing this now is we recently replaced AddonLogging.jsm with Log.jsm before Log.jsm handled exceptions).

(In reply to Gregory Szorc [:gps] from comment #8)
> There are quite a few places in the tree where we convert Error to strings
> (I'm partial to the implementation in services/common/utils.js). I wonder if
> it is worth consolidating that into its own JSM and slowly moving everyone
> to use it.

If we move that to Log.jsm, it'd help convince people to move their logging to use Log.jsm.
Attachment #8384051 - Flags: feedback?(bmcbride) → feedback+
Attachment #8383734 - Flags: feedback?(bmcbride)
It is bug 688857. I hope to take it next week.
Flags: needinfo?(jorendorff)
Duplicate of this bug: 684438
multi-comment reply...

(In reply to Mark Hammond [:markh] from comment #6)
> > This makes it hard to embed literal ${...} in a log message (other than by
> > passing it in as a parameter), but I'm fine with saying that's unsupported.
> 
> Good point - I think the regex could fairly easily prevent "\${...}" from
> being substituted.

Template strings can do this, because they get the raw string before the JS parser unescapes it. As far as I can tell, in our code we don't see the raw string so we won't be able to tell the difference between "\${}" and "${}". That leaves our users fighting with stacked \\\\ to try and get the escaping level correct; I'd rather just say it's not supported.

...
> eg, let's say an existing log has *both* a structured formatter and a basic
> formatter (presumably via different appenders).  This means that some
> logging calls may pass params, but they are only output by the the
> structured formatter.  The change you suggest (IIUC) would mean they now
> suddenly start appearing in log output generated by the basic formatter too,
> which is almost certainly not what was intended (ie, if the user wanted that
> stuff in the basic formatter log, they would already be sending it).

Mark and I had a fairly long IRC conversation about this; my points are:

a) There aren't any structured logging calls in our code base yet, so we don't need to worry about backward compatibility for those APIs
b) We do have a lot of calls in toolkit/mozapps/extensions that try to pass an error as the second parameter, because that's what worked with AddonLogging.jsm; if we select an approach that doesn't format the second parameter by default we'll need to modify all those calls
c) I've seen problems in the past where you only found out your log call had a misspelled parameter when something was failing in the field, and then you didn't have the diagnostic info because of the typo, so I'd prefer to err on the side of including more info rather than less

> > In my patch I moved the "\n" from the formatter to the appender, because
> > it's a feature of how the content is being stored (e.g. newline-separated
> > text in a file vs. newline-less messages in the browser console)
> 
> Yeah, I'm inclined to think that is a good idea, but I left it out of my
> patch so it only deals with the params.  IOW, I think that should be a
> different (but worthwhile) bug.  Or part of this bug once all the
> parameter-specific discussion is over :)

I'm turning this into a multi-patch bug, so I'll put this (and a few other things) in its own patch.


(In reply to Gregory Szorc [:gps] from comment #8)
> Comment on attachment 8383734 [details] [diff] [review]
> Add an 'error' parameter to Log.jsm methods to format exceptions
> 
> Review of attachment 8383734 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> ::: toolkit/modules/Log.jsm
> @@ +273,3 @@
> >    },
> >  
> > +  log: function (level, string, error, params) {
> 
> I'm not a huge fan of having "error" (an infrequently used argument) taking
> up space as a positional argument either here or in the more frequently-used
> level-based APIs (warn(), info(), etc) below.

Starting from Mark's patch, I think we can make this work without a specific 'error' parameter by formatting the 'params' object as an error if it smells like one.

> We officially adopt the convention that _ prefixed properties of params are
> special.

This was partly implemented in the existing code, I'm cleaning it up.

> We leave the APIs for log(), fatal(), warn(), etc as-is.

OK

> We add a logError(level, string, error, params=null) API that adds ._error
> to params and calls into log().
> If we /really/ need it, we can add logWarnError(), etc APIs for convenience.

I'd rather *either* just sniff the params object and format it as an error if it looks like one, or pass {_error: e} in params.

The second option would require changing a lot of calls in toolkit/mozapps/extensions.

> There are quite a few places in the tree where we convert Error to strings
> (I'm partial to the implementation in services/common/utils.js). I wonder if
> it is worth consolidating that into its own JSM and slowly moving everyone
> to use it.

How about I pull it into Log.jsm and expose it as part of the API, so others can use just that feature if they want?


(In reply to Gregory Szorc [:gps] from comment #9)
> Is it intentional or just a coincidence that you used the same escaping in
> this proposal as ES6's Template Strings feature?
> http://tc39wiki.calculist.org/es6/template-strings/
> 
> Unless template strings are inherently incompatible, I think we should
> absolutely design this feature to be compatible with them. If we have to
> polyfill the implementation (as you have done), such is life.

We can't *quite* line up template strings with structured logging as implemented so far, because template strings don't give us names for the substituted fields, so we can't construct corresponding name:value pairs for the params object to match the template substitutions.

Based on my understanding of template strings, using them for logging would look something like:

try {
  fileHandle = open_file(myFile);
}
catch (error) {
  log.error `Failed to open file ${myFile}: ${error}`;
}

The template string 'tag' (a function, in our case log.error()) gets passed the parsed out message and the values to substitute as arrays of strings, but as far as I can tell it doesn't get the text from inside ${...} - and that text could be arbitrary JS.

I suppose we could completely separate formatted-message logging from structured logging; that would be inconvenient in places where a developer wanted both, but maybe we don't need much of that.


(In reply to Blair McBride [:Unfocused] from comment #13)
> I also really want to see a stack-trace in the cases where we have an
> exception, as AddonLogging.jsm had that and it was *incredibly* useful (main
> reason for pushing this now is we recently replaced AddonLogging.jsm with
> Log.jsm before Log.jsm handled exceptions).

I was thinking of making a separate formatter that prints stack traces, rather than always printing them in BasicFormatter.
(In reply to Gregory Szorc [:gps] from comment #8)

> I don't believe it is coded anywhere, but we had the intention of
> establishing the convention that _ prefixed members of params were internal
> and reserved for special usage. Ultimately, we might be able to switch out
> the .prototype of the params object passed in, freeze it, and use it as the
> LogMessage object! (This would lower the overhead of logging structured
> messages.)
> 
> How about this.
> 
> We officially adopt the convention that _ prefixed properties of params are
> special.

Sat down to start implementing this and realized we need to clarify what this means.

There's always going to be a tension between developer & user oriented debug/info/warn/error logging for tracing and individual problem diagnosis vs. structured logging for aggregation and analysis; the use cases are different enough that an API supporting one well is going to have pain points for the other. Having survived a major structured logging product design & development effort a couple of jobs ago, my inclination now is to err on the side of making it easy to get information *into* the log first.

(Aside: the existing code and comments use 'message' both to mean an entire log entry with its body and metadata, and specifically the descriptive text field within the body. Can we rename one or the other to reduce confusion? Either rename metadata+body to 'entry' or rename descriptive text to 'text' or 'description?)

The existing code has special cases for an incoming params object; if it contains '_level' we try to convert that to our internal level number and use it as the log level, and if it contains '_message' we use that as the descriptive text for non-structured formatters. When the structured message is formatted we add 'action', '_time', '_namespace' and (add or replace) '_level' in the params before we convert them to JSON.

a) If a caller passes params = {_something: val} (other than _level or _message) do we intend to include that in the StructuredFormatter JSON output?

b) the 'action' field is in a gray area between data and metadata - we require it for a 'logStructured' call but don't interpret it, and the rest of the processing doesn't care whether it's there or not. My inclination is to remove the special case in Log.jsm, and document a convention that Log.jsm clients producing messages targeted at consumers with specific expectations extend their Logger instances with methods that generate correctly structured entries; e.g.

  let log = Log.repository.getLogger("my.identifier");
  log.myAction = function(text, some, inputs, here) {
     this.info(text, {action: "myAction", some: some, inputs: inputs, here: here});
  };

c) FHR went to some trouble to reduce the number of characters in what they send, mostly by using very short tags for a lot of their field names. Do we care? If so, one approach would be to pull the metadata out into array fields rather than inserting them in params._time, _namespace etc. so a structured entry would be formatted like:

[1234234, "my.identifier", "Info", "message", {"param1": "value1" ...}]
(In reply to :Irving Reid from comment #17)
> There's always going to be a tension between developer & user oriented
> debug/info/warn/error logging for tracing and individual problem diagnosis
> vs. structured logging for aggregation and analysis; the use cases are
> different enough that an API supporting one well is going to have pain
> points for the other. Having survived a major structured logging product
> design & development effort a couple of jobs ago, my inclination now is to
> err on the side of making it easy to get information *into* the log first.

We should absolutely make the client-side logging API as simple and easy-to-use as possible.

> (Aside: the existing code and comments use 'message' both to mean an entire
> log entry with its body and metadata, and specifically the descriptive text
> field within the body. Can we rename one or the other to reduce confusion?
> Either rename metadata+body to 'entry' or rename descriptive text to 'text'
> or 'description?)

One of the uses of "message" originated from before structured logging existed. I don't believe there are many consumers of the non-log*() functions. If you want to do the legwork to rename, go for it.

> a) If a caller passes params = {_something: val} (other than _level or
> _message) do we intend to include that in the StructuredFormatter JSON
> output?

That's likely undefined behavior :)

> b) the 'action' field is in a gray area between data and metadata - we
> require it for a 'logStructured' call but don't interpret it, and the rest
> of the processing doesn't care whether it's there or not. My inclination is
> to remove the special case in Log.jsm, and document a convention that
> Log.jsm clients producing messages targeted at consumers with specific
> expectations extend their Logger instances with methods that generate
> correctly structured entries; e.g.
> 
>   let log = Log.repository.getLogger("my.identifier");
>   log.myAction = function(text, some, inputs, here) {
>      this.info(text, {action: "myAction", some: some, inputs: inputs, here:
> here});
>   };

Hmmm. That seems to raise the barrier to logging a bit.

IIRC I was the person who argued for an "action" field being mandatory for structured messages. My rationale was that it's far easier for downstream consumers to filter/switch off a single field than to guess the meaning of a structured message by examining the properties therein. Put another way, a stream of objects with varied sets of key-value pairs looks like a stream of gibberish in the absence of additional identifiers.

> c) FHR went to some trouble to reduce the number of characters in what they
> send, mostly by using very short tags for a lot of their field names. Do we
> care? If so, one approach would be to pull the metadata out into array
> fields rather than inserting them in params._time, _namespace etc. so a
> structured entry would be formatted like:
> 
> [1234234, "my.identifier", "Info", "message", {"param1": "value1" ...}]

FHR did this for the payload, which is transmitted over the wire by every client. We wanted to save client bandwidth and save Mozilla money.

I believe we had this conversation before. (Is it buried in bug 884397?) I like the idea of using an array as an optimization (it's what mach's structured logging uses - run `mach build -l build.log` and examine that file). I /think/ we settled on objects because it was the easiest and least constraining.

In the end, the LogFormatter controls how each log message object gets serialized. We can have variations for arrays and objects if we want.
chmanchester: You may want to read through this thread and add context and ideas.
I'll mostly agree with gps from comment 18, but can point to some more context:

There's some exception formatting code in xpcshell's head.js that might be relevant: http://hg.mozilla.org/mozilla-central/file/de17e5deb35d/testing/xpcshell/head.js#l562

> > (Aside: the existing code and comments use 'message' both to mean an entire
> > log entry with its body and metadata, and specifically the descriptive text
> > field within the body. Can we rename one or the other to reduce confusion?
> > Either rename metadata+body to 'entry' or rename descriptive text to 'text'
> > or 'description?)
> 
> One of the uses of "message" originated from before structured logging
> existed. I don't believe there are many consumers of the non-log*()
> functions. If you want to do the legwork to rename, go for it.
> 

There is work underway to specify formats specifically for test results -- bug 916260 -- and a python implementation. Consistency with that may be desirable in terms of the fields that end up in the object logged. In terms of names of variables within Log.jsm, I would change the "message" variable that means "text content of the message" to be something like "messageText" or just "text".

> > a) If a caller passes params = {_something: val} (other than _level or
> > _message) do we intend to include that in the StructuredFormatter JSON
> > output?
> 
> That's likely undefined behavior :)

These fields are intended to be "reserved" in the sense that they might be modified by the logging library itself. I would include anything a user puts in their object to reduce surprise, but it's basically undefined behavior.

> 
> > b) the 'action' field is in a gray area between data and metadata - we
> > require it for a 'logStructured' call but don't interpret it, and the rest
> > of the processing doesn't care whether it's there or not. My inclination is
> > to remove the special case in Log.jsm, and document a convention that
> > Log.jsm clients producing messages targeted at consumers with specific
> > expectations extend their Logger instances with methods that generate
> > correctly structured entries; e.g.
> > 
> >   let log = Log.repository.getLogger("my.identifier");
> >   log.myAction = function(text, some, inputs, here) {
> >      this.info(text, {action: "myAction", some: some, inputs: inputs, here:
> > here});
> >   };
> 
> Hmmm. That seems to raise the barrier to logging a bit.
> 
> IIRC I was the person who argued for an "action" field being mandatory for
> structured messages. My rationale was that it's far easier for downstream
> consumers to filter/switch off a single field than to guess the meaning of a
> structured message by examining the properties therein. Put another way, a
> stream of objects with varied sets of key-value pairs looks like a stream of
> gibberish in the absence of additional identifiers.

My recollection is consistent with that. The action field is data if you consider a log message to represent an event whose meaning is known to a consumer, or metadata if you consider the structured log record as a container for the string you would have logged in the first place. We shouldn't make it hard to "just log" -- in some cases the action would be "debug_output" (or similar), and any consumer would look to the message text for its meaning.

> > c) FHR went to some trouble to reduce the number of characters in what they
> > send, mostly by using very short tags for a lot of their field names. Do we
> > care? If so, one approach would be to pull the metadata out into array
> > fields rather than inserting them in params._time, _namespace etc. so a
> > structured entry would be formatted like:
> > 
> > [1234234, "my.identifier", "Info", "message", {"param1": "value1" ...}]
> 
> FHR did this for the payload, which is transmitted over the wire by every
> client. We wanted to save client bandwidth and save Mozilla money.
> 
> I believe we had this conversation before. (Is it buried in bug 884397?) I
> like the idea of using an array as an optimization (it's what mach's
> structured logging uses - run `mach build -l build.log` and examine that
> file). I /think/ we settled on objects because it was the easiest and least
> constraining.
> 
> In the end, the LogFormatter controls how each log message object gets
> serialized. We can have variations for arrays and objects if we want.

Right. My goal for this format was to be general and easy to parse. Another format should be used if reducing message size is the goal.
The first patch just stabilizes things a bit before I dig in...
Attachment #8399777 - Flags: review?(gps)
Well, the scope on this didn't so much 'creep' as it did 'run through the room screaming and flailing its arms'...

This mostly takes Mark's draft patch with parameter substitution and adds the bits from my draft patch that were worth keeping. There is a first cut at how to handle parameters starting with '_' in this patch, but it gets revised in Part 3. If that's annoying to the reviewers, I can merge the two patches so that you only need to see the final version of the change.
Attachment #8383734 - Attachment is obsolete: true
Attachment #8384051 - Attachment is obsolete: true
Attachment #8399782 - Flags: review?(gps)
This patch moves exceptionStr() and stackTrace() from services/utils.js to Log.jsm, leaving behind function pointers for compatibility, and uses a slightly refactored exceptionStr() to format errors passed through Log.jsm.

This patch also switches from filtering out all parameters beginning with '_' to only filtering out those specifically internally used by Log.jsm, based on discussion in the comments on this bug.

If we land this, we'll want a follow up bug to remove all the now-redundant calls to exceptionStr() used to format message strings being passed to Log.jsm.
Attachment #8399786 - Flags: review?(gps)
Comment on attachment 8399782 [details] [diff] [review]
Part 2 - Parameter substitution and first cut at error formatting

Review of attachment 8399782 [details] [diff] [review]:
-----------------------------------------------------------------

Quick drive-by - these look good in general to me, although I am a little confused by '_error'.

::: toolkit/modules/Log.jsm
@@ +446,5 @@
>    format: function BF_format(message) {
> +    // if we have params, try and find substitutions.
> +    let messageText = message.message || "";
> +    if (message.params && this.parameterFormatter) {
> +      let seen = new Set();

I think it would be helpful to add a brief comment indicating what this routine and the |seen| set are doing.

@@ +464,5 @@
> +      if ("_error" in message.params) {
> +        let err = this.parameterFormatter.format(message.params._error);
> +        if (messageText != "") {
> +          messageText += " " + err;
> +        }

this |else| indentation isn't consistent with the rest of the file - ie, it should be '} else {' - although I'd probably have written this as:

if (messageText)
  messageText += " ";
messageText += err;

But... stepping back further, I'm not clear why '_error' is treated specially here.  I'd have thought either |log.debug("foo", exception);| or |log.debug("foo", {exception: exception});| would both be good enough for your use-case?  I see you changed this in the final patch, but I'm not sure why '_error' is classed as internal there either.

@@ +600,5 @@
> +      // Just JSONify it. Filter out elements that begin with _.
> +      return JSON.stringify(ob, (key, val) => (key && key.startsWith("_")) ? undefined : val);
> +    }
> +    catch (e) {
> +      dump(e.toSource() + "\n");

I think a Cu.reportError() would be better here.
Attachment #8399782 - Flags: feedback+
(In reply to Mark Hammond [:markh] from comment #24)
> Comment on attachment 8399782 [details] [diff] [review]
> Part 2 - Parameter substitution and first cut at error formatting
> 
> Review of attachment 8399782 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> Quick drive-by - these look good in general to me, although I am a little
> confused by '_error'.

The problem is that the current design of ParameterFormatter only does the special case handling of error messages if they're the top level object passed in; if the error object is nested inside some other object it just gets JSON.stringify() which throws away all the useful information in the error.

The special case handling of _error was intended to allow callers to pass a params object and still get an error nicely formatted, without having to explicitly substitute the error parameter into the text. I'm open to discussion about how useful this is, and whether there's a better way to support it.

I suppose we could use a filtered version of JSON.stringify to detect error-ish objects anywhere in the params structure and format them where we find them, rather than pulling out a named _error param.

> ::: toolkit/modules/Log.jsm
> @@ +446,5 @@
> >    format: function BF_format(message) {
> > +    // if we have params, try and find substitutions.
> > +    let messageText = message.message || "";
> > +    if (message.params && this.parameterFormatter) {
> > +      let seen = new Set();
> 
> I think it would be helpful to add a brief comment indicating what this
> routine and the |seen| set are doing.

OK.

> @@ +464,5 @@
> > +      if ("_error" in message.params) {
> > +        let err = this.parameterFormatter.format(message.params._error);
> > +        if (messageText != "") {
> > +          messageText += " " + err;
> > +        }
> 
> this |else| indentation isn't consistent with the rest of the file - ie, it
> should be '} else {' - although I'd probably have written this as:
> 
> if (messageText)
>   messageText += " ";
> messageText += err;

OK.

> But... stepping back further, I'm not clear why '_error' is treated
> specially here.  I'd have thought either |log.debug("foo", exception);| or
> |log.debug("foo", {exception: exception});| would both be good enough for
> your use-case?  I see you changed this in the final patch, but I'm not sure
> why '_error' is classed as internal there either.
> 
> @@ +600,5 @@
> > +      // Just JSONify it. Filter out elements that begin with _.
> > +      return JSON.stringify(ob, (key, val) => (key && key.startsWith("_")) ? undefined : val);
> > +    }
> > +    catch (e) {
> > +      dump(e.toSource() + "\n");
> 
> I think a Cu.reportError() would be better here.

Oh, here goes the scope creep again...
Yes, I think reporting this in the console is a good idea (either Cu.reportError or Browser Console), but I also want it dumped to stderr - failures in the logging subsystem, in particular, are very nasty to debug and could happen at any time, including when (and possibly because) underlying services like the console are unavailable or failing for some reason - as an example, I had to debug an AddonManager issue a few months ago where the failure happened at shutdown, after Cu.reportError() was no longer useful.

I'll add a Cu.reportError here, but I'll also file a follow up bug to review the whole module and make sure we fall back to console+stderr safely whenever some piece of infrastructure fails under us.
(In reply to :Irving Reid from comment #25)
...
> The problem is that the current design of ParameterFormatter only does the
> special case handling of error messages if they're the top level object
> passed in; if the error object is nested inside some other object it just
> gets JSON.stringify() which throws away all the useful information in the
> error.
> 
> The special case handling of _error was intended to allow callers to pass a
> params object and still get an error nicely formatted, without having to
> explicitly substitute the error parameter into the text. I'm open to
> discussion about how useful this is, and whether there's a better way to
> support it.

I think you are saying that:

 log.info("foo", exception)
 log.info("err: $(exc)", {foo: "bar", exc: exception});

would both format the exception, whereas:

 log.info("err", {foo: "bar", exc: exception});

would not.  IMO, this is perfectly fine and would allow us to avoid that magic.

> > I think a Cu.reportError() would be better here.
> Oh, here goes the scope creep again...
> Yes, I think reporting this in the console is a good idea (either Cu.reportError or Browser Console), 

This makes sense - maybe now would be a good time to add a utility for reporting internal errors - something like http://mxr.mozilla.org/mozilla-central/source/toolkit/modules/Promise-backend.js#184
Can we possibly defer further improvements to follow-up bugs?
I've run into the next issue today where having an actual error log would have saved quite a bit of time.
Comment on attachment 8399777 [details] [diff] [review]
Part 1 - clean up some reference errors and newline handling

Review of attachment 8399777 [details] [diff] [review]:
-----------------------------------------------------------------

::: toolkit/modules/Log.jsm
@@ +443,5 @@
>    format: function BF_format(message) {
>      return message.time + "\t" +
>        message.loggerName + "\t" +
>        message.levelDesc + "\t" +
> +      message.message;

I seem to recall discussion about the "\n" here having consequences beyond this file. I think we'll be OK since you changed the appenders. But be prepared for some unintended fallout. I would definitely run the xpcshell tests in services/ and browser/experiments/ just to be sure.

I agree chomping the \n is a good idea!
Attachment #8399777 - Flags: review?(gps) → review+
Comment on attachment 8399782 [details] [diff] [review]
Part 2 - Parameter substitution and first cut at error formatting

Review of attachment 8399782 [details] [diff] [review]:
-----------------------------------------------------------------

This looks pretty good. I love your attention to testing details and edge cases!

I think the next review should be a quick r+.

I think the behavior of appending extra parameters to the end of the message without decoration seems a bit weird and possibly unexpected. I can think of a number of scenarios where you are passing an existing object - say an object with lots of context - to the logger as a convenience (instead of creating a whole new object). Having every single property printed seems a bit weird and would require more effort on the calling side and more overhead to create new objects. This is the biggest issue I see with this patch.

As far as solutions go, I'm not sure. We could pass a boolean through logStructured that dictates missing parameter behavior. We could make it a property on the logger, appender, and/or formatter. Lots of choices here. Sadly, the easiest is to leave out formatting of unknown parameters until we figure out a sane solution. But that would likely prohibit us from sneaking that feature back in, since it breaks backwards compatibility. Choices, choices. I'm interesting in hearing the thoughts of others.

::: toolkit/modules/Log.jsm
@@ +445,5 @@
>  
>    format: function BF_format(message) {
> +    // if we have params, try and find substitutions.
> +    let messageText = message.message || "";
> +    if (message.params && this.parameterFormatter) {

It might be useful to add an escape hatch to disable parameter substitution. Not sure how many people would need it. Wait and see?

@@ +471,5 @@
> +        }
> +      }
> +      if (!all) {
> +        let remaining;
> +        if (seen.size == 0) {

if (!seen.size)

@@ +600,5 @@
> +      // Just JSONify it. Filter out elements that begin with _.
> +      return JSON.stringify(ob, (key, val) => (key && key.startsWith("_")) ? undefined : val);
> +    }
> +    catch (e) {
> +      dump(e.toSource() + "\n");

I agree with Mark.

::: toolkit/modules/tests/xpcshell/test_Log.js
@@ +31,5 @@
>  function run_test() {
>    run_next_test();
>  }
>  
> +add_task(function test_Logger() {

Thank you for doing this conversion.

@@ +357,5 @@
> +              'Missing object is undefined');
> +
> +  // 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');

I love your comprehensive testing!

@@ +369,5 @@
> +  // object that throws in .toJSON
> +  let ob = function() {};
> +  ob.toJSON = function() {throw "oh noes JSON"};
> +  do_check_eq(formatMessage("Fail is ${sub}", {sub: ob}),
> +              'Fail is (function () {})');

It seems weird to have a function printed like that. Not sure what we can do here. Don't let it block r+.

@@ +384,5 @@
> +              'Text with no subs {"a":"b","c":"d"}');
> +
> +  // Substitute one parameter but not the other
> +  do_check_eq(formatMessage("Text with partial sub ${a}", {a: "b", c: "d"}),
> +              'Text with partial sub b {"c":"d"}');

It seems odd to have the extra params at the end of the message like this. I think a delimiter would make a lot of sense. Maybe tack on "; extra params: ..." or something? Maybe just "; "?

@@ +396,5 @@
> +              'All params with _');
> +
> +  // Params with null and undefined values
> +  do_check_eq(formatMessage("Null ${n} undefined ${u}", {n: null, u: undefined}),
> +              'Null null undefined undefined');

This test makes me happy.
Attachment #8399782 - Flags: review?(gps) → feedback+
Comment on attachment 8399786 [details] [diff] [review]
Part 3 - move exceptionStr from services/utils.js to Log.jsm and clean up parameter formatting

Review of attachment 8399786 [details] [diff] [review]:
-----------------------------------------------------------------

I'll need to look at this again after part 2 is (possibly) changed. So no granting full review.

Do you think you could move the services/common/utils.js functions to Log.jsm as its own patch? I believe there is also an xpcshell test for it that should be moved.

::: toolkit/modules/Log.jsm
@@ +135,5 @@
> +    }
> +    return result + " " + Log.stackTrace(e);
> +  },
> +
> +  // This is for back compatibility with toolkit/services/utils.js; we duplicate

The path in the comment is wrong. Should be services/common/utils.js.

::: toolkit/mozapps/extensions/internal/XPIProvider.jsm
@@ +5784,5 @@
>   */
>  function UpdateChecker(aAddon, aListener, aReason, aAppVersion, aPlatformVersion) {
> +  if (!aListener || !aReason) {
> +    throw Components.Exception("Missing arguments to UpdateChecker", Cr.NS_ERROR_INVALID_ARG);
> +  }

I don't think you meant to include this.
Attachment #8399786 - Flags: review?(gps) → feedback+
Based on gps' request, I've separated out moving exceptionStr() and stackTrace() to a patch of its own.

I'm leaving the pre-existing unit tests in their old place, along with the back compatibility hooks, because there are still plenty of consumers of the API from commons/utils. When this lands I'll file a follow up bug to update all the API consumers, move the tests and remove the compatibility hooks.
Attachment #8399782 - Attachment is obsolete: true
Attachment #8408448 - Flags: review?(gps)
I've squashed all the message formatting and error handling into one patch, so you don't need to review me changing the same thing twice like happened a few places in the old patch structure.

Notable changes from the previous version:

As suggested by both markh and gps, I've removed the special case formatting for _error - if we're formatting an error directly (either because an error nested inside the params object is being specifically substituted into a message, or because the object passed as 'params' is an error) it gets nice formatting, otherwise it gets whatever toJSON() gives us.

You've successfully talked me out of formatting extra values from the params object and tacking them on to the end of the message. Now, if we successfully format anything from params we ignore the rest; only if there are no substitutions into the message do we put a formatted version of params on the end.

Two other features crept in:
 - if a substitution is missing, we leave the placeholder in the message.
 - if a log function is called with no message, just an object, we format as if we had a null message and the object was passed as 'params'. This lets lazy devs get away with "catch(err) {logger.error(err);}"

Try build on its way:
https://tbpl.mozilla.org/?tree=Try&rev=cae17eb954be
See the tests for examples.
Attachment #8399786 - Attachment is obsolete: true
Attachment #8408454 - Flags: review?(gps)
Attachment #8408454 - Flags: feedback?(mhammond)
Try run showed that I missed a couple more tests that depended on exact log message format.
Attachment #8408454 - Attachment is obsolete: true
Attachment #8408454 - Flags: review?(gps)
Attachment #8408454 - Flags: feedback?(mhammond)
Attachment #8409333 - Flags: review?(gps)
Attachment #8409333 - Flags: feedback?(mhammond)
Comment on attachment 8409333 [details] [diff] [review]
Part 3 - Add parameter substitution and error formatting to Log.jsm (tests fixed)

Review of attachment 8409333 [details] [diff] [review]:
-----------------------------------------------------------------

Just a fairly quick pass, but looking good and useful - thanks!

::: toolkit/modules/Log.jsm
@@ +209,5 @@
>   */
>  function LogMessage(loggerName, level, message, params) {
>    this.loggerName = loggerName;
>    this.level = level;
> +  // If the message text is empty, or a string, or a String object, normal handling

This seems quite complex when it seems all you care about is the case of "typeof message == "object" && !params"?  Also, most of our code (and a few other style-guides I can fine on the net) doesn't have params for typeof.

@@ +212,5 @@
>    this.level = level;
> +  // If the message text is empty, or a string, or a String object, normal handling
> +  if (!message || params ||
> +      typeof(message) == "string" ||
> +      (typeof(message) == "object") && (typeof(message.valueOf()) == "string")) {

I think extra parens around the '&&' conditions would make things clearer.

@@ +347,5 @@
>      }
>      if (!params) {
>        return this.log(this.level, undefined, {"action": action});
>      }
> +    if (typeof(params) != "object") {

see above - I think the original version without parens is the style of the rest of our code.

@@ +536,5 @@
> +  /**
> +   * 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 any params have *not* been substituted

This comment is out-of-date now, right?  (ie, we don't substitute missing params any more IIUC)

@@ +555,5 @@
> +    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;

I wonder if this regex should be a global const?  I 1/2 expect it would be faster (although this could also be premature optimization...)

::: toolkit/mozapps/extensions/internal/XPIProvider.jsm
@@ +5793,5 @@
>   */
>  function UpdateChecker(aAddon, aListener, aReason, aAppVersion, aPlatformVersion) {
> +  if (!aListener || !aReason) {
> +    throw Components.Exception("Missing arguments to UpdateChecker", Cr.NS_ERROR_INVALID_ARG);
> +  }

I'm not sure if this change should be part of this patch (but I guess it's OK is gps or unfocussed are also able to review addons related changes and are happy with it)
Attachment #8409333 - Flags: feedback?(mhammond) → feedback+
Comment on attachment 8408448 [details] [diff] [review]
Part 2 - Move exceptionStr() and stackTrace() from utils.js to Log.jsm

I'm out of commission for a while. Redirecting review.
Attachment #8408448 - Flags: review?(gps) → review?(rnewman)
Attachment #8409333 - Flags: review?(gps) → review?(rnewman)
Comment on attachment 8408448 [details] [diff] [review]
Part 2 - Move exceptionStr() and stackTrace() from utils.js to Log.jsm

Review of attachment 8408448 [details] [diff] [review]:
-----------------------------------------------------------------

::: toolkit/modules/Log.jsm
@@ +169,5 @@
> +
> +        if (frame.lineNumber){
> +          str += ":" + frame.lineNumber;
> +        }
> +        if (frame.name){

Can we fix up the formatting as we do this move? (Newline before `if`, space before `{`.)
Attachment #8408448 - Flags: review?(rnewman) → review+
Comment on attachment 8409333 [details] [diff] [review]
Part 3 - Add parameter substitution and error formatting to Log.jsm (tests fixed)

Review of attachment 8409333 [details] [diff] [review]:
-----------------------------------------------------------------

Looks fine to me, so apologies for what I've missed!

::: toolkit/modules/Log.jsm
@@ +26,5 @@
> +/*
> + * Dump a message everywhere we can if we have a failure
> + */
> +function dumpError(text)
> +{

Brace on same line.

@@ +112,5 @@
>    // Logging helper:
>    // let logger = Log.repository.getLogger("foo");
>    // logger.info(Log.enumerateProperties(someObject).join(","));
>    enumerateProperties: function Log_enumerateProps(aObject,
> +                                                   aExcludeComplexTypes) {

Just put it on the same line and kill the function name.

@@ +209,5 @@
>   */
>  function LogMessage(loggerName, level, message, params) {
>    this.loggerName = loggerName;
>    this.level = level;
> +  // If the message text is empty, or a string, or a String object, normal handling

I'd be inclined to invert this conditional, as Mark said: if the message is an object, and there are no params, then special-case.

@@ +216,5 @@
> +      (typeof(message) == "object") && (typeof(message.valueOf()) == "string")) {
> +    this.message = message;
> +    this.params = params;
> +  } else {
> +    // Special case to handle "log.level(object)", for example logging a caught exception

Maybe "log.$level($object)" or some other indicator that you don't mean calling the `level` method?

@@ +527,5 @@
>  // Basic formatter that doesn't do anything fancy.
>  function BasicFormatter(dateFormat) {
>    if (dateFormat)
>      this.dateFormat = dateFormat;
> +  this.parameterFormatter = new ParameterFormatter();

{} around conditional, so your reviewer doesn't say "fix indenting" :)

@@ +541,5 @@
> +   * into the text, format them as a separate object and append that
> +   * to the message (ease of use / safety for developers who
> +   * don't correctly format all their log data).
> +   */
> +  formatText: function BF_formatText(message) {

No function name.

@@ +661,5 @@
> +      }
> +      if (ob === null) {
> +        return "null";
> +      }
> +      // primitive types and objects that unbox to primitive types pass through

Nit: I prefer full sentences for comments: newline before, starting capital, ending with a period. (Throughout.)

::: toolkit/modules/tests/xpcshell/test_Log.js
@@ +450,5 @@
> +  do_check_eq(formatMessage("object missing tag ${missing} space", {mising: "not here"}),
> +              'object missing tag ${missing} space: {"mising":"not here"}');
> +});
> +
> +// If we call a log function with a non-string object in place of the text

Extra points for making these /* */ block comments.
Attachment #8409333 - Flags: review?(rnewman) → review+
Carrying forward rnewman's r+, fixed many nits.

Bulk response to the various reviews & feedbacks - 

(In reply to Mark Hammond [:markh] from comment #34)
> Comment on attachment 8409333 [details] [diff] [review]
> Part 3 - Add parameter substitution and error formatting to Log.jsm (tests
> fixed)
> 
> Review of attachment 8409333 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> Just a fairly quick pass, but looking good and useful - thanks!
> 
> ::: toolkit/modules/Log.jsm
> @@ +209,5 @@
> >   */
> >  function LogMessage(loggerName, level, message, params) {
> >    this.loggerName = loggerName;
> >    this.level = level;
> > +  // If the message text is empty, or a string, or a String object, normal handling
> 
> This seems quite complex when it seems all you care about is the case of
> "typeof message == "object" && !params"?  Also, most of our code (and a few
> other style-guides I can fine on the net) doesn't have params for typeof.

The case of a 'new String()' parameter, instead of an unboxed string, is fairly obscure but I'd rather handle it just in case. I wrote the logic in that order so that the "normal" case was handled first, but that did make the if() condition a bit more complex. Would you prefer a simpler condition, but with the special case on the "true" side of the if() and the normal case on the false side? That comes out as:

  // Special case to handle "log.level(object)", for example logging a caught exception
  // without providing text or params
  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;
  }

According to our style guide, unary operators like 'typeof' should be parenthesised: https://developer.mozilla.org/en-US/docs/Mozilla/Developer_guide/Coding_Style, search for the second occurrence of 'typeof'. I agree that much of our code doesn't follow that guideline.

(that's what you get for making me check the style guide about changing
   }
   else {
 to
   } else {
;-> )

> @@ +536,5 @@
> > +  /**
> > +   * 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 any params have *not* been substituted
> 
> This comment is out-of-date now, right?  (ie, we don't substitute missing
> params any more IIUC)

Good catch, fixed.

> @@ +555,5 @@
> > +    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;
> 
> I wonder if this regex should be a global const?  I 1/2 expect it would be
> faster (although this could also be premature optimization...)
> 
> ::: toolkit/mozapps/extensions/internal/XPIProvider.jsm
> @@ +5793,5 @@
> >   */
> >  function UpdateChecker(aAddon, aListener, aReason, aAppVersion, aPlatformVersion) {
> > +  if (!aListener || !aReason) {
> > +    throw Components.Exception("Missing arguments to UpdateChecker", Cr.NS_ERROR_INVALID_ARG);
> > +  }
> 
> I'm not sure if this change should be part of this patch (but I guess it's
> OK is gps or unfocussed are also able to review addons related changes and
> are happy with it)

Oops, I intended to remove that in the last update. Gone.


(In reply to Richard Newman [:rnewman] from comment #37)
> Comment on attachment 8409333 [details] [diff] [review]
> Part 3 - Add parameter substitution and error formatting to Log.jsm (tests
> fixed)
> 
> Review of attachment 8409333 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> Looks fine to me, so apologies for what I've missed!

All code nits addressed, lots of comment rewriting.
Attachment #8409333 - Attachment is obsolete: true
Attachment #8414498 - Flags: review+
https://hg.mozilla.org/mozilla-central/rev/3dd34ac40438
https://hg.mozilla.org/mozilla-central/rev/ea70694f55c8
https://hg.mozilla.org/mozilla-central/rev/b106aad655ad
Status: ASSIGNED → RESOLVED
Closed: 5 years ago
Resolution: --- → FIXED
Whiteboard: [fixed-in-fx-team]
Target Milestone: --- → mozilla32
Duplicate of this bug: 986689
Comment on attachment 8399777 [details] [diff] [review]
Part 1 - clean up some reference errors and newline handling

[Approval Request Comment]
Bug caused by (feature/regressing bug #): bug 661982
User impact if declined: Add-on Manager log messages do not contain error details, blocks uplift of bug 995027
Testing completed (on m-c, etc.): Has been on M-C for almost two weeks with no issues
Risk to taking this patch (and alternatives if risky): Low, alternative is not to uplift.
String or IDL/UUID changes made by this patch: None
Attachment #8399777 - Flags: approval-mozilla-aurora?
Comment on attachment 8408448 [details] [diff] [review]
Part 2 - Move exceptionStr() and stackTrace() from utils.js to Log.jsm

[Approval Request Comment]
Bug caused by (feature/regressing bug #): bug 661982
User impact if declined: Add-on Manager log messages do not contain error details, blocks uplift of bug 995027
Testing completed (on m-c, etc.): Has been on M-C for almost two weeks with no issues
Risk to taking this patch (and alternatives if risky): Low, alternative is not to uplift.
String or IDL/UUID changes made by this patch: None
Attachment #8408448 - Flags: approval-mozilla-aurora?
Comment on attachment 8414498 [details] [diff] [review]
Part 3 - Add parameter substitution and error formatting to Log.jsm, r+ nits picked

[Approval Request Comment]
Bug caused by (feature/regressing bug #): bug 661982
User impact if declined: Add-on Manager log messages do not contain error details, blocks uplift of bug 995027; note that all three patches should uplift together.
Testing completed (on m-c, etc.): Has been on M-C for almost two weeks with no issues
Risk to taking this patch (and alternatives if risky): Low, alternative is not to uplift.
String or IDL/UUID changes made by this patch: None
Attachment #8414498 - Flags: approval-mozilla-aurora?
Attachment #8399777 - Flags: approval-mozilla-aurora? → approval-mozilla-aurora+
Attachment #8408448 - Flags: approval-mozilla-aurora? → approval-mozilla-aurora+
Attachment #8414498 - Flags: approval-mozilla-aurora? → approval-mozilla-aurora+
You need to log in before you can comment on or make changes to this bug.