Lilypond loglevels & debug output

[Reinhold Kainhofer]

(This is a pretty long post, detailling my thoughts about the logging 
"framework". The first part describes the planned loglevels, so that 
documentation writers have all information. However, I'm most interested in 
your thoughts about the future directions, which are given in the second half 
of the mail, since they can really make the life of us contributors much 
easier, also for the build system!)


Dear developers,
As you know, I'm working on implementing proper loglevels into the lilypond 
binary to allow fine-grained control over the output of lilypond. My current 
patch (available at Rietveld: http://codereview.appspot.com/4822055/ ) 
currently implements the following features:

-) --loglevel=LEVEL cmd line switch with possible levels (case-insensitive,
   might even be truncated):
      o) NONE: No output at all, return code of binary !=0 for an error
      o) ERROR: Only print error messages, no warnings or progress
      o) WARNING: Only print errors & warnings, no progress
      o) BASIC_PROGRESS: error, warnings and basic progress (file name,
         success)
      o) PROGRESS: errors, warnings, progress (i.e. the current output)
      o) DEBUG: print full debug output (i.e. current --verbose output)

   The first 5 levels (NONE to PROGRESS) are indented mainly for users, who
   don't want the whole progress output (because e.g. they call lilypond in
   scripts, or process many files at once, where they just want an overview
   over the warnings/errors). The rest (DEBUG and maybe finer-grained debug
   messages, see below) are intended for developers, who want to know about
   the details of a lilypond run.

   Default is PROGRESS, i.e. the current output.
   
   Truncated strings for loglevels need to be at least: NONE, ERR, WARN,
   BASIC, PROG and DEBUG. (i.e. it's also okay to write WARNINGS or WARN or
   even WARN_ME_ABOUT_XXXX instead of WARNING). The comparison is done case-
   insensitive with only the first 3-5 characters.

-) New cmd line switch --silent, which is equal to --loglevel=ERROR

-) Environment variables LILYPOND_VERBOSE (sets --verbose) and
   LILYPOND_DEBUGLEVEL are processed before the cmd line options to specify
   a different default debuglevel. An explicit cmd line option --loglevel, 
   --silent or --verbose overrides this.
   So you can now set a loglevel of WARNING globally by 
      'export LILYPOND_LOGLEVEL=WARNING'
   and any call to lilypond that does not use an explicit --loglevel will
   only print warnings.
   Order of evaluation (later ones override): LILYPOND_VERBOSE,
   LILYPOND_LOGLEVEL, explicit cmd line args (--loglevel, --silent, --verbose)

-) A loglevel can also be given as a numeric value (undocumented), which 
   specifies the loglevel as a bitmask (i.e. if a developer wants to test
   just warnings, but no errors). This might also be used for finer-grained
   debug output for developers, see below

-) The C interface (in warn.cc), the C++ interface (in input.cc, which prints
   out exact location if the input is known) and the Guile interface
   (previously in general-scheme.cc, moved to warn-scheme.cc) to the log
   functions are basically unchanged:

   C-interface:
     o) error (string); // Fatal error, exits lilypond!
     o) programming_error (string);
     o) non_fatal_error (string);
     o) warning (string);
     o) successful (string);
     o) progress_indication (string, bool newline = false);
     o) message (string, bool newline = true);
     o) debug_output (string, bool newline = true);
   The newline argument specifies whether the message should always start on a
   new line or not (i.e. continue a previous message on the same line, which
   is the default for progress_indication!)
     
   C++-interface:
     o) Input::error (string) // Error, does NOT exit lilypond immediately!
     o) Input::programming_error (string)
     o) Input::non_fatal_error (string)
     o) Input::warning (string)
     o) Input::message (string)
     o) Input::debug_output (string)
     
   Guile-interface:
     o) (ly:error message args)   ;; Fatal error, exits lilypond!
     o) (ly:programming-error message args)
     o) (ly:warning message args)
     o) (ly:success message args)
     o) (ly:progress message args)
     o) (ly:message message args)
     o) (ly:debug message args)





However, there are some more things that I would like to implement:


-) Finer-grained debug output. We can do this by either adding another 
   --debuglevel cmd line switch (with a binary bitmask as value), or by
   using the upper 8 bits of the loglevel as a bitmask.
   The debug functions (debug_output (string), Input::debug_output (string)
   and (ly:debug message args) would then get a first argument defining the
   type of debug output, e.g. 
       debug_output (DEBUG_FONTS, "[" + string (pango_fn), true);
   The loglevel or debuglevel (whichever we choose) then needs to be given as 
   a number, though, like --loglevel=4095 (i.e. 00011111111111 in binary). Do
   you have a better idea to specify different debug areas? 

   --loglevel=DEBUG would print ALL debug messages of all debug areas.

-) Guile functions that also print out the location of a warning/error/message
   Currently, only the methods of the Input class print out the location of
   the code that triggered the output. Currently, we have two scm functions
   (version-not-seen-message and old-relative-not-used-message) that mimic
   this behavior by printing a normal message with the string "file:line:
   warning: " prepended. This breaks the loglevels, as it is a warning,
   disguised as a normal progress message...

-) Add a cmd line option to optionally print out the different types of
   message to different file descriptors (e.g. errors to stderr, warnings to
   descriptor 3, progress to descriptor 4 and debug output to descriptor 5).
   This is needed for the build system to be able to distinguish warnings from
   progress messages, etc.
   The build system could then use proper I/O redirections and piping to 
   e.g. echo everything from the error and warnings descriptors on the
   console, write everything from error, warning and progress descriptors 
   to a log file and all debug messages to a differrent debug log file.
   Without this switch, it is basically impossible to distinguish error
   messages from debug output, once lilypond printed the output.


What do you think?

Cheers,
Reinhold

-- 
------------------------------------------------------------------
Reinhold Kainhofer, address@hidden, 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