Print install download progress and handle indentation inside installer plugin

Instead of having our caller re-write the "nice output" file descriptor to achieve the desired indent level, we print it with the correct indent in the first place.

With this, we can also add a progress meter that is useful e.g. in local CNB installs over slow network connections, as the downloads take longer than the installs, meaning a build might hang for quite some time without and progress output, until, suddenly, the names of the packages installed are printed in fairly quick succession.

This progress meter is disabled in the classic buildpack, because Heroku Dashboard currently trips over the ANSI cursor control codes and ends up swallowing quite a lot of lines.

GUS-W-18506658

Author: dzuelke

bin/compile

@@ -429,12 +429,14 @@ status "Installing platform packages..."
 export export_file_path=$bp_dir/export
 export profile_dir_path=$build_dir/.profile.d
 export providedextensionslog_file_path=$(mktemp -t "provided-extensions.log.XXXXXX" -u)
-# we make a new file descriptor for the installer plugin to log "human readable" display output to, duplicated to stdout (via indent)
-exec {PHP_PLATFORM_INSTALLER_DISPLAY_OUTPUT_FDNO}> >(indent)
+# we make a new file descriptor for the installer plugin to log "human readable" display output to, duplicated to stdout
+exec {PHP_PLATFORM_INSTALLER_DISPLAY_OUTPUT_FDNO}>&1
 # the installer picks up the FD number in this env var, and writes a "display output" log to it
 # meanwhile, the "raw" output of 'composer install' goes to install.log in case we need it later
 export PHP_PLATFORM_INSTALLER_DISPLAY_OUTPUT_FDNO
-if composer install -d "$build_dir/.heroku/php" ${HEROKU_PHP_INSTALL_DEV-"--no-dev"} > $build_dir/.heroku/php/install.log 2>&1; then
+export PHP_PLATFORM_INSTALLER_DISPLAY_OUTPUT_INDENT=7
+# NO_COLOR=1 suppresses the download progress meter whose ANSI cursor codes trip up output in Heroku Dashboard
+if NO_COLOR=1 composer install -d "$build_dir/.heroku/php" ${HEROKU_PHP_INSTALL_DEV-"--no-dev"} > $build_dir/.heroku/php/install.log 2>&1; then
 	:
 else
 	code=$?
@@ -528,18 +530,16 @@ if [[ -s "$providedextensionslog_file_path" ]]; then
 		for extension in "${provides[@]:1}"; do # remaining words in line are native extensions it declares "provide"d
 			ext_package=$(cut -d":" -f1 <<< "$extension") # extract name from "ext-foo:1.2.3" string
 			ext_name=${ext_package#"heroku-sys/"} # no "heroku-sys/" prefix for human output
-			echo -n "- ${ext_name}... " | indent
 			# run a `composer require`, confined to the package we're attempting, allowing any version
 			# we're appending to install.log using tee, and using another new "display output" FD to redirect to a new single-step log (tee truncates for us)
 			# this log is checked later to see if a package install actually happened, or if it was already enabled (since both exit status 0)
-			# we're letting the indents begin the line with a \r character, so that the above `echo -n` gets overwritten
-			exec {PHP_PLATFORM_INSTALLER_DISPLAY_OUTPUT_FDNO}> >(tee "$current_install_log" | indent "" $'\r       ')
-			if composer require -d "$build_dir/.heroku/php" "${ext_package}.native:*" >> $build_dir/.heroku/php/install.log 2>&1; then
+			exec {PHP_PLATFORM_INSTALLER_DISPLAY_OUTPUT_FDNO}> >(tee "$current_install_log")
+			# NO_COLOR=1 suppresses the download progress meter whose ANSI cursor codes trip up output in Heroku Dashboard
+			if NO_COLOR=1 composer require -d "$build_dir/.heroku/php" "${ext_package}.native:*" >> $build_dir/.heroku/php/install.log 2>&1; then
 				# package added successfully
-				[[ -s "$current_install_log" ]] || { echo -e "- ${ext_name} (already enabled)" | indent "" $'\r       '; } # if nothing was actually installed above, that means the dependency was already satisfied (i.e. extension is statically built into PHP); we need to echo something to that effect
+				[[ -s "$current_install_log" ]] || { echo "- ${ext_name} (already enabled)" | indent; } # if nothing was actually installed above, that means the dependency was already satisfied (i.e. extension is statically built into PHP); we need to echo something to that effect
 			else
 				# composer did not succeed; this means no package that matches all existing package's requirements was found
-				echo -n -e "\r" # reset the line
 				notice_inline "no suitable native version of ${ext_name} available"
 			fi
 			exec {PHP_PLATFORM_INSTALLER_DISPLAY_OUTPUT_FDNO}>&-
@@ -549,7 +549,7 @@ if [[ -s "$providedextensionslog_file_path" ]]; then
 	exec {fd_num}>&-
 fi
 
-unset PHP_PLATFORM_INSTALLER_DISPLAY_OUTPUT_FDNO
+unset PHP_PLATFORM_INSTALLER_DISPLAY_OUTPUT_FDNO PHP_PLATFORM_INSTALLER_DISPLAY_OUTPUT_INDENT
 
 # log number of installed platform packages
 mmeasure "platform.count" $(composer show -d "$build_dir/.heroku/php" --installed "heroku-sys/*" 2> /dev/null | wc -l)

support/installer/src/ComposerInstallerPlugin.php

@@ -5,14 +5,12 @@
 use Composer\Composer;
 use Composer\Factory;
 use Composer\IO\{IOInterface, ConsoleIO, NullIO};
-use Symfony\Component\Console\Formatter\OutputFormatter;
-use Symfony\Component\Console\Helper\HelperSet;
+use Symfony\Component\Console\Helper\{HelperSet,ProgressBar};
 use Symfony\Component\Console\Input\ArrayInput;
 use Symfony\Component\Console\Output\StreamOutput;
-use Composer\Plugin\PluginInterface;
+use Composer\Plugin\{PluginEvents,PluginInterface,PreFileDownloadEvent,PostFileDownloadEvent};
 use Composer\EventDispatcher\EventSubscriberInterface;
-use Composer\Installer\PackageEvent;
-use Composer\Installer\PackageEvents;
+use Composer\Installer\{PackageEvent,PackageEvents};
 use Composer\Package\PackageInterface;
 use Composer\Util\Filesystem;
 
@@ -35,17 +33,36 @@ class ComposerInstallerPlugin implements PluginInterface, EventSubscriberInterfa
 
 	protected $allPlatformRequirements = null;
 
+	protected $progressBar;
+	
 	public function activate(Composer $composer, IOInterface $io)
 	{
 		$this->composer = $composer;
 		$this->io = $io;
 
+		// we were supplied with a file descriptor to write "display output" to
+		// this can be used by a calling buildpack to get a clean progress bar for downloads, followed by a list of package installs as they happen
+		// for this, we make a ConsoleIO instance to be passed to the downloaders for install() output, and a progress bar for our download event listeners
 		if($fdno = getenv("PHP_PLATFORM_INSTALLER_DISPLAY_OUTPUT_FDNO")) {
-			$styles = Factory::createAdditionalStyles();
-			$formatter = new OutputFormatter(false, $styles);
+			// a new <indent> tag that can be used in output to prefix a line using the specified indentation
+			// this way the progress bar, downloaders, etc, do not have to handle the indentation each
+			$styles = [
+				'indent' => new IndentedOutputFormatterStyle(intval(getenv('PHP_PLATFORM_INSTALLER_DISPLAY_OUTPUT_INDENT')))
+			];
+			// special formatter that ignores colors if false is passed as first arg, we want that initially
+			$formatter = new NoColorsOutputFormatter(false, $styles);
 			$input = new ArrayInput([]);
 			$input->setInteractive(false);
-			$output = new StreamOutput(fopen("php://fd/{$fdno}", "w"), StreamOutput::VERBOSITY_NORMAL, null, $formatter);
+			// obey NO_COLOR to control whether or not we want a progress bar
+			// (unfortunately, we cannot get e.g. the --no-progress or --no-ansi options from the Composer command invocation)
+			$output = new StreamOutput(fopen("php://fd/{$fdno}", "w"), StreamOutput::VERBOSITY_NORMAL, !getenv('NO_COLOR'), $formatter);
+			if($output->isDecorated()) {
+				$this->progressBar = new ProgressBar($output);
+				$progressBarFormat = ProgressBar::getFormatDefinition('normal');
+				$this->progressBar->setFormat(sprintf("<indent>Downloaded%s</indent>", $progressBarFormat));
+			}
+			// we force ANSI output to on here for the indentation output formatter style to work
+			$output->setDecorated(true);
 			$this->displayIo = new ConsoleIO($input, $output, new HelperSet());
 		} else {
 			$this->displayIo = new NullIO();
@@ -102,7 +119,61 @@ public function uninstall(Composer $composer, IOInterface $io)
 
 	public static function getSubscribedEvents()
 	{
-		return [PackageEvents::POST_PACKAGE_INSTALL => 'onPostPackageInstall'];
+		return [
+			PluginEvents::PRE_FILE_DOWNLOAD => 'onPreFileDownload',
+			PluginEvents::POST_FILE_DOWNLOAD => 'onPostFileDownload',
+			PackageEvents::PRE_PACKAGE_INSTALL => 'onPrePackageInstall',
+			PackageEvents::POST_PACKAGE_INSTALL => 'onPostPackageInstall',
+		];
+	}
+	
+	// this fires when a download starts
+	public function onPreFileDownload(PreFileDownloadEvent $event)
+	{
+		$package = $event->getContext();
+		if($event->getType() != 'package' || $package->getDistType() != 'heroku-sys-tar') {
+			return;
+		}
+		// downloads happen in parallel, so marking progress here already would be useless
+		// but we can set the number of expected downloads on the progress bar, and start it
+		if($this->progressBar && !$this->progressBar->getMaxSteps()) {
+			// we can get the number of total downloads from the current event
+			// it's the package that fired this event, and it has a LockedArrayRepository of all the packages that will be installed
+			// from that, we go find all the packages that have a dist type of "heroku-sys-tar" and count them
+			$totalDownloadCount = array_reduce($package->getRepository()->getPackages(), function($carry, $item) { return $carry + intval($item->getDistType() == 'heroku-sys-tar'); }, 0);
+			$this->progressBar->clear(); // in case our caller printed something on the same line, before the install
+			$this->progressBar->start($totalDownloadCount);
+		}
+	}
+	
+	// this fires when a download finishes, so we can output progress info
+	// (Downloader::download returns a promise for parallel downloads, so would be as useless as onPreFileDownload above)
+	public function onPostFileDownload(PostFileDownloadEvent $event)
+	{
+		if($event->getType() != 'package' || $event->getContext()->getDistType() != 'heroku-sys-tar') {
+			return;
+		}
+		if($this->progressBar) {
+			$this->progressBar->advance(); // this will re-draw for us
+		}
+	}
+	
+	// this fires for every package install
+	// nothing to do for us here except to clear a progress bar if it exists
+	public function onPrePackageInstall(PackageEvent $event)
+	{
+		// clear our progress bar, since we're done with downloads
+		// the actual package installs are printed via the Downloaders, just like Composer does it
+		if($this->progressBar) {
+			if($this->displayIo->isDecorated()) {
+				// display output is ANSI capable, we can clear the progress bar
+				$this->progressBar->clear();
+			} else {
+				// display output is not ANSI capable, we need a line break after the progress bar
+				$this->displayIo->write("");
+			}
+			$this->progressBar = null;
+		}
 	}
 
 	public function onPostPackageInstall(PackageEvent $event)

support/installer/src/Downloader.php

@@ -59,7 +59,8 @@ public function install(PackageInterface $package, string $path, bool $output =
 		$fn = str_replace('/', '$', $package->getPrettyName());
 		$marker = "$path/$fn.extracted";
 		$this->addCleanupPath($package, $marker);
-		$this->displayIo->write(sprintf('- <info>%s</info> (<comment>%s</comment>)', ComposerInstaller::formatHerokuSysName($package->getPrettyName()), $package->getFullPrettyVersion()));
+		# our indent style can't be nested together with other styling tags
+		$this->displayIo->write(sprintf("<indent>-</indent> <info>%s</info> (<comment>%s</comment>)", ComposerInstaller::formatHerokuSysName($package->getPrettyName()), $package->getFullPrettyVersion()));
 		return parent::install($package, $path, $output);
 	}
 }

support/installer/src/IndentedOutputFormatterStyle.php

@@ -0,0 +1,21 @@
+<?php
+
+namespace Heroku\Buildpack\PHP;
+
+use Symfony\Component\Console\Formatter\OutputFormatterStyle;
+
+class IndentedOutputFormatterStyle extends OutputFormatterStyle
+{
+    private $prefix;
+
+    public function __construct(int $indent = 0, ?string $foreground = null, ?string $background = null, array $options = [])
+    {
+        $this->prefix = str_repeat(" ", $indent);
+        parent::__construct($foreground, $background, $options);
+    }
+
+    public function apply(string $text)
+    {
+        return sprintf("%s%s", $this->prefix, $text);
+    }
+}

support/installer/src/NoColorsOutputFormatter.php

@@ -0,0 +1,22 @@
+<?php
+
+namespace Heroku\Buildpack\PHP;
+
+use \Symfony\Component\Console\Formatter\{NullOutputFormatterStyle,OutputFormatter,OutputFormatterStyle,OutputFormatterStyleStack};
+
+class NoColorsOutputFormatter extends OutputFormatter
+{
+	public function __construct(bool $decorated = false, array $styles = [])
+	{
+		// this will set up the default styles below
+		parent::__construct($decorated, $styles);
+		
+		if(!$decorated) {
+			// no "decoration", i.e. no ANSI stuff, so we reset the defaults
+			$this->setStyle('error', new NullOutputFormatterStyle());
+			$this->setStyle('info', new NullOutputFormatterStyle());
+			$this->setStyle('comment', new NullOutputFormatterStyle());
+			$this->setStyle('question', new NullOutputFormatterStyle());
+		}
+	}
+}

support/installer/src/NoopDownloader.php

@@ -40,7 +40,8 @@ public function prepare(string $type, PackageInterface $package, string $path, ?
 
 	public function install(PackageInterface $package, string $path): PromiseInterface
 	{
-		$this->displayIo->write(sprintf("- %s", ($this->humanMessageFormatter)($package, $path)));
+		# our indent style can't be nested together with other styling tags
+		$this->displayIo->write(sprintf("<indent>-</indent> %s", ($this->humanMessageFormatter)($package, $path)));
 		$this->io->writeError(sprintf("  - %s", ($this->installMessageFormatter)($package, $path)));
 		return \React\Promise\resolve(null);
 	}

test/spec/platform_spec.rb

@@ -93,7 +93,15 @@
 			@profiled_tmpdir = Dir.mktmpdir("profile.d")
 			FileUtils.cp("#{generator_fixtures_subdir}/base/expected_platform_composer.json", "#{@install_tmpdir}/composer.json")
 			Dir.chdir(@install_tmpdir) do
-				cmd = "exec {PHP_PLATFORM_INSTALLER_DISPLAY_OUTPUT_FDNO}> #{@humanlog_tmpfile.path}; export PHP_PLATFORM_INSTALLER_DISPLAY_OUTPUT_FDNO; export_file_path=#{@export_tmpfile.path} profile_dir_path=#{@profiled_tmpdir} composer install --no-dev"
+				cmd = <<~EOF
+					exec {PHP_PLATFORM_INSTALLER_DISPLAY_OUTPUT_FDNO}> #{Shellwords.escape(@humanlog_tmpfile.path)}
+					export PHP_PLATFORM_INSTALLER_DISPLAY_OUTPUT_FDNO
+					export PHP_PLATFORM_INSTALLER_DISPLAY_OUTPUT_INDENT=4
+					export export_file_path=#{Shellwords.escape(@export_tmpfile.path)}
+					export profile_dir_path=#{Shellwords.escape(@profiled_tmpdir)}
+					composer install --no-dev
+				EOF
+				
 				@stdout, @stderr, @status = Open3.capture3("bash -c #{Shellwords.escape(cmd)}")
 			end
 		end
@@ -144,23 +152,29 @@
 			expect(Dir.entries("#{@install_tmpdir}/etc/php/conf.d").any? {|f| f.include?("ext-mbstring.ini")}).to eq(true)
 		end
 
-		it "writes a human-readable log to a given file descriptor" do
+		it "writes a human-readable log (with the expected indentation) to a given file descriptor" do
 			version_triple = /\(\d+\.\d+\.\d+(\+[^)]+)?\)/ # 1.2.3 or 1.2.3+build2
 			bundled = /\(bundled with php\)/
+			# the download progress indicator is written using ANSI cursors:
+			# "    Downloaded 0/8 [>---------------------------]   0%\e[1G\e[2K    Downloaded 1/8 [===>------------------------]  12%\e[1G\e[2K    Downloaded 2/8 [=======>--------------------]  25%\e[1G\e[2K    Downloaded 4/8 [==============>-------------]  50%\e[1G\e[2K    Downloaded 5/8 [=================>----------]  62%\e[1G\e[2K    Downloaded 6/8 [=====================>------]  75%\e[1G\e[2K    Downloaded 7/8 [========================>---]  87%\e[1G\e[2K    Downloaded 8/8 [============================] 100%\e[1G\e[2K    - php (8.4.6)\n    - ext-sqlite3 (bundled with php)\n..."
+			# we want to check that the download progress is actually printed, and then removed using ANSI codes
+			# so we just match on the last progress report (since we're not always guaranteed to get one for every step depending on speed)
 			expect(@humanlog_tmpfile.read).to match Regexp.new(<<~EOF)
-			^- php #{version_triple.source}$
-			^- ext-sqlite3 #{bundled.source}$
-			^- ext-redis #{version_triple.source}$
-			^- ext-mbstring #{bundled.source}$
-			^- ext-ldap #{bundled.source}$
-			^- ext-intl #{bundled.source}$
-			^- ext-imap #{version_triple.source}$
-			^- ext-gmp #{bundled.source}$
-			^- blackfire #{version_triple.source}$
-			^- ext-blackfire #{version_triple.source}$
-			^- apache #{version_triple.source}$
-			^- composer #{version_triple.source}$
-			^- nginx #{version_triple.source}$
+				    Downloaded 8/8 \\[============================\\] 100%\
+				\\e\\[1G\\e\\[2K\
+				    - php #{version_triple.source}
+				    - ext-sqlite3 #{bundled.source}
+				    - ext-redis #{version_triple.source}
+				    - ext-mbstring #{bundled.source}
+				    - ext-ldap #{bundled.source}
+				    - ext-intl #{bundled.source}
+				    - ext-imap #{version_triple.source}
+				    - ext-gmp #{bundled.source}
+				    - blackfire #{version_triple.source}
+				    - ext-blackfire #{version_triple.source}
+				    - apache #{version_triple.source}
+				    - composer #{version_triple.source}
+				    - nginx #{version_triple.source}
 			EOF
 
 		end