utils/backtrace: scrub sorbet-runtime from backtrace #16014

apainintheneck · 2023-09-19T04:09:26Z

Have you followed the guidelines in our Contributing document?
Have you checked to ensure there aren't other open Pull Requests for the same change?
Have you added an explanation of what your changes do and why you'd like us to include them?
Have you written new tests for your changes? Here's an example.
Have you successfully run brew style with your changes locally?
Have you successfully run brew typecheck with your changes locally?
Have you successfully run brew tests with your changes locally?

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.

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.

Questions

Is it worth all of this extra code to have cleaner backtraces?
Would it be worth adding in some way of turning this off?
Will this make things harder to debug in some cases?

CC: @dduugg

apainintheneck · 2023-09-19T04:37:51Z

I kind of had to force the issue to recreate the initial scenario where this popped up (which means we don't have any obvious bugs in the codebase that throw errors with stack traces 😄).

I removed the following checks from the brew fetch command to mimic it's state before the fix a month or so ago.

diff --git a/Library/Homebrew/cmd/fetch.rb b/Library/Homebrew/cmd/fetch.rb
index d677dca12..ffaadbd63 100644
--- a/Library/Homebrew/cmd/fetch.rb
+++ b/Library/Homebrew/cmd/fetch.rb
@@ -166,10 +166,10 @@ module Homebrew
           SimulateSystem.with os: os, arch: arch do
             cask = Cask::CaskLoader.load(ref)
 
-            if cask.url.nil? || cask.sha256.nil?
-              opoo "Cask #{cask} is not supported on os #{os} and arch #{arch}"
-              next
-            end
+            # if cask.url.nil? || cask.sha256.nil?
+            #   opoo "Cask #{cask} is not supported on os #{os} and arch #{arch}"
+            #   next
+            # end
 
             quarantine = args.quarantine?
             quarantine = true if quarantine.nil?

Before this PR

$ brew fetch homebrew/cask/calhash --os=mojave -d
/usr/local/Homebrew/Library/Homebrew/brew.rb (Formulary::TapLoader): loading /usr/local/Homebrew/Library/Taps/homebrew/homebrew-cask/Formula/calhash.rb
/usr/local/Homebrew/Library/Homebrew/brew.rb (Cask::CaskLoader::FromAPILoader): loading homebrew/cask/calhash
/usr/local/Homebrew/Library/Homebrew/brew.rb (Cask::CaskLoader::FromAPILoader): loading calhash
Error: attempted to use a Downloadable without a URL!
/usr/local/Homebrew/Library/Homebrew/downloadable.rb:75:in `downloader'
/usr/local/Homebrew/Library/Homebrew/vendor/bundle/ruby/2.6.0/gems/sorbet-runtime-0.5.10461/lib/types/private/methods/call_validation.rb:157:in `call'
/usr/local/Homebrew/Library/Homebrew/vendor/bundle/ruby/2.6.0/gems/sorbet-runtime-0.5.10461/lib/types/private/methods/call_validation.rb:157:in `validate_call'
/usr/local/Homebrew/Library/Homebrew/vendor/bundle/ruby/2.6.0/gems/sorbet-runtime-0.5.10461/lib/types/private/methods/_methods.rb:270:in `block in _on_method_added'
/usr/local/Homebrew/Library/Homebrew/downloadable.rb:50:in `cached_download'
/usr/local/Homebrew/Library/Homebrew/vendor/bundle/ruby/2.6.0/gems/sorbet-runtime-0.5.10461/lib/types/private/methods/call_validation.rb:157:in `call'
/usr/local/Homebrew/Library/Homebrew/vendor/bundle/ruby/2.6.0/gems/sorbet-runtime-0.5.10461/lib/types/private/methods/call_validation.rb:157:in `validate_call'
/usr/local/Homebrew/Library/Homebrew/vendor/bundle/ruby/2.6.0/gems/sorbet-runtime-0.5.10461/lib/types/private/methods/_methods.rb:270:in `block in _on_method_added'
/usr/local/Homebrew/Library/Homebrew/cmd/fetch.rb:236:in `fetch_fetchable'
/usr/local/Homebrew/Library/Homebrew/cmd/fetch.rb:201:in `fetch_cask'
/usr/local/Homebrew/Library/Homebrew/cmd/fetch.rb:178:in `block (3 levels) in fetch'
/usr/local/Homebrew/Library/Homebrew/simulate_system.rb:29:in `with'
/usr/local/Homebrew/Library/Homebrew/vendor/bundle/ruby/2.6.0/gems/sorbet-runtime-0.5.10461/lib/types/private/methods/call_validation.rb:157:in `call'
/usr/local/Homebrew/Library/Homebrew/vendor/bundle/ruby/2.6.0/gems/sorbet-runtime-0.5.10461/lib/types/private/methods/call_validation.rb:157:in `validate_call'
/usr/local/Homebrew/Library/Homebrew/vendor/bundle/ruby/2.6.0/gems/sorbet-runtime-0.5.10461/lib/types/private/methods/_methods.rb:270:in `block in _on_method_added'
/usr/local/Homebrew/Library/Homebrew/cmd/fetch.rb:166:in `block (2 levels) in fetch'
/usr/local/Homebrew/Library/Homebrew/cmd/fetch.rb:163:in `each'
/usr/local/Homebrew/Library/Homebrew/cmd/fetch.rb:163:in `block in fetch'
/usr/local/Homebrew/Library/Homebrew/cmd/fetch.rb:94:in `each'
/usr/local/Homebrew/Library/Homebrew/cmd/fetch.rb:94:in `fetch'
/usr/local/Homebrew/Library/Homebrew/brew.rb:94:in `<main>'

After this PR

$ brew fetch homebrew/cask/calhash --os=mojave -d
/usr/local/Homebrew/Library/Homebrew/brew.rb (Formulary::TapLoader): loading /usr/local/Homebrew/Library/Taps/homebrew/homebrew-cask/Formula/calhash.rb
/usr/local/Homebrew/Library/Homebrew/brew.rb (Cask::CaskLoader::FromAPILoader): loading homebrew/cask/calhash
/usr/local/Homebrew/Library/Homebrew/brew.rb (Cask::CaskLoader::FromAPILoader): loading calhash
Error: attempted to use a Downloadable without a URL!
/usr/local/Homebrew/Library/Homebrew/downloadable.rb:75:in `downloader'
/usr/local/Homebrew/Library/Homebrew/downloadable.rb:50:in `cached_download'
/usr/local/Homebrew/Library/Homebrew/cmd/fetch.rb:236:in `fetch_fetchable'
/usr/local/Homebrew/Library/Homebrew/cmd/fetch.rb:201:in `fetch_cask'
/usr/local/Homebrew/Library/Homebrew/cmd/fetch.rb:178:in `block (3 levels) in fetch'
/usr/local/Homebrew/Library/Homebrew/simulate_system.rb:29:in `with'
/usr/local/Homebrew/Library/Homebrew/cmd/fetch.rb:166:in `block (2 levels) in fetch'
/usr/local/Homebrew/Library/Homebrew/cmd/fetch.rb:163:in `each'
/usr/local/Homebrew/Library/Homebrew/cmd/fetch.rb:163:in `block in fetch'
/usr/local/Homebrew/Library/Homebrew/cmd/fetch.rb:94:in `each'
/usr/local/Homebrew/Library/Homebrew/cmd/fetch.rb:94:in `fetch'
/usr/local/Homebrew/Library/Homebrew/brew.rb:94:in `<main>'

MikeMcQuaid

This makes se a lot of sense to me, nice work @apainintheneck!

dduugg · 2023-09-19T21:07:30Z

Looks promising! I'd like an easy escape hatch to include the full backtrace, perhaps when verbose or HOMEBREW_DEVELOPER is set.

It'd be nice to add a test, even a contrived one with a hardcoded backtrace (if that's the best we can do without investing a lot of effort).

apainintheneck · 2023-09-20T04:19:43Z

Looks promising! I'd like an easy escape hatch to include the full backtrace, perhaps when verbose or HOMEBREW_DEVELOPER is set.

I think showing the full backtrace when verbose is set makes the most sense. I always have HOMEBREW_DEVELOPER set so selfishly I don't want that to trigger the full backtrace.

It'd be nice to add a test, even a contrived one with a hardcoded backtrace (if that's the best we can do without investing a lot of effort).

Good point! I was more trying to get feedback on the approach first.

MikeMcQuaid · 2023-09-20T07:47:40Z

I think showing the full backtrace when verbose is set makes the most sense. I always have HOMEBREW_DEVELOPER set so selfishly I don't want that to trigger the full backtrace.

Agreed. Even --verbose might be annoying here. I wonder if it's worth using an undocumented environment variable or something. Similarly, if we actually end up stripping anything from the backtrace: could consider outputting that along with the environment variable.

apainintheneck · 2023-09-21T04:36:01Z

I'd rather not add an environment variable for this. I feel like we'd just forget about it and it wouldn't get used that much. --verbose is the most logical place to put it IMO. If we think that will still show up too often, we could combine that with --debug and/or HOMEBREW_DEVELOPER too.

apainintheneck · 2023-09-21T05:27:57Z

I added some tests with some of the backtraces I showed earlier pared-down to fit the line length limit.

MikeMcQuaid · 2023-09-21T12:09:19Z

Library/Homebrew/utils/backtrace.rb

+    def self.clean(error)
+      backtrace = error.backtrace
+
+      return backtrace if Context.current.verbose?


Not blocking this being merged but: this feels weird to me as I don't think I'd expect --verbose to modify backtraces.

Not blocking this being merged but: this feels weird to me as I don't think I'd expect --verbose to modify backtraces.

Fair point! But under what circumstances does one expect backtraces to be modified? (I like your suggestion below to echo that sorbet lines are removed.)

The point here is that using --verbose leave backtraces unmodified. My thinking is that you'd expect more output with --verbose and that means in this case that backtraces might be longer.

MikeMcQuaid · 2023-09-21T12:12:22Z

Library/Homebrew/utils/backtrace.rb

+      return backtrace if backtrace.blank?
+      return backtrace if backtrace.fetch(0).start_with?(sorbet_runtime_path)
+
+      backtrace.reject { |line| line.start_with?(sorbet_runtime_path) }


I think it would be nice to print a one-liner something like:

if any_lines_removed opoo "Removed Sorbet lines from backtrace!" unless Homebrew::EnvConfig.no_env_hints? puts "Rerun with --verbose or HOMEBREW_SORBET_BACKTRACES=1 to see these lines" end end

obviously adjusting messaging based on what we decide to go with.

Otherwise I can't see how you'd know really to run --verbose and also it feels much more useful to tell people when the lines were removed.

Alternatively: add these lines to the start of the backtrace instead.

I'm still not a fan of adding another environment variable (I think that can wait until multiple people complain about it) but adding a message makes sense. I guess we'd only need to print it the first time a backtrace is modified, right? Does that sound reasonable?

Then it would look like this:

$ brew fetch homebrew/cask/calhash --os=mojave -d /usr/local/Homebrew/Library/Homebrew/brew.rb (Formulary::TapLoader): loading /usr/local/Homebrew/Library/Taps/homebrew/homebrew-cask/Formula/calhash.rb /usr/local/Homebrew/Library/Homebrew/brew.rb (Cask::CaskLoader::FromAPILoader): loading homebrew/cask/calhash /usr/local/Homebrew/Library/Homebrew/brew.rb (Cask::CaskLoader::FromAPILoader): loading calhash Error: attempted to use a Downloadable without a URL! Warning: Removed Sorbet lines from backtrace! Rerun with --verbose to see the original backtrace /usr/local/Homebrew/Library/Homebrew/downloadable.rb:75:in `downloader' /usr/local/Homebrew/Library/Homebrew/downloadable.rb:50:in `cached_download' /usr/local/Homebrew/Library/Homebrew/cmd/fetch.rb:236:in `fetch_fetchable' /usr/local/Homebrew/Library/Homebrew/cmd/fetch.rb:201:in `fetch_cask' /usr/local/Homebrew/Library/Homebrew/cmd/fetch.rb:178:in `block (3 levels) in fetch' /usr/local/Homebrew/Library/Homebrew/simulate_system.rb:29:in `with' /usr/local/Homebrew/Library/Homebrew/cmd/fetch.rb:166:in `block (2 levels) in fetch' /usr/local/Homebrew/Library/Homebrew/cmd/fetch.rb:163:in `each' /usr/local/Homebrew/Library/Homebrew/cmd/fetch.rb:163:in `block in fetch' /usr/local/Homebrew/Library/Homebrew/cmd/fetch.rb:94:in `each' /usr/local/Homebrew/Library/Homebrew/cmd/fetch.rb:94:in `fetch' /usr/local/Homebrew/Library/Homebrew/brew.rb:94:in `<main>'

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.

MikeMcQuaid

Thanks @apainintheneck, let's see how this goes, great work 👍🏻

apainintheneck force-pushed the scrub-sorbet-runtime-from-backtrace branch from 169b149 to 53b85c1 Compare September 19, 2023 04:34

apainintheneck added the discussion Input solicited from others label Sep 19, 2023

MikeMcQuaid approved these changes Sep 19, 2023

View reviewed changes

apainintheneck force-pushed the scrub-sorbet-runtime-from-backtrace branch from 53b85c1 to 3409c08 Compare September 20, 2023 04:53

MikeMcQuaid approved these changes Sep 20, 2023

View reviewed changes

apainintheneck force-pushed the scrub-sorbet-runtime-from-backtrace branch from 3409c08 to 4537b3c Compare September 21, 2023 05:22

apainintheneck marked this pull request as ready for review September 21, 2023 05:22

MikeMcQuaid reviewed Sep 21, 2023

View reviewed changes

apainintheneck force-pushed the scrub-sorbet-runtime-from-backtrace branch from 4537b3c to 85bd4c7 Compare September 22, 2023 04:10

MikeMcQuaid approved these changes Sep 22, 2023

View reviewed changes

MikeMcQuaid merged commit 073a4bb into Homebrew:master Sep 22, 2023
24 checks passed

github-actions bot added the outdated PR was locked due to age label Oct 23, 2023

github-actions bot locked as resolved and limited conversation to collaborators Oct 23, 2023

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

utils/backtrace: scrub sorbet-runtime from backtrace #16014

utils/backtrace: scrub sorbet-runtime from backtrace #16014

apainintheneck commented Sep 19, 2023

apainintheneck commented Sep 19, 2023

MikeMcQuaid left a comment

dduugg commented Sep 19, 2023

apainintheneck commented Sep 20, 2023

MikeMcQuaid commented Sep 20, 2023

apainintheneck commented Sep 21, 2023

apainintheneck commented Sep 21, 2023

MikeMcQuaid Sep 21, 2023

dduugg Sep 21, 2023

apainintheneck Sep 22, 2023

MikeMcQuaid Sep 21, 2023

MikeMcQuaid Sep 21, 2023

apainintheneck Sep 22, 2023

apainintheneck Sep 22, 2023

MikeMcQuaid left a comment

utils/backtrace: scrub sorbet-runtime from backtrace #16014

utils/backtrace: scrub sorbet-runtime from backtrace #16014

Conversation

apainintheneck commented Sep 19, 2023

Questions

apainintheneck commented Sep 19, 2023

Before this PR

After this PR

MikeMcQuaid left a comment

Choose a reason for hiding this comment

dduugg commented Sep 19, 2023

apainintheneck commented Sep 20, 2023

MikeMcQuaid commented Sep 20, 2023

apainintheneck commented Sep 21, 2023

apainintheneck commented Sep 21, 2023

MikeMcQuaid Sep 21, 2023

Choose a reason for hiding this comment

dduugg Sep 21, 2023

Choose a reason for hiding this comment

apainintheneck Sep 22, 2023

Choose a reason for hiding this comment

MikeMcQuaid Sep 21, 2023

Choose a reason for hiding this comment

MikeMcQuaid Sep 21, 2023

Choose a reason for hiding this comment

apainintheneck Sep 22, 2023

Choose a reason for hiding this comment

apainintheneck Sep 22, 2023

Choose a reason for hiding this comment

MikeMcQuaid left a comment

Choose a reason for hiding this comment