Show a build progress spinner

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

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

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,13 +378,20 @@ 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 }
   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

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

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))

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

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