Search code examples
ruby-on-railsactiverecordpsqlpuma

Rails 5.1.4 + psql, ActiveRecord bizarre double transaction BEGIN, when expecting one

What I thought was an issue with a rack-timeout setting is actually an issue with ActiveRecord::Base.transaction

When a request hits one of our update endpoints and that update is handled in a transaction

for even something as simple as

def update
  ActiveRecord::Base.transaction do
    @note.find(params[:id])
    @note.update(text: "foo")
  end
end

Our server logs look like the following:

started /foo
BEGIN
BEGIN
UPDATE
COMMIT

one would expect:

started /foo
BEGIN
UPDATE
COMMIT

Issue is then when a error happens all transactions are not being rolled back. Our Logs look like:

started /foo
BEGIN
BEGIN
UPDATE
COMMIT
ROLLBACK

Instead of:

started /foo
BEGIN
UPDATE
ROLLBACK

Weird part

In development mode when we edit any rails file in any way. The action works as expected with one BEGIN. On a restart of the server there are two BEGINs. Also this only happens when in a controller, not in console, not even calling the controller in the console. which can be done:

rails c
# app#action "path"
app.put "/foo"
  • This issue is present on a fresh start of a server(rails s), but if I edit any part of the code and rails reloads the code base the action acts as expected.
  • Also this is only happening though controllers, taking the same code block and sticking it in a resque job, it works as expected.
  • Calling the endpoint from the console app.put "/note" works as expected.
  • Calling note.update works as expected
  • Rspec controller and integration tests work as expected.
  • Note.transaction works as expected, though double BEGIN is still present in logs

  • Note.last.update works as expected, though double BEGIN is still present in logs

  • ActiveRecord::Base.transaction does NOT work as expected.

Rails 5.1.4

Has any one seen an issue like this before? Is the possibly a AR setting or maybe introduced from a gem?

In the request that has two begin blocks The first begin is the transaction that we are opening in the controller. SO where is the 2nd pre update coming from begin coming from?

UPDATE

I opened a issue on ActiveRecord here. I will summarize it here.

The reason I think this might, though loosely an AR issue is the fact the 2nd BEGIN is actually from update method which uses a transaction.

Stack traces from lib/active_record/connection_adapters/postgresql/database_statements.rb:ln 130 I added an puts caller here for the last time it is being called before the update statement is called, in this case:

2 for our app 1 for the other rails app.

Our App

    active_record/connection_adapters/abstract/transaction.rb:130:in `initialize'
active_record/connection_adapters/abstract/transaction.rb:156:in `new'
active_record/connection_adapters/abstract/transaction.rb:156:in `block in begin_transaction'
monitor.rb:226:in `mon_synchronize'
active_record/connection_adapters/abstract/transaction.rb:152:in `begin_transaction'
active_record/connection_adapters/abstract/transaction.rb:193:in `block in within_new_transaction'
monitor.rb:226:in `mon_synchronize'
active_record/connection_adapters/abstract/transaction.rb:191:in `within_new_transaction'
active_record/connection_adapters/abstract/database_statements.rb:235:in `transaction'
active_record/transactions.rb:210:in `transaction'
active_record/transactions.rb:381:in `with_transaction_returning_status'
active_record/persistence.rb:283:in `update'
app/controllers/debugging_transactions_controller.rb:18:in `block in update'
active_record/connection_adapters/abstract/database_statements.rb:235:in `block in transaction' <<<<<<<<
active_record/connection_adapters/abstract/transaction.rb:194:in `block in within_new_transaction'
monitor.rb:226:in `mon_synchronize'
active_record/connection_adapters/abstract/transaction.rb:191:in `within_new_transaction'
active_record/connection_adapters/abstract/database_statements.rb:235:in `transaction'
active_record/transactions.rb:210:in `transaction'
app/controllers/debugging_transactions_controller.rb:12:in `update' #ActiveRecord::Base.transaction do

New Rails Application, with duplicate Gemfile and Gemfile.lock file.

active_record/connection_adapters/abstract/transaction.rb:130:in `initialize'
active_record/connection_adapters/abstract/transaction.rb:156:in `new'
active_record/connection_adapters/abstract/transaction.rb:156:in `block in begin_transaction'
monitor.rb:226:in `mon_synchronize'
active_record/connection_adapters/abstract/transaction.rb:152:in `begin_transaction' <<<<<<<<<
active_record/connection_adapters/abstract/transaction.rb:193:in `block in within_new_transaction'
monitor.rb:226:in `mon_synchronize'
active_record/connection_adapters/abstract/transaction.rb:191:in `within_new_transaction'
active_record/connection_adapters/abstract/database_statements.rb:235:in `transaction'
active_record/transactions.rb:210:in `transaction'
app/controllers/debugging_transactions_controller.rb:11:in `update' # ActiveRecord::Base.transaction do

Our app is hitting the update action of the persistance.rb which does wrap the action in a transaction but why?

Update I figured out the what but not the why.

https://github.com/rails/rails/blob/813af4655f9bf3c712cf50205eebd337070cee52/activerecord/lib/active_record/connection_adapters/abstract/transaction.rb#L151 The 1nd time this is called in a normal rails app The transaction @stack.size is 0 and AR uses a RealTransaction which is joinable. which then in https://github.com/rails/rails/blob/813af4655f9bf3c712cf50205eebd337070cee52/activerecord/lib/active_record/connection_adapters/abstract/database_statements.rb#L228

A RealTransaction is joinable and so rails runs the yield(your block)

In our application the stack size is zero and it is using a NullTransaction. Which is not joinable which then causes AR to wrap model.update aka with_transaction_returning_status in an entirely new transaction. Seems like this is a threading issue or perhaps a connection issue??

Solution

  • So I Figured this out. It was a puma worker configuration which was I believe was causing weird thread/ double connection issues.

    In our config/puma.rb file we had

    on_worker_boot do
  ApplicationRecord.establish_connection if defined?(ActiveRecord)
end

    Changing it to this fixed the issue.

    on_worker_boot do
  ActiveRecord::Base.establish_connection if defined?(ActiveRecord)
end

    Odd that ApplicationRecord#establish_connection != ActiveRecord::Base#establish_connection