Repository: kubernetes-sigs/controller-runtime

Issue:
Define own WatchErrorHandler for toolscache.Reflector
`client-go` sets a default handler for watching errors `func DefaultWatchErrorHandler(r *Reflector, err error)`, see https://github.com/kubernetes/client-go/blob/23900f492969db045e8a36396852381fd189569b/tools/cache/reflector.go#L154. Right now, if it is included in the `controller-runtime` it will use its logger `klog` by default. This leads to inconsistent log output by default. Therefore, I propose that the `controller-runtime` should overwrite this method, i.e., use its own handler.

This handler could look something like this:

```go
func WatchErrorHandler(r *toolscache.Reflector, err error) {
	log := ctrl.Log.WithValues("name", r.Name(), "description", r.TypeDescription())
	switch {
	case apierrors.IsResourceExpired(err) || apierrors.IsGone(err):
		// Don't set LastSyncResourceVersionUnavailable - LIST call with ResourceVersion=RV already
		// has a semantic that it returns data at least as fresh as provided RV.
		// So first try to LIST with setting RV to resource version of last observed object.
		log.Error(err, "watch closed")
	case err == io.EOF:
		// watch closed normally
	case err == io.ErrUnexpectedEOF:
		log.Error(err, "watch closed with unexpected EOF")
	default:
		utilruntime.HandleError(fmt.Errorf("%s: Failed to watch %v: %v", r.Name(), r.TypeDescription(), err))
	}
}
```
As you can see, we would use a logger with two fields of the reflector now. I exposed these fields recently (see https://github.com/kubernetes/client-go/commit/ce42c297f4b4444f810bedb6fcf10423eebafa5f), so the `controller-runtime` can essentially redefine the default handler of `client-go`, as the default handler also logs these fields.

**I would like to implement this, if it gets your approval.**

Discussion:
@sbueringer: If I see correctly this part is currently refactored upstream: https://github.com/kubernetes/kubernetes/pull/127709

EDIT: Sorry linked the wrong PR, this is the right one: https://github.com/kubernetes/kubernetes/pull/126387/files#diff-9ccdf713e010f73dbebd01e936cb0077fc63e4f5ab941d865ded42da219d84ec

(cc @alvaroaleman)@troy0820: I see your point.  When implementing this [PR](https://github.com/kubernetes-sigs/controller-runtime/pull/2494/files) to be able to override the WatchErrorHandler it didn't occur to me that the klog would get in the way of the controller-runtime's logging, etc.  Implementing this seems doable and allowing this to be set to the default we provide or the overridden function in the cache options.  

However, we run into the problem of trying to stay within parity with upstream not using the upstream default handler.  Maintaining that seems like a lot of drift but still doable. @alexanderstephan: Thanks, so my take-away is that this seems reasonable to implement.

@sbueringer So, I should wait until the refactoring is over to avoid merge conflicts? Or, maybe start and use the branch of the PR as basis for now?@sbueringer: I could be absolutely misunderstanding this, but I was wondering if the problem still exists if we use the error handler that takes a context (and the logger out of the context).

I would recommend waiting until the PR in upstream is merged and we bumped to a Kubernetes version that has the change. Then we can check if we can simply switch to the error handler that takes a context.

(if they merge the upstream PR we'll have the change in CR directly after the next Kubernetes alpha/beta release which shouldn't take long)@alexanderstephan: Yes, okay seems good, let's wait then. Using the context here would also make sense to me. Also, we don't have this drifting problem that was mentioned before, from my understanding.@k8s-triage-robot: 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][1]

Please send feedback to sig-contributor-experience at [kubernetes/community](https://github.com/kubernetes/community).

/lifecycle stale

[1]: https://www.kubernetes.dev/docs/guide/issue-triage/@alexanderstephan: @sbueringer Do you have any updates on this whether this issue is still relevant now that I can see that the other PR is merged?@sbueringer: The new code is here: https://github.com/kubernetes/kubernetes/blob/0ddab1694579d523e3865c75ca44d6cdf1b0ef93/staging/src/k8s.io/client-go/tools/cache/reflector.go#L188-L201

Looks like they simply use the logger from the context. I assume we should be fine, but I would suggest let's bump to the alpha.1 next week and just try it out.

Not entirely sure how much we'll have to change as part of that bump in CR and how this will exactly turn out@alexanderstephan: Okay, yes, that looks good. Considering the context is initialized correctly now in the controller-runtime, I would assume that this issue can be closed. I suspect quite some changes here. Did you have a chance to try it out?@sbueringer: > Did you have a chance to try it out?

Nope. I assume once https://github.com/kubernetes-sigs/controller-runtime/pull/3104 is merged you can test it (i.e. the WatchErrorHandler specifically) with the main branch.

Maybe we have to do these changes first to end up with an ideal behavior https://github.com/kubernetes-sigs/controller-runtime/pull/3104#discussion_r1946320586. But I didn't have time to work on this.@sbueringer: Added
```go
return nil, fmt.Errorf("abc")
```
here: https://github.com/kubernetes-sigs/controller-runtime/blob/85185e49ef2fe8345ba48c7181586ca66de8aaa3/pkg/cache/internal/informers.go#L363

Then ran `cache_suite_test.go`

I'm getting these logs
```
•E0308 12:22:26.615253   59566 reflector.go:200] "Failed to watch" err="failed to list *v1.Service: abc" logger="UnhandledError" reflector="pkg/mod/k8s.io/client-go@v0.33.0-alpha.3/tools/cache/reflector.go:285" type="*v1.Service"
E0308 12:22:48.688478   59566 reflector.go:200] "Failed to watch" err="failed to list *v1.Service: abc" logger="UnhandledError" reflector="pkg/mod/k8s.io/client-go@v0.33.0-alpha.3/tools/cache/reflector.go:285" type="*v1.Service"
```

So seems all good to me

/close

Feel free to reopen if you can still observe the issue with the CR main branch.@k8s-ci-robot: @sbueringer: Closing this issue.

<details>

In response to [this](https://github.com/kubernetes-sigs/controller-runtime/issues/2987#issuecomment-2708219793):

>Added
>```go
>return nil, fmt.Errorf("abc")
>```
>here: https://github.com/kubernetes-sigs/controller-runtime/blob/85185e49ef2fe8345ba48c7181586ca66de8aaa3/pkg/cache/internal/informers.go#L363
>
>Then ran `cache_suite_test.go`
>
>I'm getting these logs
>```
>•E0308 12:22:26.615253   59566 reflector.go:200] "Failed to watch" err="failed to list *v1.Service: abc" logger="UnhandledError" reflector="pkg/mod/k8s.io/client-go@v0.33.0-alpha.3/tools/cache/reflector.go:285" type="*v1.Service"
>E0308 12:22:48.688478   59566 reflector.go:200] "Failed to watch" err="failed to list *v1.Service: abc" logger="UnhandledError" reflector="pkg/mod/k8s.io/client-go@v0.33.0-alpha.3/tools/cache/reflector.go:285" type="*v1.Service"
>```
>
>So seems all good to me
>
>/close
>
>Feel free to reopen if you can still observe the issue with the CR main branch.


Instructions for interacting with me using PR comments are available [here](https://git.k8s.io/community/contributors/guide/pull-requests.md).  If you have questions or suggestions related to my behavior, please file an issue against the [kubernetes-sigs/prow](https://github.com/kubernetes-sigs/prow/issues/new?title=Prow%20issue:) repository.
</details>@sbueringer: /reopen

Missed something ..@k8s-ci-robot: @sbueringer: Reopened this issue.

<details>

In response to [this](https://github.com/kubernetes-sigs/controller-runtime/issues/2987#issuecomment-2708222631):

>/reopen
>
>Missed something ..


Instructions for interacting with me using PR comments are available [here](https://git.k8s.io/community/contributors/guide/pull-requests.md).  If you have questions or suggestions related to my behavior, please file an issue against the [kubernetes-sigs/prow](https://github.com/kubernetes-sigs/prow/issues/new?title=Prow%20issue:) repository.
</details>@sbueringer: Okay I think with [this PR](https://github.com/kubernetes-sigs/controller-runtime/pull/3149) it works as expected. Same code change as described in https://github.com/kubernetes-sigs/controller-runtime/issues/2987#issuecomment-2708219793

This time testing a controller configured with JSON logging

```json
{"ts":1741434916680.3196,"logger":"controller-runtime.cache.UnhandledError","caller":"runtime/runtime.go:226","msg":"Failed to watch","reflector":"pkg/mod/k8s.io/client-go@v0.33.0-alpha.3/tools/cache/reflector.go:285","type":"*v1alpha1.ExtensionConfig","err":"failed to list *v1alpha1.ExtensionConfig: abc"}
```

Another log for comparison

```json
{"ts":1741434890289.1465,"logger":"controller-runtime.metrics","caller":"server/server.go:247","msg":"Serving metrics server","v":0,"bindAddress":":8443","secure":true}
```
@alexanderstephan: Yes, this PR looks like what I would have expected. Very nice that this is now nearing completion. Thanks so much for your support!

Solution patch:
diff --git a/pkg/cache/cache.go b/pkg/cache/cache.go
index 8f14bfdb..648d0d75 100644
--- a/pkg/cache/cache.go
+++ b/pkg/cache/cache.go
@@ -113,6 +113,10 @@ type Informer interface {
 	// the handler again and an error if the handler cannot be added.
 	AddEventHandlerWithResyncPeriod(handler toolscache.ResourceEventHandler, resyncPeriod time.Duration) (toolscache.ResourceEventHandlerRegistration, error)
 
+	// AddEventHandlerWithOptions is a variant of AddEventHandlerWithResyncPeriod where
+	// all optional parameters are passed in as a struct.
+	AddEventHandlerWithOptions(handler toolscache.ResourceEventHandler, options toolscache.HandlerOptions) (toolscache.ResourceEventHandlerRegistration, error)
+
 	// RemoveEventHandler removes a previously added event handler given by
 	// its registration handle.
 	// This function is guaranteed to be idempotent and thread-safe.
@@ -207,11 +211,11 @@ type Options struct {
 	// to reduce the caches memory usage.
 	DefaultTransform toolscache.TransformFunc
 
-	// DefaultWatchErrorHandler will be used to the WatchErrorHandler which is called
+	// DefaultWatchErrorHandler will be used to set the WatchErrorHandler which is called
 	// whenever ListAndWatch drops the connection with an error.
 	//
 	// After calling this handler, the informer will backoff and retry.
-	DefaultWatchErrorHandler toolscache.WatchErrorHandler
+	DefaultWatchErrorHandler toolscache.WatchErrorHandlerWithContext
 
 	// DefaultUnsafeDisableDeepCopy is the default for UnsafeDisableDeepCopy
 	// for everything that doesn't specify this.
diff --git a/pkg/cache/internal/informers.go b/pkg/cache/internal/informers.go
index d3cbf2c7..b21a9c63 100644
--- a/pkg/cache/internal/informers.go
+++ b/pkg/cache/internal/informers.go
@@ -25,21 +25,26 @@ import (
 	"sync"
 	"time"
 
+	"github.com/go-logr/logr"
 	apierrors "k8s.io/apimachinery/pkg/api/errors"
 	"k8s.io/apimachinery/pkg/api/meta"
 	metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
 	"k8s.io/apimachinery/pkg/runtime"
 	"k8s.io/apimachinery/pkg/runtime/schema"
 	"k8s.io/apimachinery/pkg/runtime/serializer"
+	"k8s.io/apimachinery/pkg/util/wait"
 	"k8s.io/apimachinery/pkg/watch"
 	"k8s.io/client-go/dynamic"
 	"k8s.io/client-go/metadata"
 	"k8s.io/client-go/rest"
 	"k8s.io/client-go/tools/cache"
 	"sigs.k8s.io/controller-runtime/pkg/client/apiutil"
+	logf "sigs.k8s.io/controller-runtime/pkg/internal/log"
 	"sigs.k8s.io/controller-runtime/pkg/internal/syncs"
 )
 
+var log = logf.RuntimeLog.WithName("cache")
+
 // InformersOpts configures an InformerMap.
 type InformersOpts struct {
 	HTTPClient            *http.Client
@@ -52,7 +57,7 @@ type InformersOpts struct {
 	Transform             cache.TransformFunc
 	UnsafeDisableDeepCopy bool
 	EnableWatchBookmarks  bool
-	WatchErrorHandler     cache.WatchErrorHandler
+	WatchErrorHandler     cache.WatchErrorHandlerWithContext
 }
 
 // NewInformers creates a new InformersMap that can create informers under the hood.
@@ -105,7 +110,8 @@ func (c *Cache) Start(stop <-chan struct{}) {
 	// Stop on either the whole map stopping or just this informer being removed.
 	internalStop, cancel := syncs.MergeChans(stop, c.stop)
 	defer cancel()
-	c.Informer.Run(internalStop)
+	// Convert the stop channel to a context and then add the logger.
+	c.Informer.RunWithContext(logr.NewContext(wait.ContextForChannel(internalStop), log))
 }
 
 type tracker struct {
@@ -181,10 +187,10 @@ type Informers struct {
 	// NewInformer allows overriding of the shared index informer constructor for testing.
 	newInformer func(cache.ListerWatcher, runtime.Object, time.Duration, cache.Indexers) cache.SharedIndexInformer
 
-	// WatchErrorHandler allows the shared index informer's
+	// watchErrorHandler allows the shared index informer's
 	// watchErrorHandler to be set by overriding the options
 	// or to use the default watchErrorHandler
-	watchErrorHandler cache.WatchErrorHandler
+	watchErrorHandler cache.WatchErrorHandlerWithContext
 }
 
 // Start calls Run on each of the informers and sets started to true. Blocks on the context.
@@ -376,7 +382,7 @@ func (ip *Informers) addInformerToMap(gvk schema.GroupVersionKind, obj runtime.O
 
 	// Set WatchErrorHandler on SharedIndexInformer if set
 	if ip.watchErrorHandler != nil {
-		if err := sharedIndexInformer.SetWatchErrorHandler(ip.watchErrorHandler); err != nil {
+		if err := sharedIndexInformer.SetWatchErrorHandlerWithContext(ip.watchErrorHandler); err != nil {
 			return nil, false, err
 		}
 	}
diff --git a/pkg/cache/multi_namespace_cache.go b/pkg/cache/multi_namespace_cache.go
index f1e14a13..f033f85e 100644
--- a/pkg/cache/multi_namespace_cache.go
+++ b/pkg/cache/multi_namespace_cache.go
@@ -390,6 +390,23 @@ func (i *multiNamespaceInformer) AddEventHandlerWithResyncPeriod(handler toolsca
 	return handles, nil
 }
 
+// AddEventHandlerWithOptions adds the handler with options to each namespaced informer.
+func (i *multiNamespaceInformer) AddEventHandlerWithOptions(handler toolscache.ResourceEventHandler, options toolscache.HandlerOptions) (toolscache.ResourceEventHandlerRegistration, error) {
+	handles := handlerRegistration{
+		handles: make(map[string]toolscache.ResourceEventHandlerRegistration, len(i.namespaceToInformer)),
+	}
+
+	for ns, informer := range i.namespaceToInformer {
+		registration, err := informer.AddEventHandlerWithOptions(handler, options)
+		if err != nil {
+			return nil, err
+		}
+		handles.handles[ns] = registration
+	}
+
+	return handles, nil
+}
+
 // RemoveEventHandler removes a previously added event handler given by its registration handle.
 func (i *multiNamespaceInformer) RemoveEventHandler(h toolscache.ResourceEventHandlerRegistration) error {
 	handles, ok := h.(handlerRegistration)
diff --git a/pkg/internal/controller/controller.go b/pkg/internal/controller/controller.go
index d45476d3..d4047b7a 100644
--- a/pkg/internal/controller/controller.go
+++ b/pkg/internal/controller/controller.go
@@ -168,7 +168,7 @@ func (c *Controller[request]) Start(ctx context.Context) error {
 		defer c.mu.Unlock()
 
 		// TODO(pwittrock): Reconsider HandleCrash
-		defer utilruntime.HandleCrash()
+		defer utilruntime.HandleCrashWithLogger(c.LogConstructor(nil))
 
 		// NB(directxman12): launch the sources *before* trying to wait for the
 		// caches to sync so that they have a chance to register their intended
diff --git a/pkg/internal/source/kind.go b/pkg/internal/source/kind.go
index 2fdfbde8..68442391 100644
--- a/pkg/internal/source/kind.go
+++ b/pkg/internal/source/kind.go
@@ -10,7 +10,9 @@ import (
 	"k8s.io/apimachinery/pkg/api/meta"
 	"k8s.io/apimachinery/pkg/runtime"
 	"k8s.io/apimachinery/pkg/util/wait"
+	toolscache "k8s.io/client-go/tools/cache"
 	"k8s.io/client-go/util/workqueue"
+	logf "sigs.k8s.io/controller-runtime/pkg/internal/log"
 
 	"sigs.k8s.io/controller-runtime/pkg/cache"
 	"sigs.k8s.io/controller-runtime/pkg/client"
@@ -18,6 +20,8 @@ import (
 	"sigs.k8s.io/controller-runtime/pkg/predicate"
 )
 
+var logKind = logf.RuntimeLog.WithName("source").WithName("Kind")
+
 // Kind is used to provide a source of events originating inside the cluster from Watches (e.g. Pod Create).
 type Kind[object client.Object, request comparable] struct {
 	// Type is the type of object to watch.  e.g. &v1.Pod{}
@@ -68,12 +72,12 @@ func (ks *Kind[object, request]) Start(ctx context.Context, queue workqueue.Type
 				kindMatchErr := &meta.NoKindMatchError{}
 				switch {
 				case errors.As(lastErr, &kindMatchErr):
-					log.Error(lastErr, "if kind is a CRD, it should be installed before calling Start",
+					logKind.Error(lastErr, "if kind is a CRD, it should be installed before calling Start",
 						"kind", kindMatchErr.GroupKind)
 				case runtime.IsNotRegisteredError(lastErr):
-					log.Error(lastErr, "kind must be registered to the Scheme")
+					logKind.Error(lastErr, "kind must be registered to the Scheme")
 				default:
-					log.Error(lastErr, "failed to get informer from cache")
+					logKind.Error(lastErr, "failed to get informer from cache")
 				}
 				return false, nil // Retry.
 			}
@@ -87,7 +91,9 @@ func (ks *Kind[object, request]) Start(ctx context.Context, queue workqueue.Type
 			return
 		}
 
-		_, err := i.AddEventHandler(NewEventHandler(ctx, queue, ks.Handler, ks.Predicates).HandlerFuncs())
+		_, err := i.AddEventHandlerWithOptions(NewEventHandler(ctx, queue, ks.Handler, ks.Predicates).HandlerFuncs(), toolscache.HandlerOptions{
+			Logger: &logKind,
+		})
 		if err != nil {
 			ks.startedErr <- err
 			return
diff --git a/pkg/source/source.go b/pkg/source/source.go
index 267a6470..ed59925e 100644
--- a/pkg/source/source.go
+++ b/pkg/source/source.go
@@ -22,11 +22,13 @@ import (
 	"fmt"
 	"sync"
 
+	toolscache "k8s.io/client-go/tools/cache"
 	"k8s.io/client-go/util/workqueue"
 	"k8s.io/utils/ptr"
 	"sigs.k8s.io/controller-runtime/pkg/client"
 	"sigs.k8s.io/controller-runtime/pkg/event"
 	"sigs.k8s.io/controller-runtime/pkg/handler"
+	logf "sigs.k8s.io/controller-runtime/pkg/internal/log"
 	internal "sigs.k8s.io/controller-runtime/pkg/internal/source"
 	"sigs.k8s.io/controller-runtime/pkg/reconcile"
 
@@ -34,6 +36,8 @@ import (
 	"sigs.k8s.io/controller-runtime/pkg/predicate"
 )
 
+var logInformer = logf.RuntimeLog.WithName("source").WithName("Informer")
+
 // Source is a source of events (e.g. Create, Update, Delete operations on Kubernetes Objects, Webhook callbacks, etc)
 // which should be processed by event.EventHandlers to enqueue reconcile.Requests.
 //
@@ -282,7 +286,9 @@ func (is *Informer) Start(ctx context.Context, queue workqueue.TypedRateLimiting
 		return errors.New("must specify Informer.Handler")
 	}
 
-	_, err := is.Informer.AddEventHandler(internal.NewEventHandler(ctx, queue, is.Handler, is.Predicates).HandlerFuncs())
+	_, err := is.Informer.AddEventHandlerWithOptions(internal.NewEventHandler(ctx, queue, is.Handler, is.Predicates).HandlerFuncs(), toolscache.HandlerOptions{
+		Logger: &logInformer,
+	})
 	if err != nil {
 		return err
 	}



Test patch:
diff --git a/pkg/controller/controllertest/util.go b/pkg/controller/controllertest/util.go
index 2cbf12db..0b9c43c3 100644
--- a/pkg/controller/controllertest/util.go
+++ b/pkg/controller/controllertest/util.go
@@ -99,12 +99,24 @@ func (f *FakeInformer) HasSynced() bool {
 	return f.Synced
 }
 
-// AddEventHandler implements the Informer interface.  Adds an EventHandler to the fake Informers. TODO(community): Implement Registration.
+// AddEventHandler implements the Informer interface. Adds an EventHandler to the fake Informers. TODO(community): Implement Registration.
 func (f *FakeInformer) AddEventHandler(handler cache.ResourceEventHandler) (cache.ResourceEventHandlerRegistration, error) {
 	f.handlers = append(f.handlers, eventHandlerWrapper{handler})
 	return nil, nil
 }
 
+// AddEventHandlerWithResyncPeriod implements the Informer interface. Adds an EventHandler to the fake Informers (ignores resyncPeriod). TODO(community): Implement Registration.
+func (f *FakeInformer) AddEventHandlerWithResyncPeriod(handler cache.ResourceEventHandler, _ time.Duration) (cache.ResourceEventHandlerRegistration, error) {
+	f.handlers = append(f.handlers, eventHandlerWrapper{handler})
+	return nil, nil
+}
+
+// AddEventHandlerWithOptions implements the Informer interface. Adds an EventHandler to the fake Informers (ignores options). TODO(community): Implement Registration.
+func (f *FakeInformer) AddEventHandlerWithOptions(handler cache.ResourceEventHandler, _ cache.HandlerOptions) (cache.ResourceEventHandlerRegistration, error) {
+	f.handlers = append(f.handlers, eventHandlerWrapper{handler})
+	return nil, nil
+}
+
 // Run implements the Informer interface.  Increments f.RunCount.
 func (f *FakeInformer) Run(<-chan struct{}) {
 	f.RunCount++
@@ -135,15 +147,6 @@ func (f *FakeInformer) Delete(obj metav1.Object) {
 	}
 }
 
-// AddEventHandlerWithResyncPeriod does nothing.  TODO(community): Implement this.
-func (f *FakeInformer) AddEventHandlerWithResyncPeriod(handler cache.ResourceEventHandler, resyncPeriod time.Duration) (cache.ResourceEventHandlerRegistration, error) {
-	return nil, nil
-}
-
-func (f *FakeInformer) AddEventHandlerWithOptions(handler cache.ResourceEventHandler, options cache.HandlerOptions) (cache.ResourceEventHandlerRegistration, error) {
-	return nil, nil
-}
-
 // RemoveEventHandler does nothing.  TODO(community): Implement this.
 func (f *FakeInformer) RemoveEventHandler(handle cache.ResourceEventHandlerRegistration) error {
 	return nil
@@ -169,7 +172,8 @@ func (f *FakeInformer) SetWatchErrorHandler(cache.WatchErrorHandler) error {
 	return nil
 }
 
-func (f *FakeInformer) SetWatchErrorHandlerWithContext(handler cache.WatchErrorHandlerWithContext) error {
+// SetWatchErrorHandlerWithContext does nothing.  TODO(community): Implement this.
+func (f *FakeInformer) SetWatchErrorHandlerWithContext(cache.WatchErrorHandlerWithContext) error {
 	return nil
 }
 
diff --git a/pkg/log/log_test.go b/pkg/log/log_test.go
index b75604b6..f3bb4d6e 100644
--- a/pkg/log/log_test.go
+++ b/pkg/log/log_test.go
@@ -194,12 +194,12 @@ var _ = Describe("logging", func() {
 			}()
 			go func() {
 				defer GinkgoRecover()
-				delegLog.WithValues("with-value")
+				delegLog.WithValues("key", "with-value")
 				close(withValuesDone)
 			}()
 			go func() {
 				defer GinkgoRecover()
-				child.WithValues("grandchild")
+				child.WithValues("key", "grandchild")
 				close(grandChildDone)
 			}()
 			go func() {
diff --git a/pkg/manager/manager_test.go b/pkg/manager/manager_test.go
index 2c0cfa59..247a33f9 100644
--- a/pkg/manager/manager_test.go
+++ b/pkg/manager/manager_test.go
@@ -1092,9 +1092,14 @@ var _ = Describe("manger.Manager", func() {
 				msg := "controller log message"
 				m.GetControllerOptions().Logger.Info(msg)
 
-				Expect(messages).To(ContainElement(
-					ContainSubstring(msg),
-				))
+				Eventually(func(g Gomega) {
+					lock.Lock()
+					defer lock.Unlock()
+
+					g.Expect(messages).To(ContainElement(
+						ContainSubstring(msg),
+					))
+				}).Should(Succeed())
 			})
 
 			It("should return both runnables and stop errors when both error", func() {