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鈥檒l occasionally send you account related emails.

Already on GitHub? Sign in to your account

ActiveRecord adapter: unexpected error when running in a transaction #866

Open
tjefferson08 opened this issue May 13, 2024 · 12 comments
Open
Assignees

Comments

@tjefferson08
Copy link

Calling enable_actor is not idempotent (from the application perspective)

1st time: 馃槃
2nd time: 馃槨

test "enable_actor is not idempotent" do
  actor = create(:actor)

  run_enable_in_transaction = -> {
    ActiveRecord::Base.transaction do
      Flipper.enable_actor(:foo, actor)
    end
  }

  assert_nothing_raised { run_enable_in_transaction.call }

  assert_raises(ActiveRecord::StatementInvalid) { run_enable_in_transaction.call }
end

The observed effect:
Running flipper code in a transaction can unexpectedly "poison" the transaction

As I understand it, this is because the AR adapter is relying solely on DB constraints to enforce uniqueness, whereas most rails apps combine DB constraints for uniqueness with a corresponding validation on the AR model

@jnunemaker
Copy link
Collaborator

Hi! Can you paste the full statement invalid error? We rescue ActiveRecord::RecordNotUnique (source), but maybe some other database is raising a statement invalid with a lower level unique error for some reason.

What version of rails are you using and what database?

@jnunemaker jnunemaker self-assigned this May 14, 2024
@tjefferson08
Copy link
Author

tjefferson08 commented May 14, 2024

Hi!

Here's the full error message:

PG::InFailedSqlTransaction: ERROR: current transaction is aborted, commands ignored until end of transaction block

which makes sense to me, the INSERT statement from flipper fails, which aborts the transaction

I'm using rails 7.1.3.1 and Postgres version 14.11 but I suspect it may be reproducible on other databases/versions.

@jnunemaker
Copy link
Collaborator

@tjefferson08 can you get the failure from flipper? Add a rescue around it and puts the error or something? I want to see what error is failing the transaction, because as I said above, we have a rescue for this so its idempotent, so it must be something different that is being raised that we aren't rescuing. Thanks!

@tjefferson08
Copy link
Author

something different that is being raised that we aren't rescuing

I think the "something different" is the ActiveRecord::StatementInvalid

I would not expect rescuing ActiveRecord::RecordNotUnique to also rescue ActiveRecord::StatementInvalid

I tried to get a failing test into the flipper test suite but I couldn't get any of the adapter-specific tests to run (even after following the docker-compose instructions)

@jnunemaker
Copy link
Collaborator

Where was the original test case from in the issue above? The problem is we can鈥檛 replicate it so that鈥檚 why I need you to so that I can see what is inside of the active record statement invalid because I don鈥檛 want to rescue all of those as that would lead to problems, I鈥檒l likely have to check the error message in addition to the class.

@tjefferson08
Copy link
Author

yeah rescuing StatementInvalid sounds like a bad idea for sure, lotta stuff could hide in there

the test from the report was something I cooked up within my rails app's test suite as I was troubleshooting this error (it was causing an issue in one of our controllers)

I'm still trying to get the flipper test suite to go locally, I made some progress by updating some of the docker configs

a minimal new rails app might be another avenue for reproducing

@jnunemaker
Copy link
Collaborator

@tjefferson08 could you just run it from your app again? If I can just see what the error is I can setup a test to fix it. Maybe this?

ActiveRecord::Base.transaction do
  begin
    Flipper.enable_actor(:foo, actor)
  rescue => e
    p e
    raise
  end
end

@tjefferson08
Copy link
Author

Here's the trace I get from minitest:

Running 4 tests in a single process (parallelization threshold is 50)

# Running tests with run options -n/enable_actor_is_not_idempotent/ -bv --seed 21648:


OpsAccountTest#test_enable_actor_is_not_idempotent 0.44 = E

Finished tests in 0.440565s, 2.2698 tests/s, 0.0000 assertions/s.


Error:
OpsAccountTest#test_enable_actor_is_not_idempotent:
ActiveRecord::StatementInvalid: PG::InFailedSqlTransaction: ERROR:  current transaction is aborted, commands ignored until end of transaction block

    /Users/travis/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.3.1/lib/active_record/connection_adapters/postgresql/database_statements.rb:55:in `exec'
    /Users/travis/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.3.1/lib/active_record/connection_adapters/postgresql/database_statements.rb:55:in `block (2 levels) in raw_execute'
    /Users/travis/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.3.1/lib/active_record/connection_adapters/abstract_adapter.rb:1028:in `block in with_raw_connection'
    /Users/travis/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activesupport-7.1.3.1/lib/active_support/concurrency/load_interlock_aware_monitor.rb:23:in `handle_interrupt'
    /Users/travis/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activesupport-7.1.3.1/lib/active_support/concurrency/load_interlock_aware_monitor.rb:23:in `block in synchronize'
    /Users/travis/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activesupport-7.1.3.1/lib/active_support/concurrency/load_interlock_aware_monitor.rb:19:in `handle_interrupt'
    /Users/travis/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activesupport-7.1.3.1/lib/active_support/concurrency/load_interlock_aware_monitor.rb:19:in `synchronize'
    /Users/travis/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.3.1/lib/active_record/connection_adapters/abstract_adapter.rb:1000:in `with_raw_connection'
    /Users/travis/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.3.1/lib/active_record/connection_adapters/postgresql/database_statements.rb:54:in `block in raw_execute'
    /Users/travis/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activesupport-7.1.3.1/lib/active_support/notifications/instrumenter.rb:58:in `instrument'
    /Users/travis/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.3.1/lib/active_record/connection_adapters/abstract_adapter.rb:1143:in `log'
    /Users/travis/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.3.1/lib/active_record/connection_adapters/postgresql/database_statements.rb:53:in `raw_execute'
    /Users/travis/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.3.1/lib/active_record/connection_adapters/abstract/database_statements.rb:521:in `internal_execute'
    /Users/travis/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.3.1/lib/active_record/connection_adapters/abstract/savepoints.rb:20:in `release_savepoint'
    /Users/travis/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.3.1/lib/active_record/connection_adapters/abstract/transaction.rb:359:in `commit'
    /Users/travis/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.3.1/lib/active_record/connection_adapters/abstract/transaction.rb:514:in `block in commit_transaction'
    /Users/travis/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activesupport-7.1.3.1/lib/active_support/concurrency/load_interlock_aware_monitor.rb:23:in `handle_interrupt'
    /Users/travis/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activesupport-7.1.3.1/lib/active_support/concurrency/load_interlock_aware_monitor.rb:23:in `block in synchronize'
    /Users/travis/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activesupport-7.1.3.1/lib/active_support/concurrency/load_interlock_aware_monitor.rb:19:in `handle_interrupt'
    /Users/travis/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activesupport-7.1.3.1/lib/active_support/concurrency/load_interlock_aware_monitor.rb:19:in `synchronize'
    /Users/travis/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.3.1/lib/active_record/connection_adapters/abstract/transaction.rb:503:in `commit_transaction'
    /Users/travis/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.3.1/lib/active_record/connection_adapters/abstract/transaction.rb:565:in `block in within_new_transaction'
    /Users/travis/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activesupport-7.1.3.1/lib/active_support/concurrency/load_interlock_aware_monitor.rb:23:in `handle_interrupt'
    /Users/travis/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activesupport-7.1.3.1/lib/active_support/concurrency/load_interlock_aware_monitor.rb:23:in `block in synchronize'
    /Users/travis/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activesupport-7.1.3.1/lib/active_support/concurrency/load_interlock_aware_monitor.rb:19:in `handle_interrupt'
    /Users/travis/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activesupport-7.1.3.1/lib/active_support/concurrency/load_interlock_aware_monitor.rb:19:in `synchronize'
    /Users/travis/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.3.1/lib/active_record/connection_adapters/abstract/transaction.rb:532:in `within_new_transaction'
    /Users/travis/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.3.1/lib/active_record/connection_adapters/abstract/database_statements.rb:344:in `transaction'
    /Users/travis/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.3.1/lib/active_record/transactions.rb:212:in `transaction'
    test/models/ops_account_test.rb:26:in `block in <class:OpsAccountTest>'

1 tests, 0 assertions, 0 failures, 1 errors, 0 skips

I was also able to get a failure to show up within the flipper test suite:

# spec/lib/adapters/active_record_spec.rb, added at line 66
it 'should not poision wrapping transactions' do
  flipper = Flipper.new(subject)

  actor = Struct.new(:flipper_id).new('flipper-id-123')
  flipper.enable_actor(:foo, actor)

  ActiveRecord::Base.transaction do
    2.times { flipper.enable_actor(:foo, actor) }
  end
end

I don't know why I have to run it 2 times within the transaction here 馃し

@tjefferson08
Copy link
Author

tjefferson08 commented May 14, 2024

ah OK I narrowed this down

it's not until the "next query" that the transaction explodes

it 'should not poision wrapping transactions' do
  flipper = Flipper.new(subject)

  actor = Struct.new(:flipper_id).new('flipper-id-123')
  flipper.enable_actor(:foo, actor)

  ActiveRecord::Base.transaction do
    flipper.enable_actor(:foo, actor)

    # we get here just fine!
    puts 'got here!'
    expect(true).to be true

    # whoa it's not until the next query that the transaction blows up
    # with StatementInvalid
    expect(Flipper::Adapters::ActiveRecord::Gate.count).to eq 1
    puts 'never got here!'
    expect(true).to be false
  end
end

@jnunemaker
Copy link
Collaborator

Are you using transactional fixtures? I wonder if somehow that is in play here.

@tjefferson08
Copy link
Author

the original test I provided was part of our rails app's test suite, so yes, that uses transactions to keep tests from polluting one another (rails default behavior)

but I ran that last code snippet within flipper's own test suite; hopefully you can reproduce that

@tjefferson08
Copy link
Author

@jnunemaker here's a PR with that test failing, just to be super clear

sorry, I know PR comments can sometimes be kinda indecipherable

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants