Richer exception reporting for watchdog()

Hm. My first though was, what are you talking about, we already do this in _drupal_log_error() :)

But there is a case when we don't, when we are doing rollbacks. See http://api.drupal.org/api/function/comment_save/7 for an example.

Now, transactions aren't yet used in many places, so we could change these calls to include the information we want. However, I think/hope that transactions will be used more and more and it's ugly if we need to do the dirty work all over the place again and again.

My patch introduces a small, fully backwards compatible API change to $transaction->rollback() that basically allows to pass in an exception instead of a string as $message.

PS: Transaction handling in Core is something that needs to be improved and used when it's necessary. The most obvious example (there is already an issue for this), is that when you write a comment which fails and you get a transaction reroll, you still see the green "Your comment has been posted." message)

Can't reproduce the fatal error during the image tests, fixed the node test by looking for the exception string in the variables column. Maybe that should be improved by going to the watchdog page and look for the line including file and line number. so we would already have a test for the new feature. But I want to see first if Image still fails..

This makes sense, with one exception. #4 introduces a hard dependency of the DB layer on _drupal_decode_exception(). We've been trying very hard to minimize and avoid hard dependencies of Drupal against random Drupal-specific functions. (I know people have taken DBTNG, commented out 2 lines, and used it outside of Drupal. I consider that a sign that we have 2 circular dependencies left to remove before it's really good.)

Can we not just grab the data we need directly from the exception? That would be much better than adding a dependency, even if it's technically a little bit of code duplication.

Yeah sure, I'll re-roll the patch soon.

The only thing I don't get is why we have a dependency on watchdog in the first place, but we can't change that now.

Hm, I'm not convinced.

It's not just "a little bit of code duplication", we'd have to add more than 50 lines of code, especially because decode_exception also calls another function.

It's not actually a new dependency (yeah, it's a new function for another file) but it directly belongs to the watchdog() call, If you disable that, then there is no reason for this code to exist at all...

I'm adding both approaches, what are others thinking?

Simple re-roll, both patches should now pass.

To be perfectly honest I think this patch is a sign that our error handling is wrong to begin with. This degree of tight coupling between systems (every direct function call is a hard dependency) is horrible. One of the reasons the DB system is designed the way it is is to avoid hard-dependencies on other Drupal systems. "Oh the file will be loaded already" is the attitude that got us into the current mess where we need to load 10,000 lines of code to have anything work, and those lines of code all have circular dependencies on each other.

We can't fix Drupal's basic architecture here, unfortunately. But to keep the situation from getting worse I'm going to have to favor the "no call" patch and veto the "with call" patch. Introducing "just one more function call" (and no, the current code doesn't, or shouldn't, have a hard dependency on watchdog; that's why we register a callback) is the good intention that paves the road to hell.

I'm also setting this back down to needs review, because yes, the big blob of code in the "no call" patch is still a huge blob of code. Is there any way we can simplify it? How do other frameworks handle this?

The loggingCallback stuff is new if I'm not totally wrong, isn't it :) So yeah, that makes my argument from above at least partly invalid.

One point however remains:

- The main purpose of that exception decoding code *is* Drupal specific, we handle certain functions in the backtrace specially (internal query functions for example), so that we can see the function that called db_query() in the error message. I don't think this is nonsense but a huge DX improvement, that's one of the things I hate about Drupal 5 where we didn't had this (every sql error displays like "bla bla bla in _db_query() ...."). There is no point in keeping most of that code if you use a different logging callback outside of Drupal and no point in having any of this code at all if you don't have a logging callback.

Now, if our exceptions had a better structure, we could maybe handle this in a basic DrupalException from which every other exception extends. (Not 100% sure that this would fly, think PDOExceptions and so on).

Since that isn't going to happen in D7 anyway, what about using another logging callback instead of directly calling watchdog()? Then we only need to introduce a helper function somewhere in Drupal and don't need to change a single line in database.inc.

PS: Just for the record, I still don't see why we have that logging stuff inside the hatabase handler in the first place. Sure, you've removed the hardcoded dependency on Drupal, but why is a database handler responsible for logging an error when an transaction is rolled back? We don't log anything in all the other places where something else goes wrong, the calling code needs to handle it. What about removing that in D8?

Edit: Most other frameworks that use exceptions probably display the whole backtrace and don't try to convert that into a single line so they don't need to "decode" them in the first place :)

The logging callback was necessary for transactions, because we need to "delay" recording of errors in case of a transaction rollback; otherwise watchdog logs get rolled back along with everything else. :-)

However, that said, what about just passing the exception on to the logging callback, vis, watchdog()? Let watchdog handle decoding the exception. That's where we actually need that data anyway, and it puts the error-derivation and error-logging closer together where they belong.

The logging callback was necessary for transactions, because we need to "delay" recording of errors in case of a transaction rollback; otherwise watchdog logs get rolled back along with everything else. :-)

$transaction->rollback();
watchdog(...);

Wouldn't be rolled back, would it? It would be the other way round, of course.

However, that said, what about just passing the exception on to the logging callback, vis, watchdog()? Let watchdog handle decoding the exception. That's where we actually need that data anyway, and it puts the error-derivation and error-logging closer together where they belong.

That could work, I'll create a patch soon. It has in common with my proposal that we don't need to do anything (more than we already do) in database.inc.

Ok, here is a re-roll finally...

Moved the exception handling stuff to watchdog(), haven't tested this yet, let's see what the testbot says.

Gets us more functionality in watchdog, keeps the DB system clean, provides better error logging. Our work here is done. Thanks, Berdir!

+1: This vastly improves our troubleshooting capacity.

I tried this out with a fatal in mainline user code, and got excellent results (for troubleshooting), for example:

PDOException: SQLSTATE[42S22]: Column not found: 1054 Unknown column 'user_register' in 'where clause': select COUNT(*) from {variable} where name="user_register"; Array ( )  in system_block_view() (line 1950 of /home/rfay/workspace/d7git/modules/system/system.module).

(Of course I have no idea why
$x = db_query('select COUNT(*) from {variable} where name="user_register"')->fetchField();
throws an exception like that... I'm looking for somebody to explain it to me.

Related issue: #774882: update.php: errors are not logged needs to take advantage of this excellent information.

While it improves debug-ability, I'm not a fan of variable type parameters (e.g. $message can either a string or an Exception object). I thought it was much cleaner to write $e->getMessage() and to have a consistent signature. If $e->getMessage() does not return the proper information, we should call a different instance method of the exception object. Personally, I think this could be done cleaner so setting it to 'needs work'.

What other instance method? There are no other instance methods on exceptions that provide us pre-formatted data the way we want, nor can we introduce some large Drupal-specific Exception framework at this stage. (Nor do I think that's even wise, but that's another subject.)

If we want rich debugging data made available, we need to extract the information from the exception piecemeal and format it ourselves. We can either do that centrally in watchdog() or scattered about everywhere we use exceptions. I don't see how there's an alternative.

So the options are:

1) Pass an exception to watchdog() (this patch).

2) Require everyone who catches and wants to log an exception to repeat the same call to _drupal_decode_exception() and the rest of that code block in watchdog(), which means that the error string will likely vary in different places and often be missing data.

3) Introduce a completely parallel exception logging mechanism on top of watchdog, which we then also need to find a way to support through the DB layer to avoid the transaction issue and hard dependencies.

I hate variable function signatures too, but I don't see how #2 or #3 are a viable alternative. If you have a suggestion for a cleaner approach please provide it, because this is the cleanest we were able to find.

Also, rfay: I think the problem is that you're putting a column value into the string itself. Don't do that. Use a placeholder for user_register. It's more portable and less prone to breaking.

I'd like to understand what people think of #2. To me, that is a more readable and easier-to-understand solution.

Client code (modules) with Approach #2:

try {
  $transaction = db_transaction();
  do_stuff();
} 
catch (Exception $e) {
  $vars = _drupal_decode_exception($e);
  $message = '%type: %message in %function (line %line of %file).';
  $transaction->rollback('stuff', $message);
}
return; // transaction commits or rolls back as appropriate.

// ...

try {
  do_other_stuff();
} 
catch (Exception $e) {
  $message = 'Ah crap, it died'; // Much less useful than the other message.
  watchdog('stuff', $message);
}
return;

// ...

othermodule_watchdog($type, $message) {
  // All I got is a string.  I can't do anything more robust with it.
}

Client code with Approach #1:

try {
  $transaction = db_transaction();
  do_stuff();
}
catch (Exception $e) {
  $transaction->rollback('stuff', $e);
}
return; // transaction commits or rolls back as appropriate.

// ...

try {
  do_other_stuff();
} 
catch (Exception $e) {
  $watchdog('stuff', $e);
}
return;

// ...

function othermodule_watchdog($type, $message) {
  if ($message instanceof Exception) {
    $vars = _drupal_decode_exception($e);
    // I can do all kinds of fun stuff here.
  }
  else {
    // All I got is a string.  I can't do anything more robust with it.
  }
}

Approach #3:

try {
  $transaction = db_transaction();
  do_stuff();
} 
catch (Exception $e) {
  $transaction->rollbackWithException('stuff', $e);
}
return; // transaction commits or rolls back as appropriate.

// ...

try {
  do_other_stuff();
}
catch (Exception $e) {
  watchdog_exception('stuff', $e);
}
return;

// ...

function watchdog_exception($type, $e) {
  $vars = _drupal_decode_exception($e);
  $message = '%type: %message in %function (line %line of %file).';
  watchdog($type, $message);
}

function othermodule_watchdog($type, $message) {
  // All I got is a string.  I can't do anything more robust with it.
}

Really, this patch is not about the DB layer specifically now but about logging Exceptions in a centralized fashion rather than relying on everyone who catches an exception to pull out the right data to log in the same way. It's just complicated by the DB layer because of transactions rolling back dblog.module logs as a side effect. The approach this patch takes, and core takes now, is to delay the watchdog call until after the transaction has rolled back and then execute it.

#2 is a fail because it would, as shown above, rely on every caller formatting the exception in a useful and consistent fashion. That's unlikely to be something we can rely on.

#3 as above is a possibility, but it doesn't expose the exception itself to other hook_watchdog() implementations unless we add hook_watchdog_exception() and have a parallel version. It also doesn't implement DatabaseConnection::rollbackWithException(), mostly because I have no idea how we'd do it in a clean fashion. (Direct function calls from within DatabaseConnection do not count as clean.)

The only way I can see to make #3 work, and I just thought of this so it may be a totally stupid idea, is to remove the rollback parameters entirely. Instead, make dblog_watchdog() use an entirely different DB target, say, DatabaseConnection::getConnection('watchdog', 'default'); Then we'd have to setup a cloned connection to that target that is based on the one defined for default:default. While that would side-step the problem, it also means that watchdog logs made during the transaction (like "your node was saved successfully") would not be rolled back. (To be fair, though, they only roll back now if you're using dblog. Any other hook_watchdog() implementation already has this issue.) It also means a second DB connection would need to be opened for any logging, which is an extra performance cost. (The amount of that cost varies depending on the database you're using.) The targets system was actually designed to support that, but we never got around to it for various reasons (mostly relating to time and performance concerns). We would then still need to add either the utility function or hook, depending on the route we want to take.

And beta is coming up fast. :-)

0) Agreed on not putting a exception framework into core.

1) One problem of this patch is that you currently can not change the given error text. For example in #774882: update.php: errors are not logged, we might want to add in which update hook the exception occured.

2) This will look like this (untested):

require_once DRUPAL_ROOT . '/includes/errors.inc';
watchdog('type', '%type: %message in %function (line %line of %file).', _drupal_decode_exception($e), WATCHDOG_ERROR);

I don't like that we have to add the require_once call, but the rest looks do-able, It is not that much of an overhead.

3) I'd like this, if it would not create a problem inside the database layer. Such a function could look like:

function watchdog_exception($type, $exception, $message = '%type: %message in %function (line %line of %file).', $variables = array(), $severity = WATCHDOG_ERROR) {
   require_once DRUPAL_ROOT . '/includes/errors.inc';
   $variables += _drupal_decode_exception($exception);
   watchdog($type, $message, $variables, $severity);
}

The only problem here is that we would need to drop support for passing strings to $transaction->rollback(). But again, I totally fail to see why we pass the watchdog message through the database layer in the first place. Given the above method, why not doing this:

  $transaction->rollback();
  watchdog_exception('whatever', $exception);

Our database layer currently defines a loggerCallback, has methods to check and log messages to that callback (which is a callback but the arguments are hardcoded to work with watchdog() so every other application out there using our database layer will need to define a wrapper function which then calls the actual logging function. And all this just for $transaction->rollback() is is not used anywhere else.

IMHO, the only drawback of removing it is that we need to clearly document that modules log errors after rolling back exceptions.

@Crell:

- Can you please explain why we need a separate db connection? as long as we call watchdog() *after $transaction->rollback(), we're good or not? See my post above.

- Note that hook_watchdog() does not see the exception with the current implementation, we already convert it inside watchdog().

The reason for the convoluted pass through the DB layer is that $transaction->rollback() does not roll back the transaction. It flags the transaction to be rolled back later at the appropriate time. That doesn't actually happen until $transaction is destroyed by going out of scope, which is after any call we make to watchdog(), so the watchdog log of what just went wrong would get rolled back as well. Yes, all of this silliness is there to get around dblog.module. :-) A separate DB connection for dblog.module (which is unaffected by the open transaction on the main connection) would get around that as well, but has other challenges: Specifically the fact that it uses a second database connection.

$transaction->rollback();
unset($transaction);
watchdog_exception('whatever', $exception);

:p

Funny things aside, why is that? I think I see why we automatically commit, by what exactly is the "appropriate time" to roll back something? Why is that not now?

According to that, the following code won't work either:

$transaction = db_transaction();
try {
 // Try something we know that *might* fail but we can't check it in advantage.
} catch (Exception e) {
  // Uh oh, somethin went wrong.
  $transaction->rollback();

  // 1. Because the above failed, we need some special handling here. Could be as simple as storing that we failed to do something and need to re-try at a later point.
}

// 2. Do more stuff and execute queries.

Now, neither 1 nor 2 will actually work as expected, right? To have it working, you would need to wrap the in-transaction stuff in a inner function, rollback, re-throw the exception and then do 1 and/or 2. I haven't noticed that before, is this documented anywhere (http://drupal.org/node/355875 doesn't mention it)? I think this might cause *major* headache when you try to figure out why your code in 1 or 2 is not working...

I'm just trying to understand this....

It has to do with nested transactions, which are all kinds of weird. Those did get changed recently, though, so we should get David Strauss in here to see if it still makes sense.

Still ,that would only deal with half the issue. The other half is logging exceptions sanely.

OK, so I talked to David Strauss in IRC, and it turns out that an interesting side effect of the recent changes to the transaction system to support real nested transactions is that rollback() *does* now rollback immediately rather than on object destruction. That in turn renders the need for the wonky callback on the connection object moot.

So if we strip out the connection callback from the connection and allow this to be "the way it's done":

catch (Exception $e) {
  $transaction->rollback();
  watchdog('stuff', 'Eeek!');
}

Then option #3 becomes viable, either with a wrapping function or an extra hook.

(I'd be happy to be rid of the callback nonsense, frankly.)

I still don't see #2 as a viable option.

Dries, Berdir, what are your thoughts on either a utility wrapper as above or an exception-specific watchdog hook?

Awesome!

i don't have a strong preference, but I personally would go for a simple wrapper function unless you can give me a use case where we need a exception specific hook.

Will try to roll a patch soon, we can probably delete quite a bit of code.

Ok, here is a patch, let's see if this passes the tests.

All that loggingCallback stuff was only used for logRollback(), so I removed all that for now. We can add it back if we don't want to drop it.

I've noticed that we logged if we couldn't roll back the exception because the db doesn't support it, not sure what to do there. Maybe returning TRUE/FALSE?

+ * currently in, which is managed by the connection object itself The thrown
+ * exception can be logged with watchdog_exception() after the transaction
+ * has been rolled back.

There's a missing period in the first line, before "The thrown".

Also, the docblock for watchdog_exception() is confusing. It implies you can pass in a message or an exception, when in practice the exception is required. The default value for $message should also not be in the function signature. People are going to want to specify the severity more often than the message, I wager, so they'll want to either have $message come last (inconsistent with watchdog()) or be able to just pass in NULL or '' or something for the message for "yeah yeah use whatever" rather than having to replicate the complete non-trivial string.

Other than that, I really like the number of - lines there are in this patch. :-)

- Added the missing .

- Tried to improve the documentation and moved the default value out of the function signature. Not sure if it is really better now, but I tried :) Could use some help on that part...

Other than that, I really like the number of - lines there are in this patch. :-)

Actually, it scares me a bit :p

Ups...

Dries, I can handle this approach. Can you? :-)

That works for me! Will commit in the next 24 hours.

In D8, it would be nice to rename watchdog() to log_message() and watchdog_exception() to log_exception() or something along those lines. That would make the API more balanced / symmetric.

Few niggley bits:
includes/database/database.inc +126

+ *   // $txn goes out of scope here.  Unless the transaction was rolled back, it

$txn no longer is a variable.

@@ -1716,35 +1596,16 @@ class DatabaseTransaction {
    * Rolls back the current transaction.
    *
    * This is just a wrapper method to rollback whatever transaction stack we are
-   * currently in, which is managed by the connection object itself.
-   *
-   * @param $type
-   *   The category to which the rollback message belongs.
-   * @param $message
-   *   The message to store in the log. Keep $message translatable by not
-   *   concatenating dynamic values into it! Variables in the message should be
-   *   added by using placeholder strings alongside the variable's argument to
-   *   declare the value of the placeholders.
-   * @param $variables
-   *   Array of variables to replace in the message on display or NULL if the
-   *   message is already translated or not possible to translate.
-   * @param $severity
-   *   The severity of the message, as per RFC 3164.
-   * @param $link
-   *   A link to associate with the message.
+   * currently in, which is managed by the connection object itself. The thrown
+   * exception can be logged with watchdog_exception() after the transaction
+   * has been rolled back.
    *
    * @see DatabaseConnection::rollback()
-   * @see watchdog()
+   * @see watchdog_exception()

Since there is no evidence that there every was watchdog code here, it doesn't make sense to talk about it in such away. We'd be better off to make a note to the document reader that rolling back will prevent watchdog logs from being written unless watchdog_exception is used.

Just those two things, I wouldn't call it enough to not RTBC it.

Sorry I haven't read the whole thread, but was it considered to open a second, non-transactional, connection to the default database explicitly for logs? A second connection will be unaffected by transaction rollbacks.

Let's get a quick reroll though to fix those two comments.

I removed all instances of $txn to $transaction changes. I did that because AFAIK the coding standards say that we do not abbreviate variable names but doing it in this issue is killing poor kittens.

During that, I also noticed that block_admin_display_form_submit and block_admin_configure_submit in block.admin.inc both *start* a connection but then don't have any exception handling. So they are starting a transaction but *always* commit it, even in a case of an exception. Imho, this is wrong, should I open an issue for that? See http://api.drupal.org/api/function/block_admin_configure_submit/7 for example.

I don't understand the second point. I'm just trying to say that you need to log the exception *after* you're doing the rollback. I tried to improve the docs, if that's not better then please tell me more explicitly how to improve it :)

And yes, Crell had the idea about a second connection too, but opening a connections always costs some time....

Looks good to me. Let's get this in and then open a new issue to sort out $txn vs. $transaction.

There's also a related documentation cleanup issue here: #788554: Improve documentation for how to use database transactions in database.api.php

Much better, and looks good to me too. Committed to CVS HEAD. Thanks.

This is blocking the upgrade path: Recoverable fatal error: Argument 2 passed to watchdog_exception() must be an instance of Exception, null given, called in /Applications/MAMP/htdocs/d7up/includes/menu.inc on line 2311 and defined in watchdog_exception() (line 1561 of /Applications/MAMP/htdocs/d7up/includes/bootstrap.inc).

tagging

Yeah, I got that wrong :)

I guess we don't have a test for exception handling in that function :)

Committed to CVS HEAD. Thanks!

Definitely fantastic.

re #34:

All that loggingCallback stuff was only used for logRollback(), so I removed all that for now. We can add it back if we don't want to drop it.

That was the only use in core - we have been (or had been) using it in the Migrate module: #748884: Better error handling.

I'll see if I can cobble together a means to use hook_watchdog(), have to figure out how the hook implementation can find the class instance in which the error occurred...

Also related: #748982: Allow Database logging_callback to be a class method

Poor SQLite.

Heh @ patch name. :)

Committed to HEAD.