Skip to content

Conversation

@jwtty
Copy link
Collaborator

@jwtty jwtty commented May 1, 2025

Description of your changes

Recently we have seen some integration test flakiness due to data race, the race stack looks like:

Stack Trace
==================
WARNING: DATA RACE
Read at 0x00c00166b620 by goroutine 366:
  runtime.mapaccess2_faststr()
      /opt/hostedtoolcache/go/1.23.6/x64/src/runtime/map_faststr.go:117 +0x0
  k8s.io/apimachinery/pkg/apis/meta/v1/unstructured.NestedFieldNoCopy()
      /home/runner/go/pkg/mod/k8s.io/apimachinery@v0.31.1/pkg/apis/meta/v1/unstructured/helpers.go:61 +0x10f
  k8s.io/apimachinery/pkg/apis/meta/v1/unstructured.NestedString()
      /home/runner/go/pkg/mod/k8s.io/apimachinery@v0.31.1/pkg/apis/meta/v1/unstructured/helpers.go:75 +0x6b
  k8s.io/apimachinery/pkg/apis/meta/v1/unstructured.getNestedString()
      /home/runner/go/pkg/mod/k8s.io/apimachinery@v0.31.1/pkg/apis/meta/v1/unstructured/helpers.go:278 +0x44
  k8s.io/apimachinery/pkg/apis/meta/v1/unstructured.(*Unstructured).GetNamespace()
      /home/runner/go/pkg/mod/k8s.io/apimachinery@v0.31.1/pkg/apis/meta/v1/unstructured/unstructured.go:239 +0x94
  k8s.io/client-go/tools/cache.MetaNamespaceIndexFunc()
      /home/runner/go/pkg/mod/k8s.io/client-go@v0.31.1/tools/cache/index.go:90 +0x121
  k8s.io/client-go/tools/cache.(*storeIndex).updateSingleIndex()
      /home/runner/go/pkg/mod/k8s.io/client-go@v0.31.1/tools/cache/thread_safe_store.go:152 +0x101
  k8s.io/client-go/tools/cache.(*storeIndex).updateIndices()
      /home/runner/go/pkg/mod/k8s.io/client-go@v0.31.1/tools/cache/thread_safe_store.go:196 +0x237
  k8s.io/client-go/tools/cache.(*threadSafeMap).Delete()
      /home/runner/go/pkg/mod/k8s.io/client-go@v0.31.1/tools/cache/thread_safe_store.go:248 +0x117
  k8s.io/client-go/tools/cache.(*cache).Delete()
      /home/runner/go/pkg/mod/k8s.io/client-go@v0.31.1/tools/cache/store.go:194 +0xdb
  k8s.io/client-go/tools/cache.processDeltas()
      /home/runner/go/pkg/mod/k8s.io/client-go@v0.31.1/tools/cache/controller.go:566 +0x161
  k8s.io/client-go/tools/cache.(*sharedIndexInformer).HandleDeltas()
      /home/runner/go/pkg/mod/k8s.io/client-go@v0.31.1/tools/cache/shared_informer.go:643 +0x257
  k8s.io/client-go/tools/cache.(*sharedIndexInformer).HandleDeltas-fm()
      <autogenerated>:1 +0x54
  k8s.io/client-go/tools/cache.(*DeltaFIFO).Pop()
      /home/runner/go/pkg/mod/k8s.io/client-go@v0.31.1/tools/cache/delta_fifo.go:616 +0x9e8
  k8s.io/client-go/tools/cache.(*controller).processLoop()
      /home/runner/go/pkg/mod/k8s.io/client-go@v0.31.1/tools/cache/controller.go:195 +0x61
  k8s.io/client-go/tools/cache.(*controller).processLoop-fm()
      <autogenerated>:1 +0x33
  k8s.io/apimachinery/pkg/util/wait.BackoffUntil.func1()
      /home/runner/go/pkg/mod/k8s.io/apimachinery@v0.31.1/pkg/util/wait/backoff.go:226 +0x41
  k8s.io/apimachinery/pkg/util/wait.BackoffUntil()
      /home/runner/go/pkg/mod/k8s.io/apimachinery@v0.31.1/pkg/util/wait/backoff.go:227 +0xc4
  k8s.io/apimachinery/pkg/util/wait.JitterUntil()
      /home/runner/go/pkg/mod/k8s.io/apimachinery@v0.31.1/pkg/util/wait/backoff.go:204 +0x10a
  k8s.io/apimachinery/pkg/util/wait.Until()
      /home/runner/go/pkg/mod/k8s.io/apimachinery@v0.31.1/pkg/util/wait/backoff.go:161 +0x717
  k8s.io/client-go/tools/cache.(*controller).Run()
      /home/runner/go/pkg/mod/k8s.io/client-go@v0.31.1/tools/cache/controller.go:166 +0x6b4
  k8s.io/client-go/tools/cache.(*sharedIndexInformer).Run()
      /home/runner/go/pkg/mod/k8s.io/client-go@v0.31.1/tools/cache/shared_informer.go:508 +0x53a
  k8s.io/client-go/dynamic/dynamicinformer.(*dynamicSharedInformerFactory).Start.func1()
      /home/runner/go/pkg/mod/k8s.io/client-go@v0.31.1/dynamic/dynamicinformer/informer.go:108 +0xac

Previous write at 0x00c00166b620 by goroutine 1039:
  runtime.mapdelete_faststr()
      /opt/hostedtoolcache/go/1.23.6/x64/src/runtime/map_faststr.go:321 +0x0
  k8s.io/apimachinery/pkg/apis/meta/v1/unstructured.RemoveNestedField()
      /home/runner/go/pkg/mod/k8s.io/apimachinery@v0.31.1/pkg/apis/meta/v1/unstructured/helpers.go:274 +0x45e
  github.com/kubefleet-dev/kubefleet/pkg/controllers/clusterresourceplacement.generateRawContent()
      /home/runner/work/kubefleet/kubefleet/pkg/controllers/clusterresourceplacement/resource_selector.go:382 +0x3dd
  github.com/kubefleet-dev/kubefleet/pkg/controllers/clusterresourceplacement.generateManifest()
      /home/runner/work/kubefleet/kubefleet/pkg/controllers/clusterresourceplacement/resource_selector.go:429 +0x84
  github.com/kubefleet-dev/kubefleet/pkg/controllers/clusterresourceplacement.(*Reconciler).selectResources()
      /home/runner/work/kubefleet/kubefleet/pkg/controllers/clusterresourceplacement/resource_selector.go:62 +0xa84
  github.com/kubefleet-dev/kubefleet/pkg/controllers/clusterresourceplacement.(*Reconciler).ReconcileV1Alpha1()
      /home/runner/work/kubefleet/kubefleet/pkg/controllers/clusterresourceplacement/placement_controllerv1alpha1.go:116 +0xf8b
  github.com/kubefleet-dev/kubefleet/pkg/controllers/clusterresourceplacement.(*Reconciler).ReconcileV1Alpha1-fm()
      <autogenerated>:1 +0x64
  github.com/kubefleet-dev/kubefleet/pkg/utils/controller.(*controller).reconcileHandler()
      /home/runner/work/kubefleet/kubefleet/pkg/utils/controller/controller.go:269 +0x1d5
  github.com/kubefleet-dev/kubefleet/pkg/utils/controller.(*controller).processNextWorkItem()
      /home/runner/work/kubefleet/kubefleet/pkg/utils/controller/controller.go:256 +0x398
  github.com/kubefleet-dev/kubefleet/pkg/utils/controller.(*controller).Run.func2()
      /home/runner/work/kubefleet/kubefleet/pkg/utils/controller/controller.go:229 +0x132

Goroutine 366 (running) created at:
  k8s.io/client-go/dynamic/dynamicinformer.(*dynamicSharedInformerFactory).Start()
      /home/runner/go/pkg/mod/k8s.io/client-go@v0.31.1/dynamic/dynamicinformer/informer.go:106 +0x3b7
  github.com/kubefleet-dev/kubefleet/pkg/utils/informer.(*informerManagerImpl).Start()
      /home/runner/work/kubefleet/kubefleet/pkg/utils/informer/informermanager.go:192 +0xce
  github.com/kubefleet-dev/kubefleet/pkg/resourcewatcher.(*ChangeDetector).discoverResources()
      /home/runner/work/kubefleet/kubefleet/pkg/resourcewatcher/change_dector.go:195 +0x488
  github.com/kubefleet-dev/kubefleet/pkg/resourcewatcher.(*ChangeDetector).Start()
      /home/runner/work/kubefleet/kubefleet/pkg/resourcewatcher/change_dector.go:138 +0xfc4
  sigs.k8s.io/controller-runtime/pkg/manager.(*runnableGroup).reconcile.func1()
      /home/runner/go/pkg/mod/sigs.k8s.io/controller-runtime@v0.19.0/pkg/manager/runnable_group.go:226 +0x1c6
  sigs.k8s.io/controller-runtime/pkg/manager.(*runnableGroup).reconcile.gowrap1()
      /home/runner/go/pkg/mod/sigs.k8s.io/controller-runtime@v0.19.0/pkg/manager/runnable_group.go:229 +0x41

Goroutine 1039 (running) created at:
  github.com/kubefleet-dev/kubefleet/pkg/utils/controller.(*controller).Run()
      /home/runner/work/kubefleet/kubefleet/pkg/utils/controller/controller.go:224 +0x424
  github.com/kubefleet-dev/kubefleet/pkg/resourcewatcher.(*ChangeDetector).Start.func1()
      /home/runner/work/kubefleet/kubefleet/pkg/resourcewatcher/change_dector.go:154 +0xa1
  golang.org/x/sync/errgroup.(*Group).Go.func1()
      /home/runner/go/pkg/mod/golang.org/x/sync@v0.12.0/errgroup/errgroup.go:78 +0x91

As can be seen from the stack, the race happens when the v1alpha1 CRP controller reconciles some resource and updates while the shared informer reads it during resource deletion.

This race is introduced by PR #14 when calling selectResources (v1alpha1 CRP controller) or selectResourcesForPlacement (v1beta1/v1 CRP controller), we removed a deepCopy:
image
And in generateRawContent() function, we modify the object directly. These objects are pointers directly returned from the informer: https://github.com/kubefleet-dev/kubefleet/blob/main/pkg/controllers/clusterresourceplacement/resource_selector.go#L318C3-L332C4. So the controller and informer are essentially touching the same memory.

Why race only show up in the v1alpha1 integration test?

Both v1alpha1 controller and v1beta1 controller should have the same issue as they share the same generateRawContent() function. The flaky test is https://github.com/kubefleet-dev/kubefleet/blob/main/test/integration/cluster_placement_test.go#L274 where during the test, it dynamically creates an endpointSlice resource and make sure CRP picks it up. And there's a DeferCleanup() to delete the resource after the test. There's also an AfterEach() where we unjoin the memberclusters and delete the CRP. https://github.com/kubefleet-dev/kubefleet/blob/main/test/integration/cluster_placement_test.go#L111C2-L117C4. The race happens when the controller is trying to reconcile the CRP (not deleted yet) due to member cluster leaving, it re-selects the resources while the tests calls deletion on the endpointSlice obj, see test log:
0dad88b#diff-81bbeec7975586def83fe739a55b057049a1c8f852dab38aa16337c8797b53e2

I0501 17:49:47.714353   34565 v1alpha1/membercluster_controller.go:76] "Reconcile" memberCluster="/cluster-a-ksrkqdlb"
**I0501 17:49:47.714447   34565 v1alpha1/membercluster_controller.go:85] "the member cluster is in the process of being deleted" memberCluster="cluster-a-ksrkqdlb"**
I0501 17:49:47.715530   34565 resourcewatcher/event_handlers.go:155] "a memberCluster is updated" memberCluster="cluster-a-ksrkqdlb"
I0501 17:49:47.715616   34565 memberclusterplacement/membercluster_controller.go:62] "Start to reconcile a member cluster to enqueue placement events" memberCluster="cluster-a-ksrkqdlb"
I0501 17:49:47.716270   34565 memberclusterplacement/membercluster_controller.go:90] "enqueue a placement to reconcile" memberCluster="cluster-a-ksrkqdlb" placement="test-select-namespace"
I0501 17:49:47.716334   34565 memberclusterplacement/membercluster_controller.go:59] "MemberClusterPlacement reconciliation loop ends" memberCluster="cluster-a-ksrkqdlb" latency=0
I0501 17:49:47.716965   34565 clusterresourceplacement/placement_controllerv1alpha1.go:97] "Start to reconcile a ClusterResourcePlacement" placement="test-select-namespace"
I0501 17:49:47.718508   34565 clusterresourceplacement/cluster_selector.go:49] "we select all the available clusters in the fleet without a policy" placement="test-select-namespace" clusters=["cluster-b-9wfgldsr","cluster-a-ksrkqdlb"]
I0501 17:49:47.718597   34565 clusterresourceplacement/placement_controllerv1alpha1.go:113] "Successfully selected clusters" placement="test-select-namespace" number of clusters=2
I0501 17:49:47.718733   34565 clusterresourceplacement/resource_selector.go:240] "start to fetch the namespace resources by the selector" selector={"group":"","version":"v1","kind":"Namespace","labelSelector":{"matchLabels":{"fleet.azure.com/name":"test"}}}
I0501 17:49:47.718963   34565 clusterresourceplacement/resource_selector.go:293] "start to fetch all the resources inside a namespace" namespace="app"
I0501 17:49:47.721035   34565 resourcewatcher/event_handlers.go:155] "a memberCluster is updated" memberCluster="cluster-b-9wfgldsr"
I0501 17:49:47.721416   34565 memberclusterplacement/membercluster_controller.go:62] "Start to reconcile a member cluster to enqueue placement events" memberCluster="cluster-b-9wfgldsr"
I0501 17:49:47.722404   34565 memberclusterplacement/membercluster_controller.go:90] "enqueue a placement to reconcile" memberCluster="cluster-b-9wfgldsr" placement="test-select-namespace"
I0501 17:49:47.722826   34565 memberclusterplacement/membercluster_controller.go:59] "MemberClusterPlacement reconciliation loop ends" memberCluster="cluster-b-9wfgldsr" latency=1
I0501 17:49:47.722969   34565 clusterresourceplacement/resource_selector.go:61] "selected one resource " placement="test-select-namespace" resource={"version":"v1","kind":"Namespace","name":"app"}
I0501 17:49:47.723126   34565 clusterresourceplacement/resource_selector.go:61] "selected one resource " placement="test-select-namespace" resource={"version":"v1","kind":"ConfigMap","name":"test-configmap","namespace":"app"}
I0501 17:49:47.723319   34565 clusterresourceplacement/resource_selector.go:61] "selected one resource " placement="test-select-namespace" resource={"version":"v1","kind":"Secret","name":"test-secret","namespace":"app"}
I0501 17:49:47.723479   34565 clusterresourceplacement/resource_selector.go:61] "selected one resource " placement="test-select-namespace" resource={"version":"v1","kind":"Service","name":"test-nginx","namespace":"app"}
**I0501 17:49:47.723701   34565 clusterresourceplacement/resource_selector.go:61] "selected one resource " placement="test-select-namespace" resource={"group":"discovery.k8s.io","version":"v1","kind":"EndpointSlice","name":"test-nginx-export","namespace":"app"}**
I0501 17:49:47.723862   34565 clusterresourceplacement/resource_selector.go:61] "selected one resource " placement="test-select-namespace" resource={"group":"policy","version":"v1","kind":"PodDisruptionBudget","name":"zk-pdb","namespace":"app"}
I0501 17:49:47.724006   34565 clusterresourceplacement/resource_selector.go:61] "selected one resource " placement="test-select-namespace" resource={"group":"test.kubernetes-fleet.io","version":"v1alpha1","kind":"TestResource","name":"random-test-resource","namespace":"app"}
I0501 17:49:47.724134   34565 clusterresourceplacement/placement_controllerv1alpha1.go:128] "Successfully selected resources" placement="test-select-namespace" number of resources=7
I0501 17:49:47.723335   34565 v1alpha1/membercluster_controller.go:171] "successfully removed all the work finalizers in the cluster namespace" memberCluster="cluster-a-ksrkqdlb" number of work=1
==================
WARNING: DATA RACE
Read at 0x00c00183e8d0 by goroutine 344:
  runtime.mapaccess2_faststr()
...
==================
**•I0501 17:49:47.728117   34565 resourcewatcher/event_handlers.go:211] "A resource is deleted" obj="app/test-nginx-export" gvk="discovery.k8s.io/v1, Kind=EndpointSlice"**

In other tests, we either DeferCleanup a resource that is not being picked up the CRP or we wait for the CRP to be cleaned up completely before removing any additional resource. So other tests do not observe this race issue.

How to verify it actually fixes?

I did some local test. Before the fix, I ran the integration test and I observed the data race the 3rd time I ran. With the fix, I ran the integration test 20 times locally and didn't see it again.

Fixes #

I have:

  • Run make reviewable to ensure this PR is ready for review.

How has this code been tested

Special notes for your reviewer

@codecov
Copy link

codecov bot commented May 1, 2025

Codecov Report

All modified and coverable lines are covered by tests ✅

📢 Thoughts on this report? Let us know!

// generateRawContent strips all the unnecessary fields to prepare the objects for dispatch.
func generateRawContent(object *unstructured.Unstructured) ([]byte, error) {
// Make a deep copy of the object as we are modifying it.
object = object.DeepCopy()
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

who else is read/write it?

Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The informer. I put the story in the PR description.

Copy link
Contributor

@ryanzhang-oss ryanzhang-oss May 3, 2025

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

the go-client informer returns a deep copy of the object so there is no race condition between those.

Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The informer lister lists resources from the indexer, which is backed by the underlying threadsafestore. Reading the doc: https://pkg.go.dev/k8s.io/client-go/tools/cache#ThreadSafeStore, "TL;DR caveats: you must not modify anything returned by Get or List as it will break the indexing feature in addition to not being thread safe." It's required to keep the objects r/o. I don't see a deep copy as I dig the code path.

Signed-off-by: Wantong Jiang <wantjian@microsoft.com>
Copy link
Collaborator

@michaelawyu michaelawyu left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM ;)

@ryanzhang-oss ryanzhang-oss merged commit 2dd2170 into kubefleet-dev:main May 6, 2025
20 checks passed
audrastump pushed a commit to audrastump/kubefleet that referenced this pull request May 7, 2025
Signed-off-by: Wantong Jiang <wantjian@microsoft.com>
@jwtty jwtty deleted the fix-it-race branch August 18, 2025 17:49
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

3 participants