1080859 - Make logcat console log messages one line if possible

Status: RESOLVED WONTFIX

(Firefox OS Graveyard :: General, defect)

Description

[Eric Rahm [:erahm]]

In bug 1060161 we made the stack location print on a separate line, we'd like to move that back to one line if we're not printing the full stack.

Comment 1

[Eric Rahm [:erahm]]

Attachment: Make logcat console log messages one line if possible

error, assert, and trace remain mult-line full stacks, everything else has the line appended. Example output:

D/Clock   ( 3892): Content JS DEBUG: stopwatch started debug! at sw_start (app://clock.gaiamobile.org/js/panels/stopwatch/main.js:61:6)
E/Clock   ( 3892): Content JS ERROR: this is an error! 
E/Clock   ( 3892):     at sw_start (app://clock.gaiamobile.org/js/panels/stopwatch/main.js:62:6)
E/Clock   ( 3892):     at Stopwatch.Panel.prototype.handleEvent (app://clock.gaiamobile.org/js/panels/stopwatch/main.js:358:18)

Comment 2

[Jan Keromnes [:janx]]

Comment on attachment 8502825 [details] [diff] [review]
Make logcat console log messages one line if possible

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

LGTM

::: b2g/components/ProcessGlobal.js
@@ +160,3 @@
>  
>        if (message.level == 'assert' || message.level == 'error' || message.level == 'trace') {
>          stackTrace = Array.map(message.stacktrace, formatStackFrame).join('\n');

Nit: Wouldn't `stackTrace = '\n' + Array.map(...)` remove the need for a `stackPrefix` variable?

Comment 3

[Eric Rahm [:erahm]]

Comment on attachment 8502825 [details] [diff] [review]
Make logcat console log messages one line if possible

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

::: b2g/components/ProcessGlobal.js
@@ +160,3 @@
>  
>        if (message.level == 'assert' || message.level == 'error' || message.level == 'trace') {
>          stackTrace = Array.map(message.stacktrace, formatStackFrame).join('\n');

Unfortunately it wouldn't handle the empty stacktrace case.

Comment 4

[Dave Hylands [:dhylands]]

Comment on attachment 8502825 [details] [diff] [review]
Make logcat console log messages one line if possible

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

So I find the one line format to a HUGE improvement (so r+ for that), but sadly, still alot less readable than what I had before, so I'm changing my app to use dump rather than console.log.

This is what I see with this patch:
> I/Device Storage Test( 1224): Content JS LOG: Testing storage [sdcard]     at log (app://ds-test.gaiamobile.org/js/ds-test.js:553:2)
> I/Device Storage Test( 1224): Content JS LOG: Testing storage [sdcard1]     at log (app://ds-test.gaiamobile.org/js/ds-test.js:553:2)
> I/Device Storage Test( 1224): Content JS LOG: Enumerate for type 'sdcard' dir = 'undefined'     at log (app://ds-test.gaiamobile.org/js/ds-test.js:553:2)
> I/Device Storage Test( 1224): Content JS LOG: Processing sdcard     at log (app://ds-test.gaiamobile.org/js/ds-test.js:553:2)
> I/Device Storage Test( 1224): Content JS LOG: Enumerate for type 'sdcard' sdcard     at log (app://ds-test.gaiamobile.org/js/ds-test.js:553:2)
> I/Device Storage Test( 1224): Content JS LOG:   /sdcard/DCIM/100MZLLA/IMG_0003.jpg image/jpeg     at log (app://ds-test.gaiamobile.org/js/ds-test.js:553:2)
> I/Device Storage Test( 1224): Content JS LOG:   /sdcard/DCIM/100MZLLA/IMG_0002.jpg image/jpeg     at log (app://ds-test.gaiamobile.org/js/ds-test.js:553:2)
> I/Device Storage Test( 1224): Content JS LOG:   /sdcard/DCIM/100MZLLA/IMG_0004.jpg image/jpeg     at log (app://ds-test.gaiamobile.org/js/ds-test.js:553:2)
> I/Device Storage Test( 1224): Content JS LOG:   /sdcard/DCIM/100MZLLA/IMG_0001.jpg image/jpeg     at log (app://ds-test.gaiamobile.org/js/ds-test.js:553:2)
> I/Device Storage Test( 1224): Content JS LOG:   /sdcard/downloads/02-Case.jpg.jpeg image/jpeg     at log (app://ds-test.gaiamobile.org/js/ds-test.js:553:2)
> I/Device Storage Test( 1224): Content JS LOG:   /sdcard/downloads/03-Face-Faceplate.jpg.jpeg image/jpeg     at log (app://ds-test.gaiamobile.org/js/ds-test.js:553:2)
> I/Device Storage Test( 1224): Content JS LOG:   /sdcard/downloads/01-Base.jpg.jpeg image/jpeg     at log (app://ds-test.gaiamobile.org/js/ds-test.js:553:2)
> I/Device Storage Test( 1224): Content JS LOG:   /sdcard/downloads/01-Phantom.jpg.jpeg image/jpeg     at log (app://ds-test.gaiamobile.org/js/ds-test.js:553:2)
> I/Device Storage Test( 1224): Content JS LOG:   /sdcard/downloads/01-First-Pens.jpg.jpeg image/jpeg     at log (app://ds-test.gaiamobile.org/js/ds-test.js:553:2)
> I/Device Storage Test( 1224): Content JS LOG: Processing sdcard1     at log (app://ds-test.gaiamobile.org/js/ds-test.js:553:2)
> I/Device Storage Test( 1224): Content JS LOG: Enumerate for type 'sdcard' sdcard1     at log (app://ds-test.gaiamobile.org/js/ds-test.js:553:2)
> I/Device Storage Test( 1224): Content JS LOG:   /sdcard1/foo      at log (app://ds-test.gaiamobile.org/js/ds-test.js:553:2)
> I/Device Storage Test( 1224): Content JS LOG:   /sdcard1/shell.py      at log (app://ds-test.gaiamobile.org/js/ds-test.js:553:2)
> I/Device Storage Test( 1224): Content JS LOG:   /sdcard1/cmd.py      at log (app://ds-test.gaiamobile.org/js/ds-test.js:553:2)
> I/Device Storage Test( 1224): Content JS LOG:   /sdcard1/boot.py      at log (app://ds-test.gaiamobile.org/js/ds-test.js:553:2)
> I/Device Storage Test( 1224): Content JS LOG:   /sdcard1/sdcard1      at log (app://ds-test.gaiamobile.org/js/ds-test.js:553:2)

and this is what I see when I use dump (which is what I'm moving to, since I consider this to be much more readable).

> I/GeckoDump( 1169): Testing storage [sdcard]
> I/GeckoDump( 1169): Testing storage [sdcard1]
> I/GeckoDump( 1169): Enumerate for type 'sdcard' dir = 'undefined'
> I/GeckoDump( 1169): Processing sdcard
> I/GeckoDump( 1169): Enumerate for type 'sdcard' sdcard
> I/GeckoDump( 1169):   /sdcard/DCIM/100MZLLA/IMG_0003.jpg image/jpeg
> I/GeckoDump( 1169):   /sdcard/DCIM/100MZLLA/IMG_0002.jpg image/jpeg
> I/GeckoDump( 1169):   /sdcard/DCIM/100MZLLA/IMG_0004.jpg image/jpeg
> I/GeckoDump( 1169):   /sdcard/DCIM/100MZLLA/IMG_0001.jpg image/jpeg
> I/GeckoDump( 1169):   /sdcard/downloads/02-Case.jpg.jpeg image/jpeg
> I/GeckoDump( 1169):   /sdcard/downloads/03-Face-Faceplate.jpg.jpeg image/jpeg
> I/GeckoDump( 1169):   /sdcard/downloads/01-Base.jpg.jpeg image/jpeg
> I/GeckoDump( 1169):   /sdcard/downloads/01-Phantom.jpg.jpeg image/jpeg
> I/GeckoDump( 1169):   /sdcard/downloads/01-First-Pens.jpg.jpeg image/jpeg
> I/GeckoDump( 1169): Processing sdcard1
> I/GeckoDump( 1169): Enumerate for type 'sdcard' sdcard1
> I/GeckoDump( 1169):   /sdcard1/foo 
> I/GeckoDump( 1169):   /sdcard1/shell.py 
> I/GeckoDump( 1169):   /sdcard1/cmd.py 
> I/GeckoDump( 1169):   /sdcard1/boot.py 
> I/GeckoDump( 1169):   /sdcard1/sdcard1 

I also compared how many bytes of log buffer the 2 approaches take.

The "new improved" version uses 3359 bytes of logcat buffer (this is looking at the binary format), where the version using dump takes 1445 (or 43%) of the logcat buffer.

Comment 5

[Jan Keromnes [:janx]]

Comment on attachment 8502825 [details] [diff] [review]
Make logcat console log messages one line if possible

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

Wait, will we really have 5 spaces between log message and "at"? That should probably be fixed prior to landing.

Also, I still don't think this patch is an improvement to readability. Having stack traces sometimes inline and sometimes broken out is confusing, whereas always broken out clearly separates messages from origin, geographically. Both get good readability.

Dave, since you removed all code origins from your new logs, I take it you're not interested in them, so you prefer if they trail off the right edge instead of taking valuable space from actual messages. I think your switching to `dump` was the right thing for your logs, but I don't think we should make origins hard to read for everyone.

Comment 6

[Eric Rahm [:erahm]]

(In reply to Jan Keromnes [:janx] from comment #5)
> Comment on attachment 8502825 [details] [diff] [review]
> Make logcat console log messages one line if possible
> 
> > I/Device Storage Test( 1224): Content JS LOG: Testing storage [sdcard]     at log (app://ds-test.gaiamobile.org/js/ds-test.js:553:2)
> 
> Wait, will we really have 5 spaces between log message and "at"? That should
> probably be fixed prior to landing.
> 
> Also, I still don't think this patch is an improvement to readability.
> Having stack traces sometimes inline and sometimes broken out is confusing,
> whereas always broken out clearly separates messages from origin,
> geographically. Both get good readability.
> 
> Dave, since you removed all code origins from your new logs, I take it
> you're not interested in them, so you prefer if they trail off the right
> edge instead of taking valuable space from actual messages. I think your
> switching to `dump` was the right thing for your logs, but I don't think we
> should make origins hard to read for everyone.

I'm okay with WONTFIXing this, I don't have a strong opinion either way.

Comment 7

[Dave Hylands [:dhylands]]

(In reply to Jan Keromnes [:janx] from comment #5)
> Comment on attachment 8502825 [details] [diff] [review]
> Make logcat console log messages one line if possible
> 
> > I/Device Storage Test( 1224): Content JS LOG: Testing storage [sdcard]     at log (app://ds-test.gaiamobile.org/js/ds-test.js:553:2)
> 
> Wait, will we really have 5 spaces between log message and "at"? That should
> probably be fixed prior to landing.
> 
> Also, I still don't think this patch is an improvement to readability.
> Having stack traces sometimes inline and sometimes broken out is confusing,
> whereas always broken out clearly separates messages from origin,
> geographically. Both get good readability.
> 
> Dave, since you removed all code origins from your new logs, I take it
> you're not interested in them, so you prefer if they trail off the right
> edge instead of taking valuable space from actual messages. I think your
> switching to `dump` was the right thing for your logs, but I don't think we
> should make origins hard to read for everyone.

So I think that there are several types of logging.

There is logging where you get some random log message interjected from a program mixed in with all of the rest of the random messages. These are ones where having the stack trace and/or source location might actually be useful.

Then there is logging, where the log messages are used to convey information to a command which was executed, (like here's a list of Wifi APs that was found). In this case, having the stacktrace and/or location of log is completely useless and detracts from readability.

So, what I'm really asking for, is that I as a logging author, have some choice. I really don't care what the API is called, I just want to be able to convey some information the way that I want to convey it, and I don't want a stack trace with every line (especially when its the same for a bunch of consecutive lines).

If we're looking to have a cohesive logging solution, then you really need to give the coders some choice here, and not just force things to be a particular way. Otherwise, it won't get used, and that kind of defeats the whole that you're trying to accomplish.

Comment 8

[Gabriele Svelto [:gsvelto] (PTO)]

(In reply to Dave Hylands [:dhylands] from comment #7)
> If we're looking to have a cohesive logging solution, then you really need
> to give the coders some choice here, and not just force things to be a
> particular way. Otherwise, it won't get used, and that kind of defeats the
> whole that you're trying to accomplish.

Since nobody mentioned it here I think that having stacks in console logs is not really such an important thing since we already have another way to get them:

console.log("Stuff happened here: " + (new Error()).stack + "\n");

So the code that needs a stack (typically error handles for unlikely situations) can already print it out easily. For the matter one can get the line number and file name in the same way by using Error.lineNumber and Error.fileName. The only limitation is that you can't wrap them into an helper which is not super convenient.

Comment 9

[Eric Rahm [:erahm]]

(In reply to Gabriele Svelto [:gsvelto] from comment #8)
> Since nobody mentioned it here I think that having stacks in console logs is
> not really such an important thing since we already have another way to get
> them:
> 
> console.log("Stuff happened here: " + (new Error()).stack + "\n");
> 
> So the code that needs a stack (typically error handles for unlikely
> situations) can already print it out easily. For the matter one can get the
> line number and file name in the same way by using Error.lineNumber and
> Error.fileName. The only limitation is that you can't wrap them into an
> helper which is not super convenient.

This is a good point, we certainly can grab a stack manually. It does have some performance implications (and usability I guess). The console logging code already grabs a stack trace internally, but it delays actually processing it for performance reasons. So we'd be duplicating that effort and would add overhead for something that may not actually be logged (once we have configurable log levels). 

What would be really nice is if we could have a "no stack trace" option, but I'm not sure how we'd implement that. Although I guess it's already implemented in dumps() so perhaps this really is a non-issue. Perhaps we could treat |console.debug| similar to dumps() and just not add stack entry to that function (and of course the dev console would still have access to the stack trace).

For Dave's case above in comment #4 it does seem like we're overly verbose. Perhaps getting rid of the "Content JS LOG:" prefix would help. I kept that around b/c multiple console functions map to the same syslog level (info, etc) but maybe it's not really necessary. We know it's "Content JS" b/c of the log location is appended so that certainly could go.

Also as another workaround, building up a larger string and logging that would give somewhat cleaner output for Dave's use case.

Comment 10

[Dave Hylands [:dhylands]]

Printing the location first, and then printing the variable width log would also yield something more readable:

> I/Device Storage Test( 1224): (app://ds-test.gaiamobile.org/js/ds-test.js:553:2): Testing storage [sdcard]
> I/Device Storage Test( 1224): (app://ds-test.gaiamobile.org/js/ds-test.js:553:2): Testing storage [sdcard1]
> I/Device Storage Test( 1224): (app://ds-test.gaiamobile.org/js/ds-test.js:553:2): Enumerate for type 'sdcard' dir = 'undefined'
> I/Device Storage Test( 1224): (app://ds-test.gaiamobile.org/js/ds-test.js:553:2): Processing sdcard
> I/Device Storage Test( 1224): (app://ds-test.gaiamobile.org/js/ds-test.js:553:2): Enumerate for type 'sdcard' sdcard
> I/Device Storage Test( 1224): (app://ds-test.gaiamobile.org/js/ds-test.js:553:2):   /sdcard/DCIM/100MZLLA/IMG_0003.jpg image/jpeg
> I/Device Storage Test( 1224): (app://ds-test.gaiamobile.org/js/ds-test.js:553:2):   /sdcard/DCIM/100MZLLA/IMG_0002.jpg image/jpeg
> I/Device Storage Test( 1224): (app://ds-test.gaiamobile.org/js/ds-test.js:553:2):   /sdcard/DCIM/100MZLLA/IMG_0004.jpg image/jpeg
> I/Device Storage Test( 1224): (app://ds-test.gaiamobile.org/js/ds-test.js:553:2):   /sdcard/DCIM/100MZLLA/IMG_0001.jpg image/jpeg
> I/Device Storage Test( 1224): (app://ds-test.gaiamobile.org/js/ds-test.js:553:2):   /sdcard/downloads/02-Case.jpg.jpeg image/jpeg
> I/Device Storage Test( 1224): (app://ds-test.gaiamobile.org/js/ds-test.js:553:2):   /sdcard/downloads/03-Face-Faceplate.jpg.jpeg image/jpeg
> I/Device Storage Test( 1224): (app://ds-test.gaiamobile.org/js/ds-test.js:553:2):   /sdcard/downloads/01-Base.jpg.jpeg image/jpeg
> I/Device Storage Test( 1224): (app://ds-test.gaiamobile.org/js/ds-test.js:553:2):   /sdcard/downloads/01-Phantom.jpg.jpeg image/jpeg
> I/Device Storage Test( 1224): (app://ds-test.gaiamobile.org/js/ds-test.js:553:2):   /sdcard/downloads/01-First-Pens.jpg.jpeg image/jpeg
> I/Device Storage Test( 1224): (app://ds-test.gaiamobile.org/js/ds-test.js:553:2): Processing sdcard1
> I/Device Storage Test( 1224): (app://ds-test.gaiamobile.org/js/ds-test.js:553:2): Enumerate for type 'sdcard' sdcard1
> I/Device Storage Test( 1224): (app://ds-test.gaiamobile.org/js/ds-test.js:553:2):   /sdcard1/foo
> I/Device Storage Test( 1224): (app://ds-test.gaiamobile.org/js/ds-test.js:553:2):   /sdcard1/shell.py
> I/Device Storage Test( 1224): (app://ds-test.gaiamobile.org/js/ds-test.js:553:2):   /sdcard1/cmd.py
> I/Device Storage Test( 1224): (app://ds-test.gaiamobile.org/js/ds-test.js:553:2):   /sdcard1/boot.py
> I/Device Storage Test( 1224): (app://ds-test.gaiamobile.org/js/ds-test.js:553:2):   /sdcard1/sdcard1

Comment 11

[Gabriele Svelto [:gsvelto] (PTO)]

(In reply to Dave Hylands [:dhylands] from comment #10)
> Printing the location first, and then printing the variable width log would
> also yield something more readable:

+1

Comment 12

[Eric Rahm [:erahm]]

This has been dead a while, I'm going to WONTFIX it but if someone else wants to take up the cause feel free.