kubelet: Race condition in nodeshutdown unit test

[MadhavJivrajani]

What happened?

There seems to be a race condition in the following unit test

kubernetes/pkg/kubelet/nodeshutdown/nodeshutdown_manager_linux_test.go

Line 617 in 40c2d04

func Test_managerImpl_processShutdownEvent(t *testing.T) {

The race happens between
read at

kubernetes/pkg/kubelet/nodeshutdown/nodeshutdown_manager_linux_test.go

Line 707 in 40c2d04

log := tmpWriteBuffer.String()

and write at

kubernetes/pkg/kubelet/nodeshutdown/nodeshutdown_manager_linux.go

Line 328 in 40c2d04

klog.V(1).InfoS("Shutdown manager finished killing pod", "pod", klog.KObj(pod))

What did you expect to happen?

No race condition

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

cd $KUBE_ROOT/pkg/kubelet/nodeshutdown
go test -c -race
stress ./nodeshutdown.test -test.run ^Test_managerImpl_processShutdownEvent$

Anything else we need to know?

CI logs where race was detected: https://prow.k8s.io/view/gs/kubernetes-jenkins/pr-logs/pull/108039/pull-kubernetes-unit/1491676749694504960

Kubernetes version

$ 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 and version (if applicable)

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

[MadhavJivrajani]

/sig node
/cc @adisky @endocrimes

[MadhavJivrajani]

/remove-kind bug
/kind flake
(potential flake, did not use the flake template because CI is green for this test)

[kerthcet]

A related pr merged #107774 @MadhavJivrajani

[utkarsh348]

/assign

[MadhavJivrajani]

Thanks @utkarsh348, for checking again.
#107774 (comment)
@kerthcet fyi

[MadhavJivrajani]

Maybe we need something like this: #98944?

[jonyhy96]

@utkarsh348 are u working on resolve this issue? i wonder why

kubernetes/staging/src/k8s.io/client-go/transport/round_trippers_test.go

Line 518 in d899c39

// hijack the klog output

doesn't face a race condition

[MadhavJivrajani]

I think he's still working on it.
The race condition doesn't happen there because

kubernetes/staging/src/k8s.io/client-go/transport/round_trippers_test.go

Line 534 in d899c39

NewDebuggingRoundTripper(rt, tc.levels...).RoundTrip(req)

doesn't start another go routine. In the kubelet's case however, the write part of the race condition happens in another go routine that is spawned:

kubernetes/pkg/kubelet/nodeshutdown/nodeshutdown_manager_linux.go

Line 303 in 40c2d04

go func(pod *v1.Pod, group podShutdownGroup) {

write:

kubernetes/pkg/kubelet/nodeshutdown/nodeshutdown_manager_linux.go

Line 328 in 40c2d04

klog.V(1).InfoS("Shutdown manager finished killing pod", "pod", klog.KObj(pod))

[SergeyKanzhelev]

/triage accepted
/priority important-soon

[liggitt]

seen in https://prow.k8s.io/view/gs/kubernetes-jenkins/pr-logs/pull/109048/pull-kubernetes-unit/1507725298571939840

this spiked in the last couple days - https://storage.googleapis.com/k8s-triage/index.html?pr=1&test=TestLocalStorage

is this related to the klog bump (#108725)?

cc @pohly

/priority critical-urgent
/milestone v1.24

[liggitt]

increasing priority since it is impacting test runs, and marking as blocker until root caused and we understand whether it is prod-impacting

[endocrimes]

/assign

^ I'll take this one up on monday - @utkarsh348 still feel free to open a PR if you have WIP investigation/research

[MadhavJivrajani]

@endocrimes please see #108193
if you have comments/inputs on the already open one.

[pohly]

seen in https://prow.k8s.io/view/gs/kubernetes-jenkins/pr-logs/pull/109048/pull-kubernetes-unit/1507725298571939840

this spiked in the last couple days - https://storage.googleapis.com/k8s-triage/index.html?pr=1&test=TestLocalStorage

is this related to the klog bump (#108725)?

cc @pohly

I don't see how the klog bump could have made it worse. Perhaps the change around the flush daemon changed some timing conditions, but that's a rather wild guess. These tests have been faulty all along and need to be fixed.

What klog can do is support unit tests like this better. I've opened two issues:

• short term: restore state in unit tests
• long term as it depends on contextual logging: capture klog output without SetBuffer

[MadhavJivrajani]

increasing priority since it is impacting test runs, and marking as blocker until root caused and we understand whether it is prod-impacting

@liggitt I think it's safe to remove the release-blocker here. The root cause is largely as explained here: #108040 (comment) (appears to be test-only)