activerecord-cockroachdb-adapter activerecord: can produce a dirty read

activerecord: can produce a dirty read

Open otan opened this issue 2 years ago • 44 comments

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.

Oct 17 '21 20:10 otan

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

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

Oct 17 '21 20:10 blathers-crl[bot]

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

Oct 17 '21 22:10 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

Oct 17 '21 22:10 otan

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?

Oct 18 '21 14:10 keithdoggett

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

Oct 18 '21 14:10 keithdoggett

@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)?

Oct 18 '21 14:10 nvanbenschoten

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

Oct 18 '21 14:10 keithdoggett

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

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

Oct 18 '21 15:10 blathers-crl[bot]

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

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

Oct 18 '21 15:10 blathers-crl[bot]

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.

Oct 18 '21 15:10 nvanbenschoten

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.

Oct 18 '21 16:10 keithdoggett

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.

Oct 18 '21 18:10 rafiss

I was able to reproduce this in 1 of 40 runs of the activerecord roachtest running on 7e38d69aadb0c294bef8e3f3746ac5b1362a1041. That commit includes the fix in https://github.com/cockroachdb/cockroach/pull/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.

Oct 18 '21 19:10 nvanbenschoten

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 :\

Oct 18 '21 19:10 otan

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.

Oct 18 '21 19:10 nvanbenschoten

I have the tests running locally. I used the test file below then ran with RUBYOPT="-W0" TESTOPTS="-v" TEST_FILES=test/cases/transactions_test.rb bundle exec rake test. I have reproduced so far:

on e723a85739 2 out of 11 times (for the 9 passes i was running in-memory, and for the 2 failures i was running on disk)
on v21.2.0-beta.3 1 out of 1 time (running on disk)

Now that I have at least some sort of baseline I'll try to get this running in a script.

Code to repro:

require "cases/helper"
require "models/topic"
require "models/reply"
require "models/developer"
require "models/computer"

class TransactionTest < ActiveRecord::TestCase
  self.use_transactional_tests = false
  fixtures :topics, :developers

  def setup
    @first, @second = Topic.find(1, 2).sort_by(&:id)
  end
end

if ActiveRecord::Base.connection.supports_transaction_isolation? && !current_adapter?(:SQLite3Adapter)
  class ConcurrentTransactionTest < TransactionTest

    # This will cause transactions to overlap and fail unless they are performed on
    # separate database connections.
    def test_transaction_per_thread
      threads = 3.times.map do
        Thread.new do
          Topic.transaction do
            topic = Topic.find(1)
            topic.approved = !topic.approved?
            assert topic.save!
            topic.approved = !topic.approved?
            assert topic.save!
          end
          Topic.connection.close
        end
      end

      threads.each(&:join)
    end
    
    # 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
  end
end

Oct 18 '21 20:10 rafiss

RIP i wish i knew about the TESTOPTS='-n=/ConcurrentTransactionTest#test_transaction_isolation__read_committed/' trick before

Oct 18 '21 20:10 rafiss

@rafiss if you can get a reproduction with a crdb binary that includes https://github.com/cockroachdb/cockroach/commit/247332bc191a6d7bbcb043bf45509dc9517f78cf and is running with --vmodule=replica_evaluate=2 then I can try to piece together a timeline of how this dirty read materializes from the CRDB logs.

Oct 18 '21 20:10 nvanbenschoten

also one thing i didn't check is whether it's a dirty read, or we actually commit 200000 to be the result (which is also bad)

Oct 18 '21 20:10 otan

~Here's a debug.zip from a repro on 247332b running with --vmodule=replica_evaluate=2. I'm working on the bisect as well.~ debug.zip

Whoops.... I ran against the wrong commit

Oct 18 '21 21:10 rafiss

OK, here's the debug.zip from https://github.com/cockroachdb/cockroach/commit/247332bc191a6d7bbcb043bf45509dc9517f78cf

debug.zip

Oct 18 '21 21:10 rafiss

I see something strange in those logs. Searching for locking Get operations on what I believe to be this key, I see the following logs:

I211018 21:27:28.872583 100401 kv/kvserver/replica_evaluate.go:521 ⋮ [n1,s1,r140/1:‹/Table/10{3-4}›] 141885 evaluated Get command ‹header:<key:"\357\211\211\210" > key_locking:Exclusive›, txn="sql txn" meta={id=5b957646 pri=0.04637404 epo=0 ts=1634592448.835576000,0 min=1634592448.835576000,0 seq=0} lock=true stat=PENDING rts=1634592448.835576000,0 wto=false gul=1634592449.335576000,0 : resp=‹header:<num_keys:1 num_bytes:60 > value:<raw_bytes:"\331\315\033\035\n&\005David#\200\342\t8\254\232\357\226\014\260\255\210\255\005\030\254\232\357\226\014\260\255\210\255\005\030\254\232\357\226\014\260\255\210\255\005\030\254\232\357\226\014\260\255\...›, err=<nil>
I211018 21:27:28.932882 100401 kv/kvserver/replica_evaluate.go:521 ⋮ [n1,s1,r140/1:‹/Table/10{3-4}›] 141897 evaluated Get command ‹header:<key:"\357\211\211\210" sequence:1 > key_locking:Exclusive›, txn="sql txn" meta={id=5b957646 pri=0.04637404 epo=0 ts=1634592448.835827000,1 min=1634592448.835576000,0 seq=1} lock=true stat=PENDING rts=1634592448.835576000,0 wto=false gul=1634592449.335576000,0 : resp=‹header:<num_keys:1 num_bytes:60 > value:<raw_bytes:"\013\261\230\300\n&\005David#\200\265\0308\254\232\357\226\014\260\255\210\255\005\030\200\233\357\226\014\340\237\362\276\006\030\254\232\357\226\014\260\255\210\255\005\030\200\233\357\226\014\340\23...›, err=<nil>
I211018 21:27:29.079332 120256 kv/kvserver/replica_evaluate.go:521 ⋮ [n1,s1,r140/1:‹/Table/10{3-4}›] 141953 evaluated Get command ‹header:<key:"\357\211\211\210" > key_locking:Exclusive›, txn="sql txn" meta={id=c6e5306d pri=0.00344287 epo=0 ts=1634592448.952449000,0 min=1634592448.952449000,0 seq=0} lock=true stat=PENDING rts=1634592448.952449000,0 wto=false gul=1634592449.452449000,0 : resp=‹header:<num_keys:1 num_bytes:60 > value:<raw_bytes:"k\236ZU\n&\005David#\200\342\t8\254\232\357\226\014\260\255\210\255\005\030\200\233\357\226\014\200\361\332\370\006\030\254\232\357\226\014\260\255\210\255\005\030\200\233\357\226\014\200\361\332\370\0...›, err=<nil>
I211018 21:27:29.143491 120256 kv/kvserver/replica_evaluate.go:521 ⋮ [n1,s1,r140/1:‹/Table/10{3-4}›] 141976 evaluated Get command ‹header:<key:"\357\211\211\210" sequence:1 > key_locking:Exclusive›, txn="sql txn" meta={id=c6e5306d pri=0.00344287 epo=0 ts=1634592448.973936000,1 min=1634592448.952449000,0 seq=1} lock=true stat=PENDING rts=1634592448.952449000,0 wto=false gul=1634592449.452449000,0 : resp=‹header:<num_keys:1 num_bytes:58 > value:<raw_bytes:"\204v8[\n&\005David#\200\265\0308\254\232\357\226\014\260\255\210\255\005\030\202\233\357\226\014\260\313\321J\030\254\232\357\226\014\260\255\210\255\005\030\202\233\357\226\014\260\313\321J" timestam...›, err=<nil>
I211018 21:27:29.382816 120256 kv/kvserver/replica_evaluate.go:521 ⋮ [n1,s1,r140/1:‹/Table/10{3-4}›] 142022 evaluated Get command ‹header:<key:"\357\211\211\210" > key_locking:Exclusive›, txn="sql txn" meta={id=d43a2fcf pri=0.00201333 epo=0 ts=1634592449.381285000,0 min=1634592449.381285000,0 seq=0} lock=true stat=PENDING rts=1634592449.381285000,0 wto=false gul=1634592449.881285000,0 : resp=‹header:<num_keys:1 num_bytes:60 > value:<raw_bytes:"m#6$\n&\005David#\200\342\t8\254\232\357\226\014\260\255\210\255\005\030\202\233\357\226\014\220\315\214\207\001\030\254\232\357\226\014\260\255\210\255\005\030\202\233\357\226\014\220\315\214\207\001"...›, err=<nil>

These logs include 3 transactions. The first two read the key twice, which aligns with the two UPDATE statements. The third only reads the key once, which is surprising.

Searching then for the outcome of these three txns, we see:

# first txn
I211018 21:27:28.851557 100401 kv/kvserver/replica_evaluate.go:521 ⋮ [n1,s1,r140/1:‹/Table/10{3-4}›] 141878 evaluated Get command ‹header:<key:"\357\211\211\210" >›, txn="sql txn" meta={id=5b957646 pri=0.04637404 epo=0 ts=1634592448.835576000,0 min=1634592448.835576000,0 seq=0} lock=false stat=PENDING rts=1634592448.835576000,0 wto=false gul=1634592449.335576000,0 : resp=‹header:<num_keys:1 num_bytes:60 > value:<raw_bytes:"\331\315\033\035\n&\005David#\200\342\t8\254\232\357\226\014\260\255\210\255\005\030\254\232\357\226\014\260\255\210\255\005\030\254\232\357\226\014\260\255\210\255\005\030\254\232\357\226\014\260\255\...›, err=<nil>
I211018 21:27:28.872583 100401 kv/kvserver/replica_evaluate.go:521 ⋮ [n1,s1,r140/1:‹/Table/10{3-4}›] 141885 evaluated Get command ‹header:<key:"\357\211\211\210" > key_locking:Exclusive›, txn="sql txn" meta={id=5b957646 pri=0.04637404 epo=0 ts=1634592448.835576000,0 min=1634592448.835576000,0 seq=0} lock=true stat=PENDING rts=1634592448.835576000,0 wto=false gul=1634592449.335576000,0 : resp=‹header:<num_keys:1 num_bytes:60 > value:<raw_bytes:"\331\315\033\035\n&\005David#\200\342\t8\254\232\357\226\014\260\255\210\255\005\030\254\232\357\226\014\260\255\210\255\005\030\254\232\357\226\014\260\255\210\255\005\030\254\232\357\226\014\260\255\...›, err=<nil>
I211018 21:27:28.872810 100401 kv/kvserver/replica_evaluate.go:521 ⋮ [n1,s1,r140/1:‹/Table/10{3-4}›] 141886 evaluated Put command ‹header:<key:"\357\211\211\210" sequence:1 > value:<raw_bytes:"\013\261\230\300\n&\005David#\200\265\0308\254\232\357\226\014\260\255\210\255\005\030\200\233\357\226\014\340\237\362\276\006\030\254\232\357\226\014\260\255\210\255\005\030\200\233\357\226\...›, txn="sql txn" meta={id=5b957646 pri=0.04637404 epo=0 ts=1634592448.835827000,1 min=1634592448.835576000,0 seq=1} lock=true stat=PENDING rts=1634592448.835576000,0 wto=false gul=1634592449.335576000,0 : resp=‹header:<>›, err=<nil>
I211018 21:27:28.912699 100401 kv/kvserver/replica_evaluate.go:521 ⋮ [n1,s1,r140/1:‹/Table/10{3-4}›] 141892 evaluated QueryIntent command ‹header:<key:"\357\211\211\210" > txn:<id:5b957646-f4ae-43f7-abdc-eb6c3b948a55 key:"\357\211\211\210" write_timestamp:<wall_time:1634592448835827000 logical:1 > min_timestamp:<wall_time:1634592448835576000 > priority:995875 sequence:1 > error_if_missing:...›, txn="sql txn" meta={id=5b957646 pri=0.04637404 epo=0 ts=1634592448.835827000,1 min=1634592448.835576000,0 seq=0} lock=true stat=PENDING rts=1634592448.835576000,0 wto=false gul=1634592449.335576000,0 : resp=‹header:<> found_intent:true›, err=<nil>
I211018 21:27:28.912777 100401 kv/kvserver/replica_evaluate.go:521 ⋮ [n1,s1,r140/1:‹/Table/10{3-4}›] 141893 evaluated Get command ‹header:<key:"\357\211\211\210" sequence:1 >›, txn="sql txn" meta={id=5b957646 pri=0.04637404 epo=0 ts=1634592448.835827000,1 min=1634592448.835576000,0 seq=1} lock=true stat=PENDING rts=1634592448.835576000,0 wto=false gul=1634592449.335576000,0 : resp=‹header:<num_keys:1 num_bytes:60 > value:<raw_bytes:"\013\261\230\300\n&\005David#\200\265\0308\254\232\357\226\014\260\255\210\255\005\030\200\233\357\226\014\340\237\362\276\006\030\254\232\357\226\014\260\255\210\255\005\030\200\233\357\226\014\340\23...›, err=<nil>
I211018 21:27:28.932882 100401 kv/kvserver/replica_evaluate.go:521 ⋮ [n1,s1,r140/1:‹/Table/10{3-4}›] 141897 evaluated Get command ‹header:<key:"\357\211\211\210" sequence:1 > key_locking:Exclusive›, txn="sql txn" meta={id=5b957646 pri=0.04637404 epo=0 ts=1634592448.835827000,1 min=1634592448.835576000,0 seq=1} lock=true stat=PENDING rts=1634592448.835576000,0 wto=false gul=1634592449.335576000,0 : resp=‹header:<num_keys:1 num_bytes:60 > value:<raw_bytes:"\013\261\230\300\n&\005David#\200\265\0308\254\232\357\226\014\260\255\210\255\005\030\200\233\357\226\014\340\237\362\276\006\030\254\232\357\226\014\260\255\210\255\005\030\200\233\357\226\014\340\23...›, err=<nil>
I211018 21:27:28.933107 100401 kv/kvserver/replica_evaluate.go:521 ⋮ [n1,s1,r140/1:‹/Table/10{3-4}›] 141898 evaluated Put command ‹header:<key:"\357\211\211\210" sequence:2 > value:<raw_bytes:"k\236ZU\n&\005David#\200\342\t8\254\232\357\226\014\260\255\210\255\005\030\200\233\357\226\014\200\361\332\370\006\030\254\232\357\226\014\260\255\210\255\005\030\200\233\357\226\014\200\361...›, txn="sql txn" meta={id=5b957646 pri=0.04637404 epo=0 ts=1634592448.835827000,1 min=1634592448.835576000,0 seq=2} lock=true stat=PENDING rts=1634592448.835576000,0 wto=false gul=1634592449.335576000,0 : resp=‹header:<>›, err=<nil>
I211018 21:27:28.993963 100401 kv/kvserver/replica_evaluate.go:521 ⋮ [n1,s1,r140/1:‹/Table/10{3-4}›] 141919 evaluated QueryIntent command ‹header:<key:"\357\211\211\210" > txn:<id:5b957646-f4ae-43f7-abdc-eb6c3b948a55 key:"\357\211\211\210" write_timestamp:<wall_time:1634592448835827000 logical:1 > min_timestamp:<wall_time:1634592448835576000 > priority:995875 sequence:2 > error_if_missing:...›, txn="sql txn" meta={id=5b957646 pri=0.04637404 epo=0 ts=1634592448.835827000,1 min=1634592448.835576000,0 seq=0} lock=true stat=PENDING rts=1634592448.835576000,0 wto=false gul=1634592449.335576000,0 : resp=‹header:<> found_intent:true›, err=<nil>
I211018 21:27:28.994155 100401 kv/kvserver/replica_evaluate.go:521 ⋮ [n1,s1,r140/1:‹/Table/10{3-4}›] 141920 evaluated Get command ‹header:<key:"\357\211\211\210" sequence:2 >›, txn="sql txn" meta={id=5b957646 pri=0.04637404 epo=0 ts=1634592448.835827000,1 min=1634592448.835576000,0 seq=2} lock=true stat=PENDING rts=1634592448.835576000,0 wto=false gul=1634592449.335576000,0 : resp=‹header:<num_keys:1 num_bytes:60 > value:<raw_bytes:"k\236ZU\n&\005David#\200\342\t8\254\232\357\226\014\260\255\210\255\005\030\200\233\357\226\014\200\361\332\370\006\030\254\232\357\226\014\260\255\210\255\005\030\200\233\357\226\014\200\361\332\370\0...›, err=<nil>
I211018 21:27:28.994699 100349 kv/kvserver/replica_evaluate.go:521 ⋮ [n1,s1,r140/1:‹/Table/10{3-4}›] 141921 evaluated PushTxn command ‹header:<key:"\357\211\211\210" > pusher_txn:<meta:<id:21feff13-cf87-4301-ad4d-717c687d7a35 key:"\357\211\211\210" write_timestamp:<wall_time:1634592448835827000 > min_timestamp:<wall_time:1634592448835827000 > priority:117111 > name:"sql txn" last_heart...›, txn=<nil> : resp=‹header:<> pushee_txn:<meta:<id:5b957646-f4ae-43f7-abdc-eb6c3b948a55 key:"\357\211\211\210" write_timestamp:<wall_time:1634592448835827000 logical:1 > min_timestamp:<wall_time:1634592448835576000 > priority:995875 sequence:1 > last_heartbeat:<wall_time:1...›, err=‹failed to push meta={id=5b957646 key=/Table/103/1/1/0 pri=0.04637404 epo=0 ts=1634592448.835827000,1 min=1634592448.835576000,0 seq=1} lock=true stat=PENDING rts=0,0 wto=false gul=0,0›
I211018 21:27:28.995103 100349 kv/kvserver/replica_evaluate.go:521 ⋮ [n1,s1,r140/1:‹/Table/10{3-4}›] 141922 evaluated QueryTxn command ‹header:<key:"\357\211\211\210" > txn:<id:5b957646-f4ae-43f7-abdc-eb6c3b948a55 key:"\357\211\211\210" write_timestamp:<wall_time:1634592448835827000 logical:1 > min_timestamp:<wall_time:1634592448835576000 > priority:995875 sequence:1 >›, txn=<nil> : resp=‹header:<> queried_txn:<meta:<id:5b957646-f4ae-43f7-abdc-eb6c3b948a55 key:"\357\211\211\210" write_timestamp:<wall_time:1634592448835827000 logical:1 > min_timestamp:<wall_time:1634592448835576000 > priority:995875 sequence:1 > last_heartbeat:<wall_time:...›, err=<nil>
I211018 21:27:29.015427 100401 kv/kvserver/replica_evaluate.go:521 ⋮ [n1,s1,r140/1:‹/Table/10{3-4}›] 141924 evaluated Refresh command ‹header:<key:"\357\211\211\210" > refresh_from:<wall_time:1634592448835576000 >›, txn="sql txn" meta={id=5b957646 pri=0.04637404 epo=0 ts=1634592448.835827000,1 min=1634592448.835576000,0 seq=0} lock=true stat=PENDING rts=1634592448.835827000,1 wto=false gul=1634592449.335576000,0 : resp=‹header:<>›, err=<nil>
I211018 21:27:29.015554 100401 kv/kvserver/replica_evaluate.go:521 ⋮ [n1,s1,r140/1:‹/Table/10{3-4}›] 141925 evaluated Refresh command ‹header:<key:"\357\211\211\210" > refresh_from:<wall_time:1634592448835576000 >›, txn="sql txn" meta={id=5b957646 pri=0.04637404 epo=0 ts=1634592448.835827000,1 min=1634592448.835576000,0 seq=0} lock=true stat=PENDING rts=1634592448.835827000,1 wto=false gul=1634592449.335576000,0 : resp=‹header:<>›, err=<nil>
I211018 21:27:29.015647 100401 kv/kvserver/replica_evaluate.go:521 ⋮ [n1,s1,r140/1:‹/Table/10{3-4}›] 141926 evaluated Refresh command ‹header:<key:"\357\211\211\210" > refresh_from:<wall_time:1634592448835576000 >›, txn="sql txn" meta={id=5b957646 pri=0.04637404 epo=0 ts=1634592448.835827000,1 min=1634592448.835576000,0 seq=0} lock=true stat=PENDING rts=1634592448.835827000,1 wto=false gul=1634592449.335576000,0 : resp=‹header:<>›, err=<nil>
I211018 21:27:29.015730 100401 kv/kvserver/replica_evaluate.go:521 ⋮ [n1,s1,r140/1:‹/Table/10{3-4}›] 141928 evaluated Refresh command ‹header:<key:"\357\211\211\210" > refresh_from:<wall_time:1634592448835576000 >›, txn="sql txn" meta={id=5b957646 pri=0.04637404 epo=0 ts=1634592448.835827000,1 min=1634592448.835576000,0 seq=0} lock=true stat=PENDING rts=1634592448.835827000,1 wto=false gul=1634592449.335576000,0 : resp=‹header:<>›, err=<nil>
I211018 21:27:29.015815 100401 kv/kvserver/replica_evaluate.go:521 ⋮ [n1,s1,r140/1:‹/Table/10{3-4}›] 141929 evaluated Refresh command ‹header:<key:"\357\211\211\210" > refresh_from:<wall_time:1634592448835576000 >›, txn="sql txn" meta={id=5b957646 pri=0.04637404 epo=0 ts=1634592448.835827000,1 min=1634592448.835576000,0 seq=0} lock=true stat=PENDING rts=1634592448.835827000,1 wto=false gul=1634592449.335576000,0 : resp=‹header:<>›, err=<nil>
I211018 21:27:29.016115 100401 kv/kvserver/replica_evaluate.go:521 ⋮ [n1,s1,r140/1:‹/Table/10{3-4}›] 141930 evaluated EndTxn command ‹header:<key:"\357\211\211\210" sequence:3 > commit:true deadline:<wall_time:1634592710654402320 > lock_spans:<key:"\357\211\211\210" > txn_heartbeating:true›, txn="sql txn" meta={id=5b957646 pri=0.04637404 epo=0 ts=1634592448.835827000,1 min=1634592448.835576000,0 seq=3} lock=true stat=PENDING rts=1634592448.835827000,1 wto=false gul=1634592449.335576000,0 : resp=‹header:<txn:<meta:<id:5b957646-f4ae-43f7-abdc-eb6c3b948a55 key:"\357\211\211\210" write_timestamp:<wall_time:1634592448835827000 logical:1 > min_timestamp:<wall_time:1634592448835576000 > priority:995875 sequence:3 > name:"sql txn" status:COMMITTED last...›, err=<nil>
I211018 21:27:29.063683 121145 kv/kvserver/replica_evaluate.go:521 ⋮ [n1,s1,r140/1:‹/Table/10{3-4}›] 141942 evaluated ResolveIntent command ‹header:<key:"\357\211\211\210" > intent_txn:<id:5b957646-f4ae-43f7-abdc-eb6c3b948a55 key:"\357\211\211\210" write_timestamp:<wall_time:1634592448835827000 logical:1 > min_timestamp:<wall_time:1634592448835576000 > priority:995875 sequence:3 > status:COM...›, txn=<nil> : resp=‹header:<>›, err=<nil>

# second txn
I211018 21:27:29.057736 120256 kv/kvserver/replica_evaluate.go:521 ⋮ [n1,s1,r140/1:‹/Table/10{3-4}›] 141940 evaluated Get command ‹header:<key:"\357\211\211\210" >›, txn="sql txn" meta={id=c6e5306d pri=0.00344287 epo=0 ts=1634592448.952449000,0 min=1634592448.952449000,0 seq=0} lock=false stat=PENDING rts=1634592448.952449000,0 wto=false gul=1634592449.452449000,0 : resp=‹header:<num_keys:1 num_bytes:60 > value:<raw_bytes:"k\236ZU\n&\005David#\200\342\t8\254\232\357\226\014\260\255\210\255\005\030\200\233\357\226\014\200\361\332\370\006\030\254\232\357\226\014\260\255\210\255\005\030\200\233\357\226\014\200\361\332\370\0...›, err=<nil>
I211018 21:27:29.079332 120256 kv/kvserver/replica_evaluate.go:521 ⋮ [n1,s1,r140/1:‹/Table/10{3-4}›] 141953 evaluated Get command ‹header:<key:"\357\211\211\210" > key_locking:Exclusive›, txn="sql txn" meta={id=c6e5306d pri=0.00344287 epo=0 ts=1634592448.952449000,0 min=1634592448.952449000,0 seq=0} lock=true stat=PENDING rts=1634592448.952449000,0 wto=false gul=1634592449.452449000,0 : resp=‹header:<num_keys:1 num_bytes:60 > value:<raw_bytes:"k\236ZU\n&\005David#\200\342\t8\254\232\357\226\014\260\255\210\255\005\030\200\233\357\226\014\200\361\332\370\006\030\254\232\357\226\014\260\255\210\255\005\030\200\233\357\226\014\200\361\332\370\0...›, err=<nil>
I211018 21:27:29.079557 120256 kv/kvserver/replica_evaluate.go:521 ⋮ [n1,s1,r140/1:‹/Table/10{3-4}›] 141954 evaluated Put command ‹header:<key:"\357\211\211\210" sequence:1 > value:<raw_bytes:"\204v8[\n&\005David#\200\265\0308\254\232\357\226\014\260\255\210\255\005\030\202\233\357\226\014\260\313\321J\030\254\232\357\226\014\260\255\210\255\005\030\202\233\357\226\014\260\313\321J...›, txn="sql txn" meta={id=c6e5306d pri=0.00344287 epo=0 ts=1634592448.973936000,1 min=1634592448.952449000,0 seq=1} lock=true stat=PENDING rts=1634592448.952449000,0 wto=false gul=1634592449.452449000,0 : resp=‹header:<>›, err=<nil>
I211018 21:27:29.120400 120256 kv/kvserver/replica_evaluate.go:521 ⋮ [n1,s1,r140/1:‹/Table/10{3-4}›] 141965 evaluated QueryIntent command ‹header:<key:"\357\211\211\210" > txn:<id:c6e5306d-a19f-4bcf-8a41-4fa41b81aa36 key:"\357\211\211\210" write_timestamp:<wall_time:1634592448973936000 logical:1 > min_timestamp:<wall_time:1634592448952449000 > priority:73935 sequence:1 > error_if_missing:t...›, txn="sql txn" meta={id=c6e5306d pri=0.00344287 epo=0 ts=1634592448.973936000,1 min=1634592448.952449000,0 seq=0} lock=true stat=PENDING rts=1634592448.952449000,0 wto=false gul=1634592449.452449000,0 : resp=‹header:<> found_intent:true›, err=<nil>
I211018 21:27:29.120640 120256 kv/kvserver/replica_evaluate.go:521 ⋮ [n1,s1,r140/1:‹/Table/10{3-4}›] 141967 evaluated Get command ‹header:<key:"\357\211\211\210" sequence:1 >›, txn="sql txn" meta={id=c6e5306d pri=0.00344287 epo=0 ts=1634592448.973936000,1 min=1634592448.952449000,0 seq=1} lock=true stat=PENDING rts=1634592448.952449000,0 wto=false gul=1634592449.452449000,0 : resp=‹header:<num_keys:1 num_bytes:58 > value:<raw_bytes:"\204v8[\n&\005David#\200\265\0308\254\232\357\226\014\260\255\210\255\005\030\202\233\357\226\014\260\313\321J\030\254\232\357\226\014\260\255\210\255\005\030\202\233\357\226\014\260\313\321J" timestam...›, err=<nil>
I211018 21:27:29.143491 120256 kv/kvserver/replica_evaluate.go:521 ⋮ [n1,s1,r140/1:‹/Table/10{3-4}›] 141976 evaluated Get command ‹header:<key:"\357\211\211\210" sequence:1 > key_locking:Exclusive›, txn="sql txn" meta={id=c6e5306d pri=0.00344287 epo=0 ts=1634592448.973936000,1 min=1634592448.952449000,0 seq=1} lock=true stat=PENDING rts=1634592448.952449000,0 wto=false gul=1634592449.452449000,0 : resp=‹header:<num_keys:1 num_bytes:58 > value:<raw_bytes:"\204v8[\n&\005David#\200\265\0308\254\232\357\226\014\260\255\210\255\005\030\202\233\357\226\014\260\313\321J\030\254\232\357\226\014\260\255\210\255\005\030\202\233\357\226\014\260\313\321J" timestam...›, err=<nil>
I211018 21:27:29.143878 120256 kv/kvserver/replica_evaluate.go:521 ⋮ [n1,s1,r140/1:‹/Table/10{3-4}›] 141977 evaluated Put command ‹header:<key:"\357\211\211\210" sequence:2 > value:<raw_bytes:"m#6$\n&\005David#\200\342\t8\254\232\357\226\014\260\255\210\255\005\030\202\233\357\226\014\220\315\214\207\001\030\254\232\357\226\014\260\255\210\255\005\030\202\233\357\226\014\220\315\21...›, txn="sql txn" meta={id=c6e5306d pri=0.00344287 epo=0 ts=1634592448.973936000,1 min=1634592448.952449000,0 seq=2} lock=true stat=PENDING rts=1634592448.952449000,0 wto=false gul=1634592449.452449000,0 : resp=‹header:<>›, err=<nil>
I211018 21:27:29.188955 120256 kv/kvserver/replica_evaluate.go:521 ⋮ [n1,s1,r140/1:‹/Table/10{3-4}›] 141985 evaluated QueryIntent command ‹header:<key:"\357\211\211\210" > txn:<id:c6e5306d-a19f-4bcf-8a41-4fa41b81aa36 key:"\357\211\211\210" write_timestamp:<wall_time:1634592448973936000 logical:1 > min_timestamp:<wall_time:1634592448952449000 > priority:73935 sequence:2 > error_if_missing:t...›, txn="sql txn" meta={id=c6e5306d pri=0.00344287 epo=0 ts=1634592448.973936000,1 min=1634592448.952449000,0 seq=0} lock=true stat=PENDING rts=1634592448.952449000,0 wto=false gul=1634592449.452449000,0 : resp=‹header:<> found_intent:true›, err=<nil>
I211018 21:27:29.189175 120256 kv/kvserver/replica_evaluate.go:521 ⋮ [n1,s1,r140/1:‹/Table/10{3-4}›] 141986 evaluated Get command ‹header:<key:"\357\211\211\210" sequence:2 >›, txn="sql txn" meta={id=c6e5306d pri=0.00344287 epo=0 ts=1634592448.973936000,1 min=1634592448.952449000,0 seq=2} lock=true stat=PENDING rts=1634592448.952449000,0 wto=false gul=1634592449.452449000,0 : resp=‹header:<num_keys:1 num_bytes:60 > value:<raw_bytes:"m#6$\n&\005David#\200\342\t8\254\232\357\226\014\260\255\210\255\005\030\202\233\357\226\014\220\315\214\207\001\030\254\232\357\226\014\260\255\210\255\005\030\202\233\357\226\014\220\315\214\207\001"...›, err=<nil>
I211018 21:27:29.210480 120256 kv/kvserver/replica_evaluate.go:521 ⋮ [n1,s1,r140/1:‹/Table/10{3-4}›] 141990 evaluated Refresh command ‹header:<key:"\357\211\211\210" > refresh_from:<wall_time:1634592448952449000 >›, txn="sql txn" meta={id=c6e5306d pri=0.00344287 epo=0 ts=1634592448.973936000,1 min=1634592448.952449000,0 seq=0} lock=true stat=PENDING rts=1634592448.973936000,1 wto=false gul=1634592449.452449000,0 : resp=‹header:<>›, err=<nil>
I211018 21:27:29.210593 120256 kv/kvserver/replica_evaluate.go:521 ⋮ [n1,s1,r140/1:‹/Table/10{3-4}›] 141991 evaluated Refresh command ‹header:<key:"\357\211\211\210" > refresh_from:<wall_time:1634592448952449000 >›, txn="sql txn" meta={id=c6e5306d pri=0.00344287 epo=0 ts=1634592448.973936000,1 min=1634592448.952449000,0 seq=0} lock=true stat=PENDING rts=1634592448.973936000,1 wto=false gul=1634592449.452449000,0 : resp=‹header:<>›, err=<nil>
I211018 21:27:29.210694 120256 kv/kvserver/replica_evaluate.go:521 ⋮ [n1,s1,r140/1:‹/Table/10{3-4}›] 141992 evaluated Refresh command ‹header:<key:"\357\211\211\210" > refresh_from:<wall_time:1634592448952449000 >›, txn="sql txn" meta={id=c6e5306d pri=0.00344287 epo=0 ts=1634592448.973936000,1 min=1634592448.952449000,0 seq=0} lock=true stat=PENDING rts=1634592448.973936000,1 wto=false gul=1634592449.452449000,0 : resp=‹header:<>›, err=<nil>
I211018 21:27:29.210781 120256 kv/kvserver/replica_evaluate.go:521 ⋮ [n1,s1,r140/1:‹/Table/10{3-4}›] 141993 evaluated Refresh command ‹header:<key:"\357\211\211\210" > refresh_from:<wall_time:1634592448952449000 >›, txn="sql txn" meta={id=c6e5306d pri=0.00344287 epo=0 ts=1634592448.973936000,1 min=1634592448.952449000,0 seq=0} lock=true stat=PENDING rts=1634592448.973936000,1 wto=false gul=1634592449.452449000,0 : resp=‹header:<>›, err=<nil>
I211018 21:27:29.210866 120256 kv/kvserver/replica_evaluate.go:521 ⋮ [n1,s1,r140/1:‹/Table/10{3-4}›] 141994 evaluated Refresh command ‹header:<key:"\357\211\211\210" > refresh_from:<wall_time:1634592448952449000 >›, txn="sql txn" meta={id=c6e5306d pri=0.00344287 epo=0 ts=1634592448.973936000,1 min=1634592448.952449000,0 seq=0} lock=true stat=PENDING rts=1634592448.973936000,1 wto=false gul=1634592449.452449000,0 : resp=‹header:<>›, err=<nil>
I211018 21:27:29.211149 120256 kv/kvserver/replica_evaluate.go:521 ⋮ [n1,s1,r140/1:‹/Table/10{3-4}›] 141995 evaluated EndTxn command ‹header:<key:"\357\211\211\210" sequence:3 > commit:true deadline:<wall_time:1634592710654402320 > lock_spans:<key:"\357\211\211\210" > txn_heartbeating:true›, txn="sql txn" meta={id=c6e5306d pri=0.00344287 epo=0 ts=1634592448.973936000,1 min=1634592448.952449000,0 seq=3} lock=true stat=PENDING rts=1634592448.973936000,1 wto=false gul=1634592449.452449000,0 : resp=‹header:<txn:<meta:<id:c6e5306d-a19f-4bcf-8a41-4fa41b81aa36 key:"\357\211\211\210" write_timestamp:<wall_time:1634592448973936000 logical:1 > min_timestamp:<wall_time:1634592448952449000 > priority:73935 sequence:3 > name:"sql txn" status:COMMITTED last_...›, err=<nil>
I211018 21:27:29.275773 121221 kv/kvserver/replica_evaluate.go:521 ⋮ [n1,s1,r140/1:‹/Table/10{3-4}›] 141999 evaluated PushTxn command ‹header:<key:"\357\211\211\210" > pusher_txn:<meta:<id:62ac322d-5edb-496f-9be4-909a47f61540 write_timestamp:<wall_time:1634592449154443000 > min_timestamp:<wall_time:1634592449154443000 > priority:139364 > name:"sql txn" last_heartbeat:<wall_time:1634592...›, txn=<nil> : resp=‹header:<> pushee_txn:<meta:<id:c6e5306d-a19f-4bcf-8a41-4fa41b81aa36 key:"\357\211\211\210" write_timestamp:<wall_time:1634592448973936000 logical:1 > min_timestamp:<wall_time:1634592448952449000 > priority:73935 sequence:2 > status:ABORTED last_heartbea...›, err=<nil>
I211018 21:27:29.282255 121225 kv/kvserver/replica_evaluate.go:521 ⋮ [n1,s1,r140/1:‹/Table/10{3-4}›] 142000 evaluated ResolveIntent command ‹header:<key:"\357\211\211\210" > intent_txn:<id:c6e5306d-a19f-4bcf-8a41-4fa41b81aa36 key:"\357\211\211\210" write_timestamp:<wall_time:1634592448973936000 logical:1 > min_timestamp:<wall_time:1634592448952449000 > priority:73935 sequence:2 > status:ABOR...›, txn=<nil> : resp=‹header:<>›, err=<nil>

# third txn
I211018 21:27:29.382816 120256 kv/kvserver/replica_evaluate.go:521 ⋮ [n1,s1,r140/1:‹/Table/10{3-4}›] 142022 evaluated Get command ‹header:<key:"\357\211\211\210" > key_locking:Exclusive›, txn="sql txn" meta={id=d43a2fcf pri=0.00201333 epo=0 ts=1634592449.381285000,0 min=1634592449.381285000,0 seq=0} lock=true stat=PENDING rts=1634592449.381285000,0 wto=false gul=1634592449.881285000,0 : resp=‹header:<num_keys:1 num_bytes:60 > value:<raw_bytes:"m#6$\n&\005David#\200\342\t8\254\232\357\226\014\260\255\210\255\005\030\202\233\357\226\014\220\315\214\207\001\030\254\232\357\226\014\260\255\210\255\005\030\202\233\357\226\014\220\315\214\207\001"...›, err=<nil>
I211018 21:27:29.383091 120256 kv/kvserver/replica_evaluate.go:521 ⋮ [n1,s1,r140/1:‹/Table/10{3-4}›] 142024 evaluated Put command ‹header:<key:"\357\211\211\210" sequence:1 > value:<raw_bytes:"\213O\325\270\n&\005David#\200\265\0308\254\232\357\226\014\260\255\210\255\005\030\202\233\357\226\014\320\300\352\352\002\030\254\232\357\226\014\260\255\210\255\005\030\202\233\357\226\014...›, txn="sql txn" meta={id=d43a2fcf pri=0.00201333 epo=0 ts=1634592449.381285000,0 min=1634592449.381285000,0 seq=1} lock=true stat=PENDING rts=1634592449.381285000,0 wto=false gul=1634592449.881285000,0 : resp=‹header:<>›, err=<nil>
I211018 21:27:29.384127 120256 kv/kvserver/replica_evaluate.go:521 ⋮ [n1,s1,r140/1:‹/Table/10{3-4}›] 142026 evaluated EndTxn command ‹header:<key:"\357\211\211\210" sequence:2 > commit:true deadline:<wall_time:1634592710654402320 > lock_spans:<key:"\357\211\211\210" > in_flight_writes:<key:"\357\211\211\210" sequence:1 > txn_heartbeating:true›, txn="sql txn" meta={id=d43a2fcf pri=0.00201333 epo=0 ts=1634592449.381285000,0 min=1634592449.381285000,0 seq=2} lock=true stat=PENDING rts=1634592449.381285000,0 wto=false gul=1634592449.881285000,0 : resp=‹header:<txn:<meta:<id:d43a2fcf-e218-4cb2-83fb-d36296127c97 key:"\357\211\211\210" write_timestamp:<wall_time:1634592449381285000 > min_timestamp:<wall_time:1634592449381285000 > priority:43236 sequence:2 > name:"sql txn" status:STAGING last_heartbeat:<w...›, err=<nil>
I211018 21:27:29.404330 119563 kv/kvserver/replica_evaluate.go:521 ⋮ [n1,s1,r140/1:‹/Table/10{3-4}›] 142029 evaluated QueryIntent command ‹header:<key:"\357\211\211\210" > txn:<id:d43a2fcf-e218-4cb2-83fb-d36296127c97 key:"\357\211\211\210" write_timestamp:<wall_time:1634592449381285000 > min_timestamp:<wall_time:1634592449381285000 > priority:43236 sequence:1 > error_if_missing:true›, txn="sql txn" meta={id=d43a2fcf pri=0.00201333 epo=0 ts=1634592449.381285000,0 min=1634592449.381285000,0 seq=0} lock=true stat=PENDING rts=1634592449.381285000,0 wto=false gul=1634592449.881285000,0 : resp=‹header:<> found_intent:true›, err=<nil>
I211018 21:27:29.444995 121227 kv/kvserver/replica_evaluate.go:521 ⋮ [n1,s1,r140/1:‹/Table/10{3-4}›] 142031 evaluated EndTxn command ‹header:<key:"\357\211\211\210" > commit:true lock_spans:<key:"\357\211\211\210" >›, txn="sql txn" meta={id=d43a2fcf pri=0.00201333 epo=0 ts=1634592449.381285000,0 min=1634592449.381285000,0 seq=0} lock=true stat=STAGING rts=1634592449.381285000,0 wto=false gul=1634592449.881285000,0 int=1 ifw=1 : resp=‹header:<txn:<meta:<id:d43a2fcf-e218-4cb2-83fb-d36296127c97 key:"\357\211\211\210" write_timestamp:<wall_time:1634592449381285000 > min_timestamp:<wall_time:1634592449381285000 > priority:43236 sequence:2 > status:COMMITTED last_heartbeat:<wall_time:1634...›, err=<nil>
I211018 21:27:29.491470 121289 kv/kvserver/replica_evaluate.go:521 ⋮ [n1,s1,r140/1:‹/Table/10{3-4}›] 142035 evaluated ResolveIntent command ‹header:<key:"\357\211\211\210" > intent_txn:<id:d43a2fcf-e218-4cb2-83fb-d36296127c97 key:"\357\211\211\210" write_timestamp:<wall_time:1634592449381285000 > min_timestamp:<wall_time:1634592449381285000 > priority:43236 sequence:2 > status:COMMITTED›, txn=<nil> : resp=‹header:<>›, err=<nil>

The first two txns look like we would expect. Notice that they commit with seq num 3, meaning that they performed 2 writes (plus the EndTxn's seq num). The third txn commits with a seq num of 2, so it only performed a single write! That indicates that something strange is going on. Are we sure we're issuing two UPDATE statements for this third txn?

And there's more. Notice that the third txn has two EndTxn requests while the first two only have one. That's because the third commit is performing a parallel commit, because its Put is still in flight by the time the txn commits. This is not the case for the first two txns because they read their write (# Expect original salary) and create a pipeline stall. So this indicates that the txn in question never even got to the # Expect original salary step, and was instead committed immediately after its first UPDATE.

Oct 18 '21 22:10 nvanbenschoten

Would someone mind adding in a sanity check that we're actually reaching and then making it past the second dev.save! call?

Oct 18 '21 22:10 nvanbenschoten

Also, as another sanity check, when people are saying that they reproduced in the shell, are they seeing a salary of 200000 or of anything that is not 80000? I ask because the first time these steps are run, they are expected to return a salary of 70000 if the read is serialized before the write, because 70000 is the default value for the column.

Oct 18 '21 22:10 nvanbenschoten

I saw 200000 when I reproduced it in the shell and all of the test failures I saw had it as 200000.

Oct 18 '21 22:10 keithdoggett

I think I found the first half of this transaction:

I211018 21:27:28.851620 100349 kv/kvserver/replica_evaluate.go:521 ⋮ [n1,s1,r140/1:‹/Table/10{3-4}›] 141879 evaluated Get command ‹header:<key:"\357\211\211\210" >›, txn="sql txn" meta={id=21feff13 pri=0.00545341 epo=0 ts=1634592448.835827000,0 min=1634592448.835827000,0 seq=0} lock=false stat=PENDING rts=1634592448.835827000,0 wto=false gul=1634592449.335827000,0 : resp=‹header:<num_keys:1 num_bytes:60 > value:<raw_bytes:"\331\315\033\035\n&\005David#\200\342\t8\254\232\357\226\014\260\255\210\255\005\030\254\232\357\226\014\260\255\210\255\005\030\254\232\357\226\014\260\255\210\255\005\030\254\232\357\226\014\260\255\...›, err=<nil>
I211018 21:27:28.911843 100349 kv/kvserver/replica_evaluate.go:521 ⋮ [n1,s1,r140/1:‹/Table/10{3-4}›] 141890 evaluated Get command ‹header:<key:"\357\211\211\210" > key_locking:Exclusive›, txn="sql txn" meta={id=21feff13 pri=0.00545341 epo=0 ts=1634592448.835827000,0 min=1634592448.835827000,0 seq=0} lock=true stat=PENDING rts=1634592448.835827000,0 wto=false gul=1634592449.335827000,0 : resp=‹header:<>›, err=‹conflicting intents on /Table/103/1/1/0›
I211018 21:27:28.994699 100349 kv/kvserver/replica_evaluate.go:521 ⋮ [n1,s1,r140/1:‹/Table/10{3-4}›] 141921 evaluated PushTxn command ‹header:<key:"\357\211\211\210" > pusher_txn:<meta:<id:21feff13-cf87-4301-ad4d-717c687d7a35 key:"\357\211\211\210" write_timestamp:<wall_time:1634592448835827000 > min_timestamp:<wall_time:1634592448835827000 > priority:117111 > name:"sql txn" last_heart...›, txn=<nil> : resp=‹header:<> pushee_txn:<meta:<id:5b957646-f4ae-43f7-abdc-eb6c3b948a55 key:"\357\211\211\210" write_timestamp:<wall_time:1634592448835827000 logical:1 > min_timestamp:<wall_time:1634592448835576000 > priority:995875 sequence:1 > last_heartbeat:<wall_time:1...›, err=‹failed to push meta={id=5b957646 key=/Table/103/1/1/0 pri=0.04637404 epo=0 ts=1634592448.835827000,1 min=1634592448.835576000,0 seq=1} lock=true stat=PENDING rts=0,0 wto=false gul=0,0›
I211018 21:27:29.045930 121104 kv/kvserver/replica_evaluate.go:521 ⋮ [n1,s1,r140/1:‹/Table/10{3-4}›] 141938 evaluated QueryTxn command ‹header:<key:"\357\211\211\210" > txn:<id:21feff13-cf87-4301-ad4d-717c687d7a35 key:"\357\211\211\210" write_timestamp:<wall_time:1634592448835827000 > min_timestamp:<wall_time:1634592448835827000 > priority:117111 > wait_for_update:true›, txn=<nil> : resp=‹header:<> queried_txn:<meta:<id:21feff13-cf87-4301-ad4d-717c687d7a35 key:"\357\211\211\210" write_timestamp:<wall_time:1634592448835827000 > min_timestamp:<wall_time:1634592448835827000 > priority:117111 > last_heartbeat:<wall_time:1634592448835827000 >...›, err=<nil>
I211018 21:27:29.063822 100349 kv/kvserver/replica_evaluate.go:521 ⋮ [n1,s1,r140/1:‹/Table/10{3-4}›] 141943 evaluated Get command ‹header:<key:"\357\211\211\210" > key_locking:Exclusive›, txn="sql txn" meta={id=21feff13 pri=0.00545341 epo=0 ts=1634592448.835827000,0 min=1634592448.835827000,0 seq=0} lock=true stat=PENDING rts=1634592448.835827000,0 wto=false gul=1634592449.335827000,0 : resp=‹header:<>›, err=‹WriteTooOldError: write at timestamp 1634592448.835827000,0 too old; wrote at 1634592448.835827000,2›
I211018 21:27:29.064094 100349 kv/kvserver/replica_evaluate.go:521 ⋮ [n1,s1,r140/1:‹/Table/10{3-4}›] 141945 evaluated Refresh command ‹header:<key:"\357\211\211\210" > refresh_from:<wall_time:1634592448835827000 >›, txn="sql txn" meta={id=21feff13 pri=0.00545341 epo=0 ts=1634592448.835827000,2 min=1634592448.835827000,0 seq=0} lock=true stat=PENDING rts=1634592448.835827000,2 wto=false gul=1634592449.335827000,0 : resp=‹header:<>›, err=encountered recently written key ‹/Table/103/1/1/0› @1634592448.835827000,1
I211018 21:27:29.121109 121146 kv/kvserver/replica_evaluate.go:521 ⋮ [n1,s1,r140/1:‹/Table/10{3-4}›] 141971 evaluated EndTxn command ‹header:<key:"\357\211\211\210" sequence:1 > lock_spans:<key:"\357\211\211\210" > txn_heartbeating:true›, txn="sql txn" meta={id=21feff13 pri=0.01917826 epo=1 ts=1634592448.835827000,2 min=1634592448.835827000,0 seq=1} lock=true stat=PENDING rts=1634592448.835827000,2 wto=false gul=1634592449.335827000,0 : resp=‹header:<txn:<meta:<id:21feff13-cf87-4301-ad4d-717c687d7a35 key:"\357\211\211\210" epoch:1 write_timestamp:<wall_time:1634592448835827000 logical:2 > min_timestamp:<wall_time:1634592448835827000 > priority:411850 sequence:1 > name:"sql txn" status:ABORTE...›, err=<nil>

Notice that it hits a WriteTooOld error on the first UPDATE statement's locking Get, can't refresh, and then gets rolled back. I wonder if this somehow (on the client or server) broke the txn context and then allowed the UPDATE statement to retry and commit in a separate txn.

Oct 18 '21 22:10 nvanbenschoten

This timeline appears to be consistent with the first debug.zip @rafiss sent over.

Oct 18 '21 22:10 nvanbenschoten

@keithdoggett i'm having trouble reproducing this on shell again. i did see 200000

can you try, and paste the output of the shell as you are running the commands?

Oct 18 '21 23:10 otan

huh, i misspoke.

looks like this is a "problem" on 21.1 as well. https://github.com/cockroachdb/cockroach/issues/69080 Aug 24, master first hit Aug 12.

Oct 18 '21 23:10 otan

Sharing something strange I see in my repro from running ActiveRecord tests locally.

I'm using RUBYOPT="-W0" TESTOPTS="-v" TEST_FILES=test/cases/transactions_test.rb bundle exec rake test

The full logs are long and pasted below, but the strange part is I see:

ConcurrentTransactionTest#test_transaction_per_thread = 0.01 s = F


Failure:
ConcurrentTransactionTest#test_transaction_per_thread [/Users/rafiss/scratch/activerecord-cockroachdb-adapter/test/cases/transactions_test.rb:76]:
Expected: 80000
  Actual: 200000

as well as

ConcurrentTransactionTest#test_transaction_isolation__read_committed = 31.59 s = F


Failure:
ConcurrentTransactionTest#test_transaction_isolation__read_committed [/Users/rafiss/scratch/activerecord-cockroachdb-adapter/test/cases/transactions_test.rb:50]:
Expected: 80000
  Actual: 200000

However, I'm using the code I shared in https://github.com/cockroachdb/cockroach/issues/71652#issuecomment-946118074 -- and both line 50 and line 76 are from test_transaction_isolation__read_committed. Yet somehow the test suite is saying that line 76 caused test_transaction_per_thread to fail. That's weird and makes me wonder if the concurrency is confusing the test suite itself.

❯ RUBYOPT="-W0" TESTOPTS="-v" TEST_FILES=test/cases/transactions_test.rb bundle exec rake test
Using cockroachdb
Run options: -v --seed 41743

# Running:

#<Thread:0x00007fdc3da11618 /Users/rafiss/scratch/activerecord-cockroachdb-adapter/test/cases/transactions_test.rb:46 run> terminated with exception (report_on_exception is true):
Traceback (most recent call last):
	59: from /Users/rafiss/scratch/activerecord-cockroachdb-adapter/test/cases/transactions_test.rb:47:in `block (3 levels) in test_transaction_isolation__read_committed'
	58: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activerecord/lib/active_record/transactions.rb:209:in `transaction'
	57: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activerecord/lib/active_record/connection_adapters/abstract/database_statements.rb:320:in `transaction'
	56: from /Users/rafiss/scratch/activerecord-cockroachdb-adapter/lib/active_record/connection_adapters/cockroachdb/transaction_manager.rb:12:in `within_new_transaction'
	55: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activerecord/lib/active_record/connection_adapters/abstract/transaction.rb:317:in `within_new_transaction'
	54: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activesupport/lib/active_support/concurrency/load_interlock_aware_monitor.rb:21:in `synchronize'
	53: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activesupport/lib/active_support/concurrency/load_interlock_aware_monitor.rb:21:in `handle_interrupt'
	52: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activesupport/lib/active_support/concurrency/load_interlock_aware_monitor.rb:25:in `block in synchronize'
	51: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activesupport/lib/active_support/concurrency/load_interlock_aware_monitor.rb:25:in `handle_interrupt'
	50: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activesupport/lib/active_support/concurrency/load_interlock_aware_monitor.rb:26:in `block (2 levels) in synchronize'
	49: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activerecord/lib/active_record/connection_adapters/abstract/transaction.rb:319:in `block in within_new_transaction'
	48: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activerecord/lib/active_record/connection_adapters/abstract/database_statements.rb:320:in `block in transaction'
	47: from /Users/rafiss/scratch/activerecord-cockroachdb-adapter/test/cases/transactions_test.rb:53:in `block (4 levels) in test_transaction_isolation__read_committed'
	46: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activerecord/lib/active_record/suppressor.rb:48:in `save!'
	45: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activerecord/lib/active_record/transactions.rb:302:in `save!'
	44: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activerecord/lib/active_record/transactions.rb:350:in `with_transaction_returning_status'
	43: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activerecord/lib/active_record/connection_adapters/abstract/database_statements.rb:318:in `transaction'
	42: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activerecord/lib/active_record/transactions.rb:354:in `block in with_transaction_returning_status'
	41: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activerecord/lib/active_record/transactions.rb:302:in `block in save!'
	40: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activerecord/lib/active_record/validations.rb:53:in `save!'
	39: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activerecord/lib/active_record/persistence.rb:507:in `save!'
	38: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activerecord/lib/active_record/timestamp.rb:126:in `create_or_update'
	37: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activerecord/lib/active_record/callbacks.rb:457:in `create_or_update'
	36: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activesupport/lib/active_support/callbacks.rb:824:in `_run_save_callbacks'
	35: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activesupport/lib/active_support/callbacks.rb:137:in `run_callbacks'
	34: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activesupport/lib/active_support/callbacks.rb:126:in `block in run_callbacks'
	33: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activerecord/lib/active_record/autosave_association.rb:385:in `around_save_collection_association'
	32: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activesupport/lib/active_support/callbacks.rb:117:in `block in run_callbacks'
	31: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activerecord/lib/active_record/callbacks.rb:457:in `block in create_or_update'
	30: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activerecord/lib/active_record/persistence.rb:900:in `create_or_update'
	29: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activerecord/lib/active_record/timestamp.rb:121:in `_update_record'
	28: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activerecord/lib/active_record/callbacks.rb:465:in `_update_record'
	27: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activesupport/lib/active_support/callbacks.rb:824:in `_run_update_callbacks'
	26: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activesupport/lib/active_support/callbacks.rb:106:in `run_callbacks'
	25: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activerecord/lib/active_record/callbacks.rb:465:in `block in _update_record'
	24: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activerecord/lib/active_record/attribute_methods/dirty.rb:195:in `_update_record'
	23: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activerecord/lib/active_record/persistence.rb:913:in `_update_record'
	22: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activerecord/lib/active_record/locking/optimistic.rb:88:in `_update_row'
	21: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activerecord/lib/active_record/persistence.rb:891:in `_update_row'
	20: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activerecord/lib/active_record/persistence.rb:385:in `_update_record'
	19: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activerecord/lib/active_record/connection_adapters/abstract/query_cache.rb:22:in `update'
	18: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activerecord/lib/active_record/connection_adapters/abstract/database_statements.rb:179:in `update'
	17: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activerecord/lib/active_record/connection_adapters/postgresql/database_statements.rb:70:in `exec_delete'
	16: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activerecord/lib/active_record/connection_adapters/postgresql_adapter.rb:649:in `execute_and_clear'
	15: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activerecord/lib/active_record/connection_adapters/postgresql_adapter.rb:670:in `exec_no_cache'
	14: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activerecord/lib/active_record/connection_adapters/abstract_adapter.rb:687:in `log'
	13: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activesupport/lib/active_support/notifications/instrumenter.rb:24:in `instrument'
	12: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activerecord/lib/active_record/connection_adapters/abstract_adapter.rb:695:in `block in log'
	11: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activesupport/lib/active_support/concurrency/load_interlock_aware_monitor.rb:21:in `synchronize'
	10: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activesupport/lib/active_support/concurrency/load_interlock_aware_monitor.rb:21:in `handle_interrupt'
	 9: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activesupport/lib/active_support/concurrency/load_interlock_aware_monitor.rb:25:in `block in synchronize'
	 8: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activesupport/lib/active_support/concurrency/load_interlock_aware_monitor.rb:25:in `handle_interrupt'
	 7: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activesupport/lib/active_support/concurrency/load_interlock_aware_monitor.rb:26:in `block (2 levels) in synchronize'
	 6: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activerecord/lib/active_record/connection_adapters/abstract_adapter.rb:696:in `block (2 levels) in log'
	 5: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activerecord/lib/active_record/connection_adapters/postgresql_adapter.rb:671:in `block in exec_no_cache'
	 4: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activesupport/lib/active_support/dependencies/interlock.rb:47:in `permit_concurrent_loads'
	 3: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activesupport/lib/active_support/concurrency/share_lock.rb:187:in `yield_shares'
	 2: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activesupport/lib/active_support/dependencies/interlock.rb:48:in `block in permit_concurrent_loads'
	 1: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activerecord/lib/active_record/connection_adapters/postgresql_adapter.rb:672:in `block (2 levels) in exec_no_cache'
/Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activerecord/lib/active_record/connection_adapters/postgresql_adapter.rb:672:in `exec_params': ERROR:  restart transaction: TransactionRetryWithProtoRefreshError: WriteTooOldError: write at timestamp 1634604180.165727000,0 too old; wrote at 1634604180.166592000,2: "sql txn" meta={id=79057b8e pri=0.00185245 epo=0 ts=1634604180.166592000,2 min=1634604180.165727000,0 seq=0} lock=true stat=PENDING rts=1634604180.165727000,0 wto=false gul=1634604180.665727000,0 (PG::TRSerializationFailure)
HINT:  See: https://www.cockroachlabs.com/docs/v21.2/transaction-retry-error-reference.html
	59: from /Users/rafiss/scratch/activerecord-cockroachdb-adapter/test/cases/transactions_test.rb:47:in `block (3 levels) in test_transaction_isolation__read_committed'
	58: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activerecord/lib/active_record/transactions.rb:209:in `transaction'
	57: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activerecord/lib/active_record/connection_adapters/abstract/database_statements.rb:320:in `transaction'
	56: from /Users/rafiss/scratch/activerecord-cockroachdb-adapter/lib/active_record/connection_adapters/cockroachdb/transaction_manager.rb:12:in `within_new_transaction'
	55: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activerecord/lib/active_record/connection_adapters/abstract/transaction.rb:317:in `within_new_transaction'
	54: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activesupport/lib/active_support/concurrency/load_interlock_aware_monitor.rb:21:in `synchronize'
	53: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activesupport/lib/active_support/concurrency/load_interlock_aware_monitor.rb:21:in `handle_interrupt'
	52: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activesupport/lib/active_support/concurrency/load_interlock_aware_monitor.rb:25:in `block in synchronize'
	51: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activesupport/lib/active_support/concurrency/load_interlock_aware_monitor.rb:25:in `handle_interrupt'
	50: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activesupport/lib/active_support/concurrency/load_interlock_aware_monitor.rb:26:in `block (2 levels) in synchronize'
	49: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activerecord/lib/active_record/connection_adapters/abstract/transaction.rb:319:in `block in within_new_transaction'
	48: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activerecord/lib/active_record/connection_adapters/abstract/database_statements.rb:320:in `block in transaction'
	47: from /Users/rafiss/scratch/activerecord-cockroachdb-adapter/test/cases/transactions_test.rb:53:in `block (4 levels) in test_transaction_isolation__read_committed'
	46: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activerecord/lib/active_record/suppressor.rb:48:in `save!'
	45: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activerecord/lib/active_record/transactions.rb:302:in `save!'
	44: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activerecord/lib/active_record/transactions.rb:350:in `with_transaction_returning_status'
	43: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activerecord/lib/active_record/connection_adapters/abstract/database_statements.rb:318:in `transaction'
	42: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activerecord/lib/active_record/transactions.rb:354:in `block in with_transaction_returning_status'
	41: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activerecord/lib/active_record/transactions.rb:302:in `block in save!'
	40: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activerecord/lib/active_record/validations.rb:53:in `save!'
	39: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activerecord/lib/active_record/persistence.rb:507:in `save!'
	38: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activerecord/lib/active_record/timestamp.rb:126:in `create_or_update'
	37: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activerecord/lib/active_record/callbacks.rb:457:in `create_or_update'
	36: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activesupport/lib/active_support/callbacks.rb:824:in `_run_save_callbacks'
	35: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activesupport/lib/active_support/callbacks.rb:137:in `run_callbacks'
	34: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activesupport/lib/active_support/callbacks.rb:126:in `block in run_callbacks'
	33: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activerecord/lib/active_record/autosave_association.rb:385:in `around_save_collection_association'
	32: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activesupport/lib/active_support/callbacks.rb:117:in `block in run_callbacks'
	31: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activerecord/lib/active_record/callbacks.rb:457:in `block in create_or_update'
	30: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activerecord/lib/active_record/persistence.rb:900:in `create_or_update'
	29: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activerecord/lib/active_record/timestamp.rb:121:in `_update_record'
	28: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activerecord/lib/active_record/callbacks.rb:465:in `_update_record'
	27: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activesupport/lib/active_support/callbacks.rb:824:in `_run_update_callbacks'
	26: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activesupport/lib/active_support/callbacks.rb:106:in `run_callbacks'
	25: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activerecord/lib/active_record/callbacks.rb:465:in `block in _update_record'
	24: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activerecord/lib/active_record/attribute_methods/dirty.rb:195:in `_update_record'
	23: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activerecord/lib/active_record/persistence.rb:913:in `_update_record'
	22: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activerecord/lib/active_record/locking/optimistic.rb:88:in `_update_row'
	21: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activerecord/lib/active_record/persistence.rb:891:in `_update_row'
	20: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activerecord/lib/active_record/persistence.rb:385:in `_update_record'
	19: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activerecord/lib/active_record/connection_adapters/abstract/query_cache.rb:22:in `update'
	18: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activerecord/lib/active_record/connection_adapters/abstract/database_statements.rb:179:in `update'
	17: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activerecord/lib/active_record/connection_adapters/postgresql/database_statements.rb:70:in `exec_delete'
	16: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activerecord/lib/active_record/connection_adapters/postgresql_adapter.rb:649:in `execute_and_clear'
	15: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activerecord/lib/active_record/connection_adapters/postgresql_adapter.rb:670:in `exec_no_cache'
	14: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activerecord/lib/active_record/connection_adapters/abstract_adapter.rb:687:in `log'
	13: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activesupport/lib/active_support/notifications/instrumenter.rb:24:in `instrument'
	12: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activerecord/lib/active_record/connection_adapters/abstract_adapter.rb:695:in `block in log'
	11: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activesupport/lib/active_support/concurrency/load_interlock_aware_monitor.rb:21:in `synchronize'
	10: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activesupport/lib/active_support/concurrency/load_interlock_aware_monitor.rb:21:in `handle_interrupt'
	 9: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activesupport/lib/active_support/concurrency/load_interlock_aware_monitor.rb:25:in `block in synchronize'
	 8: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activesupport/lib/active_support/concurrency/load_interlock_aware_monitor.rb:25:in `handle_interrupt'
	 7: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activesupport/lib/active_support/concurrency/load_interlock_aware_monitor.rb:26:in `block (2 levels) in synchronize'
	 6: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activerecord/lib/active_record/connection_adapters/abstract_adapter.rb:696:in `block (2 levels) in log'
	 5: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activerecord/lib/active_record/connection_adapters/postgresql_adapter.rb:671:in `block in exec_no_cache'
	 4: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activesupport/lib/active_support/dependencies/interlock.rb:47:in `permit_concurrent_loads'
	 3: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activesupport/lib/active_support/concurrency/share_lock.rb:187:in `yield_shares'
	 2: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activesupport/lib/active_support/dependencies/interlock.rb:48:in `block in permit_concurrent_loads'
	 1: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activerecord/lib/active_record/connection_adapters/postgresql_adapter.rb:672:in `block (2 levels) in exec_no_cache'
/Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activerecord/lib/active_record/connection_adapters/postgresql_adapter.rb:672:in `exec_params': PG::TRSerializationFailure: ERROR:  restart transaction: TransactionRetryWithProtoRefreshError: WriteTooOldError: write at timestamp 1634604180.165727000,0 too old; wrote at 1634604180.166592000,2: "sql txn" meta={id=79057b8e pri=0.00185245 epo=0 ts=1634604180.166592000,2 min=1634604180.165727000,0 seq=0} lock=true stat=PENDING rts=1634604180.165727000,0 wto=false gul=1634604180.665727000,0 (ActiveRecord::SerializationFailure)
HINT:  See: https://www.cockroachlabs.com/docs/v21.2/transaction-retry-error-reference.html
	17: from /Users/rafiss/scratch/activerecord-cockroachdb-adapter/test/cases/transactions_test.rb:47:in `block (3 levels) in test_transaction_isolation__read_committed'
	16: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activerecord/lib/active_record/transactions.rb:209:in `transaction'
	15: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activerecord/lib/active_record/connection_adapters/abstract/database_statements.rb:320:in `transaction'
	14: from /Users/rafiss/scratch/activerecord-cockroachdb-adapter/lib/active_record/connection_adapters/cockroachdb/transaction_manager.rb:11:in `within_new_transaction'
	13: from /Users/rafiss/scratch/activerecord-cockroachdb-adapter/lib/active_record/connection_adapters/cockroachdb/transaction_manager.rb:20:in `rescue in within_new_transaction'
	12: from /Users/rafiss/scratch/activerecord-cockroachdb-adapter/lib/active_record/connection_adapters/cockroachdb/transaction_manager.rb:12:in `within_new_transaction'
	11: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activerecord/lib/active_record/connection_adapters/abstract/transaction.rb:317:in `within_new_transaction'
	10: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activesupport/lib/active_support/concurrency/load_interlock_aware_monitor.rb:21:in `synchronize'
	 9: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activesupport/lib/active_support/concurrency/load_interlock_aware_monitor.rb:21:in `handle_interrupt'
	 8: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activesupport/lib/active_support/concurrency/load_interlock_aware_monitor.rb:25:in `block in synchronize'
	 7: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activesupport/lib/active_support/concurrency/load_interlock_aware_monitor.rb:25:in `handle_interrupt'
	 6: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activesupport/lib/active_support/concurrency/load_interlock_aware_monitor.rb:26:in `block (2 levels) in synchronize'
	 5: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activerecord/lib/active_record/connection_adapters/abstract/transaction.rb:319:in `block in within_new_transaction'
	 4: from /Users/rafiss/scratch/activerecord-cockroachdb-adapter/lib/active_record/connection_adapters/cockroachdb/transaction_manager.rb:20:in `block in within_new_transaction'
	 3: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activerecord/lib/active_record/connection_adapters/abstract/database_statements.rb:320:in `block in transaction'
	 2: from /Users/rafiss/scratch/activerecord-cockroachdb-adapter/test/cases/transactions_test.rb:50:in `block (4 levels) in test_transaction_isolation__read_committed'
	 1: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/gems/minitest-5.14.0/lib/minitest/assertions.rb:218:in `assert_equal'
/Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/gems/minitest-5.14.0/lib/minitest/assertions.rb:183:in `assert': Expected: 80000 (Minitest::Assertion)
  Actual: 200000
ConcurrentTransactionTest#test_transaction_isolation__read_committed = 31.59 s = F


Failure:
ConcurrentTransactionTest#test_transaction_isolation__read_committed [/Users/rafiss/scratch/activerecord-cockroachdb-adapter/test/cases/transactions_test.rb:50]:
Expected: 80000
  Actual: 200000


rails test Users/rafiss/scratch/activerecord-cockroachdb-adapter/test/cases/transactions_test.rb:39

#<Thread:0x00007fdc3da113e8 /Users/rafiss/scratch/activerecord-cockroachdb-adapter/test/cases/transactions_test.rb:71 run> terminated with exception (report_on_exception is true):
Traceback (most recent call last):
	16: from /Users/rafiss/scratch/activerecord-cockroachdb-adapter/test/cases/transactions_test.rb:72:in `block (2 levels) in test_transaction_isolation__read_committed'
	15: from /Users/rafiss/scratch/activerecord-cockroachdb-adapter/test/cases/transactions_test.rb:72:in `times'
	14: from /Users/rafiss/scratch/activerecord-cockroachdb-adapter/test/cases/transactions_test.rb:74:in `block (3 levels) in test_transaction_isolation__read_committed'
	13: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activerecord/lib/active_record/transactions.rb:209:in `transaction'
	12: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activerecord/lib/active_record/connection_adapters/abstract/database_statements.rb:320:in `transaction'
	11: from /Users/rafiss/scratch/activerecord-cockroachdb-adapter/lib/active_record/connection_adapters/cockroachdb/transaction_manager.rb:12:in `within_new_transaction'
	10: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activerecord/lib/active_record/connection_adapters/abstract/transaction.rb:317:in `within_new_transaction'
	 9: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activesupport/lib/active_support/concurrency/load_interlock_aware_monitor.rb:21:in `synchronize'
	 8: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activesupport/lib/active_support/concurrency/load_interlock_aware_monitor.rb:21:in `handle_interrupt'
	 7: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activesupport/lib/active_support/concurrency/load_interlock_aware_monitor.rb:25:in `block in synchronize'
	 6: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activesupport/lib/active_support/concurrency/load_interlock_aware_monitor.rb:25:in `handle_interrupt'
	 5: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activesupport/lib/active_support/concurrency/load_interlock_aware_monitor.rb:26:in `block (2 levels) in synchronize'
	 4: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activerecord/lib/active_record/connection_adapters/abstract/transaction.rb:319:in `block in within_new_transaction'
	 3: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/bundler/gems/rails-0863d22660c2/activerecord/lib/active_record/connection_adapters/abstract/database_statements.rb:320:in `block in transaction'
	 2: from /Users/rafiss/scratch/activerecord-cockroachdb-adapter/test/cases/transactions_test.rb:76:in `block (4 levels) in test_transaction_isolation__read_committed'
	 1: from /Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/gems/minitest-5.14.0/lib/minitest/assertions.rb:218:in `assert_equal'
/Users/rafiss/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/gems/minitest-5.14.0/lib/minitest/assertions.rb:183:in `assert': Expected: 80000 (Minitest::Assertion)
  Actual: 200000
ConcurrentTransactionTest#test_transaction_per_thread = 0.01 s = F


Failure:
ConcurrentTransactionTest#test_transaction_per_thread [/Users/rafiss/scratch/activerecord-cockroachdb-adapter/test/cases/transactions_test.rb:76]:
Expected: 80000
  Actual: 200000


rails test Users/rafiss/scratch/activerecord-cockroachdb-adapter/test/cases/transactions_test.rb:21


Finished in 31.595065s, 0.0633 runs/s, 0.4115 assertions/s.
2 runs, 13 assertions, 2 failures, 0 errors, 0 skips
rake aborted!
Command failed with status (1)
/Users/rafiss/.rbenv/versions/2.7.4/bin/bundle:23:in `load'
/Users/rafiss/.rbenv/versions/2.7.4/bin/bundle:23:in `<main>'
Tasks: TOP => test => test:cockroachdb

Oct 19 '21 00:10 rafiss

activerecord-cockroachdb-adapter activerecord-cockroachdb-adapter copied to clipboard

activerecord: can produce a dirty read

activerecord-cockroachdb-adapter
activerecord-cockroachdb-adapter copied to clipboard