Fix flaky unit test Test_Run_Positive_VolumeMountControllerAttachEnabledRace data race #94676

JornShen · 2020-09-10T11:45:43Z

What type of PR is this?

/kind bug
/kind flake

What this PR does / why we need it:

what's the failed

one failed output

WARNING: DATA RACE
Write at 0x00c000116ba0 by goroutine 20:
  k8s.io/kubernetes/pkg/kubelet/volumemanager/reconciler.Test_Run_Positive_VolumeMountControllerAttachEnabledRace()
      /opt/workspace/myspace/k8s/kubernetes/pkg/kubelet/volumemanager/reconciler/reconciler_test.go:1794 +0x12fe
  testing.tRunner()
      /usr/local/go/src/testing/testing.go:1108 +0x202

Previous read at 0x00c000116ba0 by goroutine 25:
  k8s.io/kubernetes/pkg/volume/testing.(*FakeVolumePlugin).getFakeVolume()
      /opt/workspace/myspace/k8s/kubernetes/pkg/volume/testing/testing.go:416 +0x5bd
  k8s.io/kubernetes/pkg/volume/testing.(*FakeVolumePlugin).NewAttacher()
      /opt/workspace/myspace/k8s/kubernetes/pkg/volume/testing/testing.go:560 +0xf9
  k8s.io/kubernetes/pkg/volume/testing.(*FakeVolumePlugin).NewDeviceMounter()
      /opt/workspace/myspace/k8s/kubernetes/pkg/volume/testing/testing.go:564 +0x3c
  k8s.io/kubernetes/pkg/volume/util/operationexecutor.(*operationGenerator).GenerateMountVolumeFunc.func1()
      /opt/workspace/myspace/k8s/kubernetes/pkg/volume/util/operationexecutor/operation_generator.go:540 +0x2251
  k8s.io/kubernetes/pkg/volume/util/types.(*GeneratedOperations).Run()
      /opt/workspace/myspace/k8s/kubernetes/pkg/volume/util/types/types.go:54 +0x142
  k8s.io/kubernetes/pkg/volume/util/nestedpendingoperations.(*nestedPendingOperations).Run.func1()
/opt/workspace/myspace/k8s/kubernetes/pkg/volume/util/nestedpendingoperations/nestedpendingoperations.go:183 +0x159

Goroutine 20 (running) created at:
  testing.(*T).Run()
      /usr/local/go/src/testing/testing.go:1159 +0x796
  testing.runTests.func1()
      /usr/local/go/src/testing/testing.go:1430 +0xa6
  testing.tRunner()
      /usr/local/go/src/testing/testing.go:1108 +0x202
  testing.runTests()
      /usr/local/go/src/testing/testing.go:1428 +0x5aa
  testing.(*M).Run()
      /usr/local/go/src/testing/testing.go:1338 +0x4eb
  main.main()
      _testmain.go:73 +0x236

Goroutine 25 (running) created at: 
  k8s.io/kubernetes/pkg/volume/util/nestedpendingoperations.(*nestedPendingOperations).Run()
      /opt/workspace/myspace/k8s/kubernetes/pkg/volume/util/nestedpendingoperations/nestedpendingoperations.go:178 +0x5b2
  k8s.io/kubernetes/pkg/volume/util/operationexecutor.(*operationExecutor).MountVolume()
      /opt/workspace/myspace/k8s/kubernetes/pkg/volume/util/operationexecutor/operation_executor.go:839 +0x2b0
  k8s.io/kubernetes/pkg/kubelet/volumemanager/reconciler.(*reconciler).mountAttachVolumes()
      /opt/workspace/myspace/k8s/kubernetes/pkg/kubelet/volumemanager/reconciler/reconciler.go:255 +0x974
I0909 22:54:05.010993   24541 operation_generator.go:595] MountVolume.MountDevice succeeded for volume "volume-name" (UniqueName: "fake-plugin/fake-device1") pod "pod1" (UID: "pod1uid") device mount path ""
  k8s.io/kubernetes/pkg/kubelet/volumemanager/reconciler.(*reconciler).reconcile()
      /opt/workspace/myspace/k8s/kubernetes/pkg/kubelet/volumemanager/reconciler/reconciler.go:174 +0x46
  k8s.io/kubernetes/pkg/kubelet/volumemanager/reconciler.(*reconciler).reconciliationLoopFunc.func1()
      /opt/workspace/myspace/k8s/kubernetes/pkg/kubelet/volumemanager/reconciler/reconciler.go:151 +0x4a
  k8s.io/apimachinery/pkg/util/wait.BackoffUntil.func1()
      /opt/workspace/myspace/k8s/kubernetes/vendor/k8s.io/apimachinery/pkg/util/wait/wait.go:155 +0x75
  k8s.io/apimachinery/pkg/util/wait.BackoffUntil()
      /opt/workspace/myspace/k8s/kubernetes/vendor/k8s.io/apimachinery/pkg/util/wait/wait.go:156 +0xba
  k8s.io/apimachinery/pkg/util/wait.JitterUntil()
      /opt/workspace/myspace/k8s/kubernetes/vendor/k8s.io/apimachinery/pkg/util/wait/wait.go:133 +0x114
  k8s.io/apimachinery/pkg/util/wait.Until()
      /opt/workspace/myspace/k8s/kubernetes/vendor/k8s.io/apimachinery/pkg/util/wait/wait.go:90 +0x8e
  k8s.io/kubernetes/pkg/kubelet/volumemanager/reconciler.(*reconciler).Run()
      /opt/workspace/myspace/k8s/kubernetes/pkg/kubelet/volumemanager/reconciler/reconciler.go:146 +0x2f
  k8s.io/kubernetes/pkg/kubelet/volumemanager/reconciler.Test_Run_Positive_VolumeMountControllerAttachEnabledRace.func1()
      /opt/workspace/myspace/k8s/kubernetes/pkg/kubelet/volumemanager/reconciler/reconciler_test.go:1785 +0x48

from the output, we can find the two routine run the race to WaitForAttachHook and UnmountDeviceHook of FakeVolumePlugin.

one routine created at

kubernetes/pkg/volume/util/nestedpendingoperations/nestedpendingoperations.go

Line 183 in c3b888f

return generatedOperations.Run()

and most origin from Test_Run_Positive_VolumeMountControllerAttachEnabledRace

kubernetes/pkg/kubelet/volumemanager/reconciler/reconciler_test.go

Line 1785 in c3b888f

reconciler.Run(stopChan)

this children routine read field WaitForAttachHook and UnmountDeviceHook from FakeVolumePlugin

kubernetes/pkg/volume/testing/testing.go

Lines 415 to 416 in c3b888f

    
           volume.WaitForAttachHook = plugin.WaitForAttachHook 
        
           volume.UnmountDeviceHook = plugin.UnmountDeviceHook

while main routine in Test_Run_Positive_VolumeMountControllerAttachEnabledRace reset field WaitForAttachHook and UnmountDeviceHook of FakeVolumePlugin

kubernetes/pkg/kubelet/volumemanager/reconciler/reconciler_test.go

Line 1794 in c3b888f

fakePlugin.UnmountDeviceHook = func(mountPath string) error {

kubernetes/pkg/kubelet/volumemanager/reconciler/reconciler_test.go

Line 1804 in c3b888f

    
           fakePlugin.WaitForAttachHook = func(spec *volume.Spec, devicePath string, pod *v1.Pod, spectimeout time.Duration) (string, error) {

and they case the data race.(one read data and the other set data)

how to deal with it

children routine's trace code is in method getFakeVolume, the the caller is the method NewAttacher

kubernetes/pkg/volume/testing/testing.go

Lines 556 to 561 in c3b888f

    
           func (plugin *FakeVolumePlugin) NewAttacher() (Attacher, error) { 
        
           	plugin.Lock() 
        
           	defer plugin.Unlock() 
        
           	plugin.NewAttacherCallCount = plugin.NewAttacherCallCount + 1 
        
           	return plugin.getFakeVolume(&plugin.Attachers), nil 
        
           }

so in FakeVolumePlugin object, it has a lock to sync the data changing.

kubernetes/pkg/volume/testing/testing.go

Lines 370 to 372 in c3b888f

    
           type FakeVolumePlugin struct { 
        
           	sync.RWMutex 
        
           	PluginName             string

so from the outside in Test_Run_Positive_VolumeMountControllerAttachEnabledRace, we should acquire lock before we reset the field WaitForAttachHook and UnmountDeviceHook of FakeVolumePlugin.

result of test when using my fix

running result on my local robot.

34017 runs so far, 0 failures
34096 runs so far, 0 failures

Which issue(s) this PR fixes:

Fixes # #94568
Part of # #94528 (comment)

Does this PR introduce a user-facing change?:

NONE

k8s-ci-robot · 2020-09-10T11:45:53Z

Hi @JornShen. Thanks for your PR.

I'm waiting for a kubernetes member to verify that this patch is reasonable to test. If it is, they should reply with /ok-to-test on its own line. Until that is done, I will not automatically test new commits in this PR, but the usual testing commands by org members will still work. Regular contributors should join the org to skip this step.

Once the patch is verified, the new status will be reflected by the ok-to-test label.

I understand the commands that are listed here.

Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the kubernetes/test-infra repository.

JornShen · 2020-09-10T11:46:37Z

/cc @liggitt

k8s-ci-robot · 2020-09-10T11:47:05Z

@JornShen: Cannot trigger testing until a trusted user reviews the PR and leaves an /ok-to-test message.

In response to this:

/ok-to-test

Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the kubernetes/test-infra repository.

Lion-Wei · 2020-09-10T12:21:30Z

/ok-to-test

figo · 2020-09-11T06:12:00Z

/test pull-kubernetes-bazel-test

JornShen · 2020-09-11T07:31:33Z

/cc @liggitt @knight42 @msau42

pkg/kubelet/volumemanager/reconciler/reconciler_test.go

gnufied · 2020-09-14T23:32:41Z

/assign

JornShen · 2020-09-18T01:18:06Z

ping @gnufied

…ledRace data race ref: kubernetes#94568

msau42 · 2020-10-26T20:53:44Z

Apologies for the delay.

Looking at the test, the test stops and waits for the reconciler to stop before proceeding to update the hooks. It seems like maybe the issue could be that stopping reconciler doesn't wait for nested pending operations to finish?

JornShen · 2020-10-27T08:49:54Z

Apologies for the delay.

Looking at the test, the test stops and waits for the reconciler to stop before proceeding to update the hooks. It seems like maybe the issue could be that stopping reconciler doesn't wait for nested pending operations to finish?

@msau42. yeah, it can see from the trace log. reconciler will not wait pendingOperations.run as the latter run a routine to deal with generatedOperations.Run() which will get hook inside.

msau42 · 2020-10-27T23:49:36Z

I think adding the lock is fine. If the pending operation is still running, then it will finish without the hook set, and and a future reconciler loop will run the operation again with the hook set.

msau42 · 2020-10-27T23:52:38Z

/lgtm
/approve

Thanks for the fix!

k8s-ci-robot · 2020-10-27T23:53:18Z

[APPROVALNOTIFIER] This PR is APPROVED

This pull-request has been approved by: JornShen, msau42

The full list of commands accepted by this bot can be found here.

The pull request process is described here

Needs approval from an approver in each of these files:

~~pkg/kubelet/volumemanager/OWNERS~~ [msau42]

Approvers can indicate their approval by writing /approve in a comment
Approvers can cancel approval by writing /approve cancel in a comment

JornShen · 2020-10-28T01:29:36Z

/kind bug
/kind flake

JornShen · 2020-10-28T02:22:01Z

/test pull-kubernetes-e2e-kind
/test pull-kubernetes-e2e-gce-ubuntu-containerd

JornShen · 2020-10-28T03:57:21Z

/test pull-kubernetes-e2e-gce-ubuntu-containerd

JornShen · 2020-10-28T06:11:45Z

/test pull-kubernetes-node-e2e

k8s-ci-robot added area/kubelet sig/node Categorizes an issue or PR as relevant to SIG Node. and removed needs-sig Indicates an issue or PR lacks a `sig/foo` label and requires one. labels Sep 10, 2020

k8s-ci-robot requested review from gnufied and verult September 10, 2020 11:46

k8s-ci-robot added ok-to-test Indicates a non-member PR verified by an org member that is safe to test. and removed needs-ok-to-test Indicates a PR that requires an org member to verify it is safe to test. labels Sep 10, 2020

JornShen mentioned this pull request Sep 11, 2020

[Failing Test] bazel-test-master (periodic-kubernetes-bazel-test-master) #94528

Closed

k8s-ci-robot requested review from knight42, liggitt and msau42 September 11, 2020 07:31

knight42 reviewed Sep 11, 2020

View reviewed changes

pkg/kubelet/volumemanager/reconciler/reconciler_test.go Show resolved Hide resolved

k8s-ci-robot assigned gnufied Sep 14, 2020

Fix flaky unit test Test_Run_Positive_VolumeMountControllerAttachEnab…

b6b462b

…ledRace data race ref: kubernetes#94568

JornShen force-pushed the fix_Test_Run_Positive_VolumeMountControllerAttachEnabledRace_data_trace branch from c0870c9 to b6b462b Compare October 19, 2020 08:29

k8s-ci-robot assigned msau42 Oct 27, 2020

k8s-ci-robot added the lgtm "Looks good to me", indicates that a PR is ready to be merged. label Oct 27, 2020

k8s-ci-robot added the approved Indicates a PR has been approved by an approver from all required OWNERS files. label Oct 27, 2020

k8s-ci-robot added kind/bug Categorizes issue or PR as related to a bug. kind/flake Categorizes issue or PR as related to a flaky test. and removed needs-kind Indicates a PR lacks a `kind/foo` label and requires one. labels Oct 28, 2020

k8s-ci-robot merged commit a9e9cab into kubernetes:master Oct 28, 2020

k8s-ci-robot added this to the v1.20 milestone Oct 28, 2020

JornShen mentioned this pull request Oct 28, 2020

[Flaky unit test] Test_Run_Positive_VolumeMountControllerAttachEnabledRace data race #94568

Closed

JornShen mentioned this pull request Nov 5, 2020

REQUEST: New membership for JornShen kubernetes/org#2313

Closed

6 tasks

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Fix flaky unit test Test_Run_Positive_VolumeMountControllerAttachEnabledRace data race #94676

Fix flaky unit test Test_Run_Positive_VolumeMountControllerAttachEnabledRace data race #94676

JornShen commented Sep 10, 2020 •

edited

k8s-ci-robot commented Sep 10, 2020

JornShen commented Sep 10, 2020 •

edited

k8s-ci-robot commented Sep 10, 2020

Lion-Wei commented Sep 10, 2020

figo commented Sep 11, 2020

JornShen commented Sep 11, 2020

gnufied commented Sep 14, 2020

JornShen commented Sep 18, 2020

msau42 commented Oct 26, 2020

JornShen commented Oct 27, 2020

msau42 commented Oct 27, 2020

msau42 commented Oct 27, 2020

k8s-ci-robot commented Oct 27, 2020

JornShen commented Oct 28, 2020

JornShen commented Oct 28, 2020

JornShen commented Oct 28, 2020

JornShen commented Oct 28, 2020

	volume.WaitForAttachHook = plugin.WaitForAttachHook
	volume.UnmountDeviceHook = plugin.UnmountDeviceHook

	func (plugin *FakeVolumePlugin) NewAttacher() (Attacher, error) {
	plugin.Lock()
	defer plugin.Unlock()
	plugin.NewAttacherCallCount = plugin.NewAttacherCallCount + 1
	return plugin.getFakeVolume(&plugin.Attachers), nil
	}

Fix flaky unit test Test_Run_Positive_VolumeMountControllerAttachEnabledRace data race #94676

Fix flaky unit test Test_Run_Positive_VolumeMountControllerAttachEnabledRace data race #94676

Conversation

JornShen commented Sep 10, 2020 • edited

k8s-ci-robot commented Sep 10, 2020

JornShen commented Sep 10, 2020 • edited

k8s-ci-robot commented Sep 10, 2020

Lion-Wei commented Sep 10, 2020

figo commented Sep 11, 2020

JornShen commented Sep 11, 2020

gnufied commented Sep 14, 2020

JornShen commented Sep 18, 2020

msau42 commented Oct 26, 2020

JornShen commented Oct 27, 2020

msau42 commented Oct 27, 2020

msau42 commented Oct 27, 2020

k8s-ci-robot commented Oct 27, 2020

JornShen commented Oct 28, 2020

JornShen commented Oct 28, 2020

JornShen commented Oct 28, 2020

JornShen commented Oct 28, 2020

JornShen commented Sep 10, 2020 •

edited

JornShen commented Sep 10, 2020 •

edited