Excessive Catalog Service Queries

[josephschadlick]

When enabling consul-k8s with sync to-consul only and default sync disabled, I am experiencing a very high rate of catalog service queries on my consul server cluster (on the order of 1k per second) once I register a nodeport service. This causes an increase in load on the consul server, and I also see a large amount of cpu usage on the consul-k8s container during this period.

Consul server version: 1.1.0
consul-k8s version: 0.4.0
kubernetes version: 1.11.2
consul-helm version: 0.5.0

consul-k8s config:

$ kubectl describe pod consul-service-sync-sync-catalog-f88f98b69-p8pn9 
Name:           consul-service-sync-sync-catalog-f88f98b69-p8pn9
Namespace:      default
Node:           ip-10-16-138-32.us-west-2.compute.internal/10.16.138.32
Start Time:     Wed, 30 Jan 2019 14:49:38 -0800
Labels:         app=consul
                chart=consul-0.5.0
                component=sync-catalog
                pod-template-hash=944954625
                release=consul-service-sync
Annotations:    consul.hashicorp.com/connect-inject: false
Status:         Running
IP:             10.42.57.224
Controlled By:  ReplicaSet/consul-service-sync-sync-catalog-f88f98b69
Containers:
  consul-sync-catalog:
    Container ID:  docker://6b2e1cda57b0650784400403ac42e07f5c569b45e08b2b74599ec1c2da20100e
    Image:         hashicorp/consul-k8s:0.4.0
    Image ID:      docker-pullable://hashicorp/consul-k8s@sha256:bdef17237f140c96b5097b2374be7b8e19181c723d8a8f37c7d795913868cb68
    Port:          <none>
    Host Port:     <none>
    Command:
      /bin/sh
      -ec
      consul-k8s sync-catalog \
        -http-addr=${HOST_IP}:8500 \
        -k8s-default-sync=false \
        -to-k8s=false \
        -consul-domain=consul \
        -k8s-write-namespace=${NAMESPACE} \
        -node-port-sync-type=ExternalFirst \
      
    State:          Running

Test service config:

apiVersion: apps/v1
kind: Deployment
metadata:
  name: nginx-test-cs
spec:
  selector:
    matchLabels:
      app: nginx-test-cs
  replicas: 1 
  template:
    metadata:
      labels:
        app: nginx-test-cs
    spec:
      containers:
      - name: nginx
        image: nginx:latest
        ports:
        - containerPort: 80
---
apiVersion: v1
kind: Service
metadata:
  annotations:
    consul.hashicorp.com/service-sync: "true"
  name: nginx-test-cs
  labels:
    app: nginx-test-cs
spec:
  type: NodePort
  ports:
  - name: web
    nodePort: 30080
    port: 80
    protocol: TCP
  selector:
    app: nginx-test-cs

consul-k8s container logs:

2019-01-30T22:49:44.196Z [INFO ] to-consul/source: starting runner for endpoints
2019-01-30T22:49:45.296Z [INFO ] to-consul/controller: initial cache sync complete
2019-01-30T22:49:45.296Z [INFO ] to-consul/source.controller/endpoints: initial cache sync complete
2019-01-30T22:50:14.196Z [INFO ] to-consul/sink: registering services
2019-01-30T22:50:44.196Z [INFO ] to-consul/sink: registering services
2019-01-30T22:50:53.128Z [WARN ] to-consul/source: error loading initial endpoints: key=default/nginx-test-cs err="an empty namespace may not be set when a resource name is provided"
2019-01-30T22:50:53.128Z [INFO ] to-consul/source: upsert: key=default/nginx-test-cs
2019-01-30T22:50:53.137Z [INFO ] to-consul/source: upsert endpoint: key=default/nginx-test-cs
2019-01-30T22:51:00.625Z [INFO ] to-consul/source: upsert endpoint: key=default/nginx-test-cs
2019-01-30T22:51:14.196Z [INFO ] to-consul/sink: registering services
2019-01-30T22:51:14.196Z [INFO ] to-consul/sink: starting service watcher: service-name=nginx-test-cs
2019-01-30T22:51:44.207Z [INFO ] to-consul/sink: registering services
...
2019-01-30T22:55:44.272Z [INFO ] to-consul/sink: registering services
2019-01-30T22:56:07.312Z [INFO ] to-consul/source: upsert endpoint: key=default/nginx-test-cs
2019-01-30T22:56:07.406Z [INFO ] to-consul/source: delete: key=default/nginx-test-cs
2019-01-30T22:56:07.441Z [INFO ] to-consul/source: delete endpoint: key=default/nginx-test-cs
2019-01-30T22:56:14.279Z [INFO ] to-consul/sink: registering services
2019-01-30T22:56:14.279Z [INFO ] to-consul/sink: deregistering service: node-name=ip-10-16-138-32.us-west-2.compute.internal service-id=nginx-test-cs-17e2e9cd926d
2019-01-30T22:56:14.288Z [INFO ] to-consul/sink: stopping service watcher: service-name=nginx-test-cs
2019-01-30T22:56:44.288Z [INFO ] to-consul/sink: registering services
2019-01-30T22:56:44.288Z [INFO ] to-consul/sink: deregistering service: node-name=ip-10-16-138-32.us-west-2.compute.internal service-id=nginx-test-cs-17e2e9cd926d
2019-01-30T22:56:44.290Z [WARN ] to-consul/sink: error deregistering service: node-name=ip-10-16-138-32.us-west-2.compute.internal service-id=nginx-test-cs-17e2e9cd926d err="Unexpected response code: 500 (rpc error making call: rpc error making call: Unknown service 'nginx-test-cs-17e2e9cd926d')"
2019-01-30T22:57:14.290Z [INFO ] to-consul/sink: registering services
...
2019-01-30T23:03:14.292Z [INFO ] to-consul/sink: registering services
2019-01-30T23:03:42.732Z [WARN ] to-consul/source: error loading initial endpoints: key=default/nginx-test-cs err="an empty namespace may not be set when a resource name is provided"
2019-01-30T23:03:42.732Z [INFO ] to-consul/source: upsert: key=default/nginx-test-cs
2019-01-30T23:03:42.741Z [INFO ] to-consul/source: upsert endpoint: key=default/nginx-test-cs
2019-01-30T23:03:44.292Z [INFO ] to-consul/sink: registering services
2019-01-30T23:03:50.510Z [INFO ] to-consul/source: upsert endpoint: key=default/nginx-test-cs
2019-01-30T23:04:14.292Z [INFO ] to-consul/sink: registering services
2019-01-30T23:04:14.292Z [INFO ] to-consul/sink: starting service watcher: service-name=nginx-test-cs
2019-01-30T23:04:44.303Z [INFO ] to-consul/sink: registering services
2019-01-30T23:05:14.311Z [INFO ] to-consul/sink: registering services
2019-01-30T23:05:21.125Z [WARN ] to-consul/source: error loading initial endpoints: key=default/nginx-test-cs-2 err="an empty namespace may not be set when a resource name is provided"
2019-01-30T23:05:21.125Z [INFO ] to-consul/source: upsert: key=default/nginx-test-cs-2
2019-01-30T23:05:21.140Z [INFO ] to-consul/source: upsert endpoint: key=default/nginx-test-cs-2
2019-01-30T23:05:26.827Z [INFO ] to-consul/source: upsert endpoint: key=default/nginx-test-cs-2
2019-01-30T23:05:44.319Z [INFO ] to-consul/sink: registering services
2019-01-30T23:05:44.319Z [INFO ] to-consul/sink: starting service watcher: service-name=nginx-test-cs-2
2019-01-30T23:06:14.344Z [INFO ] to-consul/sink: registering services
...
2019-01-30T23:16:44.719Z [INFO ] to-consul/sink: registering services
2019-01-30T23:17:08.156Z [INFO ] to-consul/source: upsert endpoint: key=default/nginx-test-cs-2
2019-01-30T23:17:08.212Z [INFO ] to-consul/source: delete: key=default/nginx-test-cs-2
2019-01-30T23:17:08.228Z [INFO ] to-consul/source: delete endpoint: key=default/nginx-test-cs-2
2019-01-30T23:17:12.429Z [INFO ] to-consul/source: delete: key=default/nginx-test-cs
2019-01-30T23:17:12.459Z [INFO ] to-consul/source: delete endpoint: key=default/nginx-test-cs
2019-01-30T23:17:14.735Z [INFO ] to-consul/sink: registering services
2019-01-30T23:17:14.735Z [INFO ] to-consul/sink: deregistering service: node-name=ip-10-16-138-32.us-west-2.compute.internal service-id=nginx-test-cs-17e2e9cd926d
2019-01-30T23:17:14.744Z [INFO ] to-consul/sink: deregistering service: node-name=ip-10-16-138-32.us-west-2.compute.internal service-id=nginx-test-cs-2-390f496f4d46
2019-01-30T23:17:14.753Z [INFO ] to-consul/sink: stopping service watcher: service-name=nginx-test-cs-2
2019-01-30T23:17:14.753Z [INFO ] to-consul/sink: stopping service watcher: service-name=nginx-test-cs
2019-01-30T23:17:14.753Z [INFO ] to-consul/sink: invalid service found, scheduling for delete: service-name=nginx-test-cs-2
2019-01-30T23:17:44.753Z [INFO ] to-consul/sink: registering services
2019-01-30T23:17:44.753Z [INFO ] to-consul/sink: deregistering service: node-name=ip-10-16-138-32.us-west-2.compute.internal service-id=nginx-test-cs-2-390f496f4d46
2019-01-30T23:17:44.755Z [WARN ] to-consul/sink: error deregistering service: node-name=ip-10-16-138-32.us-west-2.compute.internal service-id=nginx-test-cs-2-390f496f4d46 err="Unexpected response code: 500 (rpc error making call: Unknown service 'nginx-test-cs-2-390f496f4d46')"
2019-01-30T23:17:44.755Z [INFO ] to-consul/sink: deregistering service: node-name=ip-10-16-138-32.us-west-2.compute.internal service-id=nginx-test-cs-17e2e9cd926d
2019-01-30T23:17:44.756Z [WARN ] to-consul/sink: error deregistering service: node-name=ip-10-16-138-32.us-west-2.compute.internal service-id=nginx-test-cs-17e2e9cd926d err="Unexpected response code: 500 (rpc error making call: rpc error making call: Unknown service 'nginx-test-cs-17e2e9cd926d')"
2019-01-30T23:18:14.757Z [INFO ] to-consul/sink: registering services
...

QPS Graph

Consul Server CPU

consul-k8s Container CPU

I'm not sure if this is an issue with consul-k8s or a misconfiguration on on my end with either the consul-k8s or consul server. Let me know if you require any additional information.
Thanks!

[tsmgeek]

are you also seeing your services disappear and then appear again a while later?

[josephschadlick]

I did not experience that, but I ran the tests for less than an hour.

[tsmgeek]

Are you running on EKS?

[josephschadlick]

Running on Rancher on ec2. Consul servers are running outside of k8s on ec2.

[adilyse]

Good catch! There was a hot loop for syncing Kubernetes services to Consul. This has been fixed by #33 and will be included in the next release.