[Phpgroupware-developers] A Logging Proposal (long)

[Doug Dicks]

All,

I've been working on some enhancements to the PHPGroupware logging
system.  By logging I mean the logging statements put in the code by the
developers for debugging, development, and monitoring, not error
messages that the end user will normally see.  And also for
troubleshooting problems as they occur in a deployed system.  My
motivation is to help support some code I'm writing, but I'd like to
contribute the changes back if the devs want them.  I've tried to make
the changes with that in mind.  

Summary of the situation:  

There are currently at least three different methods used by developers
to add logging statements to their code:  print_debug(), the errorlog
class, and several different module or class specific methods.  There
are also modules that just echo information directly into the output. 
It makes troubleshooting very confusing, both during development and
diagnosing run-time problems.

Goal:

Settle on and implement a standard way to implement logging within
PHPGroupware.  It will be easy for a developer to add logging statements
to their code.  Several levels (error, info, debug, etc.) will be
provided.  The level of logging will be configurable at run-time. 

OK.  With that out of the way, here's what I've done:

First I took at Log4PHP (http://www.vxr.it/log4php/) a port of the
widely used Java Log4J package
(http://jakarta.apache.org/log4j/docs/index.html).  After working with
it a while, I decided not to use it.  It's a fairly new port and is
evolving rapidly.  There are some extensions that I'd want to make to
interact with PHPGroupware's configuration and logging tables instead of
reading / writing to the filesystem.  I thought it would take me too
long to implement.  That said, the Log4PHP project has matured a lot in
the last month or so.  It is very possible that we may want to move to
it at a later date - more on that in a bit.

With Log4PHP ruled out (for now), I started digging into the existing
logging class, errorlog.

Errorlog is instantiated in functions.inc.php and assigned to
$GLOBALS['phpgw']->log.  Log messages are stored in the database in the
phpgw_log and phpgw_log_msg tables.  These two tables have a
"header-detail" relationship allowing one or more messages (in
phpgw_log_msg) to be associated with a single log entry (in phpgw_log).
You log an error by using the write() method or one of message() or
error() followed by a commit().  Write() stores the message immediately
in the database.  Message() and error() put the error on an internal
stack which requires a commit() to store in the database.  Each error on
the stack becomes a detail record in phpgw_log_msg.

The error messages themselves are passed in an array, which includes the
message text, the file (__FILE__), the line (__LINE__), and any
parameters to the message.  The level of the message is determined by
the first part of the message string, which is expected to begin with
the level (D,I,W,E,F). It also contains a message code.  Some examples:

$GLOBALS['phpgw']->log->error(array(
   'text'=>'E-ArgError, err: Wrong argument %1',
   'p1'=> $criteria,
   'file'=>__FILE__,
   'line'=>__LINE__));

$GLOBALS['phpgw']->log->error(array(
   'text'=>'D-Debug, dbg: %1',
   'p1'=>'This debug statement should be in the log',
   'file'=>__FILE__,
   'line'=>__LINE__));

The %1 is replaced with the contents of p1 (or p_1).  There is a limit
of 10 parameters hard-coded in errorlog.

The logging level is not configurable - all messages are written all the
time.

I also dug into the print_debug() function which is declared in
common_functions.inc.php.

function print_debug(
   $message,
   $var = 'messageonly',
   $part = 'app', 
   $level = 3)

It basically takes a message, an optional variable, and echos them out
as HTML.  It can be turned on and off by several constants -
DEBUG_OUTPUT, DEBUG_LEVEL, DEBUG_DATATYPES, DEBUG_APP, DEBUG_API.  

My Design:

There are 5 levels of logging.  They are, in order of severity, FATAL,
ERROR, WARN, INFO, and DEBUG.   These match the levels used by
class.errorlog.php.inc and those used by log4j.   If logging is set to a
given level, all messages of that severity and above are logged.  For
example, if logging is set to WARN, then FATAL, ERROR, and WARN messages
will be written, but INFO and DEBUG messages will be ignored.

Messages are written to a single table in the database.  I've eliminated
the header-detail relationship.  It wasn't used very much and triples
(insert header, select key, insert detail) the number of database calls
for a single log event.  The table contains an auto-increment key, the
date/time, the account_id of the current user, the account_lid of the
current user, the current application, the severity of the message, the
file and line number of the logging statement, and finally the message
itself.

The logging API will consist of 5 functions, one for each level.  They
are log_fatal(), log_error(), log_warn(), log_info(), and log_debug(). 
They take a single argument - an array.  This is the same array
currently used by the errorlog class.  (See below for a discussion of
this.)  An info level message would look like:

log_info(array(
   'text'=>'Created new user group %1 ',
   'p1'=> $group_name,
   'file'=>__FILE__,
   'line'=>__LINE__));

It will be backward compatible with both the $GLOBALS['phpgw']->log->
and print_debug().  This will allow the current code to continue to
function as we phase out the old logging and move to the new API.  In
addition, we could eventually (if we want) move to using Log4PHP without
changing this API.

The current logging level of PHPGroupware is stored in phpgw_config.  It
is modified within the administration module.  No configuration files
need to be changed and the application does not have to be restarted for
changes to take effect.

The PHPGroupware logging level can be set globally, at a module level,
or at a user level.  For example, I can set the global level at ERROR,
the calendar module's level at INFO, and the level for user bsmith at
DEBUG.

Log messages can be viewed from within PHPGroupware in the
administration module.  They can be deleted here as well.  The "View
User" page also as link to view log messages for just that user.

I have implemented all of the above, except the backward compatibility
with print_debug().  I'd also need to do some polishing work (rename a
few classes, create the database table modification scripts, note what
strings need translations, etc.)  But it's pretty much done.

Questions I Have:

First, the big question:

1) Is this something the team is interested in incorporating into the
base PHPGroupware?

2) Is having the file name and line number useful?  

I left it in because it was there before, but would very much like to
take it out.  If I don't have the source to look through, they aren't
very valuable.  If I do have the source, I can grep for the message if
it doesn't give enough context.  Besides, if the message is vague enough
I have to look in the code to find out what it really means, it's not a
good message.

Getting rid of it makes it possible to get rid of the array completely
and just have the developer pass in a message.  Parameters to be
substituted can be passed in additional args that default to 'noarg'. 
Then the logging calls change from 

log_debug(array('text' => 'Variable x is %1',
  'p1' => $x,
  'file' => __FILE__,
  'line' => __LINE__));

to

log_debug('Variable x is %1', $x);

Much, much easier to put write, which means it's much more likely to get
used.

3) Should I use print_r on the parameters before substituting them?  

I think so.  That way the developer doesn't have to spin through the
array themselves if they want to print the contents.  Again, it makes it
easier to use.

4) Should I include options to write logging messages to standard output
as viewable HTML or/and within comments?

Print_debug() echos as HTML now, and several modules have their own
debugging which echos messages within HTML comments.  It wouldn't be
difficult to add logic to do this in addition to writing it to the DB. 
I'd want to make this configurable on a global, per module, and per user
basis as well.  That adds some complexity to the configuration form, but
I don't think it would be too bad.   


Finally, if you made it this far, thanks for reading.  I look forward to
reading your feedback.  I hope this is something that is useful to the
PHPGroupware community as well as myself.

Doug
-- 
Doug Dicks
Revelant Technologies