On Thu, May 21, 2015 at 7:06 PM, Eric Rahm <er...@mozilla.com> wrote:
> As part of the effort to improve logging in gecko we'd like to introduce a
> new set of unified log levels.
>
> Currently we use NSPR logging which defines the following log levels:
>
> typedef enum PRLogModuleLevel {
> PR_LOG_NONE = 0, /* nothing */
> PR_LOG_ALWAYS = 1, /* always printed */ <---- lies,
> damned lies
> PR_LOG_ERROR = 2, /* error messages */
> PR_LOG_WARNING = 3, /* warning messages */
> PR_LOG_DEBUG = 4, /* debug messages */
>
> PR_LOG_NOTICE = PR_LOG_DEBUG, /* notice messages */
> PR_LOG_WARN = PR_LOG_WARNING, /* warning messages */
> PR_LOG_MIN = PR_LOG_DEBUG, /* minimal debugging messages */
> PR_LOG_MAX = PR_LOG_DEBUG /* maximal debugging messages */
> } PRLogModuleLevel;
>
> After a rather thorough examination of usages of each I have come up with
> a set that I believe would fit our needs:
>
> enum class LogLevel {
> Disabled = 0, // Logging is disabled for this module
> Error,
> Warning,
> Info,
> Debug,
> };
>
> This subset maps rather nicely to syslog and web console logging levels:
>
> | Level | PR_LOG | Console | Syslog |
> |---------|----------------|-------------------|---------|
> | Error | PR_LOG_ERROR | console.error() | error |
> | Warning | PR_LOG_WARNING | console.warn() | warning |
> | Info | n/a | console.info() | info |
> | Debug | PR_LOG_DEBUG | console.debug()* | debug |
>
> This removes all of the various PR_LOG aliases as well as |PR_LOG_ALWAYS|.
> It adds a generic |Info| level.
>
> *PR_LOG_ALWAYS*
>
> This really didn't mean what most uses thought it meant. Specifying
> |PR_LOG_ALWAYS| did not in fact mean your message was always logged, it
> just mean it was logged if at least log level 1 was specified. By default
> every logger has output disabled.
>
> For most instances it can be replaced with |Info|, a more generic log
> category that is slightly more important than |Debug|, but not an error or
> warning.
>
> *PR_LOG_DEBUG + 1 aka log level 5*
>
> Various bits of code invented a log level that was less important than
> debug (I would call this verbose). This was not specified in NSPR logging,
> but just kind of worked. With the addition of |Info| we can transition code
> that was using this pseudo log level to:
> - map PR_LOG_DEBUG => Info
> - map PR_LOG_DEBUG + 1 => Debug
>
> In this case we could have added a |Verbose| log level, but with the
> addition of |Info| and feeling that fewer is better we have decided against
> that.
>
> *How will log levels be controlled?*
>
> Similar to how it works now (if not terribly clear), turning on:
> - LogLevel::Error => Error messages will be printed
> - LogLevel::Warning => Error and Warning messages will be printed
> - LogLevel::Info => Error, Warning, and Info messages will be printed
> - LogLevel::Debug => Error, Warning, Info, and Debug messages will be
> printed
>
> As a future improvement we plan to add the ability to toggle this levels
> at runtime.
>
> Please let me know of any concerns or input you may have.
>
Better than a log level is an event type (possibly enumerated). When people
are looking at log output, they want to see specific events. While
filtering by the logger is a good way to limit/expand logging, I find that
this approach is often limiting, even when log levels are used. This
especially holds true when using the most verbose settings and output is
spammy. You end up writing tons of grep chains to sort through the mess.
To aid in complex debugging scenarios, I find it helpful for each logged
event to have an explicit type. That way, consumers can cherry pick exactly
what events they want to see. This is much more powerful than course levels
and/or logger names.
And, once you have explicit types for each logged event, it is easier to
transition to a structured logging mechanism. I could see this being useful
to e.g. automatically collect and analyze logs from client machines in the
wild. It's much easier to perform machine analysis on structured data than
unstructured. I could also see this being used for telemetry collection.
Imagine if telemetry were gathered from sniffing for specific messages on
the logging bus instead of having to instrument new telemetry probes
everywhere. But this last paragraph is scope bloat :)
_______________________________________________
dev-platform mailing list
dev-platform@lists.mozilla.org
https://lists.mozilla.org/listinfo/dev-platform
