From 8adda745a7eed27add5f9b19c6704f876088cf4a Mon Sep 17 00:00:00 2001 From: Joel Wurtz Date: Tue, 6 Oct 2026 17:10:36 +0200 Subject: [PATCH] Show the progress of parallel builds live --- CHANGELOG.md | 6 + doc/tasks.md | 6 +- src/Build/BoardBuildReporter.php | 152 ++++++++++++++++++ src/Build/BuildReporter.php | 22 +++ src/Build/StreamedBuildReporter.php | 43 +++++ src/functions.php | 19 ++- src/tasks.php | 110 +++++++++---- tests/Unit/Build/BoardBuildReporterTest.php | 118 ++++++++++++++ .../Unit/Build/StreamedBuildReporterTest.php | 26 +++ 9 files changed, 466 insertions(+), 36 deletions(-) create mode 100644 src/Build/BoardBuildReporter.php create mode 100644 src/Build/BuildReporter.php create mode 100644 src/Build/StreamedBuildReporter.php create mode 100644 tests/Unit/Build/BoardBuildReporterTest.php create mode 100644 tests/Unit/Build/StreamedBuildReporterTest.php diff --git a/CHANGELOG.md b/CHANGELOG.md index c818827..4239f01 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -1,5 +1,11 @@ # Changelog +## Unreleased + +### Changed + +* The parallel builds show their progress live: one line per service in a terminal, every line prefixed by its service anywhere else. + ## 0.10.0 - 2026-10-06 ### Added diff --git a/doc/tasks.md b/doc/tasks.md index b84e134..a2c7ba4 100644 --- a/doc/tasks.md +++ b/doc/tasks.md @@ -58,8 +58,10 @@ castor docker:build app # a single service castor docker:build --profiles builder # restrict to a profile ``` -`--parallel` builds each service on its own, all of them in parallel, and -prints the log of each one once it is done. Built together, services sharing a +`--parallel` builds each service on its own, all of them in parallel. A +terminal shows one line per service with the step it is at, and the full log of +the builds that failed once they are all done; anywhere else, a CI log or a +pipe, every line streams as it comes, prefixed by its service. Built together, services sharing a stage — an application and its builder sharing `php-base` — race their build caches, and BuildKit randomly rebuilds the steps of all but one of them ([moby/buildkit#6418](https://github.com/moby/buildkit/issues/6418)). Turn it on diff --git a/src/Build/BoardBuildReporter.php b/src/Build/BoardBuildReporter.php new file mode 100644 index 0000000..a973319 --- /dev/null +++ b/src/Build/BoardBuildReporter.php @@ -0,0 +1,152 @@ +, active: array, log: list}> */ + private array $builds = []; + private int $width; + private float $renderedAt = 0; + + /** + * @param non-empty-list $services + */ + public function __construct( + private readonly ConsoleSectionOutput $section, + private readonly OutputInterface $output, + array $services, + private readonly ?int $terminalWidth = null, + ) { + $this->width = max(array_map(strlen(...), $services)); + $now = microtime(true); + + foreach ($services as $service) { + $this->builds[$service] = ['start' => $now, 'end' => null, 'successful' => null, 'steps' => [], 'active' => [], 'log' => []]; + } + } + + public function line(string $service, string $line): void + { + $build = &$this->builds[$service]; + $build['log'][] = $line; + + // "#5 [app 2/8] RUN ..." names step 5, then "#5 0.42 " and + // "#5 DONE 1.2s" follow it. + if (!preg_match('{^#(\d+) (.+)$}', $line, $matches)) { + return; + } + + $id = (int) $matches[1]; + $rest = $matches[2]; + + if (preg_match('{^(DONE|CACHED|ERROR|CANCELED)\b}', $rest)) { + unset($build['active'][$id]); + } elseif (!isset($build['steps'][$id])) { + $build['steps'][$id] = $rest; + $build['active'][$id] = true; + } + } + + public function tick(): void + { + $now = microtime(true); + + if ($now - $this->renderedAt < self::REFRESH) { + return; + } + + $this->renderedAt = $now; + $this->section->overwrite($this->lines($now)); + } + + public function finish(string $service, bool $successful): void + { + $build = &$this->builds[$service]; + $build['end'] = microtime(true); + $build['successful'] = $successful; + } + + public function end(): void + { + $this->section->overwrite($this->lines(microtime(true))); + + foreach ($this->builds as $service => $build) { + if (false !== $build['successful']) { + continue; + } + + $this->output->writeln(''); + $this->output->writeln(\sprintf('%s', $service)); + + foreach ($build['log'] as $line) { + $this->output->writeln(OutputFormatter::escape($line)); + } + } + } + + /** + * @return list + */ + public function lines(float $now): array + { + $frame = self::SPINNER[(int) ($now / self::SPIN) % \count(self::SPINNER)]; + $columns = $this->terminalWidth ?? (new Terminal())->getWidth(); + $lines = []; + + foreach ($this->builds as $service => $build) { + $elapsed = \sprintf('%.1fs', ($build['end'] ?? $now) - $build['start']); + + [$icon, $text] = match ($build['successful']) { + true => ['✔', 'built'], + false => ['✘', 'failed'], + null => ["{$frame}", $this->currentStep($build['steps'], $build['active'])], + }; + + // Icon, two spaces, the name, two spaces, the step, a space, the time. + $room = max(0, $columns - 1 - 2 - $this->width - 2 - 1 - \strlen($elapsed) - 1); + $text = Helper::width($text) > $room ? mb_substr($text, 0, max(0, $room - 1)) . '…' : $text; + + $lines[] = \sprintf( + '%s %s %s %s%s', + $icon, + str_pad($service, $this->width), + OutputFormatter::escape($text), + str_repeat(' ', max(0, $room - Helper::width($text))), + $elapsed, + ); + } + + return $lines; + } + + /** + * @param array $steps + * @param array $active + */ + private function currentStep(array $steps, array $active): string + { + if ($active) { + return $steps[array_key_last($active)]; + } + + return $steps ? $steps[array_key_last($steps)] : 'starting'; + } +} diff --git a/src/Build/BuildReporter.php b/src/Build/BuildReporter.php new file mode 100644 index 0000000..dca86de --- /dev/null +++ b/src/Build/BuildReporter.php @@ -0,0 +1,22 @@ + */ + private array $prefixes = []; + + /** + * @param non-empty-list $services + */ + public function __construct(private readonly OutputInterface $output, array $services) + { + $width = max(array_map(strlen(...), $services)); + + foreach ($services as $i => $service) { + $this->prefixes[$service] = \sprintf('%s | ', self::COLORS[$i % \count(self::COLORS)], str_pad($service, $width)); + } + } + + public function line(string $service, string $line): void + { + $this->output->writeln($this->prefixes[$service] . OutputFormatter::escape($line)); + } + + public function tick(): void {} + + public function finish(string $service, bool $successful): void {} + + public function end(): void {} +} diff --git a/src/functions.php b/src/functions.php index 4980df3..05ea27b 100644 --- a/src/functions.php +++ b/src/functions.php @@ -77,11 +77,14 @@ function get_default_profiles(?Context $c = null): array } /** + * The command docker_compose() runs, and the context to run it in. + * * @param list $subCommand * @param list $profiles - * @param ?string $progress "auto", "tty", "plain", "json" or "quiet", left to compose when null + * + * @return array{list, Context} */ -function docker_compose(array $subCommand, ?Context $c = null, array $profiles = [], ?string $progress = null): Process +function docker_compose_command(array $subCommand, ?Context $c = null, array $profiles = [], ?string $progress = null): array { $c ??= context(); $profiles = $profiles ?: get_default_profiles($c); @@ -120,6 +123,18 @@ function docker_compose(array $subCommand, ?Context $c = null, array $profiles = $command = array_merge($command, $subCommand); + return [$command, $c]; +} + +/** + * @param list $subCommand + * @param list $profiles + * @param ?string $progress "auto", "tty", "plain", "json" or "quiet", left to compose when null + */ +function docker_compose(array $subCommand, ?Context $c = null, array $profiles = [], ?string $progress = null): Process +{ + [$command, $c] = docker_compose_command($subCommand, $c, $profiles, $progress); + // The router is not a service of this file: it joins the project network // from the outside, so it is attached after "up" and detached before "down". $network = get_project_network($c); diff --git a/src/tasks.php b/src/tasks.php index 9a9ccdc..33a0179 100644 --- a/src/tasks.php +++ b/src/tasks.php @@ -10,6 +10,8 @@ use Castor\Attribute\AsTask; use Castor\Context; use Castor\Console\Output\VerbosityLevel; +use Castor\Docker\Build\BoardBuildReporter; +use Castor\Docker\Build\StreamedBuildReporter; use Castor\Docker\Doctor\Doctor; use Castor\Docker\Doctor\HostSystemProbe; use Castor\Docker\Installer\Ast\ServiceStatementBuilder; @@ -20,7 +22,7 @@ use Symfony\Component\Console\Formatter\OutputFormatter; use Symfony\Component\Console\Helper\TableSeparator; use Symfony\Component\Console\Input\InputOption; -use Symfony\Component\Console\Output\OutputInterface; +use Symfony\Component\Console\Output\ConsoleOutputInterface; use Symfony\Component\Console\Terminal; use Symfony\Component\Process\Exception\ExceptionInterface; use Symfony\Component\Process\Process; @@ -29,7 +31,7 @@ use function Castor\capture; use function Castor\context; use function Castor\io; -use function Castor\parallel; +use function Castor\output; use function Castor\variable; use function Castor\run; @@ -77,9 +79,6 @@ function build( build_separately($command, $services, $profiles); } -/** - * Off by default: the logs of the services only show once each one is built. - */ function is_build_parallel(?bool $option = null, ?Context $c = null): bool { return $option ?? (($c ?? context())->data['build_parallel'] ?? false); @@ -91,44 +90,93 @@ function is_build_parallel(?bool $option = null, ?Context $c = null): bool * and randomly loses the steps of all but one (moby/buildkit#6418). * * @param list $command - * @param list $services + * @param non-empty-list $services * @param list $profiles */ function build_separately(array $command, array $services, array $profiles): void { - $c = context()->withQuiet()->withAllowFailure()->withTty(false)->withPty(false); + $builds = []; - $processes = parallel(...array_map( - static fn(string $service): \Closure => static fn(): Process => docker_compose([...$command, $service], $c, $profiles, 'plain'), - $services, - )); + foreach ($services as $service) { + [$compose, $c] = docker_compose_command([...$command, $service], profiles: $profiles, progress: 'plain'); + $builds[$service] = new Process($compose, $c->workingDirectory, $c->environment, null, null); + } - report_separate_builds($services, $processes); + run_builds_in_parallel($builds); } /** - * @param list $services - * @param array $processes + * Polls the processes itself rather than through castor's parallel(), which + * sleeps once per process on every round: the more services, the slower the + * output would refresh. + * + * @param non-empty-array $builds */ -function report_separate_builds(array $services, array $processes): void +function run_builds_in_parallel(array $builds): void { + $services = array_keys($builds); + $output = output(); + $reporter = $output instanceof ConsoleOutputInterface && $output->isDecorated() && stream_isatty(\STDOUT) + ? new BoardBuildReporter($output->section(), $output, $services) + : new StreamedBuildReporter($output, $services); + + /** @var array> $buffers one per stream, a line may arrive in several chunks */ + $buffers = []; + + $emit = static function (string $service, string $line) use ($reporter): void { + // BuildKit separates its steps with blank lines, which only add noise + // once interleaved with other builds. + if ('' !== $line = rtrim($line)) { + $reporter->line($service, $line); + } + }; + + foreach ($builds as $service => $process) { + $process->start(static function (string $type, string $bytes) use ($service, &$buffers, $emit): void { + $buffer = ($buffers[$service][$type] ?? '') . $bytes; + + while (false !== $end = strpos($buffer, "\n")) { + $emit($service, substr($buffer, 0, $end)); + $buffer = substr($buffer, $end + 1); + } + + $buffers[$service][$type] = $buffer; + }); + } + + $running = $builds; $failed = []; - foreach ($services as $i => $service) { - $process = $processes[$i]; + try { + while ($running) { + foreach ($running as $service => $process) { + // Reading the status is also what feeds the output callback. + if ($process->isRunning()) { + continue; + } - if (!$process instanceof Process) { - $failed[] = $service; + unset($running[$service]); - continue; - } + foreach ($buffers[$service] ?? [] as $rest) { + $emit($service, $rest); + } - io()->section($service); - io()->write($process->getOutput() . $process->getErrorOutput(), false, OutputInterface::OUTPUT_RAW); + $reporter->finish($service, $process->isSuccessful()); - if (!$process->isSuccessful()) { - $failed[] = $service; + if (!$process->isSuccessful()) { + $failed[] = $service; + } + } + + $reporter->tick(); + usleep(10_000); + } + } finally { + foreach ($running as $process) { + $process->stop(); } + + $reporter->end(); } if ($failed) { @@ -890,15 +938,13 @@ function push( } // One bake per target, for the reason build_separately() gives. - $quiet = $c->withQuiet()->withAllowFailure()->withTty(false)->withPty(false); - $services = array_keys($targets); + $builds = []; - $processes = parallel(...array_map( - static fn(string $service): \Closure => static fn(): Process => run([...$command, ...$options[$service], '--progress', 'plain', $service], context: $quiet), - $services, - )); + foreach (array_keys($targets) as $service) { + $builds[$service] = new Process([...$command, ...$options[$service], '--progress', 'plain', $service], $c->workingDirectory, $c->environment, null, null); + } - report_separate_builds($services, $processes); + run_builds_in_parallel($builds); } /** diff --git a/tests/Unit/Build/BoardBuildReporterTest.php b/tests/Unit/Build/BoardBuildReporterTest.php new file mode 100644 index 0000000..86b2709 --- /dev/null +++ b/tests/Unit/Build/BoardBuildReporterTest.php @@ -0,0 +1,118 @@ +reporter(['app', 'app-builder']); + + $reporter->line('app', '#5 [frontend 2/8] RUN apt-get update'); + $reporter->line('app', '#5 0.42 Get:1 http://deb.debian.org/debian trixie InRelease'); + $reporter->line('app-builder', '#4 [builder 1/10] FROM php-base'); + + static::assertSame([ + 'app [frontend 2/8] RUN apt-get update', + 'app-builder [builder 1/10] FROM php-base', + ], $this->steps($reporter)); + } + + /** + * BuildKit runs independent steps at once: the board follows the latest + * one still running, and falls back to the latest one started. + */ + public function testAFinishedStepGivesWayToTheOneStillRunning(): void + { + $reporter = $this->reporter(['app']); + + $reporter->line('app', '#5 [frontend 2/8] RUN apt-get update'); + $reporter->line('app', '#6 [frontend 3/8] COPY . .'); + $reporter->line('app', '#6 DONE 0.1s'); + + static::assertSame(['app [frontend 2/8] RUN apt-get update'], $this->steps($reporter)); + + $reporter->line('app', '#5 CACHED'); + + static::assertSame(['app [frontend 3/8] COPY . .'], $this->steps($reporter)); + } + + public function testAFinishedBuildShowsItsOutcome(): void + { + $reporter = $this->reporter(['app', 'node']); + + $reporter->finish('app', true); + $reporter->finish('node', false); + + static::assertSame(['✔ app built', '✘ node failed'], $this->steps($reporter, withIcon: true)); + } + + public function testALongStepIsCutToTheWidthOfTheTerminal(): void + { + $reporter = $this->reporter(['app'], width: 40); + + $reporter->line('app', '#5 [frontend 2/8] RUN install-php-extensions intl pdo_pgsql redis'); + + $line = $this->plain($reporter->lines(microtime(true))[0]); + + static::assertLessThanOrEqual(40, mb_strlen($line)); + static::assertStringContainsString('…', $line); + } + + public function testTheLogOfAFailedBuildIsPrintedInTheEnd(): void + { + $output = new BufferedOutput(); + $reporter = $this->reporter(['app', 'node'], output: $output); + + $reporter->line('app', '#5 [frontend 2/8] RUN true'); + $reporter->line('node', '#5 [node 2/4] RUN npm ci'); + $reporter->line('node', '#5 ERROR: process "npm ci" did not complete successfully'); + $reporter->finish('app', true); + $reporter->finish('node', false); + $reporter->end(); + + $printed = $output->fetch(); + + static::assertStringContainsString('npm ci" did not complete successfully', $printed); + static::assertStringNotContainsString('RUN true', $printed); + } + + /** + * @param non-empty-list $services + */ + private function reporter(array $services, int $width = 200, ?OutputInterface $output = null): BoardBuildReporter + { + $sections = []; + $section = new ConsoleSectionOutput(fopen('php://memory', 'w'), $sections, OutputInterface::VERBOSITY_NORMAL, false, new OutputFormatter()); + + return new BoardBuildReporter($section, $output ?? new BufferedOutput(), $services, $width); + } + + /** + * The lines without their spinner nor elapsed time, which move. + * + * @return list + */ + private function steps(BoardBuildReporter $reporter, bool $withIcon = false): array + { + return array_map(function (string $line) use ($withIcon): string { + $line = rtrim(preg_replace('{\s+\d+\.\ds$}', '', $this->plain($line)) ?? ''); + + return $withIcon ? $line : mb_substr($line, 3); + }, $reporter->lines(microtime(true))); + } + + private function plain(string $line): string + { + return (new OutputFormatter())->format($line) ?? ''; + } +} diff --git a/tests/Unit/Build/StreamedBuildReporterTest.php b/tests/Unit/Build/StreamedBuildReporterTest.php new file mode 100644 index 0000000..cc7a5eb --- /dev/null +++ b/tests/Unit/Build/StreamedBuildReporterTest.php @@ -0,0 +1,26 @@ +line('app', '#5 [frontend 2/8] RUN apt-get update'); + $reporter->line('app-builder', '#4 '); + + static::assertSame( + "app | #5 [frontend 2/8] RUN apt-get update\napp-builder | #4 \n", + $output->fetch(), + ); + } +}