kv/kvnemesis.TestKVNemesisMultiNode: TestKVNemesisMultiNode failed [self-recovery failure after failed retry]

[cockroach-teamcity]

kv/kvnemesis.TestKVNemesisMultiNode.TestKVNemesisMultiNode failed with artifacts on refs/heads/master @ 98557a6304fe239582e20ebd07f69a3ee8e47bdf:

          txn.ReverseScanForShare(ctx, tk(150279950105922776), tk(6930469441433212056), 0) // @1761956315.233667124,0 (/Table/100/"39744de6072938a7":v17, /Table/100/"2c415b07203002af":v38, /Table/100/"2431f91b19468f75":v21, /Table/100/"233d062b5a126223":v35, /Table/100/"025a2f792d823b85":v29, <nil>)
          txn.GetForShareSkipLocked(ctx, tk(923986943858865290)) // @1761956315.236935078,0 (<nil>, <nil>)
          txn.Get(ctx, tk(1461535347902648743)) // @1761956315.237646396,0 (<nil>, <nil>)
          {
            b := &kv.Batch{}
            txn.Run(ctx, b) // <nil>
          }
          txn.ReverseScanForUpdateSkipLocked(ctx, tk(3948682349027409141), tk(11201223208661488675), 0) // @1761956315.238575188,0 (/Table/100/"39744de6072938a7":v17, <nil>)
          txn.GetForUpdate(ctx, tk(1461535347902648743)) // @1761956315.243636558,0 (<nil>, <nil>)
          txn.PutMustAcquireExclusiveLock(ctx, tk(13269107982081865561), sv(39)) // @1761956315.244472913,0 <nil>
          txn.GetForUpdateGuaranteedDurability(ctx, tk(17968485636773111541)) // @1761956315.247371340,0 (v7, <nil>)
          {
            b := &kv.Batch{}
            b.GetForShareGuaranteedDurability(tk(420587284912812019)) // (<nil>, <nil>)
            txn.Run(ctx, b) // @1761956315.248513267,0 <nil>
          }
          txn.ReverseScanForUpdate(ctx, tk(7513377593281737848), tk(7555006292892118712), 0) // @1761956315.249297693,0 <nil>
          txn.ReverseScanForShareGuaranteedDurability(ctx, tk(7776989638975703950), tk(17001082898640518291), 0) // failed indeterminate commit recovery: programming error: timestamp change by implicitly committed transaction: 1761956315.233667124,1->1761956315.229270646,0
          return errors.New("rollback")
        }) // failed indeterminate commit recovery: programming error: timestamp change by implicitly committed transaction: 1761956315.233667124,1->1761956315.229270646,0: failed indeterminate commit recovery: programming error: timestamp change by implicitly committed transaction: 1761956315.233667124,1->1761956315.229270646,0
    kvnemesis.go:240: error applying x.ReverseScanForShareGuaranteedDurability(ctx, tk(7776989638975703950), tk(17001082898640518291), 0) // failed indeterminate commit recovery: programming error: timestamp change by implicitly committed transaction: 1761956315.233667124,1->1761956315.229270646,0: failed indeterminate commit recovery: programming error: timestamp change by implicitly committed transaction: 1761956315.233667124,1->1761956315.229270646,0
    kvnemesis.go:281: failures(verbose): /artifacts/tmp/_tmp/b4152c3c30db07feb76bcf7524cbe883/kvnemesis2403504634/failures
        repro steps: /artifacts/tmp/_tmp/b4152c3c30db07feb76bcf7524cbe883/kvnemesis2403504634/repro.go
        rangefeed KVs: /artifacts/tmp/_tmp/b4152c3c30db07feb76bcf7524cbe883/kvnemesis2403504634/kvs-rangefeed.txt
        scan KVs: /artifacts/tmp/_tmp/b4152c3c30db07feb76bcf7524cbe883/kvnemesis2403504634/kvs-scan.txt
    kvnemesis_test.go:728: Metric                              | Node 1                         | Node 2                         | Node 3                         | Node 4                        
    kvnemesis_test.go:734: ------------------------------------+--------------------------------+--------------------------------+--------------------------------+-------------------------------
    kvnemesis_test.go:741: raft.commands.proposed              | 2606                           | 40                             | 285                            | 48                            
    kvnemesis_test.go:741: raft.commands.reproposed.new-lai    | 0                              | 0                              | 8                              | 0                             
    kvnemesis_test.go:741: raft.commands.reproposed.unchanged  | 79                             | 3                              | 9                              | 5                             
    kvnemesis_test.go:741: txn.aborts                          | 6                              | 12                             | 8                              | 7                             
    kvnemesis_test.go:741: txn.durations                       | μ=9ms p50=3ms p99=92ms         | μ=32ms p50=3ms p99=298ms       | μ=24ms p50=5ms p99=427ms       | μ=20ms p50=3ms p99=476ms      
    kvnemesis_test.go:741: txn.restarts.writetooold            | 2                              | 1                              | 2                              | 0                             
    kvnemesis_test.go:741: txn.restarts.serializable           | 1                              | 0                              | 0                              | 0                             
    kvnemesis_test.go:741: txn.restarts.readwithinuncertainty  | 0                              | 0                              | 0                              | 0                             
    kvnemesis_test.go:741: txn.server_side.1PC.success         | 62                             | 0                              | 2                              | 0                             
    kvnemesis_test.go:741: txnrecovery.failures                | 1                              | 0                              | 0                              | 0                             
    kvnemesis_test.go:741: txnrecovery.successes.aborted       | 0                              | 0                              | 1                              | 0                             
    kvnemesis_test.go:741: txnrecovery.successes.committed     | 0                              | 0                              | 0                              | 0                             
    kvnemesis_test.go:741: txnwaitqueue.deadlocks_total        | 0                              | 0                              | 3                              | 0                             
    kvnemesis_test.go:663: 
        	Error Trace:	pkg/kv/kvnemesis/kvnemesis_test.go:663
        	            				pkg/kv/kvnemesis/kvnemesis_test.go:550
        	Error:      	Should be zero, but was 2
        	Test:       	TestKVNemesisMultiNode
        	Messages:   	kvnemesis detected failures
    dump_raft_logs.go:32: dumping raft logs to /artifacts/tmp/_tmp/b4152c3c30db07feb76bcf7524cbe883/kvnemesis2403504634/raftlogs
    panic.go:615: -- test log scope end --
test logs left over in: /artifacts/tmp/_tmp/b4152c3c30db07feb76bcf7524cbe883/logTestKVNemesisMultiNode2773907026
--- FAIL: TestKVNemesisMultiNode (24.43s)

Help

See also: How To Investigate a Go Test Failure (internal)

/cc @cockroachdb/kv-triage

This test on roachdash | Improve this report!

Jira issue: CRDB-56120

[stevendanna]

I think this will be fixed by https://github.com/cockroachdb/cockroach/pull/152010/files#diff-00f3f5e340e09a59107ea9063affbafdb4d360dcc35d148d32a1a714dc6d2d03R506-R510 as well.

Namely, I think what happens here is that a parallel commit fails because one of the writes was pushed. We then refresh and retry. During the retry, we fail an EndTxn with an injected error. Then during the rollback we do transaction recovery with the updated txn rather than the on-disk staging txn.

EDIT: Hrm. I pulled down the trace, and this looks like something a little different.

[stevendanna]

Ooooh. Actually, I think my original theory was nearly correct. The only thing I missed is that while it is true that only self-recovery could possibly hit the error I mentioned, that doesn't mean that the error doesn't impact other transactions. If multiple requests need to recovery a transaction concurrently, we coalesce those requests, so it is possible other transactions still see this "programming error"