Proper loglevels: cmd-line option --loglevel=NONE/ERROR/WARN/PROGRESS/INFO/DEBUG

Proper loglevels: cmd-line option --loglevel=NONE/ERROR/WARN/PROGRESS/INFO/DEBUG

Allow the user to specify which messages (s)he wants to see on stderr:
The lilypond code basically stays the same, I only added a loglevel
global variable, which is used in the warning/error*/progress*/success
functions (ly:warning, ly:error, etc. in Scheme). If the proper level
is not set for a message, it is not printed.

There are only two larger changes:
-) Global var be_verbose_global replaced by loglevel (much finer-grained)
-) New functions (full)debug_output, which replaces code like:
   if (be_verbose_global) {
	   progress_indication (...)
	 }

All changes were done to warn.cc and to the member of the Input class
(apparently, we have two parallel error-reporting "frameworks" in
lilypond...).

Note for all functions in warn.cc (not for the members of Input):
The debug_output function (and progress_indication and message) have
an optional argument to specify whether the output of the message
should always start on a new line or continue the previous output.

Documentation for this new feature is still missing (both in the AU
as well as in the CG).

[Reinhold, 2011-07-29 19:51:00]

http://codereview.appspot.com/4822055/diff/1/lily/main.cc
File lily/main.cc (right):

http://codereview.appspot.com/4822055/diff/1/lily/main.cc#newcode170
lily/main.cc:170: {0, "silent", 's', _i ("no progress, only error messages
(equivalent to log=ERROR)")},
Should be: loglevel=ERROR

http://codereview.appspot.com/4822055/diff/1/lily/main.cc#newcode172
lily/main.cc:172: {0, "verbose", 'V', _i ("be verbose (equivalent to
log=DEBUG)")},
Should be: loglevel=DEBUG

http://codereview.appspot.com/4822055/diff/1/lily/main.cc#newcode651
lily/main.cc:651: if (isatty (STDIN_FILENO) && (loglevel & LOG_INFO))
It's up for debate whether we want the lilypond version printed with LOG_WARN
and LOG_ERROR (i.e. the user only wants warnings and/or errors, nothing else).
For LOG_NONE we definitely don't want it printed.

http://codereview.appspot.com/4822055/diff/1/lily/program-option-scheme.cc
File lily/program-option-scheme.cc (right):

http://codereview.appspot.com/4822055/diff/1/lily/program-option-scheme.cc#ne...
lily/program-option-scheme.cc:259: "Was berbose output requested, i.e. loglevel
at least @code{DEBUG}?")
should be "verbose"

http://codereview.appspot.com/4822055/diff/1/lily/relocate.cc
File lily/relocate.cc (right):

http://codereview.appspot.com/4822055/diff/1/lily/relocate.cc#newcode72
lily/relocate.cc:72: // this warning should only be printed in debug mode!
The reason for this comment is that we can't simply use debug_output, because we
really want "Warning:" printed with the message!

[MikeSol, 2011-07-29 20:28:40]

LGTM.

Cheers,
MS

[Reinhold, 2011-07-29 20:46:33]

http://codereview.appspot.com/4822055/diff/1/lily/input.cc
File lily/input.cc (right):

http://codereview.appspot.com/4822055/diff/1/lily/input.cc#newcode87
lily/input.cc:87: ::print_message (s);
Can leave out the :: here

http://codereview.appspot.com/4822055/diff/1/lily/main.cc
File lily/main.cc (right):

http://codereview.appspot.com/4822055/diff/1/lily/main.cc#newcode587
lily/main.cc:587: non_fatal_error (_f ("unknown log level `%s' given, using
default (PROGRESS)", option_parser->optional_argument_str0_));
Will shorten that long line

http://codereview.appspot.com/4822055/diff/1/lily/relocate.cc
File lily/relocate.cc (left):

http://codereview.appspot.com/4822055/diff/1/lily/relocate.cc#oldcode135
lily/relocate.cc:135: warning (_f ("Relocation: compile datadir=%s, new
datadir=%s",
This warning (and the following warnings) should have never been warnings in the
first place. They are simple debug output about the relocation settings.

http://codereview.appspot.com/4822055/diff/1/scm/backend-library.scm
File scm/backend-library.scm (left):

http://codereview.appspot.com/4822055/diff/1/scm/backend-library.scm#oldcode30
scm/backend-library.scm:30: (ly:progress "\n"))
(ly:progress "\n") does not have any effect. So far, it called message(..),
where the first thing was 
if (s=="\n") 
  return;

http://codereview.appspot.com/4822055/diff/1/scm/lily.scm
File scm/lily.scm (right):

http://codereview.appspot.com/4822055/diff/1/scm/lily.scm#newcode115
scm/lily.scm:115: "Value of the --log level flag (read-only).")
should be --loglevel

[hanwenn, 2011-07-30 16:28:31]

overall commment: the parts that do the reporting should not need to know about
the format of loglevel.  

I think it would be better to have a

  if (log(ERROR)) 
  {
    ..
  }

or perhaps even

  log(ERROR, "...")

rather than having each bit do the bitmasking separately like in this patch.

[Ian Hulin (gmail), 2011-07-30 17:10:00]

FWIW LGTM apart from attached comments,

I'm currently working on main.cc and lily.scm as part of T1686, and may need
help with merging if this patch gets pushed first.

Is your current design extensible to allow us to segment the old verbose option
by function as well as debug trace level? 

Maybe have a --tracelevel option with values like INITIALIZE, PATH, FONTS,
SCHEME_DEBUG which would OR bits in the upper byte of loglevel.  That way we
could have even finer control of the --loglevel=DEBUG output.

http://codereview.appspot.com/4822055/diff/1/flower/warn.cc
File flower/warn.cc (right):

http://codereview.appspot.com/4822055/diff/1/flower/warn.cc#newcode86
flower/warn.cc:86: exit (1);
Tell the user you're crashing with a fatal error:
error (string (s);
{
  if (loglevel & LOG_ERROR)
    print_message (_f ("fatal error: %s", s.c_str()) + "\n");
  exit (1); 
}

http://codereview.appspot.com/4822055/diff/1/lily/all-font-metrics.cc
File lily/all-font-metrics.cc (right):

http://codereview.appspot.com/4822055/diff/1/lily/all-font-metrics.cc#newcode91
lily/all-font-metrics.cc:91: debug_output ("[" + string (pango_fn), true); //
start on a new line
Why do the logging output in two calls?  Why not
 debug_output ("[" + string (pango_fn)+ "]", true); // start on a new line
	here and lose line 102?
Ian

http://codereview.appspot.com/4822055/diff/1/lily/all-font-metrics.cc#newcode102
lily/all-font-metrics.cc:102: debug_output ("]", false);
Add the "]" to the previous debug_output call and get rid of this line. (See
previous)

http://codereview.appspot.com/4822055/diff/1/lily/all-font-metrics.cc#newcode128
lily/all-font-metrics.cc:128: debug_output ("[" + file_name, true); // start on
a new line
As for line 91 - do all the output in this call and get rid of the other
debug_output call below

http://codereview.appspot.com/4822055/diff/1/lily/font-config.cc
File lily/font-config.cc (right):

http://codereview.appspot.com/4822055/diff/1/lily/font-config.cc#newcode56
lily/font-config.cc:56: debug_output (_f ("adding font directory: %s", dir.c_str
()));
Capitalize "Adding" - for consistency with other messages, which start
"Initializing..." and "Building..."

http://codereview.appspot.com/4822055/diff/1/lily/input.cc
File lily/input.cc (right):

http://codereview.appspot.com/4822055/diff/1/lily/input.cc#newcode94
lily/input.cc:94: print_message (_f ("error: %s", s));
print_message ( _f ("fatal error: %s", s));

Why do you pass s here and in the similar place in 
warn.cc you need to pass s.c_str()?

http://codereview.appspot.com/4822055/diff/1/lily/program-option-scheme.cc
File lily/program-option-scheme.cc (right):

http://codereview.appspot.com/4822055/diff/1/lily/program-option-scheme.cc#ne...
lily/program-option-scheme.cc:259: "Was berbose output requested, i.e. loglevel
at least @code{DEBUG}?")
On 2011/07/29 19:51:00, Reinhold wrote:
> should be "verbose"

Or maybe "Was full debug output requested, i.e. loglevel at least @code(DEBUG)?"

http://codereview.appspot.com/4822055/diff/1/lily/program-option-scheme.cc#ne...
lily/program-option-scheme.cc:271: 
Nice feature.
If you're allowing this to be accessed from Scheme, how about translating the
number back to the keyword value as input on the command line (NONE, PROGRESS,
...)

http://codereview.appspot.com/4822055/diff/1/scm/lily.scm
File scm/lily.scm (right):

http://codereview.appspot.com/4822055/diff/1/scm/lily.scm#newcode288
scm/lily.scm:288: ;;       a newline in this case
Needs to use guile %load-hook callback,
<<<<<<
(if (ly:loglevel <> 0) 
  (set! %load-hook (lambda (filename)
    (ly:debug ( _ "\t[Loading ~a] ...\n") filename))))

(define-public (ly:load x)
  (if (not file-name)
      (ly:error (_ "cannot find: ~A") x))
  (primitive-load-path file-name))
>>>>>>
ly:load is getting a re-write in any case as part of the fix for T1686

[Reinhold, 2011-07-30 17:51:18]

On 2011/07/30 17:10:00, Ian Hulin (gmail) wrote:
> I'm currently working on main.cc and lily.scm as part of T1686, and may need
> help with merging if this patch gets pushed first.

Sure, no problem. But AFAICS, the file loading and the path lists do not really
overlap with this patch, so merging should be easy.

> Is your current design extensible to allow us to segment the old verbose
option
> by function as well as debug trace level? 
> 
> Maybe have a --tracelevel option with values like INITIALIZE, PATH, FONTS,
> SCHEME_DEBUG which would OR bits in the upper byte of loglevel.  That way we
> could have even finer control of the --loglevel=DEBUG output.

Yes, that should be possible. The only thing is that currently I have only two
debugging functions (debug_output and fulldebug_output). We might extend this to

debug_output (DEBUG_LEVEL, "message"[, /*newline*/] );

Of course, it's not straightforward how to let the user specify the desired
debug level on the console (because the debug levels are no longer in ascending
verbosity, ie. one loglevel does not imply another, like WARN implies ERROR). So
we would need to provide a way to let the user specify an OR'ed loglevel on the
command line...

> http://codereview.appspot.com/4822055/diff/1/scm/lily.scm#newcode288
> ly:load is getting a re-write in any case as part of the fix for T1686

Okay, so I'll probably have to redo that function once you are finished with the
guile 2.0 stuff.

Cheers,
Reinhold

[Reinhold, 2011-07-30 17:52:34]

http://codereview.appspot.com/4822055/diff/1/lily/all-font-metrics.cc
File lily/all-font-metrics.cc (right):

http://codereview.appspot.com/4822055/diff/1/lily/all-font-metrics.cc#newcode91
lily/all-font-metrics.cc:91: debug_output ("[" + string (pango_fn), true); //
start on a new line
On 2011/07/30 17:10:00, Ian Hulin (gmail) wrote:
> Why do the logging output in two calls?  Why not
>  debug_output ("[" + string (pango_fn)+ "]", true); // start on a new line
> 	here and lose line 102?

Because the following four lines until the "]" might also print out some debug
output. We want to keep everything printed out by this one font inside the
brackets, so it's clear that the debug output is really from this font.

http://codereview.appspot.com/4822055/diff/1/lily/font-config.cc
File lily/font-config.cc (right):

http://codereview.appspot.com/4822055/diff/1/lily/font-config.cc#newcode56
lily/font-config.cc:56: debug_output (_f ("adding font directory: %s", dir.c_str
()));
On 2011/07/30 17:10:00, Ian Hulin (gmail) wrote:
> Capitalize "Adding" - for consistency with other messages, which start
> "Initializing..." and "Building..."

Thanks for spotting this. Previously this was a warning, which should start with
a lowercase letter. Now it's only debug output, so we need a capital.

http://codereview.appspot.com/4822055/diff/1/lily/input.cc
File lily/input.cc (right):

http://codereview.appspot.com/4822055/diff/1/lily/input.cc#newcode87
lily/input.cc:87: ::print_message (s);
On 2011/07/29 20:46:33, Reinhold wrote:
> Can leave out the :: here

No, I can't :(

http://codereview.appspot.com/4822055/diff/1/lily/input.cc#newcode94
lily/input.cc:94: print_message (_f ("error: %s", s));
On 2011/07/30 17:10:00, Ian Hulin (gmail) wrote:
> print_message ( _f ("fatal error: %s", s));
> 
> Why do you pass s here and in the similar place in 
> warn.cc you need to pass s.c_str()?

No idea, I simply copied the existing code without changes...
I can probably remove the .c_str() in warn.cc...

http://codereview.appspot.com/4822055/diff/1/lily/program-option-scheme.cc
File lily/program-option-scheme.cc (right):

http://codereview.appspot.com/4822055/diff/1/lily/program-option-scheme.cc#ne...
lily/program-option-scheme.cc:259: "Was berbose output requested, i.e. loglevel
at least @code{DEBUG}?")
On 2011/07/30 17:10:00, Ian Hulin (gmail) wrote:
> On 2011/07/29 19:51:00, Reinhold wrote:
> > should be "verbose"
> 
> Or maybe "Was full debug output requested, i.e. loglevel at least
@code(DEBUG)?"

That's ambiguous, as "fulldebug" is also a debuglevel stronger than just DEBUG.

http://codereview.appspot.com/4822055/diff/1/lily/program-option-scheme.cc#ne...
lily/program-option-scheme.cc:271: 
On 2011/07/30 17:10:00, Ian Hulin (gmail) wrote:
> Nice feature.
> If you're allowing this to be accessed from Scheme, how about translating the
> number back to the keyword value as input on the command line (NONE, PROGRESS,
> ...)

Or probably do it the other way round: Replace it with a function ly:loglevel?,
with one argument, returning whether the requested loglevel is set. E.g. (if
(ly:loglevel? 'PROGRESS) ....)

http://codereview.appspot.com/4822055/diff/1/scm/lily.scm
File scm/lily.scm (right):

http://codereview.appspot.com/4822055/diff/1/scm/lily.scm#newcode288
scm/lily.scm:288: ;;       a newline in this case
On 2011/07/30 17:10:00, Ian Hulin (gmail) wrote:
>     (ly:debug ( _ "\t[Loading ~a] ...\n") filename))))

Again, the reason for [ and ] printed at the beginning and at the very end of
this function is that all log messages printed out during loading will be
bracketed by [ ... ]. This makes it easier to see whether a message was caused
inside the loaded file or sometime after the loading.
> 
> (define-public (ly:load x)
>   (if (not file-name)
>       (ly:error (_ "cannot find: ~A") x))
>   (primitive-load-path file-name))
> >>>>>>
> ly:load is getting a re-write in any case as part of the fix for T1686

[reinhold_kainhofer.com, 2011-07-30 17:54:33]

Am Samstag, 30. Juli 2011, 18:28:32 schrieben Sie:
> overall commment: the parts that do the reporting should not need to
> know about the format of loglevel.

Which parts exactly do you mean? Those that call the error/message/warning 
functions, or the error/message/warning functions themselves?


> I think it would be better to have a
> 
>    if (log(ERROR))
>    {
>      ..
>    }

You mean in those few places where I need to use "if (loglevel & LOG_DEBUG)", 
because I can't call the debug_output function? That's a good idea to keep the 
internal structure of the loglevel only inside warn.cc and provide a helper 
function to access them.

> or perhaps even
> 
>    log(ERROR, "...")

Yes, that function is currently called non_fatal_error... Unfortunately, in 
some places there is additional code in the debug case (like creating the 
debug message as a string variable, or calling a different print function of 
an external library to print debug output). In these cases I need an if.

Or do you mean the "if (loglevel & ERROR)" checks inside the 
error/non_fatal_error/etc. function?
That would mean moving the logic whether to print a message or not to the 
print_message function, so it's centralized in just one spot. That also makes 
sense.

Cheers,
Reinhold
-- 
------------------------------------------------------------------
Reinhold Kainhofer, reinhold@kainhofer.com, http://reinhold.kainhofer.com/
 * Financial & Actuarial Math., Vienna Univ. of Technology, Austria
 * http://www.fam.tuwien.ac.at/, DVR: 0005886
 * LilyPond, Music typesetting, http://www.lilypond.org

[Carl, 2011-07-30 20:20:13]

I really like this -- thanks for taking it on.

Two small comments.

http://codereview.appspot.com/4822055/diff/1/lily/font-config-scheme.cc
File lily/font-config-scheme.cc (right):

http://codereview.appspot.com/4822055/diff/1/lily/font-config-scheme.cc#newco...
lily/font-config-scheme.cc:154: debug_output (_f ("adding font directory: %s",
d.c_str ()));
Adding? (Capitalized?)

http://codereview.appspot.com/4822055/diff/1/lily/font-config-scheme.cc#newco...
lily/font-config-scheme.cc:170: debug_output (_f ("adding font file: %s",
f.c_str ()));
Adding?

[pkx166h, 2011-07-30 22:18:36]

Passes make and reg test.

[Graham Percival (old account), 2011-08-03 19:52:24]

awesome work, I really love this.  Unfortunately it cannot apply directly to git
master due to fixcc.

[hanwenn, 2011-08-04 03:41:31]

On Sat, Jul 30, 2011 at 2:42 PM, Reinhold Kainhofer
<reinhold@kainhofer.com> wrote:
> Am Samstag, 30. Juli 2011, 18:28:32 schrieben Sie:
>> overall commment: the parts that do the reporting should not need to
>> know about the format of loglevel.
>
> Which parts exactly do you mean? Those that call the error/message/warning
> functions, or the error/message/warning functions themselves?

What I mean is that the callers should tag their messages with the
type of the message, and let the logging framework decide whether to
print it or not.

There are some tiny performance optimizations, like

-  if (be_verbose_global)
+  if (loglevel & LOG_DEBUG)
     {
       string spaces = "";
       for (size_t i = 0; i < state_stack_.size (); i++)
 	spaces += " ";
-      progress_indication (string ("\n") + spaces + string ("[") +
file->name_string ());
+      debug_output (spaces + string ("[") + file->name_string ());
     }

you could just drop the if in this case.


> You mean in those few places where I need to use "if (loglevel & LOG_DEBUG)",
> because I can't call the debug_output function? That's a good idea to keep the
> internal structure of the loglevel only inside warn.cc and provide a helper
> function to access them.

yep.

> Yes, that function is currently called non_fatal_error... Unfortunately, in

Also, in lilypond, the difference between (non_fatal) error and
warning never has been very clear. Maybe we should just have a

  fatal("..") // exits

and

  error("..") // does not exit, but sets return status = 1

  warning("..") // prints, succesful exist status.


-- 
Han-Wen Nienhuys - hanwen@xs4all.nl - http://www.xs4all.nl/~hanwen

[Reinhold, 2011-08-05 17:44:43]

http://codereview.appspot.com/4822055/diff/18001/scripts/build/mf2pt1.pl
File scripts/build/mf2pt1.pl (right):

http://codereview.appspot.com/4822055/diff/18001/scripts/build/mf2pt1.pl#newc...
scripts/build/mf2pt1.pl:1: #!@PERL@
Apparently, I dit a git fetch, but didn't rebase that branch before uploading.
Please ignore all changes in this file...

[Keith, 2011-08-08 06:52:46]

I like it.

http://codereview.appspot.com/4822055/diff/6003/flower/include/warn.hh
File flower/include/warn.hh (right):

http://codereview.appspot.com/4822055/diff/6003/flower/include/warn.hh#newcode41
flower/include/warn.hh:41: // There is no separation between progress and other
info messages:
but define LOGLEVEL_INFO with an | LOG_INFO anyway, 
just in case somebody tries to send a message with LOG_INFO

http://codereview.appspot.com/4822055/diff/6003/flower/warn.cc
File flower/warn.cc (right):

http://codereview.appspot.com/4822055/diff/6003/flower/warn.cc#newcode54
flower/warn.cc:54: debug_output (_f ("Log level set to `%d'\n", loglevel));
Quotes around the number, `271', confused me

http://codereview.appspot.com/4822055/diff/6003/flower/warn.cc#newcode132
flower/warn.cc:132: /* Display a fatal error message.  Also exits lilypond.  */
Can you now remove the function non_fatal_error() in favor of error() ?  It
looks strange to use non_fatal_error to dipaly a fatal error message.

http://codereview.appspot.com/4822055/diff/6003/flower/warn.cc#newcode180
flower/warn.cc:180: // Use the progress loglevel for all normal messages
(including progress msg)
Confusing. Input::message() filters with LOG_INFO; shouldn't message() do the
same?  (at least until the duplicate code is eventually merged)

http://codereview.appspot.com/4822055/diff/6003/lily/input.cc
File lily/input.cc (right):

http://codereview.appspot.com/4822055/diff/6003/lily/input.cc#newcode130
lily/input.cc:130: print_message (LOG_INFO, s);
has no effect, unless LOG_INFO is included in one of the bitmasks.

http://codereview.appspot.com/4822055/diff/6003/lily/main.cc
File lily/main.cc (right):

http://codereview.appspot.com/4822055/diff/6003/lily/main.cc#newcode172
lily/main.cc:172: "NONE, ERROR, WARNING, PROGRESS (default), DEBUG and
FULLDEBUG.")
Most of the new lines are too long for an 80-character terminal.
You wanted to remove FULLDEBUG.