kvnemesis: TestKVNemesisSingleNode: committed deleteRangeUsingTombstone non-atomic timestamps

[tbg]

Describe the problem

committed deleteRangeUsingTombstone non-atomic timestamps: 
[d][/Table/100/"0000000000000000",/Table/100/"6ba66e4d0c6ea25e"):1686739361.925656994,1-><nil>@s27
[d][/Table/100/"6ba66e4d0c6ea25e",/Table/100/"6ba66e4d0c6ea25f"):1686739361.925656994,1-><nil>@s27
[d][/Table/100/"6ba66e4d0c6ea25f",/Table/100/"6d1492740d73eb41"):1686739361.925656994,1-><nil>@s27
[d][/Table/100/"6d1492740d73eb41",/Table/100/"7b206bdfe9a5b7e6"):1686739361.925656994,1-><nil>@s27
[d][/Table/100/"7b206bdfe9a5b7e6",/Table/100/"fe12d6f8c75f604b"):1686739362.069868437,0-><nil>@s27
[d][/Table/100/"fe12d6f8c75f604b",/Table/100/"ffffffffffffffff"):1686739362.069246287,0-><nil>@s27
[s]/Table/100/"{0000000000000000"-ffffffffffffffff"}:
  {gap:[
    <min>, 1686739361.781522812,0),
    [1686739361.787564641,0, 1686739361.791728790,0),
    [1686739362.069868437,1, <max>),
    [1686739362.069246287,0, 1686739362.069868437,1)
  }->[]

Seen on a non-batched bors build¹ for #104658 on top of 3572499 (#104685 changes only comments).

Artifacts: 1f42cf5be2fc021646bf9b2daf5eaef3.zip

Jira issue: CRDB-28758

Footnotes

1. https://teamcity.cockroachdb.com/viewLog.html?buildId=10528742&tab=buildResultsDiv&buildTypeId=Cockroach_UnitTests_BazelUnitTests ↩

[blathers-crl]

cc @cockroachdb/replication

[blathers-crl]

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

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

[blathers-crl]

cc @cockroachdb/replication

[erikgrinaker]

deleteRangeUsingTombstone isn't guaranteed to be atomic across ranges though. We don't have ranged intents, so when spanning range boundaries each range is evaluated independently.

[tbg]

I did something to make this work when I wrote kvnemesis v2 (by preventing splitting them across ranges), maybe that somehow broke, will take a quick look

[tbg]

Yeah we just prevent range-spanning here:

cockroach/pkg/kv/kvnemesis/kvnemesis_test.go

Lines 61 to 77 in 736a67e

	KVClient: &kvcoord.ClientTestingKnobs{
	// Don't let DistSender split DeleteRangeUsingTombstone across range boundaries.
	// This does happen in real CRDB, but leads to separate atomic subunits, which
	// would add complexity to kvnemesis that isn't worth it. Instead, the operation
	// generator for the most part tries to avoid range-spanning requests, and the
	// ones that do end up happening get a hard error.
	OnRangeSpanningNonTxnalBatch: func(ba *kvpb.BatchRequest) *kvpb.Error {
	for _, req := range ba.Requests {
	if req.GetInner().Method() != kvpb.DeleteRange {
	continue
	}
	if req.GetDeleteRange().UseRangeTombstone == true {
	return kvpb.NewError(errDelRangeUsingTombstoneStraddlesRangeBoundary)
	}
	}
	return nil
	},

and we don't ever use it in a txn:

cockroach/pkg/kv/kvnemesis/generator.go

Lines 270 to 271 in 6369846

	// DeleteRangeUsingTombstone does not support transactions.
	config.Ops.ClosureTxn.TxnClientOps.DeleteRangeUsingTombstone = 0

I'm not sure what's going on here, but kvnemesis was changed a few times recently by @nvanbenschoten, most recently in #104356.

[tbg]

Sure looks like it is using DelRange(..., tombstone=true) in a txn:

[tbg]

Ah no, DelRangeUsingTombstone is what we're looking for. Can confirm that it was carried out as individual operations only.

[erikgrinaker]

Ok, I'll have a look in a bit.

[tbg]

The error shows that this DeleteRangeUsingTombstone (DRUT)

db0.DelRangeUsingTombstone(ctx, tk(0), tk(18446744073709551615) /* @s27 */) // @1686739362.069868437,0 <nil>
  // ^-- trace in: /artifacts/tmp/_tmp/1f42cf5be2fc021646bf9b2daf5eaef3/kvnemesis2422980857/w0_step9_trace

created six observed fragments in the rangefeed¹. These fragments all ought to be at the same timestamp. They are not: the first four fragments match, then we get two more fragments with unique timestamps. The official execution timestamp ends up being the second to last unique timestamp (1686739362.069868437,0), which is also the largest of the bunch.

That timestamp is interesting because we also committed a SNAPSHOT txn right then:

  db0.Txn(ctx, func(ctx context.Context, txn *kv.Txn) error {
    txn.SetIsoLevel(isolation.Snapshot)
    txn.DelRange(ctx, tk(420403431433673189), tk(10570627412767213890), true /* @s23 */) // @1686739362.069868437,1 <nil>
    txn.Del(ctx, tk(12162221775285847948) /* @s24 */) // @1686739362.069868437,1 <nil>
    b := &kv.Batch{}
    b.GetForUpdate(tk(9723121657551650044)) // (<nil>, <nil>)
    b.GetForUpdate(tk(16369197900219584719)) // (<nil>, <nil>)
    txn.CommitInBatch(ctx, b) // @1686739362.069868437,1 <nil>
    return nil
  }) // @1686739362.069868437,1 <nil>
  // ^-- txnpb:("unnamed" meta={id=96d89cc1 key=/Table/100/"05d592b188f599e5" iso=Snapshot pri=0.00053365 epo=0 ts=1686739362.069868437,1 min=1686739362.049259529,0 seq=3} lock=true stat=COMMITTED rts=1686739362.069868437,1 wto=false gul=1686739362.059259529,0 int=3)
  // ^-- trace in: /artifacts/tmp/_tmp/1f42cf5be2fc021646bf9b2daf5eaef3/kvnemesis2422980857/w4_step8_trace

Note the txn timestamp is the DRUT's timestamp plus one logical tick. Perhaps this txn and the DRUT interacted somehow in a way that facilitated this issue.

However, the last DRUT fragment (timestamp 1686739362.0692...) is not such an easy match for anything. That timestamp doesn't show up anywhere else.

I'll leave the hard part of the analysis to you, @erikgrinaker, but happy to be a rubber 🦆.

Footnotes

1. https://github.com/cockroachdb/cockroach/blob/6369846e12471585b1063e9bc7d19597428f53aa/pkg/kv/kvnemesis/validator.go#L481-L556 ↩

[tbg]

Looking at the trace, it does seem like DistSender split up the request!

     0.484ms      0.025ms                event:kv/kvserver/store_send.go:154 [n1,s1] executing DeleteRange [/Table/100/"0000000000000000",/Table/100/"7b206bdfe9a5b7e6")
     0.258ms      0.025ms            event:kv/kvserver/store_send.go:154 [n1,s1] executing DeleteRange [/Table/100/"7b206bdfe9a5b7e6",/Table/100/"ffffffffffffffff")

w0_step9_trace.txt

So this is likely a bug in the suppression of precisely that, i.e. a test-only problem.

[tbg]

I think the interceptor that prevents the range-spanning request accidentally got removed here: https://github.com/cockroachdb/cockroach/pull/103963/files#r1229494377

@wenyihu6 could you send a fix? Thanks!