Date at keda operator logs not in correct format

[fraozy]

Report

The keda-operator show logs with incorrect LEVEL TIME format. Example:

1.662668042543773e+09     INFO    controller.scaledobject    Reconciling ScaledObject    {"reconciler group": "keda.sh", "reconciler kind": "ScaledObject", "name": "******", "namespace": "*******"
1.6626680425687835e+09    INFO    controller.scaledobject    Updated HPA according to ScaledObject    {"reconciler group": "keda.sh", "reconciler kind": "ScaledObject", "name": "***********"

This is preventing the monitoring tool to correctly identify the error level at log message. The error was not happening at previous version used, KEDA version 2.5.0

Expected Behavior

The date/time should be in the correct format, like :

**2021-12-03T14:13:13.552Z**	INFO	controller.scaledobject	Updated HPA according to ScaledObject	{"reconciler group": "keda.sh", "reconciler kind": "ScaledObject", "name": "bundle-homematicip", "namespace": "adapters", "HPA.Namespace": "adapters", "HPA.Name": "keda-hpa-bundle-homematicip"}

Actual Behavior

All the logs at keda-operator are been displayed with incorrect date/time.

root@CA1NB7943:~# kubectl -n infrastructure logs keda-operator-6bb8bf9b9c-xk2rs
1.6625559614358394e+09  INFO    controller-runtime.metrics      Metrics server is starting to listen    {"addr": ":8080"}
1.6625559614384465e+09  INFO    setup   Running on Kubernetes 1.23      {"version": "v1.23.8"}
1.662555961438585e+09   INFO    setup   Starting manager
1.6625559614385962e+09  INFO    setup   KEDA Version: 2.7.0
1.6625559614385996e+09  INFO    setup   Git Commit: 5f8af5cd90805d8b9c5964e1619a8b2bdcec6cfd
1.6625559614386022e+09  INFO    setup   Go Version: go1.17.3
1.6625559614386048e+09  INFO    setup   Go OS/Arch: linux/amd64
1.662555961438811e+09   INFO    Starting server {"path": "/metrics", "kind": "metrics", "addr": "[::]:8080"}
1.6625559614388692e+09  INFO    Starting server {"kind": "health probe", "addr": "[::]:8081"}
I0907 13:06:01.438904       1 leaderelection.go:248] attempting to acquire leader lease infrastructure/operator.keda.sh...
I0907 13:06:16.947296       1 leaderelection.go:258] successfully acquired lease infrastructure/operator.keda.sh
1.6625559769475043e+09  INFO    controller.scaledobject Starting EventSource    {"reconciler group": "keda.sh", "reconciler kind": "ScaledObject", "source": "kind source: *v1alpha1.ScaledObject"}
1.6625559769475174e+09  INFO    controller.triggerauthentication        Starting EventSource    {"reconciler group": "keda.sh", "reconciler kind": "TriggerAuthentication", "source": "kind source: *v1alpha1.TriggerAuthentication"}
1.6625559769475572e+09  INFO    controller.scaledjob    Starting EventSource    {"reconciler group": "keda.sh", "reconciler kind": "ScaledJob", "source": "kind source: *v1alpha1.ScaledJob"}
1.66255597694759e+09    INFO    controller.triggerauthentication        Starting Controller     {"reconciler group": "keda.sh", "reconciler kind": "TriggerAuthentication"}
1.662555976947594e+09   INFO    controller.scaledjob    Starting Controller     {"reconciler group": "keda.sh", "reconciler kind": "ScaledJob"}
1.6625559769475746e+09  INFO    controller.scaledobject Starting EventSource    {"reconciler group": "keda.sh", "reconciler kind": "ScaledObject", "source": "kind source: *v2beta2.HorizontalPodAutoscaler"}
1.662555976947647e+09   INFO    controller.scaledobject Starting Controller     {"reconciler group": "keda.sh", "reconciler kind": "ScaledObject"}
1.6625559769476047e+09  INFO    controller.clustertriggerauthentication Starting EventSource    {"reconciler group": "keda.sh", "reconciler kind": "ClusterTriggerAuthentication", "source": "kind source: *v1alpha1.ClusterTriggerAuthentication"}
1.6625559769483132e+09  INFO    controller.clustertriggerauthentication Starting Controller     {"reconciler group": "keda.sh", "reconciler kind": "ClusterTriggerAuthentication"}
1.6625559769545043e+09  INFO    KubeAPIWarningLogger    autoscaling/v2beta2 HorizontalPodAutoscaler is deprecated in v1.23+, unavailable in v1.26+; use autoscaling/v2 HorizontalPodAutoscaler
1.6625559770487144e+09  INFO    controller.scaledobject Starting workers        {"reconciler group": "keda.sh", "reconciler kind": "ScaledObject", "worker count": 5}
1.6625559770488298e+09  INFO    controller.triggerauthentication        Starting workers        {"reconciler group": "keda.sh", "reconciler kind": "TriggerAuthentication", "worker count": 1}
1.6625559770489316e+09  INFO    controller.scaledjob    Starting workers        {"reconciler group": "keda.sh", "reconciler kind": "ScaledJob", "worker count": 1}
1.662555977049954e+09   INFO    controller.clustertriggerauthentication Starting workers        {"reconciler group": "keda.sh", "reconciler kind": "ClusterTriggerAuthentication", "worker count": 1}

Steps to Reproduce the Problem

Just check the logs from keda-operator

Logs from KEDA operator

root@CA1NB7943:~# kubectl -n infrastructure logs keda-operator-6bb8bf9b9c-xk2rs
1.6625559614358394e+09  INFO    controller-runtime.metrics      Metrics server is starting to listen    {"addr": ":8080"}
1.6625559614384465e+09  INFO    setup   Running on Kubernetes 1.23      {"version": "v1.23.8"}
1.662555961438585e+09   INFO    setup   Starting manager
1.6625559614385962e+09  INFO    setup   KEDA Version: 2.7.0
1.6625559614385996e+09  INFO    setup   Git Commit: 5f8af5cd90805d8b9c5964e1619a8b2bdcec6cfd
1.6625559614386022e+09  INFO    setup   Go Version: go1.17.3
1.6625559614386048e+09  INFO    setup   Go OS/Arch: linux/amd64
1.662555961438811e+09   INFO    Starting server {"path": "/metrics", "kind": "metrics", "addr": "[::]:8080"}
1.6625559614388692e+09  INFO    Starting server {"kind": "health probe", "addr": "[::]:8081"}
I0907 13:06:01.438904       1 leaderelection.go:248] attempting to acquire leader lease infrastructure/operator.keda.sh...
I0907 13:06:16.947296       1 leaderelection.go:258] successfully acquired lease infrastructure/operator.keda.sh
1.6625559769475043e+09  INFO    controller.scaledobject Starting EventSource    {"reconciler group": "keda.sh", "reconciler kind": "ScaledObject", "source": "kind source: *v1alpha1.ScaledObject"}
1.6625559769475174e+09  INFO    controller.triggerauthentication        Starting EventSource    {"reconciler group": "keda.sh", "reconciler kind": "TriggerAuthentication", "source": "kind source: *v1alpha1.TriggerAuthentication"}
1.6625559769475572e+09  INFO    controller.scaledjob    Starting EventSource    {"reconciler group": "keda.sh", "reconciler kind": "ScaledJob", "source": "kind source: *v1alpha1.ScaledJob"}
1.66255597694759e+09    INFO    controller.triggerauthentication        Starting Controller     {"reconciler group": "keda.sh", "reconciler kind": "TriggerAuthentication"}
1.662555976947594e+09   INFO    controller.scaledjob    Starting Controller     {"reconciler group": "keda.sh", "reconciler kind": "ScaledJob"}
1.6625559769475746e+09  INFO    controller.scaledobject Starting EventSource    {"reconciler group": "keda.sh", "reconciler kind": "ScaledObject", "source": "kind source: *v2beta2.HorizontalPodAutoscaler"}
1.662555976947647e+09   INFO    controller.scaledobject Starting Controller     {"reconciler group": "keda.sh", "reconciler kind": "ScaledObject"}
1.6625559769476047e+09  INFO    controller.clustertriggerauthentication Starting EventSource    {"reconciler group": "keda.sh", "reconciler kind": "ClusterTriggerAuthentication", "source": "kind source: *v1alpha1.ClusterTriggerAuthentication"}
1.6625559769483132e+09  INFO    controller.clustertriggerauthentication Starting Controller     {"reconciler group": "keda.sh", "reconciler kind": "ClusterTriggerAuthentication"}
1.6625559769545043e+09  INFO    KubeAPIWarningLogger    autoscaling/v2beta2 HorizontalPodAutoscaler is deprecated in v1.23+, unavailable in v1.26+; use autoscaling/v2 HorizontalPodAutoscaler
1.6625559770487144e+09  INFO    controller.scaledobject Starting workers        {"reconciler group": "keda.sh", "reconciler kind": "ScaledObject", "worker count": 5}
1.6625559770488298e+09  INFO    controller.triggerauthentication        Starting workers        {"reconciler group": "keda.sh", "reconciler kind": "TriggerAuthentication", "worker count": 1}
1.6625559770489316e+09  INFO    controller.scaledjob    Starting workers        {"reconciler group": "keda.sh", "reconciler kind": "ScaledJob", "worker count": 1}
1.662555977049954e+09   INFO    controller.clustertriggerauthentication Starting workers        {"reconciler group": "keda.sh", "reconciler kind": "ClusterTriggerAuthentication", "worker count": 1}

KEDA Version

2.7.1

Kubernetes Version

1.22

Platform

Microsoft Azure

Scaler Details

Azure Service Bus

Anything else?

No response

[JorTurFer]

hey,
Could you check if the operator receives these parameters?

- '--zap-log-level=info'
- '--zap-encoder=console'
- '--zap-time-encoding=rfc3339'

This is how it should look (ignoring that I'm using my own registry)

[stale]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed in 7 days if no further activity occurs. Thank you for your contributions.

[SocalNick]

We're observing the same behavior:

1. We deploy keda via a terraform helm_release.
2. We set logging.operator.format to json
3. The deployed keda-operator resources have --zap-encoder=json in the list of args
4. However, the logs are being emitted in what appears to be klog format

I noticed there's nothing in the kedakore/keda repo that seems to indicate the log format can be changed, other than the docs.

[JorTurFer]

Hey,
kedacode/keda doesn't say anything but you can find the available formats in helm values 😄

What do you mean as klog format? Do you mean the date? You can modify that format using the value logging.operator.timeEncoding, the value rfc3339 or rfc3339nano could match your requirements (default value is rfc3339 in chart atm).

[SocalNick]

Hi @JorTurFer - I'm saying that setting the logging.operator.format doesn't do anything because it's hardcoded to console in keda:

• keda/Dockerfile

  Line 38 in dab87b5

  ENTRYPOINT ["/keda", "--zap-log-level=info", "--zap-encoder=console"]

• keda/config/manager/manager.yaml

  Line 36 in dab87b5

  - --zap-encoder=console

Am I missing something on how we can get the logging.operator.format set to json to take effect?

[JorTurFer]

I can see that the chart overrides the command and uses provided values, so if you are using helm (I think so due to the parameter you sent), the value should be overwritten.
Could you check if your deployment has those values?

[SocalNick]

I'm very sorry @JorTurFer - I was looking at logs from the keda-operator-metrics-apiserver deployment. It seems that only has a level setting as opposed to the operator having level, format, and timeEncoding.

Our logs for keda-operator are correctly being emitted as JSON 🤦

[JorTurFer]

No worries at all, it happens.
Happy to see that the issue is solved :)

[naseemkullah]

I'm very sorry @JorTurFer - I was looking at logs from the keda-operator-metrics-apiserver deployment. It seems that only has a level setting as opposed to the operator having level, format, and timeEncoding.

Our logs for keda-operator are correctly being emitted as JSON 🤦

That said, I'd like to have the metrics-apiserver log in json format as well, primarily because all info logs are emitted to stderr and those show up as error logs in our logging system. Could this functionality please be added?