log4drupal - a logging api for drupal

UPDATE: for the drupal 6 version, please go here.

if your career as a developer has included a stay in the j2ee world, then when you arrived at drupal one of your initial questions was "where's the log file?". eventually, someone told you about the watchdog table. you decided to try that for about five minutes, and then were reduced to using a combination of <pre> and print_r to scrawl debug data across your web browser.

when you tired of that, you learned a little php, did a little web research and discovered the PEAR log package and debug_backtrace(). the former is comfortably reminiscent of good old log4j and the latter finally gave you the stacktrace you'd been yearning for. still, separately, neither gave you quite what you were looking for : a log file in which every entry includes the filename and line number from which the log message originated. put them together though, and you've got log4drupal

log4drupal is a simple api that writes messages to a log file. each message is tagged with a particular log priority level (debug, info, warn, error or emergency) and you may also set the overall log threshold for your system. only messages with a priority level above your system threshold are actually printed to your log file. the system threshold may changed at any time, using the log4drupal administrative interface. you may also specify whether or not a full stack trace is included with every message. by default, a stack trace is included for messages with a priority of error and above. the administrative options are illustrated below :

log4drupal admin screen

now, on to the examples. suppose you had the following ridiculous block of code.

  $i = 0;
  while($i <= $user->profile_age) {
    log_debug("The user at least $i years old");
    $i++;
  }
 
  log_info("The user is $user->profile_age years old");
 
  if($user->profile_age < 2) {
    log_warn("User may be too young");
  }

  if($user->profile_age == 1) {
    log_error("Security violation, user much too young!");
  }

if your log threshold is set to debug then all messages will be shown in your log file as follows :

[20:23:23 11/12/07] [debug] [example.module:47] The user at least 0 years old
[20:23:23 11/12/07] [debug] [example.module:47] The user at least 1 years old
[20:23:23 11/12/07] [info] [example.module:51] The user is 1 years old
[20:23:23 11/12/07] [warning] [example.module:54] User may be too young!
[20:23:23 11/12/07] [error] [example.module:57] Security violation, user much too young!
  at /var/www/drupal/sites/all/modules/example/example.module:57
  at /var/www/drupal/sites/all/modules/example/example.module:71
  at /var/www/drupal/includes/module.inc:406
  at /var/www/drupal/modules/node/node.module:692
  at /var/www/drupal/modules/node/node.module:779
  at /var/www/drupal/modules/node/node.module:2462
  at /var/www/drupal/includes/menu.inc:418
  at /var/www/drupal/index.php:15

if your log threshold is set to warning then only the warning and error messages will be shown.

[20:27:52 11/12/07] [warning] [example.module:54] User may be too young
[20:27:52 11/12/07] [error] [example.module:57] Security violation,user much too young!
  at /var/www/drupal/sites/all/modules/example/example.module:57
  at /var/www/drupal/sites/all/modules/example/example.module:71
  at /var/www/drupal/includes/module.inc:406
  at /var/www/drupal/modules/node/node.module:692
  at /var/www/drupal/modules/node/node.module:779
  at /var/www/drupal/modules/node/node.module:2462
  at /var/www/drupal/includes/menu.inc:418
  at /var/www/drupal/index.php:15

you may download and test a copy of log4drupal here. suggestions for improvement or additional features are welcome. future improvements i've been thinking about include :

  1. integration with watchdog
  2. automatic recursive printing of any complex type messages

it's worth noting that all logging comes with a performance cost. i haven't done any serious calculations yet, but here is some ballpark data. on an unloaded server, with an average page load time of around 1.5 seconds, it takes about 0.3 milliseconds to print out one message. it takes about 0.008 milliseconds to not print out a message that is below your current system threshold.

if people are interested, i'll add this as a module to drupal.org

thanks to a former colleague, alex levine, for the original inspiration.

If you do not mind if I

If you do not mind if I clean this up and submit to Drupal.org, and give you credit?

The reason I ask, is the link http://genia.org/log-6.x-1.0.tar.gz is dead, and I have taken some time to play with your module.

Jeff Tanner
Seattle, WA

I am now actively working on

I am now actively working on a Drupal 6 version, which I will then (finally!) post to drupal.org. I promise. Check back in a couple of days.

Hi John, I just hacked the

Hi John,
I just hacked the script to work under Drupal 6. Feel free to grab it:

http://genia.org/log-6.x-1.0.tar.gz

Thank you,
Genia

Any progress posting this to

Any progress posting this to Drupal.org?

It would be really great to either do that (or merge it with trace) and update this page to point to that new file. Having these projects spread around the world often leads to module duplication (see development list messages from 11 february for details...)

yes, i will definitely take

yes, i will definitely take a look at the trace module. at a quick glance, it looks great. very full featured. i sure wish i'd been able to find it six months ago! i believe that i was thwarted in my attempt to find such a module by use of the word trace instead of logging.

i will provide a comparison of log4drupal and trace just as soon as i can.

In Drupal 6, the watchdog

In Drupal 6, the watchdog function is completely overrideable. You can change where the log message goes by implementing hook_watchdog() in your module.

One example is the syslog module, which is part of core in Drupal 6. Another is the email logging and alerts in contrib.

Better talk to the trace module author, evaluate how it interacts/overlaps with his stuff, as well as the Drupal 6 hook_watchdog() before we end up with fragmentation/duplication.

I recently installed Trace

I recently installed Trace and am interested in what the distinguishing characteristics are between it and this module.

(Trace would seem to do all the logging I need without a reliance on PEAR– if Arto checks back in, how do I call for a stack trace log every time, say, _menu_build is called?)

Sometimes the logging

Sometimes the logging message is expensive to create, only for it to get ignored inside the logging function.

Perhaps you could add the following functions.

log_debug_enabled, log_info_enabled, log_warn_enabled, log_error_enabled and log_emergency_enabled
or a log_is_level_enabled($level) function

This would allow code like

if (log_debug_enabled() == true) {
log_debug("The value of complicated($params) is : " . complicated($params) . ".");
}

I have always thought that this looks ugly coding, but if there are a lot of logging messages the time saved can mount up.

Nick

Looks like you've pretty

Looks like you've pretty much reinvented the Trace module :-)

(And among other things, Trace already does "automatic recursive printing of any complex type messages", btw.)

It sounds like there is

It sounds like there is enough interest to warrant publishing this on drupal.org. i will look into that.

i agree with andrew berry - this seems like a nice fit for the devel module. however, this is a module you would want to run on your production system (with a high logging threshold), and i've never been comfortable enabling devel on my production sites. there just seems to be alot in the devel module, and i've never had the time to fully evaluate it for efficiency and safety. perhaps i'm just being silly / paranoid. do others run devel on their production sites?

Really cool, as a j2ee

Really cool, as a j2ee refugee, makes me feel right at home in expatriate Drupal town.

Wrote quick rave on my blog: http://awebfactory.com.ar/node/273

Please publish as Drupal module, this is going to be extremely useful for many, I know I am already using it for my current work.

Victor Kane
http://awebfactory.com
victorkane@drupal.org

Looks really good. Perhaps

Looks really good. Perhaps you could look at integrating this into the devel module?

I can't keep up with the

I can't keep up with the updates if it's not on d.o.

(Well, if you make a new post every time you update it, then I can via RSS, but I wouldn't expect that to happen.)

Concur, this is an extremely

Concur, this is an extremely useful module for developers.

Yup. I only had to read the

Yup. I only had to read the name and I knew the features and the motivation right away. This would make a nice project on Drupal.org.

post new comment

the content of this field is kept private and will not be shown publicly.
  • web page addresses and e-mail addresses turn into links automatically.
  • allowed html tags: <h2> <h3> <h4> <a> <em> <strong> <cite> <code> <ul> <ol> <li> <dl> <dt> <dd>
  • lines and paragraphs break automatically.
  • you may post code using <code>...</code> (generic) or <?php ... ?> (highlighted php) tags.

more information about formatting options

captcha
are you human? we hope so.
copy the characters (respecting upper/lower case) from the image.