From 85bd4c7e1fa560db504f6ccd4ea2e6814c740421 Mon Sep 17 00:00:00 2001 From: apainintheneck Date: Mon, 11 Sep 2023 21:54:27 -0700 Subject: [PATCH] utils/backtrace: scrub sorbet-runtime from backtrace Ever since we started using this at runtime it's been polluting the backtrace output. This makes it harder to debug errors and increases the amount of info users have to paste into the box when filing an issue. This is a very direct approach. Essentially, we strip out everything related to the `sorbet-runtime` gem whenever the top line in the backtrace is unrelated to sorbet-runtime. The hope is that this will allow errors related to sorbet to be diagnosed easily while also reducing the backtrace size for all other types of errors. Sometimes it is useful to see the full backtrace though. For those cases, we include the full backtrace when `--verbose` is passed in and print a warning that the Sorbet lines have been removed from the backtrace the first time they are removed. Note: This requires gems to be set up so that the call to `Gem.paths.home` works correctly. For that reason, it must be included after `utils/gems` which is included in `standalone/load_path` already. --- Library/Homebrew/brew.rb | 8 +- Library/Homebrew/cask/audit.rb | 2 +- Library/Homebrew/cmd/install.rb | 2 +- Library/Homebrew/cmd/update-report.rb | 4 +- Library/Homebrew/dev-cmd/test.rb | 2 +- Library/Homebrew/formula_installer.rb | 10 +-- Library/Homebrew/formula_versions.rb | 2 +- Library/Homebrew/livecheck/livecheck.rb | 4 +- Library/Homebrew/migrator.rb | 4 +- Library/Homebrew/test/utils/backtrace_spec.rb | 90 +++++++++++++++++++ Library/Homebrew/utils.rb | 1 + Library/Homebrew/utils/backtrace.rb | 36 ++++++++ Library/Homebrew/utils/repology.rb | 2 +- 13 files changed, 147 insertions(+), 20 deletions(-) create mode 100644 Library/Homebrew/test/utils/backtrace_spec.rb create mode 100644 Library/Homebrew/utils/backtrace.rb diff --git a/Library/Homebrew/brew.rb b/Library/Homebrew/brew.rb index 6f185bc216..2d7854e35d 100644 --- a/Library/Homebrew/brew.rb +++ b/Library/Homebrew/brew.rb @@ -141,7 +141,7 @@ rescue UsageError => e Homebrew::Help.help cmd, remaining_args: args.remaining, usage_error: e.message rescue SystemExit => e onoe "Kernel.exit" if args.debug? && !e.success? - $stderr.puts e.backtrace if args.debug? + $stderr.puts Utils::Backtrace.clean(e) if args.debug? raise rescue Interrupt $stderr.puts # seemingly a newline is typical @@ -175,7 +175,7 @@ rescue RuntimeError, SystemCallError => e raise if e.message.empty? onoe e - $stderr.puts e.backtrace if args.debug? + $stderr.puts Utils::Backtrace.clean(e) if args.debug? exit 1 rescue MethodDeprecatedError => e @@ -184,7 +184,7 @@ rescue MethodDeprecatedError => e $stderr.puts "If reporting this issue please do so at (not Homebrew/brew or Homebrew/homebrew-core):" $stderr.puts " #{Formatter.url(e.issues_url)}" end - $stderr.puts e.backtrace if args.debug? + $stderr.puts Utils::Backtrace.clean(e) if args.debug? exit 1 rescue Exception => e # rubocop:disable Lint/RescueException onoe e @@ -196,7 +196,7 @@ rescue Exception => e # rubocop:disable Lint/RescueException $stderr.puts " #{Formatter.url(OS::ISSUES_URL)}" end end - $stderr.puts e.backtrace + $stderr.puts Utils::Backtrace.clean(e) exit 1 else exit 1 if Homebrew.failed? diff --git a/Library/Homebrew/cask/audit.rb b/Library/Homebrew/cask/audit.rb index f73f8ec44f..7c0a8a6ace 100644 --- a/Library/Homebrew/cask/audit.rb +++ b/Library/Homebrew/cask/audit.rb @@ -62,7 +62,7 @@ module Cask self rescue => e - odebug e, e.backtrace + odebug e, ::Utils::Backtrace.clean(e) add_error "exception while auditing #{cask}: #{e.message}" self end diff --git a/Library/Homebrew/cmd/install.rb b/Library/Homebrew/cmd/install.rb index bee5413080..d5cc5726be 100644 --- a/Library/Homebrew/cmd/install.rb +++ b/Library/Homebrew/cmd/install.rb @@ -339,7 +339,7 @@ module Homebrew # Need to rescue before `FormulaUnavailableError` (superclass of this) # is handled, as searching for a formula doesn't make sense here (the # formula was found, but there's a problem with its implementation). - $stderr.puts e.backtrace if Homebrew::EnvConfig.developer? + $stderr.puts Utils::Backtrace.clean(e) if Homebrew::EnvConfig.developer? ofail e.message rescue FormulaOrCaskUnavailableError, Cask::CaskUnavailableError => e Homebrew.failed = true diff --git a/Library/Homebrew/cmd/update-report.rb b/Library/Homebrew/cmd/update-report.rb index 64b4a16b8f..b5fd1544de 100644 --- a/Library/Homebrew/cmd/update-report.rb +++ b/Library/Homebrew/cmd/update-report.rb @@ -175,7 +175,7 @@ module Homebrew begin reporter = Reporter.new(tap) rescue Reporter::ReporterRevisionUnsetError => e - onoe "#{e.message}\n#{e.backtrace&.join("\n")}" if Homebrew::EnvConfig.developer? + onoe "#{e.message}\n#{Utils::Backtrace.clean(e)&.join("\n")}" if Homebrew::EnvConfig.developer? next end if reporter.updated? @@ -629,7 +629,7 @@ class Reporter system HOMEBREW_BREW_FILE, "link", new_full_name, "--overwrite" end rescue Exception => e # rubocop:disable Lint/RescueException - onoe "#{e.message}\n#{e.backtrace&.join("\n")}" if Homebrew::EnvConfig.developer? + onoe "#{e.message}\n#{Utils::Backtrace.clean(e)&.join("\n")}" if Homebrew::EnvConfig.developer? end next end diff --git a/Library/Homebrew/dev-cmd/test.rb b/Library/Homebrew/dev-cmd/test.rb index 9bd1664437..a041b282df 100644 --- a/Library/Homebrew/dev-cmd/test.rb +++ b/Library/Homebrew/dev-cmd/test.rb @@ -105,7 +105,7 @@ module Homebrew rescue Exception => e # rubocop:disable Lint/RescueException retry if retry_test?(f, args: args) ofail "#{f.full_name}: failed" - $stderr.puts e, e.backtrace + $stderr.puts e, Utils::Backtrace.clean(e) ensure ENV.replace(env) end diff --git a/Library/Homebrew/formula_installer.rb b/Library/Homebrew/formula_installer.rb index c6e457045d..d4a797e924 100644 --- a/Library/Homebrew/formula_installer.rb +++ b/Library/Homebrew/formula_installer.rb @@ -1025,7 +1025,7 @@ on_request: installed_on_request?, options: options) ofail "An unexpected error occurred during the `brew link` step" puts "The formula built, but is not symlinked into #{HOMEBREW_PREFIX}" puts e - puts e.backtrace if debug? + puts Utils::Backtrace.clean(e) if debug? @show_summary_heading = true ignore_interrupts do keg.unlink @@ -1081,7 +1081,7 @@ on_request: installed_on_request?, options: options) rescue Exception => e # rubocop:disable Lint/RescueException puts e ofail "Failed to install service files" - odebug e, e.backtrace + odebug e, Utils::Backtrace.clean(e) end sig { params(keg: Keg).void } @@ -1091,7 +1091,7 @@ on_request: installed_on_request?, options: options) ofail "Failed to fix install linkage" puts "The formula built, but you may encounter issues using it or linking other" puts "formulae against it." - odebug e, e.backtrace + odebug e, Utils::Backtrace.clean(e) @show_summary_heading = true end @@ -1102,7 +1102,7 @@ on_request: installed_on_request?, options: options) rescue Exception => e # rubocop:disable Lint/RescueException opoo "The cleaning step did not complete successfully" puts "Still, the installation was successful, so we will link it into your prefix." - odebug e, e.backtrace + odebug e, Utils::Backtrace.clean(e) Homebrew.failed = true @show_summary_heading = true end @@ -1171,7 +1171,7 @@ on_request: installed_on_request?, options: options) opoo "The post-install step did not complete successfully" puts "You can try again using:" puts " brew postinstall #{formula.full_name}" - odebug e, e.backtrace, always_display: Homebrew::EnvConfig.developer? + odebug e, Utils::Backtrace.clean(e), always_display: Homebrew::EnvConfig.developer? Homebrew.failed = true @show_summary_heading = true end diff --git a/Library/Homebrew/formula_versions.rb b/Library/Homebrew/formula_versions.rb index bd03f399d5..89362b88fe 100644 --- a/Library/Homebrew/formula_versions.rb +++ b/Library/Homebrew/formula_versions.rb @@ -57,7 +57,7 @@ class FormulaVersions rescue *IGNORED_EXCEPTIONS => e # We rescue these so that we can skip bad versions and # continue walking the history - odebug "#{e} in #{name} at revision #{revision}", e.backtrace + odebug "#{e} in #{name} at revision #{revision}", Utils::Backtrace.clean(e) rescue FormulaUnavailableError nil ensure diff --git a/Library/Homebrew/livecheck/livecheck.rb b/Library/Homebrew/livecheck/livecheck.rb index 87114521df..4fdf33f457 100644 --- a/Library/Homebrew/livecheck/livecheck.rb +++ b/Library/Homebrew/livecheck/livecheck.rb @@ -391,7 +391,7 @@ module Homebrew name += " (cask)" if ambiguous_casks.include?(formula_or_cask) onoe "#{Tty.blue}#{name}#{Tty.reset}: #{e}" - $stderr.puts e.backtrace if debug && !e.is_a?(Livecheck::Error) + $stderr.puts Utils::Backtrace.clean(e) if debug && !e.is_a?(Livecheck::Error) print_resources_info(resource_version_info, verbose: verbose) if check_for_resources nil end @@ -1016,7 +1016,7 @@ module Homebrew status_hash(resource, "error", [e.to_s], verbose: verbose) elsif !quiet onoe "#{Tty.blue}#{resource.name}#{Tty.reset}: #{e}" - $stderr.puts e.backtrace if debug && !e.is_a?(Livecheck::Error) + $stderr.puts Utils::Backtrace.clean(e) if debug && !e.is_a?(Livecheck::Error) nil end end diff --git a/Library/Homebrew/migrator.rb b/Library/Homebrew/migrator.rb index 507ad794c4..03dc043be8 100644 --- a/Library/Homebrew/migrator.rb +++ b/Library/Homebrew/migrator.rb @@ -228,7 +228,7 @@ class Migrator rescue Exception => e # rubocop:disable Lint/RescueException onoe "The migration did not complete successfully." puts e - puts e.backtrace if debug? + puts Utils::Backtrace.clean(e) if debug? puts "Backing up..." ignore_interrupts { backup_oldname } ensure @@ -358,7 +358,7 @@ class Migrator rescue Exception => e # rubocop:disable Lint/RescueException onoe "An unexpected error occurred during linking" puts e - puts e.backtrace if debug? + puts Utils::Backtrace.clean(e) if debug? ignore_interrupts { new_keg.unlink(verbose: verbose?) } raise end diff --git a/Library/Homebrew/test/utils/backtrace_spec.rb b/Library/Homebrew/test/utils/backtrace_spec.rb new file mode 100644 index 0000000000..3757c38da2 --- /dev/null +++ b/Library/Homebrew/test/utils/backtrace_spec.rb @@ -0,0 +1,90 @@ +# frozen_string_literal: true + +require "utils/backtrace" + +describe Utils::Backtrace do + let(:backtrace_no_sorbet_paths) do + [ + "/Library/Homebrew/downloadable.rb:75:in", + "/Library/Homebrew/downloadable.rb:50:in", + "/Library/Homebrew/cmd/fetch.rb:236:in", + "/Library/Homebrew/cmd/fetch.rb:201:in", + "/Library/Homebrew/cmd/fetch.rb:178:in", + "/Library/Homebrew/simulate_system.rb:29:in", + "/Library/Homebrew/cmd/fetch.rb:166:in", + "/Library/Homebrew/cmd/fetch.rb:163:in", + "/Library/Homebrew/cmd/fetch.rb:163:in", + "/Library/Homebrew/cmd/fetch.rb:94:in", + "/Library/Homebrew/cmd/fetch.rb:94:in", + "/Library/Homebrew/brew.rb:94:in", + ] + end + + let(:backtrace_with_sorbet_paths) do + [ + "/Library/Homebrew/downloadable.rb:75:in", + "/Library/Homebrew/vendor/bundle/ruby/2.6.0/gems/sorbet-runtime-0.5.10461/lib/call_validation.rb:157:in", + "/Library/Homebrew/vendor/bundle/ruby/2.6.0/gems/sorbet-runtime-0.5.10461/lib/call_validation.rb:157:in", + "/Library/Homebrew/vendor/bundle/ruby/2.6.0/gems/sorbet-runtime-0.5.10461/lib/_methods.rb:270:in", + "/Library/Homebrew/downloadable.rb:50:in", + "/Library/Homebrew/vendor/bundle/ruby/2.6.0/gems/sorbet-runtime-0.5.10461/lib/call_validation.rb:157:in", + "/Library/Homebrew/vendor/bundle/ruby/2.6.0/gems/sorbet-runtime-0.5.10461/lib/call_validation.rb:157:in", + "/Library/Homebrew/vendor/bundle/ruby/2.6.0/gems/sorbet-runtime-0.5.10461/lib/_methods.rb:270:in", + "/Library/Homebrew/cmd/fetch.rb:236:in", + "/Library/Homebrew/cmd/fetch.rb:201:in", + "/Library/Homebrew/cmd/fetch.rb:178:in", + "/Library/Homebrew/simulate_system.rb:29:in", + "/Library/Homebrew/vendor/bundle/ruby/2.6.0/gems/sorbet-runtime-0.5.10461/lib/call_validation.rb:157:in", + "/Library/Homebrew/vendor/bundle/ruby/2.6.0/gems/sorbet-runtime-0.5.10461/lib/call_validation.rb:157:in", + "/Library/Homebrew/vendor/bundle/ruby/2.6.0/gems/sorbet-runtime-0.5.10461/lib/_methods.rb:270:in", + "/Library/Homebrew/cmd/fetch.rb:166:in", + "/Library/Homebrew/cmd/fetch.rb:163:in", + "/Library/Homebrew/cmd/fetch.rb:163:in", + "/Library/Homebrew/cmd/fetch.rb:94:in", + "/Library/Homebrew/cmd/fetch.rb:94:in", + "/Library/Homebrew/brew.rb:94:in", + ] + end + + let(:backtrace_with_sorbet_error) do + backtrace_with_sorbet_paths.drop(1) + end + + def exception_with(backtrace:) + exception = StandardError.new + exception.set_backtrace(backtrace) if backtrace + exception + end + + before do + allow(described_class).to receive(:sorbet_runtime_path) + .and_return("/Library/Homebrew/vendor/bundle/ruby/2.6.0/gems/sorbet-runtime") + allow(Context).to receive(:current).and_return(Context::ContextStruct.new(verbose: false)) + end + + it "handles nil backtrace" do + exception = exception_with backtrace: nil + expect(described_class.clean(exception)).to be_nil + end + + it "handles empty array backtrace" do + exception = exception_with backtrace: [] + expect(described_class.clean(exception)).to eq [] + end + + it "removes sorbet paths when top error is not from sorbet" do + exception = exception_with backtrace: backtrace_with_sorbet_paths + expect(described_class.clean(exception)).to eq backtrace_no_sorbet_paths + end + + it "includes sorbet paths when top error is not from sorbet and verbose is set" do + allow(Context).to receive(:current).and_return(Context::ContextStruct.new(verbose: true)) + exception = exception_with backtrace: backtrace_with_sorbet_paths + expect(described_class.clean(exception)).to eq backtrace_with_sorbet_paths + end + + it "doesn't change backtrace when error is from sorbet" do + exception = exception_with backtrace: backtrace_with_sorbet_error + expect(described_class.clean(exception)).to eq backtrace_with_sorbet_error + end +end diff --git a/Library/Homebrew/utils.rb b/Library/Homebrew/utils.rb index e685e1e20b..e2958fb775 100644 --- a/Library/Homebrew/utils.rb +++ b/Library/Homebrew/utils.rb @@ -4,6 +4,7 @@ require "time" require "utils/analytics" +require "utils/backtrace" require "utils/curl" require "utils/fork" require "utils/formatter" diff --git a/Library/Homebrew/utils/backtrace.rb b/Library/Homebrew/utils/backtrace.rb new file mode 100644 index 0000000000..3030422722 --- /dev/null +++ b/Library/Homebrew/utils/backtrace.rb @@ -0,0 +1,36 @@ +# typed: true +# frozen_string_literal: true + +module Utils + module Backtrace + # Cleans `sorbet-runtime` gem paths from the backtrace unless... + # 1. `verbose` is set + # 2. first backtrace line starts with `sorbet-runtime` + # - This implies that the error is related to Sorbet. + sig { params(error: Exception).returns(T.nilable(T::Array[String])) } + def self.clean(error) + backtrace = error.backtrace + + return backtrace if Context.current.verbose? + return backtrace if backtrace.blank? + return backtrace if backtrace.fetch(0).start_with?(sorbet_runtime_path) + + old_backtrace_length = backtrace.length + backtrace.reject { |line| line.start_with?(sorbet_runtime_path) } + .tap { |new_backtrace| print_backtrace_message if old_backtrace_length > new_backtrace.length } + end + + def self.sorbet_runtime_path + @sorbet_runtime_path ||= "#{Gem.paths.home}/gems/sorbet-runtime" + end + + def self.print_backtrace_message + return if @print_backtrace_message + + opoo "Removed Sorbet lines from backtrace!" + puts "Rerun with --verbose to see the original backtrace" unless Homebrew::EnvConfig.no_env_hints? + + @print_backtrace_message = true + end + end +end diff --git a/Library/Homebrew/utils/repology.rb b/Library/Homebrew/utils/repology.rb index 15d11a93fd..1493873794 100644 --- a/Library/Homebrew/utils/repology.rb +++ b/Library/Homebrew/utils/repology.rb @@ -38,7 +38,7 @@ module Repology data = JSON.parse(output) { name => data } rescue => e - error_output = [errors, "#{e.class}: #{e}", e.backtrace].compact + error_output = [errors, "#{e.class}: #{e}", Utils::Backtrace.clean(e)].compact if Homebrew::EnvConfig.developer? $stderr.puts(*error_output) else