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).
Script output
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?