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.

Sign up for GitHub

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

Jump to bottom

Use lock syncronize on transaction rollback #73

Merged
merged 1 commit into from
Jul 12, 2024
Merged

Use lock syncronize on transaction rollback #73

merged 1 commit into from
Jul 12, 2024

Conversation

malclocke
Copy link
Contributor

We are getting intermittent failures in our code base (Rails 6.1.4 on Postgres) where occasionally database cleaner tries to rollback when there are no active transactions on the connection, resulting in the following exception:

     Failure/Error:
       DatabaseCleaner.cleaning do
         example.run
       end
 
     NoMethodError:
       undefined method `state' for nil:NilClass
     # /usr/local/bundle/gems/activerecord-6.1.4.6/lib/active_record/connection_adapters/abstract/transaction.rb:311:in `block in rollback_transaction'
     # /usr/local/bundle/gems/activesupport-6.1.4.6/lib/active_support/concurrency/load_interlock_aware_monitor.rb:26:in `block (2 levels) in synchronize'
     # /usr/local/bundle/gems/activesupport-6.1.4.6/lib/active_support/concurrency/load_interlock_aware_monitor.rb:25:in `handle_interrupt'
     # /usr/local/bundle/gems/activesupport-6.1.4.6/lib/active_support/concurrency/load_interlock_aware_monitor.rb:25:in `block in synchronize'
     # /usr/local/bundle/gems/activesupport-6.1.4.6/lib/active_support/concurrency/load_interlock_aware_monitor.rb:21:in `handle_interrupt'
     # /usr/local/bundle/gems/activesupport-6.1.4.6/lib/active_support/concurrency/load_interlock_aware_monitor.rb:21:in `synchronize'
     # /usr/local/bundle/gems/activerecord-6.1.4.6/lib/active_record/connection_adapters/abstract/transaction.rb:309:in `rollback_transaction'
     # /usr/local/bundle/gems/activerecord-6.1.4.6/lib/active_record/connection_adapters/abstract/database_statements.rb:328:in `rollback_transaction'
     # /usr/local/bundle/gems/database_cleaner-active_record-2.0.0/lib/database_cleaner/active_record/transaction.rb:17:in `block in clean'
     # /usr/local/bundle/gems/database_cleaner-active_record-2.0.0/lib/database_cleaner/active_record/transaction.rb:15:in `each'
     # /usr/local/bundle/gems/database_cleaner-active_record-2.0.0/lib/database_cleaner/active_record/transaction.rb:15:in `clean'
     # /usr/local/bundle/gems/database_cleaner-core-2.0.1/lib/database_cleaner/strategy.rb:32:in `cleaning'
     # /usr/local/lib/ruby/2.7.0/forwardable.rb:235:in `cleaning'
     # /usr/local/bundle/gems/database_cleaner-core-2.0.1/lib/database_cleaner/cleaners.rb:34:in `block (2 levels) in cleaning'
     # /usr/local/bundle/gems/database_cleaner-core-2.0.1/lib/database_cleaner/cleaners.rb:35:in `cleaning'
     # /usr/local/lib/ruby/2.7.0/forwardable.rb:235:in `cleaning'
     # ./spec/support/dbcleaner.rb:16:in `block (2 levels) in <top (required)>'
     # /usr/local/bundle/gems/rspec-core-3.11.0/lib/rspec/core/example.rb:457:in `instance_exec'
     # /usr/local/bundle/gems/rspec-core-3.11.0/lib/rspec/core/example.rb:457:in `instance_exec'
     # /usr/local/bundle/gems/rspec-core-3.11.0/lib/rspec/core/hooks.rb:390:in `execute_with'
     # /usr/local/bundle/gems/rspec-core-3.11.0/lib/rspec/core/hooks.rb:628:in `block (2 levels) in run_around_example_hooks_for'
     # /usr/local/bundle/gems/rspec-core-3.11.0/lib/rspec/core/example.rb:352:in `call'
     # /usr/local/bundle/gems/webmock-3.14.0/lib/webmock/rspec.rb:37:in `block (2 levels) in <top (required)>'
     # /usr/local/bundle/gems/rspec-core-3.11.0/lib/rspec/core/example.rb:457:in `instance_exec'
     # /usr/local/bundle/gems/rspec-core-3.11.0/lib/rspec/core/example.rb:457:in `instance_exec'
     # /usr/local/bundle/gems/rspec-core-3.11.0/lib/rspec/core/hooks.rb:390:in `execute_with'
     # /usr/local/bundle/gems/rspec-core-3.11.0/lib/rspec/core/hooks.rb:628:in `block (2 levels) in run_around_example_hooks_for'
     # /usr/local/bundle/gems/rspec-core-3.11.0/lib/rspec/core/example.rb:352:in `call'
     # /usr/local/bundle/gems/rspec-retry-0.6.2/lib/rspec/retry.rb:124:in `block in run'
     # /usr/local/bundle/gems/rspec-retry-0.6.2/lib/rspec/retry.rb:110:in `loop'
     # /usr/local/bundle/gems/rspec-retry-0.6.2/lib/rspec/retry.rb:110:in `run'
     # /usr/local/bundle/gems/rspec-retry-0.6.2/lib/rspec_ext/rspec_ext.rb:12:in `run_with_retry'
     # /usr/local/bundle/gems/rspec-retry-0.6.2/lib/rspec/retry.rb:37:in `block (2 levels) in setup'
     # /usr/local/bundle/gems/rspec-core-3.11.0/lib/rspec/core/example.rb:457:in `instance_exec'
     # /usr/local/bundle/gems/rspec-core-3.11.0/lib/rspec/core/example.rb:457:in `instance_exec'
     # /usr/local/bundle/gems/rspec-core-3.11.0/lib/rspec/core/hooks.rb:390:in `execute_with'
     # /usr/local/bundle/gems/rspec-core-3.11.0/lib/rspec/core/hooks.rb:628:in `block (2 levels) in run_around_example_hooks_for'
     # /usr/local/bundle/gems/rspec-core-3.11.0/lib/rspec/core/example.rb:352:in `call'
     # /usr/local/bundle/gems/rspec-core-3.11.0/lib/rspec/core/hooks.rb:629:in `run_around_example_hooks_for'
     # /usr/local/bundle/gems/rspec-core-3.11.0/lib/rspec/core/hooks.rb:486:in `run'
     # /usr/local/bundle/gems/rspec-core-3.11.0/lib/rspec/core/example.rb:468:in `with_around_example_hooks'
     # /usr/local/bundle/gems/rspec-core-3.11.0/lib/rspec/core/example.rb:511:in `with_around_and_singleton_context_hooks'
     # /usr/local/bundle/gems/rspec-core-3.11.0/lib/rspec/core/example.rb:259:in `run'
     # /usr/local/bundle/gems/rspec-core-3.11.0/lib/rspec/core/example_group.rb:646:in `block in run_examples'
     # /usr/local/bundle/gems/rspec-core-3.11.0/lib/rspec/core/example_group.rb:642:in `map'
     # /usr/local/bundle/gems/rspec-core-3.11.0/lib/rspec/core/example_group.rb:642:in `run_examples'
     # /usr/local/bundle/gems/rspec-core-3.11.0/lib/rspec/core/example_group.rb:607:in `run'
     # /usr/local/bundle/gems/rspec-core-3.11.0/lib/rspec/core/runner.rb:121:in `block (3 levels) in run_specs'
     # /usr/local/bundle/gems/rspec-core-3.11.0/lib/rspec/core/runner.rb:121:in `map'
     # /usr/local/bundle/gems/rspec-core-3.11.0/lib/rspec/core/runner.rb:121:in `block (2 levels) in run_specs'
     # /usr/local/bundle/gems/rspec-core-3.11.0/lib/rspec/core/configuration.rb:2068:in `with_suite_hooks'
     # /usr/local/bundle/gems/rspec-core-3.11.0/lib/rspec/core/runner.rb:116:in `block in run_specs'
     # /usr/local/bundle/gems/rspec-core-3.11.0/lib/rspec/core/reporter.rb:74:in `report'
     # /usr/local/bundle/gems/rspec-core-3.11.0/lib/rspec/core/runner.rb:115:in `run_specs'
     # /usr/local/bundle/gems/rspec-core-3.11.0/lib/rspec/core/runner.rb:89:in `run'
     # /usr/local/bundle/gems/rspec-core-3.11.0/lib/rspec/core/runner.rb:71:in `run'
     # /usr/local/bundle/gems/rspec-core-3.11.0/lib/rspec/core/runner.rb:45:in `invoke'
     # /usr/local/bundle/gems/rspec-core-3.11.0/exe/rspec:4:in `<top (required)>'
     # /usr/local/bundle/bin/rspec:23:in `load'
     # /usr/local/bundle/bin/rspec:23:in `<top (required)>'
     # /usr/local/lib/ruby/2.7.0/bundler/cli/exec.rb:63:in `load'
     # /usr/local/lib/ruby/2.7.0/bundler/cli/exec.rb:63:in `kernel_load'
     # /usr/local/lib/ruby/2.7.0/bundler/cli/exec.rb:28:in `run'
     # /usr/local/lib/ruby/2.7.0/bundler/cli.rb:476:in `exec'
     # /usr/local/lib/ruby/2.7.0/bundler/vendor/thor/lib/thor/command.rb:27:in `run'
     # /usr/local/lib/ruby/2.7.0/bundler/vendor/thor/lib/thor/invocation.rb:127:in `invoke_command'
     # /usr/local/lib/ruby/2.7.0/bundler/vendor/thor/lib/thor.rb:399:in `dispatch'
     # /usr/local/lib/ruby/2.7.0/bundler/cli.rb:30:in `dispatch'
     # /usr/local/lib/ruby/2.7.0/bundler/vendor/thor/lib/thor/base.rb:476:in `start'
     # /usr/local/lib/ruby/2.7.0/bundler/cli.rb:24:in `start'
     # /usr/local/lib/ruby/gems/2.7.0/gems/bundler-2.1.4/libexec/bundle:46:in `block in <top (required)>'
     # /usr/local/lib/ruby/2.7.0/bundler/friendly_errors.rb:123:in `with_friendly_errors'
     # /usr/local/lib/ruby/gems/2.7.0/gems/bundler-2.1.4/libexec/bundle:34:in `<top (required)>'
     # /usr/local/bin/bundle:23:in `load'
     # /usr/local/bin/bundle:23:in `<main>'

I think I have narrowed this down to a thread related race condition. We have other threads running in our test suite (ActionCable) which occasionally create transactions on a connection while database cleaner is cleaning up from a spec.

I think this is due to a race in this code:

database_cleaner-active_record/lib/database_cleaner/active_record/transaction.rb

Lines 14 to 19 in c55d0ea

def clean
connection_class.connection_pool.connections.each do |connection|
next unless connection.open_transactions > 0
connection.rollback_transaction
end
end

Where the transaction count is > 0 at the time line 16 executes, but by the time the code down in ActiveRecord gets called ...

https://github.com/rails/rails/blob/cf82c9d7826aa36f2481114961af02dbf39896dd/activerecord/lib/active_record/connection_adapters/abstract/transaction.rb#L308-L314

... the transaction from the other thread has completed and there are no longer any transactions on the connection.

The following standalone spec can reliably reproduce the issue for me (you'll need a local PG database called threadtest):

# frozen_string_literal: true

require "bundler/inline"

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

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

  gem "activerecord", "~> 6.1.4"
  gem "pg"
  gem "rspec"
  gem "database_cleaner-active_record"
end

require "active_record"
require "rspec"
require "logger"

ActiveRecord::Base.establish_connection(adapter: "postgresql", database: "threadtest")
ActiveRecord::Base.logger = Logger.new(STDOUT)

ActiveRecord::Schema.define do
  create_table :posts, force: true do |t|
  end
end

class Post < ActiveRecord::Base
end

RSpec.configure do |config|
  config.before(:suite) do
    DatabaseCleaner.strategy = :transaction
    DatabaseCleaner.clean_with(:truncation)
  end

  config.around do |example|
    DatabaseCleaner.cleaning do
      example.run
    end
  end
end

RSpec.describe "cleaning thread safety" do
  before do
    50.times do
      Thread.new {
        Post.create!
      }
    end
  end

  50.times do |i|
    example i do
      Post.create!
    end
  end
end

I don't know what the potential side effects might be, but wrapping the block in database cleaner in the same lock.synchronize causes the spec above to pass.

Use lock syncronize on transaction rollback
31e3cda 
Avoids race conditions between counting the number of open transactions
and calling rollback.
etagwerker
etagwerker approved these changes Feb 17, 2023
View reviewed changes
Copy link
Member

@etagwerker etagwerker left a comment

Choose a reason for hiding this comment

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

@malclocke Thanks for submitting this! Have you seen any side effects related to the performance of transaction cleaning? That is the only one I can think of...

Let me know!

@etagwerker etagwerker merged commit e8835a1 into DatabaseCleaner:main Jul 12, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Reviewers

@etagwerker etagwerker etagwerker approved these changes

Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

Successfully merging this pull request may close these issues.
2 participants
@malclocke @etagwerker