logging overhaul (please read)

Josh Sled jsled at asynchronous.org
Fri Feb 9 12:38:48 EST 2007 

  *** Up-front apologies for the length.  Please at least read the  
    summary and the questions in the text; search for "?".

Summary
-------

r15537 contains a major overhaul of the logging subsystem in (qof and)
gnucash.

In short, on the surface, you *should* only notice:

- a change in the format in /tmp/gnucash.trace
- more output from make check
- maybe a *bit* more output from the app
- the disabling of --loglevel (with replacement; see below)


Overview
--------

I've been growing frustrated with logging in gnucash; when I reworked
the SX code, I couldn't bring myself to write DEBUG or PINFO... I just
ended up using printf()s.  At least I could be sure they'd be printed to
the console, and without everything else at MOD_GUI. :/

More specifically, I've disliked the following things:

- No (easy) stdout/stderr support; I rue the day /tmp/gnucash.trace was
introduced.

- It's hard to change things at runtime; revising log-levels means
editing src/engine/ something.

- The granularity isn't good enough.  Each MOD_mumble is usually way too
much, MOD_GUI especially.  And adding a new level -- while much better
than before -- is a bit of a chore.

- Crap formatting.  No timestamps, no consistency.


In the mean time, I've been spoiled with log4j.  The log4x stuff is just
great.  It's proven to be a really good way to handle logging.  In
particular, the hierarchical leveling and appenders make life grand.

So I got a bee in my bonnet yesterday, and fixed our logging to be more
like that, without dep'ing on log4c or anything.  Let's call it
'log4glib'. :)


Core Changes
------------

qof_log_init() now installs a handler that interprets the "log_domain"
as a "."-seperated path.  Log level thresholds can be set for each level
in the tree.  When a message is logged, the longest level match is
found, and used as the threshold.

For instance, we can set the levels as such:

  "qof"                        = WARN
  "gnc"                        = WARN
  "gnc.ui"                     = INFO
  "gnc.ui.plugin-page.sx-list" = DEBUG

When GNC_MOD_IMPORT (now="gnc.import") logs (at DEBUG, let's say), it
will attempt to match "", then "gnc", then "gnc.import".  As "gnc" will
match -- at "WARN" -- the debug log will be rejected.  When
"gnc.ui.plugin-page.sx-list" logs at DEBUG, however...


This system uses g_log pretty heavily.  As such, I've made the QOF_LOG
levels be G_LOG_LEVELs directly, in the following correspondence:

    QOF_LOG_FATAL   = G_LOG_LEVEL_ERROR
    QOF_LOG_ERROR   = G_LOG_LEVEL_CRITICAL
    QOF_LOG_WARNING = G_LOG_LEVEL_WARNING
    QOF_LOG_INFO    = G_LOG_LEVEL_INFO
    QOF_LOG_DEBUG   = G_LOG_LEVEL_DEBUG
    QOF_LOG_DETAIL  = G_LOG_LEVEL_DEBUG
    QOF_LOG_TRACE   = G_LOG_LEVEL_DEBUG

In auditing the code, however, DETAIL and TRACE are used in a very small
number of places, and wil be removed.


The historical PERR, INFO, TRACE, ... macros were changed to simply call
g_log.  Before, the macros would qof_log_check(...) against the
ever-present `log_module`, then (maybe) call g_log(...) using
G_LOG_DOMAIN.  Now, the calls just call with "log_module" as the log
domain directly, and let the log handler do it's thing.

However, we never define G_LOG_DOMAIN anywhere. :/ As well, we do have
"raw" calls to g_{message,warning,debug,...} throughout the code ... as
well without G_LOG_DOMAIN defined.  I've added an appropriate value to
the Makefile.am's throughout the tree where those calls are made; now
these calls take advantage of the same mechanism.  We should probably do
this more uniformly and simply for every source file.

As I aluded to before, I've changed all the {GNC_QOF}_MOD_* #defines
from the form "qof-foo" and "gnucash-bar" to "qof.foo" and "gnc.bar".  I
specifically chose "." rather than the "-" that was already in play
because it's both more natural as a path-separator, as well as a guess
that it will be used far less than "-" in existing strings.


Initialization
--------------

Initilization has seen some re-work.  I'm not thrilled with it, but it
works fine for now; in some ways, it's less broken than before.

By default (i.e., calling qof_log_init()), we log to stderr with a base
level of "warn".  GnuCash will default to logging to
"/tmp/gnucash.trace", as before, and with the same levels as before
("gnc"=warn, "gnc.test"=debug (it was "trace"))

There are two new command-line options:

  * --logto ["stdout"|"stderr"|file]

    * logs to the given handle or file.

  * --log log.ger.path=level

    * sets the log-level at runtime
    * can be called multiply

  * e.g.,

      $ gnucash --logto stderr --log ""=info --log gnc.engine=warn --log gnc.ui=debug

The option "--loglevel" is presently disabled; is it used enough to
bring back, or can people just say <--log ""=whatever>?


Note that in this scheme, the "log4glib" handler sees messages from all
(unhandled) domains ... including "GLib" and "GnomeUI".  For instance,
to quiet GLib's CRITICAL's regarding "Invalid key name"s, one can say::

    $ gnucash --log GLib=error

...though this isn't a good idea, of course. :)


make check
----------

`make check` took a bit of work to make appear similar to now, with some
interesting consequences.  In most cases, just adding `qof_log_init` at
the top of the test setup raised the default level to "warn", and the
test's don't spew debugging detail.

However, I didn't quite realize that the tests -- by default -- had been
logging all sorts of warnings and criticals ... but
to /tmp/gnctest.trace ... and then overwriting them on the next test,
&c.

Now, by default (for tests), logging is to stderr.  Which makes some
things a little bit noisy, and some things very noisy:

- little bit...

  - src/gnc-module/test/ is pretty noisy, of the form:

    (process:30963): gnc.module-WARNING **: Module '../../../src/gnc-module/test/misc-mods/.libs/libfuturemodsys.so' requires newer module system

  - misc modules-related stuff everywhere:

    * 11:03:08  WARN <gnc.module> Failed to open module gnucash/app-utils
    * 11:03:08  WARN <gnc.module> : could not locate gnucash/app-utils interface v.0
    * 11:03:08  WARN <gnc.module> Initialization failed for module gnucash/import-export

and

- very noisy...

  - src/backend/file/test/(many)

    - It looks like transaction scrubbing and commodity-handling
      in these tests is sub-par, leading to hundreds of errors like:

    * 11:01:56  CRIT <gnc.engine> [xaccTransScrubSplits()] Transaction doesn't have a currency!
    * 11:01:56  CRIT <gnc.scrub> [xaccAccountScrubCommodity()] Account "" does not have a commodity!
    * 11:01:56  CRIT <gnc.scrub> [xaccAccountScrubCommodity()] Account "" does not have a commodity!
    
and:

    * 11:01:51  WARN <gnc.scrub> [xaccTransFindOldCommonCurrency()] unable to find a common currency in txn c25df6ca60518acb3044016e7c799f3c, and that is strange.
    * 11:01:51  WARN <gnc.scrub> [xaccTransScrubCurrency()] no common transaction currency found for trans="Paycheck deposit" (c25df6ca60518acb3044016e7c799f3c)
    * 11:01:51  WARN <gnc.scrub> [xaccTransScrubCurrency()]  split="" account="Checking" commodity="USD"
    * 11:01:51  WARN <gnc.scrub> [xaccTransScrubCurrency()]  split="" account="Salary" commodity="USD"

We have a couple of options:
- fix the bugs, if there are any, causing the log
- fix the test fixture to make "valid" commodities and transactions...
- suppress the logging :(


The rest of the "new" `make check` output I'm going to leave as is,
going to stderr, as it's pretty valuable.  For instance, just in the
course of doing this, I found an issue in
gnc_commodity.c:gnc_commodity_table_insert(), where ENTER was printing
random memory addresses.  As well, it appears that the expression parser
has two bugs: functions aren't evaluated correctly, and a call to
g_strrstr has an invalid arg.  There are a handful of other problems,
too; please inspect the output of `make check`. :)


Log Formatting
--------------

The current log format is as above:

    * [timestamp] [level] <[log-domain]> [message]

The timestamp and level are constant width (level is 5 characters).  The
log domain is re-iterated, which gives some context, but could become
annoying if they get long.

INFO, DEBUG, ... macros no longer add their level or spurious text to
the message; the level is known by g_log.  ENTER, LEAVE, TRACE still add
the qof_log_prettify function name; maybe 

Trailing newlines (e.g. PINFO("...\n", ...)) are removed; the logger
will newline separate output.

The space-based indentation as per ENTER/LEAVE has been disabled.
Before, the {in,de}dent calls were conditional on qof_log_check, but
that no longer exists.  I'm pretty sure it can fit back in by creating
two new log levels... but I'd like to hear feedback first?  I personally
don't find it useful, but I think others do, and it's a pretty big
regression.


Next Steps
----------

I only have a bit more I'd like to do on this project:

- add a "--logconf" option and default (~/.gnucash/logconf or
something), to allow for a bunch of common log overrides (and logging
location settings) as config.

- remove TRACE, DETAIL, DEBUGCMD, calls to qof_check_log

- we seem to use g_message() in a couple of places where we probably
want g_debug or g_info.

- "log4glib_handler" optimization
  - don't alloc strings all the time
  - run the log-level test longest->shortest

- use G_STRFUNC and G_STRLOC instead of qof_log_prettify(...).


-- 
...jsled
http://asynchronous.org/ - a=jsled;b=asynchronous.org;echo ${a}@${b}
-------------- next part --------------
A non-text attachment was scrubbed...
Name: not available
Type: application/pgp-signature
Size: 189 bytes
Desc: This is a digitally signed message part
Url : http://lists.gnucash.org/pipermail/gnucash-devel/attachments/20070209/8b0fc869/attachment.bin

More information about the gnucash-devel mailing list