Keda: MySQL connections not closed

[TBeijen]

Report

While experimenting with Keda ScaledObject using a MySQL trigger, we notice the number of connections to our MySQL database increasing indefintely. In an autoscaling cluster (AWS RDS Aurora) at some point we had 15 x ~600 connections. This was using Keda v2.0.0

Upgrading to Keda v2.1.0, hoping that #1416 would fix it, shows a slower ramp-up of connections, but the problem still exists.

Findings:

• Removing the ScaledObject stops the ramp-up.
• Number of connections drops to normal only after

DB Engine: 5.6.mysql_aurora.1.22.2

This is probably related to #1121

Please let me know if I can help out by providing additional info or run variations of the above tests.

Expected Behavior

A more or less constant number of connections to the MySQL database.

Actual Behavior

Number of connections continuously rising to the point where DB refuses new connections. Connections only closed after restarting Keda operator and metrics-apiserver.

Steps to Reproduce the Problem

1. Setup a ScaledObject similar to the one below
2. Observe DB conections ramping up

Part of the ScaledObject (slightly redacted):

spec:
  cooldownPeriod: 30
  maxReplicaCount: 80
  minReplicaCount: 4
  pollingInterval: 2
  scaleTargetRef:
    apiVersion: apps/v1
    kind: Deployment
    name: keda-poc-app
  triggers:
  - metadata:
      type: Utilization
      value: "70"
    type: cpu
  - authenticationRef:
      name: keda-poc-app
    metadata:
      dbName: redacted
      host: redacted
      port: "3306"
      query: redacted
      queryValue: "1"
      username: redacted
    type: mysql
 ```

**Logs from KEDA operator**

Repeating pattern. Nothing directly standing out.

keda-operator-778c759c5b-4qzrk keda-operator 2021-02-26T06:13:22.034Z DEBUG scalehandler Scaler for scaledObject is active {"Metrics Name": "cpu"}
keda-operator-metrics-apiserver-5b5c844d46-crqk4 keda-operator-metrics-apiserver I0226 06:13:23.279898 1 httplog.go:89] "HTTP" verb="GET" URI="/apis/external.metrics.k8s.io/v1beta1?timeout=32s" latency="9.262103ms" userAgent="kube-controller-manager/v1.16.15 (linux/amd64) kubernetes/ad4801f/controller-discovery" srcIP="10.12.131.84:43894" resp=200
keda-operator-metrics-apiserver-5b5c844d46-crqk4 keda-operator-metrics-apiserver I0226 06:13:23.827481 1 reflector.go:255] Listing and watching *v1.ConfigMap from pkg/mod/k8s.io/[email protected]/tools/cache/reflector.go:167
keda-operator-metrics-apiserver-5b5c844d46-crqk4 keda-operator-metrics-apiserver I0226 06:13:23.983352 1 provider.go:58] keda_metrics_adapter/provider "msg"="Keda provider received request for external metrics" "metric name"="mysql-test" "metricSelector"="scaledObjectName=keda-poc-app" "namespace"="keda-test-poc"
keda-operator-metrics-apiserver-5b5c844d46-crqk4 keda-operator-metrics-apiserver I0226 06:13:24.050321 1 httplog.go:89] "HTTP" verb="GET" URI="/apis/external.metrics.k8s.io/v1beta1/namespaces/keda-test-poc/mysql-test?labelSelector=scaledObjectName%3Dkeda-poc-app" latency="69.094251ms" userAgent="kube-controller-manager/v1.16.15 (linux/amd64) kubernetes/ad4801f/system:serviceaccount:kube-system:horizontal-pod-autoscaler" srcIP="10.12.131.84:43894" resp=200
keda-operator-778c759c5b-4qzrk keda-operator 2021-02-26T06:13:24.051Z DEBUG scalehandler Scaler for scaledObject is active {"Metrics Name": "cpu"}
keda-operator-778c759c5b-4qzrk keda-operator 2021-02-26T06:13:24.083Z INFO controllers.ScaledObject Reconciling ScaledObject {"ScaledObject.Namespace": "keda-test-poc", "ScaledObject.Name": "keda-poc-app"}
keda-operator-778c759c5b-4qzrk keda-operator 2021-02-26T06:13:24.083Z DEBUG controllers.ScaledObject Parsed Group, Version, Kind, Resource {"ScaledObject.Namespace": "keda-test-poc", "ScaledObject.Name": "keda-poc-app", "GVK": "apps/v1.Deployment", "Resource": "deployments"}
keda-operator-778c759c5b-4qzrk keda-operator 2021-02-26T06:13:24.089Z DEBUG controllers.ScaledObject All metric names are unique in ScaledObject {"ScaledObject.Namespace": "keda-test-poc", "ScaledObject.Name": "keda-poc-app", "value": "keda-poc-app"}
keda-operator-778c759c5b-4qzrk keda-operator 2021-02-26T06:13:24.116Z DEBUG controllers.ScaledObject ScaledObject is defined correctly and is ready for scaling {"ScaledObject.Namespace": "keda-test-poc", "ScaledObject.Name": "keda-poc-app"}
keda-operator-778c759c5b-4qzrk keda-operator 2021-02-26T06:13:24.127Z DEBUG controller Successfully Reconciled {"reconcilerGroup": "keda.sh", "reconcilerKind": "ScaledObject", "controller": "scaledobject", "name": "keda-poc-app", "namespace": "keda-test-poc"}
keda-operator-metrics-apiserver-5b5c844d46-crqk4 keda-operator-metrics-apiserver I0226 06:13:25.690202 1 httplog.go:89] "HTTP" verb="GET" URI="/apis/external.metrics.k8s.io/v1beta1?timeout=32s" latency="7.423119ms" userAgent="aws-k8s-agent/v0.0.0 (linux/amd64) kubernetes/$Format" srcIP="10.12.53.109:38612" resp=200
keda-operator-metrics-apiserver-5b5c844d46-crqk4 keda-operator-metrics-apiserver I0226 06:13:25.978768 1 httplog.go:89] "HTTP" verb="GET" URI="/apis/external.metrics.k8s.io/v1beta1?timeout=32s" latency="4.634897ms" userAgent="aws-k8s-agent/v0.0.0 (linux/amd64) kubernetes/$Format" srcIP="10.12.131.84:43894" resp=200
keda-operator-778c759c5b-4qzrk keda-operator 2021-02-26T06:13:26.105Z DEBUG scalehandler Scaler for scaledObject is active {"Metrics Name": "cpu"}
keda-operator-metrics-apiserver-5b5c844d46-crqk4 keda-operator-metrics-apiserver I0226 06:13:27.921845 1 httplog.go:89] "HTTP" verb="GET" URI="/healthz" latency="1.33484ms" userAgent="kube-probe/1.16+" srcIP="10.12.177.230:58552" resp=200
keda-operator-778c759c5b-4qzrk keda-operator 2021-02-26T06:13:28.120Z DEBUG scalehandler Scaler for scaledObject is active {"Metrics Name": "cpu"}
keda-operator-778c759c5b-4qzrk keda-operator 2021-02-26T06:13:30.169Z DEBUG scalehandler Scaler for scaledObject is active {"Metrics Name": "cpu"}
keda-operator-metrics-apiserver-5b5c844d46-crqk4 keda-operator-metrics-apiserver I0226 06:13:30.624180 1 httplog.go:89] "HTTP" verb="GET" URI="/apis/external.metrics.k8s.io/v1beta1" latency="5.574186ms" userAgent="Go-http-client/2.0" srcIP="10.12.131.84:43880" resp=200
keda-operator-metrics-apiserver-5b5c844d46-crqk4 keda-operator-metrics-apiserver I0226 06:13:30.625179 1 httplog.go:89] "HTTP" verb="GET" URI="/apis/external.metrics.k8s.io/v1beta1" latency="6.597384ms" userAgent="Go-http-client/2.0" srcIP="10.12.131.84:43880" resp=200
keda-operator-metrics-apiserver-5b5c844d46-crqk4 keda-operator-metrics-apiserver I0226 06:13:30.625922 1 httplog.go:89] "HTTP" verb="GET" URI="/apis/external.metrics.k8s.io/v1beta1" latency="7.329299ms" userAgent="Go-http-client/2.0" srcIP="10.12.131.84:43880" resp=200
keda-operator-metrics-apiserver-5b5c844d46-crqk4 keda-operator-metrics-apiserver I0226 06:13:30.625922 1 httplog.go:89] "HTTP" verb="GET" URI="/apis/external.metrics.k8s.io/v1beta1" latency="6.770291ms" userAgent="Go-http-client/2.0" srcIP="10.12.131.84:43880" resp=200
keda-operator-metrics-apiserver-5b5c844d46-crqk4 keda-operator-metrics-apiserver I0226 06:13:30.627016 1 httplog.go:89] "HTTP" verb="GET" URI="/apis/external.metrics.k8s.io/v1beta1" latency="7.553739ms" userAgent="Go-http-client/2.0" srcIP="10.12.131.84:43880" resp=200
keda-operator-metrics-apiserver-5b5c844d46-crqk4 keda-operator-metrics-apiserver I0226 06:13:30.904230 1 httplog.go:89] "HTTP" verb="GET" URI="/apis/external.metrics.k8s.io/v1beta1?timeout=32s" latency="4.970282ms" userAgent="aws-k8s-agent/v0.0.0 (linux/amd64) kubernetes/$Format" srcIP="10.12.131.84:43894" resp=200
keda-operator-metrics-apiserver-5b5c844d46-crqk4 keda-operator-metrics-apiserver I0226 06:13:31.654194 1 httplog.go:89] "HTTP" verb="GET" URI="/readyz" latency="590.076µs" userAgent="kube-probe/1.16+" srcIP="10.12.177.230:58624" resp=200
keda-operator-778c759c5b-4qzrk keda-operator 2021-02-26T06:13:32.201Z DEBUG scalehandler Scaler for scaledObject is active {"Metrics Name": "cpu"}
keda-operator-metrics-apiserver-5b5c844d46-crqk4 keda-operator-metrics-apiserver I0226 06:13:33.082674 1 httplog.go:89] "HTTP" verb="GET" URI="/apis/external.metrics.k8s.io/v1beta1?timeout=32s" latency="5.631432ms" userAgent="helm/v0.0.0 (linux/amd64) kubernetes/$Format" srcIP="10.12.53.109:38612" resp=200
keda-operator-metrics-apiserver-5b5c844d46-crqk4 keda-operator-metrics-apiserver I0226 06:13:33.829582 1 reflector.go:530] pkg/mod/k8s.io/[email protected]/tools/cache/reflector.go:167: Watch close - *v1.ConfigMap total 0 items received
keda-operator-778c759c5b-4qzrk keda-operator 2021-02-26T06:13:34.247Z DEBUG scalehandler Scaler for scaledObject is active {"Metrics Name": "cpu"}
keda-operator-778c759c5b-4qzrk keda-operator 2021-02-26T06:13:36.303Z DEBUG scalehandler Scaler for scaledObject is active {"Metrics Name": "cpu"}
keda-operator-metrics-apiserver-5b5c844d46-crqk4 keda-operator-metrics-apiserver I0226 06:13:37.925462 1 httplog.go:89] "HTTP" verb="GET" URI="/healthz" latency="4.704785ms" userAgent="kube-probe/1.16+" srcIP="10.12.177.230:58736" resp=200
keda-operator-metrics-apiserver-5b5c844d46-crqk4 keda-operator-metrics-apiserver I0226 06:13:38.122671 1 httplog.go:89] "HTTP" verb="GET" URI="/apis/external.metrics.k8s.io/v1beta1?timeout=32s" latency="4.94343ms" userAgent="helm/v0.0.0 (linux/amd64) kubernetes/$Format" srcIP="10.12.53.109:38612" resp=200
keda-operator-778c759c5b-4qzrk keda-operator 2021-02-26T06:13:38.317Z DEBUG scalehandler Scaler for scaledObject is active {"Metrics Name": "cpu"}
```

KEDA Version

2.1.0

Kubernetes Version

1.16

Platform

Amazon Web Services

Scaler Details

mysql

---

DB connections (drop is after restarting Keda components):

[ycabrer]

I think this one is my bad. The scalers are not being closed after validating the names.

@zroubalik What do you think?

https://github.com/kedacore/keda/blob/aac70e69cfb627f4addb1b8260df6599e8994c8c/controllers/scaledobject_controller.go#L255

[zroubalik]

@ycabrer yeah, seems like this is the root of the problem. I am glad we have (hopefully) found the problem quickly :)

[dan-leanix]

@ycabrer @zroubalik We observed the same issue this night with a Postgres database and KEDA version 2.1.0.

When we will have the fix available in a new KEDA version?

[zroubalik]

@dan-leanix we will discuss 2.2 release on a call next Tuesday, if everything is fine, we will release that week 🤞

[dan-leanix]

@zroubalik Thanks!

[mlushpenko]

+1 here, here's what happenned when I've restarted keda-operator that was running postgresql scaler:

Seems like you need to add defer s.Close() here

Is it already in progress or shall I create a PR for that?

UPDATE: same for MySQL scaler here. Close() method is there but never used

[zroubalik]

Seems like you need to add defer s.Close() here

Is it already in progress or shall I create a PR for that?

UPDATE: same for MySQL scaler here. Close() method is there but never used

@mlushpenko Close() method is not called from within the individual scalers, so that's why you don't see that in the particular scaler.

This merged PR should fix this issue: https://github.com/kedacore/keda/pull/1640

Previously there was a code, which initialized scalers but didn't close the connections, now the code is being moved to a location where the connections are closed.

[mlushpenko]

Thanks a lot for your answer, I've deleted one of my comments after re-reading the code, but an extra explanation is always useful. Very eager for the fix - the last obstacle before deploying keda to our production clusters.

[zroubalik]

@mlushpenko Glad to hear that!

[dan-leanix]

@dan-leanix we will discuss 2.2 release on a call next Tuesday, if everything is fine, we will release that week 🤞

@zroubalik Any news if 2.2 gets released this week?

[zroubalik]

@dan-leanix if everything will be fine, we are going to release on Thursday 🤞 😄

[mlushpenko]

@zroubalik thanks for releasing, was running it over the weekend and connections seem stable.

[zroubalik]

@mlushpenko glad to hear that! Thanks for the feedback, closing this issue.