activerecord: can produce a dirty read

[otan]

Refs: cockroachdb/cockroach#68363 (ConcurrentTransactionTest#test_transaction_isolation__read_committed, first hit Aug 12)

Setup a table:

CREATE TABLE "developers" ("id" bigserial primary key, "name" character varying, "first_name" character varying, "salary" int DEFAULT '70000', "firm_id" bigint, "mentor_id" int, "legacy_created_at" timestamp, "legacy_updated_at" timestamp, "legacy_created_on" timestamp, "legacy_updated_on" timestamp);
 insert into developers (id) values (1);

In shell 1, type:

BEGIN;
SELECT "developers"."id", "developers"."name", "developers"."salary", "developers"."firm_id", "developers"."mentor_id", "developers"."legacy_created_at", "developers"."legacy_updated_at", "developers"."legacy_created_on", "developers"."legacy_updated_on" FROM "developers" WHERE "developers"."id" = 1 LIMIT 1;
UPDATE "developers" SET "salary" = 200000 WHERE "developers"."id" = 1;

In shell 2, run:

BEGIN;

SELECT "developers"."id", "developers"."name", "developers"."salary", "developers"."firm_id", "developers"."mentor_id", "developers"."legacy_created_at", "developers"."legacy_updated_at", "developers"."legacy_created_on", "developers"."legacy_updated_on" FROM "developers" WHERE "developers"."id" = 1 LIMIT 1;

Back to shell 1:

SELECT "developers"."id", "developers"."name", "developers"."salary", "developers"."firm_id", "developers"."mentor_id", "developers"."legacy_created_at", "developers"."legacy_updated_at", "developers"."legacy_created_on", "developers"."legacy_updated_on" FROM "developers" WHERE "developers"."id" = 1 LIMIT 1;

UPDATE "developers" SET "salary" = 80000 WHERE "developers"."id" = 1;

SELECT "developers"."id", "developers"."name", "developers"."salary", "developers"."firm_id", "developers"."mentor_id", "developers"."legacy_created_at", "developers"."legacy_updated_at", "developers"."legacy_created_on", "developers"."legacy_updated_on" FROM "developers" WHERE "developers"."id" = 1 LIMIT 1;

COMMIT;

Now in shell 2, we see a salary 200000, which is a dirty read (we never committed a salary of 200000):

SELECT "developers"."id", "developers"."name", "developers"."salary", "developers"."firm_id", "developers"."mentor_id", "developers"."legacy_created_at", "developers"."legacy_updated_at", "developers"."legacy_created_on", "developers"."legacy_updated_on" FROM "developers" WHERE "developers"."id" = 1 LIMIT 1;
;
  id | name | salary | firm_id | mentor_id | legacy_created_at | legacy_updated_at | legacy_created_on | legacy_updated_on
-----+------+--------+---------+-----------+-------------------+-------------------+-------------------+--------------------
   1 | NULL | 200000 |    NULL |      NULL | NULL              | NULL              | NULL              | NULL
(1 row)

This can take a bit of time to reproduce (i've had to do this a few times each reproduction), but an external ORM, the contributor to the ORM and I have hit it multiple times, so it is not a fluke.

[blathers-crl]

Hi @otan, please add branch-* labels to identify which branch(es) this release-blocker affects.

_{🦉 Hoot! I am a Blathers, a bot for CockroachDB. My owner is otan.}

[otan]

removing blocker for now as i haven't been able to reproduce a third time and questioning my sanity

[otan]

ruby code:

    # Test for dirty reads among simultaneous transactions.
    def test_transaction_isolation__read_committed
      # Should be invariant.
      original_salary = Developer.find(1).salary
      temporary_salary = 200000

      assert_nothing_raised do
        threads = (1..3).map do
          Thread.new do
            Developer.transaction do
              # Expect original salary.
              dev = Developer.find(1)
              assert_equal original_salary, dev.salary

              dev.salary = temporary_salary
              dev.save!

              # Expect temporary salary.
              dev = Developer.find(1)
              assert_equal temporary_salary, dev.salary

              dev.salary = original_salary
              dev.save!

              # Expect original salary.
              dev = Developer.find(1)
              assert_equal original_salary, dev.salary
            end
            Developer.connection.close
          end
        end

        # Keep our eyes peeled.
        threads << Thread.new do
          10.times do
            sleep 0.05
            Developer.transaction do
              # Always expect original salary.
              assert_equal original_salary, Developer.find(1).salary
            end
          end
          Developer.connection.close
        end

        threads.each(&:join)
      end

      assert_equal original_salary, Developer.find(1).salary
    end

have not been able to reproduce with a go equivalent, you can try https://github.com/otan-cockroach/repro71652 if you'd like

[keithdoggett]

Within the test, it happens on about 1/3 of the times I've run it and we've seen it in the CI. I was able to get it to work in a shell on the first try, but I just had a single node running instead of a cluster, so maybe that makes it easier to reproduce?

[keithdoggett]

I was able to reproduce on version 21.2.0-beta.4

[nvb]

@keithdoggett have you been able to reproduce while running just this single test, or does it require running the entire test suite? Have you been able to reproduce while running the test locally (not in CI)?

[keithdoggett]

@nvanbenschoten I can reproduce it as a single test both locally and in the CI.

[blathers-crl]

Hi @dt, please add branch-* labels to identify which branch(es) this release-blocker affects.

_{🦉 Hoot! I am a Blathers, a bot for CockroachDB. My owner is otan.}

[blathers-crl]

Hi @nvanbenschoten, please add branch-* labels to identify which branch(es) this release-blocker affects.

_{🦉 Hoot! I am a Blathers, a bot for CockroachDB. My owner is otan.}

[nvb]

Thanks @keithdoggett, that's very helpful information! @rafiss has a Ruby env set up, so he's going to see how easily he can get this to fail when stressing the single test. If the cycle time is short enough, he's going to help bisect this back to a single commit.

[keithdoggett]

That sounds good let me know if you need any help with it. It was failing often enough when running locally so hopefully it won't take too long to find the commit.

[rafiss]

Update: still working on this, but my local ruby environment had broken since the last time I used it. I should have things working locally soon.

[nvb]

I was able to reproduce this in 1 of 40 runs of the activerecord roachtest running on 7e38d69aadb0c294bef8e3f3746ac5b1362a1041. That commit includes the fix in cockroachdb/cockroach#70744, which could have been one explanation of this.

However, I have been unable to reproduce in a shell or while running with @otan's Go script: https://github.com/otan-cockroach/repro71652. I'm wondering whether that script performs txn retries in the same way as activerecord.

[otan]

if you need to speed up the AR roach test, run TEST_FILES_AR="test/cases/transactions_test.rb" TESTOPTS='-n=/ConcurrentTransactionTest#test_transaction_isolation__read_committed/' bundle exec rake test

Apparently activerecord rarely hits the ProtoRefresh error :\

[nvb]

I'm wondering whether that script performs txn retries in the same way as activerecord.

Even when using https://pkg.go.dev/github.com/cockroachdb/cockroach-go/v2/crdb, I'm still not able to reproduce in Go.