From d8d5fb861ababb605674f2c1965d40720d863ad4 Mon Sep 17 00:00:00 2001 From: Harald Nordgren Date: Wed, 14 Oct 2026 19:58:22 +0200 Subject: [PATCH] Show a build progress spinner - Builds without `--verbose` print nothing while a command runs, so long ones such as `llvm` from source look stuck for hours. - The sandbox already relays the build's pseudo-terminal output, so keep a spinner below that output for the whole build, including startup, checksum checks and unpacking. - Show Ninja (`[12/345]`) or CMake (`[ 42%]`) step progress next to it, read from the newest build log, so `Formula#system` keeps writing straight to the log. - Stop drawing once a Ctrl-C is echoed, as the progress no longer matters while the build is being interrupted. --- Library/Homebrew/build_progress.rb | 111 ++++++++++++++++++ Library/Homebrew/formula_installer.rb | 1 + Library/Homebrew/sandbox.rb | 15 ++- Library/Homebrew/test/build_progress_spec.rb | 75 ++++++++++++ .../Homebrew/test/formula_installer_spec.rb | 2 +- Library/Homebrew/test/sandbox_shared_spec.rb | 21 ++++ Library/Homebrew/test/sandbox_spec.rb | 9 ++ 7 files changed, 232 insertions(+), 2 deletions(-) create mode 100644 Library/Homebrew/build_progress.rb create mode 100644 Library/Homebrew/test/build_progress_spec.rb diff --git a/Library/Homebrew/build_progress.rb b/Library/Homebrew/build_progress.rb new file mode 100644 index 0000000000000..1fc5cb718ebf6 --- /dev/null +++ b/Library/Homebrew/build_progress.rb @@ -0,0 +1,111 @@ +# typed: strict +# frozen_string_literal: true + +require "utils/tty" + +# Keeps a spinner below a build's output, followed by any step progress the +# current build log shows from e.g. Ninja (`[12/345]`) or CMake (`[ 42%]`). +class BuildProgress + STEP_PROGRESS = %r{\A\[(\d+)/(\d+)\]} + PERCENT_PROGRESS = /\A\[\s*(\d+)%\]/ + REDRAW_INTERVAL = 0.1 + LOG_CHECK_INTERVAL = 0.5 + LOG_TAIL_SIZE = 65536 + # How a pseudo-terminal echoes a typed Ctrl-C. + INTERRUPT_ECHO = "^C" + + sig { returns(T::Boolean) } + def self.tty? + return false if !$stdout.tty? || !$stderr.tty? + + ENV["TERM"] != "dumb" + end + + sig { params(logs: Pathname).void } + def initialize(logs) + require "download_queue" + + @logs = logs + @start_time = T.let(Time.now, Time) + @spinner = T.let(Homebrew::DownloadQueue::Spinner.new, Homebrew::DownloadQueue::Spinner) + # `Tty` isn't thread-safe, so resolve its colours and width before drawing in a thread. + @spinner_colour = T.let(Tty.blue.to_s, String) + @reset = T.let(Tty.reset.to_s, String) + Tty.width + @progress = T.let(nil, T.nilable(String)) + @progress_checked_at = T.let(nil, T.nilable(Time)) + @drawn = T.let(false, T::Boolean) + @at_line_start = T.let(true, T::Boolean) + @interrupted = T.let(false, T::Boolean) + end + + # Copies `input` to `output` until EOF, keeping the status line below it. + sig { params(input: IO, output: T.any(IO, StringIO)).void } + def forward(input, output) + loop do + if input.wait_readable(REDRAW_INTERVAL) + begin + data = input.readpartial(65536) + rescue EOFError, Errno::EIO + break + end + + output.write("#{Tty.move_cursor_beginning}#{Tty.clear_to_end}") if @drawn + output.write(data) + @drawn = false + # Progress is no longer interesting once the build is being interrupted. + @interrupted ||= data.start_with?(INTERRUPT_ECHO) + @at_line_start = data.end_with?("\n") + end + next if @interrupted || !@at_line_start + + output.write("#{Tty.move_cursor_beginning}#{Tty.clear_to_end}#{Tty.truncate(status)}") + @drawn = true + end + end + + # Clears the status line. + sig { params(output: T.any(IO, StringIO)).void } + def finish(output) + return unless @drawn + + output.write("#{Tty.move_cursor_beginning}#{Tty.clear_to_end}") + @drawn = false + end + + sig { returns(String) } + def status + checked_at = @progress_checked_at + if checked_at.nil? || Time.now - checked_at >= LOG_CHECK_INTERVAL + @progress = log_progress + @progress_checked_at = Time.now + end + "#{@spinner_colour}#{@spinner}#{@reset} #{@progress}" + end + + private + + # The step progress in the most recently written log of this build. + sig { returns(T.nilable(String)) } + def log_progress + log = @logs.glob("*.log") + .reject { |path| path.basename.to_s.match?(/\.(?:cc|sandbox)\.log\z/) } + .select { |path| path.mtime >= @start_time } + .max_by(&:mtime) + return if log.nil? + + File.binread(log, LOG_TAIL_SIZE, [log.size - LOG_TAIL_SIZE, 0].max).to_s.lines.reverse_each do |line| + if (match = line.match(STEP_PROGRESS)) + done = match[1].to_i + total = match[2].to_i + return "#{done}/#{total} (#{done * 100 / [total, 1].max}%)" + elsif (match = line.match(PERCENT_PROGRESS)) + return "#{match[1]}%" + end + end + nil + rescue SystemCallError + # The log was removed while reading it. + nil + end +end diff --git a/Library/Homebrew/formula_installer.rb b/Library/Homebrew/formula_installer.rb index b0c350baf3605..d62b28f940b5e 100644 --- a/Library/Homebrew/formula_installer.rb +++ b/Library/Homebrew/formula_installer.rb @@ -1256,6 +1256,7 @@ def add_build_sandbox_rules(sandbox, formula_path, log_name:) sandbox.allow_read_if_exists path: Homebrew::Trust.trust_file formula.logs.mkpath sandbox.record_log(formula.logs/"#{log_name}.sandbox.log") + sandbox.show_build_progress(formula.logs) if !verbose? && !debug? && !interactive? sandbox.allow_write_log(formula) sandbox.allow_cvs sandbox.allow_fossil diff --git a/Library/Homebrew/sandbox.rb b/Library/Homebrew/sandbox.rb index 5144a5fb7dde7..440ef57dbf2d0 100644 --- a/Library/Homebrew/sandbox.rb +++ b/Library/Homebrew/sandbox.rb @@ -7,6 +7,7 @@ require "tempfile" require "system_command" require "exceptions" +require "build_progress" require "mktemp" require "utils/fork" require "utils/output" @@ -377,6 +378,7 @@ def initialize @failed = T.let(false, T::Boolean) @logfile = T.let(nil, T.nilable(T.any(String, Pathname))) @start = T.let(nil, T.nilable(Time)) + @build_progress = T.let(nil, T.nilable(BuildProgress)) end sig { params(file: T.any(String, Pathname)).void } @@ -384,6 +386,12 @@ def record_log(file) @logfile = file end + # Show a spinner, with any step progress from the build logs, below the output. + sig { params(logs: Pathname).void } + def show_build_progress(logs) + @build_progress = BuildProgress.new(logs) if BuildProgress.tty? + end + sig { params(allow: T::Boolean, operation: String, filter: T.nilable(SandboxPathFilter), modifier: T.nilable(String)).void @@ -797,6 +805,7 @@ def run(*args, passthrough_stdin: true, child_message_handler: nil, retain_tmp: ensure stdin_thread&.kill stdout_thread&.kill + @build_progress&.finish($stdout) trap(:TTIN, old_ttin) trap(:WINCH, old_winch) end @@ -867,7 +876,11 @@ def path_filter(path, type) sig { params(controller: IO).void } def copy_pty_output(controller) - controller.each_char { |c| print(c) } + if (build_progress = @build_progress) + build_progress.forward(controller, $stdout) + else + controller.each_char { |c| print(c) } + end rescue Errno::EIO # Linux marks a PTY as an I/O error when its peer closes, so treat this as EOF: # https://github.com/torvalds/linux/blob/master/drivers/tty/pty.c diff --git a/Library/Homebrew/test/build_progress_spec.rb b/Library/Homebrew/test/build_progress_spec.rb new file mode 100644 index 0000000000000..c86ec083ed9cb --- /dev/null +++ b/Library/Homebrew/test/build_progress_spec.rb @@ -0,0 +1,75 @@ +# typed: strict +# frozen_string_literal: true + +require "build_progress" + +RSpec.describe BuildProgress do + sig { returns(BuildProgress) } + subject(:build_progress) { described_class.new(logs) } + + sig { returns(Pathname) } + let(:logs) { mktmpdir } + + before { allow(Time).to receive(:now).and_return(Time.at(1_000_000)) } + + describe "#forward" do + sig { params(chunks: String).returns(String) } + def forwarded(*chunks) + input, input_writer = IO.pipe + output_reader, output = IO.pipe + writer = Thread.new do + chunks.each do |chunk| + input_writer.write(chunk) + sleep 0.2 + end + input_writer.close + end + build_progress.forward(input, output) + build_progress.finish(output) + writer.join + output.close + output_reader.read + end + + it "draws the spinner below the output" do + expect(forwarded("==> make\n")).to match(/==> make\n\e\[0G\e\[K⠋ /) + end + + it "clears the status line when finished" do + expect(forwarded("==> make\n")).to end_with("\e[0G\e[K") + end + + it "stops drawing once Ctrl-C is echoed" do + output = forwarded("==> make\n", "^C", "One sec, cleaning up...\n") + expect(output).to end_with("\e[0G\e[K^COne sec, cleaning up...\n") + end + end + + describe "#status" do + it "shows only a spinner without a build log" do + expect(build_progress.status).to eq("⠋ ") + end + + it "shows Ninja step progress from the newest build log" do + (logs/"01.cmake.log").write("[1708/9135] /usr/bin/clang -c foo.cpp\nfoo.cpp:1:1: warning: [-Wfoo]\n") + expect(build_progress.status).to eq("⠋ 1708/9135 (18%)") + end + + it "shows CMake Makefile percentage progress" do + (logs/"01.make.log").write("[ 7%] Building CXX object foo.o\n") + expect(build_progress.status).to eq("⠋ 7%") + end + + it "ignores compiler wrapper logs" do + (logs/"01.cmake.log").write("[1/2] /usr/bin/clang -c foo.cpp\n") + (logs/"01.cmake.cc.log").write("superenv executed: clang -c foo.cpp\n") + expect(build_progress.status).to eq("⠋ 1/2 (50%)") + end + + it "ignores logs from before the build started" do + (logs/"01.cmake.log").write("[1/2] /usr/bin/clang -c foo.cpp\n") + (logs/"01.cmake.log").utime(Time.at(0), Time.at(0)) + expect(build_progress.status).to eq("⠋ ") + end + end +end diff --git a/Library/Homebrew/test/formula_installer_spec.rb b/Library/Homebrew/test/formula_installer_spec.rb index b60f27bec14ea..b3c71119f2f4b 100644 --- a/Library/Homebrew/test/formula_installer_spec.rb +++ b/Library/Homebrew/test/formula_installer_spec.rb @@ -2237,7 +2237,7 @@ def fetch; end allow(sandbox).to receive_messages(record_log: nil, allow_read_if_exists: nil, allow_write_temp_and_cache: nil, allow_write_log: nil, allow_cvs: nil, allow_fossil: nil, allow_write_xcode: nil, allow_write_cellar: nil, deny_read_home: nil, - protect_homebrew_state: nil, run: nil) + protect_homebrew_state: nil, show_build_progress: nil, run: nil) allow(formula).to receive_messages(logs: mktmpdir, update_head_version: nil, prefix: mktmpdir, network_access_allowed?: true) allow(Keg).to receive(:new).and_return(instance_double(Keg, empty_installation?: false)) diff --git a/Library/Homebrew/test/sandbox_shared_spec.rb b/Library/Homebrew/test/sandbox_shared_spec.rb index be009cc8be78e..75ba9533c87fe 100644 --- a/Library/Homebrew/test/sandbox_shared_spec.rb +++ b/Library/Homebrew/test/sandbox_shared_spec.rb @@ -566,6 +566,27 @@ expect { sandbox.copy_pty_output(controller) }.not_to raise_error end + + it "treats a PTY EIO as EOF when showing build progress" do + allow(BuildProgress).to receive(:tty?).and_return(true) + sandbox.show_build_progress(mktmpdir) + controller = instance_double(IO) + allow(controller).to receive(:wait_readable).and_return(controller) + allow(controller).to receive(:readpartial).and_raise(Errno::EIO) + + expect { sandbox.copy_pty_output(controller) }.not_to raise_error + end + + it "draws the build progress below the output when shown" do + allow(Time).to receive(:now).and_return(Time.at(0)) + allow(BuildProgress).to receive(:tty?).and_return(true) + sandbox.show_build_progress(mktmpdir) + controller, writer = IO.pipe + writer.write("foo\n") + writer.close + + expect { sandbox.copy_pty_output(controller) }.to output("foo\n\e[0G\e[K⠋ ").to_stdout + end end describe "::failure_reason" do diff --git a/Library/Homebrew/test/sandbox_spec.rb b/Library/Homebrew/test/sandbox_spec.rb index 626a50672ebff..b6b04e40e7256 100644 --- a/Library/Homebrew/test/sandbox_spec.rb +++ b/Library/Homebrew/test/sandbox_spec.rb @@ -167,6 +167,15 @@ expect(file).to exist end + it "shows build progress below the output" do + allow(BuildProgress).to receive(:tty?).and_return(true) + sandbox.show_build_progress(dir) + spinner = /[#{Homebrew::DownloadQueue::Spinner::FRAMES.join}]/ + + expect { sandbox.run "/bin/sh", "-c", "echo foo; sleep 0.3" } + .to output(/foo\r\n\e\[0G\e\[K#{spinner} /).to_stdout + end + it "writes to a path containing the seatbelt string delimiters \\ and \"" do delimiter_dir = dir/"I:\\ and \"quote\"" delimiter_dir.mkpath