MySQL connections not closed #1636

TBeijen · 2021-02-26T09:06:51Z

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

Setup a ScaledObject similar to the one below
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/client-go@v0.20.2/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/client-go@v0.20.2/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):

The text was updated successfully, but these errors were encountered:

ycabrer · 2021-03-01T09:37:25Z

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

@zroubalik What do you think?

keda/controllers/scaledobject_controller.go

Line 255 in aac70e6

scalers, err := r.scaleHandler.GetScalers(scaledObject)

zroubalik · 2021-03-01T11:08:54Z

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

dan-leanix · 2021-03-09T07:54:24Z

@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 · 2021-03-09T09:03:20Z

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

dan-leanix · 2021-03-09T09:19:35Z

@zroubalik Thanks!

mlushpenko · 2021-03-09T12:31:31Z

+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 · 2021-03-12T14:31:42Z

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: #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 · 2021-03-12T17:07:10Z

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 · 2021-03-12T17:10:54Z

@mlushpenko Glad to hear that!

dan-leanix · 2021-03-17T09:43:28Z

@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 · 2021-03-17T09:51:47Z

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

mlushpenko · 2021-03-22T12:29:27Z

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

zroubalik · 2021-03-22T12:48:10Z

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

TBeijen added the bug Something isn't working label Feb 26, 2021

ycabrer mentioned this issue Mar 1, 2021

Fix memory leak by checking triggers uniqueness properly #1640

Merged

2 tasks

zroubalik closed this as completed Mar 22, 2021

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

MySQL connections not closed #1636

MySQL connections not closed #1636

TBeijen commented Feb 26, 2021 •

edited

Loading

ycabrer commented Mar 1, 2021

zroubalik commented Mar 1, 2021

dan-leanix commented Mar 9, 2021

zroubalik commented Mar 9, 2021

dan-leanix commented Mar 9, 2021

mlushpenko commented Mar 9, 2021 •

edited

Loading

zroubalik commented Mar 12, 2021 •

edited

Loading

mlushpenko commented Mar 12, 2021

zroubalik commented Mar 12, 2021

dan-leanix commented Mar 17, 2021

zroubalik commented Mar 17, 2021

mlushpenko commented Mar 22, 2021

zroubalik commented Mar 22, 2021

MySQL connections not closed #1636

MySQL connections not closed #1636

Comments

TBeijen commented Feb 26, 2021 • edited Loading

ycabrer commented Mar 1, 2021

zroubalik commented Mar 1, 2021

dan-leanix commented Mar 9, 2021

zroubalik commented Mar 9, 2021

dan-leanix commented Mar 9, 2021

mlushpenko commented Mar 9, 2021 • edited Loading

zroubalik commented Mar 12, 2021 • edited Loading

mlushpenko commented Mar 12, 2021

zroubalik commented Mar 12, 2021

dan-leanix commented Mar 17, 2021

zroubalik commented Mar 17, 2021

mlushpenko commented Mar 22, 2021

zroubalik commented Mar 22, 2021

TBeijen commented Feb 26, 2021 •

edited

Loading

mlushpenko commented Mar 9, 2021 •

edited

Loading

zroubalik commented Mar 12, 2021 •

edited

Loading