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 6f185bc216eb4..2d7854e35d5b1 100644 --- a/Library/Homebrew/brew.rb +++ b/Library/Homebrew/brew.rb @@ -141,7 +141,7 @@ 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 @@ 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 @@ $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 @@ $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 f73f8ec44f106..7c0a8a6ace814 100644 --- a/Library/Homebrew/cask/audit.rb +++ b/Library/Homebrew/cask/audit.rb @@ -62,7 +62,7 @@ def run! 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 bee541308044c..d5cc5726be78f 100644 --- a/Library/Homebrew/cmd/install.rb +++ b/Library/Homebrew/cmd/install.rb @@ -339,7 +339,7 @@ def self.install # 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 64b4a16b8fff0..b5fd1544de49a 100644 --- a/Library/Homebrew/cmd/update-report.rb +++ b/Library/Homebrew/cmd/update-report.rb @@ -175,7 +175,7 @@ def output_update_report 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 @@ def migrate_tap_migration 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 9bd16644372c0..a041b282df56d 100644 --- a/Library/Homebrew/dev-cmd/test.rb +++ b/Library/Homebrew/dev-cmd/test.rb @@ -105,7 +105,7 @@ def test 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 c6e457045df2d..d4a797e92474a 100644 --- a/Library/Homebrew/formula_installer.rb +++ b/Library/Homebrew/formula_installer.rb @@ -1025,7 +1025,7 @@ def link(keg) 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 @@ def install_service 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 @@ def fix_dynamic_linkage(keg) 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 @@ def clean 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 @@ def post_install 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 bd03f399d57b8..89362b88fe13c 100644 --- a/Library/Homebrew/formula_versions.rb +++ b/Library/Homebrew/formula_versions.rb @@ -57,7 +57,7 @@ def formula_at_revision(revision, formula_relative_path = relative_path, &_block 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 87114521df78f..4fdf33f4576c4 100644 --- a/Library/Homebrew/livecheck/livecheck.rb +++ b/Library/Homebrew/livecheck/livecheck.rb @@ -391,7 +391,7 @@ def run_checks( 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 @@ def resource_version( 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 507ad794c45c3..03dc043be881e 100644 --- a/Library/Homebrew/migrator.rb +++ b/Library/Homebrew/migrator.rb @@ -228,7 +228,7 @@ def migrate 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 @@ def link_newname 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 0000000000000..3757c38da234b --- /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 e685e1e20b557..e2958fb775243 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 0000000000000..303042272239c --- /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 15d11a93fd547..1493873794a6d 100644 --- a/Library/Homebrew/utils/repology.rb +++ b/Library/Homebrew/utils/repology.rb @@ -38,7 +38,7 @@ def self.single_package_query(name, repository:) 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