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.
This commit is contained in:
apainintheneck 2023-09-11 21:54:27 -07:00
parent aa2a77b1f1
commit 85bd4c7e1f
13 changed files with 147 additions and 20 deletions

View File

@ -141,7 +141,7 @@ rescue UsageError => e
Homebrew::Help.help cmd, remaining_args: args.remaining, usage_error: e.message Homebrew::Help.help cmd, remaining_args: args.remaining, usage_error: e.message
rescue SystemExit => e rescue SystemExit => e
onoe "Kernel.exit" if args.debug? && !e.success? 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 raise
rescue Interrupt rescue Interrupt
$stderr.puts # seemingly a newline is typical $stderr.puts # seemingly a newline is typical
@ -175,7 +175,7 @@ rescue RuntimeError, SystemCallError => e
raise if e.message.empty? raise if e.message.empty?
onoe e onoe e
$stderr.puts e.backtrace if args.debug? $stderr.puts Utils::Backtrace.clean(e) if args.debug?
exit 1 exit 1
rescue MethodDeprecatedError => e 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 "If reporting this issue please do so at (not Homebrew/brew or Homebrew/homebrew-core):"
$stderr.puts " #{Formatter.url(e.issues_url)}" $stderr.puts " #{Formatter.url(e.issues_url)}"
end end
$stderr.puts e.backtrace if args.debug? $stderr.puts Utils::Backtrace.clean(e) if args.debug?
exit 1 exit 1
rescue Exception => e # rubocop:disable Lint/RescueException rescue Exception => e # rubocop:disable Lint/RescueException
onoe e onoe e
@ -196,7 +196,7 @@ rescue Exception => e # rubocop:disable Lint/RescueException
$stderr.puts " #{Formatter.url(OS::ISSUES_URL)}" $stderr.puts " #{Formatter.url(OS::ISSUES_URL)}"
end end
end end
$stderr.puts e.backtrace $stderr.puts Utils::Backtrace.clean(e)
exit 1 exit 1
else else
exit 1 if Homebrew.failed? exit 1 if Homebrew.failed?

View File

@ -62,7 +62,7 @@ module Cask
self self
rescue => e rescue => e
odebug e, e.backtrace odebug e, ::Utils::Backtrace.clean(e)
add_error "exception while auditing #{cask}: #{e.message}" add_error "exception while auditing #{cask}: #{e.message}"
self self
end end

View File

@ -339,7 +339,7 @@ module Homebrew
# Need to rescue before `FormulaUnavailableError` (superclass of this) # Need to rescue before `FormulaUnavailableError` (superclass of this)
# is handled, as searching for a formula doesn't make sense here (the # is handled, as searching for a formula doesn't make sense here (the
# formula was found, but there's a problem with its implementation). # 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 ofail e.message
rescue FormulaOrCaskUnavailableError, Cask::CaskUnavailableError => e rescue FormulaOrCaskUnavailableError, Cask::CaskUnavailableError => e
Homebrew.failed = true Homebrew.failed = true

View File

@ -175,7 +175,7 @@ module Homebrew
begin begin
reporter = Reporter.new(tap) reporter = Reporter.new(tap)
rescue Reporter::ReporterRevisionUnsetError => e 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 next
end end
if reporter.updated? if reporter.updated?
@ -629,7 +629,7 @@ class Reporter
system HOMEBREW_BREW_FILE, "link", new_full_name, "--overwrite" system HOMEBREW_BREW_FILE, "link", new_full_name, "--overwrite"
end end
rescue Exception => e # rubocop:disable Lint/RescueException 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 end
next next
end end

View File

@ -105,7 +105,7 @@ module Homebrew
rescue Exception => e # rubocop:disable Lint/RescueException rescue Exception => e # rubocop:disable Lint/RescueException
retry if retry_test?(f, args: args) retry if retry_test?(f, args: args)
ofail "#{f.full_name}: failed" ofail "#{f.full_name}: failed"
$stderr.puts e, e.backtrace $stderr.puts e, Utils::Backtrace.clean(e)
ensure ensure
ENV.replace(env) ENV.replace(env)
end end

View File

@ -1025,7 +1025,7 @@ on_request: installed_on_request?, options: options)
ofail "An unexpected error occurred during the `brew link` step" ofail "An unexpected error occurred during the `brew link` step"
puts "The formula built, but is not symlinked into #{HOMEBREW_PREFIX}" puts "The formula built, but is not symlinked into #{HOMEBREW_PREFIX}"
puts e puts e
puts e.backtrace if debug? puts Utils::Backtrace.clean(e) if debug?
@show_summary_heading = true @show_summary_heading = true
ignore_interrupts do ignore_interrupts do
keg.unlink keg.unlink
@ -1081,7 +1081,7 @@ on_request: installed_on_request?, options: options)
rescue Exception => e # rubocop:disable Lint/RescueException rescue Exception => e # rubocop:disable Lint/RescueException
puts e puts e
ofail "Failed to install service files" ofail "Failed to install service files"
odebug e, e.backtrace odebug e, Utils::Backtrace.clean(e)
end end
sig { params(keg: Keg).void } sig { params(keg: Keg).void }
@ -1091,7 +1091,7 @@ on_request: installed_on_request?, options: options)
ofail "Failed to fix install linkage" ofail "Failed to fix install linkage"
puts "The formula built, but you may encounter issues using it or linking other" puts "The formula built, but you may encounter issues using it or linking other"
puts "formulae against it." puts "formulae against it."
odebug e, e.backtrace odebug e, Utils::Backtrace.clean(e)
@show_summary_heading = true @show_summary_heading = true
end end
@ -1102,7 +1102,7 @@ on_request: installed_on_request?, options: options)
rescue Exception => e # rubocop:disable Lint/RescueException rescue Exception => e # rubocop:disable Lint/RescueException
opoo "The cleaning step did not complete successfully" opoo "The cleaning step did not complete successfully"
puts "Still, the installation was successful, so we will link it into your prefix." 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 Homebrew.failed = true
@show_summary_heading = true @show_summary_heading = true
end end
@ -1171,7 +1171,7 @@ on_request: installed_on_request?, options: options)
opoo "The post-install step did not complete successfully" opoo "The post-install step did not complete successfully"
puts "You can try again using:" puts "You can try again using:"
puts " brew postinstall #{formula.full_name}" 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 Homebrew.failed = true
@show_summary_heading = true @show_summary_heading = true
end end

View File

@ -57,7 +57,7 @@ class FormulaVersions
rescue *IGNORED_EXCEPTIONS => e rescue *IGNORED_EXCEPTIONS => e
# We rescue these so that we can skip bad versions and # We rescue these so that we can skip bad versions and
# continue walking the history # 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 rescue FormulaUnavailableError
nil nil
ensure ensure

View File

@ -391,7 +391,7 @@ module Homebrew
name += " (cask)" if ambiguous_casks.include?(formula_or_cask) name += " (cask)" if ambiguous_casks.include?(formula_or_cask)
onoe "#{Tty.blue}#{name}#{Tty.reset}: #{e}" 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 print_resources_info(resource_version_info, verbose: verbose) if check_for_resources
nil nil
end end
@ -1016,7 +1016,7 @@ module Homebrew
status_hash(resource, "error", [e.to_s], verbose: verbose) status_hash(resource, "error", [e.to_s], verbose: verbose)
elsif !quiet elsif !quiet
onoe "#{Tty.blue}#{resource.name}#{Tty.reset}: #{e}" 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 nil
end end
end end

View File

@ -228,7 +228,7 @@ class Migrator
rescue Exception => e # rubocop:disable Lint/RescueException rescue Exception => e # rubocop:disable Lint/RescueException
onoe "The migration did not complete successfully." onoe "The migration did not complete successfully."
puts e puts e
puts e.backtrace if debug? puts Utils::Backtrace.clean(e) if debug?
puts "Backing up..." puts "Backing up..."
ignore_interrupts { backup_oldname } ignore_interrupts { backup_oldname }
ensure ensure
@ -358,7 +358,7 @@ class Migrator
rescue Exception => e # rubocop:disable Lint/RescueException rescue Exception => e # rubocop:disable Lint/RescueException
onoe "An unexpected error occurred during linking" onoe "An unexpected error occurred during linking"
puts e puts e
puts e.backtrace if debug? puts Utils::Backtrace.clean(e) if debug?
ignore_interrupts { new_keg.unlink(verbose: verbose?) } ignore_interrupts { new_keg.unlink(verbose: verbose?) }
raise raise
end end

View File

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

View File

@ -4,6 +4,7 @@
require "time" require "time"
require "utils/analytics" require "utils/analytics"
require "utils/backtrace"
require "utils/curl" require "utils/curl"
require "utils/fork" require "utils/fork"
require "utils/formatter" require "utils/formatter"

View File

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

View File

@ -38,7 +38,7 @@ module Repology
data = JSON.parse(output) data = JSON.parse(output)
{ name => data } { name => data }
rescue => e 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? if Homebrew::EnvConfig.developer?
$stderr.puts(*error_output) $stderr.puts(*error_output)
else else