search

rails / rails

Ruby on Rails
https://rubyonrails.org
MIT License
55.56k stars 21.52k forks source link

Using `update` inside a transaction behaves differently when used in tests #44713

Open richardboehme opened 2 years ago

richardboehme commented 2 years ago

Steps to reproduce

Note: I tried using the ActiveRecord bug report template but I could not get the test case to behave like a 'normal' Rails test case (that uses transactional tests).

Expected behavior

The test and the script should print the same values for the updated database field (test2). It should not matter whether we use update or assign the attribute and use save.

Actual behavior

The test will print test for the version that uses the update method and test2 for the version that uses an assign and a save. I'm not sure if this is an actual bug or expected behavior, but it took me a lot of time to figure out why my test case was not failing (but fails on prod/dev).

I'm not into the internals of ActiveRecord but looking into the source of update I saw that there will be an additional transaction state remembered for the model (using with_transaction_returning_status which calls remember_transaction_record_state) when using update. Maybe this results in some invalid state if the update-transaction is shared with a business logic transaction above?

System configuration

Rails version: 7.0.2.3

Ruby version: 2.7.0

ghiculescu commented 2 years ago

Great report. I can replicate the issue, I can also confirm that if you add self.use_transactional_tests = false to the tests then the issue goes away.

I added some logging to the test, here's the SQL being run in the failing test:

D, [2022-03-17T10:20:49.909316 #35545] DEBUG -- :   TRANSACTION (0.0ms)  begin transaction
D, [2022-03-17T10:20:49.914272 #35545] DEBUG -- :   TRANSACTION (0.0ms)  SAVEPOINT active_record_1
D, [2022-03-17T10:20:49.914573 #35545] DEBUG -- :   ↳ test/models/test_object_test.rb:20:in `block in <class:TestObjectTest>'
D, [2022-03-17T10:20:49.915049 #35545] DEBUG -- :   TestObject Create (0.3ms)  INSERT INTO "test_objects" ("field", "timestamps", "created_at", "updated_at") VALUES (?, ?, ?, ?)  [["field", "test"], ["timestamps", nil], ["created_at", "2022-03-17 15:20:49.913840"], ["updated_at", "2022-03-17 15:20:49.913840"]]
D, [2022-03-17T10:20:49.915279 #35545] DEBUG -- :   ↳ test/models/test_object_test.rb:20:in `block in <class:TestObjectTest>'
D, [2022-03-17T10:20:49.915450 #35545] DEBUG -- :   TRANSACTION (0.0ms)  RELEASE SAVEPOINT active_record_1
D, [2022-03-17T10:20:49.915616 #35545] DEBUG -- :   ↳ test/models/test_object_test.rb:20:in `block in <class:TestObjectTest>'
D, [2022-03-17T10:20:49.916140 #35545] DEBUG -- :   TRANSACTION (0.0ms)  SAVEPOINT active_record_1
D, [2022-03-17T10:20:49.916419 #35545] DEBUG -- :   ↳ test/models/test_object_test.rb:23:in `block (2 levels) in <class:TestObjectTest>'
D, [2022-03-17T10:20:49.916585 #35545] DEBUG -- :   TestObject Update (0.1ms)  UPDATE "test_objects" SET "field" = ?, "updated_at" = ? WHERE "test_objects"."id" = ?  [["field", "test2"], ["updated_at", "2022-03-17 15:20:49.915813"], ["id", 980190967]]
D, [2022-03-17T10:20:49.916813 #35545] DEBUG -- :   ↳ test/models/test_object_test.rb:23:in `block (2 levels) in <class:TestObjectTest>'
D, [2022-03-17T10:20:49.916971 #35545] DEBUG -- :   TRANSACTION (0.0ms)  ROLLBACK TO SAVEPOINT active_record_1
D, [2022-03-17T10:20:49.917137 #35545] DEBUG -- :   ↳ test/models/test_object_test.rb:22:in `block in <class:TestObjectTest>'
D, [2022-03-17T10:20:49.917581 #35545] DEBUG -- :   TRANSACTION (0.0ms)  SAVEPOINT active_record_1
D, [2022-03-17T10:20:49.917855 #35545] DEBUG -- :   ↳ test/models/test_object_test.rb:26:in `block in <class:TestObjectTest>'
D, [2022-03-17T10:20:49.917999 #35545] DEBUG -- :   TestObject Update (0.1ms)  UPDATE "test_objects" SET "updated_at" = ? WHERE "test_objects"."id" = ?  [["updated_at", "2022-03-17 15:20:49.917213"], ["id", 980190967]]
D, [2022-03-17T10:20:49.918222 #35545] DEBUG -- :   ↳ test/models/test_object_test.rb:26:in `block in <class:TestObjectTest>'
D, [2022-03-17T10:20:49.918361 #35545] DEBUG -- :   TRANSACTION (0.0ms)  RELEASE SAVEPOINT active_record_1
D, [2022-03-17T10:20:49.918516 #35545] DEBUG -- :   ↳ test/models/test_object_test.rb:26:in `block in <class:TestObjectTest>'
D, [2022-03-17T10:20:49.919008 #35545] DEBUG -- :   TestObject Load (0.1ms)  SELECT "test_objects".* FROM "test_objects" WHERE "test_objects"."id" = ? LIMIT ?  [["id", 980190967], ["LIMIT", 1]]
D, [2022-03-17T10:20:49.919211 #35545] DEBUG -- :   ↳ test/models/test_object_test.rb:28:in `block in <class:TestObjectTest>'
D, [2022-03-17T10:20:49.919756 #35545] DEBUG -- :   TRANSACTION (0.3ms)  rollback transaction
F

Failure:
TestObjectTest#test_dirty_transactions_with_update [/Users/alex/Code/rails-dirty-transaction-update/test/models/test_object_test.rb:28]:
Expected: "test2"
  Actual: "test"

And in the passing test:

D, [2022-03-17T10:20:49.920437 #35545] DEBUG -- :   TRANSACTION (0.0ms)  begin transaction
D, [2022-03-17T10:20:49.921111 #35545] DEBUG -- :   TRANSACTION (0.0ms)  SAVEPOINT active_record_1
D, [2022-03-17T10:20:49.921376 #35545] DEBUG -- :   ↳ test/models/test_object_test.rb:7:in `block in <class:TestObjectTest>'
D, [2022-03-17T10:20:49.921774 #35545] DEBUG -- :   TestObject Create (0.3ms)  INSERT INTO "test_objects" ("field", "timestamps", "created_at", "updated_at") VALUES (?, ?, ?, ?)  [["field", "test"], ["timestamps", nil], ["created_at", "2022-03-17 15:20:49.920881"], ["updated_at", "2022-03-17 15:20:49.920881"]]
D, [2022-03-17T10:20:49.921997 #35545] DEBUG -- :   ↳ test/models/test_object_test.rb:7:in `block in <class:TestObjectTest>'
D, [2022-03-17T10:20:49.933194 #35545] DEBUG -- :   TRANSACTION (0.1ms)  RELEASE SAVEPOINT active_record_1
D, [2022-03-17T10:20:49.933397 #35545] DEBUG -- :   ↳ test/models/test_object_test.rb:7:in `block in <class:TestObjectTest>'
D, [2022-03-17T10:20:49.933877 #35545] DEBUG -- :   TRANSACTION (0.0ms)  SAVEPOINT active_record_1
D, [2022-03-17T10:20:49.934121 #35545] DEBUG -- :   ↳ test/models/test_object_test.rb:11:in `block (2 levels) in <class:TestObjectTest>'
D, [2022-03-17T10:20:49.934296 #35545] DEBUG -- :   TestObject Update (0.1ms)  UPDATE "test_objects" SET "field" = ?, "updated_at" = ? WHERE "test_objects"."id" = ?  [["field", "test2"], ["updated_at", "2022-03-17 15:20:49.933576"], ["id", 980190967]]
D, [2022-03-17T10:20:49.934487 #35545] DEBUG -- :   ↳ test/models/test_object_test.rb:11:in `block (2 levels) in <class:TestObjectTest>'
D, [2022-03-17T10:20:49.934629 #35545] DEBUG -- :   TRANSACTION (0.0ms)  ROLLBACK TO SAVEPOINT active_record_1
D, [2022-03-17T10:20:49.934787 #35545] DEBUG -- :   ↳ test/models/test_object_test.rb:9:in `block in <class:TestObjectTest>'
D, [2022-03-17T10:20:49.935228 #35545] DEBUG -- :   TRANSACTION (0.0ms)  SAVEPOINT active_record_1
D, [2022-03-17T10:20:49.935486 #35545] DEBUG -- :   ↳ test/models/test_object_test.rb:14:in `block in <class:TestObjectTest>'
D, [2022-03-17T10:20:49.935627 #35545] DEBUG -- :   TestObject Update (0.0ms)  UPDATE "test_objects" SET "field" = ?, "updated_at" = ? WHERE "test_objects"."id" = ?  [["field", "test2"], ["updated_at", "2022-03-17 15:20:49.934894"], ["id", 980190967]]
D, [2022-03-17T10:20:49.935868 #35545] DEBUG -- :   ↳ test/models/test_object_test.rb:14:in `block in <class:TestObjectTest>'
D, [2022-03-17T10:20:49.935988 #35545] DEBUG -- :   TRANSACTION (0.0ms)  RELEASE SAVEPOINT active_record_1
D, [2022-03-17T10:20:49.936133 #35545] DEBUG -- :   ↳ test/models/test_object_test.rb:14:in `block in <class:TestObjectTest>'
D, [2022-03-17T10:20:49.936492 #35545] DEBUG -- :   TestObject Load (0.0ms)  SELECT "test_objects".* FROM "test_objects" WHERE "test_objects"."id" = ? LIMIT ?  [["id", 980190967], ["LIMIT", 1]]
D, [2022-03-17T10:20:49.936716 #35545] DEBUG -- :   ↳ test/models/test_object_test.rb:16:in `block in <class:TestObjectTest>'
D, [2022-03-17T10:20:49.937185 #35545] DEBUG -- :   TRANSACTION (0.3ms)  rollback transaction

I think the key is this, in the passing test:

D, [2022-03-17T10:20:49.935627 #35545] DEBUG -- :   TestObject Update (0.0ms)  UPDATE "test_objects" SET "field" = ?, "updated_at" = ? WHERE "test_objects"."id" = ?  [["field", "test2"], ["updated_at", "2022-03-17 15:20:49.934894"], ["id", 980190967]]
D, [2022-03-17T10:20:49.935868 #35545] DEBUG -- :   ↳ test/models/test_object_test.rb:14:in `block in <class:TestObjectTest>'

Basically the "test2" change is being rolled back, but then when you do test.update(updated_at: Time.current) it's being saved again. If you remove that line from both tests, they both end in the same state (field = "test").

This makes me wonder...

The test and the script should print the same values for the updated database field (test2).

Why do you expect this? The change to field is rolled back. Is it because of the seemingly-unrelated change to updated_at? (I agree there's probably a bug here since the behaviour is different between test and the runner, I just want to make sure we're on the same page about what the expected behaviour is.)

richardboehme commented 2 years ago

Basically the "test2" change is being rolled back, but then when you do test.update(updated_at: Time.current) it's being saved again. If you remove that line from both tests, they both end in the same state (field = "test").

This makes me wonder...

The test and the script should print the same values for the updated database field (test2).

Why do you expect this? The change to field is rolled back. Is it because of the seemingly-unrelated change to updated_at? (I agree there's probably a bug here since the behaviour is different between test and the runner, I just want to make sure we're on the same page about what the expected behaviour is.)

Thanks for looking into this!

As far as I know if we rollback a transaction the model itself is not being "rolled" back. This is why I assume that the model stays with field = "test2". It just was not updated in the database because of the rollback. The second update then implicitly updates the "field" column. This is exactly what happend in one of our code bases (by accident). I wanted to write a test for it and it magically passed even though I did not change the behavior. This is how I noticed, that there must be a difference between running this in a test and running it in dev/prod.

I agree it's kind of unexpected that the update of the updated_at column would update the field column as well but, looking at the implementation of update, it kind of makes sense.

ghiculescu commented 2 years ago

Ahh yep i suppose that makes sense. The object isn't being rolled back, but changes is resetting.

class TestObjectTest < ActiveSupport::TestCase
  test 'dirty transactions with save' do
    test = TestObject.create(field: 'test')

    ActiveRecord::Base.transaction do # Transaction by business logic
      test.field = 'test2'
      test.save
      raise ActiveRecord::Rollback # something fails
    end
    assert_equal "test2", test.field
    assert test.changes.key?("field")
    test.update(updated_at: Time.current)

    assert_equal "test2", test.reload.field
  end

  test 'dirty transactions with update' do
    test = TestObject.create(field: 'test')

    ActiveRecord::Base.transaction do # Transaction by business logic
      test.update(field: 'test2')
      raise ActiveRecord::Rollback # something fails
    end
    assert_equal "test2", test.field
    assert test.changes.key?("field"), test.changes # fails here, changes is {}
    test.update(updated_at: Time.current)

    assert_equal "test2", test.reload.field
  end
end
richardboehme commented 2 years ago

Yeah it seems like this is the problem... This is why the save called by the second update does not pick it up.

ghiculescu commented 2 years ago

A few more observations:

All the rollbacks go through here: https://github.com/rails/rails/blob/0169d15bc7ec4557971d6ac6120e48b2cac9c407/activerecord/lib/active_record/connection_adapters/abstract/transaction.rb#L156

In test, full_rollback? is false, because a SavepointTransaction is being used, presumably because you're already inside a transaction (from the test) so the stack isn't empty: https://github.com/rails/rails/blob/0169d15bc7ec4557971d6ac6120e48b2cac9c407/activerecord/lib/active_record/connection_adapters/abstract/transaction.rb#L303..L319

In the rails runner, full_rollback? is true and a RealTransaction is being used.

This matters because this force param eventually ends up here: https://github.com/rails/rails/blob/18707ab17fa492eb25ad2e8f9818a320dc20b823/activerecord/lib/active_record/transactions.rb#L398

And I think that's why changes isn't being reset and is ending up as {} - the mutation reset happens in that method.

richardboehme commented 2 years ago

Interesting... It uses the SavepointTransaction because DBMS like postgreSQL do not support nested transactions, right?

I wonder why it works with assign + save though. I guess the difference is, that update calls with_transaction_returning_status before assigning the attributes, while the other method will only call with_transaction_returning_status when calling save (after the attribute was already set).

With this information I could reproduce the problem outside of tests, using this script:

test = TestObject.create(field: 'bar')
test.transaction do
  test.transaction(requires_new: true) do
    test.update(field: 'foo')
    raise ActiveRecord::Rollback
  end
  puts test.changes.key?("field")
end

We would expect test.changes.key?("field") to be true but it returns false. I wonder how this can be fixed though...

ghiculescu commented 2 years ago

This patch makes all your tests pass (both in test and via the runner): https://github.com/rails/rails/compare/main...ghiculescu:double-transaction-in-test

The issue is that remember_transaction_record_state was being called twice on the update path. Once from update, once from save. This means @_start_transaction_state[:level] += 1 was called twice, which then means that the check in restore_transaction_record_state failed so it would never restore anything. Everything else in remember_transaction_record_state is idempotent, so a better fix might be to make the incrementing thing also idempotent... I just don't see any neater ways to do it.

richardboehme commented 2 years ago

This patch makes all your tests pass (both in test and via the runner):

That's super cool! I already thought about this double transaction that we do in update might be a problem. With your explanation this whole think starts to make a lot of sense!

rails-bot[bot] commented 2 years ago

This issue has been automatically marked as stale because it has not been commented on for at least three months. The resources of the Rails team are limited, and so we are asking for your help. If you can still reproduce this error on the 7-0-stable branch or on main, please reply with all of the information you have about it in order to keep the issue open. Thank you for all your contributions.