Use logger from context given by controller runtime wherever it's applicable #765

panyuenlau · 2022-02-04T17:47:14Z

Q	A
Bug fix?	no
New feature?	no
API breaks?	no
Deprecations?	no
Related tickets	fixes #743
License	Apache 2.0

What's in this PR?

Use logger from the context given by the controller runtime wherever it is applicable

Why?

Simplify the codebase by :

Reducing the number of loggers that we initialized for the controllers
Reducing the number of parameters that get passed to a lot of functions

Additional context

Example logs with the changes:

I0203 22:11:43.591047       1 request.go:665] Waited for 1.044370458s due to client-side throttling, not priority and fairness, request: GET:https://10.10.0.1:443/apis/telemetry.istio.io/v1alpha1?timeout=32s
{"level":"info","ts":"2022-02-03T22:11:43.592Z","logger":"controller-runtime.metrics","msg":"Metrics server is starting to listen","addr":":8080"}
{"level":"info","ts":"2022-02-03T22:11:43.593Z","logger":"controller-runtime.webhook","msg":"Registering webhook","path":"/validate"}
{"level":"info","ts":"2022-02-03T22:11:43.593Z","logger":"setup","msg":"starting manager"}
{"level":"info","ts":"2022-02-03T22:11:43.593Z","logger":"controller-runtime.webhook.webhooks","msg":"Starting webhook server"}
{"level":"info","ts":"2022-02-03T22:11:43.593Z","msg":"Starting server","path":"/metrics","kind":"metrics","addr":"[::]:8080"}
{"level":"info","ts":"2022-02-03T22:11:43.594Z","logger":"controller-runtime.certwatcher","msg":"Updated current TLS certificate"}
{"level":"info","ts":"2022-02-03T22:11:43.594Z","logger":"controller-runtime.webhook","msg":"Serving webhook server","host":"","port":443}
{"level":"info","ts":"2022-02-03T22:11:43.594Z","logger":"controller-runtime.certwatcher","msg":"Starting certificate watcher"}
I0203 22:11:43.694455       1 leaderelection.go:248] attempting to acquire leader lease kafka/controller-leader-election-helper...
I0203 22:11:59.264106       1 leaderelection.go:258] successfully acquired lease kafka/controller-leader-election-helper
{"level":"info","ts":"2022-02-03T22:11:59.264Z","logger":"controller.KafkaTopic","msg":"Starting EventSource","reconciler group":"kafka.banzaicloud.io","reconciler kind":"KafkaTopic","source":"kind source: *v1alpha1.KafkaTopic"}
{"level":"info","ts":"2022-02-03T22:11:59.264Z","logger":"controller.KafkaTopic","msg":"Starting Controller","reconciler group":"kafka.banzaicloud.io","reconciler kind":"KafkaTopic"}
{"level":"info","ts":"2022-02-03T22:11:59.265Z","logger":"controller.CruiseControl","msg":"Starting EventSource","reconciler group":"kafka.banzaicloud.io","reconciler kind":"KafkaCluster","source":"kind source: *v1beta1.KafkaCluster"}
{"level":"info","ts":"2022-02-03T22:11:59.265Z","logger":"controller.CruiseControl","msg":"Starting Controller","reconciler group":"kafka.banzaicloud.io","reconciler kind":"KafkaCluster"}
{"level":"info","ts":"2022-02-03T22:11:59.265Z","logger":"controller.KafkaUser","msg":"Starting EventSource","reconciler group":"kafka.banzaicloud.io","reconciler kind":"KafkaUser","source":"kind source: *v1alpha1.KafkaUser"}
{"level":"info","ts":"2022-02-03T22:11:59.265Z","logger":"controller.KafkaUser","msg":"Starting EventSource","reconciler group":"kafka.banzaicloud.io","reconciler kind":"KafkaUser","source":"kind source: *v1.CertificateSigningRequest"}
{"level":"info","ts":"2022-02-03T22:11:59.265Z","logger":"controller.KafkaUser","msg":"Starting Controller","reconciler group":"kafka.banzaicloud.io","reconciler kind":"KafkaUser"}
{"level":"info","ts":"2022-02-03T22:11:59.265Z","logger":"controller.KafkaCluster","msg":"Starting EventSource","reconciler group":"kafka.banzaicloud.io","reconciler kind":"KafkaCluster","source":"kind source: *v1beta1.KafkaCluster"}
{"level":"info","ts":"2022-02-03T22:11:59.265Z","logger":"controller.KafkaCluster","msg":"Starting EventSource","reconciler group":"kafka.banzaicloud.io","reconciler kind":"KafkaCluster","source":"kind source: *v1.Service"}
{"level":"info","ts":"2022-02-03T22:11:59.266Z","logger":"controller.KafkaCluster","msg":"Starting EventSource","reconciler group":"kafka.banzaicloud.io","reconciler kind":"KafkaCluster","source":"kind source: *v1.ConfigMap"}
{"level":"info","ts":"2022-02-03T22:11:59.266Z","logger":"controller.KafkaCluster","msg":"Starting EventSource","reconciler group":"kafka.banzaicloud.io","reconciler kind":"KafkaCluster","source":"kind source: *v1beta1.PodDisruptionBudget"}
{"level":"info","ts":"2022-02-03T22:11:59.266Z","logger":"controller.KafkaCluster","msg":"Starting EventSource","reconciler group":"kafka.banzaicloud.io","reconciler kind":"KafkaCluster","source":"kind source: *v1.PersistentVolumeClaim"}
{"level":"info","ts":"2022-02-03T22:11:59.266Z","logger":"controller.KafkaCluster","msg":"Starting EventSource","reconciler group":"kafka.banzaicloud.io","reconciler kind":"KafkaCluster","source":"kind source: *v1.Pod"}
{"level":"info","ts":"2022-02-03T22:11:59.266Z","logger":"controller.KafkaCluster","msg":"Starting EventSource","reconciler group":"kafka.banzaicloud.io","reconciler kind":"KafkaCluster","source":"kind source: *v1.Service"}
{"level":"info","ts":"2022-02-03T22:11:59.266Z","logger":"controller.KafkaCluster","msg":"Starting EventSource","reconciler group":"kafka.banzaicloud.io","reconciler kind":"KafkaCluster","source":"kind source: *v1.Deployment"}
{"level":"info","ts":"2022-02-03T22:11:59.266Z","logger":"controller.KafkaCluster","msg":"Starting EventSource","reconciler group":"kafka.banzaicloud.io","reconciler kind":"KafkaCluster","source":"kind source: *v1.ConfigMap"}
{"level":"info","ts":"2022-02-03T22:11:59.266Z","logger":"controller.KafkaCluster","msg":"Starting EventSource","reconciler group":"kafka.banzaicloud.io","reconciler kind":"KafkaCluster","source":"kind source: *v1.Service"}
{"level":"info","ts":"2022-02-03T22:11:59.266Z","logger":"controller.KafkaCluster","msg":"Starting EventSource","reconciler group":"kafka.banzaicloud.io","reconciler kind":"KafkaCluster","source":"kind source: *v1.Deployment"}
{"level":"info","ts":"2022-02-03T22:11:59.266Z","logger":"controller.KafkaCluster","msg":"Starting EventSource","reconciler group":"kafka.banzaicloud.io","reconciler kind":"KafkaCluster","source":"kind source: *v1.ConfigMap"}
{"level":"info","ts":"2022-02-03T22:11:59.266Z","logger":"controller.KafkaCluster","msg":"Starting Controller","reconciler group":"kafka.banzaicloud.io","reconciler kind":"KafkaCluster"}
{"level":"info","ts":"2022-02-03T22:11:59.666Z","logger":"controller.KafkaTopic","msg":"Starting workers","reconciler group":"kafka.banzaicloud.io","reconciler kind":"KafkaTopic","worker count":10}
{"level":"info","ts":"2022-02-03T22:11:59.667Z","logger":"controller.KafkaTopic","msg":"Reconciling KafkaTopic","reconciler group":"kafka.banzaicloud.io","reconciler kind":"KafkaTopic","name":"kafkacat-airports","namespace":"kafka","kafkatopic":"kafka/kafkacat-airports","Request.Name":"kafkacat-airports"}
{"level":"info","ts":"2022-02-03T22:11:59.734Z","logger":"controller.CruiseControl","msg":"Starting workers","reconciler group":"kafka.banzaicloud.io","reconciler kind":"KafkaCluster","worker count":1}
{"level":"info","ts":"2022-02-03T22:11:59.735Z","logger":"controller.CruiseControl","msg":"no active tasks found in Kafka Cluster status","reconciler group":"kafka.banzaicloud.io","reconciler kind":"KafkaCluster","name":"kafka","namespace":"kafka"}
{"level":"info","ts":"2022-02-03T22:11:59.737Z","logger":"controller.KafkaUser","msg":"Starting workers","reconciler group":"kafka.banzaicloud.io","reconciler kind":"KafkaUser","worker count":1}
{"level":"info","ts":"2022-02-03T22:11:59.737Z","logger":"controller.KafkaCluster","msg":"Starting workers","reconciler group":"kafka.banzaicloud.io","reconciler kind":"KafkaCluster","worker count":1}
{"level":"info","ts":"2022-02-03T22:11:59.737Z","logger":"controller.KafkaUser","msg":"Reconciling KafkaUser","reconciler group":"kafka.banzaicloud.io","reconciler kind":"KafkaUser","name":"example-kafkauser","namespace":"default","kafkauser":"default/example-kafkauser","Request.Name":"example-kafkauser"}
{"level":"info","ts":"2022-02-03T22:11:59.737Z","logger":"controller.KafkaCluster","msg":"Reconciling KafkaCluster","reconciler group":"kafka.banzaicloud.io","reconciler kind":"KafkaCluster","name":"kafka","namespace":"kafka","Request.Namespace":"kafka/kafka","Request.Name":"kafka"}
{"level":"info","ts":"2022-02-03T22:11:59.834Z","logger":"controller.KafkaCluster","msg":"CR status updated","reconciler group":"kafka.banzaicloud.io","reconciler kind":"KafkaCluster","name":"kafka","namespace":"kafka","Request.Namespace":"kafka/kafka","Request.Name":"kafka","status":"ClusterReconciling"}
{"level":"info","ts":"2022-02-03T22:11:59.934Z","logger":"controller.KafkaUser","msg":"Ensuring read ACLs for User: CN=example-kafkauser -> Topic: kafkacat-airports","reconciler group":"kafka.banzaicloud.io","reconciler kind":"KafkaUser","name":"example-kafkauser","namespace":"default","kafkauser":"default/example-kafkauser","Request.Name":"example-kafkauser"}
{"level":"info","ts":"2022-02-03T22:11:59.944Z","logger":"kafka_util","msg":"Kafka client closed cleanly"}
{"level":"info","ts":"2022-02-03T22:11:59.962Z","logger":"kafka_util","msg":"Kafka client closed cleanly"}
{"level":"info","ts":"2022-02-03T22:11:59.963Z","logger":"controller.KafkaTopic","msg":"Topic already exists, verifying configuration","reconciler group":"kafka.banzaicloud.io","reconciler kind":"KafkaTopic","name":"kafkacat-airports","namespace":"kafka","kafkatopic":"kafka/kafkacat-airports","Request.Name":"kafkacat-airports"}
{"level":"info","ts":"2022-02-03T22:11:59.981Z","logger":"controller.KafkaTopic","msg":"Verified partitions and configuration for topic","reconciler group":"kafka.banzaicloud.io","reconciler kind":"KafkaTopic","name":"kafkacat-airports","namespace":"kafka","kafkatopic":"kafka/kafkacat-airports","Request.Name":"kafkacat-airports"}
{"level":"info","ts":"2022-02-03T22:11:59.982Z","logger":"controller.KafkaTopic","msg":"Ensured topic","reconciler group":"kafka.banzaicloud.io","reconciler kind":"KafkaTopic","name":"kafkacat-airports","namespace":"kafka","kafkatopic":"kafka/kafkacat-airports","Request.Name":"kafkacat-airports"}
{"level":"info","ts":"2022-02-03T22:11:59.982Z","logger":"kafka_util","msg":"Kafka client closed cleanly"}
{"level":"info","ts":"2022-02-03T22:12:00.160Z","logger":"controller.KafkaCluster","msg":"Kafka cluster state updated","reconciler group":"kafka.banzaicloud.io","reconciler kind":"KafkaCluster","name":"kafka","namespace":"kafka","Request.Namespace":"kafka/kafka","Request.Name":"kafka","component":"kafka","clusterName":"kafka","clusterNamespace":"kafka"}
{"level":"info","ts":"2022-02-03T22:12:00.177Z","logger":"kafka_util","msg":"Kafka client closed cleanly"}
{"level":"info","ts":"2022-02-03T22:12:00.304Z","logger":"controller.KafkaCluster","msg":"Kafka cluster state updated","reconciler group":"kafka.banzaicloud.io","reconciler kind":"KafkaCluster","name":"kafka","namespace":"kafka","Request.Namespace":"kafka/kafka","Request.Name":"kafka","component":"kafka","clusterName":"kafka","clusterNamespace":"kafka"}
{"level":"info","ts":"2022-02-03T22:12:00.339Z","logger":"kafka_util","msg":"Kafka client closed cleanly"}
{"level":"info","ts":"2022-02-03T22:12:00.355Z","logger":"kafka_util","msg":"Kafka client closed cleanly"}
{"level":"info","ts":"2022-02-03T22:12:00.355Z","logger":"controller.KafkaCluster.generateCCTopic","msg":"CruiseControl topic has been created by CruiseControl","reconciler group":"kafka.banzaicloud.io","reconciler kind":"KafkaCluster","name":"kafka","namespace":"kafka","Request.Namespace":"kafka/kafka","Request.Name":"kafka","component":"kafka-cruisecontrol"}
{"level":"info","ts":"2022-02-03T22:12:00.367Z","logger":"controller.KafkaCluster","msg":"CR status updated","reconciler group":"kafka.banzaicloud.io","reconciler kind":"KafkaCluster","name":"kafka","namespace":"kafka","Request.Namespace":"kafka/kafka","Request.Name":"kafka","component":"kafka-cruisecontrol","status":"CruiseControlTopicReady"}
{"level":"info","ts":"2022-02-03T22:12:00.367Z","logger":"controller.KafkaCluster","msg":"Generating capacity config","reconciler group":"kafka.banzaicloud.io","reconciler kind":"KafkaCluster","name":"kafka","namespace":"kafka","Request.Namespace":"kafka/kafka","Request.Name":"kafka","component":"kafka-cruisecontrol"}
{"level":"info","ts":"2022-02-03T22:12:00.367Z","logger":"controller.KafkaCluster","msg":"incoming network throughput is not set falling back to default value","reconciler group":"kafka.banzaicloud.io","reconciler kind":"KafkaCluster","name":"kafka","namespace":"kafka","Request.Namespace":"kafka/kafka","Request.Name":"kafka","component":"kafka-cruisecontrol"}
{"level":"info","ts":"2022-02-03T22:12:00.367Z","logger":"controller.KafkaCluster","msg":"outgoing network throughput is not set falling back to default value","reconciler group":"kafka.banzaicloud.io","reconciler kind":"KafkaCluster","name":"kafka","namespace":"kafka","Request.Namespace":"kafka/kafka","Request.Name":"kafka","component":"kafka-cruisecontrol"}
{"level":"info","ts":"2022-02-03T22:12:00.367Z","logger":"controller.KafkaCluster","msg":"The following brokerCapacity was generated","reconciler group":"kafka.banzaicloud.io","reconciler kind":"KafkaCluster","name":"kafka","namespace":"kafka","Request.Namespace":"kafka/kafka","Request.Name":"kafka","component":"kafka-cruisecontrol","brokerCapacity":{"brokerId":"0","capacity":{"DISK":{"/kafka-logs/kafka":"10737"},"CPU":"150","NW_IN":"125000","NW_OUT":"125000"},"doc":"Capacity unit used for disk is in MB, cpu is in percentage, network throughput is in KB."}}
{"level":"info","ts":"2022-02-03T22:12:00.367Z","logger":"controller.KafkaCluster","msg":"incoming network throughput is not set falling back to default value","reconciler group":"kafka.banzaicloud.io","reconciler kind":"KafkaCluster","name":"kafka","namespace":"kafka","Request.Namespace":"kafka/kafka","Request.Name":"kafka","component":"kafka-cruisecontrol"}
{"level":"info","ts":"2022-02-03T22:12:00.367Z","logger":"controller.KafkaCluster","msg":"outgoing network throughput is not set falling back to default value","reconciler group":"kafka.banzaicloud.io","reconciler kind":"KafkaCluster","name":"kafka","namespace":"kafka","Request.Namespace":"kafka/kafka","Request.Name":"kafka","component":"kafka-cruisecontrol"}
{"level":"info","ts":"2022-02-03T22:12:00.367Z","logger":"controller.KafkaCluster","msg":"The following brokerCapacity was generated","reconciler group":"kafka.banzaicloud.io","reconciler kind":"KafkaCluster","name":"kafka","namespace":"kafka","Request.Namespace":"kafka/kafka","Request.Name":"kafka","component":"kafka-cruisecontrol","brokerCapacity":{"brokerId":"1","capacity":{"DISK":{"/kafka-logs/kafka":"10737"},"CPU":"150","NW_IN":"125000","NW_OUT":"125000"},"doc":"Capacity unit used for disk is in MB, cpu is in percentage, network throughput is in KB."}}
{"level":"info","ts":"2022-02-03T22:12:00.367Z","logger":"controller.KafkaCluster","msg":"Generated capacity config was successful with values: {\n    \"brokerCapacities\": [\n        {\n            \"brokerId\": \"0\",\n            \"capacity\": {\n                \"DISK\": {\n                    \"/kafka-logs/kafka\": \"10737\"\n                },\n                \"CPU\": \"150\",\n                \"NW_IN\": \"125000\",\n                \"NW_OUT\": \"125000\"\n            },\n            \"doc\": \"Capacity unit used for disk is in MB, cpu is in percentage, network throughput is in KB.\"\n        },\n        {\n            \"brokerId\": \"1\",\n            \"capacity\": {\n                \"DISK\": {\n                    \"/kafka-logs/kafka\": \"10737\"\n                },\n                \"CPU\": \"150\",\n                \"NW_IN\": \"125000\",\n                \"NW_OUT\": \"125000\"\n            },\n            \"doc\": \"Capacity unit used for disk is in MB, cpu is in percentage, network throughput is in KB.\"\n        },\n        {\n            \"brokerId\": \"-1\",\n            \"capacity\": {\n                \"DISK\": {\n                    \"/kafka-logs/kafka\": \"10737\"\n                },\n                \"CPU\": \"100\",\n                \"NW_IN\": \"125000\",\n                \"NW_OUT\": \"125000\"\n            },\n            \"doc\": \"Capacity unit used for disk is in MB, cpu is in percentage, network throughput is in KB.\"\n        }\n    ]\n}","reconciler group":"kafka.banzaicloud.io","reconciler kind":"KafkaCluster","name":"kafka","namespace":"kafka","Request.Namespace":"kafka/kafka","Request.Name":"kafka","component":"kafka-cruisecontrol"}
{"level":"info","ts":"2022-02-03T22:12:00.374Z","logger":"controller.KafkaCluster","msg":"ensuring finalizers on kafkacluster","reconciler group":"kafka.banzaicloud.io","reconciler kind":"KafkaCluster","name":"kafka","namespace":"kafka","Request.Namespace":"kafka/kafka","Request.Name":"kafka"}
{"level":"info","ts":"2022-02-03T22:12:00.411Z","logger":"controller.KafkaCluster","msg":"CR status updated","reconciler group":"kafka.banzaicloud.io","reconciler kind":"KafkaCluster","name":"kafka","namespace":"kafka","Request.Namespace":"kafka/kafka","Request.Name":"kafka","status":"ClusterRunning"}

Checklist

Implementation tested
Logging code meets the guideline

amberimam

Looks good! Thanks for taking care of this. :)

controllers/kafkacluster_controller.go

controllers/kafkatopic_controller.go

controllers/kafkauser_controller.go

Use logger from context when it's possible

b6120fd

panyuenlau requested a review from a team as a code owner February 4, 2022 17:47

panyuenlau and others added 4 commits February 4, 2022 12:48

Merge branch 'master' into use-runtime-logger

c5da902

Remove unused import and fix code format

e1dc3eb

Fix lint issues - remove unused var and sort imports

5c50228

Merge branch 'master' into use-runtime-logger

91ecc12

amberimam previously approved these changes Feb 4, 2022

View reviewed changes

stoader previously approved these changes Feb 5, 2022

View reviewed changes

adamantal previously approved these changes Feb 7, 2022

View reviewed changes

baluchicken requested changes Feb 7, 2022

View reviewed changes

controllers/kafkacluster_controller.go Outdated Show resolved Hide resolved

baluchicken reviewed Feb 7, 2022

View reviewed changes

controllers/kafkatopic_controller.go Outdated Show resolved Hide resolved

baluchicken reviewed Feb 7, 2022

View reviewed changes

controllers/kafkauser_controller.go Outdated Show resolved Hide resolved

Remove duplicated info by using WithValues()

7cdb0f6

panyuenlau dismissed stale reviews from adamantal, stoader, and amberimam via 7cdb0f6 February 7, 2022 14:46

baluchicken approved these changes Feb 7, 2022

View reviewed changes

panyuenlau requested review from adamantal, stoader and amberimam February 7, 2022 15:05

amberimam approved these changes Feb 7, 2022

View reviewed changes

panyuenlau merged commit 68a6465 into banzaicloud:master Feb 7, 2022

panyuenlau deleted the use-runtime-logger branch February 7, 2022 16:54

panyuenlau mentioned this pull request Feb 27, 2023

Allow creating KafkaTopic CR for topic that already present on the Kafka cluster #934

Merged

4 tasks

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Use logger from context given by controller runtime wherever it's applicable #765

Use logger from context given by controller runtime wherever it's applicable #765

panyuenlau commented Feb 4, 2022 •

edited

amberimam left a comment

Use logger from context given by controller runtime wherever it's applicable #765

Use logger from context given by controller runtime wherever it's applicable #765

Conversation

panyuenlau commented Feb 4, 2022 • edited

What's in this PR?

Why?

Additional context

Checklist

amberimam left a comment

Choose a reason for hiding this comment

panyuenlau commented Feb 4, 2022 •

edited