Flaky test failure in staging/src/k8s.io/client-go/util/workqueue

[tatsuhiro-t]

What happened?

$ go test -run TestAddTwoFireEarly -race -count=10000 ./staging/src/k8s.io/client-go/util/workqueue/...
--- FAIL: TestAddTwoFireEarly (10.01s)
    delaying_queue_test.go:160: unexpected err: timed out waiting for the condition
FAIL
FAIL	k8s.io/client-go/util/workqueue	100.405s
FAIL

What did you expect to happen?

Tests always succeed

How can we reproduce it (as minimally and precisely as possible)?

Run

go test -run TestAddTwoFireEarly -race -count=10000 ./staging/src/k8s.io/client-go/util/workqueue/...

Repeat until it fails.

Anything else we need to know?

If FakeClock.Step is called after https://github.com/kubernetes/client-go/blob/d2f5fba1f82d119e09288c70ce87bccb3dc119e4/util/workqueue/delaying_queue.go#L279 and before https://github.com/kubernetes/client-go/blob/d2f5fba1f82d119e09288c70ce87bccb3dc119e4/util/workqueue/delaying_queue.go#L300,
the created timer fires at entry.readyAt.Sub(now) + FakeClock.time that has been adjusted by FakeClock.Step.
Because we do not call FakeClock.Step with the positive duration anymore, this timer never fire. Note now is the FakeClock.time before it is adjusted by FakeClock.Step.

The proposed fix is as follows.
First add NewDeadlineTimer(t *time.Time) Timer to k8s.io/utils/clock.Clock, which fires at the given t.
Second, replace NewTimer with NewDeadlineTimer at https://github.com/kubernetes/client-go/blob/d2f5fba1f82d119e09288c70ce87bccb3dc119e4/util/workqueue/delaying_queue.go#L300
Finally, call FakeClock.Step(0) at https://github.com/kubernetes/client-go/blob/d2f5fba1f82d119e09288c70ce87bccb3dc119e4/util/workqueue/delaying_queue_test.go#L234 so that FakeClock deals with waiters.

Kubernetes version

```console $ kubectl version # paste output here ```

Cloud provider

OS version

# On Linux:
$ cat /etc/os-release
# paste output here
$ uname -a
# paste output here

# On Windows:
C:\> wmic os get Caption, Version, BuildNumber, OSArchitecture
# paste output here

Install tools

Container runtime (CRI) and version (if applicable)

Related plugins (CNI, CSI, ...) and versions (if applicable)

[tatsuhiro-t]

/sig api-machinery

[mauri870]

Is that reproducible for you with x/tools/stress?

$ go test -c -race ./staging/src/k8s.io/client-go/util/workqueue/...
$ go run golang.org/x/tools/cmd/stress@latest -p 256  ./workqueue.test -test.v -test.run ^TestAddTwoFireEarly$

Edit: I got it after a couple thousand runs

5s: 512 runs so far, 0 failures
10s: 1152 runs so far, 0 failures
15s: 1789 runs so far, 0 failures
20s: 2424 runs so far, 0 failures

/tmp/go-stress-20240619T095442-4267781378
=== RUN   TestAddTwoFireEarly
    delaying_queue_test.go:160: unexpected err: timed out waiting for the condition
--- FAIL: TestAddTwoFireEarly (10.00s)
FAIL


ERROR: exit status 1

25s: 3063 runs so far, 1 failures (0.03%)

[mauri870]

/triage accepted

[mauri870]

@tatsuhiro-t Your fix makes sense, are you planning on sending a PR? Thanks.

[mauri870]

/assign

[mauri870]

Just preassigning, if you want to work on it let me know.

[mauri870]

/kind flake

[mauri870]

/remove-kind bug

[tatsuhiro-t]

Yes, let me work on this issue.

I have not tried x/tools/stress. Lots of trials are needed to reproduce it.

[mauri870]

Thanks. I don't think -race is required to reproduce the issue. The race instrumentation might slow the runtime down just enough for this to reproduce more easier.

I had better luck reproducing with stress and a higher number of parallel processes:

go test -c ./staging/src/k8s.io/client-go/util/workqueue/...
go run golang.org/x/tools/cmd/stress@latest -p 1024 -failure unexpected ./workqueue.test -test.v -test.run ^TestAddTwoFireEarly$

/assign tatsuhiro-t

[tatsuhiro-t]

Yeah, I used -race to save the number of runs and time.