Skip to content

logger.WithValues bypasses KubeAwareEncoder #1290

@timebertt

Description

@timebertt

When calling WithValues on a zap-backed logger, the value bypasses the KubeAwareEncoder, meaning it will be fully marshalled using the underlying encoder (e.g. json encoder).

For example:
If I add a key and value to the example controller here:

// Print the ReplicaSet
log.Info("Reconciling ReplicaSet", "replicaSet", rs, "container name", rs.Spec.Template.Spec.Containers[0].Name)

it will use the KubeAwareEncoder (which is the desired behaviour)

{"level":"info", [...] "replicaSet":{"apiVersion":"apps/v1","kind":"ReplicaSet","namespace":"kube-system","name":"coredns-66bff467f8"},"container name":"coredns"}

But if I use WithValues, which helps avoiding to add the values for every log statement in a controller, like this:

// Print the ReplicaSet
log = log.WithValues("replicaSet", rs)
log.Info("Reconciling ReplicaSet", "container name", rs.Spec.Template.Spec.Containers[0].Name)

it will bypass the KubeAwareEncoder and fully marshal the object into json, which will make the logs very hard to search:

{"level":"info", [...] "replicaSet":"&ReplicaSet{ObjectMeta:{coredns-66bff467f8  kube-system /apis/apps/v1/namespaces/kube-system/replicasets/coredns-66bff467f8 627fa1f9-ff8f-40fc-9f16-5df4dd71d567 13218 1 2020-12-04 13:49:52 +0100 CET <nil> <nil> map[hello:world k8s-app:kube-dns pod-template-hash:66bff467f8] map[deployment.kubernetes.io/desired-replicas:2 deployment.kubernetes.io/max-replicas:3 deployment.kubernetes.io/revision:1] [{apps/v1 Deployment coredns 9675a95d-33c0-42bc-82ae-b785d55280b1 0xc0004de338 0xc0004de339}] []  [{kube-controller-manager Update apps/v1 2020-12-04 13:50:21 +0100 CET FieldsV1 {\"f:metadata\":{\"f:annotations\":{\".\":{},\"f:deployment.kubernetes.io/desired-replicas\":{},\"f:deployment.kubernetes.io/max-replicas\":{},\"f:deployment.kubernetes.io/revision\":{}},\"f:labels\":{\".\":{},\"f:k8s-app\":{},\"f:pod-template-hash\":{}},\"f:ownerReferences\":{\".\":{},\"k:{\\\"uid\\\":\\\"9675a95d-33c0-42bc-82ae-b785d55280b1\\\"}\":{\".\":{},\"f:apiVersion\":{},\"f:blockOwnerDeletion\":{},\"f:controller\":{},\"f:kind\":{},\"f:name\":{},\"f:uid\":{}}}},\"f:spec\":{\"f:replicas\":{},\"f:selector\":{\"f:matchLabels\":{\".\":{},\"f:k8s-app\":{},\"f:pod-template-hash\":{}}},\"f:template\":{\"f:metadata\":{\"f:labels\":{\".\":{},\"f:k8s-app\":{},\"f:pod-template-hash\":{}}},\"f:spec\":{\"f:containers\":{\"k:{\\\"name\\\":\\\"coredns\\\"}\":{\".\":{},\"f:args\":{},\"f:image\":{},\"f:imagePullPolicy\":{},\"f:livenessProbe\":{\".\":{},\"f:failureThreshold\":{},\"f:httpGet\":{\".\":{},\"f:path\":{},\"f:port\":{},\"f:scheme\":{}},\"f:initialDelaySeconds\":{},\"f:periodSeconds\":{},\"f:successThreshold\":{},\"f:timeoutSeconds\":{}},\"f:name\":{},\"f:ports\":{\".\":{},\"k:{\\\"containerPort\\\":53,\\\"protocol\\\":\\\"TCP\\\"}\":{\".\":{},\"f:containerPort\":{},\"f:name\":{},\"f:protocol\":{}},\"k:{\\\"containerPort\\\":53,\\\"protocol\\\":\\\"UDP\\\"}\":{\".\":{},\"f:containerPort\":{},\"f:name\":{},\"f:protocol\":{}},\"k:{\\\"containerPort\\\":9153,\\\"protocol\\\":\\\"TCP\\\"}\":{\".\":{},\"f:containerPort\":{},\"f:name\":{},\"f:protocol\":{}}},\"f:readinessProbe\":{\".\":{},\"f:failureThreshold\":{},\"f:httpGet\":{\".\":{},\"f:path\":{},\"f:port\":{},\"f:scheme\":{}},\"f:periodSeconds\":{},\"f:successThreshold\":{},\"f:timeoutSeconds\":{}},\"f:resources\":{\".\":{},\"f:limits\":{\".\":{},\"f:memory\":{}},\"f:requests\":{\".\":{},\"f:cpu\":{},\"f:memory\":{}}},\"f:securityContext\":{\".\":{},\"f:allowPrivilegeEscalation\":{},\"f:capabilities\":{\".\":{},\"f:add\":{},\"f:drop\":{}},\"f:readOnlyRootFilesystem\":{}},\"f:terminationMessagePath\":{},\"f:terminationMessagePolicy\":{},\"f:volumeMounts\":{\".\":{},\"k:{\\\"mountPath\\\":\\\"/etc/coredns\\\"}\":{\".\":{},\"f:mountPath\":{},\"f:name\":{},\"f:readOnly\":{}}}}},\"f:dnsPolicy\":{},\"f:nodeSelector\":{\".\":{},\"f:kubernetes.io/os\":{}},\"f:priorityClassName\":{},\"f:restartPolicy\":{},\"f:schedulerName\":{},\"f:securityContext\":{},\"f:serviceAccount\":{},\"f:serviceAccountName\":{},\"f:terminationGracePeriodSeconds\":{},\"f:tolerations\":{},\"f:volumes\":{\".\":{},\"k:{\\\"name\\\":\\\"config-volume\\\"}\":{\".\":{},\"f:configMap\":{\".\":{},\"f:defaultMode\":{},\"f:items\":{},\"f:name\":{}},\"f:name\":{}}}}}},\"f:status\":{\"f:availableReplicas\":{},\"f:fullyLabeledReplicas\":{},\"f:observedGeneration\":{},\"f:readyReplicas\":{},\"f:replicas\":{}}}} {builtins Update apps/v1 2020-12-04 15:08:51 +0100 CET FieldsV1 {\"f:metadata\":{\"f:labels\":{\"f:hello\":{}}}}}]},Spec:ReplicaSetSpec{Replicas:*2,Selector:&v1.LabelSelector{MatchLabels:map[string]string{k8s-app: kube-dns,pod-template-hash: 66bff467f8,},MatchExpressions:[]LabelSelectorRequirement{},},Template:{{      0 0001-01-01 00:00:00 +0000 UTC <nil> <nil> map[k8s-app:kube-dns pod-template-hash:66bff467f8] map[] [] []  []} {[{config-volume {nil nil nil nil nil nil nil nil nil nil nil nil nil nil nil nil nil nil ConfigMapVolumeSource{LocalObjectReference:LocalObjectReference{Name:coredns,},Items:[]KeyToPath{KeyToPath{Key:Corefile,Path:Corefile,Mode:nil,},},DefaultMode:*420,Optional:nil,} nil nil nil nil nil nil nil nil nil nil}}] [] [{coredns k8s.gcr.io/coredns:1.6.7 [] [-conf /etc/coredns/Corefile]  [{dns 0 53 UDP } {dns-tcp 0 53 TCP } {metrics 0 9153 TCP }] [] [] {map[memory:{{178257920 0} {<nil>} 170Mi BinarySI}] map[cpu:{{100 -3} {<nil>} 100m DecimalSI} memory:{{73400320 0} {<nil>} 70Mi BinarySI}]} [{config-volume true /etc/coredns  <nil> }] [] &Probe{Handler:Handler{Exec:nil,HTTPGet:&HTTPGetAction{Path:/health,Port:{0 8080 },Host:,Scheme:HTTP,HTTPHeaders:[]HTTPHeader{},},TCPSocket:nil,},InitialDelaySeconds:60,TimeoutSeconds:5,PeriodSeconds:10,SuccessThreshold:1,FailureThreshold:5,} &Probe{Handler:Handler{Exec:nil,HTTPGet:&HTTPGetAction{Path:/ready,Port:{0 8181 },Host:,Scheme:HTTP,HTTPHeaders:[]HTTPHeader{},},TCPSocket:nil,},InitialDelaySeconds:0,TimeoutSeconds:1,PeriodSeconds:10,SuccessThreshold:1,FailureThreshold:3,} nil nil /dev/termination-log File IfNotPresent &SecurityContext{Capabilities:&Capabilities{Add:[NET_BIND_SERVICE],Drop:[all],},Privileged:nil,SELinuxOptions:nil,RunAsUser:nil,RunAsNonRoot:nil,ReadOnlyRootFilesystem:*true,AllowPrivilegeEscalation:*false,RunAsGroup:nil,ProcMount:nil,WindowsOptions:nil,SeccompProfile:nil,} false false false}] [] Always 0xc0004de398 <nil> Default map[kubernetes.io/os:linux] coredns coredns <nil>  false false false <nil> &PodSecurityContext{SELinuxOptions:nil,RunAsUser:nil,RunAsNonRoot:nil,SupplementalGroups:[],FSGroup:nil,RunAsGroup:nil,Sysctls:[]Sysctl{},WindowsOptions:nil,FSGroupChangePolicy:nil,SeccompProfile:nil,} []   nil default-scheduler [{CriticalAddonsOnly Exists   <nil>} {node-role.kubernetes.io/master   NoSchedule <nil>}] [] system-cluster-critical <nil> nil [] <nil> <nil> <nil> map[] [] <nil>}},MinReadySeconds:0,},Status:ReplicaSetStatus{Replicas:2,FullyLabeledReplicas:2,ObservedGeneration:1,ReadyReplicas:2,AvailableReplicas:2,Conditions:[]ReplicaSetCondition{},},}","container name":"coredns"}

I didn't find any issue/discussion related to a fix for this, other than this note from @DirectXMan12:

// NB(directxman12): can't just override AddReflected, since the encoder calls AddReflected on itself directly

So I'm opening this issue to see what can be done here to fix this behaviour.

Metadata

Metadata

Assignees

Labels

help wantedDenotes an issue that needs help from a contributor. Must meet "help wanted" guidelines.kind/bugCategorizes issue or PR as related to a bug.lifecycle/staleDenotes an issue or PR has remained open with no activity and has become stale.needs-triageIndicates an issue or PR lacks a `triage/foo` label and requires one.

Type

No type

Projects

No projects

Milestone

No milestone

Relationships

None yet

Development

No branches or pull requests

Issue actions