[ticket/13126] Improve the feedback when running the migrations

PHPBB3-13126

phpBB/install/database_update.php

@@ -174,6 +174,19 @@ define('IN_DB_UPDATE', true);
 // End startup code
 
 $migrator = $phpbb_container->get('migrator');
+$migrator->set_output_handler(
+	new \phpbb\db\migrator_output_handler(
+		function($message, $verbosity) use ($user)
+		{
+			if ($verbosity <= \phpbb\db\migrator_output_handler::VERBOSITY_NORMAL)
+			{
+				$final_message = call_user_func_array(array($user, 'lang'), $message);
+				echo $final_message . "<br />\n";
+			}
+		}
+	)
+);
+
 $migrator->create_migrations_table();
 
 $phpbb_extension_manager = $phpbb_container->get('ext.manager');
@@ -199,8 +212,6 @@ $safe_time_limit = min(15, ($phpbb_ini->get_int('max_execution_time') / 2));
 
 while (!$migrator->finished())
 {
-	$migration_start_time = microtime(true);
-
 	try
 	{
 		$migrator->update();
@@ -219,28 +230,6 @@ while (!$migrator->finished())
 		$migrator->last_run_migration['state']
 	);
 
-	if (isset($migrator->last_run_migration['effectively_installed']) && $migrator->last_run_migration['effectively_installed'])
-	{
-		echo $user->lang('MIGRATION_EFFECTIVELY_INSTALLED', $migrator->last_run_migration['name']);
-	}
-	else
-	{
-		if ($migrator->last_run_migration['task'] == 'process_data_step' && $state['migration_data_done'])
-		{
-			echo $user->lang('MIGRATION_DATA_DONE', $migrator->last_run_migration['name'], (microtime(true) - $migration_start_time));
-		}
-		else if ($migrator->last_run_migration['task'] == 'process_data_step')
-		{
-			echo $user->lang('MIGRATION_DATA_IN_PROGRESS', $migrator->last_run_migration['name'], (microtime(true) - $migration_start_time));
-		}
-		else if ($state['migration_schema_done'])
-		{
-			echo $user->lang('MIGRATION_SCHEMA_DONE', $migrator->last_run_migration['name'], (microtime(true) - $migration_start_time));
-		}
-	}
-
-	echo "<br />\n";
-
 	// Are we approaching the time limit? If so we want to pause the update and continue after refreshing
 	if ((time() - $update_start_time) >= $safe_time_limit)
 	{

phpBB/language/en/migrator.php

@@ -41,12 +41,16 @@ $lang = array_merge($lang, array(
 
 	'GROUP_NOT_EXIST'					=> 'The group "%s" unexpectedly does not exist.',
 
+	'MIGRATION_APPLY_DEPENDENCIES'		=> 'Apply dependencies of %s.',
 	'MIGRATION_DATA_DONE'				=> 'Installed Data: %1$s; Time: %2$.2f seconds',
 	'MIGRATION_DATA_IN_PROGRESS'		=> 'Installing Data: %1$s; Time: %2$.2f seconds',
+	'MIGRATION_DATA_RUNNING'			=> 'Installing Data: %s.',
 	'MIGRATION_EFFECTIVELY_INSTALLED'	=> 'Migration already effectively installed (skipped): %s',
 	'MIGRATION_EXCEPTION_ERROR'			=> 'Something went wrong during the request and an exception was thrown. The changes made before the error occurred were reversed to the best of our abilities, but you should check the board for errors.',
 	'MIGRATION_NOT_FULFILLABLE'			=> 'The migration "%1$s" is not fulfillable, missing migration "%2$s".',
+	'MIGRATION_NOT_VALID'				=> '%s is not a valid migration.',
 	'MIGRATION_SCHEMA_DONE'				=> 'Installed Schema: %1$s; Time: %2$.2f seconds',
+	'MIGRATION_SCHEMA_RUNNING'			=> 'Installing Schema: %s.',
 
 	'MODULE_ERROR'						=> 'An error occurred while creating a module: %s',
 	'MODULE_INFO_FILE_NOT_EXIST'		=> 'A required module info file is missing: %2$s',

phpBB/phpbb/console/command/db/migrate.php

@@ -53,6 +53,30 @@ class migrate extends \phpbb\console\command\command
 
 	protected function execute(InputInterface $input, OutputInterface $output)
 	{
+		$user = $this->user;
+		$this->migrator->set_output_handler(
+			new \phpbb\db\migrator_output_handler(
+				function($message, $verbosity) use ($output, $user)
+				{
+					if ($verbosity <= $output->getVerbosity())
+					{
+						$final_message = call_user_func_array(array($user, 'lang'), $message);
+
+						if ($verbosity === \phpbb\db\migrator_output_handler::VERBOSITY_NORMAL)
+						{
+							$final_message = '<info>' . $final_message . '</info>';
+						}
+						else if ($verbosity === \phpbb\db\migrator_output_handler::VERBOSITY_VERY_VERBOSE)
+						{
+							$final_message = '<comment>' . $final_message . '</comment>';
+						}
+
+						$output->writeln($final_message);
+					}
+				}
+			)
+		);
+
 		$this->migrator->create_migrations_table();
 
 		$this->cache->purge();
@@ -61,8 +85,6 @@ class migrate extends \phpbb\console\command\command
 		$orig_version = $this->config['version'];
 		while (!$this->migrator->finished())
 		{
-			$migration_start_time = microtime(true);
-
 			try
 			{
 				$this->migrator->update();
@@ -73,36 +95,6 @@ class migrate extends \phpbb\console\command\command
 				$this->finalise_update();
 				return 1;
 			}
-
-			$migration_stop_time = microtime(true) - $migration_start_time;
-
-			$state = array_merge(
-				array(
-					'migration_schema_done' => false,
-					'migration_data_done'	=> false,
-				),
-				$this->migrator->last_run_migration['state']
-			);
-
-			if (!empty($this->migrator->last_run_migration['effectively_installed']))
-			{
-				$msg = $this->user->lang('MIGRATION_EFFECTIVELY_INSTALLED', $this->migrator->last_run_migration['name']);
-				$output->writeln("<comment>$msg</comment>");
-			}
-			else if ($this->migrator->last_run_migration['task'] == 'process_data_step' && $state['migration_data_done'])
-			{
-				$msg = $this->user->lang('MIGRATION_DATA_DONE', $this->migrator->last_run_migration['name'], $migration_stop_time);
-				$output->writeln("<info>$msg</info>");
-			}
-			else if ($this->migrator->last_run_migration['task'] == 'process_data_step')
-			{
-				$output->writeln($this->user->lang('MIGRATION_DATA_IN_PROGRESS', $this->migrator->last_run_migration['name'], $migration_stop_time));
-			}
-			else if ($state['migration_schema_done'])
-			{
-				$msg = $this->user->lang('MIGRATION_SCHEMA_DONE', $this->migrator->last_run_migration['name'], $migration_stop_time);
-				$output->writeln("<info>$msg</info>");
-			}
 		}
 
 		if ($orig_version != $this->config['version'])

phpBB/phpbb/db/migrator.php

@@ -67,6 +67,13 @@ class migrator
 	*/
 	public $last_run_migration = false;
 
+	/**
+	 * The output handler. A null handler is configured by default.
+	 *
+	 * @var migrator_output_handler
+	 */
+	public $output_handler;
+
 	/**
 	* Constructor of the database migrator
 	*/
@@ -84,6 +91,8 @@ class migrator
 
 		$this->table_prefix = $table_prefix;
 
+		$this->output_handler = new migrator_output_handler();
+
 		foreach ($tools as $tool)
 		{
 			$this->tools[$tool->get_name()] = $tool;
@@ -94,6 +103,16 @@ class migrator
 		$this->load_migration_state();
 	}
 
+	/**
+	 * Set the output handler.
+	 *
+	 * @param migrator_output_handler $handler The output handler
+	 */
+	public function set_output_handler(migrator_output_handler $handler)
+	{
+		$this->output_handler = $handler;
+	}
+
 	/**
 	* Loads all migrations and their application state from the database.
 	*
@@ -161,6 +180,10 @@ class migrator
 					return;
 				}
 			}
+			else
+			{
+				$this->output_handler->write(array('MIGRATION_EFFECTIVELY_INSTALLED', $name), migrator_output_handler::VERBOSITY_DEBUG);
+			}
 		}
 	}
 
@@ -175,6 +198,7 @@ class migrator
 	{
 		if (!class_exists($name))
 		{
+			$this->output_handler->write(array('MIGRATION_NOT_VALID', $name), migrator_output_handler::VERBOSITY_DEBUG);
 			return false;
 		}
 
@@ -191,6 +215,11 @@ class migrator
 				'migration_end_time'	=> 0,
 			);
 
+		if (!empty($state['migration_depends_on']))
+		{
+			$this->output_handler->write(array('MIGRATION_APPLY_DEPENDENCIES', $name), migrator_output_handler::VERBOSITY_DEBUG);
+		}
+
 		foreach ($state['migration_depends_on'] as $depend)
 		{
 			if ($this->unfulfillable($depend) !== false)
@@ -227,6 +256,8 @@ class migrator
 				);
 
 				$this->last_run_migration['effectively_installed'] = true;
+
+				$this->output_handler->write(array('MIGRATION_EFFECTIVELY_INSTALLED', $name), migrator_output_handler::VERBOSITY_NORMAL);
 			}
 			else
 			{
@@ -238,23 +269,43 @@ class migrator
 
 		if (!$state['migration_schema_done'])
 		{
+			$this->output_handler->write(array('MIGRATION_SCHEMA_RUNNING', $name), migrator_output_handler::VERBOSITY_VERY_VERBOSE);
+
 			$this->last_run_migration['task'] = 'process_schema_step';
+			$elapsed_time = microtime(true);
 			$steps = $this->helper->get_schema_steps($migration->update_schema());
 			$result = $this->process_data_step($steps, $state['migration_data_state']);
+			$elapsed_time = microtime(true) - $elapsed_time;
 
 			$state['migration_data_state'] = ($result === true) ? '' : $result;
 			$state['migration_schema_done'] = ($result === true);
+
+			$this->output_handler->write(array('MIGRATION_SCHEMA_DONE', $name, $elapsed_time), migrator_output_handler::VERBOSITY_NORMAL);
 		}
 		else if (!$state['migration_data_done'])
 		{
 			try
 			{
+				$this->output_handler->write(array('MIGRATION_DATA_RUNNING', $name), migrator_output_handler::VERBOSITY_VERY_VERBOSE);
+
 				$this->last_run_migration['task'] = 'process_data_step';
+
+				$elapsed_time = microtime(true);
 				$result = $this->process_data_step($migration->update_data(), $state['migration_data_state']);
+				$elapsed_time = microtime(true) - $elapsed_time;
 
 				$state['migration_data_state'] = ($result === true) ? '' : $result;
 				$state['migration_data_done'] = ($result === true);
 				$state['migration_end_time'] = ($result === true) ? time() : 0;
+
+				if ($state['migration_schema_done'])
+				{
+					$this->output_handler->write(array('MIGRATION_DATA_DONE', $name, $elapsed_time), migrator_output_handler::VERBOSITY_NORMAL);
+				}
+				else
+				{
+					$this->output_handler->write(array('MIGRATION_DATA_IN_PROGRESS', $name, $elapsed_time), migrator_output_handler::VERBOSITY_VERBOSE);
+				}
 			}
 			catch (\phpbb\db\migration\exception $e)
 			{

phpBB/phpbb/db/migrator_output_handler.php

@@ -0,0 +1,55 @@
+<?php
+/**
+*
+* This file is part of the phpBB Forum Software package.
+*
+* @copyright (c) phpBB Limited <https://www.phpbb.com>
+* @license GNU General Public License, version 2 (GPL-2.0)
+*
+* For full copyright and license information, please see
+* the docs/CREDITS.txt file.
+*
+*/
+
+namespace phpbb\db;
+
+class migrator_output_handler
+{
+	const VERBOSITY_QUIET        = 0;
+	const VERBOSITY_NORMAL       = 1;
+	const VERBOSITY_VERBOSE      = 2;
+	const VERBOSITY_VERY_VERBOSE = 3;
+	const VERBOSITY_DEBUG        = 4;
+
+	/**
+	 * A callable used to write the output.
+	 *
+	 * @var callable
+	 */
+	private $closure;
+
+	/**
+	 * Constructor
+	 *
+	 * @param callable $closure The closure used to write the output. (null by default)
+	 */
+	public function __construct(\Closure $closure = null)
+	{
+		if ($closure === null) {
+			$closure = function($message, $verbosity) {};
+		}
+		$this->closure = $closure;
+	}
+
+	/**
+	 * Write output using the configured closure.
+	 *
+	 * @param string|array $message The message to write or an array containing the language key and all of its parameters.
+	 * @param int $verbosity The verbosity of the message.
+	 */
+	public function write($message, $verbosity)
+	{
+		$closure = $this->closure;
+		$closure((array) $message, $verbosity);
+	}
+}