1060161 - ProcessGlobal should append stack traces to console.trace,assert,error messages

Status: RESOLVED FIXED

(Firefox OS Graveyard :: General, defect)

Description

[Eric Rahm [:erahm]]

When building up the log message in ProcessGlobal [1] we should append the stack information to trace, assert, and error messages.

I believe this can be done by accessing the |message.stacktrace| variable. This should be an array with the following fields availalble: functionName, filename, lineNumber.

[1] http://hg.mozilla.org/mozilla-central/annotate/2a15dc07ddaa/b2g/components/ProcessGlobal.js#l115

Comment 1

[Eric Rahm [:erahm]]

Attachment: Add stack trace to console.assert,error,trace messages

This generates a stack trace for the assert, error and trace log levels. The trace is then appended to the console message in the form:
  <function> :: <file>:<line>

Comment 2

[Eric Rahm [:erahm]]

Comment on attachment 8488938 [details] [diff] [review]
Add stack trace to console.assert,error,trace messages

Vivien it looks like you've reviewed this code before. I'm not set on the output format, so any comments on that would be great.

Comment 3

[Eric Rahm [:erahm]]

An example of the output:

E/Clock   (19808): Content JS ERROR at app://clock.gaiamobile.org/js/panels/stopwatch/main.js:62 in sw_start: this is an error! 
E/Clock   (19808):   sw_start :: app://clock.gaiamobile.org/js/panels/stopwatch/main.js:62
E/Clock   (19808):   Stopwatch.Panel.prototype.handleEvent :: app://clock.gaiamobile.org/js/panels/stopwatch/main.js:356
E/Clock   (19808): Content JS TRACE at app://clock.gaiamobile.org/js/panels/stopwatch/main.js:66 in sw_start: 
E/Clock   (19808):   sw_start :: app://clock.gaiamobile.org/js/panels/stopwatch/main.js:66
E/Clock   (19808):   Stopwatch.Panel.prototype.handleEvent :: app://clock.gaiamobile.org/js/panels/stopwatch/main.js:356
E/Clock   (19808): Content JS ASSERT at app://clock.gaiamobile.org/js/panels/stopwatch/main.js:67 in sw_start: One better not equal two 
E/Clock   (19808):   sw_start :: app://clock.gaiamobile.org/js/panels/stopwatch/main.js:67
E/Clock   (19808):   Stopwatch.Panel.prototype.handleEvent :: app://clock.gaiamobile.org/js/panels/stopwatch/main.js:356

Comment 4

[Vivien Nicolas (:vingtetun) (:21) - (NOT reading bugmails, needinfo? please)]

Comment on attachment 8488938 [details] [diff] [review]
Add stack trace to console.assert,error,trace messages

Moving the review to Janx, as he is more involved in devtools than me those days :)

Comment 5

[Jan Keromnes [:janx]]

Comment on attachment 8488938 [details] [diff] [review]
Add stack trace to console.assert,error,trace messages

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

Thanks a lot for this feature! The code generally looks good, but I'd like you to address two things first:

1) In the prefix, the "at" and "in" information already constitute a stack trace of depth 1:

Content JS ERROR at app://verticalhome.gaiamobile.org/js/configurator.js:66 in loadSingleVariantConf: IccHelper isn't enabled. SingleVariant configuration can't be loaded 
  loadSingleVariantConf :: app://verticalhome.gaiamobile.org/js/configurator.js:66
  onLoadInitJSON :: app://verticalhome.gaiamobile.org/js/configurator.js:154
  _xhrOnLoadFile :: app://verticalhome.gaiamobile.org/js/configurator.js:30

To avoid duplicating information ([e-mail]:66 is shown twice) and improve readability (both occurrences use different formats), please remove the "at" and "in" information from the prefix, and always define and push stackTrace. Use either depth=1 (just the "in" and "at" information you removed from the prefix), or depth=Infinite (iterating over message.stacktrace) in case of ASSERT, ERROR or TRACE. I'd suggest changing the `switch` to an `if/else`.

2) I'd suggest using the same stack trace format as the non-standard Error.prototype.stack[1]:

Firefox (or Safari) style would look like:

Content JS ERROR: IccHelper isn't enabled. SingleVariant configuration can't be loaded
loadSingleVariantConf@app://verticalhome.gaiamobile.org/js/configurator.js:66
onLoadInitJSON@app://verticalhome.gaiamobile.org/js/configurator.js:154
_xhrOnLoadFile@app://verticalhome.gaiamobile.org/js/configurator.js:30

Chrome style would look like:

Content JS ERROR: IccHelper isn't enabled. SingleVariant configuration can't be loaded
    at loadSingleVariantConf (app://verticalhome.gaiamobile.org/js/configurator.js:66)
    at onLoadInitJSON (app://verticalhome.gaiamobile.org/js/configurator.js:154)
    at _xhrOnLoadFile (app://verticalhome.gaiamobile.org/js/configurator.js:30)

I prefer Chrome style because I find it more readable for equivalent parsability, but I leave the choice up to you.

[1] http://wiki.ecmascript.org/doku.php?id=strawman:error_stack

Comment 6

[Jan Keromnes [:janx]]

P.S. Sorry to r- just for nits! The patch is great, but the nits felt slightly too big for an instant r+.

Comment 7

[Eric Rahm [:erahm]]

Attachment: Add stack trace to console.assert,error,trace messages

Jan, thanks for the quick review! I agree your proposed format is much cleaner, this should address both of your requests.

Output now looks like:
E/Clock   ( 2939): Content JS DEBUG: stopwatch started debug! 
E/Clock   ( 2939):     at sw_start (app://clock.gaiamobile.org/js/panels/stopwatch/main.js:61)
E/Clock   ( 2939): Content JS ERROR: this is an error! 
E/Clock   ( 2939):     at sw_start (app://clock.gaiamobile.org/js/panels/stopwatch/main.js:62)
E/Clock   ( 2939):     at Stopwatch.Panel.prototype.handleEvent (app://clock.gaiamobile.org/js/panels/stopwatch/main.js:356)
E/Clock   ( 2939): Content JS INFO: this is an info message 
E/Clock   ( 2939):     at sw_start (app://clock.gaiamobile.org/js/panels/stopwatch/main.js:63)
E/Clock   ( 2939): Content JS LOG: starting stopwatch! 
E/Clock   ( 2939):     at sw_start (app://clock.gaiamobile.org/js/panels/stopwatch/main.js:64)
E/Clock   ( 2939): Content JS WARN: You have been warned! 
E/Clock   ( 2939):     at sw_start (app://clock.gaiamobile.org/js/panels/stopwatch/main.js:65)
E/Clock   ( 2939): Content JS TRACE: 
E/Clock   ( 2939):     at sw_start (app://clock.gaiamobile.org/js/panels/stopwatch/main.js:66)
E/Clock   ( 2939):     at Stopwatch.Panel.prototype.handleEvent (app://clock.gaiamobile.org/js/panels/stopwatch/main.js:356)
E/Clock   ( 2939): Content JS ASSERT: One better not equal two 
E/Clock   ( 2939):     at sw_start (app://clock.gaiamobile.org/js/panels/stopwatch/main.js:67)
E/Clock   ( 2939):     at Stopwatch.Panel.prototype.handleEvent (app://clock.gaiamobile.org/js/panels/stopwatch/main.js:356)

Comment 8

[Jan Keromnes [:janx]]

Comment on attachment 8490227 [details] [diff] [review]
Add stack trace to console.assert,error,trace messages

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

Very nice! Thanks for addressing my nits.

::: b2g/components/ProcessGlobal.js
@@ +32,5 @@
>  
> +function formatStackFrame(aFrame) {
> +  let functionName = aFrame.functionName || '<anonymous>';
> +  return '    at ' + functionName +
> +         ' (' + aFrame.filename + ':' + aFrame.lineNumber + ')';

It's a shame that aFrame.columnNumber seems to never be defined here.

Comment 9

[Eric Rahm [:erahm]]

try: https://tbpl.mozilla.org/?tree=Try&rev=7d8ab2362e47

Comment 10

[Eric Rahm [:erahm]]

remote:   https://hg.mozilla.org/integration/mozilla-inbound/rev/2cdb665bcdd3

Comment 11

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

https://hg.mozilla.org/mozilla-central/rev/2cdb665bcdd3

Comment 12

[Dave Hylands [:dhylands]]

I got to see the new logging today, and personally I find the fact that the call site is listed on every single message makes the log completley unreadable.

For example:
> 15:26:14.189 5603/5603       Device Storage Test  I   Content JS LOG: Testing storage [sdcard]
> 15:26:14.189 5603/5603       Device Storage Test  I       at log (app://ds-test.gaiamobile.org/js/ds-test.js:542:2)
> 15:26:14.189 5603/5603       Device Storage Test  I   Content JS LOG: Testing storage [sdcard1]
> 15:26:14.189 5603/5603       Device Storage Test  I       at log (app://ds-test.gaiamobile.org/js/ds-test.js:542:2)
> 15:26:14.189 5603/5603       Device Storage Test  I   Content JS LOG: Free Space for type 'sdcard'
> 15:26:14.189 5603/5603       Device Storage Test  I       at log (app://ds-test.gaiamobile.org/js/ds-test.js:542:2)
> 15:26:14.199 5603/5603       Device Storage Test  I   Content JS LOG: Processing sdcard
> 15:26:14.199 5603/5603       Device Storage Test  I       at log (app://ds-test.gaiamobile.org/js/ds-test.js:542:2)
> 15:26:14.239 5603/5603       Device Storage Test  I   Content JS LOG:   sdcard = 3.84 GB
> 15:26:14.239 5603/5603       Device Storage Test  I       at log (app://ds-test.gaiamobile.org/js/ds-test.js:542:2)
> 15:26:14.239 5603/5603       Device Storage Test  I   Content JS LOG: Processing sdcard1
> 15:26:14.239 5603/5603       Device Storage Test  I       at log (app://ds-test.gaiamobile.org/js/ds-test.js:542:2)
> 15:26:14.819 5603/5603       Device Storage Test  I   Content JS LOG:   sdcard1 = 61.90 MB
> 15:26:14.819 5603/5603       Device Storage Test  I       at log (app://ds-test.gaiamobile.org/js/ds-test.js:542:2)

Since all of the gaia apps currently use some type of common logging function, including the call site is essentially useless.

I have no issues with having errors and warnings including the stack trace, but having it on all logging levels means I'll have to find some more readable way of logging.

This also more than doubles the amount of information being logged, which means we'll be getting less than half the amount of log that we got before.

Comment 13

[Eric Rahm [:erahm]]

(In reply to Dave Hylands [:dhylands] from comment #12)
> I got to see the new logging today, and personally I find the fact that the
> call site is listed on every single message makes the log completley
> unreadable.

I agree, it's certainly more verbose and a bit harder to grok. I do think it's still a step up from what we had.

> Since all of the gaia apps currently use some type of common logging
> function, including the call site is essentially useless.

We should be moving away from this scheme in favor of calling console.* directly, so hopefully that will be a non-issue.

> I have no issues with having errors and warnings including the stack trace,
> but having it on all logging levels means I'll have to find some more
> readable way of logging.

Yes currently we'll print the full stack for |assert|, |error|, and |trace|.

> This also more than doubles the amount of information being logged, which
> means we'll be getting less than half the amount of log that we got before.

This just is kind of true, the previous format including the location, just in a different format. If the logs are limited by lines, then yes it's a serious concern.

Perhaps a good middle ground here is to return to using one line for everything but assert, error, and trace. In example:

> 15:26:14.189 5603/5603       Device Storage Test  I   Content JS LOG: Testing storage [sdcard] at log (app://ds-test.gaiamobile.org/js/ds-test.js:542:2)

I think this works well for logcat output, and developers who want a nicer interactive format can still use the devtools console.

janx, what do you think of this suggestion?

Comment 14

[Dave Hylands [:dhylands]]

I think that having one line output is much more readable than having 2 lines.

I don't see why you would want to call console directly for debug output. Then you don't have any options to disable logging. Generally speaking we want debug style output off by default, and then you'd do something to enable it.

Comment 15

[Eric Rahm [:erahm]]

(In reply to Dave Hylands [:dhylands] from comment #14)
> I think that having one line output is much more readable than having 2
> lines.

Excellent, we'll see what janx thinks.

> I don't see why you would want to call console directly for debug output.
> Then you don't have any options to disable logging. Generally speaking we
> want debug style output off by default, and then you'd do something to
> enable it.

There was a discussion of this on dev-b2g already, that's probably the right forum to continue the conversation. In short I'd like to make per-app logging configurable so that depending on the level certain console functions become a no-op. ie:
>  if (Camera.log_level == WARN)
>    console.log = () => {};

Comment 16

[Jan Keromnes [:janx]]

> Perhaps a good middle ground here is to return to using one line for everything but assert, error, and trace.
> [...]
> janx, what do you think of this suggestion?

I don't mind a return to one-liners when only one call site is provided, even though I'm not particularly in favor of it.

15:26:14.189 5603/5603       Device Storage Test  I   Content JS LOG: Testing storage [sdcard] at log (app://ds-test.gaiamobile.org/js/ds-test.js:542:2)

These lines are generally long, so they will wrap. I don't think that makes them more readable than:

15:26:14.189 5603/5603       Device Storage Test  I   Content JS LOG: Testing storage [sdcard]
15:26:14.189 5603/5603       Device Storage Test  I       at log (app://ds-test.gaiamobile.org/js/ds-test.js:542:2)

For longer messages, I think one-liners are even less readable. Compare:

15:26:14.189 5603/5603       Device Storage Test  I   Content JS ERROR: IccHelper isn't enabled. SingleVariant configuration can't be loaded at loadSingleVariantConf (app://verticalhome.gaiamobile.org/js/configurator.js:66)

to:

15:26:14.189 5603/5603       Device Storage Test  I   Content JS ERROR: IccHelper isn't enabled. SingleVariant configuration can't be loaded
15:26:14.189 5603/5603       Device Storage Test  I       at loadSingleVariantConf (app://verticalhome.gaiamobile.org/js/configurator.js:66)

However, both options are inherently not very readable because there is so much clutter around the actual message, which you have to get used to locate "geographically" anyway. The devtools console should address readability needs.

If Dave prefers one-liners, I'm OK with that, and I'll leave it up to you to decide if the first call site should always be a one-liner, or if in a full stack trace it should remain on a separate line like the prior call sites.