This is not a present problem with core, although with some custom changes to core, it can manifest itself as WSOD.

If someone adds watchdog() calls too early, the module_implements() in the watchdog() function will cause an error, since module.inc would not have been loaded yet.

An example is some changes that we have on drupal.org itself (albeit in Drupal 5.x) where we have something like this in cache.inc to each function:

watchdog('cache', 'cache_set called');

This causes a WSOD, or an error and Drupal will abort. Even if you enable the syslog module, it will not work, because module.inc has not been loaded yet.

Discovering this the painful way on scratch.drupal.org while patching Drupal 5, I decided to have a workaround for it.

So, the attached patch provides a fallback method to log to a plain text file if that happens.

The patch allows a variable $drupal_log to be defined in settings.php and set to a writeable path to log those early errors.

As I said, this is quasi-hackish and is not committable in core in its current state. It is mainly here for those who have 'exotic' needs providing a way for not erroring out and still getting the info you need.

Support from Acquia helps fund testing for Drupal Acquia logo

Comments

Dave Reid’s picture

I don't think this applies to 7.x since we have the function registry now and automatically includes the code it needs to...

kbahey’s picture

It definitely applies to 7.x.

Try it: add a watchdog() call to cache_set(), and visit admin/build/menu and see what happens with or without the patch.

Dave Reid’s picture

Dave Reid’s picture

Here's the fix for D7 that uses drupal_function_exists to make sure module_implements can be used.

kbahey’s picture

This is much nicer of course, but still does not cover all cases, if we are too early.

It will cover the case where you add watchdog() calls in cache.inc, but if you add it in settings.php, Drupal will still die, whereas my original patch will not.

Attaching a version that uses a configuration variable.

Dave Reid’s picture

Status: Needs review » Needs work

That's kind of silly if you were to call watchdog from settings.php... Drupal isn't loaded enough. Also, I don't think we want to get into putting this file output into watchdog, but maybe it would be more appropriate check for drupal_function_exists('watchdog') in drupal_error_handler.

kbahey’s picture

Status: Needs work » Needs review
FileSize
1.2 KB

Not silly at all.

I had that same problem on drupal.org, when testing it on scratch.

There was a line in settings.php saying:

if ($blah) { something ...}

Yet, $blah is really one of the $_SERVER['variable_name'], and no line preceding it to say:

$blah = $_SERVER['variable_name'];

Once I applied the watchdog backport patch the site died because of the undefined variable error, because drupal_error_handler() got triggered.

I found a better solution, but not without drawbacks. Instead of using our own log file, we use PHP's error_log, and that will log it to the web servers' log. This has the advantage of always being there, regardless, and needs no configuration. But, on some shared hosts it may not be accessible.

Dave Reid’s picture

That seems more reasonable, but I still think this logic should be moved to drupal_error, but I would need to test that.

kbahey’s picture

Title: Hack to detect early watchdog errors before module.inc is loaded » Watchdog should work, even if the error is too early, before module.inc is loaded

I guess now that we are using error_log(), this is no longer a hack, and hence changing the title.

The only part that needs polish is the serialize format used.

We use this in the dblog module:

t($dblog->message, unserialize($dblog->variables));

But that is not all that is needed, there is the severity, type, link (if present) and user, and we have to do all that on one line, and make it look pretty.

kbahey’s picture

Here is an example of why this patch is needed http://drupal.org/cvs?commit=150381, albeit on Drupal 6 (which we should port this patch to).

Here is a reroll.

kbahey’s picture

Better formatting of the message when logging to error_log() to make it human readable. This is similar to what syslog.module does already.

Only chx can read serialized arrays on the fly, though he recommended this for mere mortals ...

webchick’s picture

Status: Needs review » Needs work

The code in the else looks eerily like theme_syslog_format() (though slightly different). We should unify those into one function and call it from both places.

+      $message .= '|' . strip_tags(is_null($variables) ? $message : strtr($message, $variables));

One of these lines is not like the others... :)

kbahey’s picture

Status: Needs work » Needs review
FileSize
3.18 KB

Here is a patch that centralizes the code for both watchdog() and syslog.module.

Look! Alligators!

Dries’s picture

Cool little patch. Webserver logging is cool.

The behavior of the patch is a bit odd from a user's point of view:

  • How many people would be able to predict or discover this behavior without explanation?
  • Try explaining the proposed behavior to someone -- it requires words and gestures then should be necessary. I can see the support forums overflowing with: "Yeah, but did you check your web server logs too? You should do so because $long_complicated_explanation."

Wouldn't it be better to provide the user the following options and to make the behavior more explicit:

  1. log to the database (not always possible, logs might be incomplete but accessible from within Drupal site)
  2. log to the webserver logs (always possible)
  3. log to a syslog daemon (always possible

These should probably be checkboxes, not radio buttons. By making it so, the behavior becomes "learnable" and "understandable". We might have to do more still.

chx’s picture

Status: Needs review » Needs work

3) is not always possible. Also I said that I am against the further bloating of poor bootstrap.inc. This is a rare enough edge case. I sugggested loading syslog.module (4K!) from a hardwired path in this case.

kbahey’s picture

Dries,

Here is some background:

Starting from Drupal 6, the ability to log to different places is a configurable feature, depending on the module you enable (dblog.module, syslog.module or emaillog.module from contrib, I can add webserverlog.module to contrib or core if you want it there, just ask).

However, this patch is not about that. It preserves the selection a site admin makes on where to log stuff, but provides a fallback mechanism for those situations where there is an early failure before the module system is initialized

This is useful in mainly developer centric or advanced cases, for example when you enable a custom caching module, or when we are still stabilizing PDO (e.g. key length, data type, ..etc.)

So, this patch is mainly DX, not UX, and will come in handy in many cases.

chx

I hear you about bootstrap bloat. But I don't like the hard coded path include. webchick does not like it either. Any other options? Can we move the format_error_message() function to common.inc? Is that early enough?

pwolanin’s picture

"formar_error_message" is a typo for the function name.

We are also seeing php errors :

Call to undefined function theme() in modules/syslog/syslog.module on line 83

Which suggests something (e.g. the error handler) is trying to call watchdog before we reach the full botstrap and theme.inc is loaded. So, I 'm not sure this chnage is sufficient.

mikeryan’s picture

In #1013302: Versioned dependencies fail with dev versions and git clones (specifically, this comment), I have a different symptom stemming from watchdog getting called too early. Basically, with a versioned dependency in a .info file:

dependencies[] = migrate (>2.3)

update.php reports a requirements failure when Migrate is a git clone of appropriate age, even with git_deploy present. The early call to watchdog() caches hook info too early, so when it's time to drupal_alter('system_info'...), git_deploy doesn't hear about it.

dagmar’s picture

Component: watchdog.module » dblog.module
Issue summary: View changes

Moved to dblog.module for future triage.