kv/kvserver: TestLeaseExpirationBasedDrainTransferWithExtension failed

[cockroach-teamcity]

kv/kvserver.TestLeaseExpirationBasedDrainTransferWithExtension failed with artifacts on release-23.1.11-rc @ b2012193c9558ed2f6541da27469a8c5ecca52ae:

=== RUN   TestLeaseExpirationBasedDrainTransferWithExtension
    test_log_scope.go:161: test logs captured to: /artifacts/tmp/_tmp/33e1d369c27b9c01b2b6009c561815a3/logTestLeaseExpirationBasedDrainTransferWithExtension2127012733
    test_log_scope.go:79: use -show-logs to present logs inline
    client_replica_test.go:1806: condition failed to evaluate within 3m45s: [NotLeaseHolderError] lease held by different store; r64: replica (n1,s1):1 not lease holder; current lease is repl=(n2,s2):2 seq=2 start=1694777961.282534834,0 exp=1694778193.624914971,0 pro=1694778187.624914971,0
    panic.go:540: -- test log scope end --
test logs left over in: /artifacts/tmp/_tmp/33e1d369c27b9c01b2b6009c561815a3/logTestLeaseExpirationBasedDrainTransferWithExtension2127012733
--- FAIL: TestLeaseExpirationBasedDrainTransferWithExtension (233.09s)

Parameters: TAGS=bazel,gss,race

Help

See also: How To Investigate a Go Test Failure (internal)

/cc @cockroachdb/kv

This test on roachdash | Improve this report!

Jira issue: CRDB-31574

[andrewbaptist]

@kvoli I'm removing the release blocker tag, but can you take a look at this when you get a chance? We have seen few failures that are similar to this so just wanted to make sure this wasn't anything new.

[nvanbenschoten]

I can reproduce after 524 runs completed, 1 failures, over 8m18s under stress + race.

dev test pkg/kv/kvserver -f=TestLeaseExpirationBasedDrainTransferWithExtension --race --stress

I'm taking a look at what's going wrong.

[nvanbenschoten]

We see the lease extension get blocked, unblocked, and then succeed:

I230925 14:41:54.292263 4082 kv/kvserver_test/client_replica_test.go:1544 ⋮ [T1,n2,s2,r64/2:‹/System{\x00aaa-test…-/NodeLive…}›] 215  filter blocking request: ‹header:<key:"\004\000aaa-testing" > lease:<start:<wall_time:1695652917282965205 > expiration:<wall_time:1695652923282965205 > replica:<node_id:2 store_id:2 replica_id:2 type:VOTER_FULL > proposed_ts:<wall_time:1695652917282965205 > > prev_lease:<start:<wall_time:1695652914275046965 > expiration:<wall_time:1695652920274444638 > replica:<node_id:2 store_id:2 replica_id:2 type:VOTER_FULL > proposed_ts:<wall_time:1695652914274444638 > sequence:2 acquisition_type:Transfer > min_proposed_ts:<>›
I230925 14:41:54.298729 4082 kv/kvserver_test/client_replica_test.go:1546 ⋮ [T1,n2,s2,r64/2:‹/System{\x00aaa-test…-/NodeLive…}›] 216  filter unblocking lease request

After this point, we see the drain get stuck waiting to transfer away the lease:

I230925 14:41:57.521738 4083 kv/kvserver/store.go:1823 ⋮ [drain] 257  waiting for 1 replicas to transfer their lease away
I230925 14:41:54.352268 3140 kv/kvserver/replica_proposal.go:276 ⋮ [T1,n2,s2,r64/2:‹/System{\x00aaa-test…-/NodeLive…}›,raft] 224  new range lease repl=(n2,s2):2 seq=2 start=1695652914.275046965,0 exp=1695652923.282965205,0 pro=1695652917.282965205,0 following repl=(n2,s2):2 seq=2 start=1695652914.275046965,0 exp=1695652920.274444638,0 pro=1695652914.274444638,0
...
I230925 14:41:57.521738 4083 kv/kvserver/store.go:1823 ⋮ [drain] 257  waiting for 1 replicas to transfer their lease away
I230925 14:41:57.897760 3142 kv/kvserver/replica_proposal.go:276 ⋮ [T1,n2,s2,r64/2:‹/System{\x00aaa-test…-/NodeLive…}›,raft] 258  new range lease repl=(n2,s2):2 seq=2 start=1695652914.275046965,0 exp=1695652926.883641757,0 pro=1695652920.883641757,0 following repl=(n2,s2):2 seq=2 start=1695652914.275046965,0 exp=1695652923.282965205,0 pro=1695652917.282965205,0

Eventually, the drain hits a 5s timeout:

I230925 14:41:59.316693 4083 kv/kvserver/store.go:1823 ⋮ [drain] 262  waiting for 1 replicas to transfer their lease away
W230925 14:41:59.356646 4083 kv/kvserver/store.go:1839 ⋮ [drain] 263  unable to drain cleanly within 5s (cluster setting ‹server.shutdown.lease_transfer_wait›), service might briefly deteriorate if the node is terminated: waiting for 1 replicas to transfer their lease away

At this point, we give up on the drain and the test is bound to eventually fail.

The questions to answer are:

• what's blocking the lease transfer from n2 to n1?
• would the drain have ever completed if this timeout was higher?
• why are we now occasionally hitting this 5s timeout?

[nvanbenschoten]

With additional logging (--vmodule=store=1), I see the following log lines repeating:

I230925 15:30:40.343542 4708 kv/kvserver/store.go:1736 ⋮ [T1,drain,n2,s2,r64/2:‹/System{\x00aaa-test…-/NodeLive…}›] 271  attempting to transfer lease repl=(n2,s2):2 seq=2 start=1695655839.861607363,0 exp=1695655849.138051962,0 pro=1695655843.138051962,0 for range r64:‹/System{\x00aaa-testing-/NodeLiveness}› [(n1,s1):1, (n2,s2):2, next=3, gen=3, sticky=9223372036.854775807,2147483647]
E230925 15:30:40.344498 4708 kv/kvserver/store.go:1767 ⋮ [T1,drain,n2,s2,r64/2:‹/System{\x00aaa-test…-/NodeLive…}›] 272  failed to transfer lease repl=(n2,s2):2 seq=2 start=1695655839.861607363,0 exp=1695655849.138051962,0 pro=1695655843.138051962,0 for range r64:‹/System{\x00aaa-testing-/NodeLiveness}› [(n1,s1):1, (n2,s2):2, next=3, gen=3, sticky=9223372036.854775807,2147483647] when draining: ‹no suitable transfer target found›

So the lease transfer repeatedly hits a no suitable transfer target found status.

[nvanbenschoten]

This reminds me of #101885.

[nvanbenschoten]

n1 seems to be getting filtered out as a lease transfer target here:

cockroach/pkg/kv/kvserver/allocator/allocatorimpl/allocator.go

Lines 1986 to 1988 in b201219

	candidates, _ = storePool.LiveAndDeadReplicas(
	candidates, false, /* includeSuspectAndDrainingStores */
	)

[andrewbaptist]

Was the store recently started or flapping liveness?

[nvanbenschoten]

It wasn't recently restarted, but I think the liveness is artificially flapping because the test is messing with manual clocks and injecting large clock jumps.

[nvanbenschoten]

Fixed by #111254.