Handle download progress, indentation, and "already enabled" printing inside installer plugin

.github/workflows/ci.yml

@@ -23,7 +23,7 @@ env:
   HEROKU_API_KEY: ${{ secrets.HEROKU_API_KEY }}
   HEROKU_API_USER: ${{ secrets.HEROKU_API_USER }}
   GIT_HTTP_LOW_SPEED_LIMIT: 1000
-  GIT_HTTP_LOW_SPEED_TIME: 60
+  GIT_HTTP_LOW_SPEED_TIME: 300
 
 jobs:
   integration-test:

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=$?
@@ -510,14 +512,10 @@ else
 	EOF
 fi
 
-# close display output FD (we make new ones for each iteration next)
-exec {PHP_PLATFORM_INSTALLER_DISPLAY_OUTPUT_FDNO}>&-
-
-export -n providedextensionslog_file_path # export no longer needed
+export -n providedextensionslog_file_path # export no longer needed (and we don't want more entries written by the plugin even if it encounters them)
 if [[ -s "$providedextensionslog_file_path" ]]; then
 	notice_inline "detected userland polyfill packages for PHP extensions"
 	notice_inline "now attempting to install native extension packages"
-	current_install_log=$(mktemp -t "currentinstall.log.XXXXXX" -u) # for capturing the single "composer install" output
 	# the platform installer recorded userland packages that "provide" a PHP extension
 	# for each occurrence (source package providing other package(s)) in the list,
 	# we will now attempt to install the real native extension packages (rest of the line)
@@ -528,28 +526,23 @@ 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
-				# 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
-			else
+			#   (the .native "replace"d variant in each extension matches the regular version, so the constraint for that regular version is enough)
+			# 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
 				# 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}>&-
 		done
 	done {fd_num}< "$providedextensionslog_file_path" # use bash 4.1+ automatic file descriptor allocation (better than hardcoding e.g. "3<"), otherwise this loop's stdin (the lines of the file) will be consumed by programs called inside the loop
-	rm "$current_install_log"
 	exec {fd_num}>&-
 fi
 
-unset PHP_PLATFORM_INSTALLER_DISPLAY_OUTPUT_FDNO
+# clean up installer variables and files
+# we want to keep export_file_path and profile_dir_path for newrelic and blackfire attempts at the end though
+rm -f "$providedextensionslog_file_path"
+unset providedextensionslog_file_path
+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/composer.json

@@ -1,7 +1,7 @@
 {
 	"type": "composer-plugin",
 	"name": "heroku/installer-plugin",
-	"version": "1.7.3",
+	"version": "1.7.5",
 	"autoload": {
 		"psr-4": {
 			"Heroku\\Buildpack\\PHP\\": "src/"

support/installer/src/ComposerInstaller.php

@@ -16,7 +16,9 @@ public function getInstallPath(PackageInterface $package)
 
 	public static function formatHerokuSysName(string $name): string
 	{
-		return sscanf($name, "heroku-sys/%s")[0] ?? $name;
+		// strip a "heroku-sys/" prefix if it exists, and in that case, also a ".native" postfix
+		// this turns our internal "heroku-sys/ext-foobar.native" or "heroku-sys/php" names into "ext-foobar" or "php" for display output
+		return preg_replace('#^(heroku-sys/)(.+?)(?(1).native)?$#', '$2', $name);
 	}
 
 	/**

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,PrePoolCreateEvent};
 use Composer\EventDispatcher\EventSubscriberInterface;
-use Composer\Installer\PackageEvent;
-use Composer\Installer\PackageEvents;
+use Composer\Installer\{InstallerEvent,InstallerEvents,PackageEvent,PackageEvents};
 use Composer\Package\PackageInterface;
 use Composer\Util\Filesystem;
 
@@ -33,19 +31,40 @@ class ComposerInstallerPlugin implements PluginInterface, EventSubscriberInterfa
 	protected $profileCounter = 10;
 	protected $configCounter = 10;
 
+	protected $requestedPackages = [];
 	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)
+			// (using $io->isDecorated() does not help either, as regular stdout/stderr might be redirected, but not our display output FD)
+			$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,9 +121,117 @@ public function uninstall(Composer $composer, IOInterface $io)
 
 	public static function getSubscribedEvents()
 	{
-		return [PackageEvents::POST_PACKAGE_INSTALL => 'onPostPackageInstall'];
+		return [
+			PluginEvents::PRE_POOL_CREATE => 'onPrePoolCreate',
+			InstallerEvents::PRE_OPERATIONS_EXEC => 'onPreOperationsExec',
+			PluginEvents::PRE_FILE_DOWNLOAD => 'onPreFileDownload',
+			PluginEvents::POST_FILE_DOWNLOAD => 'onPostFileDownload',
+			PackageEvents::PRE_PACKAGE_INSTALL => 'onPrePackageInstall',
+			PackageEvents::POST_PACKAGE_INSTALL => 'onPostPackageInstall',
+		];
+	}
+
+	// This does not fire on initial install, as the plugin gets installed as part of that, but the event fires before the plugin install.
+	// Just what we want, since the logic in here is for the "ext-foobar.native" install attempts after the main packages installation.
+	// For those invocations, the plugin is already enabled, and this event handler fires.
+	public function onPrePoolCreate(PrePoolCreateEvent $event)
+	{
+		// the list of explicitly requested packages from e.g. a 'composer require ext-foobar.native:*'
+		// we remember this for later, so we can output a message about already-enabled extensions
+		// this will be e.g. ["heroku-sys/ext-mbstring.native"]
+		$this->requestedPackages = $event->getRequest()->getUpdateAllowList();
+	}
+
+	// This does not fire on initial install, as the plugin gets installed as part of that, but the event fires before the plugin install.
+	// Just what we want, since the logic in here is for the "ext-foobar.native" install attempts after the main packages installation.
+	// For those invocations, the plugin is already enabled, and this event handler fires.
+	public function onPreOperationsExec(InstallerEvent $event)
+	{
+		// From the list of operations, we are getting all packages due for install.
+		// For each package, we check the "replaces" declarations.
+		// For instance, "heroku-sys/ext-mbstring" will declare that it replaces "heroku-sys/ext-mbstring.native".
+		// The "replaces" array is keyed by "replacement destination", so it's e.g.:
+		//   {"heroku-sys/ext-mbstring.native": {Composer\Package\Link(source="heroku-sys/ext-mbstring",target="heroku-sys/ext-mbstring.native")}}
+		// For any package found here that is in the requestAllowList made in onPrePoolCreate, this means a regular installation,
+		// the Downloader will print install progress in this case.
+		// What we are really looking for, though, is packages in requestAllowList that are not in our list of operations,
+		// that means the extension is already enabled (either installed previously, or enabled in PHP by default).
+		// Because no installer event will fire in that case (nothing gets installed, after all), we want to output a message here.
+		$installs = [];
+		foreach($event->getTransaction()->getOperations() as $operation) {
+			// add the package itself, just for completeness
+			if ($operation->getOperationType() == "install") {
+				$installs[] = $operation->getPackage()->getPrettyName();
+			}
+			// add all "replace" declarations from the package
+			$installs = array_merge($installs, array_keys($operation->getPackage()->getReplaces()));
+		}
+		foreach(array_diff($this->requestedPackages, $installs) as $requestedPackageNotInstalled) {
+			$this->displayIo->write(sprintf('<indent>-</indent> <info>%s</info> (already enabled)', ComposerInstaller::formatHerokuSysName($requestedPackageNotInstalled)));
+		}
+	}
+
+	// Because our plugin declares "plugin-modifies-downloads", Composer installs it first.
+	// After that, all other package downloads trigger this event.
+	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 update the number of expected downloads on the progress bar
+		if($this->progressBar) {
+			$downloadCount = $this->progressBar->getMaxSteps();
+			if(!$downloadCount++) { // post-increment operator
+				// first invocation, we want to initialize the progress bar with a start time
+				$this->progressBar->start($downloadCount);
+				// however, our maximum step count will now increase with each onPreFileDownload
+				// that looks a little confusing if we print every time, so we clear the progress bar again immediately
+				// also useful in case our caller printed something on the same line, before the install
+				$this->progressBar->clear();
+			} else {
+				$this->progressBar->setMaxSteps($downloadCount);
+			}
+		}
+	}
+
+	// Because our plugin declares "plugin-modifies-downloads", Composer installs it first.
+	// After that, all other package downloads trigger this event.
+	// We use it to output progress info when a download finishes
+	// (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
+		}
+	}
+
+	// Because our plugin declares "plugin-modifies-install-path", Composer installs it first.
+	// After that, all other package installs trigger this event.
+	// 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;
+		}
 	}
 
+	// Because our plugin declares "plugin-modifies-install-path", Composer installs it first.
+	// After that, all other package installs trigger this event.
+	// Here we do a lot of the "heavy lifting"
 	public function onPostPackageInstall(PackageEvent $event)
 	{
 		// first, load all platform requirements from all operations

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/fixtures/platform/installer/polyfills-nodowngrade/README.md

@@ -0,0 +1,5 @@
+This test case asserts that a native extension install attempt for a polyfilled extension will not change existing locked dependencies.
+
+It used to test using `ext-xmlrpc`, which was only bundled with PHP 7. The initial `"php": "*"` requirement would pick PHP 8 (which no longer had `ext-xmlrpc`) due to an available polyfill for it, and we don't want to downgrade PHP to version 7 once the `ext-xmlrpc.native` install attempt is made.
+
+We don't have PHP 7 anymore, and the only recently retired extension is `ext-imap` (since PHP 8.4), but that is available through PECL and we offer it, so we have to use specific versions of extensions. A suitable candidate therefore is `ext-newrelic`, which is only available in version 11 for PHP 8.4, so our polyfill provides `ext-newrelic` version 10, and `composer.json` also depends on version 10.