cockroachdb / cockroachdb/cockroach
kv/kvnemesis: TestKVNemesisMultiNode_BufferedWritesLockDurabilityUpgrades failed
- Dominant language
- Go
- Stars
- 32.5k
- Forks
- 4.1k
- PR merge metrics
- PR metrics pending
Description
kv/kvnemesis.TestKVNemesisMultiNode_BufferedWritesLockDurabilityUpgrades [failed](https://teamcity.cockroachdb.com/buildConfiguration/Cockroach_Nightlies_NightlyCockroachExtraStress/21503373?buildTab=log) with [artifacts](https://teamcity.cockroachdb.com/buildConfiguration/Cockroach_Nightlies_NightlyCockroachExtraStress/21503373?buildTab=artifacts#/) on master @ [319dd258bfe217be1db20e8693c79c1748133094](https://github.com/cockroachdb/cockroach/commits/319dd258bfe217be1db20e8693c79c1748133094):
```
txn.GetForUpdateSkipLocked(ctx, tk(9461373726699280586)) // @1788829895.440148653,0 (, )
txn.ReverseScanForUpdateSkipLocked(ctx, tk(2711640570529200775), tk(9929735945149548023), 0) // @1788829895.440148653,0 (/Table/100/"6ded05aacd8c3416":v1, /Table/100/"57b7671eab413be2":v25, /Table/100/"490668d7954d91aa":v31, /Table/100/"3b2ae05254c7d4c9":v38, /Table/100/"3af3cb1d092ded73":v37, /Table/100/"384a0d8a38825245":v24, )
txn.ReverseScanForShareSkipLockedGuaranteedDurability(ctx, tk(2711014911988922127), tk(5957044145986222273), 0) // @1788829895.440148653,0 (/Table/100/"490668d7954d91aa":v31, /Table/100/"3b2ae05254c7d4c9":v38, /Table/100/"3af3cb1d092ded73":v37, /Table/100/"384a0d8a38825245":v24, )
txn.ReverseScan(ctx, tk(4955585596578554981), tk(17106277758612035759), 0) // @1788829895.440148653,0 (/Table/100/"ec2b91e883be6a2b":v55, /Table/100/"bf26b0604939a063":v23, /Table/100/"9843dba87836bf4f":v63, /Table/100/"8bc0e2a5e79f206a":v11, /Table/100/"6ded05aacd8c3416":v1, /Table/100/"57b7671eab413be2":v25, /Table/100/"490668d7954d91aa":v31, )
txn.DelRange(ctx, tk(5469626622887848588), tk(12710809915224903581), true /* @s48 */) // @1788829895.440148653,0 (/Table/100/"57b7671eab413be2", /Table/100/"6ded05aacd8c3416", /Table/100/"8bc0e2a5e79f206a", /Table/100/"9843dba87836bf4f", )
txn.CPutAllowIfDoesNotExist(ctx, tk(10862718729718964391), sv(49), exp(non-existent value)) // @1788829895.440148653,0
txn.DelRange(ctx, tk(16727941291841751274), tk(17316980404855284421), true /* @s50 */) // @1788829895.440148653,0 (/Table/100/"ec2b91e883be6a2b", )
txn.Scan(ctx, tk(5827279477811915548), tk(18046764860027035156), 0) // @1788829895.440148653,0 (/Table/100/"96c02121abe1a0a7":v49, /Table/100/"bf26b0604939a063":v23, )
txn.Get(ctx, tk(6320633983457639394)) // @1788829895.440148653,0 (, )
txn.CPut(ctx, tk(18021442537717552631), sv(51), exp()) // @1788829895.440148653,0
b := &kv.Batch{}
b.CPut(tk(11475369574928384379), sv(52), exp()) // TransactionRetryWithProtoRefreshError: TransactionRetryError: retry txn (RETRY_SERIALIZABLE - failed preemptive refresh due to conflicting locks on /Table/100/"bf26b0604939a063" [reason=wait_policy] - conflicting txn: meta={id=d315ddcd key=/Table/100/"40a451383cadb992" iso=Serializable pri=99.99999991 epo=0 ts=1788829895.938205949,0 min=1788829895.938205949,0 seq=0}): "unnamed" meta={id=c9ed2093 key=/Table/100/"69376aecea055477" iso=Serializable pri=99.99999995 epo=99 ts=1788829895.938205949,1 min=1788829799.482163646,0 seq=4} lock=true stat=PENDING rts=1788829895.440148653,0 gul=1788829799.492163646,0 obs={n2@1788829799.543045037,0}
b.CPut(tk(7501609327462551040), sv(53), exp()) // TransactionRetryWithProtoRefreshError: TransactionRetryError: retry txn (RETRY_SERIALIZABLE - failed preemptive refresh due to conflicting locks on /Table/100/"bf26b0604939a063" [reason=wait_policy] - conflicting txn: meta={id=d315ddcd key=/Table/100/"40a451383cadb992" iso=Serializable pri=99.99999991 epo=0 ts=1788829895.938205949,0 min=1788829895.938205949,0 seq=0}): "unnamed" meta={id=c9ed2093 key=/Table/100/"69376aecea055477" iso=Serializable pri=99.99999995 epo=99 ts=1788829895.938205949,1 min=1788829799.482163646,0 seq=4} lock=true stat=PENDING rts=1788829895.440148653,0 gul=1788829799.492163646,0 obs={n2@1788829799.543045037,0}
txn.CommitInBatch(ctx, b) // TransactionRetryWithProtoRefreshError: TransactionRetryError: retry txn (RETRY_SERIALIZABLE - failed preemptive refresh due to conflicting locks on /Table/100/"bf26b0604939a063" [reason=wait_policy] - conflicting txn: meta={id=d315ddcd key=/Table/100/"40a451383cadb992" iso=Serializable pri=99.99999991 epo=0 ts=1788829895.938205949,0 min=1788829895.938205949,0 seq=0}): "unnamed" meta={id=c9ed2093 key=/Table/100/"69376aecea055477" iso=Serializable pri=99.99999995 epo=99 ts=1788829895.938205949,1 min=1788829799.482163646,0 seq=4} lock=true stat=PENDING rts=1788829895.440148653,0 gul=1788829799.492163646,0 obs={n2@1788829799.543045037,0}
return nil
}) // have retried transaction: unnamed (id: c9ed2093-238b-4274-be96-5c4160308d1e) 101 times, most recently because of the retryable error: TransactionRetryWithProtoRefreshError: TransactionRetryError: retry txn (RETRY_SERIALIZABLE - failed preemptive refresh due to conflicting locks on /Table/100/"bf26b0604939a063" [reason=wait_policy] - conflicting txn: meta={id=d315ddcd key=/Table/100/"40a451383cadb992" iso=Serializable pri=99.99999991 epo=0 ts=1788829895.938205949,0 min=1788829895.938205949,0 seq=0}): "unnamed" meta={id=c9ed2093 key=/Table/100/"69376aecea055477" iso=Serializable pri=99.99999995 epo=99 ts=1788829895.938205949,1 min=1788829799.482163646,0 seq=4} lock=true stat=PENDING rts=1788829895.440148653,0 gul=1788829799.492163646,0 obs={n2@1788829799.543045037,0}. Terminating retry loop and returning error due to max retry limit (100). Rollback error: .: have retried transaction: unnamed (id: c9ed2093-238b-4274-be96-5c4160308d1e) 101 times, most recently because of the retryable error: TransactionRetryWithProtoRefreshError: TransactionRetryError: retry txn (RETRY_SERIALIZABLE - failed preemptive refresh due to conflicting locks on /Table/100/"bf26b0604939a063" [reason=wait_policy] - conflicting txn: meta={id=d315ddcd key=/Table/100/"40a451383cadb992" iso=Serializable pri=99.99999991 epo=0 ts=1788829895.938205949,0 min=1788829895.938205949,0 seq=0}): "unnamed" meta={id=c9ed2093 key=/Table/100/"69376aecea055477" iso=Serializable pri=99.99999995 epo=99 ts=1788829895.938205949,1 min=1788829799.482163646,0 seq=4} lock=true stat=PENDING rts=1788829895.440148653,0 gul=1788829799.492163646,0 obs={n2@1788829799.543045037,0}. Terminating retry loop and returning error due to max retry limit (100). Rollback error: .
kvnemesis.go:282: failures(verbose): /artifacts/tmp/_tmp/dfc5378a5992f1418cc83df178842118/kvnemesis4009101273/failures
repro steps: /artifacts/tmp/_tmp/dfc5378a5992f1418cc83df178842118/kvnemesis4009101273/repro.go
rangefeed KVs: /artifacts/tmp/_tmp/dfc5378a5992f1418cc83df178842118/kvnemesis4009101273/kvs-rangefeed.txt
scan KVs: /artifacts/tmp/_tmp/dfc5378a5992f1418cc83df178842118/kvnemesis4009101273/kvs-scan.txt
kvnemesis_test.go:1102: Metric | Node 1 | Node 2 | Node 3
kvnemesis_test.go:1108: ------------------------------------+--------------------------------+--------------------------------+-------------------------------
kvnemesis_test.go:1115: follower_reads.success_count | 91 | 125 | 49
kvnemesis_test.go:1115: raft.commands.proposed | 7293 | 2250 | 2563
kvnemesis_test.go:1115: raft.commands.reproposed.new-lai | 1 | 16 | 0
kvnemesis_test.go:1115: raft.commands.reproposed.unchanged | 132 | 13 | 21
kvnemesis_test.go:1115: txn.aborts | 50 | 34 | 126
kvnemesis_test.go:1115: txn.commits | 1578 | 767 | 861
kvnemesis_test.go:1115: txn.durations | μ=103ms p50=11ms p99=974ms | μ=566ms p50=151ms p99=3.489s | μ=510ms p50=146ms p99=1.907s
kvnemesis_test.go:1115: txn.restarts.writetooold | 2 | 0 | 4
kvnemesis_test.go:1115: txn.write_buffering.disabled_after_buffering | 0 | 2 | 0
kvnemesis_test.go:1115: distsender.rpc.err.writeintenterrtype | 27 | 0 | 99
kvnemesis_test.go:1115: txn.restarts.serializable | 1 | 0 | 98
kvnemesis_test.go:1115: txn.restarts.readwithinuncertainty | 0 | 0 | 0
kvnemesis_test.go:1115: txn.restarts.commitdeadlineexceeded | 8 | 1 | 0
kvnemesis_test.go:1115: txn.server_side.1PC.success | 251 | 2 | 2
kvnemesis_test.go:1115: txnrecovery.failures | 0 | 0 | 0
kvnemesis_test.go:1115: txnrecovery.successes.aborted | 0 | 0 | 0
kvnemesis_test.go:1115: txnrecovery.successes.committed | 0 | 0 | 0
kvnemesis_test.go:1115: txnwaitqueue.deadlocks_total | 0 | 102 | 0
kvnemesis_test.go:988:
Error Trace: pkg/kv/kvnemesis/kvnemesis_test.go:988
pkg/kv/kvnemesis/kvnemesis_test.go:660
Error: Should be zero, but was 1
Test: TestKVNemesisMultiNode_BufferedWritesLockDurabilityUpgrades
Messages: kvnemesis detected failures
dump_raft_logs.go:32: dumping raft logs to /artifacts/tmp/_tmp/dfc5378a5992f1418cc83df178842118/kvnemesis4009101273/raftlogs
panic.go:694: -- test log scope end --
test logs left over in: /artifacts/tmp/_tmp/dfc5378a5992f1418cc83df178842118/logTestKVNemesisMultiNode_BufferedWritesLockDurabilityUpgrades1679940748
--- FAIL: TestKVNemesisMultiNode_BufferedWritesLockDurabilityUpgrades (241.40s)
```
Help
See also: [How To Investigate a Go Test Failure \(internal\)](https://cockroachlabs.atlassian.net/l/c/HgfXfJgM)
/cc @cockroachlabs/kv-triage
[Improve this report!](https://github.com/cockroachdb/cockroach/tree/master/pkg/cmd/bazci/githubpost/issues)
Jira issue: CRDB-68018
Contributor guide
Assessment
This issue has not been assessed yet.