Details
-
Bug
-
Resolution: Done
-
Minor
-
None
-
4.12, 4.11, 4.10
-
Low
-
2
-
Sprint 228
-
1
-
Rejected
-
False
-
-
-
Bug Fix
Description
Description of problem:
The cluster-ingress-operator log output is a little noisy when starting the operator's controllers, in part because of the way in which the configurable-route controller configures its watches.
Version-Release number of selected component (if applicable):
4.10+.
How reproducible:
Always.
Steps to Reproduce:
1. Check the ingress-operator logs, and search for "configurable_route_controller": oc -n openshift-ingress-operator logs -c ingress-operator deploy/ingress-operator | grep -e configurable_route_controller
Actual results:
The operator emits log messages like the following on startup:
2022-11-23T08:47:35.646-0600 INFO operator.init controller/controller.go:241 Starting EventSource {"controller": "configurable_route_controller", "source": "&{{%!s(*v1.Role=&{{ } { 0 {{0 0 <nil>}} <nil> <nil> map[] map[] [] [] []} []}) %!s(*cache.multiNamespaceCache=&{map[openshift-config:0xc000712110 openshift-config-managed:0xc000712108 openshift-ingress:0xc0007120f8 openshift-ingress-canary:0xc000712100 openshift-ingress-operator:0xc0007120e8] 0xc000261ea0 0xc00010e190 0xc0007120e0}) %!s(chan error=<nil>) %!s(func()=<nil>)}}"}
2022-11-23T08:47:35.646-0600 INFO operator.init controller/controller.go:241 Starting EventSource {"controller": "configurable_route_controller", "source": "&{{%!s(*v1.RoleBinding=&{{ } { 0 {{0 0 <nil>}} <nil> <nil> map[] map[] [] [] []} [] { }}) %!s(*cache.multiNamespaceCache=&{map[openshift-config:0xc000712110 openshift-config-managed:0xc000712108 openshift-ingress:0xc0007120f8 openshift-ingress-canary:0xc000712100 openshift-ingress-operator:0xc0007120e8] 0xc000261ea0 0xc00010e190 0xc0007120e0}) %!s(chan error=<nil>) %!s(func()=<nil>)}}"}
2022-11-23T08:47:35.646-0600 INFO operator.init controller/controller.go:241 Starting Controller {"controller": "configurable_route_controller"}
Expected results:
The operator should emit log messages like the following on startup:
2022-11-23T08:48:43.076-0600 INFO operator.init controller/controller.go:241 Starting EventSource {"controller": "configurable_route_controller", "source": "kind source: *v1.Role"}
2022-11-23T08:48:43.078-0600 INFO operator.init controller/controller.go:241 Starting EventSource {"controller": "configurable_route_controller", "source": "kind source: *v1.RoleBinding"}
2022-11-23T08:48:43.078-0600 INFO operator.init controller/controller.go:241 Starting Controller {"controller": "configurable_route_controller"}
Additional info:
The cited noisiness results from two issues. First, the configurable-route controller needlessly uses source.NewKindWithCache() to configure its watches when it would be sufficient and slightly simpler to use source.Kind.
Second, recent versions of controller-runtime have excessively noisy logging for the kindWithCache source type. The configurable-route controller was introduced in OpenShift 4.8, which uses controller-runtime v0.9.0-alpha.1. OpenShift 4.9 has controller-runtime v0.9.0, OpenShift 4.10 has controller-runtime v0.11.0, and OpenShift 4.11 has controller-runtime v0.12.0. A change in controller-runtime v0.11.0 causes the noisiness. Before this change, the output was excessively quiet, for example:
2022-09-28T20:51:40.979Z INFO operator.init.controller-runtime.manager.controller.configurable_route_controller controller/controller.go:221 Starting EventSource {"source": {}}
2022-09-28T20:51:40.979Z INFO operator.init.controller-runtime.manager.controller.configurable_route_controller controller/controller.go:221 Starting EventSource {"source": {}}
I have filed an issue upstream to improve the logging for kindWithCache: https://github.com/kubernetes-sigs/controller-runtime/pull/2057