Logging-format json sometimes writes plaintext messages

[petermajn]

Describe the bug:
Cert-manager on our cluster is configured with the flag "--logging-format=json". Sometimes I see messages in logs formatted as plaintext. It was a problem before as described in #6254.

Examples

Certmanager controller

{"ts":1708340302756.7686,"caller":"clientcmd/client_config.go:618","msg":"Neither --kubeconfig nor --master was specified.  Using the inClusterConfig.  This might not work.","v":0}
I0219 10:58:22.763642       1 controller.go:89] "enabled controllers: [certificaterequests-approver certificaterequests-issuer-acme certificaterequests-issuer-ca certificaterequests-issuer-selfsigned certificaterequests-issuer -vault certificaterequests-issuer-venafi certificates-issuing certificates-key-manager certificates-metrics certificates-readiness certificates-request-manager certificates-revision-manager certificates-trigger challenges clus terissuers ingress-shim issuers orders]" logger="cert-manager.controller"
{"ts":1708340302771.8833,"caller":"leaderelection/leaderelection.go:250","msg":"attempting to acquire leader lease kube-system/cert-manager-controller...","v":0}
{"ts":1708340328661.3528,"caller":"leaderelection/leaderelection.go:260","msg":"successfully acquired lease kube-system/cert-manager-controller","v":0}
{"ts":1708340328699.108,"caller":"cache/reflector.go:351","msg":"Caches populated for *v1.PartialObjectMetadata from k8s.io/client-go@v0.29.0/tools/cache/reflector.go:229","v":2}
{"ts":1708340328699.2065,"caller":"cache/reflector.go:351","msg":"Caches populated for *v1.PartialObjectMetadata from k8s.io/client-go@v0.29.0/tools/cache/reflector.go:229","v":2}
{"ts":1708340328700.8635,"caller":"cache/reflector.go:351","msg":"Caches populated for *v1.PartialObjectMetadata from k8s.io/client-go@v0.29.0/tools/cache/reflector.go:229","v":2}
{"ts":1708340328701.0466,"caller":"cache/reflector.go:351","msg":"Caches populated for *v1.Certificate from k8s.io/client-go@v0.29.0/tools/cache/reflector.go:229","v":2}
{"ts":1708340328701.29,"caller":"cache/reflector.go:351","msg":"Caches populated for *v1.Ingress from k8s.io/client-go@v0.29.0/tools/cache/reflector.go:229","v":2}
{"ts":1708340328701.3655,"caller":"cache/reflector.go:351","msg":"Caches populated for *v1.Secret from k8s.io/client-go@v0.29.0/tools/cache/reflector.go:229","v":2}
{"ts":1708340328758.724,"caller":"cache/reflector.go:351","msg":"Caches populated for *v1.ClusterIssuer from k8s.io/client-go@v0.29.0/tools/cache/reflector.go:229","v":2}
{"ts":1708340328818.2126,"caller":"cache/reflector.go:351","msg":"Caches populated for *v1.Issuer from k8s.io/client-go@v0.29.0/tools/cache/reflector.go:229","v":2}
{"ts":1708340328876.8904,"caller":"cache/reflector.go:351","msg":"Caches populated for *v1.Order from k8s.io/client-go@v0.29.0/tools/cache/reflector.go:229","v":2}
I0219 10:58:48.877465       1 util.go:83] "owning resource not found in cache" logger="cert-manager.controller.certificaterequests-issuer-acme.handleOwnedResource" resource_name="<REDACTED>" resource_namespace="<REDACTED>" resource_kind="Order" resource_version="v1" related_resource_namespace="<REDACTED>" related_resource_name="<REDACTED>" related_resource_kind="CertificateRequest"
{"ts":1708340328930.5337,"caller":"cache/reflector.go:351","msg":"Caches populated for *v1.Challenge from k8s.io/client-go@v0.29.0/tools/cache/reflector.go:229","v":2}
{"ts":1708340328996.188,"caller":"cache/reflector.go:351","msg":"Caches populated for *v1.CertificateRequest from k8s.io/client-go@v0.29.0/tools/cache/reflector.go:229","v":2}

cainjector

I0219 10:58:22.870384       1 setup.go:119] "Registering a reconciler for injectable" logger="cert-manager" kind="mutatingwebhookconfiguration"
I0219 10:58:22.872008       1 setup.go:119] "Registering a reconciler for injectable" logger="cert-manager" kind="validatingwebhookconfiguration"
I0219 10:58:22.872043       1 setup.go:119] "Registering a reconciler for injectable" logger="cert-manager" kind="apiservice"
I0219 10:58:22.873407       1 setup.go:119] "Registering a reconciler for injectable" logger="cert-manager" kind="customresourcedefinition"
{"ts":1708340302881.5186,"caller":"cache/reflector.go:351","msg":"Caches populated for *v1.APIService from k8s.io/client-go@v0.29.0/tools/cache/reflector.go:229","v":2}
{"ts":1708340302882.498,"caller":"cache/reflector.go:351","msg":"Caches populated for *v1.ValidatingWebhookConfiguration from k8s.io/client-go@v0.29.0/tools/cache/reflector.go:229","v":2}
{"ts":1708340302882.6836,"caller":"cache/reflector.go:351","msg":"Caches populated for *v1.MutatingWebhookConfiguration from k8s.io/client-go@v0.29.0/tools/cache/reflector.go:229","v":2}
{"ts":1708340303044.084,"caller":"cache/reflector.go:351","msg":"Caches populated for *v1.CustomResourceDefinition from k8s.io/client-go@v0.29.0/tools/cache/reflector.go:229","v":2}
I0219 10:58:23.073982       1 controller.go:178] "Starting EventSource" logger="cert-manager" controller="mutatingwebhookconfiguration" controllerGroup="admissionregistration.k8s.io" controllerKind="MutatingWebhookConfiguratio
I0219 10:58:23.074052       1 controller.go:178] "Starting EventSource" logger="cert-manager" controller="mutatingwebhookconfiguration" controllerGroup="admissionregistration.k8s.io" controllerKind="MutatingWebhookConfiguratio
I0219 10:58:23.074073       1 controller.go:178] "Starting EventSource" logger="cert-manager" controller="mutatingwebhookconfiguration" controllerGroup="admissionregistration.k8s.io" controllerKind="MutatingWebhookConfiguratio
I0219 10:58:23.074054       1 controller.go:178] "Starting EventSource" logger="cert-manager" controller="validatingwebhookconfiguration" controllerGroup="admissionregistration.k8s.io" controllerKind="ValidatingWebhookConfigur
I0219 10:58:23.074086       1 controller.go:178] "Starting EventSource" logger="cert-manager" controller="mutatingwebhookconfiguration" controllerGroup="admissionregistration.k8s.io" controllerKind="MutatingWebhookConfiguratio
I0219 10:58:23.074095       1 controller.go:178] "Starting EventSource" logger="cert-manager" controller="validatingwebhookconfiguration" controllerGroup="admissionregistration.k8s.io" controllerKind="ValidatingWebhookConfigur
I0219 10:58:23.074098       1 controller.go:186] "Starting Controller" logger="cert-manager" controller="mutatingwebhookconfiguration" controllerGroup="admissionregistration.k8s.io" controllerKind="MutatingWebhookConfiguration
I0219 10:58:23.074108       1 controller.go:178] "Starting EventSource" logger="cert-manager" controller="validatingwebhookconfiguration" controllerGroup="admissionregistration.k8s.io" controllerKind="ValidatingWebhookConfigur
I0219 10:58:23.074203       1 controller.go:178] "Starting EventSource" logger="cert-manager" controller="validatingwebhookconfiguration" controllerGroup="admissionregistration.k8s.io" controllerKind="ValidatingWebhookConfigur
I0219 10:58:23.074235       1 controller.go:186] "Starting Controller" logger="cert-manager" controller="validatingwebhookconfiguration" controllerGroup="admissionregistration.k8s.io" controllerKind="ValidatingWebhookConfigura
I0219 10:58:23.074225       1 controller.go:178] "Starting EventSource" logger="cert-manager" controller="apiservice" controllerGroup="apiregistration.k8s.io" controllerKind="APIService" source="kind source: *v1.APIService"
I0219 10:58:23.074256       1 controller.go:178] "Starting EventSource" logger="cert-manager" controller="apiservice" controllerGroup="apiregistration.k8s.io" controllerKind="APIService" source="kind source: *v1.Secret"
I0219 10:58:23.074266       1 controller.go:178] "Starting EventSource" logger="cert-manager" controller="apiservice" controllerGroup="apiregistration.k8s.io" controllerKind="APIService" source="kind source: *v1.Secret"
I0219 10:58:23.074271       1 controller.go:178] "Starting EventSource" logger="cert-manager" controller="customresourcedefinition" controllerGroup="apiextensions.k8s.io" controllerKind="CustomResourceDefinition" source="kind
I0219 10:58:23.074287       1 controller.go:178] "Starting EventSource" logger="cert-manager" controller="customresourcedefinition" controllerGroup="apiextensions.k8s.io" controllerKind="CustomResourceDefinition" source="kind
I0219 10:58:23.074297       1 controller.go:178] "Starting EventSource" logger="cert-manager" controller="customresourcedefinition" controllerGroup="apiextensions.k8s.io" controllerKind="CustomResourceDefinition" source="kind
I0219 10:58:23.074313       1 controller.go:178] "Starting EventSource" logger="cert-manager" controller="customresourcedefinition" controllerGroup="apiextensions.k8s.io" controllerKind="CustomResourceDefinition" source="kind
I0219 10:58:23.074322       1 controller.go:186] "Starting Controller" logger="cert-manager" controller="customresourcedefinition" controllerGroup="apiextensions.k8s.io" controllerKind="CustomResourceDefinition"
I0219 10:58:23.074277       1 controller.go:178] "Starting EventSource" logger="cert-manager" controller="apiservice" controllerGroup="apiregistration.k8s.io" controllerKind="APIService" source="kind source: *v1.Certificate"
I0219 10:58:23.074349       1 controller.go:186] "Starting Controller" logger="cert-manager" controller="apiservice" controllerGroup="apiregistration.k8s.io" controllerKind="APIService"
{"ts":1708340303080.0151,"caller":"cache/reflector.go:351","msg":"Caches populated for *v1.Certificate from k8s.io/client-go@v0.29.0/tools/cache/reflector.go:229","v":2}
{"ts":1708340303116.9106,"caller":"cache/reflector.go:351","msg":"Caches populated for *v1.Secret from k8s.io/client-go@v0.29.0/tools/cache/reflector.go:229","v":2}
I0219 10:58:23.181669       1 controller.go:220] "Starting workers" logger="cert-manager" controller="customresourcedefinition" controllerGroup="apiextensions.k8s.io" controllerKind="CustomResourceDefinition" worker count=1
I0219 10:58:23.188864       1 controller.go:220] "Starting workers" logger="cert-manager" controller="mutatingwebhookconfiguration" controllerGroup="admissionregistration.k8s.io" controllerKind="MutatingWebhookConfiguration" w
I0219 10:58:23.189484       1 controller.go:220] "Starting workers" logger="cert-manager" controller="apiservice" controllerGroup="apiregistration.k8s.io" controllerKind="APIService" worker count=1
I0219 10:58:23.189831       1 controller.go:220] "Starting workers" logger="cert-manager" controller="validatingwebhookconfiguration" controllerGroup="admissionregistration.k8s.io" controllerKind="ValidatingWebhookConfiguratio

webhook

{"ts":1708340302694.3489,"caller":"clientcmd/client_config.go:618","msg":"Neither --kubeconfig nor --master was specified.  Using the inClusterConfig.  This might not work.","v":0}
{"ts":1708340302768.8542,"caller":"cache/reflector.go:351","msg":"Caches populated for *v1.Secret from k8s.io/client-go@v0.29.0/tools/cache/reflector.go:229","v":2}

Expected behaviour:
All log output should be formatted with json.

Steps to reproduce the bug:

• Install cert-manager v1.14.0 into a k8s cluster with --logging-format=json enabled.
• Get the logs from the three installed pods.

Anything else we need to know?:
The problem was gone in v1.13.3 but reappears in v1.14.0. and up to latest (v1.14.2)

Environment details::

• Kubernetes version: v1.27.7
• Cloud-provider/provisioner: AKS
• cert-manager version: v1.14.2
• Install method: helm

/kind bug

[inteon]

@petermajn could you provide a (redacted) example of this output?
There might be some libraries/ part of the code that use incorrect logging logic, but we need example output to be able to debug this issue.

[petermajn]

Yes I can, but first have to switch to v1.14.0 again first, since we are using v1.13.3 at the moment. I will update the issue once I have some examples.

[inteon]

Ok, make sure to use v1.14.2 since there are known issues with v1.14.0 that have been fixed in v1.14.2 (see release notes: https://github.com/cert-manager/cert-manager/releases/tag/v1.14.2).

[petermajn]

@inteon I updated the issue with example log outputs.