Hi, I’m trying to fully understand when a pod will appear in Consul. We are trying to estimate the time it takes from a deployment being created to it showing up in Consul.
I have a pod that is being added with 1 replica, and takes about 30 seconds to pass readiness checks. It also has an endpoint that gets created immediately. I initially assumed it would show up in consul immediately due to the endpoint being created so quickly, but it actually takes around 40 seconds to show up. At first I thought this was due to the sync interval so I set that to 8s (rather than the default 30s) but that didn’t change anything… Now I’m thinking it waits for the health checks to pass, but that delta still doesn’t line up.
Here’s some analysis I’ve been doing…
I wrote a script to scale to 0, wait until the service is no longer in consul catalog, then scale up and see how long it takes to show up in catalog. Here is the output, side by side with the logs (of which I’ve omitted specific details).
2021/02/23 18:27:14 Scaled down to 0 2021/02/23 18:28:08 Service removed from consul 2021/02/23 18:28:08 Scaled up to 1 2021/02/23 18:28:10 Found endpoint in K8s Endpoints 2021/02/23 18:28:34 Pod is ready in K8s 2021/02/23 18:28:51 Found service in Consul Catalog 2021/02/23 18:28:51 NAME | TIME ---------------------------------------+---------- Time from replica change to catalog | 42398ms Time from endpoint to catalog | 40343ms Time from container ready to catalog | 16153ms Average Request Time (error) | 185ms
Catalog Sync Logs
2021-02-24T02:27:14.228Z [INFO] to-consul/source: upsert endpoint: key=my-namespace/my-service 2021-02-24T02:27:16.184Z [INFO] to-consul/sink: registering services 2021-02-24T02:27:16.185Z [INFO] to-consul/sink: stopping service watcher: service-name=my-service-my-namespace service-consul-namespace= 2021-02-24T02:27:33.284Z [INFO] to-consul/sink: registering services 2021-02-24T02:27:49.189Z [INFO] to-consul/sink: registering services 2021-02-24T02:27:59.089Z [INFO] to-consul/sink: invalid service found, scheduling for delete: service-name=my-service-my-namespace service-consul-namespace= 2021-02-24T02:28:07.089Z [INFO] to-consul/sink: registering services 2021-02-24T02:28:07.089Z [INFO] to-consul/sink: deregistering service: node-name=k8s-sync service-id=my-service-f4dc43e6accd service-consul-namespace= 2021-02-24T02:28:16.587Z [INFO] to-consul/source: upsert endpoint: key=my-namespace/my-service 2021-02-24T02:28:24.586Z [INFO] to-consul/sink: registering services 2021-02-24T02:28:34.765Z [INFO] to-consul/source: upsert endpoint: key=my-namespace/my-service 2021-02-24T02:28:41.879Z [INFO] to-consul/sink: registering services 2021-02-24T02:28:41.879Z [INFO] to-consul/sink: starting service watcher: service-name=my-service-my-namespace service-consul-namespace= 2021-02-24T02:28:59.286Z [INFO] to-consul/sink: registering services 2021-02-24T02:29:16.694Z [INFO] to-consul/sink: registering services
As you can see, it takes about 40 seconds for it to appear, and 16 seconds to appear even after passing readiness checks. Can anyone help me realize where are these delays coming from?