Reduce the useless verbosity of batch update output (#3372)

src/Commands/core/UpdateDBCommands.php

@@ -2,6 +2,7 @@
 namespace Drush\Commands\core;
 
 use Consolidation\Log\ConsoleLogLevel;
+use DrushBatchContext;
 use Consolidation\OutputFormatters\StructuredData\RowsOfFields;
 use Consolidation\OutputFormatters\StructuredData\UnstructuredListData;
 use Consolidation\SiteAlias\SiteAliasManagerAwareInterface;
@@ -169,14 +170,16 @@ public function process($batch_id, $options = ['format' => 'json'])
      *
      * This method is static since since it is called by _drush_batch_worker().
      *
-     * @param $module
+     * @param string $module
      *   The module whose update will be run.
-     * @param $number
+     * @param int $number
      *   The update number to run.
-     * @param $context
-     *   The batch context array
+     * @param array $dependency_map
+     *   The update dependency map.
+     * @param DrushBatchContext $context
+     *   The batch context object.
      */
-    public static function updateDoOne($module, $number, $dependency_map, &$context)
+    public static function updateDoOne($module, $number, array $dependency_map, DrushBatchContext $context)
     {
         $function = $module . '_update_' . $number;
 
@@ -202,9 +205,13 @@ public static function updateDoOne($module, $number, $dependency_map, &$context)
                     Database::startLog($function);
                 }
 
-                Drush::logger()->notice("Update started: $function");
+                if (empty($context['results'][$module][$number]['type'])) {
+                    Drush::logger()->notice("Update started: $function");
+                }
+
                 $ret['results']['query'] = $function($context['sandbox']);
                 $ret['results']['success'] = true;
+                $ret['type'] = 'update';
             } catch (\Throwable $e) {
                 // PHP 7 introduces Throwable, which covers both Error and Exception throwables.
                 $ret['#abort'] = ['success' => false, 'query' => $e->getMessage()];
@@ -263,10 +270,10 @@ public static function updateDoOne($module, $number, $dependency_map, &$context)
      *
      * @param string $function
      *   The post-update function to execute.
-     * @param array $context
-     *   The batch context.
+     * @param DrushBatchContext $context
+     *   The batch context object.
      */
-    public static function updateDoOnePostUpdate($function, &$context)
+    public static function updateDoOnePostUpdate($function, DrushBatchContext $context)
     {
         $ret = [];
 
@@ -284,10 +291,13 @@ public static function updateDoOnePostUpdate($function, &$context)
         list($module, $name) = explode('_post_update_', $function, 2);
         module_load_include('php', $module, $module . '.post_update');
         if (function_exists($function)) {
-            Drush::logger()->notice("Update started: $function");
+            if (empty($context['results'][$module][$name]['type'])) {
+                Drush::logger()->notice("Update started: $function");
+            }
             try {
                 $ret['results']['query'] = $function($context['sandbox']);
                 $ret['results']['success'] = true;
+                $ret['type'] = 'post_update';
 
                 if (!isset($context['sandbox']['#finished']) || (isset($context['sandbox']['#finished']) && $context['sandbox']['#finished'] >= 1)) {
                     \Drupal::service('update.post_update_registry')->registerInvokedUpdates([$function]);
@@ -328,7 +338,7 @@ public static function updateDoOnePostUpdate($function, &$context)
             // Setting this value will output an error message.
             // @see \DrushBatchContext::offsetSet()
             $context['error_message'] = "Update failed: $function";
-        } else {
+        } elseif ($context['finished'] == 1 && empty($ret['#abort'])) {
             // Setting this value will output a success message.
             // @see \DrushBatchContext::offsetSet()
             $context['message'] = "Update completed: $function";

tests/functional/UpdateDBTest.php

@@ -265,6 +265,49 @@ public function testSuccessfulUpdate()
         $this->assertNotContains('Failed', $this->getErrorOutput());
     }
 
+    /**
+     * Tests the output on batch update.
+     */
+    public function testBatchUpdateLogMessages()
+    {
+        $options = [
+            'yes' => null,
+        ];
+        $this->setUpDrupal(1, true);
+        $this->setupModulesForTests(['woot'], Path::join(__DIR__, 'resources/modules/d8'));
+        $this->drush('pm:enable', ['woot'], $options);
+
+        // Force re-run of woot_update_8105().
+        $this->drush('php:eval', ['drupal_set_installed_schema_version("woot", 8104)'], $options);
+        // Force re-run of woot_post_update_batch().
+        $this->forcePostUpdate('woot_post_update_batch', $options);
+
+        // Run updates.
+        $this->drush('updatedb', [], $options);
+
+        $expected_update_output = <<<UPDATE
+>  [notice] Update started: woot_update_8105
+>  [notice] Iteration 1.
+>  [notice] Iteration 2.
+>  [notice] Finished at 3.
+>  [notice] Update completed: woot_update_8105
+UPDATE;
+        $expected_post_update_output = <<<POST_UPDATE
+>  [notice] Update started: woot_post_update_batch
+>  [notice] Iteration 1.
+>  [notice] Iteration 2.
+>  [notice] Finished at 3.
+>  [notice] Update completed: woot_post_update_batch
+POST_UPDATE;
+
+        // On Windows systems the new line delimiter is a CR+LF (\r\n) sequence
+        // instead of LF (\n) as it is on *nix systems.
+        $actual_output = str_replace("\r\n", "\n", $this->getErrorOutputRaw());
+
+        $this->assertContains($expected_update_output, $actual_output);
+        $this->assertContains($expected_post_update_output, $actual_output);
+    }
+
     public function tearDown()
     {
         $this->recursiveDelete($this->pathPostUpdate, true);

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

@@ -37,3 +37,15 @@ function woot_update_8104() {
   \Drupal::service('renderer')->renderPlain($render_array);
   return t('This is the update message from woot_update_8104');
 }
+
+/**
+ * Batch update.
+ */
+function woot_update_8105(array &$sandbox) {
+  $sandbox['current'] = isset($sandbox['current']) ? ++$sandbox['current'] : 1;
+  $sandbox['#finished'] = (int) $sandbox['current'] === 3;
+  if ($sandbox['#finished']) {
+    return "Finished at {$sandbox['current']}.";
+  }
+  return "Iteration {$sandbox['current']}.";
+}

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

@@ -40,3 +40,11 @@ function woot_post_update_render()
     ];
     \Drupal::service('renderer')->renderPlain($render_array);
 }
+
+/**
+ * Batch post update.
+ */
+function woot_post_update_batch(array &$sandbox)
+{
+    return woot_update_8105($sandbox);
+}