Update messages are logged in the wrong order

src/Commands/core/UpdateDBCommands.php

@@ -210,6 +210,11 @@ 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;
@@ -265,7 +270,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'], []];
         }
 
@@ -367,7 +372,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 +388,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

@@ -82,7 +82,20 @@ public function testFailedUpdate()
 
  // 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] Executing woot_update_8101
+ [notice] This is the update message from woot_update_8101
+ [ok] Performing woot_update_8101
+ [notice] Executing woot_update_8102
+ [error]  8102 error
+ [ok] Performing woot_update_8102
+ [error]  Failed batch process: woot_update_8102
+ [error]  Finished performing updates.
+LOG;
+
+        $this->assertErrorOutputEquals(preg_replace('#  *#', ' ', $this->simplifyOutput($expected_error_output)));
     }
 
     /**

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

@@ -4,7 +4,7 @@
  * Good update.
  */
 function woot_update_8101() {
-  return t('woot_update_8101');
+  return t('This is the update message from woot_update_8101');
 }
 
 /**