Adding a way to disable friendly errors

[martinos]

All my scripts have at_exit handle that logs all the uncaught exception to a file. This is very useful for diagnosing issues. This was working very well for a while but now all programs that are executed with bundle exec are run insides the FriendlyErrors.with_friendly_errors method which changes the raised exception.

I think that it should have a way to disable that filtering because it changes the behaviour the original program. I would expect that program to have exactly the same output either it's run inside bundler or not.

[colby-swandale]

Can you provide examples of the problem you're experiencing?

[martinos]

I use this for logging my errors:

GIT_REV = `git rev-parse HEAD`
process_name = "#{$0} #{ARGV.join(" ")}"
$script_start_time = Time.now

Rails.logger.info("%%%%%%%%% Starting Rails with PID: #{Process.pid}, process name:  #{process_name} #{ARGV.join(" ")} and git sha #{GIT_REV}")

# We want to log the uncaught exceptions
at_exit do
  if ($! && (($!.class != SystemExit) || (!$!.success?)))
    Rails.logger.fatal("Uncaught exception")
    Rails.logger.fatal($!.inspect)
    Rails.logger.fatal($!.backtrace.join("\n"))
  end
  Rails.logger.info("&&&&&&&&& Exiting #{process_name}. Execution duration: #{Time.now - $script_start_time} sec")
end

But with bundle exec the error is lost:

, [2018-01-08T16:08:35.112280 #78591]  INFO -- : %%%%%%%%% Starting Rails with PID: 78591, process name:  /Users/me/.gem/ruby/2.1.3/bin/boson -b test_raise -b test_raise and git sha 23990fc6485b0370753752e54b12fe52acb3e3b6

F, [2018-01-08T16:08:35.581638 #78591] FATAL -- : Uncaught exception
F, [2018-01-08T16:08:35.581673 #78591] FATAL -- : #<SystemExit: exit>
F, [2018-01-08T16:08:35.581689 #78591] FATAL -- : /Users/me/.gem/ruby/2.1.3/gems/bundler-1.16.0.pre.2/lib/bundler/friendly_errors.rb:125:in `exit'
/Users/me/.gem/ruby/2.1.3/gems/bundler-1.16.0.pre.2/lib/bundler/friendly_errors.rb:125:in `rescue in with_friendly_errors'
/Users/me/.gem/ruby/2.1.3/gems/bundler-1.16.0.pre.2/lib/bundler/friendly_errors.rb:122:in `with_friendly_errors'
/Users/me/.gem/ruby/2.1.3/gems/bundler-1.16.0.pre.2/exe/bundle:22:in `<top (required)>'
/Users/me/.gem/ruby/2.1.3/bin/bundle:23:in `load'
/Users/me/.gem/ruby/2.1.3/bin/bundle:23:in `<main>'
I, [2018-01-08T16:08:35.581710 #78591]  INFO -- : &&&&&&&&& Exiting /Users/me/.gem/ruby/2.1.3/bin/boson -b test_raise. Execution duration: 0.42705 sec

Without bundle exec I should see the callstack with the original error which is not the case.

[martinos]

If I use a binstub instead of bundle exec it's works as a charm. So bundle exec behave differently than binstubs.

Here's what I get with binstubs:

1-08T16:43:26.091271 #81088]  INFO -- : %%%%%%%%% Starting Rails with PID: 81088, process name:  ./bin/boson -b test_raise -b test_raise and git sha 23990fc6485b0370753752e54b12fe52acb3e3b6

F, [2018-01-08T16:43:26.563606 #81088] FATAL -- : Uncaught exception
F, [2018-01-08T16:43:26.563669 #81088] FATAL -- : #<SystemExit: Error: TATA
Original error: TATA
  lib/boson/commands/misc_task.rb:178:in `test_raise'
  /Users/me/.gem/ruby/2.1.3/gems/boson-more-0.3.0/lib/boson/namespacer.rb:16:in `full_invoke'
  /Users/me/.gem/ruby/2.1.3/gems/boson-1.3.0/lib/boson/bare_runner.rb:42:in `execute_command'
  /Users/me/.gem/ruby/2.1.3/gems/boson-more-0.3.0/lib/boson/save.rb:174:in `execute_command'
  /Users/me/.gem/ruby/2.1.3/gems/boson-more-0.3.0/lib/boson/pipe_runner.rb:24:in `block in execute_command'
  /Users/me/.gem/ruby/2.1.3/gems/boson-more-0.3.0/lib/boson/pipe_runner.rb:22:in `each'
  /Users/me/.gem/ruby/2.1.3/gems/boson-more-0.3.0/lib/boson/pipe_runner.rb:22:in `inject'
  /Users/me/.gem/ruby/2.1.3/gems/boson-more-0.3.0/lib/boson/pipe_runner.rb:22:in `execute_command'
  /Users/me/.gem/ruby/2.1.3/gems/boson-more-0.3.0/lib/boson/science.rb:244:in `execute_command'
  /Users/me/.gem/ruby/2.1.3/gems/boson-1.3.0/lib/boson/bin_runner.rb:25:in `execute_option_or_command'
  /Users/me/.gem/ruby/2.1.3/gems/boson-more-0.3.0/lib/boson/runner_options.rb:67:in `execute_option_or_command'
  /Users/me/.gem/ruby/2.1.3/gems/boson-1.3.0/lib/boson/bin_runner.rb:102:in `start'
  /Users/me/.gem/ruby/2.1.3/gems/boson-1.3.0/bin/boson:6:in `<top (required)>'
  ./bin/boson:21:in `load'
  ./bin/boson:21:in `<main>'>
F, [2018-01-08T16:43:26.563698 #81088] FATAL -- : /Users/mchabot/.gem/ruby/2.1.3/gems/boson-1.3.0/lib/boson/bare_runner.rb:33:in `abort'

I have a workaround for my case but I think that rescuing exception and exiting instead of rerasing the exception changes the behaviour of the original program.

I personally found at_exit to be too brittle in general to use in larger projects,
but I agree that the error should be propagated and/or disabled at the
user's discretion.

I may be wrong but perhaps not many other people use an at_exit solution.

Still agree with your comment though. :)

[martinos]

The at_exit solution is the only solution that I have found to easily track errors on script crash. This helped me a lot in diagnosing these issues. I think people are not using this solution because most Ruby developer are programming in Rails where exceptions are catched for you. Note that bundle exec is mainly used for running external script through rake, thor etc...

By the way every day you are using at_exit because all test framework run on it. I agree that we should avoid using it but I thing that the logging solution is super useful when you have scripts that runs on cron jobs.

[colby-swandale]

Thanks for the great example! I can confirm this issue

[thbar]

I second what @martinos said ; for multiple clients we're using at_exit to monitor Kiba ETL jobs running as crons, and with the current behaviour, error notification systems are just sending a lot of noise. I would love a way to disable this!

[rbroemeling]

As an addendum: bundler is completely breaking the common path for exception trackers with this, as well. As an example, the Bugsnag gem installs an at_exit handler to catch uncaught exceptions. I just spent ~2 hours tracking down why it wasn't working, and ended up at exactly this code path -- the "disguising" of the exception as a SystemExit exception effectively hides it from Bugsnag.

[rbroemeling]

For what it's worth, the simplest test case that I've come up with to demonstrate this issue is this:

#!/usr/bin/env ruby

at_exit do
  puts "in at_exit: #{$!.class.to_s}"
end

1/0

If you put that in a file, chmod +x it, and then run it with/without bundle exec, the reported exception class is ZeroDivisionError when running without bundle exec, and SystemExit when running with bundle exec.

[thbar]

This has been solved partially by rubygems/bundler#629, but some occurrences are still present:

• https://app.bugsnag.com/mystery-applicant/ma-etl/errors/5d6fc7bc378d610019b982cb?filters[error.status][0]=open&filters[event.since][0]=30d

I've notified Bugsnag themselves.

Presumably this error will get solved at some point, but keeping it opened as still relevant.