storage: range does not match splits

[tbg]

--- FAIL: TestSplitTriggerRaftSnapshotRace (10.79s)
	client_split_test.go:562: "key-53": split unexpected error: split at key "key-53" failed: replica corruption (processed=true): range does not match splits: ("key-45"-"key-53") + ("key-53"-/Table/SystemConfigSpan/Start) != [n1,s1,r10/1:/Table/1{3-4}]


11946 runs completed, 1 failures, over 57m7s

via

git fetch tbg && git checkout fix/split-trigger-wait && git reset --hard @{upstream} && make stress PKG=./pkg/storage/ TESTS=SplitTriggerRaftSnap | tee log

(i.e. just use master once #32782 is in).

I think this is a merge bug, based on this not failing before I changed the test to allow merges.

Two repros attached.
crash1.txt
crash2.txt

[tbg]

Got another one after 6s:
crash3.txt

[benesch]

Ok, I've tracked this down to a problem in the internal executor:

I181220 06:11:25.172707 3094 storage/replica_command.go:350  [n2,s2,r197/2:key-{38-50}] initiating a split of this range at key "key-45" [r322] with desc r197:key-{38-45} [(n1,s1):1, (n2,s2):2, (n3,s3):3, next=4, gen=2] and txn b1780318
I181220 06:11:25.276770 3094 storage/replica_command.go:350  [n2,s2,r197/2:key-{38-50}] initiating a split of this range at key "key-45" [r322] with desc r197:key-{38-45} [(n1,s1):1, (n2,s2):2, (n3,s3):3, next=4, gen=2] and txn 651f0584
I181220 06:11:25.289284 2753 storage/replica_command.go:394  [n2,s2,r197/2:key-{38-50}] split internal executor changed id from cf654e35-8c9e-4909-b864-4c302c4d5277 to 4dac1d01-c88c-498e-9749-b0a592054dfb
I181220 06:11:25.300231 2655 storage/replica_command.go:497  [n2,merge,s2,r151/2:key-3{7-8}] initiating a merge of r197:key-{38-50} [(n1,s1):1, (n2,s2):2, (n3,s3):3, next=4, gen=1] into this range r151:key-3{7-8} [(n1,s1):1, (n2,s2):2, (n3,s3):3, next=4, gen=1] txn=70b5ffaa
I181220 06:11:25.312588 6567 storage/batcheval/cmd_end_transaction.go:331  [n1,s1,r9/1:/Table/1{3-4}] commit split txn: baHeader={1545286285.280656231,0 (n1,s1):1 9 normal "split" id=4dac1d01 key=/Table/13/1/2018-12-20T06:11:22.278246Z/410307412906573826/0 rw=true pri=0.06488501 stat=PENDING epo=0 ts=1545286285.280656231,0 orig=1545286285.280656231,0 max=1545286285.280882424,0 wto=false seq=16 CONSISTENT %!s(int64=0) %!s(bool=false) %!s(bool=false) 2 <nil> %!s(bool=false)} txn=4dac1d01 args=&roachpb.SplitTrigger{LeftDesc:roachpb.RangeDescriptor{RangeID:197, StartKey:roachpb.RKey{0x6b, 0x65, 0x79, 0x2d, 0x33, 0x38}, EndKey:roachpb.RKey{0x6b, 0x65, 0x79, 0x2d, 0x34, 0x38}, Replicas:[]roachpb.ReplicaDescriptor{roachpb.ReplicaDescriptor{NodeID:1, StoreID:1, ReplicaID:1}, roachpb.ReplicaDescriptor{NodeID:2, StoreID:2, ReplicaID:2}, roachpb.ReplicaDescriptor{NodeID:3, StoreID:3, ReplicaID:3}}, NextReplicaID:4, Generation:(*int64)(0xc4203f8dc8)}, RightDesc:roachpb.RangeDescriptor{RangeID:259, StartKey:roachpb.RKey{0x6b, 0x65, 0x79, 0x2d, 0x34, 0x38}, EndKey:roachpb.RKey{0x6b, 0x65, 0x79, 0x2d, 0x35, 0x30}, Replicas:[]roachpb.ReplicaDescriptor{roachpb.ReplicaDescriptor{NodeID:1, StoreID:1, ReplicaID:1}, roachpb.ReplicaDescriptor{NodeID:2, StoreID:2, ReplicaID:2}, roachpb.ReplicaDescriptor{NodeID:3, StoreID:3, ReplicaID:3}}, NextReplicaID:4, Generation:(*int64)(nil)}}
F181220 06:11:25.312648 6567 storage/batcheval/cmd_end_transaction.go:778  [n1,s1,r9/1:/Table/1{3-4}] range does not match splits: ("key-38"-"key-48") + ("key-48"-"key-50") != [n1,s1,r9/1:/Table/1{3-4}]

The salient line is

I181220 06:11:25.289284 2753 storage/replica_command.go:394  [n2,s2,r197/2:key-{38-50}] split internal executor changed id from cf654e35-8c9e-4909-b864-4c302c4d5277 to 4dac1d01-c88c-498e-9749-b0a592054dfb

which indicates that the internal executor used to add an entry to the rangelog about the split decides to restart the txn with a new ID (!!!!!). This is kind of insane. I can only assume that turning on merges somehow causes the split txns to hit some sort of non-retryable conflicts that cause the internal executor to decide to restart with a new txn.

I'll dig in more tomorrow.