search

hashicorp / consul-k8s

First-class support for Consul Service Mesh on Kubernetes
https://www.consul.io/docs/k8s
Mozilla Public License 2.0
670 stars 324 forks source link

Seeing existing valid services deregister upon restart/startup #280

Open praymann opened 4 years ago

praymann commented 4 years ago

We (Invoca) started upgrading to 0.15.0 and are still seeing behavior that matches what is described in https://github.com/hashicorp/consul-k8s/pull/208.

If we delete the pod running consul-k8s catalog-sync upon startup we see watchReapableServices log that services are invalid and set them for deregistration before the registration is generated and the given service is added to the serviceNames. Then once we start seeing syncFull fire, all our services start to deregister only to register moments later.

Here is an example with DEBUG logging, cut up to show a single service ``` 2020-06-18T18:58:58.369Z [DEBUG] to-consul/source.controller/endpoints: queue: op=add key=homer/homer-oauth 2020-06-18T18:58:58.370Z [DEBUG] to-consul/controller: queue: op=add key=homer/homer-oauth 2020-06-18T18:58:58.470Z [DEBUG] to-consul/source.controller/endpoints: processing object: key=homer/homer-oauth exists=true 2020-06-18T18:58:58.607Z [DEBUG] to-consul/sink: [watchReapableServices] services returned from catalog: services=["{ a}", "{ b}", "{ c}", "{ d}", "{ e}", "{ f}", "{ g}", "{ h}", "{ i}", "{ j}", "{ k}", "{ l}", "{ m}", "{ homer-oauth}", "{ n}", "{ o}", "{ p}", "{ q}", "{ r}", "{ s}", "{ t}", "{ u}", "{ v}", "{ w}", "{ x}", "{ y}", "{ z}", "{ 0}", "{ 1}", "{ 2}", "{ 3}", "{ 4}", "{ 5}", "{ 6}", "{ 7}", "{ 8}", "{ 9}", "{ 10}", "{ 11}", "{ 12}", "{ 13}", "{ 14}", "{ 15}", "{ 16}", "{ 17}", "{ 18}", "{ 19}"] 2020-06-18T18:58:58.620Z [INFO] to-consul/sink: invalid service found, scheduling for delete: service-name=homer-oauth service-consul-namespace= 2020-06-18T18:58:58.621Z [DEBUG] to-consul/sink: [scheduleReapServiceLocked] service being scheduled for deregistration: namespace= service name=homer-oauth service id=homer-oauth-438e14cc70e0 service dereg="&{k8s-sync homer-oauth-438e14cc70e0 }" 2020-06-18T18:59:04.360Z [DEBUG] to-consul/controller: processing object: key=homer/homer-oauth exists=true 2020-06-18T18:59:04.360Z [DEBUG] to-consul/source: [ServiceResource.Upsert] adding service to serviceMap: key=homer/homer-oauth service=[...] 2020-06-18T18:59:04.361Z [DEBUG] to-consul/source: [generateRegistrations] generating registration: key=homer/homer-oauth 2020-06-18T18:59:04.361Z [DEBUG] to-consul/source: generated registration: key=homer/homer-oauth service=homer-oauth namespace= instances=1 2020-06-18T18:59:04.363Z [DEBUG] to-consul/sink: [Sync] adding service to serviceNames set: service="&{ homer-oauth-438e14cc70e0 homer-oauth [...] 2020-06-18T18:59:04.363Z [DEBUG] to-consul/sink: [Sync] adding service to namespaces map: service="&{ homer-oauth-438e14cc70e0 homer-oauth [...] 2020-06-18T18:59:04.363Z [INFO] to-consul/source: upsert: key=homer/homer-oauth 2020-06-18T18:59:04.553Z [DEBUG] to-consul/sink: [Sync] adding service to serviceNames set: service="&{ homer-oauth-438e14cc70e0 homer-oauth [...] 2020-06-18T18:59:04.553Z [DEBUG] to-consul/sink: [Sync] adding service to namespaces map: service="&{ homer-oauth-438e14cc70e0 homer-oauth [...] 2020-06-18T18:59:04.753Z [DEBUG] to-consul/sink: [Sync] adding service to serviceNames set: service="&{ homer-oauth-438e14cc70e0 homer-oauth [...] 2020-06-18T18:59:04.753Z [DEBUG] to-consul/sink: [Sync] adding service to namespaces map: service="&{ homer-oauth-438e14cc70e0 homer-oauth [...] 2020-06-18T18:59:05.559Z [DEBUG] to-consul/sink: [Sync] adding service to serviceNames set: service="&{ homer-oauth-438e14cc70e0 homer-oauth [...] 2020-06-18T18:59:05.559Z [DEBUG] to-consul/sink: [Sync] adding service to namespaces map: service="&{ homer-oauth-438e14cc70e0 homer-oauth [...] 2020-06-18T18:59:05.563Z [DEBUG] to-consul/sink: [Sync] adding service to serviceNames set: service="&{ homer-oauth-438e14cc70e0 homer-oauth [...] 2020-06-18T18:59:05.563Z [DEBUG] to-consul/sink: [Sync] adding service to namespaces map: service="&{ homer-oauth-438e14cc70e0 homer-oauth [...] 2020-06-18T18:59:05.754Z [DEBUG] to-consul/sink: [Sync] adding service to serviceNames set: service="&{ homer-oauth-438e14cc70e0 homer-oauth [...] 2020-06-18T18:59:05.754Z [DEBUG] to-consul/sink: [Sync] adding service to namespaces map: service="&{ homer-oauth-438e14cc70e0 homer-oauth [...] 2020-06-18T18:59:05.955Z [DEBUG] to-consul/sink: [Sync] adding service to serviceNames set: service="&{ homer-oauth-438e14cc70e0 homer-oauth [...] 2020-06-18T18:59:05.955Z [DEBUG] to-consul/sink: [Sync] adding service to namespaces map: service="&{ homer-oauth-438e14cc70e0 homer-oauth [...] 2020-06-18T18:59:06.157Z [DEBUG] to-consul/sink: [Sync] adding service to serviceNames set: service="&{ homer-oauth-438e14cc70e0 homer-oauth [...] 2020-06-18T18:59:06.157Z [DEBUG] to-consul/sink: [Sync] adding service to namespaces map: service="&{ homer-oauth-438e14cc70e0 homer-oauth [...] 2020-06-18T18:59:06.157Z [DEBUG] to-consul/sink: [Sync] adding service to serviceNames set: service="&{ homer-oauth-438e14cc70e0 homer-oauth [...] 2020-06-18T18:59:06.157Z [DEBUG] to-consul/sink: [Sync] adding service to namespaces map: service="&{ homer-oauth-438e14cc70e0 homer-oauth [...] 2020-06-18T18:59:06.556Z [DEBUG] to-consul/sink: [Sync] adding service to serviceNames set: service="&{ homer-oauth-438e14cc70e0 homer-oauth [...] 2020-06-18T18:59:06.556Z [DEBUG] to-consul/sink: [Sync] adding service to namespaces map: service="&{ homer-oauth-438e14cc70e0 homer-oauth [...] 2020-06-18T18:59:06.563Z [DEBUG] to-consul/sink: [Sync] adding service to serviceNames set: service="&{ homer-oauth-438e14cc70e0 homer-oauth [...] 2020-06-18T18:59:06.563Z [DEBUG] to-consul/sink: [Sync] adding service to namespaces map: service="&{ homer-oauth-438e14cc70e0 homer-oauth [...] 2020-06-18T18:59:06.756Z [DEBUG] to-consul/sink: [Sync] adding service to serviceNames set: service="&{ homer-oauth-438e14cc70e0 homer-oauth [...] 2020-06-18T18:59:06.756Z [DEBUG] to-consul/sink: [Sync] adding service to namespaces map: service="&{ homer-oauth-438e14cc70e0 homer-oauth [...] 2020-06-18T18:59:06.760Z [DEBUG] to-consul/sink: [Sync] adding service to serviceNames set: service="&{ homer-oauth-438e14cc70e0 homer-oauth [...] 2020-06-18T18:59:06.760Z [DEBUG] to-consul/sink: [Sync] adding service to namespaces map: service="&{ homer-oauth-438e14cc70e0 homer-oauth [...] 2020-06-18T18:59:07.154Z [DEBUG] to-consul/sink: [Sync] adding service to serviceNames set: service="&{ homer-oauth-438e14cc70e0 homer-oauth [...] 2020-06-18T18:59:07.154Z [DEBUG] to-consul/sink: [Sync] adding service to namespaces map: service="&{ homer-oauth-438e14cc70e0 homer-oauth [...] 2020-06-18T18:59:07.161Z [DEBUG] to-consul/sink: [Sync] adding service to serviceNames set: service="&{ homer-oauth-438e14cc70e0 homer-oauth [...] 2020-06-18T18:59:07.161Z [DEBUG] to-consul/sink: [Sync] adding service to namespaces map: service="&{ homer-oauth-438e14cc70e0 homer-oauth [...] 2020-06-18T18:59:07.356Z [DEBUG] to-consul/sink: [Sync] adding service to serviceNames set: service="&{ homer-oauth-438e14cc70e0 homer-oauth [...] 2020-06-18T18:59:07.356Z [DEBUG] to-consul/sink: [Sync] adding service to namespaces map: service="&{ homer-oauth-438e14cc70e0 homer-oauth [...] 2020-06-18T18:59:07.358Z [DEBUG] to-consul/sink: [Sync] adding service to serviceNames set: service="&{ homer-oauth-438e14cc70e0 homer-oauth [...] 2020-06-18T18:59:07.358Z [DEBUG] to-consul/sink: [Sync] adding service to namespaces map: service="&{ homer-oauth-438e14cc70e0 homer-oauth [...] 2020-06-18T18:59:28.350Z [DEBUG] to-consul/sink: [syncFull] starting watchService routine: namespace= service=homer-oauth 2020-06-18T18:59:28.350Z [INFO] to-consul/sink: starting service watcher: service-name=homer-oauth service-consul-namespace= 2020-06-18T18:59:28.371Z [DEBUG] to-consul/sink: [watchReapableServices] services returned from catalog: services=["{ a}", "{ b}", "{ c}", "{ d}", "{ e}", "{ f}", "{ g}", "{ h}", "{ i}", "{ j}", "{ k}", "{ l}", "{ m}", "{ homer-oauth}", "{ n}", "{ o}", "{ p}", "{ q}", "{ r}", "{ s}", "{ t}", "{ u}", "{ v}", "{ w}", "{ x}", "{ y}", "{ z}", "{ 0}", "{ 1}", "{ 2}", "{ 3}", "{ 4}", "{ 5}", "{ 6}", "{ 7}", "{ 8}", "{ 9}", "{ 10}", "{ 11}", "{ 12}", "{ 13}", "{ 14}", "{ 15}", "{ 16}", "{ 17}", "{ 18}", "{ 19}"] 2020-06-18T18:59:29.787Z [INFO] to-consul/sink: deregistering service: node-name=k8s-sync service-id=homer-oauth-438e14cc70e0 service-consul-namespace= 2020-06-18T18:59:40.361Z [DEBUG] to-consul/sink: registered service instance: node-name=k8s-sync service-name=homer-oauth consul-namespace-name= service=[...] 2020-06-18T18:59:42.630Z [DEBUG] to-consul/sink: [watchReapableServices] serviceNames contains service: namespace= service-name=homer-oauth 2020-06-18T18:59:42.650Z [DEBUG] to-consul/sink: [watchReapableServices] services returned from catalog: services=["{ a}", "{ b}", "{ c}", "{ d}", "{ e}", "{ f}", "{ g}", "{ h}", "{ i}", "{ j}", "{ k}", "{ l}", "{ m}", "{ homer-oauth}", "{ n}", "{ o}", "{ p}", "{ q}", "{ r}", "{ s}", "{ t}", "{ u}", "{ v}", "{ w}", "{ x}", "{ y}", "{ z}", "{ 0}", "{ 1}", "{ 2}", "{ 3}", "{ 4}", "{ 5}", "{ 6}", "{ 7}", "{ 8}", "{ 9}", "{ 10}", "{ 11}", "{ 12}", "{ 13}", "{ 14}", "{ 15}", "{ 16}", "{ 17}", "{ 18}", "{ 19}"] 2020-06-18T18:59:42.650Z [DEBUG] to-consul/sink: [watchReapableServices] serviceNames contains service: namespace= service-name=homer-oauth 2020-06-18T18:59:42.658Z [DEBUG] to-consul/sink: [watchReapableServices] services returned from catalog: services=["{ a}", "{ b}", "{ c}", "{ d}", "{ e}", "{ f}", "{ g}", "{ h}", "{ i}", "{ j}", "{ k}", "{ l}", "{ m}", "{ homer-oauth}", "{ n}", "{ o}", "{ p}", "{ q}", "{ r}", "{ s}", "{ t}", "{ u}", "{ v}", "{ w}", "{ x}", "{ y}", "{ z}", "{ 0}", "{ 1}", "{ 2}", "{ 3}", "{ 4}", "{ 5}", "{ 6}", "{ 7}", "{ 8}", "{ 9}", "{ 10}", "{ 11}", "{ 12}", "{ 13}", "{ 14}", "{ 15}", "{ 16}", "{ 17}", "{ 18}", "{ 19}"] 2020-06-18T18:59:50.150Z [DEBUG] to-consul/sink: [watchReapableServices] serviceNames contains service: namespace= service-name=homer-oauth 2020-06-18T19:00:13.251Z [DEBUG] to-consul/sink: registered service instance: node-name=k8s-sync service-name=homer-oauth consul-namespace-name= service=[...] 2020-06-18T19:00:50.422Z [DEBUG] to-consul/sink: registered service instance: node-name=k8s-sync service-name=homer-oauth consul-namespace-name= service=[...] 2020-06-18T19:00:52.292Z [DEBUG] to-consul/sink: [watchReapableServices] services returned from catalog: services=["{ a}", "{ b}", "{ c}", "{ d}", "{ e}", "{ f}", "{ g}", "{ h}", "{ i}", "{ j}", "{ k}", "{ l}", "{ m}", "{ homer-oauth}", "{ n}", "{ o}", "{ p}", "{ q}", "{ r}", "{ s}", "{ t}", "{ u}", "{ v}", "{ w}", "{ x}", "{ y}", "{ z}", "{ 0}", "{ 1}", "{ 2}", "{ 3}", "{ 4}", "{ 5}", "{ 6}", "{ 7}", "{ 8}", "{ 9}", "{ 10}", "{ 11}", "{ 12}", "{ 13}", "{ 14}", "{ 15}", "{ 16}", "{ 17}", "{ 18}", "{ 19}"] 2020-06-18T19:00:52.292Z [DEBUG] to-consul/sink: [watchReapableServices] serviceNames contains service: namespace= service-name=homer-oauth 2020-06-18T19:01:23.479Z [DEBUG] to-consul/sink: registered service instance: node-name=k8s-sync service-name=homer-oauth consul-namespace-name= service=[...] 2020-06-18T19:01:53.071Z [DEBUG] to-consul/sink: [watchReapableServices] services returned from catalog: services=["{ a}", "{ b}", "{ c}", "{ d}", "{ e}", "{ f}", "{ g}", "{ h}", "{ i}", "{ j}", "{ k}", "{ l}", "{ m}", "{ homer-oauth}", "{ n}", "{ o}", "{ p}", "{ q}", "{ r}", "{ s}", "{ t}", "{ u}", "{ v}", "{ w}", "{ x}", "{ y}", "{ z}", "{ 0}", "{ 1}", "{ 2}", "{ 3}", "{ 4}", "{ 5}", "{ 6}", "{ 7}", "{ 8}", "{ 9}", "{ 10}", "{ 11}", "{ 12}", "{ 13}", "{ 14}", "{ 15}", "{ 16}", "{ 17}", "{ 18}", "{ 19}"] 2020-06-18T19:01:53.072Z [DEBUG] to-consul/sink: [watchReapableServices] serviceNames contains service: namespace= service-name=homer-oauth 2020-06-18T19:01:57.649Z [DEBUG] to-consul/sink: registered service instance: node-name=k8s-sync service-name=homer-oauth consul-namespace-name= service=[...] ```

If it's helpful at all, here is what we're using while running this in Kubernetes: 

        - consul-k8s
        - sync-catalog
        - -k8s-default-sync=true
        - -to-consul=true
        - -consul-k8s-tag=foo.bar.cloud-region.k8s
        - -to-k8s=false
        - -allow-k8s-namespace=*
        - -deny-k8s-namespace=default
        - -deny-k8s-namespace=kube-system
        - -deny-k8s-namespace=kube-public
        - -node-port-sync-type=InternalOnly
        - -sync-clusterip-services=true
        - -log-level=debug
praymann commented 4 years ago

I was curious why we see multiple of:

[Sync] adding service to serviceNames set: x
[Sync] adding service to namespaces map: x

and why it seems like it always comes after to-consul/source: upsert: key=.

If I peek at resource.go it looks like that comes from https://github.com/hashicorp/consul-k8s/blob/v0.15.0/catalog/to-consul/resource.go#L203 which has t.sync() before it which leads to https://github.com/hashicorp/consul-k8s/blob/v0.15.0/catalog/to-consul/resource.go#L633 where it passes the contents of t.consulMap into t.Syncer.Sync(). Doesn't that then unlock the watchReapableServices after we've synced only one service?

My logs seem to confirm that since I see [watchReapableServices] appear within milliseconds after the first to-consul/source: upsert: key= log entry and it finds all the services yet to hit the consulMap as invalid.

praymann commented 4 years ago

Am I correct in saying that https://github.com/hashicorp/consul-k8s/pull/191/files implemented it such that it required all the valid services to be upserted (and synced) before unblocking the watchReapableServices?

praymann commented 4 years ago

@lkysow is my analysis above correct?