Closed Bug 1060171 Opened 7 years ago Closed 6 years ago

logcat entries from console logging should use proper log level

Categories

(Core :: XPCOM, defect)

All
Gonk (Firefox OS)
defect
Not set
normal

Tracking

()

RESOLVED FIXED
mozilla35

People

(Reporter: erahm, Assigned: erahm)

Details

Attachments

(3 files, 4 obsolete files)

It looks like we'd probably want to modify |nsIConsoleMessage| to support a log level enum, then in ProcessGlobal we'd switch to using nsIConsoleMessage and set the enum.

A super hacky solution would be to parse the log message and extract the log level.
This is going to be a little tricky mapping all the console methods [1] to logcat levels. Below is my proposal.

Logcat provides:
  - Verbose
  - Debug
  - Information
  - Warning
  - Error

Console methods to map:
  - debug()  -> Debug
  - log()    -> Debug
  - info()   -> Information
  - error()  -> Error
  - trace()  -> Verbose? NB: this just prints a stack trace
  - warn()   -> Warning
  - assert() -> Error
  - count()  -> Debug
  - default  -> Debug (or maybe Info)

:janx, do you have any opinions on the mappings I've proposed? To be clear I'm talking about the logcat output level that can be used to filter logs in logcat and is prefixed to the log message. ie:
    (V|D|I|W|E)/AppName   (pid): message

[1] https://developer.mozilla.org/en-US/docs/Web/API/console#Methods
Flags: needinfo?(janx)
Strange, `adb logcat --help` seems to indicate that "Information" (*:I) is the default log level. However, running `adb logcat` with no command-line args or ANDROID_LOG_TAGS variable clearly shows me "Debug" messages. I think the documentation is lying.

That's a good thing, because most of the time when using logcat, you'll probably need at least a "Debug" level to understand what's happening. If that unspecified default level ever changes, many developers will be angry to see their console.logs disappearing, and the log tag syntax is not the most intuitive or well documented.

That being said, I mostly agree with your mapping. I would just:
- Bump the priority of log() to Information, just to be safe because it's used and relied on a lot.
- Promote trace() to Debug, because it seems strange to hide it alone at that low a priority.
- I guess you don't care about group() or dir() because they make no sense in logcat, but what about time() and timeEnd()? Maybe time(), timeEnd() and dir() (probably falls back to log()) should be Debug.
- I imagine that by "default" you mean new or non-standard log levels we can't predict? If that's the case Debug should be fine.
Flags: needinfo?(janx)
This adds a logLevel attribute to nsIConsoleMessage, supporting log level constants, and updates the implementations to expose the attribute.
Assignee: nobody → erahm
Status: NEW → ASSIGNED
Attached patch Part 2: Add nsIConsoleLogMessage (obsolete) — Splinter Review
This adds nsIConsoleLogMessage which exposes a method for explicitly setting a console message's log level. Concrete implementation and plumbing to expose it to JS are included.
This switches ProcessGlobal over to using the nsIConsoleLogMessage interface. Mapping of console methods to a log level is included.
This maps nsIConsoleMessage's log level to logcat priority level and uses that when outputting to logcat instead of always using the error level.
Comment on attachment 8491043 [details] [diff] [review]
Part 1: Add log levels to nsIConsoleMessage

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

The main change here is in nsIConsoleMessage.idl, the rest is just updating the implementing interfaces.
Attachment #8491043 - Flags: review?(nfroyd)
Attachment #8491044 - Flags: review?(nfroyd)
Comment on attachment 8491045 [details] [diff] [review]
Part 3: Set log level when forwarding to console service

Vivien can you take a look at this or suggestion someone else? It looks like janx is out on PTO. See comment 1 and comment 2 for background on the mapping decisions.
Attachment #8491045 - Flags: review?(21)
Comment on attachment 8491047 [details] [diff] [review]
Part 3: Map log level to logcat level in ConsoleService

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

Dave, can you take a look at this? The major change here is that we no longer default to ANDROID_LOG_ERROR. nsIScriptErrors will be output at warning or error level, console logs will use the appropriate level for each method as defined in attachment 8491045 [details] [diff] [review]. If a log level is not specified the default is info.
Attachment #8491047 - Flags: review?(dhylands)
Comment on attachment 8491043 [details] [diff] [review]
Part 1: Add log levels to nsIConsoleMessage

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

r=me with the below changes.

::: xpcom/base/nsConsoleMessage.cpp
@@ +53,5 @@
>    CopyUTF16toUTF8(mMessage, aResult);
>  
>    return NS_OK;
>  }
> +

Please delete this extra line.

::: xpcom/base/nsIConsoleMessage.idl
@@ +14,4 @@
>  interface nsIConsoleMessage : nsISupports
>  {
> +    /** Log level constants. */
> +    const unsigned short debug = 0;

Bikeshed color comment: I don't think there's any reason for these to be |short|, given that log messages are not really space-critical, and I think that uint16_t creates holes in nsConsoleLogMessage in part 2 anyway.  |unsigned int| would be fine.
Attachment #8491043 - Flags: review?(nfroyd) → review+
Comment on attachment 8491044 [details] [diff] [review]
Part 2: Add nsIConsoleLogMessage

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

Is there any reason not to just have nsConsoleMessage implement the additional nsIConsoleLogMessage interface, rather than copying the nsConsoleMessage implementation?
Attachment #8491044 - Flags: review?(nfroyd)
(In reply to Nathan Froyd (:froydnj) from comment #11)
> Comment on attachment 8491044 [details] [diff] [review]
> Part 2: Add nsIConsoleLogMessage
> 
> Review of attachment 8491044 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> Is there any reason not to just have nsConsoleMessage implement the
> additional nsIConsoleLogMessage interface, rather than copying the
> nsConsoleMessage implementation?

Excellent point!

Primarily because nsConsoleMessage wasn't exposed to JS, also originally I didn't have the log level in the base interface. It looks like I should be able to just add a contract ID and then get rid of a bunch of duplicated code. I'll update the patches with that change.
(In reply to Eric Rahm [:erahm] from comment #12)
> (In reply to Nathan Froyd (:froydnj) from comment #11)
> > Comment on attachment 8491044 [details] [diff] [review]
> > Part 2: Add nsIConsoleLogMessage
> > 
> > Review of attachment 8491044 [details] [diff] [review]:
> > -----------------------------------------------------------------
> > 
> > Is there any reason not to just have nsConsoleMessage implement the
> > additional nsIConsoleLogMessage interface, rather than copying the
> > nsConsoleMessage implementation?
> 
> Excellent point!
> 
> Primarily because nsConsoleMessage wasn't exposed to JS, also originally I
> didn't have the log level in the base interface. It looks like I should be
> able to just add a contract ID and then get rid of a bunch of duplicated
> code. I'll update the patches with that change.

I just remembered the primary issue: that would require adding some sort of |Init(message, level)| to nsIConsoleMessage and then we'd have to implement that in nsIScriptError too (which already has it's own conflicting Init methods).
Comment on attachment 8491047 [details] [diff] [review]
Part 3: Map log level to logcat level in ConsoleService

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

This looks reasonable to me. I didn't actually test it, so I'm assuming that it works :)
Attachment #8491047 - Flags: review?(dhylands) → review+
Instead of requiring a new interface we can just create a nsIConsoleMessage-like object. Nathan, can you take a look at this?
Attachment #8491842 - Flags: review?(nfroyd)
Attachment #8491045 - Attachment is obsolete: true
Attachment #8491045 - Flags: review?(21)
Attachment #8491044 - Attachment is obsolete: true
Attachment #8491047 - Attachment description: Part 4: Map log level to logcat level in ConsoleService → Part 3: Map log level to logcat level in ConsoleService
Comment on attachment 8491842 [details] [diff] [review]
Part 2: Set log level when forwarding to console service

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

r=me, but you may want to have a b2g-ish person take a look too.  (It's possible that including more XPCOM-ish stuff, like a QueryInterface property, etc., might make this faster, but I'll vote for holding off on that until we figure out whether this is a bottleneck.)

::: b2g/components/ProcessGlobal.js
@@ +151,5 @@
> +      // Create a nsIConsoleMessage-like object with the log level specified.
> +      let consoleMsg = {
> +        logLevel: getLogLevel(message),
> +        timeStamp: Date.now(),
> +        toString: () => prefix + Array.join(args, ' ')

I think it might be worth performing this concatenation outside of the closure, so we're not hanging onto |args| and |prefix| for the life of the object.
Attachment #8491842 - Flags: review?(nfroyd) → review+
I've switched over to using a proper class with a QI. Testing shows this to be faster than without.
Attachment #8491842 - Attachment is obsolete: true
Comment on attachment 8492412 [details] [diff] [review]
Part 2: Set log level when forwarding to console service

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

Nathan, I changed this enough that it's worth reviewing again. Vivien, I'm tagging you back in per Nathan's request.
Attachment #8492412 - Flags: review?(nfroyd)
Attachment #8492412 - Flags: review?(21)
Comment on attachment 8492412 [details] [diff] [review]
Part 2: Set log level when forwarding to console service

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

r=me with the fix below.

::: b2g/components/ProcessGlobal.js
@@ +158,5 @@
>          args.push('\n' + stackTrace);
>        }
>  
> +      let msg = 'Content JS ' + message.level.toUpperCase() + ': ' + Array.join(args, ' ');
> +      Services.console.logMessage(consoleMsg, new ConsoleMessage(msg, message.level));

Where is this 'consoleMsg' variable coming from?  Is this leftover from some testing?

logMessage is also being given too many arguments.
Attachment #8492412 - Flags: review?(nfroyd) → review+
Comment on attachment 8492412 [details] [diff] [review]
Part 2: Set log level when forwarding to console service

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

::: b2g/components/ProcessGlobal.js
@@ +158,5 @@
>          args.push('\n' + stackTrace);
>        }
>  
> +      let msg = 'Content JS ' + message.level.toUpperCase() + ': ' + Array.join(args, ' ');
> +      Services.console.logMessage(consoleMsg, new ConsoleMessage(msg, message.level));

Yes, sorry I messed up a qfold. It should just be .logMessage(new ConsoleMessage(...))
Updates from Nathan's review.
Attachment #8493247 - Flags: review?(21)
Attachment #8492412 - Attachment is obsolete: true
Attachment #8492412 - Flags: review?(21)
Comment on attachment 8493247 [details] [diff] [review]
Part 2: Set log level when forwarding to console service

Carrying forward r+ from froydnj.
Attachment #8493247 - Flags: review+
Comment on attachment 8493247 [details] [diff] [review]
Part 2: Set log level when forwarding to console service

Punting to Fabrice.
Attachment #8493247 - Flags: review?(21) → review?(fabrice)
Attachment #8493247 - Flags: review?(fabrice) → review+
You need to log in before you can comment on or make changes to this bug.