Data race during manager shutdown #2760

ahmetb · 2024-04-05T04:57:25Z

I'd like to report a data race caught by go test -race during my end-to-end test suite (which uses envtest, but does not use Ginkgo) which ended up failing my test.

The data race has occurred during the shutdown sequence. It seems during this time, one of the reconcilers was doing an API call, which ended up getting cancelled due to ctx cancellation I do as part of the tear down (to shut down envtest and the Runnables).

I am not at all sure if it is related to controller-runtime, as the concurrent reader/writer goroutine stacks are pointing to net/http:

Read routine https://github.com/golang/go/blob/go1.22.0/src/net/http/transport.go#L683
Write routine https://github.com/golang/go/blob/go1.22.0/src/net/http/transport.go#L656

But here it goes.

2024-04-02T18:22:08Z	INFO	Tests finished	{"duration": "2.049504249s", "exitCode": 0}
2024-04-02T18:22:08Z	INFO	Shutting down controllers
2024-04-02T18:22:08Z	INFO	Shutting down envtest
2024-04-02T18:22:08Z	INFO	Stopping and waiting for non leader election runnables
2024-04-02T18:22:08Z	INFO	Stopping and waiting for leader election runnables
2024-04-02T18:22:08Z	INFO	Shutdown signal received, waiting for all workers to finish	{"controller": "kubernetescontrolplane", "controllerGroup": "example.com", "controllerKind": "KubernetesControlPlane"}
2024-04-02T18:22:08Z	INFO	Shutdown signal received, waiting for all workers to finish	{"controller": "etcdcluster", "controllerGroup": "example.com", "controllerKind": "EtcdCluster"}
2024-04-02T18:22:08Z	INFO	All workers finished	{"controller": "kubernetescontrolplane", "controllerGroup": "example.com", "controllerKind": "KubernetesControlPlane"}
==================
WARNING: DATA RACE
Read at 0x00c0001361c0 by goroutine 269:
  net/http.rewindBody()
      /export/home/tester/.go/1.22.0/src/net/http/transport.go:683 +0xcb
  net/http.(*Transport).roundTrip()
      /export/home/tester/.go/1.22.0/src/net/http/transport.go:557 +0x6db
  net/http.(*Transport).RoundTrip()
      /export/home/tester/.go/1.22.0/src/net/http/roundtrip.go:17 +0x33
  k8s.io/client-go/transport.(*userAgentRoundTripper).RoundTrip()
      /export/home/tester/go-athens/pkg/mod/k8s.io/[email protected]/transport/round_trippers.go:168 +0x4f6
  net/http.send()
      /export/home/tester/.go/1.22.0/src/net/http/client.go:259 +0x9a6
  net/http.(*Client).send()
      /export/home/tester/.go/1.22.0/src/net/http/client.go:180 +0x14e
  net/http.(*Client).do()
      /export/home/tester/.go/1.22.0/src/net/http/client.go:724 +0x11c8
  net/http.(*Client).Do()
      /export/home/tester/.go/1.22.0/src/net/http/client.go:590 +0x6a6
  k8s.io/client-go/rest.(*Request).request()
      /export/home/tester/go-athens/pkg/mod/k8s.io/[email protected]/rest/request.go:1023 +0x3ac
  k8s.io/client-go/rest.(*Request).Do()
      /export/home/tester/go-athens/pkg/mod/k8s.io/[email protected]/rest/request.go:1063 +0x119
  sigs.k8s.io/controller-runtime/pkg/client.(*typedClient).PatchSubResource()
      /export/home/tester/go-athens/pkg/mod/sigs.k8s.io/[email protected]/pkg/client/typed_client.go:277 +0x924
  sigs.k8s.io/controller-runtime/pkg/client.(*subResourceClient).Patch()
      /export/home/tester/go-athens/pkg/mod/sigs.k8s.io/[email protected]/pkg/client/client.go:595 +0x484
  golnkd.in/k8s-compute-broker-controller/control-plane-manager/internal/controller.(*EtcdClusterReconciler).Reconcile()
      /export/content/data/multiproduct-post-commit/i001/workspace/k8s-compute-broker-controller_a60f2169246cc0c4f7d68a8124dca5ad12006477/control-plane-manager/internal/controller/etcdcluster_controller.go:81 +0x78d
  sigs.k8s.io/controller-runtime/pkg/internal/controller.(*Controller).Reconcile()
      /export/home/tester/go-athens/pkg/mod/sigs.k8s.io/[email protected]/pkg/internal/controller/controller.go:119 +0x1a1
  sigs.k8s.io/controller-runtime/pkg/internal/controller.(*Controller).reconcileHandler()
      /export/home/tester/go-athens/pkg/mod/sigs.k8s.io/[email protected]/pkg/internal/controller/controller.go:316 +0x59a
  sigs.k8s.io/controller-runtime/pkg/internal/controller.(*Controller).processNextWorkItem()
      /export/home/tester/go-athens/pkg/mod/sigs.k8s.io/[email protected]/pkg/internal/controller/controller.go:266 +0x399
  sigs.k8s.io/controller-runtime/pkg/internal/controller.(*Controller).Start.func2.2()
      /export/home/tester/go-athens/pkg/mod/sigs.k8s.io/[email protected]/pkg/internal/controller/controller.go:227 +0xb2

Previous write at 0x00c0001361c0 by goroutine 304:
  net/http.(*readTrackingBody).Read()
      /export/home/tester/.go/1.22.0/src/net/http/transport.go:656 +0x44
  golang.org/x/net/http2.(*clientStream).writeRequestBody()
      /export/home/tester/go-athens/pkg/mod/golang.org/x/[email protected]/http2/transport.go:1732 +0x5d9
  golang.org/x/net/http2.(*clientStream).writeRequest()
      /export/home/tester/go-athens/pkg/mod/golang.org/x/[email protected]/http2/transport.go:1440 +0xf32
  golang.org/x/net/http2.(*clientStream).doRequest()
      /export/home/tester/go-athens/pkg/mod/golang.org/x/[email protected]/http2/transport.go:1326 +0x33
  golang.org/x/net/http2.(*ClientConn).RoundTrip.gowrap1()
      /export/home/tester/go-athens/pkg/mod/golang.org/x/[email protected]/http2/transport.go:1232 +0x44

Goroutine 269 (running) created at:
  sigs.k8s.io/controller-runtime/pkg/internal/controller.(*Controller).Start.func2()
      /export/home/tester/go-athens/pkg/mod/sigs.k8s.io/[email protected]/pkg/internal/controller/controller.go:223 +0x80b
  sigs.k8s.io/controller-runtime/pkg/internal/controller.(*Controller).Start()
      /export/home/tester/go-athens/pkg/mod/sigs.k8s.io/[email protected]/pkg/internal/controller/controller.go:234 +0x2b9
  sigs.k8s.io/controller-runtime/pkg/manager.(*runnableGroup).reconcile.func1()
      /export/home/tester/go-athens/pkg/mod/sigs.k8s.io/[email protected]/pkg/manager/runnable_group.go:223 +0x1c6
  sigs.k8s.io/controller-runtime/pkg/manager.(*runnableGroup).reconcile.gowrap1()
      /export/home/tester/go-athens/pkg/mod/sigs.k8s.io/[email protected]/pkg/manager/runnable_group.go:226 +0x41

Goroutine 304 (running) created at:
  golang.org/x/net/http2.(*ClientConn).RoundTrip()
      /export/home/tester/go-athens/pkg/mod/golang.org/x/[email protected]/http2/transport.go:1232 +0x7d7
  golang.org/x/net/http2.(*Transport).RoundTripOpt()
      /export/home/tester/go-athens/pkg/mod/golang.org/x/[email protected]/http2/transport.go:564 +0x644
  golang.org/x/net/http2.(*Transport).RoundTrip()
      /export/home/tester/go-athens/pkg/mod/golang.org/x/[email protected]/http2/transport.go:513 +0x37
  golang.org/x/net/http2.noDialH2RoundTripper.RoundTrip()
      /export/home/tester/go-athens/pkg/mod/golang.org/x/[email protected]/http2/transport.go:3136 +0x26
  net/http.(*Transport).roundTrip()
      /export/home/tester/.go/1.22.0/src/net/http/transport.go:553 +0x641
  net/http.(*Transport).RoundTrip()
      /export/home/tester/.go/1.22.0/src/net/http/roundtrip.go:17 +0x33
  k8s.io/client-go/transport.(*userAgentRoundTripper).RoundTrip()
      /export/home/tester/go-athens/pkg/mod/k8s.io/[email protected]/transport/round_trippers.go:168 +0x4f6
  net/http.send()
      /export/home/tester/.go/1.22.0/src/net/http/client.go:259 +0x9a6
  net/http.(*Client).send()
      /export/home/tester/.go/1.22.0/src/net/http/client.go:180 +0x14e
  net/http.(*Client).do()
      /export/home/tester/.go/1.22.0/src/net/http/client.go:724 +0x11c8
  net/http.(*Client).Do()
      /export/home/tester/.go/1.22.0/src/net/http/client.go:590 +0x6a6
  k8s.io/client-go/rest.(*Request).request()
      /export/home/tester/go-athens/pkg/mod/k8s.io/[email protected]/rest/request.go:1023 +0x3ac
  k8s.io/client-go/rest.(*Request).Do()
      /export/home/tester/go-athens/pkg/mod/k8s.io/[email protected]/rest/request.go:1063 +0x119
  sigs.k8s.io/controller-runtime/pkg/client.(*typedClient).PatchSubResource()
      /export/home/tester/go-athens/pkg/mod/sigs.k8s.io/[email protected]/pkg/client/typed_client.go:277 +0x924
  sigs.k8s.io/controller-runtime/pkg/client.(*subResourceClient).Patch()
      /export/home/tester/go-athens/pkg/mod/sigs.k8s.io/[email protected]/pkg/client/client.go:595 +0x484
  golnkd.in/k8s-compute-broker-controller/control-plane-manager/internal/controller.(*EtcdClusterReconciler).Reconcile()
      /export/content/data/multiproduct-post-commit/i001/workspace/k8s-compute-broker-controller_a60f2169246cc0c4f7d68a8124dca5ad12006477/control-plane-manager/internal/controller/etcdcluster_controller.go:81 +0x78d
  sigs.k8s.io/controller-runtime/pkg/internal/controller.(*Controller).Reconcile()
      /export/home/tester/go-athens/pkg/mod/sigs.k8s.io/[email protected]/pkg/internal/controller/controller.go:119 +0x1a1
  sigs.k8s.io/controller-runtime/pkg/internal/controller.(*Controller).reconcileHandler()
      /export/home/tester/go-athens/pkg/mod/sigs.k8s.io/[email protected]/pkg/internal/controller/controller.go:316 +0x59a
  sigs.k8s.io/controller-runtime/pkg/internal/controller.(*Controller).processNextWorkItem()
      /export/home/tester/go-athens/pkg/mod/sigs.k8s.io/[email protected]/pkg/internal/controller/controller.go:266 +0x399
  sigs.k8s.io/controller-runtime/pkg/internal/controller.(*Controller).Start.func2.2()
      /export/home/tester/go-athens/pkg/mod/sigs.k8s.io/[email protected]/pkg/internal/controller/controller.go:227 +0xb2
==================
2024-04-02T18:22:08Z	DEBUG	Status updated	{"controller": "etcdcluster", "controllerGroup": "example.com", "controllerKind": "EtcdCluster", "EtcdCluster": {"name":"test"}, "namespace": "", "name": "test", "reconcileID": "c175233f-a6c2-46c4-82af-49e68f48bdbb"}
2024-04-02T18:22:08Z	ERROR	Reconciler error	{"controller": "etcdcluster", "controllerGroup": "example.com", "controllerKind": "EtcdCluster", "EtcdCluster": {"name":"test"}, "namespace": "", "name": "test", "reconcileID": "c175233f-a6c2-46c4-82af-49e68f48bdbb", "error": "failed to patch EtcdCluster status: Patch \"https://127.0.0.1:40187/apis/example.com/v1alpha1/etcdclusters/test/status\": context canceled", "errorCauses": [{"error": "failed to patch EtcdCluster status: Patch \"https://127.0.0.1:40187/apis/example.com/v1alpha1/etcdclusters/test/status\": context canceled"}]}
2024-04-02T18:22:08Z	INFO	All workers finished	{"controller": "etcdcluster", "controllerGroup": "example.com", "controllerKind": "EtcdCluster"}
2024-04-02T18:22:08Z	INFO	Stopping and waiting for caches
2024-04-02T18:22:08Z	INFO	Stopping and waiting for webhooks
2024-04-02T18:22:08Z	INFO	Stopping and waiting for HTTP servers
2024-04-02T18:22:08Z	INFO	controller-runtime.metrics	Shutting down metrics server with timeout of 1 minute
2024-04-02T18:22:08Z	INFO	Wait completed, proceeding to shutdown the manager
2024-04-02T18:22:08Z	INFO	Controllers stopped
2024-04-02T18:22:09Z	INFO	Teardown finished	{"duration": "1.107332537s"}
Found 1 data race(s)

The text was updated successfully, but these errors were encountered:

vincepri · 2024-04-08T18:17:14Z

Maybe related to #2757

Are you able to update to latest v0.17 commit?

vincepri · 2024-04-08T18:20:27Z

Or https://github.com/kubernetes-sigs/controller-runtime/releases/tag/v0.17.3

k8s-triage-robot · 2024-07-07T19:14:43Z

The Kubernetes project currently lacks enough contributors to adequately respond to all issues.

This bot triages un-triaged issues according to the following rules:

After 90d of inactivity, lifecycle/stale is applied
After 30d of inactivity since lifecycle/stale was applied, lifecycle/rotten is applied
After 30d of inactivity since lifecycle/rotten was applied, the issue is closed

You can:

Mark this issue as fresh with /remove-lifecycle stale
Close this issue with /close
Offer to help out with Issue Triage

Please send feedback to sig-contributor-experience at kubernetes/community.

/lifecycle stale

sbueringer · 2024-07-15T06:24:37Z

@ahmetb ^^

k8s-triage-robot · 2024-08-14T06:39:53Z

The Kubernetes project currently lacks enough active contributors to adequately respond to all issues.

This bot triages un-triaged issues according to the following rules:

After 90d of inactivity, lifecycle/stale is applied
After 30d of inactivity since lifecycle/stale was applied, lifecycle/rotten is applied
After 30d of inactivity since lifecycle/rotten was applied, the issue is closed

You can:

Mark this issue as fresh with /remove-lifecycle rotten
Close this issue with /close
Offer to help out with Issue Triage

Please send feedback to sig-contributor-experience at kubernetes/community.

/lifecycle rotten

k8s-triage-robot · 2024-09-13T06:49:32Z

The Kubernetes project currently lacks enough active contributors to adequately respond to all issues and PRs.

This bot triages issues according to the following rules:

After 90d of inactivity, lifecycle/stale is applied
After 30d of inactivity since lifecycle/stale was applied, lifecycle/rotten is applied
After 30d of inactivity since lifecycle/rotten was applied, the issue is closed

You can:

Reopen this issue with /reopen
Mark this issue as fresh with /remove-lifecycle rotten
Offer to help out with Issue Triage

Please send feedback to sig-contributor-experience at kubernetes/community.

/close not-planned

k8s-ci-robot · 2024-09-13T06:49:36Z

@k8s-triage-robot: Closing this issue, marking it as "Not Planned".

In response to this:

The Kubernetes project currently lacks enough active contributors to adequately respond to all issues and PRs.

This bot triages issues according to the following rules:

After 90d of inactivity, lifecycle/stale is applied

After 30d of inactivity since lifecycle/stale was applied, lifecycle/rotten is applied

After 30d of inactivity since lifecycle/rotten was applied, the issue is closed

You can:

Reopen this issue with /reopen

Mark this issue as fresh with /remove-lifecycle rotten

Offer to help out with Issue Triage

Please send feedback to sig-contributor-experience at kubernetes/community.

/close not-planned

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-sigs/prow repository.

k8s-ci-robot added the lifecycle/stale Denotes an issue or PR has remained open with no activity and has become stale. label Jul 7, 2024

k8s-ci-robot added lifecycle/rotten Denotes an issue or PR that has aged beyond stale and will be auto-closed. and removed lifecycle/stale Denotes an issue or PR has remained open with no activity and has become stale. labels Aug 14, 2024

k8s-ci-robot closed this as not planned Won't fix, can't repro, duplicate, stale Sep 13, 2024

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Data race during manager shutdown #2760

Data race during manager shutdown #2760

ahmetb commented Apr 5, 2024

vincepri commented Apr 8, 2024

vincepri commented Apr 8, 2024

k8s-triage-robot commented Jul 7, 2024

sbueringer commented Jul 15, 2024

k8s-triage-robot commented Aug 14, 2024

k8s-triage-robot commented Sep 13, 2024

k8s-ci-robot commented Sep 13, 2024

Data race during manager shutdown #2760

Data race during manager shutdown #2760

Comments

ahmetb commented Apr 5, 2024

vincepri commented Apr 8, 2024

vincepri commented Apr 8, 2024

k8s-triage-robot commented Jul 7, 2024

sbueringer commented Jul 15, 2024

k8s-triage-robot commented Aug 14, 2024

k8s-triage-robot commented Sep 13, 2024

k8s-ci-robot commented Sep 13, 2024