Two of FrameworksTest gets "undefined class/module Mysql2:: (ArgumentError)" since #39723 #42968

yahonda · 2021-08-08T05:21:45Z

Since #39723 has been merged to main branch ,two of FrameworksTest gets "undefined class/module Mysql2:: (ArgumentError)". https://buildkite.com/rails/rails/builds/79982#a24742cc-7394-4ff0-8713-aa64164fd925

Steps to reproduce

cd railties
# test "expire schema cache dump if the version can't be checked because the database is unhealthy" 
bin/test test/application/initializers/frameworks_test.rb:254
# test "does not expire schema cache dump if check_schema_cache_dump_version is false and the database unhealthy" do
bin/test test/application/initializers/frameworks_test.rb:285

Expected behavior

Both of them should finish successfully.

Actual behavior

% ruby -v
ruby 3.0.2p107 (2021-07-07 revision 0db68f0233) [x86_64-darwin21]
% bin/test test/application/initializers/frameworks_test.rb:254
... snip ...
Run options: --seed 49040

# Running:

#<Thread:0x00007fa48a156270 /Users/yahonda/.rbenv/versions/3.0.2/lib/ruby/gems/3.0.0/gems/minitest-5.14.4/lib/minitest/parallel.rb:28 run> terminated with exception (report_on_exception is true):
/Users/yahonda/src/github.com/rails/rails/activesupport/lib/active_support/testing/isolation.rb:23:in `load': undefined class/module Mysql2:: (ArgumentError)
	from /Users/yahonda/src/github.com/rails/rails/activesupport/lib/active_support/testing/isolation.rb:23:in `run'
	from /Users/yahonda/.rbenv/versions/3.0.2/lib/ruby/gems/3.0.0/gems/minitest-5.14.4/lib/minitest.rb:1029:in `run_one_method'
	from /Users/yahonda/.rbenv/versions/3.0.2/lib/ruby/gems/3.0.0/gems/minitest-5.14.4/lib/minitest/parallel.rb:33:in `block (2 levels) in start'
/Users/yahonda/src/github.com/rails/rails/activesupport/lib/active_support/testing/isolation.rb:23:in `load': undefined class/module Mysql2:: (ArgumentError)
	from /Users/yahonda/src/github.com/rails/rails/activesupport/lib/active_support/testing/isolation.rb:23:in `run'
	from /Users/yahonda/.rbenv/versions/3.0.2/lib/ruby/gems/3.0.0/gems/minitest-5.14.4/lib/minitest.rb:1029:in `run_one_method'
	from /Users/yahonda/.rbenv/versions/3.0.2/lib/ruby/gems/3.0.0/gems/minitest-5.14.4/lib/minitest/parallel.rb:33:in `block (2 levels) in start'
%

% ruby -v
ruby 3.0.2p107 (2021-07-07 revision 0db68f0233) [x86_64-darwin21]
% bin/test test/application/initializers/frameworks_test.rb:285
... snip ...
Run options: --seed 42827

# Running:

#<Thread:0x00007f916a88f5b0 /Users/yahonda/.rbenv/versions/3.0.2/lib/ruby/gems/3.0.0/gems/minitest-5.14.4/lib/minitest/parallel.rb:28 run> terminated with exception (report_on_exception is true):
/Users/yahonda/src/github.com/rails/rails/activesupport/lib/active_support/testing/isolation.rb:23:in `load': undefined class/module Mysql2:: (ArgumentError)
	from /Users/yahonda/src/github.com/rails/rails/activesupport/lib/active_support/testing/isolation.rb:23:in `run'
	from /Users/yahonda/.rbenv/versions/3.0.2/lib/ruby/gems/3.0.0/gems/minitest-5.14.4/lib/minitest.rb:1029:in `run_one_method'
	from /Users/yahonda/.rbenv/versions/3.0.2/lib/ruby/gems/3.0.0/gems/minitest-5.14.4/lib/minitest/parallel.rb:33:in `block (2 levels) in start'
/Users/yahonda/src/github.com/rails/rails/activesupport/lib/active_support/testing/isolation.rb:23:in `load': undefined class/module Mysql2:: (ArgumentError)
	from /Users/yahonda/src/github.com/rails/rails/activesupport/lib/active_support/testing/isolation.rb:23:in `run'
	from /Users/yahonda/.rbenv/versions/3.0.2/lib/ruby/gems/3.0.0/gems/minitest-5.14.4/lib/minitest.rb:1029:in `run_one_method'
	from /Users/yahonda/.rbenv/versions/3.0.2/lib/ruby/gems/3.0.0/gems/minitest-5.14.4/lib/minitest/parallel.rb:33:in `block (2 levels) in start'
	%

System configuration

Rails version: main branch

Ruby version:ruby 3.0.2p107 (2021-07-07 revision 0db68f0233) [x86_64-darwin21]

hahmed · 2021-08-08T22:04:28Z

Thanks for reporting this issue!

Looking at those 2 railties tests, they are trying to establish a connection to the database and expecting a connection failure. The exception is:

#<Mysql2::Error::ConnectionError: Can't connect to MySQL server on '127.0.0.1' (61)>

config:

{:adapter=>"mysql2", :pool=>5, :timeout=>5000, :database=>"db/development.sqlite3", :port=>1, :host=>"127.0.0.1", :flags=>2}

Both tests are failing because of the conditional check:

elsif [ConnectionAdapters::Mysql2Adapter::ER_CONN_HOST_ERROR, ConnectionAdapters::Mysql2Adapter::ER_UNKNOWN_HOST_ERROR].include?(error.error_number)
            raise ActiveRecord::DatabaseConnectionError.hostname_error(config[:host])

I'm going to dig into those 2 tests and see if I can find out what's happening.

hahmed · 2021-08-11T22:20:10Z

I have looked into this a little more. I can see that we are simulating unhealthy db check by using an incorrect host which is now caught here

rails/activerecord/lib/active_record/connection_adapters/mysql2_adapter.rb

Line 50 in da911da

    
           elsif [ConnectionAdapters::Mysql2Adapter::ER_CONN_HOST_ERROR, ConnectionAdapters::Mysql2Adapter::ER_UNKNOWN_HOST_ERROR].include?(error.error_number)

This means that an exception is now raised much earlier than what's expected in those tests, as in the exception is now raised on app boot here

rails/railties/test/application/initializers/frameworks_test.rb

Line 263 in da911da

require "#{app_path}/config/environment"

In the failing tests, we are not expecting an exception on app boot rather, the app should continue to boot but an exception is now being raised.

That code was introduced #40119, @byroot I could not find a way to simulate the connection error based off the new code, any ideas?

hahmed · 2021-08-11T22:22:48Z

Whoops, apologies for accidentally closing 😅

hahmed · 2021-08-11T22:27:30Z

Also... on my machine both tests are now failing on 2.7, 3.0 too, I wonder why CI only caught ruby head.

byroot · 2021-08-11T22:27:46Z

Hum, I only had a quick glance (late here) I'll have a closer look tomorrow.

But yeah, normally all DB access during boot should rescue any connection errors (this is to ensure you can deploy a fix to production if your DB is down).

So either something make it connect from an unexpected code path, or the exception raised is different than the one expected so the protection no longer works.

hahmed · 2021-08-11T22:56:18Z

In the linked PR I tried to rescue those errors on the AR railtie, but that never worked will have another look tomorrow.

There is an issue with parallel testing or the reporter which is not serialising the error from the test correctly so I added require "mysql2" to the file test/application/initializers/frameworks_test.rb so I could see what's wrong, here is the stack trace:

Error:
ApplicationTests::FrameworksTest#test_expire_schema_cache_dump_if_the_version_can't_be_checked_because_the_database_is_unhealthy:
ActiveRecord::DatabaseConnectionError: There is an issue connecting with your hostname: 127.0.0.1.

Please check your database configuration and ensure there is a valid connection to your database.

    /Users/haroon/projects/rails/activerecord/lib/active_record/connection_adapters/mysql2_adapter.rb:51:in `rescue in new_client'
    /Users/haroon/projects/rails/activerecord/lib/active_record/connection_adapters/mysql2_adapter.rb:43:in `new_client'
    /Users/haroon/projects/rails/activerecord/lib/active_record/connection_adapters/mysql2_adapter.rb:23:in `mysql2_connection'
    /Users/haroon/projects/rails/activerecord/lib/active_record/connection_adapters/abstract/connection_pool.rb:643:in `public_send'
    /Users/haroon/projects/rails/activerecord/lib/active_record/connection_adapters/abstract/connection_pool.rb:643:in `new_connection'
    /Users/haroon/projects/rails/activerecord/lib/active_record/connection_adapters/abstract/connection_pool.rb:687:in `checkout_new_connection'
    /Users/haroon/projects/rails/activerecord/lib/active_record/connection_adapters/abstract/connection_pool.rb:666:in `try_to_checkout_new_connection'
    /Users/haroon/projects/rails/activerecord/lib/active_record/connection_adapters/abstract/connection_pool.rb:627:in `acquire_connection'
    /Users/haroon/projects/rails/activerecord/lib/active_record/connection_adapters/abstract/connection_pool.rb:328:in `checkout'
    /Users/haroon/projects/rails/activerecord/lib/active_record/connection_adapters/abstract/connection_pool.rb:168:in `connection'
    /Users/haroon/projects/rails/activerecord/lib/active_record/connection_adapters/abstract/connection_handler.rb:211:in `retrieve_connection'
    /Users/haroon/projects/rails/activerecord/lib/active_record/connection_handling.rb:309:in `retrieve_connection'
    /Users/haroon/projects/rails/activerecord/lib/active_record/connection_handling.rb:265:in `connection'
    /Users/haroon/projects/rails/activerecord/lib/active_record/model_schema.rb:395:in `table_exists?'
    /Users/haroon/projects/rails/activerecord/lib/active_record/encryption/encryptable_record.rb:125:in `validate_column_size'
    /Users/haroon/projects/rails/activerecord/lib/active_record/encryption/encryptable_record.rb:92:in `encrypt_attribute'
    /Users/haroon/projects/rails/activerecord/lib/active_record/encryption/encryptable_record.rb:53:in `block in encrypts'
    /Users/haroon/projects/rails/activerecord/lib/active_record/encryption/encryptable_record.rb:50:in `each'
    /Users/haroon/projects/rails/activerecord/lib/active_record/encryption/encryptable_record.rb:50:in `encrypts'
    /Users/haroon/projects/rails/actiontext/app/models/action_text/encrypted_rich_text.rb:7:in `<class:EncryptedRichText>'
    /Users/haroon/projects/rails/actiontext/app/models/action_text/encrypted_rich_text.rb:4:in `<module:ActionText>'
    /Users/haroon/projects/rails/actiontext/app/models/action_text/encrypted_rich_text.rb:3:in `<top (required)>'
    /Users/haroon/.gem/ruby/3.0.2/gems/zeitwerk-2.5.0.beta/lib/zeitwerk/kernel.rb:27:in `require'
    /Users/haroon/.gem/ruby/3.0.2/gems/zeitwerk-2.5.0.beta/lib/zeitwerk/kernel.rb:27:in `require'
    /Users/haroon/.gem/ruby/3.0.2/gems/zeitwerk-2.5.0.beta/lib/zeitwerk/loader/helpers.rb:93:in `const_get'
    /Users/haroon/.gem/ruby/3.0.2/gems/zeitwerk-2.5.0.beta/lib/zeitwerk/loader/helpers.rb:93:in `cget'
    /Users/haroon/.gem/ruby/3.0.2/gems/zeitwerk-2.5.0.beta/lib/zeitwerk/loader.rb:230:in `block (2 levels) in eager_load'
    /Users/haroon/.gem/ruby/3.0.2/gems/zeitwerk-2.5.0.beta/lib/zeitwerk/loader/helpers.rb:24:in `block in ls'
    /Users/haroon/.gem/ruby/3.0.2/gems/zeitwerk-2.5.0.beta/lib/zeitwerk/loader/helpers.rb:16:in `each_child'
    /Users/haroon/.gem/ruby/3.0.2/gems/zeitwerk-2.5.0.beta/lib/zeitwerk/loader/helpers.rb:16:in `ls'
    /Users/haroon/.gem/ruby/3.0.2/gems/zeitwerk-2.5.0.beta/lib/zeitwerk/loader.rb:225:in `block in eager_load'
    /Users/haroon/.gem/ruby/3.0.2/gems/zeitwerk-2.5.0.beta/lib/zeitwerk/loader.rb:212:in `synchronize'
    /Users/haroon/.gem/ruby/3.0.2/gems/zeitwerk-2.5.0.beta/lib/zeitwerk/loader.rb:212:in `eager_load'
    /Users/haroon/.gem/ruby/3.0.2/gems/zeitwerk-2.5.0.beta/lib/zeitwerk/loader.rb:301:in `each'
    /Users/haroon/.gem/ruby/3.0.2/gems/zeitwerk-2.5.0.beta/lib/zeitwerk/loader.rb:301:in `eager_load_all'
    /Users/haroon/projects/rails/railties/lib/rails/application/finisher.rb:111:in `block in <module:Finisher>'
    /Users/haroon/projects/rails/railties/lib/rails/initializable.rb:32:in `instance_exec'
    /Users/haroon/projects/rails/railties/lib/rails/initializable.rb:32:in `run'
    /Users/haroon/projects/rails/railties/lib/rails/initializable.rb:61:in `block in run_initializers'
    /Users/haroon/.rubies/ruby-3.0.2/lib/ruby/3.0.0/tsort.rb:228:in `block in tsort_each'
    /Users/haroon/.rubies/ruby-3.0.2/lib/ruby/3.0.0/tsort.rb:350:in `block (2 levels) in each_strongly_connected_component'
    /Users/haroon/.rubies/ruby-3.0.2/lib/ruby/3.0.0/tsort.rb:431:in `each_strongly_connected_component_from'
    /Users/haroon/.rubies/ruby-3.0.2/lib/ruby/3.0.0/tsort.rb:349:in `block in each_strongly_connected_component'
    /Users/haroon/.rubies/ruby-3.0.2/lib/ruby/3.0.0/tsort.rb:347:in `each'
    /Users/haroon/.rubies/ruby-3.0.2/lib/ruby/3.0.0/tsort.rb:347:in `call'
    /Users/haroon/.rubies/ruby-3.0.2/lib/ruby/3.0.0/tsort.rb:347:in `each_strongly_connected_component'
    /Users/haroon/.rubies/ruby-3.0.2/lib/ruby/3.0.0/tsort.rb:226:in `tsort_each'
    /Users/haroon/.rubies/ruby-3.0.2/lib/ruby/3.0.0/tsort.rb:205:in `tsort_each'
    /Users/haroon/projects/rails/railties/lib/rails/initializable.rb:60:in `run_initializers'
    /Users/haroon/projects/rails/railties/lib/rails/application.rb:369:in `initialize!'
    /Users/haroon/projects/rails/tmp/d20210811-10419-oivctw/app/config/environment.rb:5:in `<top (required)>'
    /Users/haroon/.gem/ruby/3.0.2/gems/zeitwerk-2.5.0.beta/lib/zeitwerk/kernel.rb:35:in `require'
    /Users/haroon/.gem/ruby/3.0.2/gems/zeitwerk-2.5.0.beta/lib/zeitwerk/kernel.rb:35:in `require'
    /Users/haroon/projects/rails/activesupport/lib/active_support/dependencies.rb:291:in `block in require'
    /Users/haroon/projects/rails/activesupport/lib/active_support/dependencies.rb:261:in `load_dependency'
    /Users/haroon/projects/rails/activesupport/lib/active_support/dependencies.rb:291:in `require'
    /Users/haroon/projects/rails/railties/test/application/initializers/frameworks_test.rb:264:in `block (2 levels) in <class:FrameworksTest>'
    /Users/haroon/projects/rails/railties/test/env_helpers.rb:27:in `switch_env'
    /Users/haroon/projects/rails/railties/test/application/initializers/frameworks_test.rb:263:in `block in <class:FrameworksTest>'

byroot · 2021-08-12T07:04:34Z

activerecord/lib/active_record/model_schema.rb:395:in `table_exists?'
activerecord/lib/active_record/encryption/encryptable_record.rb:125:in `validate_column_size'
activerecord/lib/active_record/encryption/encryptable_record.rb:92:in `encrypt_attribute'

Ok it's what I thought, this model is trying to hit the database as soon as it's loaded, it shouldn't.

byroot · 2021-08-12T07:06:19Z

Oh, and there was a rescue there:

rails/activerecord/lib/active_record/encryption/encryptable_record.rb

Lines 124 to 130 in da911da

    
           def validate_column_size(attribute_name) 
        
             if table_exists? && limit = columns_hash[attribute_name.to_s]&.limit 
        
               validates_length_of attribute_name, maximum: limit 
        
             end 
        
           rescue ActiveRecord::ConnectionNotEstablished => e 
        
             Rails.logger.warn "Skipping adding length validation for #{self.name}\##{attribute_name}. Can't check column limit due to: #{e.inspect}" 
        
           end

, but only for ConnectionNotEstablished.

hahmed · 2021-08-12T12:19:28Z

Thanks Jean, rescuing inside encryptable_record has fixed those tests. 👌

I'm wondering why encryptable_record is loaded at this point because we never seem to be using it -- prob an entirely different issue though.

byroot · 2021-08-13T08:18:13Z

I think #43009 should have fixed it.

hahmed · 2021-08-13T22:35:46Z

Those tests are still failing on main branch and on that PR

hahmed · 2021-08-18T22:17:28Z

Closing because this was fixed by the commit cabe311

hahmed added activerecord railties With reproduction steps labels Aug 8, 2021

hahmed mentioned this issue Aug 10, 2021

Fix failing railties framework tests #42991

Closed

hahmed closed this as completed Aug 11, 2021

hahmed reopened this Aug 11, 2021

hahmed closed this as completed Aug 18, 2021

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Two of FrameworksTest gets "undefined class/module Mysql2:: (ArgumentError)" since #39723 #42968

Two of FrameworksTest gets "undefined class/module Mysql2:: (ArgumentError)" since #39723 #42968

yahonda commented Aug 8, 2021

hahmed commented Aug 8, 2021 •

edited

Loading

hahmed commented Aug 11, 2021 •

edited

Loading

hahmed commented Aug 11, 2021

hahmed commented Aug 11, 2021

byroot commented Aug 11, 2021

hahmed commented Aug 11, 2021

byroot commented Aug 12, 2021

byroot commented Aug 12, 2021

hahmed commented Aug 12, 2021

byroot commented Aug 13, 2021

hahmed commented Aug 13, 2021

hahmed commented Aug 18, 2021

Two of FrameworksTest gets "undefined class/module Mysql2:: (ArgumentError)" since #39723 #42968

Two of FrameworksTest gets "undefined class/module Mysql2:: (ArgumentError)" since #39723 #42968

Comments

yahonda commented Aug 8, 2021

Steps to reproduce

Expected behavior

Actual behavior

System configuration

hahmed commented Aug 8, 2021 • edited Loading

hahmed commented Aug 11, 2021 • edited Loading

hahmed commented Aug 11, 2021

hahmed commented Aug 11, 2021

byroot commented Aug 11, 2021

hahmed commented Aug 11, 2021

byroot commented Aug 12, 2021

byroot commented Aug 12, 2021

hahmed commented Aug 12, 2021

byroot commented Aug 13, 2021

hahmed commented Aug 13, 2021

hahmed commented Aug 18, 2021

hahmed commented Aug 8, 2021 •

edited

Loading

hahmed commented Aug 11, 2021 •

edited

Loading