Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

envtest - Failed to Watch error on every test run #904

Closed
zscholl opened this issue Apr 16, 2020 · 6 comments
Closed

envtest - Failed to Watch error on every test run #904

zscholl opened this issue Apr 16, 2020 · 6 comments
Labels
lifecycle/rotten Denotes an issue or PR that has aged beyond stale and will be auto-closed.

Comments

@zscholl
Copy link

zscholl commented Apr 16, 2020 •
edited
Loading

I'm using the envtest setup with ginkgo to test an operator.

My test is setup like so:

var _ = BeforeSuite(func(done Done) {
	var err error
	By("bootstrapping test environment")

	ctx = context.Background()

	err = apis.AddToScheme(scheme.Scheme)
	Expect(err).ToNot(HaveOccurred())

	testEnv = &envtest.Environment{
		CRDDirectoryPaths: []string{
			path.Join(getFileDir(), "../../../deploy/crds"),
		},
		AttachControlPlaneOutput: true,
	}

	cfg, err = testEnv.Start()
	time.Sleep(time.Second * 5)
	Expect(err).ToNot(HaveOccurred())
	Expect(cfg).ToNot(BeNil())

	k8sManager, err = ctrl.NewManager(cfg, ctrl.Options{Scheme: scheme.Scheme})
	Expect(err).ToNot(HaveOccurred())

	config, _ := appConfig.Load()

	err = Add(k8sManager, &config)
	Expect(err).ToNot(HaveOccurred())

	go func() {
		defer GinkgoRecover()
		err = k8sManager.Start(ctrl.SetupSignalHandler())
		Expect(err).ToNot(HaveOccurred())
	}()

	k8sClient, err = client.New(cfg, client.Options{Scheme: scheme.Scheme})
	Expect(err).ToNot(HaveOccurred())
	Expect(k8sClient).ToNot(BeNil())

	close(done)
}, 60)

My tests pass when I create my custom CR and check that operations were performed as expected, however, I always get this error message:

•E0416 09:59:20.909075   57189 reflector.go:280] pkg/mod/k8s.io/[email protected]/tools/cache/reflector.go:96: Failed to watch *v1alpha1.CrdType: Get "http://127.0.0.1:55567/apis/mycrd.example.com/v1alpha1/crdType?allowWatchBookmarks=true&resourceVersion=62&timeoutSeconds=582&watch=true": dial tcp 127.0.0.1:55567: connect: connection refused

It looks like this is happening after the etcd and kubernetes API server have been shut down so I'm not sure what the problem is.

Here's the full control plane output:

2020-04-16 09:59:06.125333 I | etcdmain: etcd Version: 3.3.11
2020-04-16 09:59:06.125494 I | etcdmain: Git SHA: 2cf9e51d2
2020-04-16 09:59:06.125499 I | etcdmain: Go Version: go1.10.7
2020-04-16 09:59:06.125502 I | etcdmain: Go OS/Arch: darwin/amd64
2020-04-16 09:59:06.125506 I | etcdmain: setting maximum number of CPUs to 12, total number of available CPUs is 12
2020-04-16 09:59:06.125519 N | etcdmain: failed to detect default host (default host not supported on darwin_amd64)
2020-04-16 09:59:06.126146 I | embed: listening for peers on http://localhost:0
2020-04-16 09:59:06.126220 I | embed: listening for client requests on 127.0.0.1:55562
2020-04-16 09:59:06.127908 I | etcdserver: name = default
2020-04-16 09:59:06.127918 I | etcdserver: data dir = /var/folders/g8/lqxnjm554fz5r3f5j6328tw40000gp/T/k8s_test_framework_599252336
2020-04-16 09:59:06.127925 I | etcdserver: member dir = /var/folders/g8/lqxnjm554fz5r3f5j6328tw40000gp/T/k8s_test_framework_599252336/member
2020-04-16 09:59:06.127928 I | etcdserver: heartbeat = 100ms
2020-04-16 09:59:06.127933 I | etcdserver: election = 1000ms
2020-04-16 09:59:06.127935 I | etcdserver: snapshot count = 100000
2020-04-16 09:59:06.127945 I | etcdserver: advertise client URLs = http://127.0.0.1:55562
2020-04-16 09:59:06.127948 I | etcdserver: initial advertise peer URLs = http://localhost:2380
2020-04-16 09:59:06.127954 I | etcdserver: initial cluster = default=http://localhost:2380
2020-04-16 09:59:06.260523 I | etcdserver: starting member 8e9e05c52164694d in cluster cdf818194e3a8c32
2020-04-16 09:59:06.260551 I | raft: 8e9e05c52164694d became follower at term 0
2020-04-16 09:59:06.260559 I | raft: newRaft 8e9e05c52164694d [peers: [], term: 0, commit: 0, applied: 0, lastindex: 0, lastterm: 0]
2020-04-16 09:59:06.260562 I | raft: 8e9e05c52164694d became follower at term 1
2020-04-16 09:59:06.262233 W | auth: simple token is not cryptographically signed
2020-04-16 09:59:06.262904 I | etcdserver: starting server... [version: 3.3.11, cluster version: to_be_decided]
2020-04-16 09:59:06.262949 I | etcdserver: 8e9e05c52164694d as single-node; fast-forwarding 9 ticks (election ticks 10)
2020-04-16 09:59:06.262970 E | etcdserver: cannot monitor file descriptor usage (cannot get FDUsage on darwin)
2020-04-16 09:59:06.263240 I | etcdserver/membership: added member 8e9e05c52164694d [http://localhost:2380] to cluster cdf818194e3a8c32
2020-04-16 09:59:07.061824 I | raft: 8e9e05c52164694d is starting a new election at term 1
2020-04-16 09:59:07.061869 I | raft: 8e9e05c52164694d became candidate at term 2
2020-04-16 09:59:07.061889 I | raft: 8e9e05c52164694d received MsgVoteResp from 8e9e05c52164694d at term 2
2020-04-16 09:59:07.061903 I | raft: 8e9e05c52164694d became leader at term 2
2020-04-16 09:59:07.061910 I | raft: raft.node: 8e9e05c52164694d elected leader 8e9e05c52164694d at term 2
2020-04-16 09:59:07.061983 I | etcdserver: setting up the initial cluster version to 3.3
2020-04-16 09:59:07.081242 N | etcdserver/membership: set the initial cluster version to 3.3
2020-04-16 09:59:07.081263 I | embed: ready to serve client requests
2020-04-16 09:59:07.081329 I | etcdserver: published {Name:default ClientURLs:[http://127.0.0.1:55562]} to cluster cdf818194e3a8c32
2020-04-16 09:59:07.081342 I | etcdserver/api: enabled capabilities for version 3.3
2020-04-16 09:59:07.081815 N | embed: serving insecure client requests on 127.0.0.1:55562, this is strongly discouraged!
Flag --insecure-port has been deprecated, This flag will be removed in a future version.
Flag --insecure-bind-address has been deprecated, This flag will be removed in a future version.
Flag --admission-control has been deprecated, Use --enable-admission-plugins or --disable-admission-plugins instead. Will be removed in a future version.
I0416 09:59:07.403158   57252 serving.go:311] Generated self-signed cert (/var/folders/g8/lqxnjm554fz5r3f5j6328tw40000gp/T/k8s_test_framework_922261519/apiserver.crt, /var/folders/g8/lqxnjm554fz5r3f5j6328tw40000gp/T/k8s_test_framework_922261519/apiserver.key)
I0416 09:59:07.403249   57252 server.go:557] external host was not specified, using 127.0.0.1
W0416 09:59:07.403259   57252 authentication.go:415] AnonymousAuth is not allowed with the AlwaysAllow authorizer. Resetting AnonymousAuth to false. You should use a different authorizer
I0416 09:59:07.403440   57252 server.go:146] Version: v1.13.1
W0416 09:59:08.039783   57252 admission.go:61] AlwaysAdmit admission controller is deprecated. Please remove this controller from your configuration files and scripts.
I0416 09:59:08.039813   57252 plugins.go:158] Loaded 1 mutating admission controller(s) successfully in the following order: AlwaysAdmit.
I0416 09:59:08.039817   57252 plugins.go:161] Loaded 1 validating admission controller(s) successfully in the following order: AlwaysAdmit.
W0416 09:59:08.040298   57252 admission.go:61] AlwaysAdmit admission controller is deprecated. Please remove this controller from your configuration files and scripts.
I0416 09:59:08.040818   57252 plugins.go:158] Loaded 1 mutating admission controller(s) successfully in the following order: AlwaysAdmit.
I0416 09:59:08.040827   57252 plugins.go:161] Loaded 1 validating admission controller(s) successfully in the following order: AlwaysAdmit.
I0416 09:59:08.057258   57252 master.go:228] Using reconciler: lease
W0416 09:59:08.232114   57252 genericapiserver.go:334] Skipping API batch/v2alpha1 because it has no resources.
W0416 09:59:08.323035   57252 genericapiserver.go:334] Skipping API rbac.authorization.k8s.io/v1alpha1 because it has no resources.
W0416 09:59:08.331616   57252 genericapiserver.go:334] Skipping API scheduling.k8s.io/v1alpha1 because it has no resources.
W0416 09:59:08.341533   57252 genericapiserver.go:334] Skipping API storage.k8s.io/v1alpha1 because it has no resources.
W0416 09:59:08.394981   57252 genericapiserver.go:334] Skipping API admissionregistration.k8s.io/v1alpha1 because it has no resources.
[restful] 2020/04/16 09:59:08 log.go:33: [restful/swagger] listing is available at https://127.0.0.1:55568/swaggerapi
[restful] 2020/04/16 09:59:08 log.go:33: [restful/swagger] https://127.0.0.1:55568/swaggerui/ is mapped to folder /swagger-ui/
[restful] 2020/04/16 09:59:09 log.go:33: [restful/swagger] listing is available at https://127.0.0.1:55568/swaggerapi
[restful] 2020/04/16 09:59:09 log.go:33: [restful/swagger] https://127.0.0.1:55568/swaggerui/ is mapped to folder /swagger-ui/
W0416 09:59:09.711907   57252 admission.go:61] AlwaysAdmit admission controller is deprecated. Please remove this controller from your configuration files and scripts.
I0416 09:59:09.711924   57252 plugins.go:158] Loaded 1 mutating admission controller(s) successfully in the following order: AlwaysAdmit.
I0416 09:59:09.711928   57252 plugins.go:161] Loaded 1 validating admission controller(s) successfully in the following order: AlwaysAdmit.
I0416 09:59:12.642385   57252 deprecated_insecure_serving.go:51] Serving insecurely on 127.0.0.1:55567
I0416 09:59:12.644332   57252 secure_serving.go:116] Serving securely on [::]:55568
I0416 09:59:12.644447   57252 autoregister_controller.go:136] Starting autoregister controller
I0416 09:59:12.644462   57252 cache.go:32] Waiting for caches to sync for autoregister controller
I0416 09:59:12.644495   57252 apiservice_controller.go:90] Starting APIServiceRegistrationController
I0416 09:59:12.644503   57252 crdregistration_controller.go:112] Starting crd-autoregister controller
I0416 09:59:12.644518   57252 cache.go:32] Waiting for caches to sync for APIServiceRegistrationController controller
I0416 09:59:12.644522   57252 controller_utils.go:1027] Waiting for caches to sync for crd-autoregister controller
I0416 09:59:12.644543   57252 controller.go:84] Starting OpenAPI AggregationController
I0416 09:59:12.644559   57252 crd_finalizer.go:242] Starting CRDFinalizer
I0416 09:59:12.644576   57252 customresource_discovery_controller.go:203] Starting DiscoveryController
I0416 09:59:12.644590   57252 naming_controller.go:284] Starting NamingConditionController
I0416 09:59:12.644602   57252 establishing_controller.go:73] Starting EstablishingController
proto: no coders for int
proto: no encoder for ValueSize int [GetProperties]
I0416 09:59:12.652828   57252 available_controller.go:283] Starting AvailableConditionController
I0416 09:59:12.652991   57252 cache.go:32] Waiting for caches to sync for AvailableConditionController controller
W0416 09:59:12.734735   57252 lease.go:222] Resetting endpoints for master service "kubernetes" to [127.0.0.1]
E0416 09:59:12.735390   57252 controller.go:155] Unable to perform initial Kubernetes service initialization: Endpoints "kubernetes" is invalid: subsets[0].addresses[0].ip: Invalid value: "127.0.0.1": may not be in the loopback range (127.0.0.0/8)
I0416 09:59:12.748602   57252 cache.go:39] Caches are synced for autoregister controller
I0416 09:59:12.748608   57252 cache.go:39] Caches are synced for APIServiceRegistrationController controller
I0416 09:59:12.748607   57252 controller_utils.go:1034] Caches are synced for crd-autoregister controller
I0416 09:59:12.756766   57252 cache.go:39] Caches are synced for AvailableConditionController controller
W0416 09:59:12.804700   57252 lease.go:222] Resetting endpoints for master service "kubernetes" to [127.0.0.1]
E0416 09:59:12.805829   57252 controller.go:204] unable to sync kubernetes service: Endpoints "kubernetes" is invalid: subsets[0].addresses[0].ip: Invalid value: "127.0.0.1": may not be in the loopback range (127.0.0.0/8)
I0416 09:59:13.650221   57252 storage_scheduling.go:91] created PriorityClass system-node-critical with value 2000001000
I0416 09:59:13.672067   57252 storage_scheduling.go:91] created PriorityClass system-cluster-critical with value 2000000000
I0416 09:59:13.672081   57252 storage_scheduling.go:100] all system priority classes are created successfully or already exist.
•E0416 09:59:20.909075   57189 reflector.go:280] pkg/mod/k8s.io/[email protected]/tools/cache/reflector.go:96: Failed to watch *v1alpha1.crdType: Get "http://127.0.0.1:55567/apis/mycrd.example.com/v1alpha1/crdType?allowWatchBookmarks=true&resourceVersion=62&timeoutSeconds=582&watch=true": dial tcp 127.0.0.1:55567: connect: connection refused

Using sigs.k8s.io/controller-runtime v0.4.0
@fejta-bot
Copy link

Issues go stale after 90d of inactivity.
Mark the issue as fresh with /remove-lifecycle stale.
Stale issues rot after an additional 30d of inactivity and eventually close.

If this issue is safe to close now please do so with /close.

Send feedback to sig-testing, kubernetes/test-infra and/or fejta.
/lifecycle stale

@k8s-ci-robot k8s-ci-robot added the lifecycle/stale Denotes an issue or PR has remained open with no activity and has become stale. label Jul 15, 2020
@dyson
Copy link

dyson commented Jul 17, 2020 •
edited
Loading

I believe the issue here is that the k8sManager never receives on the channel from ctrl.SetupSignalHandler() to shutdown and like you mention the server and etcd are shutdown from underneath it. The manager needs to be shutdown cleanly first.

dyson added a commit to gocardless/theatre that referenced this issue Jul 17, 2020
@dyson
Unit and integration test improvements
155159a 
Don't set verbose in 'make test' as envTest is really noisey in the
integration tests.

Also fixes an issue with the manager not being shut down cleanly at the
end of integration tests which would result in error log output:
kubernetes-sigs/controller-runtime#904
dyson added a commit to gocardless/theatre that referenced this issue Jul 17, 2020
@dyson
Improve unit and integration tests
192b4ba 
Don't set verbose in 'make test' as envTest is really noisey in the
integration tests.

Also fixes an issue with the manager not being shut down cleanly at the
end of integration tests which would result in error log output:
kubernetes-sigs/controller-runtime#904
@rnaveiras rnaveiras mentioned this issue Jul 29, 2020
Open
@fejta-bot
Copy link

Stale issues rot after 30d of inactivity.
Mark the issue as fresh with /remove-lifecycle rotten.
Rotten issues close after an additional 30d of inactivity.

If this issue is safe to close now please do so with /close.

Send feedback to sig-testing, kubernetes/test-infra and/or fejta.
/lifecycle rotten

@k8s-ci-robot 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 16, 2020
@fejta-bot
Copy link

Rotten issues close after 30d of inactivity.
Reopen the issue with /reopen.
Mark the issue as fresh with /remove-lifecycle rotten.

Send feedback to sig-testing, kubernetes/test-infra and/or fejta.
/close

@k8s-ci-robot
Copy link
Contributor

@fejta-bot: Closing this issue.

In response to this:

Rotten issues close after 30d of inactivity.
Reopen the issue with /reopen.
Mark the issue as fresh with /remove-lifecycle rotten.

Send feedback to sig-testing, kubernetes/test-infra and/or fejta.
/close

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.

@hardikdr
Copy link
Member

Was there any resolution for this issue?

@oriyarde oriyarde mentioned this issue Mar 7, 2022
Merged
@jiridanek jiridanek mentioned this issue Oct 22, 2024
Closed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
lifecycle/rotten Denotes an issue or PR that has aged beyond stale and will be auto-closed.
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
5 participants
@dyson @zscholl @hardikdr @k8s-ci-robot @fejta-bot