Improve the log of the updatedb command

[pfrenssen]

This partially fixes #3296.

The output of the updatedb command can be quite confusing, since misleading messages are being output, and incorrect statuses are being communicated.

Here is some example output from the current update test suite:

 [notice] Executing woot_update_8101
 [ok] Performing woot_update_8101
 [notice] Executing woot_update_8102
 [error]  8102 error 
 [ok] Performing woot_update_8102
 [notice] woot_update_8101
 [error]  Failed batch process: woot_update_8102 
 [error]  Finished performing updates.

• There appears to be duplicated information about "executing" and "performing" each individual update. In fact when the log mentions that it is "Performing hook_update_x" the update has already finished.
• Update 8102 failed, so there should not be any [ok] associated with it.
• It shouldn't mention that the "batch process" failed. That the batch API is used behind the scenes is an implementation detail and not important to mention in the log output.

Edit: Note that the scope of this PR is solely to change the existing messages so they are less confusing. The order of the messages is being corrected in #3302, missing errors are in #3308.

[pfrenssen]

Test fails as expected. Now committing the fix.

[claudiu-cristea]

So, i assume that #3302 should be closed, right?

[claudiu-cristea]

I've added 525f33b to log also the failures.

[pfrenssen]

This doesn't look right, now the messages are in the wrong order. The initial test proved that the output was there, and in the right place (during the execution):

[notice] Update started: woot_update_8102
[error] This is the exception message thrown in woot_update_8102
[error] Update failed: woot_update_8102

With your patch the error is still there but in the wrong location.

Can you give some more info on what you are trying to solve? Maybe you didn't have an exception but a different (uncatchable?) error?

This issue is not about adding things to the log that are not already there, but about improving the existing messages so they are less confusing. If you are not seeing something important, we can best fix this in a separate issue.

So, i assume that #3302 should be closed, right?

No, #3302 is also a different scope, it's about making sure the log messages are appearing in the correct order. This is about improving the messages.

[pfrenssen]

I've discussed this with @claudiu-cristea. I'm going to revert this to the previous state so the PR and split off the missing exception to a separate issue. It seems that only exceptions in hook_update_N() are correctly logged, those in post-updates are not.

Follow up issue to fix the missing error message is #3308. A copy of the original fix by @claudiu-cristea is here: https://github.com/pfrenssen/drush/commits/missing-exception

[claudiu-cristea]

Discussed with @pfrenssen and I will review this PR tomorrow morning so it can be quickly ready for the 9 stable release.

[claudiu-cristea]

Good job! I rerolled the PR. @weitzman, @greg-1-anderson I've tested this on out project wit this PR the log messages improved. Good to go.

[weitzman]

Merged in #3310