kv/kvserver: TestClosedTimestampInactiveAfterSubsumption failed [old closedts]

[cockroach-teamcity]

(kv/kvserver).TestClosedTimestampInactiveAfterSubsumption failed on master@04f694a38169ecbdde2362809cff1897205add21:

I210126 22:27:41.178243 859284 kv/kvserver/replica_command.go:1748  [n1,replicate,s1,r32/1:/Table/3{6-7}] 6780  change replicas (add [(n3,s3):3LEARNER] remove []): existing descriptor r32:/Table/3{6-7} [(n1,s1):1, (n2,s2):2, next=3, gen=2]
I210126 22:27:41.187689 859284 kv/kvserver/replica_raft.go:248  [n1,s1,r32/1:/Table/3{6-7}] 6781  proposing SIMPLE(l3) [(n3,s3):3LEARNER]: after=[(n1,s1):1 (n2,s2):2 (n3,s3):3LEARNER] next=4
I210126 22:27:41.193488 859284 kv/kvserver/store_snapshot.go:1142  [n1,replicate,s1,r32/1:/Table/3{6-7}] 6782  streamed LEARNER_INITIAL snapshot cf7611ff at applied index 19 to (n3,s3):3LEARNER in 0.00s @ 12 MiB/s: kv pairs: 11, log entries: 0, rate-limit: 8.0 MiB/s, queued: 0.00s
I210126 22:27:41.194255 864890 kv/kvserver/replica_raftstorage.go:820  [n3,s3,r32/3:{-}] 6783  applying snapshot of type LEARNER_INITIAL [id=cf7611ff index=19]
I210126 22:27:41.201842 864890 kv/kvserver/replica_raftstorage.go:841  [n3,s3,r32/3:/Table/3{6-7}] 6784  applied snapshot of type LEARNER_INITIAL [total=7msingestion=4@7msid=cf7611ff index=19]
I210126 22:27:41.207398 864842 kv/kvserver/raft_snapshot_queue.go:126  [n1,raftsnapshot,s1,r32/1:/Table/3{6-7}] 6785  skipping snapshot; replica is likely a learner in the process of being added: (n3,s3):3LEARNER
I210126 22:27:41.208504 859284 kv/kvserver/replica_command.go:1748  [n1,replicate,s1,r32/1:/Table/3{6-7}] 6786  change replicas (add [(n3,s3):3] remove []): existing descriptor r32:/Table/3{6-7} [(n1,s1):1, (n2,s2):2, (n3,s3):3LEARNER, next=4, gen=3]
I210126 22:27:41.222641 859284 kv/kvserver/replica_raft.go:248  [n1,s1,r32/1:/Table/3{6-7}] 6787  proposing SIMPLE(v3) [(n3,s3):3]: after=[(n1,s1):1 (n2,s2):2 (n3,s3):3] next=4
I210126 22:27:41.225036 859284 kv/kvserver/replica_command.go:1748  [n1,replicate,s1,r30/1:/Table/3{4-5}] 6788  change replicas (add [(n3,s3):2LEARNER] remove []): existing descriptor r30:/Table/3{4-5} [(n1,s1):1, next=2, gen=0]
I210126 22:27:41.229687 859284 kv/kvserver/replica_raft.go:248  [n1,s1,r30/1:/Table/3{4-5}] 6789  proposing SIMPLE(l2) [(n3,s3):2LEARNER]: after=[(n1,s1):1 (n3,s3):2LEARNER] next=3
I210126 22:27:41.232617 859284 kv/kvserver/store_snapshot.go:1142  [n1,replicate,s1,r30/1:/Table/3{4-5}] 6790  streamed LEARNER_INITIAL snapshot 242f5668 at applied index 15 to (n3,s3):2LEARNER in 0.00s @ 6.3 MiB/s: kv pairs: 7, log entries: 0, rate-limit: 8.0 MiB/s, queued: 0.00s
I210126 22:27:41.232935 864917 kv/kvserver/raft_snapshot_queue.go:126  [n1,raftsnapshot,s1,r30/1:/Table/3{4-5}] 6791  skipping snapshot; replica is likely a learner in the process of being added: (n3,s3):2LEARNER
I210126 22:27:41.233442 864859 kv/kvserver/replica_raftstorage.go:820  [n3,s3,r30/2:{-}] 6792  applying snapshot of type LEARNER_INITIAL [id=242f5668 index=15]
I210126 22:27:41.235978 864859 kv/kvserver/replica_raftstorage.go:841  [n3,s3,r30/2:/Table/3{4-5}] 6793  applied snapshot of type LEARNER_INITIAL [total=2msingestion=4@2msid=242f5668 index=15]
I210126 22:27:41.237262 859284 kv/kvserver/replica_command.go:1748  [n1,replicate,s1,r30/1:/Table/3{4-5}] 6794  change replicas (add [(n3,s3):2] remove []): existing descriptor r30:/Table/3{4-5} [(n1,s1):1, (n3,s3):2LEARNER, next=3, gen=1]
I210126 22:27:41.242750 859284 kv/kvserver/replica_raft.go:248  [n1,s1,r30/1:/Table/3{4-5}] 6795  proposing SIMPLE(v2) [(n3,s3):2]: after=[(n1,s1):1 (n3,s3):2] next=3
I210126 22:27:41.243663 859284 kv/kvserver/replica_command.go:1748  [n1,replicate,s1,r30/1:/Table/3{4-5}] 6796  change replicas (add [(n2,s2):3LEARNER] remove []): existing descriptor r30:/Table/3{4-5} [(n1,s1):1, (n3,s3):2, next=3, gen=2]
I210126 22:27:41.253909 859284 kv/kvserver/replica_raft.go:248  [n1,s1,r30/1:/Table/3{4-5}] 6797  proposing SIMPLE(l3) [(n2,s2):3LEARNER]: after=[(n1,s1):1 (n3,s3):2 (n2,s2):3LEARNER] next=4
I210126 22:27:41.260447 859284 kv/kvserver/store_snapshot.go:1142  [n1,replicate,s1,r30/1:/Table/3{4-5}] 6798  streamed LEARNER_INITIAL snapshot 5939eca2 at applied index 19 to (n2,s2):3LEARNER in 0.00s @ 12 MiB/s: kv pairs: 11, log entries: 0, rate-limit: 8.0 MiB/s, queued: 0.00s
I210126 22:27:41.260995 864924 kv/kvserver/replica_raftstorage.go:820  [n2,s2,r30/3:{-}] 6799  applying snapshot of type LEARNER_INITIAL [id=5939eca2 index=19]
I210126 22:27:41.261070 864935 kv/kvserver/raft_snapshot_queue.go:126  [n1,raftsnapshot,s1,r30/1:/Table/3{4-5}] 6800  skipping snapshot; replica is likely a learner in the process of being added: (n2,s2):3LEARNER
I210126 22:27:41.264804 864924 kv/kvserver/replica_raftstorage.go:841  [n2,s2,r30/3:/Table/3{4-5}] 6801  applied snapshot of type LEARNER_INITIAL [total=4msingestion=4@2msid=5939eca2 index=19]
I210126 22:27:41.265787 859284 kv/kvserver/replica_command.go:1748  [n1,replicate,s1,r30/1:/Table/3{4-5}] 6802  change replicas (add [(n2,s2):3] remove []): existing descriptor r30:/Table/3{4-5} [(n1,s1):1, (n3,s3):2, (n2,s2):3LEARNER, next=4, gen=3]
I210126 22:27:41.276188 859284 kv/kvserver/replica_raft.go:248  [n1,s1,r30/1:/Table/3{4-5}] 6803  proposing SIMPLE(v3) [(n2,s2):3]: after=[(n1,s1):1 (n3,s3):2 (n2,s2):3] next=4
I210126 22:27:41.294029 859284 testutils/testcluster/testcluster.go:938  [-] 6804  WaitForFullReplication took: 2.640980963s
I210126 22:27:41.347250 865330 kv/kvserver/replica_command.go:396  [n1,split,s1,r35/1:/{Table/39-Max}] 6805  initiating a split of this range at key /Table/53 [r36] (zone config)
I210126 22:27:41.380603 864996 util/log/event_log.go:32  [n1,client=127.0.0.1:45218,hostssl,user=root] 6806 ={"Timestamp":1611700061368121963,"EventType":"set_cluster_setting","Statement":"SET CLUSTER SETTING \"kv.closed_timestamp.target_duration\" = '5s'","User":"root","SettingName":"kv.closed_timestamp.target_duration","Value":"00:00:05"}
I210126 22:27:41.389391 864996 util/log/event_log.go:32  [n1,client=127.0.0.1:45218,hostssl,user=root] 6807 ={"Timestamp":1611700061381726817,"EventType":"set_cluster_setting","Statement":"SET CLUSTER SETTING \"kv.closed_timestamp.close_fraction\" = 0.333","User":"root","SettingName":"kv.closed_timestamp.close_fraction","Value":"0.333"}
I210126 22:27:41.406058 864996 util/log/event_log.go:32  [n1,client=127.0.0.1:45218,hostssl,user=root] 6808 ={"Timestamp":1611700061394264718,"EventType":"set_cluster_setting","Statement":"SET CLUSTER SETTING \"kv.closed_timestamp.follower_reads_enabled\" = true","User":"root","SettingName":"kv.closed_timestamp.follower_reads_enabled","Value":"true"}
I210126 22:27:41.424104 859284 kv/kvserver/replica_command.go:396  [n1,s1,r36/1:/{Table/53-Max}] 6809  initiating a split of this range at key /Table/53/1/1 [r37] (manual)
I210126 22:27:41.452496 859284 kv/kvserver/replica_command.go:396  [n1,s1,r37/1:/{Table/53/1/1-Max}] 6810  initiating a split of this range at key /Table/53/1/2 [r38] (manual)
I210126 22:27:41.471744 859284 testutils/testcluster/testcluster.go:934  [-] 6811  WaitForFullReplication
I210126 22:27:41.485943 859284 testutils/testcluster/testcluster.go:938  [-] 6812  WaitForFullReplication took: 14.135018ms
I210126 22:27:41.488537 866194 kv/kvserver/replica_command.go:652  [n1,s1,r37/1:/Table/53/1/{1-2}] 6813  initiating a merge of r38:/{Table/53/1/2-Max} [(n1,s1):1, (n2,s2):2, (n3,s3):3, next=4, gen=7] into this range (manual)
    closed_timestamp_test.go:603: kv/kvserver/replica_command.go:769: merge failed: waiting for all right-hand replicas to catch up: rpc error: code = Unknown desc = r38 was not found on s3
    closed_timestamp_test.go:594: kv/kvserver/replica_command.go:769: merge failed: waiting for all right-hand replicas to catch up: rpc error: code = Unknown desc = r38 was not found on s3
I210126 22:27:41.510982 859284 util/stop/stopper.go:560  [-] 6814  quiescing
I210126 22:27:41.511014 859284 testutils/testcluster/testcluster.go:97  [-] 6815  TestCluster quiescing nodes
I210126 22:27:41.511057 866189 util/stop/stopper.go:560  [n3] 6816  quiescing
I210126 22:27:41.513371 866187 util/stop/stopper.go:560  [n1] 6817  quiescing
I210126 22:27:41.513852 866188 util/stop/stopper.go:560  [n2] 6818  quiescing
W210126 22:27:41.514274 864436 kv/kvserver/intentresolver/intent_resolver.go:752  [-] 6819  failed to gc transaction record: could not GC completed transaction anchored at /Local/Range/System/NodeLiveness/RangeDescriptor: node unavailable; try another peer
W210126 22:27:41.515667 861067 jobs/registry.go:700  [-] 6820  canceling all adopted jobs due to stopper quiescing
W210126 22:27:41.517001 862457 sql/sqlliveness/slinstance/slinstance.go:183  [n3] 6821  exiting heartbeat loop
W210126 22:27:41.522057 861066 sql/sqlliveness/slinstance/slinstance.go:183  [n1] 6822  exiting heartbeat loop
W210126 22:27:41.522117 862458 jobs/registry.go:700  [-] 6823  canceling all adopted jobs due to stopper quiescing
W210126 22:27:41.523163 862040 sql/sqlliveness/slinstance/slinstance.go:183  [n2] 6824  exiting heartbeat loop
W210126 22:27:41.523246 862408 kv/kvserver/raft_transport.go:633  [n2] 6825  while processing outgoing Raft queue to node 1: rpc error: code = Canceled desc = grpc: the client connection is closing:
W210126 22:27:41.523313 862041 jobs/registry.go:700  [-] 6826  canceling all adopted jobs due to stopper quiescing
    --- FAIL: TestClosedTimestampInactiveAfterSubsumption/without_lease_transfer (3.94s)

More

Parameters:

• GOFLAGS=-json

make stressrace TESTS=TestClosedTimestampInactiveAfterSubsumption PKG=./pkg/kv/kvserver TESTTIMEOUT=5m STRESSFLAGS='-timeout 5m' 2>&1

See this test on roachdash
_{powered by pkg/cmd/internal/issues}