999898 - Add another log level = PR_LOG_VERBOSE to PRLogModuleLevel

Status: NEW

(NSPR :: NSPR, defect)

Description

[JW Wang [:jwwang] [:jw_wang]]

From the experience of debugging mochitest timeouts in content/media, sometimes we need to print log message per frame which is just too verbose and quickly flooding the whole screen. Can we add another log level, PR_LOG_VERBOSE to separate the very verbose debugging messages from those less verbose debugging messages of PR_LOG_DEBUG?

Comment 1

[Honza Bambas (:mayhemer)]

We already have 5 levels.  I suggest to use them in the code more structurally then to add 6th level.  I recently did something like that for nsHttp in bug 965031.  It should be made code-wide or finally move to something better then PR_LOG and have better structuring.

Comment 2

[Wan-Teh Chang]

JW: I took a quick look at the PRLogModuleLevel enum definition in prlog.h.
We can add new logging levels higher than PR_LOG_DEBUG without breaking
backward compatibility. However, it seems that PR_LOG_DEBUG is the verbose
logging level. I guess you want a logging level that is more verbose than
the debug (also known as "informational") logging level?

Another workaround is to use a separate logging module for the verbose log
messages. Would that work well for you?

Comment 3

[JW Wang [:jwwang] [:jw_wang]]

I would prefer one logging module to rule them all.

In a sense, the log messages are for debugging and different log level means different severity/importance for what the system could go wrong. Usually, we use PR_LOG_ERROR/PR_LOG_WARNING to indicate something wrong to the system, and use PR_LOG_DEBUG to trace the code flow or status/state of the system. Sometimes we need frame-level debugging where you have 30/60 frames per second while playing a media file. The huge amount of frame-level messages will quickly flood the screen/log file and make it hard to find useful information from it. Therefore I want to divide PR_LOG_DEBUG into 2 sub-levels which are less/more verbose ones (I would like to assign 5 to PR_LOG_VERBOSE).

Btw, PR_LOG_NONE looks strange to me which doesn't print nothing as the name suggested.

Comment 4

[Honza Bambas (:mayhemer)]

I'd be more comfortable you use a different module for your verbose messages.  PR_LOG is already enough complicated.  I can imagine some time later somebody will need PR_LOG_ULTRA_VERBOSE level...  and later PR_LOG_SUBATOMIC... and so on and on.


Personally I'd much more like to be able to make a module a super-module of another one.

A good use case would be our http logging that has several layers: channel/transaction/connection/conn-manager/socket-abstraction/nspr socket.  For the first 4 we have "nsHttp" and try to log channel on higher levels then transaction that should be on higher level then connection etc.  Gladly socket has a different module.

I'd like to be able to define a way that I only want to log only down to the transaction level, like NSPR_LOG_MODULES="nsHttp:transaction:5" and this would log all from channel and transaction layers of the hierarchy and I don't get flooded with all the connection crap I don't want to see at the moment.

Is this what would help your case too?

Comment 5

[JW Wang [:jwwang] [:jw_wang]]

That would be another thinking which turns a log level into another log module where you have one log module to print DEBUG/WARNING/ERROR messages and another to print VERBOSE messages no matter of the log level which seems a bit weird to me.

Since Android has 5 log levels (VERBOSE, DEBUG, INFO, WARN, ERROR), I would still be comfortable if we can remove PR_LOG_NONE which seems useless and put PR_LOG_VERBOES = 5 in. We still have 5 log levels.

Comment 6

[Chris Pearce [:cpearce (Not reading bugmail)]]

I'd rather not add another NSPR log module to our code, because then we're just creating a duplicate logging framework in order to increase the verbosity of logging on the same logical module. We have a perfectly good and mature logging module already here, and it looks like we only need to change one header to affect this change in a backwards compatible way.

I note that people (roc no less) are already using PR_LOG_DEBUG+1 in order to work around this limitation:

http://dxr.mozilla.org/mozilla-central/search?tree=mozilla-central&q=PR_LOG_DEBUG%2B1&redirect=true

I also note that GStreamer has 9 distinct logging levels (though I think only 8 are used in practice):
http://gstreamer.freedesktop.org/data/doc/gstreamer/head/gstreamer/html/gst-running.html

Comment 7

[Chris Pearce [:cpearce (Not reading bugmail)]]

Honza, I noticed that in Bug 965031 attachment 8371759 [details] [diff] [review] you actually log on NSPR_LOG_LEVEL=5, when the maximum PR_LOG_DEBUG=4. You're doing exactly what we're asking to do, except we're trying to get the API changed so we can do it in a manner blessed by the API.

Comment 8

[Honza Bambas (:mayhemer)]

(In reply to Chris Pearce (:cpearce) from comment #7)
> Honza, I noticed that in Bug 965031 attachment 8371759 [details] [diff] [review]
> [review] you actually log on NSPR_LOG_LEVEL=5, when the maximum
> PR_LOG_DEBUG=4. You're doing exactly what we're asking to do, except we're
> trying to get the API changed so we can do it in a manner blessed by the API.

Yup, this convinces me.  Note that everybody is using 5 and I always tell people to do moduleName:_5_ when asking for logs.  I didn't realize that 5 is actually behind what we define as regular levels.  So, yes, let's add a new one.  I was just hoping for something smarter here...

Comment 9

[JW Wang [:jwwang] [:jw_wang]]

Hi Wan-Teh,
Per our discussion, is it OK to add PR_LOG_VERBOSE to the log levels?

Comment 10

[JW Wang [:jwwang] [:jw_wang]]

Attachment: 999898_add_verbose_log_level.patch

Per our discussion, add another log level for verbose messages.

Comment 11

[BugBot [:suhaib / :marco/ :calixte]]

Clear a needinfo that is pending on an inactive user.

For more information, please visit auto_nag documentation.

Comment 12

[BugBot [:suhaib / :marco/ :calixte]]

The bug assignee is inactive on Bugzilla, so the assignee is being reset.