pkg/server: TestDrain is flakey

[fantapop]

Describe the problem

TestDrain has been flaking a lot today.

Failed
=== RUN   TestDrain
    test_log_scope.go:161: test logs captured to: /artifacts/tmp/_tmp/ab5462d2cb3989e2a33018db970f23de/logTestDrain523638963
    test_log_scope.go:79: use -show-logs to present logs inline
    drain_test.go:254: expected remaining false, got true
    panic.go:500: -- test log scope end --
--- FAIL: TestDrain (74.31s)

Jira issue: CRDB-19064

[rafiss]

Do you have a link to a failure?

I looked at the Test History on Bazel CI and Github CI, and it says 1000 of the last 1000 runs have passed.

[fantapop]

its failing in Merged Bazel Extended CI This is one of the build statuses that posts to the flaky-test-fighter-ops channel.

[adityamaru]

This test is failing pretty consistently under testrace so I'm going to skip it under race as flaky-test oncall. @rafiss is sql-experience going to own unskipping this or should I rope someone else in?

[rafiss]

KV is a better home for this

[shralex]

@AlexTalks can you take a look please

[blathers-crl]

Hi @nvanbenschoten, 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.}

[AlexTalks]

So here is what I am seeing when I run this under race:

# test: sendDrainNoShutdown()
I230325 00:39:15.227264 14158 1@server/drain.go:145 ⋮ [T1,n1] 373  drain request received with doDrain = true, shutdown = false
...
I230325 00:39:17.782437 14158 1@server/drain.go:399 ⋮ [T1,n1] 377  (DEBUG) initiating kvserver node drain
I230325 00:39:17.782596 14158 1@kv/kvserver/store.go:1559 ⋮ [T1,drain,n1,s1] 378  (DEBUG) store marked as draining
I230325 00:39:18.149121 14158 1@server/drain.go:293 ⋮ [T1,n1] 379  drain remaining: 51
I230325 00:39:18.149263 14158 1@server/drain.go:295 ⋮ [T1,n1] 380  drain details: descriptor leases: 22, liveness record: 1, range lease iterations: 28
I230325 00:39:18.149475 14158 1@server/drain.go:175 ⋮ [T1,n1] 381  drain request completed without server shutdown

# test: sendDrainNoShutdown() again
I230325 00:39:18.151604 14728 1@server/drain.go:145 ⋮ [T1,n1] 383  drain request received with doDrain = true, shutdown = false
...
I230325 00:39:18.155547 986 kv/kvserver/replica_proposal.go:272 ⋮ [T1,n1,s1,r51/1:‹/Table/5{0-1}›,raft] 385  new range lease repl=(n1,s1):1 seq=1 start=0,0 exp=1679704764.152223164,0 pro=1679704758.152223164,0 following repl=(n1,s1):1 seq=1 start=0,0 exp=1679704746.135729956,0 pro=1679704740.135729956,0
I230325 00:39:18.172450 14728 1@server/drain.go:399 ⋮ [T1,n1] 386  (DEBUG) initiating kvserver node drain
I230325 00:39:18.172613 14728 1@kv/kvserver/store.go:1559 ⋮ [T1,drain,n1,s1] 387  (DEBUG) store marked as draining
I230325 00:39:18.182123 14728 1@server/drain.go:293 ⋮ [T1,n1] 388  drain remaining: 1
I230325 00:39:18.182249 14728 1@server/drain.go:295 ⋮ [T1,n1] 389  drain details: range lease iterations: 1
I230325 00:39:18.182404 14728 1@server/drain.go:175 ⋮ [T1,n1] 390  drain request completed without server shutdown

Have confirmed this across multiple test runs, and it seems like after the first drain / before the second drain starts when store.SetDraining(...) is called again, there's a lease extension that happens. It seems like when this occurs, the second call to drain ends up having 1 lease remaining - I'm not sure if this should be transferred away (and thus should be 0) before the remaining count is reported by store.SetDraining(..), or if this is entirely acceptable behavior and it's simply that we need to call sendDrainNoShutdown() repeatedly until we have no more remaining leases, sort of like how the CLI does it.

I have a fix I'm putting up that changes the test to reissue the drain request until there are no more leases remaining, but if there's actually an issue here with the lease extension occuring (or store.setDraining(..) not reporting the remaining number correctly) we'll want to fix that instead.