Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Implicitly assert no exception is raised in block assertions #37313

Merged
merged 1 commit into from
Oct 7, 2019

Conversation

casperisfine
Copy link
Contributor

Ref: Shopify/statsd-instrument#184 (comment)

This simply a quick proof of concept to showcase a fairly nasty foot gun with some block based assertions. See this comment chain for the initial discussion, but I'll explain it all here.

The problem

See the following test case:

class CounterTest < ActiveSupport::TestCase
  class Counter
    attr_reader :count

    def initialize
      @count = 0
    end

    def increment!
      @count += 1
      raise "OMG"
    end
  end

  test "it works" do
    counter = Counter.new

    assert_raises RuntimeError do
      assert_no_difference -> { counter.count } do
        counter.increment!
      end
    end
  end
end

It passes even though counter.count changed from 0 to 1, this is because assert_difference like most other block based assertions (e.g. assert_enqueued_*) are totally bypassed when an error happen.

Of course the test is arguably broken, the user here should put the assert_raises inside the assert_no_difference.

But realistically it's not hard to overlook this, so I think it would make sense to consider any raised exception, as an assertion failure.

@rafaelfranca @wvanbergen thoughts?

@rafaelfranca
Copy link
Member

The build is broken but it looks unrelated. Can you double check just it is not related?

@wvanbergen
Copy link
Contributor

When looking into this, we found a number of bugs in Shopify's code base and test suites that were hiding because of this issue.

I don't think many people know that assertions use exceptions under the hood, and will not assume that the nesting order of assert_raises with another block-based assertion method matters.

@casperisfine
Copy link
Contributor Author

The build is broken but it looks unrelated. Can you double check just it is not related?

It seems like it is. It fails consistently on my branch, even when ran in isolation, but not on master.

I'm afraid I won't have time to investigate today.

@casperisfine
Copy link
Contributor Author

Ok, so I updated other block based assertions to also expect no errors.

However for the Railie test failing, I'm having a very hard time investigating it.

(drbunix:/tmp/druby161.0) /rails/activesupport/lib/active_support/testing/parallelization.rb:18:in `record': DRb::DRbConnError (DRb::DRbConnError)
	from (drbunix:/tmp/druby161.0) /usr/local/lib/ruby/2.5.0/drb/drb.rb:1630:in `perform_without_block'
	from (drbunix:/tmp/druby161.0) /usr/local/lib/ruby/2.5.0/drb/drb.rb:1590:in `perform'
	from (drbunix:/tmp/druby161.0) /usr/local/lib/ruby/2.5.0/drb/drb.rb:1674:in `block (2 levels) in main_loop'
	from (drbunix:/tmp/druby161.0) /usr/local/lib/ruby/2.5.0/drb/drb.rb:1670:in `loop'
	from (drbunix:/tmp/druby161.0) /usr/local/lib/ruby/2.5.0/drb/drb.rb:1670:in `block in main_loop'
	from /rails/activesupport/lib/active_support/testing/parallelization.rb:107:in `rescue in block (2 levels) in start'
	from /rails/activesupport/lib/active_support/testing/parallelization.rb:101:in `block (2 levels) in start'
	from /rails/activesupport/lib/active_support/testing/parallelization.rb:77:in `fork'
	from /rails/activesupport/lib/active_support/testing/parallelization.rb:77:in `block in start'
	from /rails/activesupport/lib/active_support/testing/parallelization.rb:74:in `times'
	from /rails/activesupport/lib/active_support/testing/parallelization.rb:74:in `each'
	from /rails/activesupport/lib/active_support/testing/parallelization.rb:74:in `map'
	from /rails/activesupport/lib/active_support/testing/parallelization.rb:74:in `start'
	from /usr/local/bundle/gems/minitest-5.11.3/lib/minitest.rb:133:in `run'
	from /usr/local/bundle/gems/minitest-5.11.3/lib/minitest.rb:63:in `block in autorun'
/rails/activesupport/lib/active_support/testing/parallelization.rb:129:in `shutdown': Queue not empty, but all workers have finished. This probably means that a worker crashed and 1 tests were missed. (RuntimeError)
	from /usr/local/bundle/gems/minitest-5.11.3/lib/minitest.rb:140:in `run'
	from /usr/local/bundle/gems/minitest-5.11.3/lib/minitest.rb:63:in `block in autorun'
Run options: -n test_should_create_user --seed 58711

# Running:

It seems like the parallel worker crash, but I have no idea how to access logs so figure the root cause.

@casperisfine
Copy link
Contributor Author

@kaspth seems like you worked on that failing test before. Do you have any pointers as to how I could debug it?

Clearly the worker crash, but I have no idea why. Getting a backtrace or something would help.

@@ -30,6 +30,8 @@ def assert_not(object, message = nil)
# end
def assert_nothing_raised
yield
rescue => error
raise Minitest::UnexpectedError, error
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I actually wonder about the utility of adding this here, it seems minitest does it automatically: https://github.com/seattlerb/minitest/blob/15ed8e4ce504c8313058a1d6fc4918299be34328/lib/minitest/test.rb#L200-L201

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@kaspth that actually the whole point of the PR. If I take the PR description snippet again:

    assert_raises RuntimeError do # rescue StandardError and compare with what is expected
      assert_no_difference -> { counter.count } do # made a noop by the RuntimeError
        counter.increment! # raises RuntimeError (subclass of StandardError)
      end
    end

So the idea here is to eagerly wrap the error in Minitest::UnexpectedError which doesn't inherit from StandardError so that assert_raises doesn't catch it and hide the legitimate issue.

@kaspth
Copy link
Contributor

kaspth commented Oct 5, 2019

I've tried to debug this some more. I've run the test file locally from cd railties with:

bin/test test/application/test_runner_test.rb -n /test_run_in_parallel_with_unknown_object/

which fails with the error seen on CI. I've added these things to get more insight:

diff --git a/activesupport/lib/active_support/testing/assertions.rb b/activesupport/lib/active_support/testing/assertions.rb
index e04ff98dc0..d272551e9f 100644
--- a/activesupport/lib/active_support/testing/assertions.rb
+++ b/activesupport/lib/active_support/testing/assertions.rb
@@ -31,6 +31,7 @@ def assert_not(object, message = nil)
       def assert_nothing_raised
         yield
       rescue => error
+        Rails.logger.info error.message
         raise Minitest::UnexpectedError, error
       end
 
diff --git a/activesupport/lib/active_support/testing/parallelization.rb b/activesupport/lib/active_support/testing/parallelization.rb
index 96518a4a58..fb65917a06 100644
--- a/activesupport/lib/active_support/testing/parallelization.rb
+++ b/activesupport/lib/active_support/testing/parallelization.rb
@@ -15,6 +15,10 @@ def initialize
         end
 
         def record(reporter, result)
+          Rails.logger.info("buf: #{result.buf}")
+          Rails.logger.info("name: #{result.name}")
+          # Rails.logger.info(result.exception)
+
           raise DRb::DRbConnError if result.is_a?(DRb::DRbUnknown)
 
           reporter.synchronize do
diff --git a/railties/test/application/test_runner_test.rb b/railties/test/application/test_runner_test.rb
index 9bc7cfbec7..00ab25bffd 100644
--- a/railties/test/application/test_runner_test.rb
+++ b/railties/test/application/test_runner_test.rb
@@ -640,6 +640,8 @@ def test_run_in_parallel_with_unknown_object
       RUBY
 
       output = run_test_command("-n test_should_create_user")
+      puts output.split("\n")
+      Dir.chdir(app_path) { require "byebug"; byebug; `open log/test.log` }
 
       assert_match "ActionController::InvalidAuthenticityToken", output
     end

(somehow the log file wouldn't open without the byebug in there.)

What seems to be going is that DrbUnknown is thrown and converted per 90266a7#diff-f4d22edadb7ed6b4cc88e000d6c3ed69

In my patch I'm outputting the buf and name for the thing that Drb can't unmarshal. It seems that the resulting Minitest::Result can't be unmarshalled. Here's the log output when I ran the tests on my machine:


UsersControllerTest: test_should_create_user

Started POST "/users" for 127.0.0.1 at 2019-10-05 18:40:05 +0200
Processing by UsersController#create as HTML
Parameters: {"user"=>{"name"=>"MyString"}}
Can't verify CSRF token authenticity.
Completed 422 Unprocessable Entity in 0ms (ActiveRecord: 0.0ms | Allocations: 224)
ActionController::InvalidAuthenticityToken
buf: ��o:�Minitest::Result�:
@Namei"�test_should_create_user�:�EF:�@failures[�o:�Minitest::UnexpectedError : mesgI"�Unexpected exception�;�T:�bt0:�@exceptiono:/ActionController::InvalidAuthenticityToken ;
0;�[bI"��/Users/kaspth/code/rails/actionpack/lib/action_controller/metal/request_forgery_protection.rb:215:in handle_unverified_request'�;�FI"��/Users/kaspth/code/rails/actionpack/lib/action_controller/metal/request_forgery_protection.rb:247:in handle_unverified_request'�;�FI"��/Users/kaspth/code/rails/actionpack/lib/action_controller/metal/request_forgery_protection.rb:242:in verify_authenticity_token'�;�FI"i/Users/kaspth/code/rails/activesupport/lib/active_support/callbacks.rb:427:in block in make_lambda'�;�FI"p/Users/kaspth/code/rails/activesupport/lib/active_support/callbacks.rb:199:in block (2 levels) in halting'�;�FI"|/Users/kaspth/code/rails/actionpack/lib/abstract_controller/callbacks.rb:34:in block (2 levels) in module:Callbacks'�;�FI"e/Users/kaspth/code/rails/activesupport/lib/active_support/callbacks.rb:200:in block in halting'�;�FI"k/Users/kaspth/code/rails/activesupport/lib/active_support/callbacks.rb:512:in block in invoke_before'�;�FI"Y/Users/kaspth/code/rails/activesupport/lib/active_support/callbacks.rb:512:in each'�;�FI"b/Users/kaspth/code/rails/activesupport/lib/active_support/callbacks.rb:512:in invoke_before'�;�FI"b/Users/kaspth/code/rails/activesupport/lib/active_support/callbacks.rb:133:in run_callbacks'�;�FI"d/Users/kaspth/code/rails/actionpack/lib/abstract_controller/callbacks.rb:41:in process_action'�;�FI"e/Users/kaspth/code/rails/actionpack/lib/action_controller/metal/rescue.rb:22:in process_action'�;�FI"w/Users/kaspth/code/rails/actionpack/lib/action_controller/metal/instrumentation.rb:33:in block in process_action'�;�FI"l/Users/kaspth/code/rails/activesupport/lib/active_support/notifications.rb:203:in block in instrument'�;�FI"o/Users/kaspth/code/rails/activesupport/lib/active_support/notifications/instrumenter.rb:24:in instrument'�;�FI"c/Users/kaspth/code/rails/activesupport/lib/active_support/notifications.rb:203:in instrument'�;�FI"n/Users/kaspth/code/rails/actionpack/lib/action_controller/metal/instrumentation.rb:32:in process_action'�;�FI"n/Users/kaspth/code/rails/actionpack/lib/action_controller/metal/params_wrapper.rb:245:in process_action'�;�FI"r/Users/kaspth/code/rails/activerecord/lib/active_record/railties/controller_runtime.rb:27:in process_action'�;�FI"Y/Users/kaspth/code/rails/actionpack/lib/abstract_controller/base.rb:136:in process'�;�FI"U/Users/kaspth/code/rails/actionview/lib/action_view/rendering.rb:39:in process'�;�FI"Y/Users/kaspth/code/rails/actionpack/lib/action_controller/metal.rb:190:in dispatch'�;�FI"Y/Users/kaspth/code/rails/actionpack/lib/action_controller/metal.rb:251:in dispatch'�;�FI"b/Users/kaspth/code/rails/actionpack/lib/action_dispatch/routing/route_set.rb:50:in dispatch'�;�FI"_/Users/kaspth/code/rails/actionpack/lib/action_dispatch/routing/route_set.rb:33:in serve'�;�FI"e/Users/kaspth/code/rails/actionpack/lib/action_dispatch/journey/router.rb:50:in block in serve'�;�FI"[/Users/kaspth/code/rails/actionpack/lib/action_dispatch/journey/router.rb:32:in each'�;�FI"/Users/kaspth/code/rails/actionpack/lib/action_dispatch/journey/router.rb:32:in serve'�;�FI"_/Users/kaspth/code/rails/actionpack/lib/action_dispatch/routing/route_set.rb:834:in call'�;�FI"u/Users/kaspth/.rbenv/versions/2.6.3/lib/ruby/gems/2.6.0/gems/rack-2.0.7/lib/rack/tempfile_reaper.rb:15:in call'�;�FI"j/Users/kaspth/.rbenv/versions/2.6.3/lib/ruby/gems/2.6.0/gems/rack-2.0.7/lib/rack/etag.rb:25:in call'�;�FI"u/Users/kaspth/.rbenv/versions/2.6.3/lib/ruby/gems/2.6.0/gems/rack-2.0.7/lib/rack/conditional_get.rb:38:in call'�;�FI"j/Users/kaspth/.rbenv/versions/2.6.3/lib/ruby/gems/2.6.0/gems/rack-2.0.7/lib/rack/head.rb:12:in call'�;�FI"/Users/kaspth/code/rails/actionpack/lib/action_dispatch/http/feature_policy.rb:17:in call'�;�FI"i/Users/kaspth/code/rails/actionpack/lib/action_dispatch/http/content_security_policy.rb:18:in call'�;�FI"}/Users/kaspth/.rbenv/versions/2.6.3/lib/ruby/gems/2.6.0/gems/rack-2.0.7/lib/rack/session/abstract/id.rb:232:in context'�;�FI"z/Users/kaspth/.rbenv/versions/2.6.3/lib/ruby/gems/2.6.0/gems/rack-2.0.7/lib/rack/session/abstract/id.rb:226:in call'�;�FI"/Users/kaspth/code/rails/actionpack/lib/action_dispatch/middleware/cookies.rb:646:in call'�;�FI"j/Users/kaspth/code/rails/actionpack/lib/action_dispatch/middleware/callbacks.rb:27:in block in call'�;�FI"b/Users/kaspth/code/rails/activesupport/lib/active_support/callbacks.rb:100:in run_callbacks'�;�FI"a/Users/kaspth/code/rails/actionpack/lib/action_dispatch/middleware/callbacks.rb:26:in call'�;�FI"/Users/kaspth/code/rails/actionpack/lib/action_dispatch/middleware/executor.rb:14:in call'�;�FI"m/Users/kaspth/code/rails/actionpack/lib/action_dispatch/middleware/actionable_exceptions.rb:17:in call'�;�FI"h/Users/kaspth/code/rails/actionpack/lib/action_dispatch/middleware/debug_exceptions.rb:30:in call'�;�FI"g/Users/kaspth/code/rails/actionpack/lib/action_dispatch/middleware/show_exceptions.rb:33:in call'�;�FI"P/Users/kaspth/code/rails/railties/lib/rails/rack/logger.rb:37:in call_app'�;�FI"U/Users/kaspth/code/rails/railties/lib/rails/rack/logger.rb:26:in block in call'�;�FI"h/Users/kaspth/code/rails/activesupport/lib/active_support/tagged_logging.rb:86:in block in tagged'�;�FI"/Users/kaspth/code/rails/activesupport/lib/active_support/tagged_logging.rb:28:in tagged'�;�FI"_/Users/kaspth/code/rails/activesupport/lib/active_support/tagged_logging.rb:86:in tagged'�;�FI"L/Users/kaspth/code/rails/railties/lib/rails/rack/logger.rb:26:in call'�;�FI"a/Users/kaspth/code/rails/actionpack/lib/action_dispatch/middleware/remote_ip.rb:81:in call'�;�FI"b/Users/kaspth/code/rails/actionpack/lib/action_dispatch/middleware/request_id.rb:27:in call'�;�FI"u/Users/kaspth/.rbenv/versions/2.6.3/lib/ruby/gems/2.6.0/gems/rack-2.0.7/lib/rack/method_override.rb:22:in call'�;�FI"m/Users/kaspth/.rbenv/versions/2.6.3/lib/ruby/gems/2.6.0/gems/rack-2.0.7/lib/rack/runtime.rb:22:in call'�;�FI"t/Users/kaspth/code/rails/activesupport/lib/active_support/cache/strategy/local_cache_middleware.rb:29:in call'�;�FI"/Users/kaspth/code/rails/actionpack/lib/action_dispatch/middleware/executor.rb:14:in call'�;�FI"/Users/kaspth/code/rails/actionpack/lib/action_dispatch/middleware/static.rb:129:in call'�;�FI"o/Users/kaspth/.rbenv/versions/2.6.3/lib/ruby/gems/2.6.0/gems/rack-2.0.7/lib/rack/sendfile.rb:111:in call'�;�FI"j/Users/kaspth/code/rails/actionpack/lib/action_dispatch/middleware/host_authorization.rb:82:in call'�;�FI"H/Users/kaspth/code/rails/railties/lib/rails/engine.rb:527:in call'�;�FI"z/Users/kaspth/.rbenv/versions/2.6.3/lib/ruby/gems/2.6.0/gems/rack-test-1.1.0/lib/rack/mock_session.rb:29:in request'�;�FI"{/Users/kaspth/.rbenv/versions/2.6.3/lib/ruby/gems/2.6.0/gems/rack-test-1.1.0/lib/rack/test.rb:266:in process_request'�;�FI"s/Users/kaspth/.rbenv/versions/2.6.3/lib/ruby/gems/2.6.0/gems/rack-test-1.1.0/lib/rack/test.rb:119:in request'�;�FI"d/Users/kaspth/code/rails/actionpack/lib/action_dispatch/testing/integration.rb:274:in process'�;�FI"/Users/kaspth/code/rails/actionpack/lib/action_dispatch/testing/integration.rb:23:in post'�;�FI"�{/Users/kaspth/code/rails/actionpack/lib/action_dispatch/testing/integration.rb:362:in block (2 levels) in <module:Runner>'�;�FI"��/Users/kaspth/code/rails/tmp/d20191005-54311-1agmj6i/app/test/controllers/users_controller_test.rb:20:in block (2 levels) in class:UsersControllerTest'�;�FI"r/Users/kaspth/code/rails/activesupport/lib/active_support/testing/assertions.rb:32:in assert_nothing_raised'�;�FI"o/Users/kaspth/code/rails/activesupport/lib/active_support/testing/assertions.rb:101:in assert_difference'�;�FI"��/Users/kaspth/code/rails/tmp/d20191005-54311-1agmj6i/app/test/controllers/users_controller_test.rb:19:in block in <class:UsersControllerTest>'�;�FI"��/Users/kaspth/.rbenv/versions/2.6.3/lib/ruby/gems/2.6.0/gems/minitest-5.11.3/lib/minitest/test.rb:98:in block (3 levels) in run'�;�FI"�}/Users/kaspth/.rbenv/versions/2.6.3/lib/ruby/gems/2.6.0/gems/minitest-5.11.3/lib/minitest/test.rb:195:in capture_exceptions'�;�FI"��/Users/kaspth/.rbenv/versions/2.6.3/lib/ruby/gems/2.6.0/gems/minitest-5.11.3/lib/minitest/test.rb:95:in block (2 levels) in run'�;�FI"r/Users/kaspth/.rbenv/versions/2.6.3/lib/ruby/gems/2.6.0/gems/minitest-5.11.3/lib/minitest.rb:265:in time_it'�;�FI"{/Users/kaspth/.rbenv/versions/2.6.3/lib/ruby/gems/2.6.0/gems/minitest-5.11.3/lib/minitest/test.rb:94:in block in run'�;�FI"t/Users/kaspth/.rbenv/versions/2.6.3/lib/ruby/gems/2.6.0/gems/minitest-5.11.3/lib/minitest.rb:360:in on_signal'�;�FI"�|/Users/kaspth/.rbenv/versions/2.6.3/lib/ruby/gems/2.6.0/gems/minitest-5.11.3/lib/minitest/test.rb:211:in with_info_handler'�;�FI"r/Users/kaspth/.rbenv/versions/2.6.3/lib/ruby/gems/2.6.0/gems/minitest-5.11.3/lib/minitest/test.rb:93:in run'�;�FI"y/Users/kaspth/.rbenv/versions/2.6.3/lib/ruby/gems/2.6.0/gems/minitest-5.11.3/lib/minitest.rb:960:in run_one_method'�;�FI"|/Users/kaspth/code/rails/activesupport/lib/active_support/testing/parallelization.rb:100:in block (3 levels) in start'�;�FI"t/Users/kaspth/.rbenv/versions/2.6.3/lib/ruby/gems/2.6.0/gems/minitest-5.11.3/lib/minitest.rb:360:in on_signal'�;�FI"|/Users/kaspth/.rbenv/versions/2.6.3/lib/ruby/gems/2.6.0/gems/minitest-5.11.3/lib/minitest.rb:347:in with_info_handler'�;�FI"{/Users/kaspth/code/rails/activesupport/lib/active_support/testing/parallelization.rb:99:in block (2 levels) in start'�;�FI"f/Users/kaspth/code/rails/activesupport/lib/active_support/testing/parallelization.rb:81:in fork'�;�FI"p/Users/kaspth/code/rails/activesupport/lib/active_support/testing/parallelization.rb:81:in block in start'�;�FI"g/Users/kaspth/code/rails/activesupport/lib/active_support/testing/parallelization.rb:78:in times'�;�FI"f/Users/kaspth/code/rails/activesupport/lib/active_support/testing/parallelization.rb:78:in each'�;�FI"e/Users/kaspth/code/rails/activesupport/lib/active_support/testing/parallelization.rb:78:in map'�;�FI"g/Users/kaspth/code/rails/activesupport/lib/active_support/testing/parallelization.rb:78:in start'�;�FI"n/Users/kaspth/.rbenv/versions/2.6.3/lib/ruby/gems/2.6.0/gems/minitest-5.11.3/lib/minitest.rb:133:in run'�;�FI"z/Users/kaspth/.rbenv/versions/2.6.3/lib/ruby/gems/2.6.0/gems/minitest-5.11.3/lib/minitest.rb:63:in block in autorun'�;�F:�bt_locations@�:
cause0;�@
:�@assertionsi�:�@klassi"�UsersControllerTest�;�F:
@Timef�0.11846800008788705:�@source_location[�I"g/Users/kaspth/code/rails/tmp/d20191005-54311-1agmj6i/app/test/controllers/users_controller_test.rb�;�Fi�
name: ActionController::InvalidAuthenticityToken
buf: ��o:�Minitest::Result�:
@Namei"�test_should_create_user�:�EF:�@failures[�o:�Minitest::UnexpectedError : mesgI"�Unexpected exception�;�T:�bt0:�@exceptiono:�DRb::DRbRemoteError�: @ReasonI"/ActionController::InvalidAuthenticityToken�;�F;
I"\ActionController::InvalidAuthenticityToken (ActionController::InvalidAuthenticityToken)�;�T;�[bI"��/Users/kaspth/code/rails/actionpack/lib/action_controller/metal/request_forgery_protection.rb:215:in handle_unverified_request'�;�FI"��/Users/kaspth/code/rails/actionpack/lib/action_controller/metal/request_forgery_protection.rb:247:in handle_unverified_request'�;�FI"��/Users/kaspth/code/rails/actionpack/lib/action_controller/metal/request_forgery_protection.rb:242:in verify_authenticity_token'�;�FI"i/Users/kaspth/code/rails/activesupport/lib/active_support/callbacks.rb:427:in block in make_lambda'�;�FI"p/Users/kaspth/code/rails/activesupport/lib/active_support/callbacks.rb:199:in block (2 levels) in halting'�;�FI"|/Users/kaspth/code/rails/actionpack/lib/abstract_controller/callbacks.rb:34:in block (2 levels) in module:Callbacks'�;�FI"e/Users/kaspth/code/rails/activesupport/lib/active_support/callbacks.rb:200:in block in halting'�;�FI"k/Users/kaspth/code/rails/activesupport/lib/active_support/callbacks.rb:512:in block in invoke_before'�;�FI"Y/Users/kaspth/code/rails/activesupport/lib/active_support/callbacks.rb:512:in each'�;�FI"b/Users/kaspth/code/rails/activesupport/lib/active_support/callbacks.rb:512:in invoke_before'�;�FI"b/Users/kaspth/code/rails/activesupport/lib/active_support/callbacks.rb:133:in run_callbacks'�;�FI"d/Users/kaspth/code/rails/actionpack/lib/abstract_controller/callbacks.rb:41:in process_action'�;�FI"e/Users/kaspth/code/rails/actionpack/lib/action_controller/metal/rescue.rb:22:in process_action'�;�FI"w/Users/kaspth/code/rails/actionpack/lib/action_controller/metal/instrumentation.rb:33:in block in process_action'�;�FI"l/Users/kaspth/code/rails/activesupport/lib/active_support/notifications.rb:203:in block in instrument'�;�FI"o/Users/kaspth/code/rails/activesupport/lib/active_support/notifications/instrumenter.rb:24:in instrument'�;�FI"c/Users/kaspth/code/rails/activesupport/lib/active_support/notifications.rb:203:in instrument'�;�FI"n/Users/kaspth/code/rails/actionpack/lib/action_controller/metal/instrumentation.rb:32:in process_action'�;�FI"n/Users/kaspth/code/rails/actionpack/lib/action_controller/metal/params_wrapper.rb:245:in process_action'�;�FI"r/Users/kaspth/code/rails/activerecord/lib/active_record/railties/controller_runtime.rb:27:in process_action'�;�FI"Y/Users/kaspth/code/rails/actionpack/lib/abstract_controller/base.rb:136:in process'�;�FI"U/Users/kaspth/code/rails/actionview/lib/action_view/rendering.rb:39:in process'�;�FI"Y/Users/kaspth/code/rails/actionpack/lib/action_controller/metal.rb:190:in dispatch'�;�FI"Y/Users/kaspth/code/rails/actionpack/lib/action_controller/metal.rb:251:in dispatch'�;�FI"b/Users/kaspth/code/rails/actionpack/lib/action_dispatch/routing/route_set.rb:50:in dispatch'�;�FI"_/Users/kaspth/code/rails/actionpack/lib/action_dispatch/routing/route_set.rb:33:in serve'�;�FI"e/Users/kaspth/code/rails/actionpack/lib/action_dispatch/journey/router.rb:50:in block in serve'�;�FI"[/Users/kaspth/code/rails/actionpack/lib/action_dispatch/journey/router.rb:32:in each'�;�FI"/Users/kaspth/code/rails/actionpack/lib/action_dispatch/journey/router.rb:32:in serve'�;�FI"_/Users/kaspth/code/rails/actionpack/lib/action_dispatch/routing/route_set.rb:834:in call'�;�FI"u/Users/kaspth/.rbenv/versions/2.6.3/lib/ruby/gems/2.6.0/gems/rack-2.0.7/lib/rack/tempfile_reaper.rb:15:in call'�;�FI"j/Users/kaspth/.rbenv/versions/2.6.3/lib/ruby/gems/2.6.0/gems/rack-2.0.7/lib/rack/etag.rb:25:in call'�;�FI"u/Users/kaspth/.rbenv/versions/2.6.3/lib/ruby/gems/2.6.0/gems/rack-2.0.7/lib/rack/conditional_get.rb:38:in call'�;�FI"j/Users/kaspth/.rbenv/versions/2.6.3/lib/ruby/gems/2.6.0/gems/rack-2.0.7/lib/rack/head.rb:12:in call'�;�FI"/Users/kaspth/code/rails/actionpack/lib/action_dispatch/http/feature_policy.rb:17:in call'�;�FI"i/Users/kaspth/code/rails/actionpack/lib/action_dispatch/http/content_security_policy.rb:18:in call'�;�FI"}/Users/kaspth/.rbenv/versions/2.6.3/lib/ruby/gems/2.6.0/gems/rack-2.0.7/lib/rack/session/abstract/id.rb:232:in context'�;�FI"z/Users/kaspth/.rbenv/versions/2.6.3/lib/ruby/gems/2.6.0/gems/rack-2.0.7/lib/rack/session/abstract/id.rb:226:in call'�;�FI"/Users/kaspth/code/rails/actionpack/lib/action_dispatch/middleware/cookies.rb:646:in call'�;�FI"j/Users/kaspth/code/rails/actionpack/lib/action_dispatch/middleware/callbacks.rb:27:in block in call'�;�FI"b/Users/kaspth/code/rails/activesupport/lib/active_support/callbacks.rb:100:in run_callbacks'�;�FI"a/Users/kaspth/code/rails/actionpack/lib/action_dispatch/middleware/callbacks.rb:26:in call'�;�FI"/Users/kaspth/code/rails/actionpack/lib/action_dispatch/middleware/executor.rb:14:in call'�;�FI"m/Users/kaspth/code/rails/actionpack/lib/action_dispatch/middleware/actionable_exceptions.rb:17:in call'�;�FI"h/Users/kaspth/code/rails/actionpack/lib/action_dispatch/middleware/debug_exceptions.rb:30:in call'�;�FI"g/Users/kaspth/code/rails/actionpack/lib/action_dispatch/middleware/show_exceptions.rb:33:in call'�;�FI"P/Users/kaspth/code/rails/railties/lib/rails/rack/logger.rb:37:in call_app'�;�FI"U/Users/kaspth/code/rails/railties/lib/rails/rack/logger.rb:26:in block in call'�;�FI"h/Users/kaspth/code/rails/activesupport/lib/active_support/tagged_logging.rb:86:in block in tagged'�;�FI"/Users/kaspth/code/rails/activesupport/lib/active_support/tagged_logging.rb:28:in tagged'�;�FI"_/Users/kaspth/code/rails/activesupport/lib/active_support/tagged_logging.rb:86:in tagged'�;�FI"L/Users/kaspth/code/rails/railties/lib/rails/rack/logger.rb:26:in call'�;�FI"a/Users/kaspth/code/rails/actionpack/lib/action_dispatch/middleware/remote_ip.rb:81:in call'�;�FI"b/Users/kaspth/code/rails/actionpack/lib/action_dispatch/middleware/request_id.rb:27:in call'�;�FI"u/Users/kaspth/.rbenv/versions/2.6.3/lib/ruby/gems/2.6.0/gems/rack-2.0.7/lib/rack/method_override.rb:22:in call'�;�FI"m/Users/kaspth/.rbenv/versions/2.6.3/lib/ruby/gems/2.6.0/gems/rack-2.0.7/lib/rack/runtime.rb:22:in call'�;�FI"t/Users/kaspth/code/rails/activesupport/lib/active_support/cache/strategy/local_cache_middleware.rb:29:in call'�;�FI"/Users/kaspth/code/rails/actionpack/lib/action_dispatch/middleware/executor.rb:14:in call'�;�FI"/Users/kaspth/code/rails/actionpack/lib/action_dispatch/middleware/static.rb:129:in call'�;�FI"o/Users/kaspth/.rbenv/versions/2.6.3/lib/ruby/gems/2.6.0/gems/rack-2.0.7/lib/rack/sendfile.rb:111:in call'�;�FI"j/Users/kaspth/code/rails/actionpack/lib/action_dispatch/middleware/host_authorization.rb:82:in call'�;�FI"H/Users/kaspth/code/rails/railties/lib/rails/engine.rb:527:in call'�;�FI"z/Users/kaspth/.rbenv/versions/2.6.3/lib/ruby/gems/2.6.0/gems/rack-test-1.1.0/lib/rack/mock_session.rb:29:in request'�;�FI"{/Users/kaspth/.rbenv/versions/2.6.3/lib/ruby/gems/2.6.0/gems/rack-test-1.1.0/lib/rack/test.rb:266:in process_request'�;�FI"s/Users/kaspth/.rbenv/versions/2.6.3/lib/ruby/gems/2.6.0/gems/rack-test-1.1.0/lib/rack/test.rb:119:in request'�;�FI"d/Users/kaspth/code/rails/actionpack/lib/action_dispatch/testing/integration.rb:274:in process'�;�FI"/Users/kaspth/code/rails/actionpack/lib/action_dispatch/testing/integration.rb:23:in post'�;�FI"�{/Users/kaspth/code/rails/actionpack/lib/action_dispatch/testing/integration.rb:362:in block (2 levels) in <module:Runner>'�;�FI"��/Users/kaspth/code/rails/tmp/d20191005-54311-1agmj6i/app/test/controllers/users_controller_test.rb:20:in block (2 levels) in class:UsersControllerTest'�;�FI"r/Users/kaspth/code/rails/activesupport/lib/active_support/testing/assertions.rb:32:in assert_nothing_raised'�;�FI"o/Users/kaspth/code/rails/activesupport/lib/active_support/testing/assertions.rb:101:in assert_difference'�;�FI"��/Users/kaspth/code/rails/tmp/d20191005-54311-1agmj6i/app/test/controllers/users_controller_test.rb:19:in block in <class:UsersControllerTest>'�;�FI"��/Users/kaspth/.rbenv/versions/2.6.3/lib/ruby/gems/2.6.0/gems/minitest-5.11.3/lib/minitest/test.rb:98:in block (3 levels) in run'�;�FI"�}/Users/kaspth/.rbenv/versions/2.6.3/lib/ruby/gems/2.6.0/gems/minitest-5.11.3/lib/minitest/test.rb:195:in capture_exceptions'�;�FI"��/Users/kaspth/.rbenv/versions/2.6.3/lib/ruby/gems/2.6.0/gems/minitest-5.11.3/lib/minitest/test.rb:95:in block (2 levels) in run'�;�FI"r/Users/kaspth/.rbenv/versions/2.6.3/lib/ruby/gems/2.6.0/gems/minitest-5.11.3/lib/minitest.rb:265:in time_it'�;�FI"{/Users/kaspth/.rbenv/versions/2.6.3/lib/ruby/gems/2.6.0/gems/minitest-5.11.3/lib/minitest/test.rb:94:in block in run'�;�FI"t/Users/kaspth/.rbenv/versions/2.6.3/lib/ruby/gems/2.6.0/gems/minitest-5.11.3/lib/minitest.rb:360:in on_signal'�;�FI"�|/Users/kaspth/.rbenv/versions/2.6.3/lib/ruby/gems/2.6.0/gems/minitest-5.11.3/lib/minitest/test.rb:211:in with_info_handler'�;�FI"r/Users/kaspth/.rbenv/versions/2.6.3/lib/ruby/gems/2.6.0/gems/minitest-5.11.3/lib/minitest/test.rb:93:in run'�;�FI"y/Users/kaspth/.rbenv/versions/2.6.3/lib/ruby/gems/2.6.0/gems/minitest-5.11.3/lib/minitest.rb:960:in run_one_method'�;�FI"|/Users/kaspth/code/rails/activesupport/lib/active_support/testing/parallelization.rb:100:in block (3 levels) in start'�;�FI"t/Users/kaspth/.rbenv/versions/2.6.3/lib/ruby/gems/2.6.0/gems/minitest-5.11.3/lib/minitest.rb:360:in on_signal'�;�FI"|/Users/kaspth/.rbenv/versions/2.6.3/lib/ruby/gems/2.6.0/gems/minitest-5.11.3/lib/minitest.rb:347:in with_info_handler'�;�FI"{/Users/kaspth/code/rails/activesupport/lib/active_support/testing/parallelization.rb:99:in block (2 levels) in start'�;�FI"f/Users/kaspth/code/rails/activesupport/lib/active_support/testing/parallelization.rb:81:in fork'�;�FI"p/Users/kaspth/code/rails/activesupport/lib/active_support/testing/parallelization.rb:81:in block in start'�;�FI"g/Users/kaspth/code/rails/activesupport/lib/active_support/testing/parallelization.rb:78:in times'�;�FI"f/Users/kaspth/code/rails/activesupport/lib/active_support/testing/parallelization.rb:78:in each'�;�FI"e/Users/kaspth/code/rails/activesupport/lib/active_support/testing/parallelization.rb:78:in map'�;�FI"g/Users/kaspth/code/rails/activesupport/lib/active_support/testing/parallelization.rb:78:in start'�;�FI"n/Users/kaspth/.rbenv/versions/2.6.3/lib/ruby/gems/2.6.0/gems/minitest-5.11.3/lib/minitest.rb:133:in run'�;�FI"z/Users/kaspth/.rbenv/versions/2.6.3/lib/ruby/gems/2.6.0/gems/minitest-5.11.3/lib/minitest.rb:63:in block in autorun'�;�F:
causeo:/ActionController::InvalidAuthenticityToken ;
0;�[b@�@�@�@�@�@�@�@�@�@�@�@�@�@�@�@�@�@�@ @!@"@#@$@%@&@'@(@)@*@+@,@-@.@/@0@1@2@3@4@5@6@7@8@9@:@;@<@=@>@?@@@A@B@C@D@E@F@G@H@I@J@K@L@M@N@O@P@Q@R@S@T@U@V@W@X@Y@Z@[@@]@^@_@`@a@b@c@d@e@f@g@h@i@j:�bt_locations@l;�0:�@assertionsi�:�@klassi"�UsersControllerTest�;�F:
@Timef�0.11846800008788705:�@source_location[�I"g/Users/kaspth/code/rails/tmp/d20191005-54311-1agmj6i/app/test/controllers/users_controller_test.rb�;�Fi�
name: ActionController::InvalidAuthenticityToken

@kaspth
Copy link
Contributor

kaspth commented Oct 5, 2019

A potential other fix for the original issue is to override assert_raises and have it yield with a binding that doesn't respond to assertions that shouldn't be used within it.

@kaspth
Copy link
Contributor

kaspth commented Oct 5, 2019

Hope this helps, I've never really worked with Drb before, so we'd need either Aaron, Eileen or @y-yagi on the case for better assistance.

@y-yagi
Copy link
Member

y-yagi commented Oct 6, 2019

The test fails because it passes an exception class that can not be resolved by the DRb server(This is exactly what I wanted to solve with #34476).
This may be solved by exception class is wrapped with Minitest::UnexpectedError.

diff --git a/activesupport/lib/active_support/testing/assertions.rb b/activesupport/lib/active_support/testing/assertions.rb
index e04ff98..f283b98 100644
--- a/activesupport/lib/active_support/testing/assertions.rb
+++ b/activesupport/lib/active_support/testing/assertions.rb
@@ -31,7 +31,7 @@ def assert_not(object, message = nil)
       def assert_nothing_raised
         yield
       rescue => error
-        raise Minitest::UnexpectedError, error
+        raise Minitest::UnexpectedError.new(error)
       end

But as kaspth already mentioned, I think we don't need raise Minitest::UnexpectedError there.
https://github.com/rails/rails/pull/37313/files#r331753147

@kaspth
Copy link
Contributor

kaspth commented Oct 7, 2019

I'm learning more and more towards this not being something that we should solve. It looks like minitest ships with two other block based assertions assert_output and assert_throws.

The latter sounds like it would exhibit the same problem. E.g. what happens when execution gets halted deep in the stack?

Copy link
Contributor Author

@casperisfine casperisfine left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

It looks like minitest ships with two other block based assertions

Indeed, but I have very little hope to get this accepted in Minitest. They're not very receptive to changes aimed at preventing mistakes.

IMHO Rails could make this change, and then I could submit a PR on Minitest, just in case.

@casperisfine
Copy link
Contributor Author

@y-yagi your diff fixed the CI indeed. I'm not quite sure I understand how, but...

@rafaelfranca rafaelfranca merged commit 99d12b9 into rails:master Oct 7, 2019
@rafaelfranca
Copy link
Member

I think this is a problem we should fix here and of course try to get the PR submitted to minitest.

@kaspth
Copy link
Contributor

kaspth commented Oct 7, 2019

Cool cool, I'm happy to go with this, as long as we do make an attempt at upstreaming it, which sounds like we are so all good 😊✌️

@kaspth
Copy link
Contributor

kaspth commented Oct 7, 2019

Grain of salt warning, since I haven't checked this, but I'll just reiterate that I think assert_throws, though rarely used, would exhibit a similar problem.

@casperisfine
Copy link
Contributor Author

Ref: minitest/minitest#809

@artemave
Copy link
Contributor

artemave commented Mar 31, 2021

As a result of this change, the following no longer works in rails 6.1:

assert_raises SomeError do
  perform_enqueued_jobs
end

Because it is now always throwing Minitest::UnextectedError.

This looks like a bug to me.

@casperisfine
Copy link
Contributor Author

@artemave not sure what you mean, do you have a more fully featured example?

Are you trying to assert than one of the enqueued job is raising an error when performed?

@artemave
Copy link
Contributor

Are you trying to assert than one of the enqueued job is raising an error when performed?

Yes.

@casperisfine
Copy link
Contributor Author

Wouldn't it make more sense to assert this by calling perform directly?

@artemave
Copy link
Contributor

Sometimes code under test enqueues jobs.

@ghiculescu
Copy link
Member

ghiculescu commented Jun 11, 2021

@casperisfine here's another example. given this test:

    assert_raises(ArgumentError) do
      email = MyMailer.send_email(foo)
      assert_emails(0) { email.deliver_now }
    end

Then in the mailer we raise an ArgumentError for whatever reason.

class MyMailer < ApplicationMailer
  def send_email(foo)
    raise(ArgumentError, "wrong inputs")
  end
end

On Rails 6, the test passes. On 6.1 it fails, but it still prints out the ArgumentError, so it's pretty confusing why it failed. By adding begin/rescue statements I confirmed that assert_emails(0) { email.deliver_now } is raising a Minitest::UnexpectedError, which isn't what assert_raises expects so it's failing there. Looking into the backtrace

Is there a better way to write this test?

@ghiculescu
Copy link
Member

Executable test case for ^

# frozen_string_literal: true

require "bundler/inline"

gemfile(true) do
  source "https://rubygems.org"

  git_source(:github) { |repo| "https://github.com/#{repo}.git" }

  gem "rails", github: "rails/rails", branch: "main"
end

require "action_controller"
require "active_job"
require "active_job/railtie"
require "action_mailer"
require "action_mailer/railtie"
require "rails/test_help"
require "minitest/autorun"

class TestApp < Rails::Application
  config.root = __dir__
  routes.append {}
end
TestApp.initialize!

class MyMailer < ActionMailer::Base
  def send_email(foo)
    raise ArgumentError, "bad email!"
  end
end

class BuggyJobTest < ActionDispatch::IntegrationTest
  def test_that_fails
    assert_raises(ArgumentError) do
      email = MyMailer.send_email("foo")
      assert_emails(0) { email.deliver_now }
    end
  end

  def test_that_passes
    assert_raises(Minitest::UnexpectedError) do
      email = MyMailer.send_email("foo")
      assert_emails(0) { email.deliver_now }
    end
  end
end

I would expect the first test to pass, and the second test to fail. Instead it's the other way around:

# Running:

E

Error:
BuggyJobTest#test_that_fails:
ArgumentError: bad email!
    test.rb:29:in `send_email'
    test.rb:37:in `block (2 levels) in test_that_fails'
    test.rb:37:in `block in test_that_fails'
    test.rb:35:in `test_that_fails'


rails test test.rb:34

.

Finished in 0.051051s, 39.1765 runs/s, 19.5883 assertions/s.
2 runs, 1 assertions, 0 failures, 1 errors, 0 skips

@ghiculescu
Copy link
Member

Is there a better way to write this test?

Swapping the assertions around gets the test passing again:

assert_emails(0) do
  assert_raise(ArgumentError) { email.deliver_now }
end

I think it's pretty confusing / hard to debug though.

@p8
Copy link
Member

p8 commented Jun 12, 2021

Moved the discussion to another issue: #42459 (comment)

@casperisfine
Copy link
Contributor Author

On Rails 6, the test passes. On 6.1 it fails

As explained on your draft PR, that email.deliver_now could have sent a hundreds emails, and your assert_emails(0) wouldn't have caught it on 6.0. That's why we made this change.

I'm open to improve error message or things like that, but not to revert this behavior.

ghiculescu added a commit to ghiculescu/rails that referenced this pull request Jul 12, 2021
…aised

Follow up to rails#37313

- Adds regression tests
- Logs a warning in cases where assertions are nested in a way that's likely to be confusing
@@ -30,6 +30,8 @@ def assert_not(object, message = nil)
# end
def assert_nothing_raised
yield
rescue => error
raise Minitest::UnexpectedError.new(error)

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This made minitest a surprised dependency for 6.1

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Oh good pickup. I will have a go at fixing next week unless someone beats me to it.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Oh wait I thought this was #42459

That said isn’t minitest already a dependency?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yes it is:

s.add_dependency "minitest", ">= 5.1"

So not sure what @mathieujobin means exactly.

byroot added a commit to byroot/rails that referenced this pull request Feb 19, 2022
Fix: rails#44397
Ref: rails#37313
Ref: rails#42459

This avoid mistakes such as:

```ruby
assert_raise Something do
  assert_queries(1) do
    raise Something
  end
end
```

Co-Authored-By: Alex Coomans <alexc@squareup.com>
byroot added a commit that referenced this pull request Feb 19, 2022
Fix: #44397
Ref: #37313
Ref: #42459

This avoid mistakes such as:

```ruby
assert_raise Something do
  assert_queries(1) do
    raise Something
  end
end
```

Co-Authored-By: Alex Coomans <alexc@squareup.com>
jyoun-godaddy pushed a commit to jyoun-godaddy/activestorage that referenced this pull request Jul 5, 2022
Fix: rails/rails#44397
Ref: rails/rails#37313
Ref: rails/rails#42459

This avoid mistakes such as:

```ruby
assert_raise Something do
  assert_queries(1) do
    raise Something
  end
end
```

Co-Authored-By: Alex Coomans <alexc@squareup.com>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

Successfully merging this pull request may close these issues.

None yet

10 participants