Drupal Exception Wrapper Class

Not sure what was going on with the title.

From what I was able to tell by experiment and poking around in the code, exception logging in core is only applicable when the exception bubbles up all the way. The exception should be logged even if it is caught and the overall process continues unabated.

At admin/settings/logging you can choose whether or not to display PHP errors, and I'm thinking that it would be consistent to place the option on that same form. Overall I'm thinking that a hook might still be an appropriate way to handle the actual output, but that deserves more thought.

When you do a watchdog call, you pass in the variables that you want to log in an array, and the message in a translatable string. That's more or less what I was thinking of here, passing in the variables array in the new DrupalException() call.

Hrm, one of the main reasons we chose to log on shutdown was because (as the exception bubbled up) we could catch, add data, and then throw in a variety of our core rendering functions because the stack trace won't contain info about variables not passed in as arguments (but the global $user id can still be relevant). This doesn't really play into the traditional watchdog variables methodology, because these extra bits of data aren't available at the time of the message creation and aren't in the same scope, but are still useful. That should still be possible to work around.

I disagree about not logging caught exceptions.

Unless someone is using the exception system as a message-passing tool (which is bad for all sorts of reasons), an exception represents a *problem* during the overall rendering of the page / running of a script / etc. If it's a fatal problem, we display an error page. If it's minor like my sidebar widget example, then we don't need to scrap the whole execution so we catch the exception, but we still want to let a site admin know that the sidebar widget is broken. Making that process automatic removes a burden from the developers, and also ensures consistency.

The alternative is to force developers to both throw an exception and (immediately prior to that) record a watchdog message. Or, any time you write a try / catch you will have to put a watchdog call in the catch. That doesn't seem like a reasonable response to some developers mis-using the exception system overall.

If there is no problem going on, the developer shouldn't throw an exception and instead should (optionally, usually notice level) make a watchdog call and (mandatory) leave the function gracefully.

I'm all for making caught exceptions and uncaught log at different levels, however. Then it puts the option squarely in the hands of the site admin.

In any case, I think we should at least hurry and get some stubs in place and get the current exceptions converted. Matters like when / where to log the data don't affect the need to have a standard exception class, and that standard can be extended later as needed.

Plan for initial version, which I hope to have in patch form by next Monday:

* Create the class, modify all existing core Exception classes to extend it
* Change all throw new Exception lines to throw new DrupalException
* Interface with Watchdog in a sensible way
* Ability to append data to the exception and then pass it back up the tree
* Have stack traces available in some form
* Treat caught and uncaught differently, according to some settings (specifically, treat everything as caught until it hits the top level then change a flag)
* If DB is not available for watchdog message, trigger_error instead (may do it in a different patch)
* Possibly have more developer-friendly output via a patch to the Devel module (including an option to output potentially sensitive info)

edit: reminder to self -- depending on how the logging works out, there may need to be a function call to temporarily suppress exception logging

I have a basic version in place, patch attached. As is, it would be an improvement to get the class in place, and we can further extend it later. Further documentation, etc. to come.

Current version notes:

* Class created
* Now thrown / extended as needed in the rest of the code
* Exception messages are fully translatable, including the string replacement from array logic
* By default, logs at WATCHDOG_NOTICE level if caught, WATCHDOG_ERROR if uncaught
* Method for catch -> add data -> throw pattern, which helps with debugging
* Modified dblog_event to also display all variable data, which is often redundant but in this case allows variables not used in the message to be seen through the admin

Now that exception messages are translatable, there are a number of places that should be modified to use it. I modified the one place in core that needed to change.

Also, I didn't change anything in the simpletests because I'm not sure if they should be normal exceptions or DrupalExceptions.

Some remaining items that I haven't really found an optimal way to handle yet:

* Full stack trace for development - will probably add to devel module instead of doing any logging in core, since it's a lot of data
* Full data logging when database is unavailable (will currently just log the PHP error from uncaught exception handler)

Some usage examples are below.

try {
  throw new DrupalException('test !one !two !three',array('!one'=>'a','!two'=>'b'));
} catch (DrupalException $e) {
  // Normally this would happen in a different function.  For
  // example, the block rendering function might add some info 
  // about the block and then continue on if the block fails to 
  // render.
  $e->addVariables(array('!three' => 'c'));
  // If for some reason you don't want this caught Exception to log:
  // $e->setShouldLog(FALSE);
  // Sometimes adding variables is helpful even when the 
  // Exception is not going to bubble up, for debug purposes.
  throw $e;
} catch (Exception $e) {
  // This could do something different if desired, but
  // normally any non-DrupalException is going to be fatal
  // and we can just leave it uncaught.  However, we do need
  // to handle non-Drupal exceptions in places like the cron
  // where we often want the execution to continue regardless.
}

Didn't realize that the patch ended up with a .txt extension... fixing for testing system.

And the patch...

When your IDE fails you...

Term saves the day.

Added suggestions from chx / Gabor.

I left $shouldLog protected with a setter because the setter does something other than just chance the var (registers shutdown func). The watchdog member vars are now public, and the setters / getters are gone.

The t() is also gone, but I think that it's still worth adding back eventually. The t() function is used in that way in a dozen or so places in core already, so it's not inconsistent. Even if nobody ever translates an exception message (which has somewhat limited utility anyway, since the code is English), the t() still does the variable text replacement so you don't always have to look up the exception in the watchdog report.

I see two possible solutions for translating exception messages (if it's valuable to do so):

* Change the code that looks for t() and provides a list of translatable strings to also look for this - new *Exception('*
* Chance the usage to new DrupalException( t('The message !var', array('!var' => 'value')))

I don't really like the second option because the logging won't be as good (you no longer have the variables separated out), and it's not as transparent to the developers.

Damien, in practice there should be very few exceptions thrown during a given run, but I'll see how a static array works out next time I'm digging around in there.

yched, in this version you would throw new DrupalException('message', $vars_or_code, FALSE) to avoid logging those user errors.

My general preference is to err on the side of excessive NOTICE-level logging rather than accidentally failing to report something that was important, but if the general consensus is do default to not-logged then I'm OK with that. Any other opinions?

chx, reconsidering the setters:

The general reason that people use the usually-bloated getter / setter pattern is the same reason that core uses wrappers for PHP functions; if we find an issue with a wrapper-less function later (often enough UTF-8 issues), then it's an enormous pain to fix because we have to fix 100 places in contrib instead of just one place in core.

I don't think UTF-8 specifically will be an issue, but I also don't believe we can safely say that some Exception class down the line won't want to extend a setter to something more than just $this->var = $var.

Lesser of two evils?

Cross-post, in the event that potx needs modifications: #533296: Exceptions and potx

Last week I talked at a fair length with Crell in IRC, and here are some notes now that I've had some time to digest it some.

Most places that do a catch are going to catch Exception anyway (or DrupalException then Exception) because they also have to worry about PDO Exceptions and / or DB exceptions (Crell expressed a desire to keep the DBTNG layer loosely coupled with Drupal core, which may result in the DB layer not using the DrupalException class at all). So, we will probably need a utility function drupal_log_exception($ex) that accepts either a DrupalException or Exception. Then, most of the time the developer won't have to care what kind of Exception it is.

With the DrupalException close to the current form, this helper function will just set logging to TRUE if it's a DrupalException, or do a watchdog call if it's a plain Exception (passing in the Exception message text).

It is impossible to translate all Exceptions via potx, because potx won't have access to the source of any libraries getting compiled in to PHP (which usually throw PDOExceptions). However, my vote is that we still pass the Exception $messages through t() when we log them (and / or during display???) so that it is possible to do the translation manually if desired. I'm still undecided which is better: throw new DrupalException(t('message !var', array('!var' => 'val'))) and just taking $message or having DrupalException take the same args as watchdog, but I'm leaning towards the watchdog syntax even though it will require some potx regex changes.

The other issue brings up some important considerations:

"The exceptions seem to need to end up two places, on the form via form_set_error() and logs via watchdog(). watchdog() wants the untranslated string and arguments and form_set_error() needs a form element to blame so I added a DrupalException class that can handle this bit."

The current versions on this issue don't report form errors that well, I'll roll it in.

In the other version, the DrupalException calls parent with the translated string as the message. I'll have to put some more thought into that one, not sure where it will come into play.

New patch coming soon, I'd love to get this in before the cut-off date.

Summary so far (this is of course my opinion, so chime in if you disagree on anything):

This is a developer experience issue. Since D7 is PHP5 only, we can replace the drupal_set_message then return (and pray) workflow with a thrown exception. A core exception system could handle logging, displaying messages to the user, and form validation error messages.

The old way also runs into major problems when an error occurs deep down the code tree and you need to detect / handle the situation gracefully, usually because some function in the middle doesn't return an appropriate result on error.

Minimally we need to have the following in core for this to work well:

* Some functions for gracefully logging and handling PDOExceptions and other errors from external libraries
* A core DrupalException class to hold the additional data that Drupal needs on errors (form source, watchdog data, etc.)
* Sensible translation scheme

Additional wishlist items:
* Ability to pull a stack trace for a given logged exception and / or display it to the screen
* More powerful logging tools and logic
* If the database has gone away, log to apache error log (this is a definite candidate for a different issue)
* Easy to get all the needed data into

And items of contention:
* How much code is appropriate to put into common / bootstrap
* What should be handled by the Devel module (or similar contrib code)
* By default, should a caught exception log? This determines whether a developer needs to explicitly log or suppress a caught exception (they will often need to do one or the other).
* Should we pass variable strings to t()? This allows PDOExceptions to be manually translated, but potx will need a patch to its regex.
* Related to the above: new DrupalException(t('my message')) or have DrupalException handle it transparently?
* OOP - when a painful bug fix later can be avoided by creating a public function now, prefer future-proofing or un-bloated core?
* Are shutdown functions acceptable from a performance standpoint? In this case they will only be registered when an exception is going to be logged.

Future, not critical for code freeze:
* More behavior settings for exceptions / logging

My line of thinking was: if the default case is to log, less experienced developers won't really even have to think about it in more cases. But it's pretty much a toss-up in my book, I can get behind either approach.

I did plan on having a setting at some point, specifically a threshold to log to the database. If the uncaught and caught exceptions are logged at different levels, it's easy to ignore what you want on the production environment.

However, the default still determines what the actual code will have to look like. The developers will either have to explicitly prevent recording some messages or explicitly log some other set, and the code will accommodate one or the other. I'm pretty sure they're mutually exclusive.

Notes from IRC:

* Going to scrap automatic logging of caught exceptions for now, add a setting to enable it (or devel module hook or something) later.
* PHP Magic Methods for getters / setters eliminates the need for actual ones entirely, since we can make the change silently later if it's needed (thanks cwgordon7).
* Some interest in the ability to catch, add data, and throw to add context to an exception. I think I'll leave that in, since it shouldn't add much of a code or memory footprint by itself. May still split it off into a different issue.

Attached is a basic patch, with the sole intent of getting the API established ASAP. I fully intend to get simpletests, etc. in place afterward.

Sample usage:

try {
  throw new DrupalException(
    'test !one !two !three', //$message
    array('!one'=>'a','!two'=>'b'), //$variables
    WATCHDOG_ERROR, //$severity (unless changed when logged)
    l('Account','User') //$link
  );
  // Normally you should use DrupalException unless the code needs to be possible to run outside Drupal.
  throw new PDOException('PDO FTW');
} catch (DrupalException $e) {
  // This kind of a catch block is normally just to affect logging. For
  // example, the block rendering function might add some info
  // about the block and then continue on if the block fails to render.
  $e->addVariables(array('!three' => 'c'));
  // If you want the Exception to log even though it has been caught, do this:
  watchdog_exception($e);
  // Sometimes it is helpful to add variables even when the result is still going
  // to be fatal, so there is more to go on in debug.
  throw $e;
} catch (Exception $e) {
  // Catch Exception any time that you want to prevent a proces
  // from failing regardless of the error source, rather than just
  // affect logging.
  watchdog_exception($e);
  return 'got a normal exception but logged it!';
}
return 'all is well, continue on.';

For later:

* Simpletests
* Documentation
* Getting the API used throughout core (some catch blocks may need be modified, and almost all custom Exception classes, form validation)
* potx expression changes
* Better output to the screen, including more consistent use of t()
* Stack traces
* Log differently when the DB isn't available
* _drupal_decode_exception should pass variables up the tree, so it can be translated without logging the translated version to the DB

Thanks for the review!

I removed the var_dump.

The double-logging is because _drupal_decode_exception needs a rewrite for a number of reasons (as noted in comment 46), but that's not an API change so I'm going to do it in a separate patch.

I'm not seeing a double-log when it is caught, using code in my sample above.

Thanks for the review!

The drupal_render_cache_set() items were trailing whitespace removed by my IDE. I can remove them from the patch if you want, but I believe we're supposed to remove trailing whitespace anyway so it should still be an improvement.

} catch (Exception $e) { - There was one added in my patch, and two that already existed in the database module. I removed the one from the patch, but I'm hesitant to remove the other one yet. I opened a separate issue: #576248: [policy] Coding Standards Update for PHP5

I cleaned up the DrupalException constructor comment, it had leftovers from a previous patch that no longer applied.

NOTE comment format changed and additional details added.

Serialized variables array from watchdog row comment fixed as above.

Regarding the double blank lines in the dblog admin file: I previously made it consistent with what was in there before, but now I set it to be a single blank line throughout the file.

The function watchdog_exception is needed because external libraries, etc. will never throw a DrupalException, and this function makes it so the developer doesn't need to care if all they want to do is log. I added a better explanation to the function header, which was somewhat difficult in 80 characters and one line.

Common.inc whitespace changes removed, documented remaining watchdog_exception params.

It is impossible to make all Exceptions extend DrupalException, because PDOExceptions, etc. will be thrown from outside code. Therefore, we need a helper method to log non-Drupal Exceptions, and since that method also accepts DrupalExceptions, you should only ever need to call watchdog_exception() in a catch block other than a few special cases. Module code should rarely call shouldLog().

Logging a caught exception is entirely up to the developer. I intend to use it in the Block module later, because a failed block render should log (it's an error and needs to be fixed) but doesn't need to be fatal.

Per comment #46 there are a number of things left to do, and the initial patch just has the goal of determining the API so that its scope is achievable. However, I can add method comments to the patch later today if it's going to hold up the initial commit.

That's not really a good example, because it doesn't reflect the normal use case. That is the throw-er setting the exception to log, which really shouldn't be done (at least in normal cases, there may be some outliers). Whether or not to log should be up to the function doing the catch.

Here is a more typical example:

try {
  // This function or its subordinates could either throw a DrupalException or a PDOException.
  do_something();
}
catch (Exception $e) {
  // Non-fatal, but important enough to log.
  watchdog_exception($e);
}

Probably 95% of the watchdog_exception appearances in the code will look like that.

Made the two changes from Crell and added more documentation for DamZ.

Is it the whole data adding / shouldLog / shutdown function workflow the part you guys are leery about, or is there some other aspect? I like it because it allows developers to add context to a log entry, for example that the Exception was thrown during the render of block 123, which has been incredibly helpful in our old custom CMS. If you have a different suggestion for chaining exceptions, I'm all ears.

Summary of the issue so far:

The goal is to make Exception handling in Drupal more developer-friendly and functional. This means creating sensible usage patterns that Drupal developers will be familiar with already (similar to watchdog) and gracefully handling caught and uncaught exceptions with minimal developer action.

To this end, we've created the DrupalException class and some support functions for logging. Also new is the ability to append additional variables to a DrupalException as it bubbles up the execution stack, so that the Block module can record the block ID for context and easier debugging.

The current patch goal is just to get the API nailed down before the October 15th deadline. There are many things that will have to be done after (see below) but in the interest of keeping this patch reviewable and workable that can / will be done after the initial commit. To test / review, use the patch in #61.

Basic use cases:

function doSomething() {
  throw new DrupalException(
    'test !one !two !three', //$message
    array('!one'=>'a','!two'=>'b'), //$variables
    WATCHDOG_ERROR, //$severity (unless changed when logged)
    l('Account','User') //$link
  );
}

// And then in your main function, where you want to use doSomething:
try {
  doSomething();
} 
catch (Exception $e) {
  // Catch Exception any time that you want to prevent a proces
  // from failing regardless of the error source, rather than just
  // affect logging.
  watchdog_exception($e);
  return 'got a normal exception but logged it!';
}
return 'all is well, continue on.';

More elaborate example with addVariables:

try {
  throw new DrupalException(
    'test !one !two !three', //$message
    array('!one'=>'a','!two'=>'b'), //$variables
    WATCHDOG_ERROR, //$severity (unless changed when logged)
    l('Account','User') //$link
  );
  // Normally you should use DrupalException unless the code needs to be possible to run outside Drupal (rare).
  throw new PDOException('PDO FTW');
}
catch (DrupalException $e) {
  // This kind of a catch block is normally just to affect logging. For
  // example, the block rendering function might add some info
  // about the block and then continue on if the block fails to render.
  $e->addVariables(array('!three' => 'c'));
  // If you want the Exception to log even though it has been caught, do this:
  watchdog_exception($e);
  // Sometimes it is helpful to add variables even when the result is still going
  // to be fatal, so there is more to go on in debug.
  throw $e;
}
catch (Exception $e) {
  // Catch Exception any time that you want to prevent a proces
  // from failing regardless of the error source, rather than just
  // affect logging.
  watchdog_exception($e);
  return 'got a normal exception but logged it!';
}
return 'all is well, continue on.';

For later:

* Rewriting _drupal_decode_exception and the Exception handler function (currently logs twice and the code isn't separated out well)
* _drupal_decode_exception should pass variables up the tree, so it can be translated without logging the translated version to the DB
* Simpletests
* Documentation
* Getting the API used throughout core (some catch blocks may need be modified, and almost all custom Exception classes, form validation)
* potx expression changes
* Better output to the screen, including more consistent use of t()
* Stack traces in conjunction with Devel module
* Log differently when the DB isn't available

tagging

Forked minimalist version to #601020: Exception Handler Logging and Improvements so we can get something in for D7.