search

kedacore / keda

KEDA is a Kubernetes-based Event Driven Autoscaling component. It provides event driven scale for any container running in Kubernetes
https://keda.sh
Apache License 2.0
8.57k stars 1.08k forks source link

Date at keda operator logs not in correct format #3655

Closed fraozy closed 1 year ago

fraozy commented 2 years ago

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 commented 2 years ago

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) image

stale[bot] commented 2 years ago

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 commented 2 years ago

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 commented 2 years ago

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

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 commented 2 years ago

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

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

JorTurFer commented 2 years ago

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 commented 2 years ago

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 commented 2 years ago

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

naseemkullah commented 1 year ago

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?