Memory leak & haproxy.cfg stopped syncing

[aaronbbrown]

👋🏻 from GitHub

Today, we ran into an issue where the controller started began leaking memory and then stopped updating /etc/haproxy/haproxy.cfg leading to a situation where haproxy had an incorrect set of backends. Memory usage had a spike right around the time haproxy.cfg stopped updating and then kept slowly creeping up.

The light green line is the problematic Pod. Red is the CPU request, and the other lines are the other Pods from this Deployment of the ingress controller which were functioning normally.

Attached is an SVG flame graph of the process captured with perf several hours after the initial spike, while the memory was staircasing its way up as well as a stack trace captured by sending the process SIGQUIT.

• stacktrace.log
• controller.svg.gz

Kubernetes Deployment YAML

---
# Source: kubernetes-ingress/templates/controller-configmap.yaml
apiVersion: v1
kind: ConfigMap
metadata:
  name: ingress-unicorn-api-kubernetes-ingress
  namespace: haproxytech-ingress
  labels:
    addonmanager.kubernetes.io/mode: Reconcile
    app.kubernetes.io/name: kubernetes-ingress
    helm.sh/chart: kubernetes-ingress-1.14.2
    app.kubernetes.io/managed-by: Helm
    app.kubernetes.io/instance: ingress-unicorn-api
    app.kubernetes.io/version: 1.6.0
data:
  syslog-server: address:stdout, facility:daemon, format:raw, 
  nbthread: "1"
  timeout-client: 150s
  timeout-client-fin: 5s
  timeout-connect: 100ms
  timeout-queue: 90s
  timeout-server: 150s
  timeout-server-fin: 5s
  timeout-tunnel: 150s


---
# Source: kubernetes-ingress/templates/controller-deployment.yaml
apiVersion: apps/v1
kind: Deployment
metadata:
  name: ingress-unicorn-api-kubernetes-ingress
  namespace: haproxytech-ingress
  labels:
    addonmanager.kubernetes.io/mode: Reconcile
    app.kubernetes.io/name: kubernetes-ingress
    helm.sh/chart: kubernetes-ingress-1.14.2
    app.kubernetes.io/managed-by: Helm
    app.kubernetes.io/instance: ingress-unicorn-api
    app.kubernetes.io/version: 1.6.0
spec:
  replicas: 4
  selector:
    matchLabels:
      app.kubernetes.io/name: kubernetes-ingress
      app.kubernetes.io/instance: ingress-unicorn-api
  template:
    metadata:
      labels:
        app.kubernetes.io/name: kubernetes-ingress
        app.kubernetes.io/instance: ingress-unicorn-api
    spec:
      serviceAccountName: ingress-unicorn-api-kubernetes-ingress
      terminationGracePeriodSeconds: 60
      dnsPolicy: ClusterFirst
      priorityClassName: system-cluster-critical

      # The helm chart doesn't have a configurable for securityContext, so this is manually added
      securityContext:
        sysctls:
        - name: net.core.somaxconn
          value: "10240"
        - name: net.ipv4.tcp_tw_reuse
          value: "1"

      containers:
        - name: kubernetes-ingress-controller
          image: "haproxytech/kubernetes-ingress:1.6.0"
          imagePullPolicy: IfNotPresent
          args:
          - --configmap=haproxytech-ingress/ingress-unicorn-api-kubernetes-ingress
          - --ingress.class=haproxytech-unicorn-api
          - --publish-service=haproxytech-ingress/ingress-unicorn-api-kubernetes-ingress
          - --log=info
          - --configmap-tcp-services=haproxytech-ingress/tcpservices-unicorn-api
          - --disable-http
          - --disable-https
          - --disable-ipv6
          ports:
            - name: stat
              containerPort: 1024
              protocol: TCP
            - name: http-tcp
              containerPort: 8080
              protocol: TCP
          readinessProbe:
            failureThreshold: 3
            httpGet:
              path: /
              port: 1024
              scheme: HTTP
            initialDelaySeconds: 5
            periodSeconds: 10
            successThreshold: 1
            timeoutSeconds: 1
          startupProbe:
            failureThreshold: 20
            httpGet:
              path: /healthz
              port: 1042
              scheme: HTTP
            initialDelaySeconds: 0
            periodSeconds: 1
            successThreshold: 1
            timeoutSeconds: 1
          env:
          - name: POD_NAME
            valueFrom:
              fieldRef:
                fieldPath: metadata.name
          - name: POD_NAMESPACE
            valueFrom:
              fieldRef:
                fieldPath: metadata.namespace
          - name: GOMAXPROCS
            value: "1"
          resources:
            requests:
              cpu: 1
              memory: 256Mi
          lifecycle:
            preStop:
              exec:
                command:
                - /bin/sh
                - -c
                - sleep 5
      affinity:
        podAntiAffinity:
          requiredDuringSchedulingIgnoredDuringExecution:
          - labelSelector:
              matchExpressions:
              - key: app.kubernetes.io/name
                operator: In
                values:
                - kubernetes-ingress
            topologyKey: kubernetes.io/hostname

Versions:

• Ingress controller v1.6.0
• Kubernetes 1.20.2
• Kernel 4.19

❤️ for any help you can provide/suggestions. Happy to provide more information.

[Mo3m3n]

Hi
I have a couple of questions to better understand the context:

• Are you able to reproduce this ?
• Do you have logs for the failing pods ?
• Do you know if the memory issue was with the controller process or the haproxy one ?
  Thanks !

[aaronbbrown]

Thanks for the quick reply @Mo3m3n!

• Are you able to reproduce this ?

It has only happened once so far. I cannot reproduce it on demand and it took over 3 days of continuous running before it manifested.

• Do you have logs for the failing pods ?

Here are the ingress controller logs up until the point where everything failed. All logs stopped after that point.
haproxytech-ingress.log

• Do you know if the memory issue was with the controller process or the haproxy one ?

It was the haproxy-ingress-controller process. haproxy memory was normal.

[Mo3m3n]

Thanks @aaronbbrown
Unfortunately nothing really useful in the logs as we only have the last 143 lines where haproxy is telling that everything is going down :)
For now all I can do is run IC on a test cluster for a couple of days and monitor memory resources.
On your side what you can do is run the IC with -p arg to enable pprofendpoint at /debug/pprof so it would be useful to get information about golang memory allocations of the heap for example (curl -sK < IC-Endpoint >/debug/pprof/heap > heap.out) in the meantime I will try to make sense out of the provided perf flame graph

[bedis]

@aaronbbrown do you perform any kind of specific operations such as adding / removing services, scaling in / out services and rolling updates?
and if so, does it happen often?

[aaronbbrown]

@bedis we have rolling updates to the workload backed by this ingress occur 20-30 times a day.

[aaronbbrown]

Attached is a heap dump from http://localhost:6060/debug/pprof/heap inside a frozen pod.
heap.out.gz

[Mo3m3n]

Thanks @aaronbbrown for the details
This starts to make sense to me and I think there is a relation between:

we have rolling updates to the workload backed by this ingress occur 20-30 times a day.

and the heap profile you shared. Maybe some events are not handled or are delayed resulting in this important memory usage.
The rolling updates you talked about, they involve what type of kubernetes resources exactly (ingress, secret, pod, etc) and how many of them ?
I will deploy a similar rolling updates but with higher frequency to reproduce this.

[aaronbbrown]

The rolling updates you talked about, they involve what type of kubernetes resources exactly (ingress, secret, pod, etc) and how many of them ?

Each production deployment involves:

     10 ConfigMap
     56 Deployment
      2 Ingress (these are actually a CRD, not the Kubernetes Ingress)
      1 Namespace
      1 ResourceQuota
      6 Service

There are 50-80 Pods in the largest Deployment, but most are small (1-2 replicas). We run one ingress controller per service, so the label selectors should only match a single Service and set of Pods from one Deployment. There are only 2 ingress controllers running, each with 4 replicas.

I attempted to reproduce this bug for days by constantly rolling over pods from a Deployment (by changing an annotation in spec.template.spec.metadata) and it never occurred. In production, we've had this occur 3 times in the past 2 weeks, though. Interestingly, both times were on weekends where deployments are less frequent. This makes me think that maybe I should try a similar experiment, but by touching the Service resource 🤔.

[Mo3m3n]

I attempted to reproduce this bug for days by constantly rolling over pods from a Deployment (by changing an annotation in spec.template.spec.metadata) and it never occurred.

You have the same kubernetes version in your production cluster and the cluster where you were attempting to reproduce this ?

[aaronbbrown]

You have the same kubernetes version in your production cluster and the cluster where you were attempting to reproduce this ?

Correct. The clusters are 1.20.1.

[Mo3m3n]

I was able to reproduce this and have a similar memory profile to what you have provided.
I had to generate more kubernetes events than the IC can handle which made the memory used by the "apimachinery watcher" increase.
I have also seen the issue you reported in #319 and it is important to know if that one is related to the memory issue described here: in such case the huge memory consumption may be the result of IC controller being too much busy with some cpu intensive tasks. If it is unrelated (like in my tests) then we will focus on improving the performance of the k8s event dispatch in IC.
So can you check if the high memory usage reported here comes also with a high cpu usage ?

[aaronbbrown]

The examples in #319 are definitely the haproxy process using abnormal amounts of CPU. I'm not certain if that is the case where the memory 📈 (and haproxy.cfg stopped being updated for several days, until the process was killed) because I'm not capturing per-process stats. CPU utilization of the Pod did go up around the time when the memory 📈, but I don't know for sure which process was utilizing that CPU.

[Mo3m3n]

Thanks for your patience @aaronbbrown
The issue here seems to be related to the --publish-service param where controller is updating ingresses status in a blocking/synchronous way.
So the more ingresses and kubernetes events there are, the more controller will spend time waiting on UpdateStatus which leads to accumulating events an incease of memory use.
I will get back to you this week with a fix, in the meantime let me know if you are indeed using "publish-service" param