TODO: unclean shutdown of envtest e2e tests

[jiridanek]

Harmless, but annoying

2024-10-22T13:38:47+02:00	INFO	Stopping and waiting for webhooks
2024-10-22T13:38:47+02:00	INFO	controller-runtime.webhook	Shutting down webhook server with timeout of 1 minute
2024-10-22T13:38:47+02:00	INFO	Stopping and waiting for HTTP servers
2024-10-22T13:38:47+02:00	INFO	Wait completed, proceeding to shutdown the manager
2024-10-22T13:38:47+02:00	DEBUG	controller-runtime.certwatcher	certificate event	{"event": "REMOVE        \"/var/folders/f1/3m518k5d34l72v_9nqyjzqm80000gn/T/envtest-serving-certs-2153001584/tls.key\""}
2024-10-22T13:38:47+02:00	ERROR	controller-runtime.certwatcher	error re-watching file	{"error": "fsnotify: watcher already closed"}
sigs.k8s.io/controller-runtime/pkg/certwatcher.(*CertWatcher).handleEvent
	/Users/jdanek/go/pkg/mod/sigs.k8s.io/[email protected]/pkg/certwatcher/certwatcher.go:185
sigs.k8s.io/controller-runtime/pkg/certwatcher.(*CertWatcher).Watch
	/Users/jdanek/go/pkg/mod/sigs.k8s.io/[email protected]/pkg/certwatcher/certwatcher.go:133
2024-10-22T13:38:47+02:00	ERROR	controller-runtime.certwatcher	error re-reading certificate	{"error": "open /var/folders/f1/3m518k5d34l72v_9nqyjzqm80000gn/T/envtest-serving-certs-2153001584/tls.crt: no such file or directory"}
sigs.k8s.io/controller-runtime/pkg/certwatcher.(*CertWatcher).handleEvent
	/Users/jdanek/go/pkg/mod/sigs.k8s.io/[email protected]/pkg/certwatcher/certwatcher.go:190
sigs.k8s.io/controller-runtime/pkg/certwatcher.(*CertWatcher).Watch
	/Users/jdanek/go/pkg/mod/sigs.k8s.io/[email protected]/pkg/certwatcher/certwatcher.go:133


Ran 2 of 2 Specs in 10.003 seconds
SUCCESS! -- 2 Passed | 0 Failed | 0 Pending | 0 Skipped

This is something that people in general struggled with

• envtest - Failed to Watch error on every test run kubernetes-sigs/controller-runtime#904
• Kubebuilder v2 improvements + ideas gocardless/theatre#210

and we have a TODO comment for it

https://github.com/opendatahub-io/kubeflow/blob/0743e0e444f236b75d90eb2053ac0e79ead5950f/components/odh-notebook-controller/controllers/suite_test.go#L189-L195

The solution seems to be to create a nested context for

subctx, cancel := context.WithCancel(ctx)

...

	// Start the manager
	go func() {
		defer GinkgoRecover()
		err := mgr.Start(ctx)
		Expect(err).ToNot(HaveOccurred(), "Failed to run manager")
	}()

...

// when we're done testing
cancel()

but it needs to be checked.

[jiridanek]

^^ that nested context does not seem to be good enough, I still see unclean shutdowns

[jiridanek]

• Reduce error outputs in integration tests kubernetes-sigs/kueue#543

resolved by suppressing DEBUG logs

[jiridanek]

• tests: set GracefulShutdownTimeout to 0 to prevent context cancellation errors Kong/kubernetes-ingress-controller#5073

I like the suggestion of using

// Set the GracefulShutdownTimeout to 0 to prevent errors:
// failed waiting for all runnables to end within grace period of 30s: context deadline exceeded
// Ref: https://github.com/kubernetes-sigs/controller-runtime/blob/e59161ee/pkg/manager/internal.go#L543-L548
cfg.GracefulShutdownTimeout = lo.ToPtr(time.Duration(0))

[jiridanek]

The webhook timeout cannot be changed

idleConnsClosed := make(chan struct{})
go func() {
	<-ctx.Done()
	log.Info("Shutting down webhook server with timeout of 1 minute")

	ctx, cancel := context.WithTimeout(context.Background(), 1*time.Minute)
	defer cancel()
	if err := srv.Shutdown(ctx); err != nil {
		// Error from closing listeners, or context timeout
		log.Error(err, "error shutting down the HTTP server")
	}
	close(idleConnsClosed)
}()

• https://github.com/kubernetes-sigs/controller-runtime/blob/e3347b5405cdd0da5bff527af3d406117938ba6b/pkg/webhook/server.go#L249

[jiridanek]

One more advice, similarly to the previous, I found one other likely option in the struct docs

	BaseContext: func() context.Context {
		return ctx
	},

[jiridanek]

Waiting for

err = mgr.Start(ctx)

to return (after ctx is cancelled) and only then calling

err := envTest.Stop()

seems to be effective against

2024-11-17T20:19:57+01:00       ERROR   controller-runtime.certwatcher  error re-reading certificate    {"error": "open /var/folders/f1/3m518k5d34l72v_9nqyjzqm80000gn/T/envtest-serving-certs-737480808/tls.crt: no such file or directory"}

[jiridanek]

• RHOAIENG-15772: tests(odh-nbc): wait for controller manager to stop before stopping envtest #463
• RHOAIENG-15772: tests(odh-nbc): disable graceful shutdown period for envtest #464

The fixes were implemented in these two PRs, and the logs look somewhat quieter now

•STEP: Stopping the manager
2024-11-29T10:04:50Z	INFO	controller-runtime.webhook	Shutting down webhook server with timeout of 1 minute
STEP: Tearing down the test environment
W1129 10:04:50.311928   24977 reflector.go:462] pkg/mod/k8s.io/[email protected]/tools/cache/reflector.go:229: watch of *v1.NetworkPolicy ended with: an error on the server ("unable to decode an event from the watch stream: context canceled") has prevented the request from succeeding
W1129 10:04:50.311981   24977 reflector.go:462] pkg/mod/k8s.io/[email protected]/tools/cache/reflector.go:229: watch of *v1.RoleBinding ended with: an error on the server ("unable to decode an event from the watch stream: context canceled") has prevented the request from succeeding
2024-11-29T10:04:50Z	INFO	Shutdown signal received, waiting for all workers to finish	{"controller": "notebook", "controllerGroup": "kubeflow.org", "controllerKind": "Notebook"}
2024-11-29T10:04:50Z	INFO	Stopping and waiting for non leader election runnables
2024-11-29T10:04:50Z	INFO	Stopping and waiting for leader election runnables
2024-11-29T10:04:50Z	INFO	Stopping and waiting for caches
2024-11-29T10:04:50Z	INFO	Stopping and waiting for webhooks
2024-11-29T10:04:50Z	INFO	Stopping and waiting for HTTP servers
2024-11-29T10:04:50Z	INFO	Wait completed, proceeding to shutdown the manager

Ran 31 of 31 Specs in 68.277 seconds
SUCCESS! -- 31 Passed | 0 Failed | 0 Pending | 0 Skipped

Most importantly, the shutdown is almost immediate, within 1 second, instead of about 10 seconds it used to take before.

I think we are as much done as we can reasonably be here.