DEV: Report all exceptions in RSpec example failure lines (#24981)

Why this change?

Previously, we were attaching any server exception to the RSpec
example's `Exception#cause` by doing `example.exception.cause =
RspecErrorTracker.last_exception`. However, this is problematic because
it relies on RSpec internal implementation details where RSpec will
print out the exception's cause. The other problem is that when RSpec
prints out the exception cause, it only includes a single line of
backtrace which isn't very helpful sometimes.

While this change of tracking the last exception works OK for request
specs, it doesn't not work for system specs where multiple requests can
be triggered in an example potentially leading to multiple exceptions.
Knowing all the exceptions which happened in the request is important
for us when it comes to debugging system test failures.

What does this change do?

`RspecErrorTracker` now tracks all exceptions that occurs during an
 RSpec example run. All the exceptions including the fullback trace of
each exception is printed out as part of the example's `extra_failure_lines` metadata.

Example:

```
Failures:

  1) Shortcuts | mark all read when chat is open when pressing shift+esc marks all channels read
     Failure/Error: expect(page).to have_content("all read messagasd")
       expected to find text "all read messagasd" in "Topics\nMy Posts\nReview\nAdmin\nMore\nCategories\nAmazing Category 0\nAmazing Category 1\nAmazing Category 2\nUncategorized\nAll categories\nConfigure defaults\nMessages\nInbox\nMy threads\nChannels\nKino Buffs 2\nMusic Lodge 0\nMusic Lodge 1\nPersonal chat\nMusic Lodge 1\nChat settings have been set to retain channel messages for 90 days.\nToday\nbruce6\n2:46 pm\nall read message 0\nbruce7\n2:46 pm\nall read message 1\nbruce8\n2:46 pm\nall read message 2\nbruce9\n2:46 pm\nall read message 3\nbruce10\n2:46 pm\nall read message 4\nbruce11\n2:46 pm\nall read message 5\nbruce12\n2:46 pm\nall read message 6\nbruce13\n2:46 pm\nall read message 7\nbruce14\n2:46 pm\nall read message 8\nbruce15\n2:46 pm\nall read message 9\nShowing all messages"

     [Screenshot Image]: /home/tgxworld/work/discourse/tmp/capybara/failures_r_spec_example_groups_shortcuts_mark_all_read_when_chat_is_open_when_pressing_shift_esc_marks_all_channels_read_236.png

     ~~~~~~~ SERVER EXCEPTIONS ~~~~~~~
     Error encountered while proccessing /stylesheets/desktop_theme_1_5dba82f48b7d6e4a9d54ffd915712811591356b7.css
       RuntimeError: boom
         /home/tgxworld/work/discourse/app/controllers/application_controller.rb:996:in `set_cross_origin_opener_policy_header'
         /home/tgxworld/.asdf/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/activesupport-7.0.7/lib/active_support/callbacks.rb:400:in `block in make_lambda'
         /home/tgxworld/.asdf/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/activesupport-7.0.7/lib/active_support/callbacks.rb:236:in `block in halting_and_conditional'
         /home/tgxworld/.asdf/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/activesupport-7.0.7/lib/active_support/callbacks.rb:599:in `block in invoke_after'
         /home/tgxworld/.asdf/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/activesupport-7.0.7/lib/active_support/callbacks.rb:599:in `each'
         /home/tgxworld/.asdf/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/activesupport-7.0.7/lib/active_support/callbacks.rb:599:in `invoke_after'
         /home/tgxworld/.asdf/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/activesupport-7.0.7/lib/active_support/callbacks.rb:133:in `block in run_callbacks'
         /home/tgxworld/work/discourse/app/controllers/application_controller.rb:423:in `block in with_resolved_locale'
         /home/tgxworld/.asdf/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/i18n-1.14.1/lib/i18n.rb:322:in `with_locale'
         /home/tgxworld/work/discourse/app/controllers/application_controller.rb:423:in `with_resolved_locale'
         /home/tgxworld/.asdf/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/activesupport-7.0.7/lib/active_support/callbacks.rb:127:in `block in run_callbacks'
         /home/tgxworld/.asdf/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/activesupport-7.0.7/lib/active_support/callbacks.rb:138:in `run_callbacks'
         /home/tgxworld/.asdf/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/actionpack-7.0.7/lib/abstract_controller/callbacks.rb:233:in `process_action'
         /home/tgxworld/.asdf/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/actionpack-7.0.7/lib/action_controller/metal/rescue.rb:23:in `process_action'
         /home/tgxworld/.asdf/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/actionpack-7.0.7/lib/action_controller/metal/instrumentation.rb:67:in `block in process_action'
         /home/tgxworld/.asdf/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/activesupport-7.0.7/lib/active_support/notifications.rb:206:in `block in instrument'
         /home/tgxworld/.asdf/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/activesupport-7.0.7/lib/active_support/notifications/instrumenter.rb:24:in `instrument'
         /home/tgxworld/.asdf/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/activesupport-7.0.7/lib/active_support/notifications.rb:206:in `instrument'
         /home/tgxworld/.asdf/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/actionpack-7.0.7/lib/action_controller/metal/instrumentation.rb:66:in `process_action'
         /home/tgxworld/.asdf/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/actionpack-7.0.7/lib/action_controller/metal/params_wrapper.rb:259:in `process_action'
         /home/tgxworld/.asdf/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.0.7/lib/active_record/railties/controller_runtime.rb:27:in `process_action'
         /home/tgxworld/.asdf/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/actionpack-7.0.7/lib/abstract_controller/base.rb:151:in `process'
         /home/tgxworld/.asdf/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/actionview-7.0.7/lib/action_view/rendering.rb:39:in `process'
         /home/tgxworld/.asdf/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/actionpack-7.0.7/lib/action_controller/metal.rb:188:in `dispatch'
         /home/tgxworld/.asdf/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/actionpack-7.0.7/lib/action_controller/metal.rb:251:in `dispatch'
         /home/tgxworld/.asdf/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/actionpack-7.0.7/lib/action_dispatch/routing/route_set.rb:49:in `dispatch'
         /home/tgxworld/.asdf/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/actionpack-7.0.7/lib/action_dispatch/routing/route_set.rb:32:in `serve'
         /home/tgxworld/.asdf/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/actionpack-7.0.7/lib/action_dispatch/journey/router.rb:50:in `block in serve'
         /home/tgxworld/.asdf/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/actionpack-7.0.7/lib/action_dispatch/journey/router.rb:32:in `each'
         /home/tgxworld/.asdf/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/actionpack-7.0.7/lib/action_dispatch/journey/router.rb:32:in `serve'
         /home/tgxworld/.asdf/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/actionpack-7.0.7/lib/action_dispatch/routing/route_set.rb:852:in `call'
         /home/tgxworld/work/discourse/lib/middleware/omniauth_bypass_middleware.rb:64:in `call'
         /home/tgxworld/.asdf/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/rack-2.2.8/lib/rack/tempfile_reaper.rb:15:in `call'
         /home/tgxworld/.asdf/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/rack-2.2.8/lib/rack/conditional_get.rb:27:in `call'
         /home/tgxworld/.asdf/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/rack-2.2.8/lib/rack/head.rb:12:in `call'
         /home/tgxworld/.asdf/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/actionpack-7.0.7/lib/action_dispatch/http/permissions_policy.rb:38:in `call'
         /home/tgxworld/work/discourse/lib/content_security_policy/middleware.rb:12:in `call'
         /home/tgxworld/work/discourse/lib/middleware/anonymous_cache.rb:351:in `call'
         /home/tgxworld/work/discourse/lib/middleware/gtm_script_nonce_injector.rb:10:in `call'
         /home/tgxworld/work/discourse/spec/rails_helper.rb:47:in `call'
         /home/tgxworld/work/discourse/config/initializers/008-rack-cors.rb:14:in `call'
         /home/tgxworld/.asdf/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/rack-2.2.8/lib/rack/session/abstract/id.rb:266:in `context'
         /home/tgxworld/.asdf/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/rack-2.2.8/lib/rack/session/abstract/id.rb:260:in `call'
         /home/tgxworld/.asdf/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/actionpack-7.0.7/lib/action_dispatch/middleware/cookies.rb:704:in `call'
         /home/tgxworld/.asdf/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/actionpack-7.0.7/lib/action_dispatch/middleware/callbacks.rb:27:in `block in call'
         /home/tgxworld/.asdf/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/activesupport-7.0.7/lib/active_support/callbacks.rb:99:in `run_callbacks'
         /home/tgxworld/.asdf/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/actionpack-7.0.7/lib/action_dispatch/middleware/callbacks.rb:26:in `call'
         /home/tgxworld/work/discourse/plugins/discourse-geoblocking/lib/geoblocking_middleware.rb:24:in `call'
         /home/tgxworld/.asdf/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/actionpack-7.0.7/lib/action_dispatch/middleware/debug_exceptions.rb:28:in `call'
         /home/tgxworld/.asdf/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/actionpack-7.0.7/lib/action_dispatch/middleware/show_exceptions.rb:29:in `call'
         /home/tgxworld/.asdf/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/railties-7.0.7/lib/rails/rack/logger.rb:40:in `call_app'
         /home/tgxworld/.asdf/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/railties-7.0.7/lib/rails/rack/logger.rb:27:in `call'
         /home/tgxworld/work/discourse/config/initializers/100-quiet_logger.rb:20:in `call'
         /home/tgxworld/work/discourse/config/initializers/100-silence_logger.rb:29:in `call'
         /home/tgxworld/.asdf/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/actionpack-7.0.7/lib/action_dispatch/middleware/remote_ip.rb:93:in `call'
         /home/tgxworld/.asdf/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/actionpack-7.0.7/lib/action_dispatch/middleware/request_id.rb:26:in `call'
         /home/tgxworld/work/discourse/lib/middleware/enforce_hostname.rb:24:in `call'
         /home/tgxworld/.asdf/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/rack-2.2.8/lib/rack/method_override.rb:24:in `call'
         /home/tgxworld/.asdf/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/actionpack-7.0.7/lib/action_dispatch/middleware/executor.rb:14:in `call'
         /home/tgxworld/.asdf/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/actionpack-7.0.7/lib/action_dispatch/middleware/static.rb:23:in `call'
         /home/tgxworld/.asdf/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/rack-2.2.8/lib/rack/sendfile.rb:110:in `call'
         /home/tgxworld/.asdf/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/actionpack-7.0.7/lib/action_dispatch/middleware/host_authorization.rb:131:in `call'
         /home/tgxworld/.asdf/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/message_bus-4.3.8/lib/message_bus/rack/middleware.rb:60:in `call'
         /home/tgxworld/work/discourse/lib/middleware/request_tracker.rb:233:in `call'
         /home/tgxworld/work/discourse/config/initializers/200-first_middlewares.rb:27:in `call'
         /home/tgxworld/.asdf/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/railties-7.0.7/lib/rails/engine.rb:530:in `call'
         /home/tgxworld/.asdf/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/rack-2.2.8/lib/rack/urlmap.rb:74:in `block in call'
         /home/tgxworld/.asdf/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/rack-2.2.8/lib/rack/urlmap.rb:58:in `each'
         /home/tgxworld/.asdf/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/rack-2.2.8/lib/rack/urlmap.rb:58:in `call'
         /home/tgxworld/.asdf/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/rack-2.2.8/lib/rack/builder.rb:244:in `call'
         /home/tgxworld/.asdf/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/capybara-3.39.2/lib/capybara/server/animation_disabler.rb:25:in `call'
         /home/tgxworld/.asdf/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/capybara-3.39.2/lib/capybara/server/middleware.rb:60:in `call'
         /home/tgxworld/.asdf/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/puma-6.4.0/lib/puma/configuration.rb:272:in `call'
         /home/tgxworld/.asdf/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/puma-6.4.0/lib/puma/request.rb💯in `block in handle_request'
         /home/tgxworld/.asdf/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/puma-6.4.0/lib/puma/thread_pool.rb:378:in `with_force_shutdown'
         /home/tgxworld/.asdf/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/puma-6.4.0/lib/puma/request.rb:99:in `handle_request'
         /home/tgxworld/.asdf/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/puma-6.4.0/lib/puma/server.rb:443:in `process_client'
         /home/tgxworld/.asdf/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/puma-6.4.0/lib/puma/server.rb:241:in `block in run'
         /home/tgxworld/.asdf/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/puma-6.4.0/lib/puma/thread_pool.rb:155:in `block in spawn_thread'
     ~~~~~~~ END SERVER EXCEPTIONS ~~~~~~~

     ~~~~~~~ JS LOGS ~~~~~~~
     http://localhost:31337/stylesheets/desktop_theme_1_5dba82f48b7d6e4a9d54ffd915712811591356b7.css?__ws=localhost - Failed to load resource: the server responded with a status of 500 (Internal Server Error)
     ~~~~~ END JS LOGS ~~~~~
```
This commit is contained in:
Alan Guo Xiang Tan 2023-12-20 15:17:12 +08:00 committed by GitHub
parent cdd66b24ec
commit f5ca96528d
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
1 changed files with 47 additions and 47 deletions

View File

@ -26,12 +26,16 @@ require "webmock/rspec"
require "minio_runner" require "minio_runner"
class RspecErrorTracker class RspecErrorTracker
def self.last_exception=(ex) def self.exceptions
@ex = ex @exceptions ||= {}
end end
def self.last_exception def self.clear_exceptions
@ex @exceptions&.clear
end
def self.report_exception(path, exception)
exceptions[path] = exception
end end
def initialize(app, config = {}) def initialize(app, config = {})
@ -46,7 +50,7 @@ class RspecErrorTracker
# and also Mocha::ExpectationError inherit from Exception instead of StandardError # and also Mocha::ExpectationError inherit from Exception instead of StandardError
# they do not get captured by the rescue => e shorthand :( # they do not get captured by the rescue => e shorthand :(
rescue WebMock::NetConnectNotAllowedError, Mocha::ExpectationError, StandardError => e rescue WebMock::NetConnectNotAllowedError, Mocha::ExpectationError, StandardError => e
RspecErrorTracker.last_exception = e RspecErrorTracker.report_exception(env["PATH_INFO"], e)
raise e raise e
end end
end end
@ -125,7 +129,7 @@ module TestSetup
I18n.locale = SiteSettings::DefaultsProvider::DEFAULT_LOCALE I18n.locale = SiteSettings::DefaultsProvider::DEFAULT_LOCALE
RspecErrorTracker.last_exception = nil RspecErrorTracker.clear_exceptions
if $test_cleanup_callbacks if $test_cleanup_callbacks
$test_cleanup_callbacks.reverse_each(&:call) $test_cleanup_callbacks.reverse_each(&:call)
@ -449,21 +453,6 @@ RSpec.configure do |config|
end end
end end
config.after :each do |example|
if example.exception && ex = RspecErrorTracker.last_exception
# magic in a cause if we have none
unless example.exception.cause
class << example.exception
attr_accessor :cause
end
example.exception.cause = ex
end
end
unfreeze_time
ActionMailer::Base.deliveries.clear
end
config.after(:suite) do config.after(:suite) do
FileUtils.remove_dir(concurrency_safe_tmp_dir, true) if SpecSecureRandom.value FileUtils.remove_dir(concurrency_safe_tmp_dir, true) if SpecSecureRandom.value
Downloads.clear Downloads.clear
@ -539,36 +528,26 @@ RSpec.configure do |config|
# failed system tests a lot trickier. # failed system tests a lot trickier.
if ENV["SELENIUM_DISABLE_VERBOSE_JS_LOGS"].blank? if ENV["SELENIUM_DISABLE_VERBOSE_JS_LOGS"].blank?
if example.exception if example.exception
skip_js_errors = false lines << "~~~~~~~ JS LOGS ~~~~~~~"
if example.exception.kind_of?(RSpec::Core::MultipleExceptionError) if js_logs.empty?
lines << "~~~~~~~ SYSTEM TEST ERRORS ~~~~~~~" lines << "(no logs)"
example.exception.all_exceptions.each { |ex| lines << ex.message } else
lines << "~~~~~ END SYSTEM TEST ERRORS ~~~~~" js_logs.each do |log|
# System specs are full of image load errors that are just noise, no need
skip_js_errors = true # to log this.
end if (
log.message.include?("Failed to load resource: net::ERR_CONNECTION_REFUSED") &&
if !skip_js_errors (log.message.include?("uploads") || log.message.include?("images"))
lines << "~~~~~~~ JS LOGS ~~~~~~~" ) || log.message.include?("favicon.ico")
if js_logs.empty? next
lines << "(no logs)"
else
js_logs.each do |log|
# System specs are full of image load errors that are just noise, no need
# to log this.
if (
log.message.include?("Failed to load resource: net::ERR_CONNECTION_REFUSED") &&
(log.message.include?("uploads") || log.message.include?("images"))
) || log.message.include?("favicon.ico")
next
end
lines << log.message
end end
lines << log.message
end end
lines << "~~~~~ END JS LOGS ~~~~~"
end end
lines << "~~~~~ END JS LOGS ~~~~~"
end end
end end
@ -588,6 +567,27 @@ RSpec.configure do |config|
Discourse.redis.flushdb Discourse.redis.flushdb
end end
config.after :each do |example|
if example.exception && RspecErrorTracker.exceptions.present?
lines = RSpec.current_example.metadata[:extra_failure_lines]
lines << "~~~~~~~ SERVER EXCEPTIONS ~~~~~~~"
RspecErrorTracker.exceptions.each_with_index do |(path, ex), index|
lines << "\n" if index != 0
lines << "Error encountered while proccessing #{path}"
lines << " #{ex.class}: #{ex.message}"
ex.backtrace.each { |line| lines << " #{line}" }
end
lines << "~~~~~~~ END SERVER EXCEPTIONS ~~~~~~~"
lines << "\n"
end
unfreeze_time
ActionMailer::Base.deliveries.clear
end
config.before(:each, type: :multisite) do config.before(:each, type: :multisite) do
Rails.configuration.multisite = true # rubocop:disable Discourse/NoDirectMultisiteManipulation Rails.configuration.multisite = true # rubocop:disable Discourse/NoDirectMultisiteManipulation