Inconsistent logs formats

[ikavgo]

Describe the bug

I was debugging my kubernetes installation the other day. I wanted to correlate a resource status that waited on queue with topology operator logs. I noticed that topology operator emits logs in at least two different formats which makes it harder to comprehend and process automatically.

To Reproduce

Just use topology operator I guess.

Expected behavior
All log entries follow the same format.

Screenshots

Version and environment information

• Messaging Topology Operator: rabbitmqoperator/messaging-topology-operator:1.2.1
• RabbitMQ: 🤷‍♂️
• RabbitMQ Cluster Operator: rabbitmqoperator/cluster-operator:1.10.0
• Kubernetes: 1.21.2
• Local kind cluster

Additional context

Text examples:

{"level":"info","ts":1643717737.1284227,"logger":"controller-runtime.manager.controller.policy","msg":"RabbitmqCluster is already gone: cannot find its connection secret","reconciler group":"rabbitmq.com","reconciler kind":"Policy","name":"t.test-gykmeuum.t1-ojnfglwq.bfec80f8648192b525493efd156b5a8ecd6","namespace":"test-gykmeuum","policy":"t.test-gykmeuum.t1-ojnfglwq.bfec80f8648192b525493efd156b5a8ecd6"}

E0201 12:15:37.133237       1 event.go:264] Server rejected event '&v1.Event{TypeMeta:v1.TypeMeta{Kind:"", APIVersion:""}, ObjectMeta:v1.ObjectMeta{Name:"t.test-gykmeuum.t1-ojnfglwq.bfec80f8648192b525493efd156b5a8ecd6.16cfa892b88dc812", GenerateName:"", Namespace:"test-gykmeuum", SelfLink:"", UID:"", ResourceVersion:"", Generation:0, CreationTimestamp:time.Date(1, time.January, 1, 0, 0, 0, 0, time.UTC), DeletionTimestamp:<nil>, DeletionGracePeriodSeconds:(*int64)(nil), Labels:map[string]string(nil), Annotations:map[string]string(nil), OwnerReferences:[]v1.OwnerReference(nil), Finalizers:[]string(nil), ClusterName:"", ManagedFields:[]v1.ManagedFieldsEntry(nil)}, InvolvedObject:v1.ObjectReference{Kind:"Policy", Namespace:"test-gykmeuum", Name:"t.test-gykmeuum.t1-ojnfglwq.bfec80f8648192b525493efd156b5a8ecd6", UID:"7c133096-4b03-456c-bb02-5ef8f87fec32", APIVersion:"rabbitmq.com/v1beta1", ResourceVersion:"67248", FieldPath:""}, Reason:"SuccessfulDelete", Message:"successfully deleted policy", Source:v1.EventSource{Component:"policy-controller", Host:""}, FirstTimestamp:time.Date(2022, time.February, 1, 12, 15, 37, 128511506, time.Local), LastTimestamp:time.Date(2022, time.February, 1, 12, 15, 37, 128511506, time.Local), Count:1, Type:"Normal", EventTime:time.Date(1, time.January, 1, 0, 0, 0, 0, time.UTC), Series:(*v1.EventSeries)(nil), Action:"", Related:(*v1.ObjectReference)(nil), ReportingController:"", ReportingInstance:""}': 'events "t.test-gykmeuum.t1-ojnfglwq.bfec80f8648192b525493efd156b5a8ecd6.16cfa892b88dc812" is forbidden: unable to create new content in namespace test-gykmeuum because it is being terminated' (will not retry!)

[ablease]

Hey @ikvmw, this "E0201" message is from the controller runtime, or somwhere deep inside k8's.

I deployed the messaging topology operator on a GKE cluster and saw some similar formatted log lines with different messages e.g:

I0221 12:19:33.822128       1 leaderelection.go:248] attempting to acquire leader lease rabbitmq-system/messaging-topology-operator-leader-election...

After conferring with @ChunyiLyu, I don't think we can capture these events and wrap them in the json format simillar to logs from the logger in our operators.

I think we can close this issue, let me know.

[coro]

This issue is present in all of our operators that use controller-runtime. The problem is because controller-runtime's logger is a separate logger to the one used in client-go. Kubebuilder scaffolds the controller-runtime logger with Zap logger config, that can also be passed in on the command line of the operator, but client-go uses the klog logger. See this issue: kubernetes-sigs/controller-runtime#1420 (comment)

With a fairly simple diff, you can set the LogSink of the klog logger in the operator to match the controller-runtime logger:

diff --git a/main.go b/main.go
index a86b114..644aacf 100644
--- a/main.go
+++ b/main.go
@@ -12,6 +12,7 @@ package main
 import (
        "flag"
        "fmt"
+       "k8s.io/klog/v2"
        "os"
        "regexp"
        "strings"
@@ -73,7 +74,9 @@ func main() {
 
        flag.Parse()
 
-       ctrl.SetLogger(zap.New(zap.UseFlagOptions(&opts)))
+       logger := zap.New(zap.UseFlagOptions(&opts))
+       ctrl.SetLogger(logger)
+       // https://github.com/kubernetes-sigs/controller-runtime/issues/1420#issuecomment-794525248
+       klog.SetLogger(logger.WithName("messaging-topology-operator"))

leading to output like:

{"level":"info","ts":1646655238.5066237,"logger":"controller-runtime.webhook","msg":"Serving webhook server","host":"","port":9443}
{"level":"info","ts":1646655238.5068078,"logger":"controller-runtime.certwatcher","msg":"Starting certificate watcher"}
{"level":"info","ts":1646655238.706574,"logger":"messaging-topology-operator","msg":"attempting to acquire leader lease rabbitmq-system/messaging-topology-operator-leader-election...\n"}

This would change any klog logging done by our dependencies (which I think is just client-go) to be output in this format, which I think is worth it for consistency. What do you think?

[ablease]

Hey Connor, thanks for this context! I was struggling to find this when I had a look at this issue. This is super useful, thanks!