Post-update logging

src/Commands/core/UpdateDBCommands.php

@@ -179,7 +179,7 @@ public function updateDoOne($module, $number, $dependency_map, &$context)
                     Database::startLog($function);
                 }
 
-                $this->logger()->notice("Executing " . $function);
+                $this->logger()->notice("Update started: $function");
                 $ret['results']['query'] = $function($context['sandbox']);
                 $ret['results']['success'] = true;
             } // @TODO We may want to do different error handling for different exception
@@ -210,17 +210,98 @@ public function updateDoOne($module, $number, $dependency_map, &$context)
         }
         $context['results'][$module][$number] = array_merge($context['results'][$module][$number], $ret);
 
+        // Log the message that was returned.
+        if (!empty($ret['results']['query'])) {
+            $this->logger()->notice(strip_tags((string) $ret['results']['query']));
+        }
+
         if (!empty($ret['#abort'])) {
             // Record this function in the list of updates that were aborted.
             $context['results']['#abort'][] = $function;
+            // Setting this value will output an error message.
+            // @see \DrushBatchContext::offsetSet()
+            $context['error_message'] = "Update failed: $function";
         }
 
         // Record the schema update if it was completed successfully.
         if ($context['finished'] == 1 && empty($ret['#abort'])) {
             drupal_set_installed_schema_version($module, $number);
+            // Setting this value will output a success message.
+            // @see \DrushBatchContext::offsetSet()
+            $context['message'] = "Update completed: $function";
+        }
+    }
+
+    /**
+     * Batch command that executes a single post-update.
+     *
+     * @param string $function
+     *   The post-update function to execute.
+     * @param array $context
+     *   The batch context.
+     */
+    public function updateDoOnePostUpdate($function, &$context)
+    {
+        $ret = [];
+
+        // If this update was aborted in a previous step, or has a dependency that was
+        // aborted in a previous step, go no further.
+        if (!empty($context['results']['#abort'])) {
+            return;
+        }
+
+        list($module, $name) = explode('_post_update_', $function, 2);
+        module_load_include('php', $module, $module . '.post_update');
+        if (function_exists($function)) {
+            $this->logger()->notice("Update started: $function");
+            try {
+                $ret['results']['query'] = $function($context['sandbox']);
+                $ret['results']['success'] = true;
+
+                if (!isset($context['sandbox']['#finished']) || (isset($context['sandbox']['#finished']) && $context['sandbox']['#finished'] >= 1)) {
+                    \Drupal::service('update.post_update_registry')->registerInvokedUpdates([$function]);
+                }
+            } catch (\Exception $e) {
+                // @TODO We may want to do different error handling for different exception
+                // types, but for now we'll just log the exception and return the message
+                // for printing.
+                // @see https://www.drupal.org/node/2564311
+                $this->logger()->error($e->getMessage());
+
+                $variables = Error::decodeException($e);
+                unset($variables['backtrace']);
+                $ret['#abort'] = [
+                    'success' => false,
+                    'query' => t('%type: @message in %function (line %line of %file).', $variables),
+                ];
+            }
+        }
+
+        if (isset($context['sandbox']['#finished'])) {
+            $context['finished'] = $context['sandbox']['#finished'];
+            unset($context['sandbox']['#finished']);
+        }
+        if (!isset($context['results'][$module][$name])) {
+            $context['results'][$module][$name] = [];
+        }
+        $context['results'][$module][$name] = array_merge($context['results'][$module][$name], $ret);
+
+        // Log the message that was returned.
+        if (!empty($ret['results']['query'])) {
+            $this->logger()->notice(strip_tags((string) $ret['results']['query']));
         }
 
-        $context['message'] = 'Performing ' . $function;
+        if (!empty($ret['#abort'])) {
+            // Record this function in the list of updates that were aborted.
+            $context['results']['#abort'][] = $function;
+            // Setting this value will output an error message.
+            // @see \DrushBatchContext::offsetSet()
+            $context['error_message'] = "Update failed: $function";
+        } else {
+            // Setting this value will output a success message.
+            // @see \DrushBatchContext::offsetSet()
+            $context['message'] = "Update completed: $function";
+        }
     }
 
     /**
@@ -265,7 +346,7 @@ public function updateBatch($options)
         // update themselves.
         // @see \Drupal\Core\Entity\EntityDefinitionUpdateManagerInterface::applyEntityUpdate()
         // @see \Drupal\Core\Entity\EntityDefinitionUpdateManagerInterface::applyFieldUpdate()
-        if ($options['entity-updates'] &&  \Drupal::entityDefinitionUpdateManager()->needsUpdates()) {
+        if ($options['entity-updates'] && \Drupal::entityDefinitionUpdateManager()->needsUpdates()) {
             $operations[] = [[$this, 'updateEntityDefinitions'], []];
         }
 
@@ -278,7 +359,7 @@ public function updateBatch($options)
                     $operations[] = [[$this, 'cacheRebuild'], []];
                 }
                 foreach ($post_updates as $function) {
-                    $operations[] = ['update_invoke_post_update', [$function]];
+                    $operations[] = [[$this, 'updateDoOnePostUpdate'], [$function]];
                 }
             }
         }
@@ -304,7 +385,10 @@ public function updateBatch($options)
         } elseif (!array_key_exists('object', $result)) {
             $this->logger()->error(dt('Batch process did not return a result object.'));
         } elseif (!empty($result['object'][0]['#abort'])) {
-            $this->logger()->error(dt('Failed batch process: !process', [
+            // Whenever an error occurs the batch process does not continue, so
+            // this array should only contain a single item, but we still output
+            // all available data for completeness.
+            $this->logger()->error(dt('Update aborted by: !process', [
                 '!process' => implode(', ', $result['object'][0]['#abort']),
             ]));
         } else {
@@ -367,7 +451,7 @@ public function cacheRebuild()
     }
 
     /**
-     * Process and display any returned update output.
+     * Batch update callback, clears the cache if needed.
      *
      * @see \Drupal\system\Controller\DbUpdateController::batchFinished()
      * @see \Drupal\system\Controller\DbUpdateController::results()
@@ -383,16 +467,6 @@ public function updateFinished($success, $results, $operations)
         } else {
             drupal_flush_all_caches();
         }
-
-        // Log update results.
-        unset($results['#abort']);
-        foreach ($results as $module => $updates) {
-            foreach ($updates as $number => $update) {
-                if (empty($update['#abort']) && $update['results']['success'] && !empty($update['results']['query'])) {
-                    $this->logger()->notice(strip_tags($update['results']['query']));
-                }
-            }
-        }
     }
 
     /**

tests/CommandUnishTestCase.php

@@ -66,11 +66,39 @@ abstract class CommandUnishTestCase extends UnishTestCase
    */
     protected function getSimplifiedOutput()
     {
-        $output = $this->getOutput();
+        return $this->simplifyOutput($this->getOutput());
+    }
+
+    /**
+     * Returns a simplified version of the error output to facilitate testing.
+     *
+     * @return string
+     *   A simplified version of the error output that has things like full
+     *   paths and superfluous whitespace removed from it.
+     */
+    protected function getSimplifiedErrorOutput()
+    {
+        return $this->simplifyOutput($this->getErrorOutput());
+    }
+
+    /**
+     * Remove things like full paths and extra whitespace from the given string.
+     *
+     * @param string $output
+     *   The output string to simplify.
+     *
+     * @return string
+     *   The simplified output.
+     */
+    protected function simplifyOutput($output)
+    {
         // We do not care if Drush inserts a -t or not in the string. Depends on whether there is a tty.
         $output = preg_replace('# -t #', ' ', $output);
         // Remove double spaces from output to help protect test from false negatives if spacing changes subtlely
         $output = preg_replace('#  *#', ' ', $output);
+        // Remove leading and trailing spaces.
+        $output = preg_replace('#^ *#m', '', $output);
+        $output = preg_replace('# *$#m', '', $output);
         // Debug flags may be added to command strings if we are in debug mode. Take those out so that tests in phpunit --debug mode work
         $output = preg_replace('# --debug #', ' ', $output);
         $output = preg_replace('# --verbose #', ' ', $output);
@@ -479,4 +507,25 @@ protected function assertOutputEquals($expected, $filter = '')
         }
         $this->assertEquals($expected, $output);
     }
+
+    /**
+     * Checks that the error output matches the expected output.
+     *
+     * This matches against a simplified version of the actual output that has
+     * absolute paths and duplicate whitespace removed, to avoid false negatives
+     * on minor differences.
+     *
+     * @param string $expected
+     *   The expected output.
+     * @param string $filter
+     *   Optional regular expression that should be ignored in the error output.
+     */
+    protected function assertErrorOutputEquals($expected, $filter = '')
+    {
+        $output = $this->getSimplifiedErrorOutput();
+        if (!empty($filter)) {
+            $output = preg_replace($filter, '', $output);
+        }
+        $this->assertEquals($expected, $output);
+    }
 }

tests/UpdateDBTest.php

@@ -72,17 +72,85 @@ public function testFailedUpdate()
         $this->drush('updatedb', [], $options, null, null, self::EXIT_ERROR);
 
         $expected_output = <<<LOG
- -------- ----------- --------------- ---------------------- 
-  Module   Update ID   Type            Description           
- -------- ----------- --------------- ---------------------- 
-  woot     8101        hook_update_n   Good update.          
-  woot     8102        hook_update_n   Failing update.       
-  woot     failing     post-update     Failing post-update.  
- -------- ----------- --------------- ---------------------- 
+ -------- ----------- --------------- -----------------------
+  Module   Update ID   Type            Description
+ -------- ----------- --------------- -----------------------
+  woot     8101        hook_update_n   Good update.
+  woot     8102        hook_update_n   Failing update.
+  woot     8103        hook_update_n   Another good update.
+  woot     failing     post-update     Failing post-update.
+ -------- ----------- --------------- -----------------------
 
  // Do you wish to run the specified pending updates?: yes.
 LOG;
-        $this->assertOutputEquals(preg_replace('#  *#', ' ', trim($expected_output)));
+        $this->assertOutputEquals(preg_replace('#  *#', ' ', $this->simplifyOutput($expected_output)));
+
+        $expected_error_output = <<<LOG
+ [notice] Update started: woot_update_8101
+ [notice] This is the update message from woot_update_8101
+ [ok] Update completed: woot_update_8101
+ [notice] Update started: woot_update_8102
+ [error] This is the exception message thrown in woot_update_8102
+ [error] Update failed: woot_update_8102
+ [error] Update aborted by: woot_update_8102
+ [error] Finished performing updates.
+LOG;
+
+        $this->assertErrorOutputEquals(preg_replace('#  *#', ' ', $this->simplifyOutput($expected_error_output)));
+    }
+
+    /**
+     * Tests that a failed post-update is handled correctly.
+     */
+    public function testFailedPostUpdate()
+    {
+        $sites = $this->setUpDrupal(1, true);
+        $options = [
+            'yes' => null,
+            'root' => $root = $this->webroot(),
+            'uri' => key($sites),
+        ];
+        $this->setupModulesForTests($root);
+        $this->drush('pm-enable', ['woot'], $options);
+
+        // Force re-run of woot_update_8103().
+        $this->drush('php:eval', array('drupal_set_installed_schema_version("woot", 8102)'), $options);
+
+        // Force re-run of post-update hooks.
+        $this->forcePostUpdate('woot_post_update_a', $options);
+        $this->forcePostUpdate('woot_post_update_failing', $options);
+
+        // Run updates.
+        $this->drush('updatedb', [], $options, null, null, self::EXIT_ERROR);
+
+        $expected_output = <<<LOG
+ -------- ----------- --------------- -------------------------
+  Module   Update ID    Type            Description
+ -------- ----------- --------------- -------------------------
+  woot     8103         hook_update_n   Another good update.
+  woot     a            post-update     Successful post-update.
+  woot     failing      post-update     Failing post-update.
+ -------- ----------- --------------- -------------------------
+
+ // Do you wish to run the specified pending updates?: yes.
+LOG;
+        $this->assertOutputEquals(preg_replace('#  *#', ' ', $this->simplifyOutput($expected_output)));
+
+        $expected_error_output = <<<LOG
+ [notice] Update started: woot_update_8103
+ [notice] This is the update message from woot_update_8103
+ [ok] Update completed: woot_update_8103
+ [notice] Update started: woot_post_update_a
+ [notice] This is the update message from woot_post_update_a
+ [ok] Update completed: woot_post_update_a
+ [notice] Update started: woot_post_update_failing
+ [error]  This is the exception message thrown in woot_post_update_failing
+ [error]  Update failed: woot_post_update_failing
+ [error]  Update aborted by: woot_post_update_failing
+ [error] Finished performing updates.
+LOG;
+
+        $this->assertErrorOutputEquals(preg_replace('#  *#', ' ', $this->simplifyOutput($expected_error_output)));
     }
 
     /**

tests/resources/modules/d8/woot/woot.install

@@ -4,12 +4,19 @@
  * Good update.
  */
 function woot_update_8101() {
-  return t('woot_update_8101');
+  return t('This is the update message from woot_update_8101');
 }
 
 /**
  * Failing update.
  */
 function woot_update_8102() {
-  throw new \Exception('8102 error');
+  throw new \Exception('This is the exception message thrown in woot_update_8102');
+}
+
+/**
+ * Another good update.
+ */
+function woot_update_8103() {
+  return t('This is the update message from woot_update_8103');
 }

tests/resources/modules/d8/woot/woot.post_update.php

@@ -1,11 +1,21 @@
 <?php
 
+/**
+ * Successful post-update.
+ */
+function woot_post_update_a()
+{
+    // Note that this is called 'a' so that it will run first. The post-updates
+    // are executed in alphabetical order.
+    return t('This is the update message from woot_post_update_a');
+}
+
 /**
  * Failing post-update.
  */
 function woot_post_update_failing()
 {
-    throw new \Exception('post update error');
+    throw new \Exception('This is the exception message thrown in woot_post_update_failing');
 }
 
 /**