update.php: errors are not logged

I was able to replicate this bug following the steps outlined in #1

No patch here.

I'm taking a look at it at the code sprint.

I can reproduce the error described in #1 too. Anyway, as http://api.drupal.org/api/function/hook_update_N/7 says, the update hook itself has to throw an update exception in case of an error. So i think this is not a bug, you are implementing the hook_update_N hook not correctly.

I wasn't able to fix this (or determine if a fix is really needed) before I had to leave the code sprint. (now)

[Incidently, I was able to reproduce the behavior in #1, and tracked the throwing of the exception in this fake case to schema.inc line 395, in the funtion addUniqueKey()]

schema failure *do* throw exceptions, so #8 is wrong. You wouldn't see a failure in the summary in the first place if there would be no exception.

update_do_one() is not logging to the database. Will roll a patch tomorrow

The exception was being caught and the message returned in the $res array, but the exception is otherwise never logged and $res is only used to print summary results to the screen.

I've added a watchdog() call to log the exception.

update_do_one() is quite a mess currently. The $ret variable doesn't seem to be used at all. I guess all those should be converted to the new $context, and the problem will just go away.

Looks like $ret gets merged into $context a little later on - I suppose we could just update $context directly...

@marcvangend: No, I just meant that I saw the behavior in #1 (no logging) too.

Is the documentation at http://api.drupal.org/api/function/hook_update_N/7 incorrect, then?

Comment line reformatted to fit within 80 characters.

The exception is thrown - it's just that it is in fact caught, not logged, and not re-thrown. Rethrowing does in fact log a DrupalUpdateException, but the way things are currently set up, this breaks other things.

Re-attaching patch, the previous one was almost 24 hours in the queue

Off topic: thanks, @marcvangend. I did have a quick look at the queue - looks like there was something funky going on. However, the first instance of the patch looks like it got tested finally, so we're good :)

Looks good to me. Can we also fix the docs at http://api.drupal.org/api/function/hook_update_N/7?

Let's make the doc change, if it is necessary, a separate issue.

Here's what I see if I just throw a DrupalUpdateException wrapping the DatabaseSchemaObjectDoesNotExistException.

And here's the corresponding entry in watchdog, generated (I believe) by the generic Drupal exception handler.

Conclusion - if we do as the documentation for update_do_one() suggests and throw a DrupalUpdateException, this will generate error logs with lots of stack trace information, which is potentially helpful.

However, it's not clear to me where this exception should be handled so that it doesn't get in the way of batch processing.

I'm thinking this should probably throw the exception, like the documentation says it's supposed to. The challenge now is to determine where the exception should be caught, so that exception handling and batch processing co-exist nicely.

If #711108: Richer exception reporting for watchdog() gets commited, watchdog() will be able to decode exceptions on its own, so you could just pass $e to watchdog as the $message and it would log it properly (including file, location and more details in case of pdo exceptions), similiar to what we currently display.

I think the update manager should handle exceptions during datebase updates and not re-throw them as we don't want to break batch runs because of failing update functions.

If for example the database goes down and watchdog() throws an exception too, I think we can safely let that exception bubble up since batch api won't work without the database anyway.

@Berdir - is there a way that we can handle exceptions higher up without breaking the batch processing? I've had a first look and I don't understand the way batch processing works well enough to see how to do this, though it may be clear to someone who understands this better than I do.

If we can't find an 'obvious' way to implement this (which I gather was the solution intended/implied by the documentation), I'm willing to set the issue status back to rtbc.

I don't think we should handle them higher, why do you?

The only that should be "handled" higher up is when logging to watchdog fails and something is *really* broken then anyway (database crashed, went down, ...) in which case we can't continue with batch processing anyway.

#20: 774882-01.patch queued for re-testing.

Thanks @Berdir. At this point, I think you're right and handling the exception here makes sense.

Thanks for the excellent and important work on this patch.

I note that the watchdog error gives no context at all. Shouldn't it at least give a statement of which hook_update_N() was running? It would be Oh, so much better if it would give the actual query that ran (reference #711108: Richer exception reporting for watchdog() which doesn't seem to add this)

For example, the current hook_update_N() error described in #410636-23: D6->D7 update does not create required menus results in the following when update.php is run:

The following updates returned messages
system module
Update #7053

    * Failed: SQLSTATE[23000]: Integrity constraint violation: 1062 Duplicate entry 'user-menu' for key 'PRIMARY'

which is probably not enough, but it at least gives context: You know that it was system_update_7053() where the problem happened.

However, with this patch (#20), the watchdog entry provides not context (except that it's the update system). The output to watchdog is only:

Type	update
Date	Monday, May 17, 2010 - 22:11
User	rfay
Location	http://d7git.l/update.php?id=25&op=do
Referrer	http://d7git.l/update.php?op=start&id=25
Message	SQLSTATE[23000]: Integrity constraint violation: 1062 Duplicate entry 'user-menu' for key 'PRIMARY'
Severity	error
Hostname	127.0.0.1
Operations	

What I'd like to see would be

• What hook_update_N() caused the error
• Preferably database details (like the query that was run) that hopefully #711108: Richer exception reporting for watchdog() could provide to us (but I don't think it does yet)

EDIT: #711108: Richer exception reporting for watchdog() does provide great information for watchdog. I think we can provide that here too.

#711108: Richer exception reporting for watchdog() has been committed. That may help us get lots of the information we need to actually report what goes on when something goes wrong.

Updated the patch to use watchdog_exception() and also use drupal_decode_exception() to display the exception details.

i did not add any additional information because you can see the function name and that tells you which update step it was :)

+++ includes/update.inc
@@ -733,10 +733,15 @@ function update_do_one($module, $number, $dependency_map, &$context) {
+      $variables += _drupal_decode_exception($exception);

$variables = _drupal_decode_exception($e);

And there's no need for the += is there?

Attached patch makes those changes. With that, it seems to work very nicely - way, way better. Complete explanation of what's going on, and logged to watchdog. Yay!

Powered by Dreditor.

Very useful patch. The += was unnecessary since $variables isn't previously defined.

Nice sleuthing on this, folks! Committed to HEAD. Thanks!