[racket-dev] (reposted from users) Noisy compiler at PLTSTDERR=info

At Wed, 21 Jan 2015 11:22:38 -0500, Tony Garnock-Jones wrote:
> Over the past few months, more and more subsystems have started logging
> at info level as part of regular compilation.
> 
> I prefer having PLTSTDERR=info in order to catch log-info that happens
> at runtime, and find the compile-time log output quite distracting.
> 
> My current workaround is to set
> 
> PLTSTDERR="info warning at cm warning at compiler/cm warning at module-prefetch
> warning at setup/parallel-build warning at cm-accomplice
> warning at online-check-syntax"
> 
> but this is quite verbose, and as subsystem log messages come and go
> I'll need to keep updating it.
> 
> Could one of the following ideas be worth exploring?
> 
>  1. Have a superlogger for these (and other?) compile-time-ish loggers,
>     so that I could write "info warning at compilation", excluding the
>     noise in one fell swoop
> 
>  2. Have a phase number associated with logging, so I could say
>     "info at 0 warning at 1", or similar

I have a suggestion below, but it's based on a guess of what you really
want, and it might be a bad guess.


Here's my train of thought:

On 1 above: I've been uncertain of the best way to organize logging
from the start, but the idea of grouping topics hierarchically (such as
a "compilation" topic group) doesn't sound promising. The original
implementation had a notion of hierarchy that I thought might play out
this way, but it didn't. Overall, it seems to be difficult to fit
topics into a hierarchy a priori, in much the same way that it has been
difficult or awkward to group exceptions hierarchically (and few Racket
libraries attempt to extend the exception hierarchy). I guess there's
often a mismatch between the producer's original idea of organization
the and consumer's eventual idea.

On 2 above: I'm not sure why compilation or phase 1 is special. As more
and more libraries use logging, it seems like they will generate noise
(from your perspective) at run time, too.


More generally:

The most successful step in the logging system's evolution was the move
toward "<level>@<topic>" specifications that include specific <topic>s
of interest. In a growing sea of information, knowing which pieces you
want and specifying those pieces makes sense. Trying to exclude a
category of information is much harder, because it's hard to know all
the information that will be available to exclude.

At the same time, it makes sense to have "error" messages visible all
the time for all topics, because users should see errors that they
didn't anticipate. Similarly, it makes sense for a user to request
extra unanticipated information at the "warning" level.

In this sense, the "info" label is ambiguous. The "info" level could be
like "warning": information that a human consumer might be interested
in without anticipating it, but (unlike "warning") not a suggestion of
a problem. Or "info" could be more like "debug": details that are only
useful when you're looking closely at a specific subsystem. A potential
distinction between "info" and "debug" is that the former makes sense
to the consumer of the subsystem as opposed to the producer.

My only idea, then, is that we're missing a level somewhere between
"debug" and "warning". My guess is that you're getting too much
information from "info", because you wanted a human-volume level of
status information; sometimes "info" is used for that. Other uses of
"info" are more like "debug" --- not really human-volume --- and that's
the part you don't want to see. It happens that many of the current
"debug"-like uses of "info" are in compilation subsystems.

If I'm guessing right, then we could introduce a new level and sort out
existing uses:

 * fatal - last-ditch communication channel before termination
 * error - errors
 * warning - info for humans that alerts a potential mistake
 * info - info for humans on status and progress
 * detail - info for subsystem consumers, not necessarily human-volume
 * debug - info for subsystem implementers, not necessarily human-volume

The idea is that most of the compilation messages could move to
"detail". (Or maybe it makes sense to add the level between "info" and
"warning"; it becomes a transition and compatibility question as much
as anything.)

In retrospect, I realize that I've often struggled with choosing "info"
vs. "debug" levels precisely because I haven't been clear on which is
meant as human-volume --- or even that it makes sense to consider a
human-volume vs. machine-volume distinction. Other times, I've
struggled with "info" vs. "debug" because of a internal vs. external
distinction.


Does any of that connect to your actual situation and goals?