Create a watchdog hook to enable customized logging and alerts via modules

Very nice! Big +1.

The fact that you've left the watchdog() function intact and with the same interface is VERY important, because that function is called thousands of times within Drupal, so changing it would be a major pain! The new hook_watchdog() is simple, unobtrusive, and effective.

I think that this patch is RTBC as is. We should leave the watchdog module as 'required' for now, since it is currently responsible for generating the main 'admin' page. But when the new administration / dashboard / control panel module comes in, and system.module is changed to support a choosable menu callback for the 'admin' page (with the 'site control panel' being the new default), we can definitely change watchdog to be 'optional', and we can change system.module to no longer depend on it for menu callback.

Haven't tested the patch, but the concept gets a +1 from me. This would be really useful for a number of my sites.

I am not sure that watchdog.inc belongs to includes but it will have to do until the modules move to their own directories...

in combination with logger [1], it is possible to paste this info into a syslogd as well. downside, you need to use *nix (well, downside being that it is not cross platform, windows can do syslogging as well but no logger tool is avail for that AFAIK). Another downside it that you need to script logger to get the priority from the input file and change that again in to the syslogd. I still would like to see a more generic way to write to a configurable syslogd service to be called. When drupal will hit huge scale implementations, we need to make sure it can deliver its data to standardized monitoring software and either SNMP (dont do that!) or syslog would be the preffered way to do that IMHO.

But it is a good start and I'll try to experiment from here.

[1] http://www.hmug.org/man/1/logger.php

Tried and tested the last file/patches. They work, but I cannot oversee the impact, so please do not read this as a review :)

But...
A quick and very dirty test showed me that with this patch its possible to let watchdog, via the new hook, and a jabberdog.module, talk to you via Jabber/XMPP. Really cool if you want to track your site over Jabber.
Another (non tested, but certainly possible) implementation would be swatchdog.module that does "stuff" if a watchdog matches a certain regexp.

Not sure I like the watchdog bootrap hack. Yes, it's a hack. If we are going to do this for the watchdog, then what's next?

imho this should never hit core (well, never, but not in a long time) since having drupal send messages to other media than the database would only be used by a relative small proportion of all drupal installs (but probably the bigger installs)

from a functional requitements pov, i would like to see the following in a module:
* select if errors should be on screen, in database and or other / syslog
* select syslog server (127.0.0.1 or other ipv4/ipv6/fqdn)
* select trehsholds to be send (1-7)
* select "x" in "the last messages was repeated x times" (hence, no more endless filling up of log files/database but within a timeframe (cronrun?) just repeat the last message with "x times", just like syslog

then people still can tail -f that file if that is their way of monitoring or read the syslog files from HP openview, tivoly or any other "think big (money)" corporate management tool. you could even parse the data and put it in mrtg for example.

See also http://php.net/syslog ...

bert: the module itself should not be part of core, but providing the hooks to enable such modules to be written could be interesting. Maybe we need to look at t(). It is also pluggable but with a lot less code.

I have been looking for this kind of functionality ever since I started using drupal.
Would love to see this kind of functionality, and the Swatch/Jabber possibilities also sounds great!
(...and now I can track this topic ;) Thanks!

Patch applied with an offset.

I am very excited about the possibilities gained with this patch. The rawlog.module is rough, but shows what is possible here (think syslog, logcheck, even a devel or admin block). Patch + rawlog.module works as advertised, and a `tail -f watchdog.log` is a beautiful thing. Nice! Setting to Needs Review.

I think it might be intersting to take into account the slightly extended requirement I defined some months ago about a generalized logging system: it probably wouldn't change the implementation much, but would allow modules like statistics or zeitgeist to use a more centralized logging service.

@jakeg:

What do you mean 'patch applied with an offset'?

The patch applies successfully, but the line numbers in system.module have changed, so `patch` has to move the patch around a bit:

patching file includes/bootstrap.inc
patching file modules/system/system.module
<b>Hunk #1 succeeded at 1192 (offset 19 lines).</b>
patching file modules/watchdog/watchdog.module

No big deal, but a re-roll to make it squeaky clean might be a good idea.

Thanks for your work on this.

+1 on this feature.

This allows syslog or SNMP or many other things to be done.

+1 on this feature's direction.

It's generally^[1] a Bad Idea to store high-activity LOGS to "hot"^[2] databases, e.g. drupal's database. That's what flat files and syslog are for. Generally^[1] if it becomes necessary or useful to crunch log data in a database for the relational capabilities it provides, that's when a reporting, batch or data warehouse-style database is called for.

Ideally, all logging, such as watchdog and accesslog, could be selectively directed to various storage locations, e.g. database, flat file, syslog, etc.

As Dries pointed out, adding syslog capability to PHP is easy: use the syslog() function.

[1] generally -- does not mean all cases; there are of course plenty of exceptions.
[2] hot -- a transactional database with lots of insert/update activity, or a database in the critical path of an active real-time or interactive application.

Can't we add an option to watchdog.module to use syslog? It could be a simple configuration setting for power users, and it might simplify the code. :)

When people say 'use syslog' etc. do you mean output to PHP's errorlog file, or do you mean invoke syslogd to create a new log file in /var/log/ such as /var/log/drupal_log? I'm not familiar with the concept of syslog, but often tail logs in /var/log/.

Syslog is a feature of UNIX systems, and Windows can be made to use it as well.

The idea is that your application just passes the log info, with a severity level to "syslog". Then it is up to the system adminstrator to direct where these go.

For example, on a simple one box system, they would go to /var/log/something. On a cluster, you may have all the boxes spitting out the logs to one central location, so the admin can look at only one log. On a bigger cluster, there can be software that takes in syslog as a "feed" and issues alerts via email or pager when something is wrong.

All this is possible without the application changing at all, as long as it uses syslog. So the benefits of this are huge.

For Drupal, if it just provides a hook for watchdog and another for accesslog, then contrib modules can make Drupal log to database, log to syslog, log to SNMP, log to /dev/null, ...etc.

See http://php.net/syslog and http://php.net/error_log. The former writes to syslog as configured in /etc/syslog.conf (or php.ini?). The latter writes to the Apache error log.

jakeg

The whole idea of using syslog, is that the application (Drupal in this case) does not know (nor care) where the output goes.

The system defines that and that can be changed without the application's knowledge.

The simplest way is to have a hook_watchdog() and hook_accesslog(), then a module that calles php's syslog() call with a severity. Where it ends up is system defined, not application defined.

Another module can do exactly what you want: put the output in a specific file.

Here is a new patch with a new approach. It is simple and less radical yet functional.

What this patch does is:

1. Add a new settings option to enable logging to syslog.

2. If this option is set, then no logging to the database will occur.

3. All the info that is currently logged to the database is now in the syslog, in addition to the following:

a. An identifier, "Drupal", which allows drupal only messages to be extracted if needed.
b. The $base_url is included, in case there are multiple sites on one server, or even multiple servers with multiple sites logging to an external syslog server.
c. The information is delimited by | and hence parsable.

4. If this option is set, then admin/logs/watchdog and friends will display a message saying the output is going to syslog.

Tested it on today's head, and works well for me on Linux. Testing needed on PHP4 as well as on Windows (goes to NT Log?).

I think this is great functionality, and I'd love to have this in core. However, I think we want it to be more flexible so we can support multiple output channels (sms, jabber, syslog, watchdog table), and selectively route messages to the proper channels. In other words, I like the initial approach best (watchdog hook + optional watchdog module), except that it doesn't allow us to selectively route messages to different channels.

The routing can be added on later, or could be implemented as part of the modules that implement the _watchdog hook so I'd be happy to commit an up-to-date version of the last watchdog_hook patch.

Okay ...

Here is a new patch that makes watchdog a hook, without making it a .inc or anything like that.

The watchdog module itself is now optional, and implements logging to the watchdog table.

The bootstrap watchdog() function is still there and now sends the log info to modules that implement a hook_watchdog and are enabled under admin/settings/watchdog-logging.

The admin/settings/watchdog-logging screen lists all modules that implement the hook_watchdog, and the user can turn logging on or off for each in one place. For example, they can say they want syslog and jabber only.

Modules that implement hook_watchdog are additive. This means that you can have logging to the watchdog table AND logging to the syslog AND logging to email, or no logging at all if you so wish.

I have a working syslog.module that works with this patch which I will attach next.

This is a tested patch, so should work without too much trouble.

After applying the patch, make sure that the watchdog module is enabled, then visit Administer > Site Configuration > Logging and enable the modules that can do logging. You should see the output go to all the destinations defined.

Dries, if this patch has a chance of making it to core, I will write an email logging too (for example, user can select which messages go to which email address, so they can have errors going to their pager/mobile, warnings go to regular email, and info ignored).

And here is the syslog module. This is a tar.gz renamed to txt. Rename it back to tar.gz and extract it to sites/all/modules and it should show up under Site Configuration > Logging.

As I said, I will write an email logging module too, but only if this patch is sure to make it to core.

Here is a new version of the patch, same functionality as #42, but with better descriptions and a more consistent UI.

And, because I am impatient, I have already written the emaillog module already.

It allows 3 different destinations depending on severity level. So, one can configure ERROR to go to a cell phone's address (or a pager), but WARNING and NOTICE can go to a regular email.

Also, you can make them go to a shared mailbox, and other nifty things.

So, the remaining module would be jabber (hi walkah!).

Then things get really interesting as people integrate enterprise network monitors and make Drupal being monitorable from Nagios, OpenNMS, HP OpenView, Tivoli and the like.

(This is realling a tar.gz archive, so just rename it and you are good to go)

+1 The potential uses for this are virtually limitless. Developers could trigger all sorts of actions on watchdog events - some practical and others potentially silly - but certainly fun thinking of the possibilities.

Newer version with better package name of syslog and emaillog modules, in tar.gz format.

Download, rename to something.tar.gz then extract into your modules directory.

+1

I really like the idea. I don't have much drupal experience to review anything but I still like the idea ;-)

Maybe share some screenshots?

Attached is a revised patch. No new functionality, but some fixes to wording, consistency, ...etc.

@Dries (and others) you can find a detailed write up and screen shots as well as examples in this post.

It is starting to look good, but more work is required.

1. "Logging and Alerts" should be "Logging and alerts". As we don't do alerts, just "Logging" would be best.

2. Why fiddle with the active database in watchdog_watchdog()? Please don't.

3. We have 'modules' not 'plugins'. Inconsistent terminology.

4. The logging and alerts page is confusing. What are the checkboxes for? It looks like you enabled two layers of 'enabling'. If I want to disable these, I'll disable the entire watchdog module. No need for an additional checkbox.

5. We don't abbreviate variables (i.e. $var). Try to use a slightly more descriptive name, or not a variable at all.

I'm sure glad I did not spend my weekend implementing hook_watchdog after my conversations about it with Dries, chx and others last week. That was what I had planned until some family things came up. We would have duplicated each other's work! :-)

As I mentioned much earlier in this issue, I think this is a great idea. I would love to see it back-ported into 5.x, as well.

When I get a chance, I'll try your code out, Khalid, and look it over.

One thought: be aware that hook_watchdog will probably add significant overhead compared to the simple SQL logging of the previous watchdog module for sites where database contention was not a bottleneck. So the code which implements it should be examined for refactoring for performance pretty early on in its life cycle.

New patch added. Still the same overall design, but adds the following:

1. Instead of 3 severity levels (ERROR, WARNING, NOTICE), it adds three more (CRITICAL which is higher than ERROR, INFO, which is lower than NOTICE, and DEBUG which is the lowest). This now allows modules to use the new CRITICAL value for things that need an alert (no one wants PHP errors going to their pager).

2. An upgrade path is provided via the _update_2007() function in system.install so that the data is reformatted to the new values. I tested this, and it works fine.

Other than that, it address the points raised by Dries.

Some specifics responses:

@Dries

1. "Logging and Alerts" should be "Logging and alerts".

Done. See attached patch.

As we don't do alerts, just "Logging" would be best.

But we do have alerts with this patch. The emaillog.module attached in #47 sends messages to different destinations. So, we can say that only errors be sent to a mobile phone, while notice messages go to a normal email.

Once a jabber alert module is written (Hi walkah!) alerts can go to IM.

The same goes to SMS.

2. Why fiddle with the active database in watchdog_watchdog()? Please don't.

This has been in watchdog() function in bootstrap.inc for a long time. The reason it is there is that there is no assurance that we changed the database to something else at some point in the page request, and therefore have to switch back to the Drupal database to log to the watchdog, then switch back to the database we are using.

So, my patch just moves this from bootstrap.inc to watchdog.module.

3. We have 'modules' not 'plugins'. Inconsistent terminology.

Already fixed in the patch attached to #50.

4. The logging and alerts page is confusing. What are the checkboxes for? It looks like you enabled two layers of 'enabling'. If I want to disable these, I'll disable the entire watchdog module. No need for an additional checkbox.

The reason is that in the future we can route different severity levels to different mechanisms, and there is a central place needed for this. For example, when the site throttles due to traffic (say this is critical severity), I want a pager alert, and also want to log the message to syslog. Similarly, if there is a database error, I want to send this to IM, as well as have it loggged to syslog.

If we have 4 logging/alert modules enabled, then the site admin has to go to 4 different places to do that. While if it is all in one place it is just a matter of listing severity as a column heading, and the modules as rows (like the Access control page).

I may even eliminate the per module settings page and centralize it all here via form_alter for all modules.

I am not hung up too much on this part though, and would like to see what others think.

5. We don't abbreviate variables (i.e. $var). Try to use a slightly more descriptive name, or not a variable at all.

Fixed in attached patch.

@Chris Johnson

One thought: be aware that hook_watchdog will probably add significant overhead compared to the simple SQL logging of the previous watchdog module for sites where database contention was not a bottleneck. So the code which implements it should be examined for refactoring for performance pretty early on in its life cycle.

Actually no. One of the objectives of this patch is to lessen the load on the database, by avoiding inserts to the watchdog table altogether. I have seen watchdog become the bottleneck on busy sites, specially when cron kicks in, and there is a delete of older entries from the log, while all other apache processes that want to insert in it are locked out.

Sending the messages to syslog is much cheaper, and does relieve the database.

Of course, it all depends on how you implement the alert. I imagine that sending emails has some overhead.

I did a benchmark. One using the watchdog for logging, and the other uses syslog.

I added a watchdog message in index.php, so that each requests will generate one message. Using ab2 with 5 concurrent threads, and 1000 requests total.

The results are virtually the same as far as requests per seconds go.

Using syslog

Document Path:          /
Document Length:        3923 bytes

Concurrency Level:      5
Time taken for tests:   130.573547 seconds
Complete requests:      1000
Failed requests:        0
Write errors:           0
Total transferred:      4437000 bytes
HTML transferred:       3923000 bytes
Requests per second:    7.66 [#/sec] (mean)
Time per request:       652.868 [ms] (mean)
Time per request:       130.574 [ms] (mean, across all concurrent requests)
Transfer rate:          33.18 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0    7  57.1      0     859
Processing:   125  643 271.5    641    4647
Waiting:        0  637 277.5    640    4552
Total:        125  651 272.7    644    4774

Percentage of the requests served within a certain time (ms)
  50%    644
  66%    720
  75%    759
  80%    782
  90%    857
  95%    942
  98%   1120
  99%   1635
 100%   4774 (longest request)

Using the watchdog

Document Path:          /
Document Length:        3923 bytes

Concurrency Level:      5
Time taken for tests:   130.665650 seconds
Complete requests:      1000
Failed requests:        0
Write errors:           0
Total transferred:      4437000 bytes
HTML transferred:       3923000 bytes
Requests per second:    7.65 [#/sec] (mean)
Time per request:       653.328 [ms] (mean)
Time per request:       130.666 [ms] (mean, across all concurrent requests)
Transfer rate:          33.16 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0    7  59.2      0     862
Processing:   124  644 267.3    641    4617
Waiting:        0  637 272.3    641    4511
Total:        124  651 281.0    647    5471

Percentage of the requests served within a certain time (ms)
  50%    647
  66%    728
  75%    769
  80%    799
  90%    877
  95%    960
  98%   1111
  99%   1288
 100%   5471 (longest request)

Of course, the parameters of the test above do not really deal with issues such as database locking (e.g. when cron is executing a delete on the watchdog table for old entries), and concurrency can be more on larger sites.

Conclusion: syslog is no slower than watchdog table logging.

So, I thought I should try something more aggressive. Maybe having 10 messages per page load would reveal something.

The results are in favor of syslog over watchdog, but only marginally.

syslog:

Document Path:          /
Document Length:        3923 bytes

Concurrency Level:      5
Time taken for tests:   132.811652 seconds
Complete requests:      1000
Failed requests:        0
Write errors:           0
Total transferred:      4437000 bytes
HTML transferred:       3923000 bytes
Requests per second:    7.53 [#/sec] (mean)
Time per request:       664.058 [ms] (mean)
Time per request:       132.812 [ms] (mean, across all concurrent requests)
Transfer rate:          32.63 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0    7  59.1      0     876
Processing:   126  650 252.1    648    4413
Waiting:        0  644 257.6    648    4310
Total:        126  658 262.9    649    5225

Percentage of the requests served within a certain time (ms)
  50%    649
  66%    718
  75%    763
  80%    789
  90%    860
  95%    939
  98%   1117
  99%   1416
 100%   5225 (longest request)

watchdog:

Document Path:          /
Document Length:        3923 bytes

Concurrency Level:      5
Time taken for tests:   138.322273 seconds
Complete requests:      1000
Failed requests:        0
Write errors:           0
Total transferred:      4437000 bytes
HTML transferred:       3923000 bytes
Requests per second:    7.23 [#/sec] (mean)
Time per request:       691.611 [ms] (mean)
Time per request:       138.322 [ms] (mean, across all concurrent requests)
Transfer rate:          31.33 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0    7  61.8      0     891
Processing:   129  681 286.1    680    4622
Waiting:        0  675 292.7    679    4601
Total:        129  689 302.2    681    5509

Percentage of the requests served within a certain time (ms)
  50%    681
  66%    741
  75%    782
  80%    806
  90%    871
  95%    945
  98%   1298
  99%   1646
 100%   5509 (longest request)

I think we're taking the wrong approach with these extra levels. For example, on buytaert.net, I want new comments to go IM. A new comment being posted is not a "critical" event, and yet I want them to go to IM. New comments would probably be a "notice", but I certainly don't want all "notices" to go to my IM either.

To make a long story short: I don't think the filtering based on levels works. As such, I prefer not to introduce new levels. Instead, we should work on more expressive mechanisms to route certain messages. This should probably be left for another patch.

(I've not tested the new patch yet, but I will shortly. Just wanted to vote against these new levels for now.)

I think we're taking the wrong approach with these extra levels. For example, on buytaert.net, I want new comments to go IM. A new comment being posted is not a "critical" event, and yet I want them to go to IM. New comments would probably be a "notice", but I certainly don't want all "notices" to go to my IM either.

I hear what you are saying. The new levels give more granular control for modules to decide what levels things go to. webchick has also encountered a problem where she needs a trivial level of messages. The debug level also gives developers a new avenue instead of print_r(). So if debug is set to go a special /var/log/drupal.debug, then we can just tail -f that log.

If we use today's levels as they are, we cannot say ERROR (for example) goes to IM, because it will be flooded by other since simply there are too many of these messages already in modules all over the place. New levels avoid this problem since we can give clear guidelines on what is considered CRITICAL, and what is DEBUG, ...etc.

There is nothing hardcoded about which level goes where. It is all configurable in the new system. Either the add on modules decide it, or (in the very near future after this patch goes thru) the central "Logging and alerts" setting will decide which levels go where in matrix.

So, for buytaert.net, you will be able to set NOTICE to go to IM, as you want it to be.

This is also backward compatible, in the sense that existing levels are the same, and no module needs to change because of this new watchdog hook.

Instead, we should work on more expressive mechanisms to route certain messages. This should probably be left for another patch.

Yes, and I have that on my list. The central Logging and alerts setting will be able to give the user the option on where to route each level.

Does that convince you of the merits of new levels? If no one thinks there is merit in it, then I can easily roll this back.

"There is nothing hardcoded about which level goes where. It is all
configurable in the new system. Either the add on modules decide it, or
(in the very near future after this patch goes thru) the central
"Logging and alerts" setting will decide which levels go where in
matrix."

How would the GUI of such a beast look?

I outlined that in #53, in reply to point 4 by Dries.

Nothing concrete yet, but a matrix in "Logging and alerts" with checkboxes like what Access control has today (Roles as column heading, Permissions as row headings). So, for this, we would have Severity levels as columns, and logging modules as rows.

This needs to be refined more by adding a section for the settings for each module. For example, for the email log module, it needs to have a different email address for each level.

But as Dries said, let us get the hook in core, then do another round for the rest.

1. My point was that I want a _subset_ of all notices to go to IM. I'm arguing that these levels are not necessarily the right way to dispatch or route messages. So, let's get rid of the extra levels you introduced -- at least for now.

Some more feedback. Change:
+ 'description' => t('Enable logging and alerts of Drupal watchdog messages to various destinations.'),
to
+ 'description' => t('Enable logging and alerts.'),

2. I'm not sure this is clear:

 +    '#description' => t('This is a list of modules that can be used to log Drupal messages to various destinations, as well as send alerts.'),
   ); 

For someone not familiar with advanced logging functionality, it might not be clear what 'various destinanations' implies, or why this is useful. It wouldn't hurt to be a bit more verbose here, so things are a tad more explanatory to newbies.

3. The checkbox overview page has to go. You enable/disable modules on the modules administration page. As a result, all these checks (if (variable_get('watchdog_watchdog', 0)) {) can go as well.

4. "the Drupal database" should be "the database".

I'll commit this patch once these are implemented. Thanks!

Yes, extra levels are probably not needed. Per module or even regex matches are likely to be the most flexible.

Great work, Khalid.

Yes, the way this should work is very much like your e-mail clients folder filtering. You need to be able to uses wildcard matching (i..e message contains "new comment") to route messages to the proper output channel. We need a regular filter implementation.

As I stated above SNMP/Syslog are a *must* to get Drupal in high end hosting, nobody is going to check dozens of local logfiles.

For me, syslog is a must. From my syslog servers I can route criticals to other channels like a pager or Instant Messaging. I dont have the need for that in the application (Drupal) itself. But I can imagine that smaller hosting facilities want it in the application, though they will find that the scaling of this and ability to do correlation will in the end not be beneficial.

BTW: your ABenchmarks are when syslog is localhost I presume? Keep in mind that syslog is UDP so on a congested network or slow syslogserver potentially not available/reliable (*what* will you log *where* in that case?)

BTW2: On the use of extra levels: I think you should use the full 8 levels. If you dont, please at least use the numerical format defined in RFC3164 and dont re-invent the status of a critical yourself. This is at least what I make of the code where a critical is 5
+define('WATCHDOG_CRITICAL', 5);

As I said, most datacentra route their workflow based on the severity of a syslog message, routing 0 to pagers, 1 to IM, 2 to troubleticket etc... That way people can still use their generic workflow for Drupal syslog messages and dont have to parse and rewrite stuff.

If you use only 5 levels, please us the same as defined in the RFC, for example:"

0 WATCHDOG_ERROR
1 -reserved-
2 WATCHDOG_WARNING
3 WATCHDOG_NOTICE
4 -reserved-
5 WATCHDOG_INFO
6 -reserved-
7 WATCHDOG_DEBUG

BTW3: I dont get it if this is core or contrib?

BTW4: Please use the "last message repeated 45 times" when something repeating is happening, hence caching the last line, compare it to the new line and dont send when same message happens and only send over the wire the number of times it has been happening.

I didn't knew about that RFC. Here is what the RFC defines:

        Numerical         Severity
          Code

           0       Emergency: system is unusable
           1       Alert: action must be taken immediately
           2       Critical: critical conditions
           3       Error: error conditions
           4       Warning: warning conditions
           5       Notice: normal but significant condition
           6       Informational: informational messages
           7       Debug: debug-level messages

With that in mind, I'm turning around, and I think it might actually make sense to support the syslog levels -- especially if we document this properly, and cite the RFC.

That said, I still think that routing shouldn't be based on log level alone. I want to use wildcard matching (in addition to log levels).

Bert: what tools are you referring to that use the syslog output to send information to pagers? Do you have some names and or screenshots? It would be interesting to see how these log-levels are actually used in practice, and how they filter messages.

(I know that the OSL uses this mechanism to monitor our systems. They get paged when something goes really wrong.)

http://php.net/syslog also defines these error levels. With that in mind, I think it makes sense to map our error levels onto syslog's.

If there are other logging tools available, it's probably a good idea to list them now.

- If we go with these levels, we'll want to update the color-coding of the watchdog table. Looks like we might need more gradients.

- We'll want to document these levels so people use them properly. Then, based on the documentation, we'll want to revise the existing watchdog() calls in core.

we use dozen of different tools for parsing the syslog files, trailered for the need. we have multiple redundant syslog servers with the data on a nas. we also use different syslog files for different applications and maintenance teams. for example syslog/routers/routername/loglevel and syslog/application/bea/customerenvironment/server/loglevel etc

For parsing we use anything from expensive high-cost-to-implement stuff like Tivoli (trivia: spell it backwards) from IBM, HP Openview from HP etc. But most of all, own shell en perl scripts. Sure, has its downsides as anyone with some programming knowledge knows but works, is maintainable (sort of) and gets the job done.

I dont think we should list any log parsing tools since you will not use a log parser just because drupal can do syslog but a hosting company has it in place and is glad Drupal can do syslog. There are dozens of tools in the OSS community that can do something useful with syslog; from ignoring it when a scheduled maintenance was planned to sending out jabberd calls to a ticket system. for starters take a look at http://www.loganalysis.org/sections/parsing/generic-log-parsers/ but there are dozen more (cacti is a good one and used a lot http://cacti.net/)

Also look at the question raised above: what are you going to log where when syslogd is unavailable?

Here is a patch that implements Dries suggestions #59, as well as implement the RFC values.

define('WATCHDOG_EMERG',    0); // Emergency: system is unusable
define('WATCHDOG_ALERT',    1); // Alert: action must be taken immediately
define('WATCHDOG_CRITICAL', 2); // Critical: critical conditions
define('WATCHDOG_ERROR',    3); // Error: error conditions
define('WATCHDOG_WARNING',  4); // Warning: warning conditions
define('WATCHDOG_NOTICE',   5); // Notice: normal but significant condition
define('WATCHDOG_INFO',     6); // Informational: informational messages
define('WATCHDOG_DEBUG',    7); // Debug: debug-level messages

It also updates the values in your current watchdog to the new values, when you run update.php on an existing site.

The centralized user interface is now gone, so just enabling a module makes it log messages to wherever it decides. We can revisit this later after we have the hook in core.

I tested it with 3 logging modules enabled, watchdog, emaillog and syslog, and they all work.

Please review this patch.

@bert

Thanks for chipping in about the severity levels and such. You are more eloquent than I am and that made Dries see the value in this.

Regarding SNMP, this patch alone is not enough, since an SNMP device has to implement a MIB (Management Information Base) and store monitoring info in it, so when the SNMP agent polls it, it responds with the values. So, if Drupal is to be an SNMP device, we have to think of a MIB for it and what fields it contains.

I just wanted to second most of Bert Boerland's points. Since most of the benefits of creating hook_watchdog are those which larger installations need, it's important to consider their use cases.

@khalid -- thanks for running the benchmarks. I did not say that syslog would be more overhead than a database, rather that calling a hook, which could potentially be implemented by a dozen modules, is a potentially expensive operation -- perhaps more so than a simple SQL insert on a database without contention (most small Drupal sites). Your benchmarks are a good data point to show the concern is not great.

I have not yet had a chance to try this patch and extensively examine it, but I am concerned with clean abstractions. There is a lot of talk about how to filter / prioritize messages and the GUI for configuring same. Shouldn't there be 3 cleanly separated pieces here, perhaps as 2 or even 3 issues:

1. Create hook_watchdog in core
2. Revise current watchdog module to use hook_watchdog to continue providing current logging capabilities
3. Create new logging modules which implement hook_watchdog -- including any kind of clever filtering developers of same might want

The core hook is the most important part to get right the first time. If the interface is defined properly such that the necessary data is handed to implementing modules, it will enable a wide variety of methods, addressing both Dries's use case and Bert's, for example.

I hope my remarks are helpful. I will try to make some time to examine and test the patches in the near future.

@Chris J

There is a lot of talk about how to filter / prioritize messages and the GUI for configuring same.

As it stands today, there is nothing to say what goes where. Each module can decide where to route, based on whatever criteria it wants (e.g. severity, type, ...etc.).

So, that part is as you want it.

Shouldn't there be 3 cleanly separated pieces here, perhaps as 2 or even 3 issues:

1. Create hook_watchdog in core

The patch does that.

2. Revise current watchdog module to use hook_watchdog to continue providing current logging capabilities

The patch includes a refactored watchdog module that uses hook_watchdog, makes the module optional, and reformats the data to use the new severity codes.

3. Create new logging modules which implement hook_watchdog -- including any kind of clever filtering developers of same might want.

I already have two modules that do that. One is for syslog, and one is for email. They do work, and I tested them. They are NOT included in the patch, as you rightly state.

Once this patch hits core, I will create a contrib module for them.

The core hook is the most important part to get right the first time. If the interface is defined properly such that the necessary data is handed to implementing modules, it will enable a wide variety of methods, addressing both Dries's use case and Bert's, for example.

The core hook uses the arguments already in use for the watchdog() function that many modules call today. So, it is backward compatible, apart from the use of new codes, which the update.php part takes care of.

I hope this is all in line with your thinking.

Review the patch when you have time.

When this patch gets committed, don't create these contrib projects just yet. We'll want to work on the filtering/routing and that might affect the APIs. In my mind, this patch implements part 1 of 2.

Hopefully, someone else helps review/test this patch.

I have working versions of these two modules already and I tested them with the last patch.

An earlier version is attached in this comment.

One way of handling this is to have three pieces, per module:

- each logging/alert module does a form_alter to make its settings visible under a central place (so all logging/alerts is administered in one place for all modules),

- a part that decides "what goes where", based on severity, type, regexp, or whatever

- a part that does the actual delivery to the destination.

I will wait for it to solidify though, then I will be happy to get input on how best to proceed.

Testing this patch now with a fresh copy of Drupal HEAD.

On install, Drupal warned me to run update, and I did. Only update listed was for system module, which makes sense. The watchdog updates ran ok, although I got an error on "DELETE FROM cache_menu" -- table does not exist. The resulting message in the database watchdog log has some HTML problems. It looks like this:

Table 'cj6.cache_menu' doesn't exist query: DELETE FROM cache_menu in /home/chris/www/d6/includes/database.mysql.inc on line 172.

When viewing "Recent log entires", I get these errors at the top of the page before the log listings:

# notice: Undefined index: 0 in /home/code/www/d6/modules/watchdog/watchdog.module on line 164.
# notice: Undefined index: 0 in /home/code/www/d6/modules/watchdog/watchdog.module on line 172.

Both seem to be related to the array index value in $watchdog->severity.

I will press onward as these do not seem critical problems.

syslog module appears to be functioning correctly.

If we are going to use the pipe '|' symbol as a delimiter in syslog, we should be sure that it is never a valid character in a URL, or parsers will fail when they occur.

Received this message when enabling the emaillog module:

notice: Undefined variable: items in /home/chris/www/d6/modules/logging_alerts/emaillog/emaillog.module on line 30.

Not finding any GUI bits to configure the emaillog.

Actually, not seeing any new GUI pieces. Hmmm...

The last logging tar.gz was a bit outdated.

Attached are the latest versions I used. Give them a spin.

I saw that cache_menu error a couple of times, but was unable to remember the exact sequence that causes it. It is definitely related to chx menu work, so we need to open a new issue for it, if chx is not working on it already.

Updating title to reflect better what it does now.

Attached is a watchdog.install to replace the removed table creation in system.install otherwise the watchdog table is not created.

I don't like the idea of the watchdog.module (or any form of logging) not being enabled by default during a clean install. For new installs, watchdog messages should be logged (ie messages generated by the install profile). Enabling the watchdog.module in a install profile's _profile_modules() seems to work fine, logging warnings produced by running the install wizard.

I also added a hook_uninstall() to the watchdog.install

Should system_update_2007() be moved to watchdog.install as well?

Duh, and the watchdog.install file...

@Khalid: got the new tar file. GUI pieces for email appear to work fine. No new errors. Old errors with undefined index in watchdog module remain (using both at once). For people using both, or for users familiar with the watchdog.module categorizations (e.g. cron, php, etc.) the severity levels in the email form are a bit confusing. Email header data is pretty good and complete. You might want to translate the timestamp into human readable format.

I'll keep playing with it. Looks good so far.

@asimmonds, thanks for the watchdog.install. I discovered today it was not included, and was about to attach it. (Side point: cvs diff -N is supposed to include it. It doesn't. Will take
it up with infra).

I don't like the idea of the watchdog.module (or any form of logging) not being enabled by default during a clean install. For new installs, watchdog messages should be logged (ie messages generated by the install profile). Enabling the watchdog.module in a install profile's _profile_modules() seems to work fine, logging warnings produced by running the install wizard.

I see you have a point there. I changed the default profile to include watchdog by default. It is still optional. This is far better than having it mandatory (defeats the purpose of the patch), or not having it on at all (most small site will use only the watchdog).

Should system_update_2007() be moved to watchdog.install as well?

I will leave this to be decided by core people. Steven? Drumm?

@Chris Johnson

Old errors with undefined index in watchdog module remain (using both at once).

This happens when you don't have any rows in the watchdog table yet. The attached patch fixes this problem.

For people using both, or for users familiar with the watchdog.module categorizations (e.g. cron, php, etc.) the severity levels in the email form are a bit confusing.

The severity levels are now the same for all modules, in compliance with the RFC.

Email header data is pretty good and complete. You might want to translate the timestamp into human readable format.

This module will be in contrib, and I will put that on my to do list. In any case, you can do it today either in template.php overriding the theme_*() function, or by using drupal_mail_alter().

@asimmonds, thanks for the watchdog.install. I discovered today it was not included, and was about to attach it. (Side point: cvs diff -N is supposed to include it. It doesn't. Will take it up with infra).

I don't like the idea of the watchdog.module (or any form of logging) not being enabled by default during a clean install. For new installs, watchdog messages should be logged (ie messages generated by the install profile). Enabling the watchdog.module in a install profile's _profile_modules() seems to work fine, logging warnings produced by running the install wizard.

I see you have a point there. I changed the default profile to include watchdog by default. It is still optional. This is far better than having it mandatory (defeats the purpose of the patch), or not having it on at all (most small site will use only the watchdog).

Should system_update_2007() be moved to watchdog.install as well?

I will leave this to be decided by core people. Steven? Drumm?

@Chris Johnson

Old errors with undefined index in watchdog module remain (using both at once).

This happens when you don't have any rows in the watchdog table yet. The attached patch fixes this problem.

For people using both, or for users familiar with the watchdog.module categorizations (e.g. cron, php, etc.) the severity levels in the email form are a bit confusing.

The severity levels are now the same for all modules, in compliance with the RFC.

Email header data is pretty good and complete. You might want to translate the timestamp into human readable format.

This module will be in contrib, and I will put that on my to do list. In any case, you can do it today either in template.php overriding the theme_*() function, or by using drupal_mail_alter().

Attempt to close tags.

@asimmonds, thanks for the watchdog.install. I discovered today it was not included, and was about to attach it. (Side point: cvs diff -N is supposed to include it. It doesn't. Will take it up with infra).

I don't like the idea of the watchdog.module (or any form of logging) not being enabled by default during a clean install. For new installs, watchdog messages should be logged (ie messages generated by the install profile). Enabling the watchdog.module in a install profile's _profile_modules() seems to work fine, logging warnings produced by running the install wizard.

I see you have a point there. I changed the default profile to include watchdog by default. It is still optional. This is far better than having it mandatory (defeats the purpose of the patch), or not having it on at all (most small site will use only the watchdog).

Should system_update_2007() be moved to watchdog.install as well?

I will leave this to be decided by core people. Steven? Drumm?

@Chris Johnson

Old errors with undefined index in watchdog module remain (using both at once).

This happens when you don't have any rows in the watchdog table yet. The attached patch fixes this problem.

For people using both, or for users familiar with the watchdog.module categorizations (e.g. cron, php, etc.) the severity levels in the email form are a bit confusing.

The severity levels are now the same for all modules, in compliance with the RFC.

Email header data is pretty good and complete. You might want to translate the timestamp into human readable format.

This module will be in contrib, and I will put that on my to do list. In any case, you can do it today either in template.php overriding the theme_*() function, or by using drupal_mail_alter().

Attached is an All-In-One (tm) patch, that includes the watchdog.install for core, as well as the emaillog and syslog modules.

Here is a detailed description of the patch for those just joining us now.

- Makes the watchdog() call hook_watchdog in all enabled modules that implement it.
- Expands the severity levels from 3 (Error, Warning, Notice) to the 8 levels defined in RFC 3164.
- The watchdog module is now optional, but enabled by default in the default install profile.
- Moves the settings for watchdog to the watchdog module.
- Moves the watchdog table creation to the new watchdog.install, which also adds an uninstall.
- Add an update function to reformat old watchdog messages to the new severity codes (see above).
- Introduces a new grouping of modules called "Logging and alerts".
- Includes two contributed modules, email logging/alerts, and syslog logging.

I'll test the patch ASAP, but I'm still on vacation (internet time is limited).

Personally, I wouldn't mind to take things a little bit further, and the try and make more improvements (i.e. filtering the watchdog/dblog, rotating the dblog so it doesn't grow to big, filter UI for different log modules, etc). This seems like a good time to harness some of core's logging functionality and UI.

For example, the syslog module is small enough that it could be included in core (but be disabled by default). What do you think about that? By including it in core, we can make a filter UI that makes a bit more sense.

khaley: do you feel like working on this a little bit more after this patch lands? Can we take this further?

-slight hijacked but since dries opened this a bit-

It would be great if the admin could do a
-------------------------
Log to:
[x] watchdog (local)
____[_] Rotate log per: [dropdown: day,week,month]
____[x] Max size log in lines: [dropdown:100,500,1000,10000] (maybe better to leave this field open?)
____[_] Max size log in KBytes: [dropdown: 10KB,100KB,1MB]
[_] syslog
____IP address syslog server [___].[___].[___].[___]
____Severity error level (helplink) [dropdown 0,1,2,3,4,5,6,7]
[x] Mail
____email address [username]@[host.tld]
____Severity error level (helplink) [dropdown 0,1,2,3,4,5,6,7]
-------------------------

Maybe this should be integrated with services module somehow to enable more hooks for outputting data? RSS, Jabber, twitter ...?

also note that -like syslog and mentioned before- it would be great to cache the last log line and only sum up repetitive events, like "last messages repeated 10 times"

See also this related problem I had 3 years ago that started it from my PoV.

How about we:

1. Rename watchdog.module to dblog.module.

2. We add syslog.module to core so we have both 'dblog' and 'syslog' in core. Having syslog in core makes sense to me. It's not just for enterprise-level purposes -- I don't run an enterprise and I frequently tail various deamons' syslog, for example.

3. We add a feature to rotate the dblog based on the number of entries, rather than based on lifetime. This fixes a performance/scalability issue. See also Bert's comment.

4. We add a basic filter configuration screen to core. I don't think filtering by severity is sufficient, but it could make for a good start that is worth committing. In future patches, we can add more advanced filtering that allows selectively allows you to send certain messages to certain output channels (regardless of their severity).

The above would make for a great improvement in Drupal 6, IMO.

I will work on the things Dries suggested.

Stay tuned.

Meanwhile the last patch attached is still reviewable for those who want to see what this is all about.

Attached is a new patch. It has the following:

- The watchdog.module is now called dblog.module.
- The dblog module deletes rows based on an admin defined threshold, using cron. I don't see a need to do by the size, since this varies from one database backend to the other, as well adds processing overhead everytime cron runs (need to query the database for size of stored data, ..etc.).
- Moved cleaning of flood table to system.module, since dblog may be disabled in some sites.
- syslog.module is now part of core.
- syslog.module now uses Earl Miles' new theme registry to format its messages.

The emaillog module is now in my sandbox for those interested in testing it.

@Bert

I did most of what you wanted. I don't think it is a good idea to put a server IP address in the syslog settings. This should be done in syslog.conf. Isn't that the whole idea of using syslog? You do not care where you messages go, and let the sysadmin or enterprise policy do that?

This leaves this point:

4. We add a basic filter configuration screen to core. I don't think filtering by severity is sufficient, but it could make for a good start that is worth committing. In future patches, we can add more advanced filtering that allows selectively allows you to send certain messages to certain output channels (regardless of their severity).

My experience is that filtering upstream is never a good idea. The application (Drupal in this case) should just throw out its messages to wherever it should go (db, email, syslog, whatever). It is up to the downstream handler to do the filtering based on whatever criteria.

This relieves the application from making any decisions, and leaves it to the monitoring/logging software to do so.

For example, syslog uses two criteria: facility and severity, and /etc/syslog.conf is the place to route things based on that. For example, I can decide that the drupal messages go to /var/log/drupal (all severity). If one wants more filtering, then they can do:

# tail -f /var/log/drupal | egrep "pattern1|pattern2|pattern3"

And I will see only those three patterns on the screen.

Similarly, email can be handled by procmail or whatever.

One can also implement their own module that does their own specific filtering without forcing core to have such a feature.

I am willing to be convinced otherwise though. So arguments for/against are welcome.

at least two design flaws are in my screen mockup above, syslog servers can be addressed by hostname, fqdn or ipv6 address. So just having 4 octets as input isnt "future ready"

The same holds true for amil addresses "joe", "joe@127.0.0.1" and "joe@example.com" are all valid

So dont use that part in your code

Regarding your comments on syslog use. Yes thats true. But you cant use this module when hosting a drupal site on a wamp platform. Your / Dries call

at least two design flaws are in my screen mockup above, syslog servers can be addressed by hostname, fqdn or ipv6 address. So just having 4 octets as input isnt "future ready"

The idea behind syslog is to send to "syslog" and let the local syslog configuration decide where to route them. It can decide by facility and severity where to route the messages. So it can keep some local and send some off to another server. The point is that the application need not worry about these things.

Regarding parsing/filtering, there are already several external solutions to do that. Here is a sample from Debian/Ubuntu.

libparse-syslog-perl - Perl module for parsing syslog entries
Unix syslogs are convenient to read for humans but because of small differences between operating systems and things like 'last message
repeated xx times' not very easy to parse by a script.

Parse::Syslog presents a simple interface to parse syslog files: you create a parser on a file (with new) and call next to get one line at a time with Unix-timestamp, host, program, pid and text returned in a hash-reference.

syslog-ng - Next generation logging daemon
Provides filtering based on message content (among other features)

syslog-summary - Summarize the contents of a syslog log file
This program summarizes the contents of a log file written by syslog, by displaying each unique (except for the time) line once, and also the number of times such a line occurs in the input. The lines are displayed in the order they occur in the input.

The same holds true for amil addresses "joe", "joe@127.0.0.1" and "joe@example.com" are all valid

So dont use that part in your code

I left that as free form entry for now. So it covers the above cases.

Regarding your comments on syslog use. Yes thats true. But you cant use this module when hosting a drupal site on a wamp platform. Your / Dries call

Actually, you can use it. The PHP manual says:

On Windows NT, the syslog service is emulated using the Event Log.

Note: Use of LOG_LOCAL0 through LOG_LOCAL7 for the facility parameter of openlog() is not available in Windows.

This is why I give a selection of LOCAL0 to LOCAL7 as well as USER, which can be used in Windows.

There are more sophisticated solutions for Windows if one needs it, such as:

http://www.kiwisyslog.com/syslog-info.php
http://www.winsyslog.com/en/

So, even WAMP is covered with syslog.

Again, it is optional, and nothing forces a user to use it.

This patch is almost ready:

1. Don't put the loggers in their own package. Put them back in 'Core - optional', please.

2. I'd consider to merge the configuration screens under a generic 'Logging settings' page. There could be two fieldsets or two sub-tabs. Currently, the different settings appear to be all over the map, which isn't particularly helpful for the user.

3. We need to do a better job communicating the differences to the user. We need to incorporate practical advice about whether to use syslog or dblog. Imagine that your mom wants to know which logger to enable? What would you tell her? The answer should be part of the form descriptions and/or help texts at the top of the pages. This will be easier if we centralize the settings better.

1. Don't put the loggers in their own package. Put them back in 'Core - optional', please.

Done.

2. I'd consider to merge the configuration screens under a generic 'Logging settings' page. There could be two fieldsets or two sub-tabs. Currently, the different settings appear to be all over the map, which isn't particularly helpful for the user.

OK, done.

They are not all in one screen, but they are in one section. There is a "logging and alerts" under settings now, and that will list each module's settings in there, if the menu hierarchy is admin/settings/logging.

3. We need to do a better job communicating the differences to the user. We need to incorporate practical advice about whether to use syslog or dblog. Imagine that your mom wants to know which logger to enable? What would you tell her? The answer should be part of the form descriptions and/or help texts at the top of the pages. This will be easier if we centralize the settings better.

Centralization is done. I guess we can make this go into core first, then let people use it and refine the wording of each module's description.

Patch attached.

I've committed a slightly modified version of this patch to CVS HEAD. I'm marking this 'code needs work' as it needs work, especially on the documentation front. dblog.css also needs work ... it wasn't included, so I added a basic one.

Good work guys.

I am changing the category to bug report since it is committed.

I started to review new syslog module and I think Windows will be a trouble for this module. I am attaching two patches that works in two different ways.

This one defines LOG_LOCAL[0-7] if Drupal is installed on Windows. This may not work all the time since it depends on some numbers.

This one keeps LOG_LOCAL[0-7] in conditional blocks to keep the code Windows compatible.

DEFAULT_SYSLOG_LEVEL must be DEFAULT_SYSLOG_FACILITY

Erdem

LOG0 to LOG7 are not available on Windows, per the PHP manual.

The syslog module already lists LOG_USER and says "use this for Windows".

The first patch should not be considered, since you hard code values instead of depending on the PHP defines.

The second patch is better, since it default Windows to a define that it can use.

Can someone test it on Windows?

This is a documentation patch, describing more what each module does, so as to give some guidance to the user.

i committed erdem's patch. Khaley's patch will need to be re-rolled, I'm afraid.

Documentation patch rerolled.

great work on these improvements. this is a lovely enhancement to the logging system. reminder: as you're cleaning up the documentation about this, please be sure to update http://drupal.org/node/114774 about these changes, too. thanks!

@dww, thanks for the nudge. I just added documentation for this, and some guidelines.

@kbahey: perfect, thanks!

I created new documentation for hook_watchdog. It is mis-formatted at the moment, but I committed an attempt to fix that.

Also, I rerolled the usability patch that puts more descriptions in the admin pages so as to better describe what happens now.

Committed the documentation improvements! Thanks.

eeek, i just realized there's a critical bug in system_update_6007(). :( update_sql() doesn't understand %d like db_query() does (which, IMHO is a bug in its own right, but that's a separate issue -- however, the fact that so many people looked at this patch and didn't see anything wrong with update 6007 should be ample evidence that update_sql() needs some lovin').

anyway, until update_sql() works like the rest of our db layer, we need to manually inject the int values in the right place in the query, or else when you run system_update_6007() all the severity fields in your whole {watchdog} table get set to 0, the default value for that field. :(

i've tested this and it works, but i'm not going to RTBC my own patch.

p.s. once this patch is committed, we should set the title and other info of this issue back to the original values for posterity. ;)

This is critical.

Setting to RTBC.

Committed to CVS HEAD. Thanks.

A 5.1 port of this patch is available in #149341.

What version of Drupal is this in? Do I need to install a module/patch or has it make it into a release of Drupal?

Thanks.

It's included in Drupal 6 and subsequent releases.