kv: failure in TestLearnerReplicateQueueRace

[knz]

Found here: https://teamcity.cockroachdb.com/buildConfiguration/Cockroach_BazelEssentialCi/8262010?showRootCauses=false&expandBuildChangesSection=true&expandBuildProblemsSection=true&expandBuildTestsSection=true

=== RUN   TestLearnerReplicateQueueRace
    test_log_scope.go:161: test logs captured to: /artifacts/tmp/_tmp/7438ab096787a15a8ce5f502b5724798/logTestLearnerReplicateQueueRace1790270096
    test_log_scope.go:79: use -show-logs to present logs inline
    replica_learner_test.go:1117:
          Error Trace:  /home/roach/.cache/bazel/_bazel_roach/c5a4e7d36696d9cd970af2045211a7df/sandbox/processwrapper-sandbox/7671/execroot/com_github_cockroachdb_cockroach/bazel-out/k8-fastbuild/bin/pkg/kv/kvserver/kvserver_test_/kvserver_test.runfiles/com_github_cockroachdb_cockroach/pkg/kv/kvserver/replica_learner_test.go:1117
          Error:        Received unexpected error:
                        AdminChangeReplicas error: trying to remove a replica that doesn't exist: {ChangeType:REMOVE_VOTER Target:n3,s3}
                        (1) AdminChangeReplicas error: trying to remove a replica that doesn't exist: {ChangeType:REMOVE_VOTER Target:n3,s3}
                          | -- cause hidden behind barrier
                          | AdminChangeReplicas error: trying to remove a replica that doesn't exist: {ChangeType:REMOVE_VOTER Target:n3,s3}
                          | (1) attached stack trace
                          |   -- stack trace:
                          |   | github.com/cockroachdb/cockroach/pkg/testutils/testcluster.(*TestCluster).changeReplicas
                          |   |   github.com/cockroachdb/cockroach/pkg/testutils/testcluster/testcluster.go:762
                          |   | github.com/cockroachdb/cockroach/pkg/testutils/testcluster.(*TestCluster).RemoveVoters
                          |   |   github.com/cockroachdb/cockroach/pkg/testutils/testcluster/testcluster.go:918
                          |   | github.com/cockroachdb/cockroach/pkg/kv/kvserver_test.TestLearnerReplicateQueueRace
                          |   |   github.com/cockroachdb/cockroach/pkg/kv/kvserver_test/pkg/kv/kvserver/replica_learner_test.go:1116
                          |   | testing.tRunner
                          |   |   GOROOT/src/testing/testing.go:1446
                          |   | runtime.goexit
                          |   |   GOROOT/src/runtime/asm_amd64.s:1594
                          | Wraps: (2) AdminChangeReplicas error
                          | Wraps: (3) forced error mark
                          |   | "invalid replication change"
                          |   | github.com/cockroachdb/errors/withstack/*withstack.withStack::
                          | Wraps: (4) assertion failure
                          | Wraps: (5)
                          |   | (opaque error wrapper)
                          |   | type name: github.com/cockroachdb/errors/withstack/*withstack.withStack
                          |   | reportable 0:
                          |   |
                          |   | github.com/cockroachdb/cockroach/pkg/kv/kvserver.validateRemovals
                          |   |   github.com/cockroachdb/cockroach/pkg/kv/kvserver/pkg/kv/kvserver/replica_command.go:1457
                          |   | github.com/cockroachdb/cockroach/pkg/kv/kvserver.validateReplicationChanges
                          |   |   github.com/cockroachdb/cockroach/pkg/kv/kvserver/pkg/kv/kvserver/replica_command.go:1626
                          |   | github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*Replica).changeReplicasImpl
                          |   |   github.com/cockroachdb/cockroach/pkg/kv/kvserver/pkg/kv/kvserver/replica_command.go:1013
                          |   | github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*Replica).ChangeReplicas
                          |   |   github.com/cockroachdb/cockroach/pkg/kv/kvserver/pkg/kv/kvserver/replica_command.go:991
                          |   | github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*Replica).executeAdminBatch
                          |   |   github.com/cockroachdb/cockroach/pkg/kv/kvserver/pkg/kv/kvserver/replica_send.go:955
                          |   | github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*Replica).SendWithWriteBytes
                          |   |   github.com/cockroachdb/cockroach/pkg/kv/kvserver/pkg/kv/kvserver/replica_send.go:187
                          |   | github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*Store).SendWithWriteBytes
                          |   |   github.com/cockroachdb/cockroach/pkg/kv/kvserver/pkg/kv/kvserver/store_send.go:205
                          |   | github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*Stores).SendWithWriteBytes
                          |   |   github.com/cockroachdb/cockroach/pkg/kv/kvserver/pkg/kv/kvserver/stores.go:203
                          |   | github.com/cockroachdb/cockroach/pkg/server.(*Node).batchInternal
                          |   |   github.com/cockroachdb/cockroach/pkg/server/node.go:1121
                          |   | github.com/cockroachdb/cockroach/pkg/server.(*Node).Batch
                          |   |   github.com/cockroachdb/cockroach/pkg/server/node.go:1173
                          |   | github.com/cockroachdb/cockroach/pkg/rpc.makeInternalClientAdapter.func1
                          |   |   github.com/cockroachdb/cockroach/pkg/rpc/pkg/rpc/context.go:741
                          |   | github.com/cockroachdb/cockroach/pkg/util/tracing/grpcinterceptor.ServerInterceptor.func1
                          |   |   github.com/cockroachdb/cockroach/pkg/util/tracing/grpcinterceptor/grpc_interceptor.go:95
                          |   | github.com/cockroachdb/cockroach/pkg/rpc.bindUnaryServerInterceptorToHandler.func1
                          |   |   github.com/cockroachdb/cockroach/pkg/rpc/pkg/rpc/context.go:813
                          |   | github.com/cockroachdb/cockroach/pkg/rpc.NewServerEx.func3
                          |   |   github.com/cockroachdb/cockroach/pkg/rpc/pkg/rpc/context.go:260
                          |   | github.com/cockroachdb/cockroach/pkg/rpc.bindUnaryServerInterceptorToHandler.func1
                          |   |   github.com/cockroachdb/cockroach/pkg/rpc/pkg/rpc/context.go:813
                          |   | github.com/cockroachdb/cockroach/pkg/rpc.kvAuth.unaryInterceptor
                          |   |   github.com/cockroachdb/cockroach/pkg/rpc/pkg/rpc/auth.go:73
                          |   | github.com/cockroachdb/cockroach/pkg/rpc.bindUnaryServerInterceptorToHandler.func1
                          |   |   github.com/cockroachdb/cockroach/pkg/rpc/pkg/rpc/context.go:813
                          |   | github.com/cockroachdb/cockroach/pkg/rpc.NewServerEx.func1.1
                          |   |   github.com/cockroachdb/cockroach/pkg/rpc/pkg/rpc/context.go:229
                          |   | github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunTaskWithErr
                          |   |   github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:322
                          |   | github.com/cockroachdb/cockroach/pkg/rpc.NewServerEx.func1
                          |   |   github.com/cockroachdb/cockroach/pkg/rpc/pkg/rpc/context.go:227
                          |   | github.com/cockroachdb/cockroach/pkg/rpc.bindUnaryServerInterceptorToHandler.func1
                          |   |   github.com/cockroachdb/cockroach/pkg/rpc/pkg/rpc/context.go:813
                          |   | github.com/cockroachdb/cockroach/pkg/rpc.makeInternalClientAdapter.func2
                          |   |   github.com/cockroachdb/cockroach/pkg/rpc/pkg/rpc/context.go:751
                          |   | github.com/cockroachdb/cockroach/pkg/util/tracing/grpcinterceptor.ClientInterceptor.func2
                          |   |   github.com/cockroachdb/cockroach/pkg/util/tracing/grpcinterceptor/grpc_interceptor.go:225
                          |   | github.com/cockroachdb/cockroach/pkg/rpc.getChainUnaryInvoker.func1
                          |   |   github.com/cockroachdb/cockroach/pkg/rpc/pkg/rpc/context.go:897
                          |   | github.com/cockroachdb/cockroach/pkg/rpc.makeInternalClientAdapter.func3
                          |   |   github.com/cockroachdb/cockroach/pkg/rpc/pkg/rpc/context.go:782
                          |   | github.com/cockroachdb/cockroach/pkg/rpc.internalClientAdapter.Batch
                          |   |   github.com/cockroachdb/cockroach/pkg/rpc/pkg/rpc/context.go:905
                          |   | github.com/cockroachdb/cockroach/pkg/kv/kvclient/kvcoord.(*grpcTransport).sendBatch
                          |   |   github.com/cockroachdb/cockroach/pkg/kv/kvclient/kvcoord/transport.go:209
                          |   | github.com/cockroachdb/cockroach/pkg/kv/kvclient/kvcoord.(*grpcTransport).SendNext
                          |   |   github.com/cockroachdb/cockroach/pkg/kv/kvclient/kvcoord/transport.go:188
                          |   | github.com/cockroachdb/cockroach/pkg/kv/kvclient/kvcoord.(*DistSender).sendToReplicas
                          |   |   github.com/cockroachdb/cockroach/pkg/kv/kvclient/kvcoord/dist_sender.go:2142
                          |   | github.com/cockroachdb/cockroach/pkg/kv/kvclient/kvcoord.(*DistSender).sendPartialBatch
                          |   |   github.com/cockroachdb/cockroach/pkg/kv/kvclient/kvcoord/dist_sender.go:1668
                          |   | github.com/cockroachdb/cockroach/pkg/kv/kvclient/kvcoord.(*DistSender).divideAndSendBatchToRanges
                          |   |   github.com/cockroachdb/cockroach/pkg/kv/kvclient/kvcoord/dist_sender.go:1240
                          |   | github.com/cockroachdb/cockroach/pkg/kv/kvclient/kvcoord.(*DistSender).Send
                          |   |   github.com/cockroachdb/cockroach/pkg/kv/kvclient/kvcoord/dist_sender.go:861
                          | Wraps: (6) trying to remove a replica that doesn't exist: {ChangeType:REMOVE_VOTER Target:n3,s3}
                          | Error types: (1) *withstack.withStack (2) *errutil.withPrefix (3) *markers.withMark (4) *assert.withAssertionFailure (5) *errbase.opaqueWrapper (6) *errutil.leafError
                        Error types: (1) *barriers.barrierErr
          Test:         TestLearnerReplicateQueueRace

cc @erikgrinaker @tbg for triage

Jira issue: CRDB-23264

[blathers-crl]

cc @cockroachdb/replication

[erikgrinaker]

@aliher1911 can you have a look at this?

[knz]

another one https://teamcity.cockroachdb.com/buildConfiguration/Cockroach_BazelEssentialCi/8334222?showRootCauses=false&expandBuildChangesSection=true&expandBuildProblemsSection=true&expandBuildTestsSection=true

[aliher1911]

Test tries to upreplicate while blocking the snapshot processing.

When failure happens it looks like change replicas fails and retries (again unsuccessfully).

I230116 21:15:56.229477 191599 13@kv/kvserver/replicate_queue.go:1208 ⋮ [T1,n1,s1,r55/1:‹/{Table/Max-Max}›] 7  adding voter n3,s3: ‹[1*:15, 2:0]›
I230116 21:15:56.230642 191599 13@kv/kvserver/replica_command.go:2333 ⋮ [T1,n1,s1,r55/1:‹/{Table/Max-Max}›] 8  change replicas (add [(n3,s3):3LEARNER] remove []): existing descriptor r55:‹/{Table/Max-Max}› [(n1,s1):1, (n2,s2):2, next=3, gen=3, sticky=9223372036.854775807,2147483647]
I230116 21:16:57.254873 191599 13@kv/kvserver/replica_command.go:2333 ⋮ [T1,n1,s1,r55/1:‹/{Table/Max-Max}›] 9  change replicas (add [(n3,s3):3LEARNER] remove []): existing descriptor r55:‹/{Table/Max-Max}› [(n1,s1):1, (n2,s2):2, next=3, gen=3, sticky=9223372036.854775807,2147483647]
I230116 21:16:57.275710 191599 13@kv/kvserver/replicate_queue.go:818 ⋮ [T1,n1,replicate,s1,r55/1:‹/{Table/Max-Max}›] 10  error processing replica: change replicas of r55 failed: ‹kv/kvserver/intentresolver/intent_resolver.go›:957: stopping‹›

And we see that failure is happening because we have conflicting transaction:

W230116 21:16:11.233392 187375 kv/kvserver/spanlatch/manager.go:558 ⋮ [T1,n1,s1,r55/1:‹/{Table/Max-Max}›] 197  have been waiting 15s to acquire ‹read› latch ‹/Local/Range/Table/Max/RangeDescriptor@0,0›, held by ‹write› latch ‹/Local/Range/Table/Max/RangeDescriptor@0,0›
W230116 21:16:11.252047 191599 kv/kvserver/spanlatch/manager.go:558 ⋮ [T1,n1,s1,r55/1:‹/{Table/Max-Max}›] 198  have been waiting 15s to acquire ‹read› latch ‹/Local/Range/Table/Max/RangeDescriptor@0,0›, held by ‹write› latch ‹/Local/Range/Table/Max/RangeDescriptor@0,0›
W230116 21:16:12.229424 191707 kv/kvserver/spanlatch/manager.go:558 ⋮ [T1,n1,s1,r55/1:‹/{Table/Max-Max}›] 200  have been waiting 15s to acquire ‹read› latch ‹/Local/Range/Table/Max/RangeDescriptor@0,0›, held by ‹write› latch ‹/Local/Range/Table/Max/RangeDescriptor@0,0›
W230116 21:16:12.605475 191737 kv/kvserver/spanlatch/manager.go:558 ⋮ [T1,n1,s1,r55/1:‹/{Table/Max-Max}›] 201  have been waiting 15s to acquire ‹write› latch ‹/Local/RangeID/55/r/AbortSpan/"ff3bb908-2ccf-43c8-ab5f-89cfa7aacc97"@0,0›, held by ‹read› latch ‹/Local/RangeID/55/r/AbortSpan/"ff3bb908-2ccf-43c8-ab5f-89cfa7aacc97"@0,0›
...
W230116 21:16:16.239261 191595 kv/kvserver/intentresolver/intent_resolver.go:799 ⋮ [T1] 207  failed to gc transaction record: ‹operation "cleanup txn record" timed out after 20.012s (given timeout 20s)›: could not GC completed transaction anchored at /Local/Range/Table/Max/‹RangeDescriptor›: context deadline exceeded