diff --git a/src/Commands/core/UpdateDBCommands.php b/src/Commands/core/UpdateDBCommands.php index fa710c066a..66696635b6 100644 --- a/src/Commands/core/UpdateDBCommands.php +++ b/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'])); - } - } - } } /** diff --git a/tests/CommandUnishTestCase.php b/tests/CommandUnishTestCase.php index 0e99f87e6a..94894dce88 100644 --- a/tests/CommandUnishTestCase.php +++ b/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); + } } diff --git a/tests/UpdateDBTest.php b/tests/UpdateDBTest.php index ea81ad93a6..0a04882b1d 100644 --- a/tests/UpdateDBTest.php +++ b/tests/UpdateDBTest.php @@ -72,17 +72,85 @@ public function testFailedUpdate() $this->drush('updatedb', [], $options, null, null, self::EXIT_ERROR); $expected_output = <<assertOutputEquals(preg_replace('# *#', ' ', trim($expected_output))); + $this->assertOutputEquals(preg_replace('# *#', ' ', $this->simplifyOutput($expected_output))); + + $expected_error_output = <<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 = <<assertOutputEquals(preg_replace('# *#', ' ', $this->simplifyOutput($expected_output))); + + $expected_error_output = <<assertErrorOutputEquals(preg_replace('# *#', ' ', $this->simplifyOutput($expected_error_output))); } /** diff --git a/tests/resources/modules/d8/woot/woot.install b/tests/resources/modules/d8/woot/woot.install index 909f791283..be9dd39cc4 100644 --- a/tests/resources/modules/d8/woot/woot.install +++ b/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'); } diff --git a/tests/resources/modules/d8/woot/woot.post_update.php b/tests/resources/modules/d8/woot/woot.post_update.php index f256be0bd0..289cd14ed0 100644 --- a/tests/resources/modules/d8/woot/woot.post_update.php +++ b/tests/resources/modules/d8/woot/woot.post_update.php @@ -1,11 +1,21 @@