[GRM] Configurable log level

[timebertt]

How to categorize this issue?

/area usability
/area logging
/kind enhancement

What would you like to be added:
Let's add the possibility to configure a log level for grm, so that we can minimize the amount of log output in productive environments (to not flood the logging stack with unnecessary log entries) but to be able to get all the interesting logs during development or debugging.

Why is this needed:
grm currently logs a lot of stuff for each reconciliation and health check run. For example:

{"level":"info","ts":"2020-06-24T08:12:14.327Z","logger":"gardener-resource-manager.reconciler","msg":"Applying","resource":"rbac.authorization.k8s.io/v1/ClusterRoleBinding/default/typha-cpva"}
{"level":"info","ts":"2020-06-24T08:12:14.325Z","logger":"gardener-resource-manager.reconciler","msg":"Applying","resource":"rbac.authorization.k8s.io/v1/ClusterRole/default/gardener.cloud:psp:kube-system:calico-kube-controllers"}
{"level":"info","ts":"2020-06-24T08:12:14.327Z","logger":"gardener-resource-manager.reconciler","msg":"Applying","resource":"v1/ServiceAccount/kube-system/typha-cpha"}
{"level":"info","ts":"2020-06-24T08:12:14.327Z","logger":"gardener-resource-manager.reconciler","msg":"Applying","resource":"apps/v1/Deployment/kube-system/calico-typha-vertical-autoscaler"}
{"level":"info","ts":"2020-06-24T08:12:14.327Z","logger":"gardener-resource-manager.reconciler","msg":"Applying","resource":"v1/ServiceAccount/kube-system/typha-cpva"}
{"level":"info","ts":"2020-06-24T08:12:14.327Z","logger":"gardener-resource-manager.reconciler","msg":"Applying","resource":"rbac.authorization.k8s.io/v1/RoleBinding/kube-system/gardener.cloud:psp:typha-cpva"}
{"level":"info","ts":"2020-06-24T08:12:14.327Z","logger":"gardener-resource-manager.reconciler","msg":"Applying","resource":"rbac.authorization.k8s.io/v1/RoleBinding/kube-system/typha-cpha"}
{"level":"info","ts":"2020-06-24T08:12:14.327Z","logger":"gardener-resource-manager.reconciler","msg":"Applying","resource":"rbac.authorization.k8s.io/v1/RoleBinding/kube-system/gardener.cloud:psp:calico-typha"}
{"level":"info","ts":"2020-06-24T08:12:14.327Z","logger":"gardener-resource-manager.reconciler","msg":"Applying","resource":"v1/ServiceAccount/kube-system/calico-typha"}
{"level":"info","ts":"2020-06-24T08:12:14.327Z","logger":"gardener-resource-manager.reconciler","msg":"Applying","resource":"v1/Service/kube-system/calico-typha"}

{"level":"info","ts":"2020-06-24T08:12:14.940Z","logger":"gardener-resource-manager.health-reconciler","msg":"Starting ManagedResource health checks","object":"shoot-garden-aws/extension-networking-calico-config"}
{"level":"info","ts":"2020-06-24T08:12:15.189Z","logger":"gardener-resource-manager.health-reconciler","msg":"Finished ManagedResource health checks","object":"shoot-garden-aws/extension-networking-calico-config"}
{"level":"info","ts":"2020-06-24T08:12:15.701Z","logger":"gardener-resource-manager.health-reconciler","msg":"Starting ManagedResource health checks","object":"shoot-garden-aws/shoot-core"}
{"level":"info","ts":"2020-06-24T08:12:15.954Z","logger":"gardener-resource-manager.health-reconciler","msg":"Finished ManagedResource health checks","object":"shoot-garden-aws/shoot-core"}
{"level":"info","ts":"2020-06-24T08:12:20.709Z","logger":"gardener-resource-manager.health-reconciler","msg":"Starting ManagedResource health checks","object":"shoot-garden-aws/extension-controlplane-storageclasses"}
{"level":"info","ts":"2020-06-24T08:12:20.719Z","logger":"gardener-resource-manager.health-reconciler","msg":"Finished ManagedResource health checks","object":"shoot-garden-aws/extension-controlplane-storageclasses"}
{"level":"info","ts":"2020-06-24T08:12:20.743Z","logger":"gardener-resource-manager.health-reconciler","msg":"Starting ManagedResource health checks","object":"shoot-garden-aws/extension-controlplane-shoot"}
{"level":"info","ts":"2020-06-24T08:12:20.754Z","logger":"gardener-resource-manager.health-reconciler","msg":"Finished ManagedResource health checks","object":"shoot-garden-aws/extension-controlplane-shoot"}
{"level":"info","ts":"2020-06-24T08:12:20.977Z","logger":"gardener-resource-manager.health-reconciler","msg":"Starting ManagedResource health checks","object":"shoot-garden-aws/extension-shoot-dns-service-shoot"}
{"level":"info","ts":"2020-06-24T08:12:20.986Z","logger":"gardener-resource-manager.health-reconciler","msg":"Finished ManagedResource health checks","object":"shoot-garden-aws/extension-shoot-dns-service-shoot"}

[rfranzke]

+1

[timebertt]

/assign
/touch

[timebertt]

I spent some more time with this based on the thoughts summarized in gardener-attic/gardener-resource-manager#98 (comment) and will pause my work on this for now, because of several headaches:

• we can't use klogr directly, because it seems like it's not supposed to be used in conjunction with a structured logger implementation under the hood (e.g. zapr). So if we use the k8s.io/component-base/logs utilities for having the same flags like k8s components and for json formatting, klogr will output messages like these:

  {"ts":1614007234337.0151,"msg":" \"msg\"=\"Starting gardener-resource-manager...\"  \"version\"=\"v0.0.0-dev\"\n","v":0}
  {"ts":1614007234337.085,"msg":" \"msg\"=\"FLAG: --add_dir_header=false\"  \n","v":0}
  {"ts":1614007234337.094,"msg":" \"msg\"=\"FLAG: --alsologtostderr=false\"  \n","v":0}
  

  This basically contradicts to all principles of structured logging, I guess, so it doesn't make sense to use it like that.

• if we instead use the logr implementation with json format we can get from k8s.io/component-base/logs/json, logs will end up like this:

  {"ts":1614009469754.6802,"msg":"Finished to reconcile ManagedResource","v":0,"name":"example","namespace":"default","v":0,"managedresource":"default/example","v":0,"resource":{"apiVersion":"v1","kind":"ConfigMap","namespace":"default","name":"test-1234"},"v":0,"name":"managedresource-example1","namespace":"default","v":0,"name":"managedresource-example2","namespace":"default","v":0,"secret":"default/managedresource-example1","v":0,"name":"example","namespace":"default","v":0,"managedresource":"default/example","v":0,"resource":{"apiVersion":"v1","kind":"ConfigMap","namespace":"default","name":"test-5678"},"v":0,"resource":{"apiVersion":"apps/v1","kind":"Deployment","namespace":"default","name":"nginx-deployment"},"v":0,"resource":{"apiVersion":"v1","kind":"ConfigMap","namespace":"default","name":"test-5678"},"v":0,"resource":{"apiVersion":"apps/v1","kind":"Deployment","namespace":"default","name":"nginx-deployment"},"v":0,"resource":{"apiVersion":"v1","kind":"ConfigMap","namespace":"default","name":"test-1234"},"v":0}
  

  That's also not very pretty and I don't know how to fix it.

• We could also construct a zapr ourselves (just like we are doing currently), but use some custom flags that resemble those of k8s components and instruct klog to log to that one. But then we will have to tweak zap's output format to not output the log level's string representations (e.g. INFO or DEBUG) because we would want to use numeric log levels.

• Also, I assume that the used log levels that controller-runtime code outputs at won't match the ones we use in our controllers. I.e. debug logs from the manager/recorder/webhook handler or similar will always be logged, even if the level is set to 2, which we would interpret as "normal log level".

I have some WIP laying around here for further reference: https://github.com/timebertt/gardener-resource-manager/tree/enh/log-level-wip

Long story short: This is all too confusing and too much pain, I simply can't get a clear target picture.
I'm open to pick this up again later on, but it will consume a lot more time than originally anticipated.

/unassign in favor of #2822

[timebertt]

Superseeded by #5191.

/close