ActiveRecord::ConcurrentMigrationError with departure on fresh rails 7.1.3.4 app

[krismichalski]

I'm getting ActiveRecord::ConcurrentMigrationError: Failed to release advisory lock on fresh rails 7.1.3.4 app.

╰─ rails db:migrate
Including for_alter statements
== 20240612095004 CreateThings: migrating =====================================
-- create_table(:things)
   -> 0.0076s
== 20240612095004 CreateThings: migrated (0.0076s) ============================

bin/rails aborted!
ActiveRecord::ConcurrentMigrationError:  (ActiveRecord::ConcurrentMigrationError)

Failed to release advisory lock


Tasks: TOP => db:migrate
(See full trace by running task with --trace

Environment

macOS Sonoma 14.4.1
mySQL 8.0.34 for macos13 on arm64
pt-online-schema-change 3.5.5
ruby 3.2.2
rails 7.1.3.4
departure 6.7.0

Steps to reproduce

1. rails new departure_sample_rails_71_app -d mysql
2. Add departure to Gemfile
3. bundle install
4. rails db:create
5. rails g migration create_things
6. rails db:migrate

There will be an error, but changes in database will appear - it's possible to do rails db:rollback which reverts the changes and produces the same error.

Additional notes

There was a similar issue in the past for rails 5.2.0 - #31 - and reverting the fix for that issue (#32) fixes the problem for rails 7.1.3.4.

After adding:
config/initializers/departure_connection_base_overwrite.rb

module Departure
  class ConnectionBase < ActiveRecord::Base
    def self.establish_connection(config = nil)
      super
    end
  end

  class OriginalAdapterConnection < ConnectionBase; end
end

rails db:migrate works without issue.

The problem is in this rails method: https://github.com/rails/rails/blob/v7.1.3.4/activerecord/lib/active_record/migration.rb#L1594

      def with_advisory_lock
        lock_id = generate_migrator_advisory_lock_id

        got_lock = connection.get_advisory_lock(lock_id)
        raise ConcurrentMigrationError unless got_lock
        load_migrated # reload schema_migrations to be sure it wasn't changed by another process before we got the lock
        yield
      ensure
        if got_lock && !connection.release_advisory_lock(lock_id)
          raise ConcurrentMigrationError.new(
            ConcurrentMigrationError::RELEASE_LOCK_FAILED_MESSAGE
          )
        end
      end

In rails 7.0.8.4 connection.instance_variable_get(:@config)[:adapter] returns mysql2 before and after yield.
In rails 7.1.3.4 connection.instance_variable_get(:@config)[:adapter] returns mysql2 before yield and percona after.

Here are the logs from log/development.log during the migration:

   (0.1ms)  SELECT GET_LOCK('2327322385476548145', 0)
  ActiveRecord::SchemaMigration Load (0.2ms)  SELECT `schema_migrations`.`version` FROM `schema_migrations` ORDER BY `schema_migrations`.`version` ASC
  ActiveRecord::InternalMetadata Load (0.6ms)  SELECT * FROM `ar_internal_metadata` WHERE `ar_internal_metadata`.`key` = 'environment' ORDER BY `ar_internal_metadata`.`key` ASC LIMIT 1
Migrating to CreateThings (20240612095004)
   (0.2ms)  SET NAMES utf8mb4,  @@SESSION.sql_mode = CONCAT(CONCAT(@@sql_mode, ',STRICT_ALL_TABLES'), ',NO_AUTO_VALUE_ON_ZERO'),  @@SESSION.wait_timeout = 2147483
   (0.1ms)  SET NAMES utf8mb4,  @@SESSION.sql_mode = CONCAT(CONCAT(@@sql_mode, ',STRICT_ALL_TABLES'), ',NO_AUTO_VALUE_ON_ZERO'),  @@SESSION.wait_timeout = 2147483
   (6.2ms)  CREATE TABLE `things` (`id` bigint NOT NULL AUTO_INCREMENT PRIMARY KEY, `created_at` datetime(6) NOT NULL)
   (8.2ms)  CREATE TABLE `things` (`id` bigint NOT NULL AUTO_INCREMENT PRIMARY KEY, `created_at` datetime(6) NOT NULL)
  ActiveRecord::SchemaMigration Create (0.5ms)  INSERT INTO `schema_migrations` (`version`) VALUES ('20240612095004')
   (0.4ms)  SELECT RELEASE_LOCK('2327322385476548145')
   (1.3ms)  SELECT RELEASE_LOCK('2327322385476548145')

at some point the SQL commands are duplicated and I believe that the second RELEASE_LOCK fails and causes the error to be raised.

[nilbus]

I'm seeing this too across multiple apps at Doximity that use departure.

[brianjaustin]

@krismichalski are you sure reverting that PR works? I tried

# Make all connections in the connection pool to use PerconaAdapter
# instead of the current adapter.
def reconnect_with_percona
  ActiveRecord::Base.establish_connection(connection_config.merge(adapter: 'percona'))
end

(changed from https://github.com/departurerb/departure/blob/master/lib/departure/migration.rb#L73C1-L78C8)

and that still results in a different connection ID after reconnect_with_percona is run (and the same error). I suspect something about establish_connection changed, but I am having trouble pinning down exactly what (rails/rails#52858 would be promising, but seems to only be in effect for Rails 7.2+).

I would also not recommend that patch to work around the issue; it effectively disables running pt-online-schema-change in favour of the default Rails migration runner (I noticed this when running in a Docker container without ptosc installed). One could try using the advisory_locks for the database connection (rails/rails#33691) instead if using ptosc is still needed

[douglas]

@brianjaustin Thank you so much for your message above!

Due to this, I can confirm using the suggested patch indeed disables pt-online-schema-change, which is not ideal and could lead to dangerous situations when running migrations on large tables.

After your message, I spent a bunch of hours trying to understand what changed in Rails to cause this, and I finally found it!

The change that broke departure happened on lib/active_record/migration.rb specifically in the method with_advisory_lock.

On Rails 7.0.8.7, this is how it is defined:

      def with_advisory_lock
        lock_id = generate_migrator_advisory_lock_id

        with_advisory_lock_connection do |connection|   #   <===========================
          got_lock = connection.get_advisory_lock(lock_id)
          raise ConcurrentMigrationError unless got_lock

          load_migrated # reload schema_migrations to be sure it wasn't changed by another process before we got the lock
          yield
        ensure
          if got_lock && !connection.release_advisory_lock(lock_id)
            raise ConcurrentMigrationError.new(
              ConcurrentMigrationError::RELEASE_LOCK_FAILED_MESSAGE
            )
          end
        end
      end

      def with_advisory_lock_connection(&block)
        pool = ActiveRecord::ConnectionAdapters::ConnectionHandler.new.establish_connection(
          ActiveRecord::Base.connection_db_config
        )

        pool.with_connection(&block)
      ensure
        pool&.disconnect!
      end

And this is how it is defined on Rails 7.1:

      def with_advisory_lock
        lock_id = generate_migrator_advisory_lock_id

        got_lock = connection.get_advisory_lock(lock_id)
        raise ConcurrentMigrationError unless got_lock

        load_migrated # reload schema_migrations to be sure it wasn't changed by another process before we got the lock
        yield
      ensure
        if got_lock && !connection.release_advisory_lock(lock_id)
          raise ConcurrentMigrationError.new(
            ConcurrentMigrationError::RELEASE_LOCK_FAILED_MESSAGE
          )
        end
      end

Note that on Rails 7.0.8.7, the locking works because of the method with_advisory_lock_connection so the same connection is used to issue and release the lock, which is not the case on Rails 7.1.

Here is the Rails PR containing the abovementioned change.

I don't know exactly how to patch Departure to make it work with these changes in Rails 7.1 as it is the first time I dove this deep in Active Record, but for now, here are the options I thought about for the short term:

• Set advisory_locks: false in database.yml since the current Departure release is broken for this feature
• Return to Rails 7.0 (which may not be feasible for many folks)
• Set percona as the adapter in database.yml, as it worked for migrations since the locks are acquired and released from the same connection, but please, don't do it as there could be nasty side-effects as the adapter was not intended to be used this way.

[Austio]

Should be closed by #121