A bad call to watchdog() should not break the error logging system.

I've not read the patch but for me this sounds like a strange idea; it's better to make a patch to the module that is where the error is.

Seems like the protection should happen before serializing rather than after unserializing (i.e. on store rather than on retrieve).

Then it should check *both* places, for paranoia's sake.

Also, two tests should be written:

1. Try to call watchdog with improper values and assert failure.
2. Manually insert bogus data into watchdog table and assert that the log can still be viewed.

The attached contains the tests suggested in #1492898-8: A bad call to watchdog() should not break the error logging system..

Case 1 creates a watchdog call using watchdog('module_name', 'Error', WATCHDOG_ERROR);, and then selects the message back from the database and asserts that the variables field in the database is a serialized php.

Case 2 manually inserts a record into {watchdog} with intentionally bad data. Then the admin/reports/dblog is checked to make sure there is no error.

I think we came up with fixes for both cases. Case 2 is covered by the patch in #1492898-2: A bad call to watchdog() should not break the error logging system.. Case 2 is fixed in dblog_watchdog by checking if the passed variables value is an array or null before inserting into the database. If a non-null non-array value is passed, it is wrapped in an array before being saved to the database.

We're not sure of the reason for the need to check that variables is not null for case 2, but other dblog tests fail without it. It would probably be good to get some more eyes on that to make sure it's the right solution.

Thanks to greengurl and simplicitymetrics for their contribution on this.

After a bit more discussion at the drupalcon sprint, I'm pretty sure this is something that shouldn't be fixed. I'll attempt to explain the reasoning:

The central issue is is the bad call to watchdog. watchdog('module_name', 'Error', WATCHDOG_ERROR); does not use the right parameters. If you want to specify an severity, you have to include the (in this case empty) array for use with t(). If you don't you will get an bad record in the database. It is not the problem of drupal core to prevent module developers from using core apis incorrectly.

The other issue is that the bad record created by misusing watchdog breaks the dblog gui. It does not prevent future messages from being log. Because the proposed solution works in the theme layer, it will only work if the site is not using a custom theme_dblog_message. Once they do, it will probably be broken again.

There might be a solution by moving the unserialize call into the preprocess function, which can then account for bad data coming from the watchdog table, but this would not be backportable to d7 because it would break implementations of theme_dblog_message which rely on that parameter being serialzed.

Right now the solution is to fix bad calls to watchdog. If you need to have the proposed solution on your site, you should be able to get the same effect by implementing theme_dblog_message in your theme and use the logic in the attached patch.

This violates the "Never hide coding errors" culture of Drupal. Perhaps the main watchdog() function could use some sanity-checking, like:

  if (!is_array($variables)) {
    $t = get_t();
    $key = '!INVALID_WATCHDOG_VARIABLES_PARAMETER';
    $error = $t('Invalid call to the watchdog() function. The third parameter must be an array.');
    $variables = array($key => "<br />$error");
    $message .= $key;
    drupal_set_message($message, 'error');
  }

Or even:

  if (!is_array($variables)) {
    throw new Exception('Invalid call to the watchdog() function. The third parameter must be an array.');
  }

Sorry; crosspost.

My position is that:

1. Calling watchdog with invalid parameters should trigger an immediate error rather than silently making the error log unviewable.

2. It should be possible to view the error log even if one or more records contain bad data.

Here is a tests-only patch. If at least one person agrees that this is the correct approach, I will attempt to write code that makes the test pass.

Might as well let the testbot verify that it fails.

This is one of those nice to have, but not need to have issues.

The primary fix to this issue is to call watchdog correctly (which I may be doing incorrectly since I frequently use NULL as the third parameter).

However, if bad values are written to the table (since there is no type checking on input), it should not result in the report page being inaccessible. The error log is one of the first places people turn when there is a problem. It sure would help if gave some clue about what the issue might be, especially for those just starting out on the steeep Drupal learning curve.

As a result, I am all for improvements and potential type checking in how the watchdog data might be used or summarized. +1 @pillarsdotnet.

I'm still not quite convinced that the proper course of action is to make watchdog throw an exception. It seems like it's venturing down the path of "it's the responsibility of the API to make sure it's used correctly." If it is important that we get an exception to prevent bad data into the watchdog table, should

+++ b/core/modules/dblog/dblog.testundefined
@@ -48,6 +48,43 @@ class DBLogTestCase extends DrupalWebTestCase {
+    db_insert('watchdog')
+      ->fields(array(
+          'type' => 'test',
+          'message' => 'Test Watchdog message with bad data.',
+          'variables' => 'This is not a serialized array.',
+          'severity' => -1, // This is not a valid WATCHDOG constant.
+          'location' => 'This is not a valid url.',
+          'hostname' => 'This is not a valid hostname.'
+        ))

Throw an exception as well?

I do, however, agree that the dblog should not be made unaccessible because of bad code. But since we can never catch all the ways bad data can be inserted into {watchdog}, the only solution which will prevent that is to fix it at display time (this making the proposed changes to watchdog a separate issue; one that is worth discussing). But is the proper way to do this by doing sanity checking in the theme layer?

I'm still not quite convinced that the proper course of action is to make watchdog throw an exception.

It would certainly make it easier to troubleshoot the root cause of the problem, which is a bad call to watchdog. In general, the Drupal core philosophy of handling bad data from external code sources is to fail immediately and spectacularly, to provide both motivation and instruction in correcting the external coding error.

It seems like it's venturing down the path of "it's the responsibility of the API to make sure it's used correctly."

No, it's venturing down the path of "It's the responsibility of the API to report failure as soon as possible." Remember that the existing code also generates an exception, but only after an indeterminate amount of time has elapsed.

But since we can never catch all the ways bad data can be inserted into {watchdog}

Exactly. The insert doesn't even have to come from Drupal, so there's no point trying to catch it at insert time, unless you're going to rely on non-portable database constraints.

the proper way to do this by doing sanity checking in the theme layer?

I disagree. The proper thing is sanity checking before calling functions that assume a certain class of data, especially when failure would render debugging of the root cause more difficult.

But my point is:

Does this look like a valid test? If so, I'll code a solution that makes the test pass. If not, there's no point in trying.

It looks like the functionality in the test is right, but the first part seems to be more a test against watchdog and not dblog. It probably belongs in a different test file; maybe bootstrap.test? Might even make sense to file the change for watchdog as another issue.

Okay, here's my first attempt at making the tests pass. Let's see what the testbot says.

Corrected.

Grrr...

Move sanity-check to its own function.

Another try...

How can the retrieved NOT NULL field value not be set?

Okay, maybe something is calling watchdog before common.inc is loaded?

Or maybe the database row object should be cloned before being modified?

Okay, I give up. Going to test locally until I work out those bugs.

Okay, this passes locally, although the core/includes/common.inc fragment may only be necessary because I'm running nginx instead of Apache.

+++ b/core/modules/dblog/dblog.admin.incundefined
@@ -6,6 +6,41 @@
+ * @return object
+ *   A sanitized clone of the passed object.

The function does not actually return a sanitized object. Also surprised that dblog_overview() does not use the sanitized dblog object as I would expect based on the function name.

Unnecessary hunks removed. The common.inc fragment was definitely a workaround for an nginx bug.

@Lars Toomre: Sorry; forgot to update header when I changed the function back.

Just noticed those "11 passes" (WTF?)

Maybe fixing?

I forget that PHP 5.3+ passes as a default objects by reference. Does it make sense to modify the code to make it an explicit call by reference? This would result in the following and make clear how the sanitized result is returned.

function dblog_sanity_check(&$dblog) {

Here's the interdiff between #39 and #43:

UPDATED: See #1502906: Bot #699 is passing everything in core with 11 assertions

(interdiff removed for brevity)

Interesting that this sanity check caught an otherwise unnoticed bug. The dblog_top() function wasn't bothering to select the severity field before passing data to theme('dblog_message'...).

@@ -99,10 +128,11 @@ function dblog_top($type) {
   $query = db_select('watchdog', 'w')->extend('PagerDefault')->extend('TableSort');
   $query->addExpression('COUNT(wid)', 'count');
   $query = $query
-    ->fields('w', array('message', 'variables'))
+    ->fields('w', array('message', 'variables', 'severity'))
     ->condition('w.type', $type)
     ->groupBy('message')
     ->groupBy('variables')
+    ->groupBy('severity')
     ->limit(30)
     ->orderByHeader($header);
   $query->setCountQuery($count_query);
@@ -110,6 +140,7 @@ function dblog_top($type) {
 
   $rows = array();
   foreach ($result as $dblog) {
+    dblog_sanity_check($dblog);
     $rows[] = array($dblog->count, theme('dblog_message', array('event' => $dblog)));
   }

It would be quite natural for a theme implementation to assume that a dblog event object has a severity field and to theme the message display accordingly.

@#44, No, passing an object by reference is an error. But I'll update the function header to note that it modifies the object in-place.

Also renamed dblog_sanity_check() to dblog_sanitize_row().

 /**
+ * Sanitize a dblog event object to meet theme expectations.
+ *
+ * Ensures that the variables field contains a serialized array, and that
+ * the severity field contains a valid logging severity constant.  If either
+ * constraint fails, corrects the data and appends an appropriate notice to
+ * the message field.

My understanding is that the docblock needs to start with an active verb (ie 'Sanitizes'). I would also change the subsequent explanation to be complete sentences, such as "This function ensures that the ..."

Corrected.

Hi folks,

I've just made the incorrect call to watchdog's function and now my logs are unaccessible.

How do I recover from that? Should I just truncate the watchdog table?

I'm glad you've also identified this issue.

a.

You only make this mistake in development and then you can truncate and fix your code. It doesn't worth adding another N lines to core IMNSHO.

If you want Drupal not to stop at Recoverable Errors you may define your own error handler to overwrite Drupal's error handler function (see _drupal_error_handler_real()).

Place something like this in your settings.php, preferably not at your production site:

set_error_handler('catch_recoverable_errors', E_RECOVERABLE_ERROR);
function catch_recoverable_errors($errno, $errstr, $errfile, $errline, $errcontext) {
  // do something useful
}

There are 3 reasons why I think this should be fixed, in decreasing order of importance:

1) It is important that Drupal core does not allow contributed modules to accidentally destroy core functionality. Let me give an example: let's say contributed module X accidentally includes an incorrectly coded watchdog() call. Imagine that hundreds of users (99% of whom have no SQL knowledge) install this version of the module along with other automatic upgrades. Most of them sooner or later have this wrongly coded call to watchdog() get called. This breaks completely the Report log. They are not programmers so they can never again check their Report log!! It was not Drupal core that caused the problem, but core should be a little more robust than that.

2) This is a huge pain for even normal developers. I hit this error because I've obviously made somewhere a mistaken call to watchdog(). It has now trashed my ability to easily view my production report log, which is extremely unfriendly. Sure, it was my fault for no doubt calling at some stage the watchdog() function with a wrong parameter, but to make the report log completely inaccessible is really a completely unacceptable error handling.

3) Much of the work to fix this problem has already been done by developers such as pillarsdotnet so I think adding a few extra lines of code to core is well worth the effort.

If you have some idea of which error messages are causing the problem you may get away with deleting only some of the watchdog messages, e.g.

delete  FROM `watchdog` WHERE `type` LIKE '%naughty_module%'

See #1279680: watchdog() does not type its array arguments the solution was to add type hinting. The point is not that the work is done but the code is pointless apis should be called with appropriate parmeters and in a sensible way.

Duplicate of #1279680: watchdog() does not type its array arguments - discussion is still ongoing over there about exactly if / how this should be fixed.