Deadlock in `check_pending_migrations` with multiple databases and missing `connects_to`

[bensheldon]

I looked into this with @matthewd and he believed it warranted opening an issue for visibility.

Briefly, I have a Rails Application with multiple databases configured in database.yml (primary and animals). And I have a Rails Engine with a BaseRecord < ActiveRecord::Base that doesn't have a connects_to .

When running the application, for some reason the check_pending_migrations middleware is causing a hang because it seems to be waiting on attempt_to_checkout_all_existing_connections.

In my poking at it, the only connection that seems to be checked out and waiting for that exclusive checkout is the same connection that has been checked out a little earlier in the callstack from with_temporary_connection.

Report generated by `ActionDispatch::DebugLocks`

Thread 0 [0x3c78 sleep]  No lock (yielded share)

/Users/bensheldon/.rbenv/versions/3.2.2/lib/ruby/3.2.0/monitor.rb:108:in `sleep'
/Users/bensheldon/.rbenv/versions/3.2.2/lib/ruby/3.2.0/monitor.rb:108:in `wait'
/Users/bensheldon/.rbenv/versions/3.2.2/lib/ruby/3.2.0/monitor.rb:108:in `wait_for_cond'
/Users/bensheldon/.rbenv/versions/3.2.2/lib/ruby/3.2.0/monitor.rb:108:in `wait'
/Users/bensheldon/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.0/lib/active_record/connection_adapters/abstract/connection_pool/queue.rb:174:in `wait'
/Users/bensheldon/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.0/lib/active_record/connection_adapters/abstract/connection_pool/queue.rb:119:in `block (2 levels) in wait_poll'
/Users/bensheldon/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activesupport-7.1.0/lib/active_support/concurrency/share_lock.rb:187:in `yield_shares'
/Users/bensheldon/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activesupport-7.1.0/lib/active_support/dependencies/interlock.rb:41:in `permit_concurrent_loads'
/Users/bensheldon/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.0/lib/active_record/connection_adapters/abstract/connection_pool/queue.rb:118:in `block in wait_poll'
/Users/bensheldon/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.0/lib/active_record/connection_adapters/abstract/connection_pool/queue.rb:117:in `loop'
/Users/bensheldon/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.0/lib/active_record/connection_adapters/abstract/connection_pool/queue.rb:117:in `wait_poll'
/Users/bensheldon/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.0/lib/active_record/connection_adapters/abstract/connection_pool/queue.rb:78:in `internal_poll'
/Users/bensheldon/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.0/lib/active_record/connection_adapters/abstract/connection_pool/queue.rb:204:in `internal_poll'
/Users/bensheldon/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.0/lib/active_record/connection_adapters/abstract/connection_pool/queue.rb:73:in `block in poll'
/Users/bensheldon/.rbenv/versions/3.2.2/lib/ruby/3.2.0/monitor.rb:202:in `synchronize'
/Users/bensheldon/.rbenv/versions/3.2.2/lib/ruby/3.2.0/monitor.rb:202:in `mon_synchronize'
/Users/bensheldon/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.0/lib/active_record/connection_adapters/abstract/connection_pool/queue.rb:82:in `synchronize'
/Users/bensheldon/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.0/lib/active_record/connection_adapters/abstract/connection_pool/queue.rb:73:in `poll'
/Users/bensheldon/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.0/lib/active_record/connection_adapters/abstract/connection_pool.rb:661:in `acquire_connection'
/Users/bensheldon/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.0/lib/active_record/connection_adapters/abstract/connection_pool.rb:355:in `checkout'
/Users/bensheldon/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.0/lib/active_record/connection_adapters/abstract/connection_pool.rb:591:in `checkout_for_exclusive_access'
/Users/bensheldon/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.0/lib/active_record/connection_adapters/abstract/connection_pool.rb:559:in `block (3 levels) in attempt_to_checkout_all_existing_connections'
/Users/bensheldon/.rbenv/versions/3.2.2/lib/ruby/3.2.0/monitor.rb:202:in `synchronize'
/Users/bensheldon/.rbenv/versions/3.2.2/lib/ruby/3.2.0/monitor.rb:202:in `mon_synchronize'
/Users/bensheldon/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.0/lib/active_record/connection_adapters/abstract/connection_pool.rb:555:in `block (2 levels) in attempt_to_checkout_all_existing_connections'
/Users/bensheldon/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.0/lib/active_record/connection_adapters/abstract/connection_pool.rb:554:in `loop'
/Users/bensheldon/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.0/lib/active_record/connection_adapters/abstract/connection_pool.rb:554:in `block in attempt_to_checkout_all_existing_connections'
/Users/bensheldon/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.0/lib/active_record/connection_adapters/abstract/connection_pool/queue.rb:185:in `with_a_bias_for'
/Users/bensheldon/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.0/lib/active_record/connection_adapters/abstract/connection_pool.rb:553:in `attempt_to_checkout_all_existing_connections'
/Users/bensheldon/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.0/lib/active_record/connection_adapters/abstract/connection_pool.rb:539:in `block in with_exclusively_acquired_all_connections'
/Users/bensheldon/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.0/lib/active_record/connection_adapters/abstract/connection_pool.rb:615:in `with_new_connections_blocked'
/Users/bensheldon/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.0/lib/active_record/connection_adapters/abstract/connection_pool.rb:538:in `with_exclusively_acquired_all_connections'
/Users/bensheldon/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.0/lib/active_record/connection_adapters/abstract/connection_pool.rb:261:in `disconnect'
/Users/bensheldon/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.0/lib/active_record/connection_adapters/abstract/connection_pool.rb:283:in `disconnect!'
/Users/bensheldon/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.0/lib/active_record/connection_adapters/pool_config.rb:56:in `block in disconnect!'
/Users/bensheldon/.rbenv/versions/3.2.2/lib/ruby/3.2.0/mutex_m.rb:79:in `synchronize'
/Users/bensheldon/.rbenv/versions/3.2.2/lib/ruby/3.2.0/mutex_m.rb:79:in `mu_synchronize'
/Users/bensheldon/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.0/lib/active_record/connection_adapters/pool_config.rb:52:in `disconnect!'
/Users/bensheldon/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.0/lib/active_record/connection_adapters/abstract/connection_handler.rb:308:in `disconnect_pool_from_pool_manager'
/Users/bensheldon/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.0/lib/active_record/connection_adapters/abstract/connection_handler.rb:155:in `establish_connection'
/Users/bensheldon/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.0/lib/active_record/tasks/database_tasks.rb:516:in `with_temporary_pool'
/Users/bensheldon/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.0/lib/active_record/tasks/database_tasks.rb:500:in `with_temporary_connection'
/Users/bensheldon/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.0/lib/active_record/tasks/database_tasks.rb:494:in `block in with_temporary_connection_for_each'
/Users/bensheldon/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.0/lib/active_record/tasks/database_tasks.rb:493:in `each'
/Users/bensheldon/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.0/lib/active_record/tasks/database_tasks.rb:493:in `with_temporary_connection_for_each'
/Users/bensheldon/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.0/lib/active_record/migration.rb:771:in `pending_migrations'
/Users/bensheldon/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.0/lib/active_record/migration.rb:750:in `check_pending_migrations'
/Users/bensheldon/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.0/lib/active_record/migration.rb:642:in `block (2 levels) in call'
/Users/bensheldon/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activesupport-7.1.0/lib/active_support/file_update_checker.rb:85:in `execute'
/Users/bensheldon/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.0/lib/active_record/migration.rb:647:in `block in call'
/Users/bensheldon/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.0/lib/active_record/migration.rb:639:in `synchronize'
/Users/bensheldon/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.0/lib/active_record/migration.rb:639:in `call'
/Users/bensheldon/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/actionpack-7.1.0/lib/action_dispatch/middleware/callbacks.rb:29:in `block in call'
/Users/bensheldon/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activesupport-7.1.0/lib/active_support/callbacks.rb:101:in `run_callbacks'
/Users/bensheldon/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/actionpack-7.1.0/lib/action_dispatch/middleware/callbacks.rb:28:in `call'
/Users/bensheldon/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/actionpack-7.1.0/lib/action_dispatch/middleware/executor.rb:14:in `call'
/Users/bensheldon/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/actionpack-7.1.0/lib/action_dispatch/middleware/actionable_exceptions.rb:16:in `call'
/Users/bensheldon/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/actionpack-7.1.0/lib/action_dispatch/middleware/debug_exceptions.rb:29:in `call'
/Users/bensheldon/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/web-console-4.2.1/lib/web_console/middleware.rb:132:in `call_app'
/Users/bensheldon/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/web-console-4.2.1/lib/web_console/middleware.rb:28:in `block in call'
/Users/bensheldon/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/web-console-4.2.1/lib/web_console/middleware.rb:17:in `catch'
/Users/bensheldon/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/web-console-4.2.1/lib/web_console/middleware.rb:17:in `call'
/Users/bensheldon/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/actionpack-7.1.0/lib/action_dispatch/middleware/show_exceptions.rb:31:in `call'
/Users/bensheldon/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/railties-7.1.0/lib/rails/rack/logger.rb:37:in `call_app'
/Users/bensheldon/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/railties-7.1.0/lib/rails/rack/logger.rb:24:in `block in call'
/Users/bensheldon/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activesupport-7.1.0/lib/active_support/tagged_logging.rb:135:in `block in tagged'
/Users/bensheldon/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activesupport-7.1.0/lib/active_support/tagged_logging.rb:39:in `tagged'
/Users/bensheldon/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activesupport-7.1.0/lib/active_support/tagged_logging.rb:135:in `tagged'
/Users/bensheldon/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activesupport-7.1.0/lib/active_support/broadcast_logger.rb:212:in `method_missing'
/Users/bensheldon/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/railties-7.1.0/lib/rails/rack/logger.rb:24:in `call'
/Users/bensheldon/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/sprockets-rails-3.4.2/lib/sprockets/rails/quiet_assets.rb:13:in `call'
/Users/bensheldon/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/actionpack-7.1.0/lib/action_dispatch/middleware/remote_ip.rb:92:in `call'
/Users/bensheldon/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/actionpack-7.1.0/lib/action_dispatch/middleware/request_id.rb:28:in `call'
/Users/bensheldon/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/rack-3.0.8/lib/rack/method_override.rb:28:in `call'
/Users/bensheldon/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/rack-3.0.8/lib/rack/runtime.rb:24:in `call'
/Users/bensheldon/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activesupport-7.1.0/lib/active_support/cache/strategy/local_cache_middleware.rb:29:in `call'
/Users/bensheldon/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/actionpack-7.1.0/lib/action_dispatch/middleware/server_timing.rb:59:in `block in call'
/Users/bensheldon/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/actionpack-7.1.0/lib/action_dispatch/middleware/server_timing.rb:24:in `collect_events'
/Users/bensheldon/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/actionpack-7.1.0/lib/action_dispatch/middleware/server_timing.rb:58:in `call'
/Users/bensheldon/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/actionpack-7.1.0/lib/action_dispatch/middleware/executor.rb:14:in `call'
/Users/bensheldon/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/actionpack-7.1.0/lib/action_dispatch/middleware/static.rb:25:in `call'
/Users/bensheldon/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/rack-3.0.8/lib/rack/sendfile.rb:114:in `call'
/Users/bensheldon/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/actionpack-7.1.0/lib/action_dispatch/middleware/host_authorization.rb:141:in `call'
/Users/bensheldon/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/railties-7.1.0/lib/rails/engine.rb:529:in `call'
/Users/bensheldon/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/puma-6.4.0/lib/puma/configuration.rb:272:in `call'
/Users/bensheldon/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/puma-6.4.0/lib/puma/request.rb:100:in `block in handle_request'
/Users/bensheldon/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/puma-6.4.0/lib/puma/thread_pool.rb:378:in `with_force_shutdown'
/Users/bensheldon/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/puma-6.4.0/lib/puma/request.rb:99:in `handle_request'
/Users/bensheldon/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/puma-6.4.0/lib/puma/server.rb:443:in `process_client'
/Users/bensheldon/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/puma-6.4.0/lib/puma/server.rb:241:in `block in run'
/Users/bensheldon/.rbenv/versions/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'

Our thinking is that by not having a connects_to on the model, the model is using the connection that’s used on ActiveRecord::Base. But the migration checker also uses the connection on ActiveRecord::Base to do the migration. When the temporary connection tries to disconnect and clean up, it gets stuck waiting for the currently outstanding connection to be returned to the pool. Which it can’t because that thread is stuck waiting for it to be returned to the pool.

And a thought was to fix it with with_temporary_connection_for_each so that it is ok for there to be an existing pool that can be set aside when running the migration-related queries.

Initially reported in bensheldon/good_job#1103

[eileencodes]

Our thinking is that by not having a connects_to on the model, the model is using the connection that’s used on ActiveRecord::Base. But the migration checker also uses the connection on ActiveRecord::Base to do the migration

Yea, BaseRecord inherits from the parent class, in this case ApplicationRecord which is set up to be the same connection as ActiveRecord::Base, but this would have been true in the past as well. Pending migrations check wasn't working for multiple databases until the 7.1 release so I think we would have seen this in 7.0 if it hadn't been broken. If a class doesn't set its own explicit connection, it will use whatever the next connection is in the inheritance chain, which by default will always fall back to ActiveRecord::Base.

And a thought was to fix it with with_temporary_connection_for_each so that it is ok for there to be an existing pool that can be set aside when running the migration-related queries.

I'm confused - check_pending_migrations is already using with_temporary_connection_for_each. Do you mean to use that somewhere else?

As a note, I found that this also doesn't reproduce when eager loading the application.

[eileencodes]

Also to narrow this down, the issue here isn't related to multiple databases, I can reproduce it without AnimalsRecord by just calling establish_connection in ApplicationRecord.

Edit: ok actually it's not related to AnimalsRecord but it is related to having multiple configs in the config file. I thought this was maybe related to a different issue I had fixed with migrations but it's actually a little different.

[bensheldon]

Thank you for looking into this 💖

And a thought was to fix it with with_temporary_connection_for_each so that it is ok for there to be an existing pool that can be set aside when running the migration-related queries.

I'm confused - check_pending_migrations is already using with_temporary_connection_for_each. Do you mean to use that somewhere else?

Oops, sorry, I think the notes I took from talking with @matthewd aren't great 🥵 I think the idea was: if there is already an existing database connection pool, put it aside, and then create a new database connection-pool specifically to do the migration-related queries, and then put back the original connection pool afterwards.

[eileencodes]

if there is already an existing database connection pool, put it aside, and then create a new database connection-pool specifically to do the migration-related queries, and then put back the original connection pool afterwards.

So creating a special class to run migration related queries (or anything in the rake tasks) was my original intention when adding with_temporary_connection_for_each but it's hard AF to actually get that working in the active record tests and I honestly got a little burnt out on trying to make it work. Far too much of the test framework expects ActiveRecord::Base.connection to Just Work.

My ultimate goal is to never clobber connections. I just don't know a straightforward way to get there.

[eileencodes]

Chatted with Matthew and we came up with a way to bandaid fix this particular issue (we can make a temporary class to establish connections on only for the pending migrations check). Then in 7.2/8.0 I'll fix it a better way that can't be backported. Fix incoming.

[etiennebarrie]

I'm seeing something similar in our app, which mostly doesn't use connects_to, when the code is reloaded and Active Record clears all reloadable connections:

rails/activerecord/lib/active_record/railtie.rb

Lines 301 to 310 in 26f8edf

	initializer "active_record.set_reloader_hooks" do
	ActiveSupport.on_load(:active_record) do
	ActiveSupport::Reloader.before_class_unload do
	if ActiveRecord::Base.connected?
	ActiveRecord::Base.clear_cache!
	ActiveRecord::Base.connection_handler.clear_reloadable_connections!(:all)
	end
	end
	end
	end

However, we're not seeing a deadlock but each role/pool in sequence times out "attempting to checkout all existing connections".

Removing the pending migrations check with config.active_record.migration_error = nil solves the issue, but I can't see anything in /rails/locks with the DebugLocks middleware.

I started looking at removing ActiveRecord::PendingMigrationConnection because it seemed off but that led me here.

@eileencodes Can you share the better way to fix the issue that couldn't be backported that doesn't involve having that class?