Improve logging when using PartialObjectMetadata

[erikgb]

This week, we spent some time debugging a complex issue in cert-manager approver-policy, and we would have been a lot more effective if controller-runtime had logged information about the actual resource (probably kind) behind the PartialObjectMetadata when the controller only cares for metadata of resources. Below is a redacted extract of the logs from a real cluster having this issue. We would love to know which resource cache was not synced in time, since approver-policy is watching for metadata on multiple resources. 😅

{"time":"2026-04-01T10:24:37.979652102Z","level":"INFO","msg":"Starting EventSource","controller":"certificaterequest","controllerGroup":"cert-manager.io","controllerKind":"CertificateRequest","source":"kind source: *v1.PartialObjectMetadata","logger":"controller-manager"}
{"time":"2026-04-01T10:24:37.97968379Z","level":"INFO","msg":"Starting EventSource","controller":"certificaterequest","controllerGroup":"cert-manager.io","controllerKind":"CertificateRequest","source":"kind source: *v1.PartialObjectMetadata","logger":"controller-manager"}
{"time":"2026-04-01T10:24:37.979661641Z","level":"INFO","msg":"Starting EventSource","controller":"certificaterequest","controllerGroup":"cert-manager.io","controllerKind":"CertificateRequest","source":"kind source: *v1.PartialObjectMetadata","logger":"controller-manager"}
{"time":"2026-04-01T10:24:37.979674009Z","level":"INFO","msg":"Starting EventSource","controller":"certificaterequest","controllerGroup":"cert-manager.io","controllerKind":"CertificateRequest","source":"kind source: *v1.PartialObjectMetadata","logger":"controller-manager"}
{"time":"2026-04-01T10:24:37.979679689Z","level":"INFO","msg":"Starting EventSource","controller":"certificaterequest","controllerGroup":"cert-manager.io","controllerKind":"CertificateRequest","source":"kind source: *v1.CertificateRequest","logger":"controller-manager"}
{"time":"2026-04-01T10:24:37.979693096Z","level":"INFO","msg":"Starting EventSource","controller":"certificaterequest","controllerGroup":"cert-manager.io","controllerKind":"CertificateRequest","source":"kind source: *v1.PartialObjectMetadata","logger":"controller-manager"}
{"time":"2026-04-01T10:24:37.979889744Z","level":"DEBUG+1","msg":"Starting reflector","logger":"controller-manager/controller-runtime/cache","type":"*v1.PartialObjectMetadata","resyncPeriod":37016549581214,"reflector":"k8s.io/client-go@v0.35.2/tools/cache/reflector.go:289"}
{"time":"2026-04-01T10:24:37.979911295Z","level":"DEBUG+1","msg":"Listing and watching","logger":"controller-manager/controller-runtime/cache","type":"*v1.PartialObjectMetadata","reflector":"k8s.io/client-go@v0.35.2/tools/cache/reflector.go:289"}
{"time":"2026-04-01T10:24:37.980355279Z","level":"DEBUG+1","msg":"Starting reflector","logger":"controller-manager/controller-runtime/cache","type":"*v1.PartialObjectMetadata","resyncPeriod":34589431939704,"reflector":"k8s.io/client-go@v0.35.2/tools/cache/reflector.go:289"}
{"time":"2026-04-01T10:24:37.980474094Z","level":"DEBUG+1","msg":"Starting reflector","logger":"controller-manager/controller-runtime/cache","type":"*v1.PartialObjectMetadata","resyncPeriod":37769082400875,"reflector":"k8s.io/client-go@v0.35.2/tools/cache/reflector.go:289"}
{"time":"2026-04-01T10:24:37.980488544Z","level":"DEBUG+1","msg":"Listing and watching","logger":"controller-manager/controller-runtime/cache","type":"*v1.PartialObjectMetadata","reflector":"k8s.io/client-go@v0.35.2/tools/cache/reflector.go:289"}
{"time":"2026-04-01T10:24:37.980650845Z","level":"DEBUG+1","msg":"Starting reflector","logger":"controller-manager/controller-runtime/cache","type":"*v1.PartialObjectMetadata","resyncPeriod":36665984018484,"reflector":"k8s.io/client-go@v0.35.2/tools/cache/reflector.go:289"}
{"time":"2026-04-01T10:24:37.980664479Z","level":"DEBUG+1","msg":"Listing and watching","logger":"controller-manager/controller-runtime/cache","type":"*v1.PartialObjectMetadata","reflector":"k8s.io/client-go@v0.35.2/tools/cache/reflector.go:289"}
{"time":"2026-04-01T10:24:37.980831847Z","level":"DEBUG+1","msg":"Starting reflector","logger":"controller-manager/controller-runtime/cache","type":"*v1.PartialObjectMetadata","resyncPeriod":37695204345075,"reflector":"k8s.io/client-go@v0.35.2/tools/cache/reflector.go:289"}
{"time":"2026-04-01T10:24:37.980844748Z","level":"DEBUG+1","msg":"Listing and watching","logger":"controller-manager/controller-runtime/cache","type":"*v1.PartialObjectMetadata","reflector":"k8s.io/client-go@v0.35.2/tools/cache/reflector.go:289"}
{"time":"2026-04-01T10:24:37.981012847Z","level":"DEBUG+1","msg":"Listing and watching","logger":"controller-manager/controller-runtime/cache","type":"*v1.PartialObjectMetadata","reflector":"k8s.io/client-go@v0.35.2/tools/cache/reflector.go:289"}
{"time":"2026-04-01T10:24:37.986083642Z","level":"DEBUG","msg":"Data couldn't be fetched in watchlist mode. Falling back to regular list. This is expected if watchlist is not supported or disabled in kube-apiserver.","logger":"controller-manager/controller-runtime/cache","err":"ListOptions.meta.k8s.io \"\" is invalid: sendInitialEvents: Forbidden: sendInitialEvents is forbidden for watch unless the WatchList feature gate is enabled"}
{"time":"2026-04-01T10:24:37.986284515Z","level":"DEBUG","msg":"Data couldn't be fetched in watchlist mode. Falling back to regular list. This is expected if watchlist is not supported or disabled in kube-apiserver.","logger":"controller-manager/controller-runtime/cache","err":"ListOptions.meta.k8s.io \"\" is invalid: sendInitialEvents: Forbidden: sendInitialEvents is forbidden for watch unless the WatchList feature gate is enabled"}
{"time":"2026-04-01T10:24:37.986453447Z","level":"DEBUG","msg":"Data couldn't be fetched in watchlist mode. Falling back to regular list. This is expected if watchlist is not supported or disabled in kube-apiserver.","logger":"controller-manager/controller-runtime/cache","err":"ListOptions.meta.k8s.io \"\" is invalid: sendInitialEvents: Forbidden: sendInitialEvents is forbidden for watch unless the WatchList feature gate is enabled"}
{"time":"2026-04-01T10:24:37.986554022Z","level":"DEBUG","msg":"Data couldn't be fetched in watchlist mode. Falling back to regular list. This is expected if watchlist is not supported or disabled in kube-apiserver.","logger":"controller-manager/controller-runtime/cache","err":"ListOptions.meta.k8s.io \"\" is invalid: sendInitialEvents: Forbidden: sendInitialEvents is forbidden for watch unless the WatchList feature gate is enabled"}
{"time":"2026-04-01T10:24:37.986679063Z","level":"DEBUG","msg":"Data couldn't be fetched in watchlist mode. Falling back to regular list. This is expected if watchlist is not supported or disabled in kube-apiserver.","logger":"controller-manager/controller-runtime/cache","err":"ListOptions.meta.k8s.io \"\" is invalid: sendInitialEvents: Forbidden: sendInitialEvents is forbidden for watch unless the WatchList feature gate is enabled"}
{"time":"2026-04-01T10:24:37.98680437Z","level":"DEBUG","msg":"Data couldn't be fetched in watchlist mode. Falling back to regular list. This is expected if watchlist is not supported or disabled in kube-apiserver.","logger":"controller-manager/controller-runtime/cache","err":"ListOptions.meta.k8s.io \"\" is invalid: sendInitialEvents: Forbidden: sendInitialEvents is forbidden for watch unless the WatchList feature gate is enabled"}
{"time":"2026-04-01T10:24:37.994097946Z","level":"DEBUG+2","msg":"Caches populated","logger":"controller-manager/controller-runtime/cache","type":"*v1.PartialObjectMetadata","reflector":"k8s.io/client-go@v0.35.2/tools/cache/reflector.go:289"}
{"time":"2026-04-01T10:24:37.999583103Z","level":"DEBUG+2","msg":"Caches populated","logger":"controller-manager/controller-runtime/cache","type":"*v1.PartialObjectMetadata","reflector":"k8s.io/client-go@v0.35.2/tools/cache/reflector.go:289"}
{"time":"2026-04-01T10:24:38.007432982Z","level":"DEBUG+2","msg":"Caches populated","logger":"controller-manager/controller-runtime/cache","type":"*v1.PartialObjectMetadata","reflector":"k8s.io/client-go@v0.35.2/tools/cache/reflector.go:289"}
{"time":"2026-04-01T10:24:38.023072539Z","level":"DEBUG+2","msg":"Caches populated","logger":"controller-manager/controller-runtime/cache","type":"*v1.PartialObjectMetadata","reflector":"k8s.io/client-go@v0.35.2/tools/cache/reflector.go:289"}
{"time":"2026-04-01T10:24:38.06987908Z","level":"DEBUG+2","msg":"Caches populated","logger":"controller-manager/controller-runtime/cache","type":"*v1.PartialObjectMetadata","reflector":"k8s.io/client-go@v0.35.2/tools/cache/reflector.go:289"}
{"time":"2026-04-01T10:24:47.979613356Z","level":"DEBUG-1","msg":"workqueue_items","controller":"certificaterequest","logger":"controller-manager","items":[]}
{"time":"2026-04-01T10:26:37.979887312Z","level":"ERROR","msg":"Could not wait for Cache to sync","controller":"certificaterequest","controllerGroup":"cert-manager.io","controllerKind":"CertificateRequest","source":"kind source: *v1.PartialObjectMetadata","logger":"controller-manager","err":"failed to wait for certificaterequest caches to sync kind source: *v1.PartialObjectMetadata: timed out waiting for cache to be synced for Kind *v1.PartialObjectMetadata"}

[alvaroaleman]

Makes sense and should do the same for unstructured. Should only require specialcasing the two here:

controller-runtime/pkg/internal/source/kind.go

Line 120 in 885e77d

return fmt.Sprintf("kind source: %T", ks.Type)

[erikgb]

Thanks for the suggestion, Alvaro! I just opened up #3494, PTAL!