From f5ca96528ddc6cc14e5c86cf2172418ab863e845 Mon Sep 17 00:00:00 2001 From: Alan Guo Xiang Tan Date: Wed, 20 Dec 2023 15:17:12 +0800 Subject: [PATCH] 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:100: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 ~~~~~ ``` --- spec/rails_helper.rb | 94 ++++++++++++++++++++++---------------------- 1 file changed, 47 insertions(+), 47 deletions(-) diff --git a/spec/rails_helper.rb b/spec/rails_helper.rb index e750e7b648a..68da4628cce 100644 --- a/spec/rails_helper.rb +++ b/spec/rails_helper.rb @@ -26,12 +26,16 @@ require "webmock/rspec" require "minio_runner" class RspecErrorTracker - def self.last_exception=(ex) - @ex = ex + def self.exceptions + @exceptions ||= {} end - def self.last_exception - @ex + def self.clear_exceptions + @exceptions&.clear + end + + def self.report_exception(path, exception) + exceptions[path] = exception end def initialize(app, config = {}) @@ -46,7 +50,7 @@ class RspecErrorTracker # and also Mocha::ExpectationError inherit from Exception instead of StandardError # they do not get captured by the rescue => e shorthand :( rescue WebMock::NetConnectNotAllowedError, Mocha::ExpectationError, StandardError => e - RspecErrorTracker.last_exception = e + RspecErrorTracker.report_exception(env["PATH_INFO"], e) raise e end end @@ -125,7 +129,7 @@ module TestSetup I18n.locale = SiteSettings::DefaultsProvider::DEFAULT_LOCALE - RspecErrorTracker.last_exception = nil + RspecErrorTracker.clear_exceptions if $test_cleanup_callbacks $test_cleanup_callbacks.reverse_each(&:call) @@ -449,21 +453,6 @@ RSpec.configure do |config| 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 FileUtils.remove_dir(concurrency_safe_tmp_dir, true) if SpecSecureRandom.value Downloads.clear @@ -539,36 +528,26 @@ RSpec.configure do |config| # failed system tests a lot trickier. if ENV["SELENIUM_DISABLE_VERBOSE_JS_LOGS"].blank? if example.exception - skip_js_errors = false + lines << "~~~~~~~ JS LOGS ~~~~~~~" - if example.exception.kind_of?(RSpec::Core::MultipleExceptionError) - lines << "~~~~~~~ SYSTEM TEST ERRORS ~~~~~~~" - example.exception.all_exceptions.each { |ex| lines << ex.message } - lines << "~~~~~ END SYSTEM TEST ERRORS ~~~~~" - - skip_js_errors = true - end - - if !skip_js_errors - lines << "~~~~~~~ JS LOGS ~~~~~~~" - if js_logs.empty? - 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 + if js_logs.empty? + 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 - lines << "~~~~~ END JS LOGS ~~~~~" end + + lines << "~~~~~ END JS LOGS ~~~~~" end end @@ -588,6 +567,27 @@ RSpec.configure do |config| Discourse.redis.flushdb 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 Rails.configuration.multisite = true # rubocop:disable Discourse/NoDirectMultisiteManipulation