Proxy keeps trying to connect to stale identity IP address #6184
Comments
|
@alex-berger Thanks for another great bug report. The first thing I'd want to look into is the state of the pod's DNS--proxies discover the identity service by resolving SRV records for |
|
@olix0r I grepped for {"timestamp":"[ 98617.927784s]","level":"DEBUG","fields":{"message":"resolve_srv","name":"linkerd-dst-headless.linkerd.svc.cluster.local."},"target":"linkerd_dns","spans":[{"orig_dst":"10.40.30.51:3000","name":"ingress"},{"dst":"grafana.kube-system.svc.cluster.local:3000","name":"override"}],"threadId":"ThreadId(3)"}
{"timestamp":"[ 98617.932566s]","level":"DEBUG","fields":{"addrs":"[10.40.12.80:8086, 10.40.16.95:8086, 10.40.32.167:8086]"},"target":"linkerd_dns","spans":[{"orig_dst":"10.40.30.51:3000","name":"ingress"},{"dst":"grafana.kube-system.svc.cluster.local:3000","name":"override"}],"threadId":"ThreadId(3)"}
{"timestamp":"[ 98617.932627s]","level":"DEBUG","fields":{"addrs":"[10.40.12.80:8086, 10.40.16.95:8086, 10.40.32.167:8086]"},"target":"linkerd_proxy_dns_resolve","spans":[{"orig_dst":"10.40.30.51:3000","name":"ingress"},{"dst":"grafana.kube-system.svc.cluster.local:3000","name":"override"}],"threadId":"ThreadId(3)"}
{"timestamp":"[ 98617.934687s]","level":"DEBUG","fields":{"message":"Resolving","dst":"grafana.kube-system.svc.cluster.local:3000","context":"{\"ns\":\"gloo-system\", \"nodeName\":\"ip-10-40-9-160.eu-central-1.compute.internal\"}\n"},"target":"linkerd_proxy_api_resolve::resolve","spans":[{"orig_dst":"10.40.30.51:3000","name":"ingress"},{"v":"1.x","name":"http"},{"dst":"grafana.kube-system.svc.cluster.local:3000","name":"override"},{"dst":"grafana.kube-system.svc.cluster.local:3000","name":"logical"},{"addr":"grafana.kube-system.svc.cluster.local:3000","name":"concrete"}],"threadId":"ThreadId(2)"}
{"timestamp":"[ 98617.937693s]","level":"TRACE","fields":{"metadata":"MetadataMap { headers: {\"content-type\": \"application/grpc\", \"date\": \"Wed, 26 May 2021 12:16:41 GMT\"} }"},"target":"linkerd_proxy_api_resolve::resolve","spans":[{"orig_dst":"10.40.30.51:3000","name":"ingress"},{"v":"1.x","name":"http"},{"dst":"grafana.kube-system.svc.cluster.local:3000","name":"override"},{"dst":"grafana.kube-system.svc.cluster.local:3000","name":"logical"},{"addr":"grafana.kube-system.svc.cluster.local:3000","name":"concrete"}],"threadId":"ThreadId(2)"}
{"timestamp":"[ 98617.937761s]","level":"TRACE","fields":{"message":"Connected"},"target":"linkerd_proxy_resolve::recover","spans":[{"orig_dst":"10.40.30.51:3000","name":"ingress"},{"v":"1.x","name":"http"},{"dst":"grafana.kube-system.svc.cluster.local:3000","name":"override"},{"dst":"grafana.kube-system.svc.cluster.local:3000","name":"logical"},{"addr":"grafana.kube-system.svc.cluster.local:3000","name":"concrete"}],"threadId":"ThreadId(2)"}
{"timestamp":"[ 98617.937892s]","level":"DEBUG","fields":{"message":"Add","endpoints":"1"},"target":"linkerd_proxy_api_resolve::resolve","spans":[{"orig_dst":"10.40.30.51:3000","name":"ingress"},{"v":"1.x","name":"http"},{"dst":"grafana.kube-system.svc.cluster.local:3000","name":"override"},{"dst":"grafana.kube-system.svc.cluster.local:3000","name":"logical"},{"addr":"grafana.kube-system.svc.cluster.local:3000","name":"concrete"}],"threadId":"ThreadId(2)"}
{"timestamp":"[ 98617.937914s]","level":"TRACE","fields":{"message":"Resolved endpoint","addr":"10.40.30.51:3000","metadata":"Metadata { labels: {\"deployment\": \"grafana-deployment\", \"namespace\": \"kube-system\", \"pod\": \"grafana-deployment-87bbb98-44q59\", \"pod_template_hash\": \"87bbb98\", \"service\": \"grafana\", \"serviceaccount\": \"grafana-serviceaccount\"}, protocol_hint: Unknown, opaque_transport_port: None, identity: None, authority_override: None }","concrete":"Concrete { resolve: ConcreteAddr(NameAddr { name: \"grafana.kube-system.svc.cluster.local.\", port: 3000 }), logical: Logical { protocol: Http1, profile: .., logical_addr: LogicalAddr(grafana.kube-system.svc.cluster.local:3000) } }"},"target":"linkerd_app_outbound::endpoint","spans":[{"orig_dst":"10.40.30.51:3000","name":"ingress"},{"v":"1.x","name":"http"},{"dst":"grafana.kube-system.svc.cluster.local:3000","name":"override"},{"dst":"grafana.kube-system.svc.cluster.local:3000","name":"logical"},{"addr":"grafana.kube-system.svc.cluster.local:3000","name":"concrete"}],"threadId":"ThreadId(2)"}
{"timestamp":"[ 98622.933614s]","level":"DEBUG","fields":{"message":"resolve_srv","name":"linkerd-dst-headless.linkerd.svc.cluster.local."},"target":"linkerd_dns","spans":[{"orig_dst":"10.40.30.51:3000","name":"ingress"},{"dst":"grafana.kube-system.svc.cluster.local:3000","name":"override"}],"threadId":"ThreadId(2)"}
{"timestamp":"[ 98622.935086s]","level":"DEBUG","fields":{"addrs":"[10.40.12.80:8086, 10.40.16.95:8086, 10.40.32.167:8086]"},"target":"linkerd_dns","spans":[{"orig_dst":"10.40.30.51:3000","name":"ingress"},{"dst":"grafana.kube-system.svc.cluster.local:3000","name":"override"}],"threadId":"ThreadId(2)"}
{"timestamp":"[ 98622.935131s]","level":"DEBUG","fields":{"addrs":"[10.40.12.80:8086, 10.40.16.95:8086, 10.40.32.167:8086]"},"target":"linkerd_proxy_dns_resolve","spans":[{"orig_dst":"10.40.30.51:3000","name":"ingress"},{"dst":"grafana.kube-system.svc.cluster.local:3000","name":"override"}],"threadId":"ThreadId(2)"}
{"timestamp":"[ 98631.534495s]","level":"DEBUG","fields":{"message":"resolve_srv","name":"linkerd-dst-headless.linkerd.svc.cluster.local."},"target":"linkerd_dns","spans":[{"orig_dst":"10.40.30.51:3000","name":"ingress"},{"dst":"grafana.kube-system.svc.cluster.local:3000","name":"override"}],"threadId":"ThreadId(2)"}
{"timestamp":"[ 98631.536194s]","level":"DEBUG","fields":{"addrs":"[10.40.12.80:8086, 10.40.16.95:8086, 10.40.32.167:8086]"},"target":"linkerd_dns","spans":[{"orig_dst":"10.40.30.51:3000","name":"ingress"},{"dst":"grafana.kube-system.svc.cluster.local:3000","name":"override"}],"threadId":"ThreadId(3)"}
{"timestamp":"[ 98631.536270s]","level":"DEBUG","fields":{"addrs":"[10.40.12.80:8086, 10.40.16.95:8086, 10.40.32.167:8086]"},"target":"linkerd_proxy_dns_resolve","spans":[{"orig_dst":"10.40.30.51:3000","name":"ingress"},{"dst":"grafana.kube-system.svc.cluster.local:3000","name":"override"}],"threadId":"ThreadId(3)"}
{"timestamp":"[ 98663.194286s]","level":"DEBUG","fields":{"message":"resolve_srv","name":"linkerd-dst-headless.linkerd.svc.cluster.local."},"target":"linkerd_dns","spans":[{"orig_dst":"10.40.30.51:3000","name":"ingress"},{"dst":"grafana.kube-system.svc.cluster.local:3000","name":"override"}],"threadId":"ThreadId(3)"}
{"timestamp":"[ 98663.196208s]","level":"DEBUG","fields":{"addrs":"[10.40.12.80:8086, 10.40.16.95:8086, 10.40.32.167:8086]"},"target":"linkerd_dns","spans":[{"orig_dst":"10.40.30.51:3000","name":"ingress"},{"dst":"grafana.kube-system.svc.cluster.local:3000","name":"override"}],"threadId":"ThreadId(2)"}
{"timestamp":"[ 98663.196235s]","level":"DEBUG","fields":{"addrs":"[10.40.12.80:8086, 10.40.16.95:8086, 10.40.32.167:8086]"},"target":"linkerd_proxy_dns_resolve","spans":[{"orig_dst":"10.40.30.51:3000","name":"ingress"},{"dst":"grafana.kube-system.svc.cluster.local:3000","name":"override"}],"threadId":"ThreadId(2)"}
{"timestamp":"[ 98781.228775s]","level":"DEBUG","fields":{"message":"resolve_srv","name":"linkerd-dst-headless.linkerd.svc.cluster.local."},"target":"linkerd_dns","spans":[{"orig_dst":"10.40.30.51:3000","name":"ingress"},{"dst":"grafana.kube-system.svc.cluster.local:3000","name":"override"}],"threadId":"ThreadId(2)"}
{"timestamp":"[ 98781.230394s]","level":"DEBUG","fields":{"addrs":"[10.40.12.80:8086, 10.40.16.95:8086, 10.40.32.167:8086]"},"target":"linkerd_dns","spans":[{"orig_dst":"10.40.30.51:3000","name":"ingress"},{"dst":"grafana.kube-system.svc.cluster.local:3000","name":"override"}],"threadId":"ThreadId(2)"}
{"timestamp":"[ 98781.230447s]","level":"DEBUG","fields":{"addrs":"[10.40.12.80:8086, 10.40.16.95:8086, 10.40.32.167:8086]"},"target":"linkerd_proxy_dns_resolve","spans":[{"orig_dst":"10.40.30.51:3000","name":"ingress"},{"dst":"grafana.kube-system.svc.cluster.local:3000","name":"override"}],"threadId":"ThreadId(2)"}
{"timestamp":"[ 98781.233032s]","level":"DEBUG","fields":{"message":"Resolving","dst":"grafana.kube-system.svc.cluster.local:3000","context":"{\"ns\":\"gloo-system\", \"nodeName\":\"ip-10-40-9-160.eu-central-1.compute.internal\"}\n"},"target":"linkerd_proxy_api_resolve::resolve","spans":[{"name":"outbound"},{"client.addr":"10.40.2.232:57436","name":"accept"},{"orig_dst":"10.40.30.51:3000","name":"ingress"},{"v":"1.x","name":"http"},{"dst":"grafana.kube-system.svc.cluster.local:3000","name":"override"},{"dst":"grafana.kube-system.svc.cluster.local:3000","name":"logical"},{"addr":"grafana.kube-system.svc.cluster.local:3000","name":"concrete"}],"threadId":"ThreadId(3)"}
{"timestamp":"[ 98781.248482s]","level":"TRACE","fields":{"metadata":"MetadataMap { headers: {\"content-type\": \"application/grpc\", \"date\": \"Wed, 26 May 2021 12:19:24 GMT\"} }"},"target":"linkerd_proxy_api_resolve::resolve","spans":[{"name":"outbound"},{"client.addr":"10.40.2.232:57436","name":"accept"},{"orig_dst":"10.40.30.51:3000","name":"ingress"},{"v":"1.x","name":"http"},{"dst":"grafana.kube-system.svc.cluster.local:3000","name":"override"},{"dst":"grafana.kube-system.svc.cluster.local:3000","name":"logical"},{"addr":"grafana.kube-system.svc.cluster.local:3000","name":"concrete"}],"threadId":"ThreadId(3)"}
{"timestamp":"[ 98781.248559s]","level":"TRACE","fields":{"message":"Connected"},"target":"linkerd_proxy_resolve::recover","spans":[{"name":"outbound"},{"client.addr":"10.40.2.232:57436","name":"accept"},{"orig_dst":"10.40.30.51:3000","name":"ingress"},{"v":"1.x","name":"http"},{"dst":"grafana.kube-system.svc.cluster.local:3000","name":"override"},{"dst":"grafana.kube-system.svc.cluster.local:3000","name":"logical"},{"addr":"grafana.kube-system.svc.cluster.local:3000","name":"concrete"}],"threadId":"ThreadId(3)"}
{"timestamp":"[ 98781.248727s]","level":"DEBUG","fields":{"message":"Add","endpoints":"1"},"target":"linkerd_proxy_api_resolve::resolve","spans":[{"name":"outbound"},{"client.addr":"10.40.2.232:57436","name":"accept"},{"orig_dst":"10.40.30.51:3000","name":"ingress"},{"v":"1.x","name":"http"},{"dst":"grafana.kube-system.svc.cluster.local:3000","name":"override"},{"dst":"grafana.kube-system.svc.cluster.local:3000","name":"logical"},{"addr":"grafana.kube-system.svc.cluster.local:3000","name":"concrete"}],"threadId":"ThreadId(2)"}
{"timestamp":"[ 98781.248759s]","level":"TRACE","fields":{"message":"Resolved endpoint","addr":"10.40.30.51:3000","metadata":"Metadata { labels: {\"deployment\": \"grafana-deployment\", \"namespace\": \"kube-system\", \"pod\": \"grafana-deployment-87bbb98-44q59\", \"pod_template_hash\": \"87bbb98\", \"service\": \"grafana\", \"serviceaccount\": \"grafana-serviceaccount\"}, protocol_hint: Unknown, opaque_transport_port: None, identity: None, authority_override: None }","concrete":"Concrete { resolve: ConcreteAddr(NameAddr { name: \"grafana.kube-system.svc.cluster.local.\", port: 3000 }), logical: Logical { protocol: Http1, profile: .., logical_addr: LogicalAddr(grafana.kube-system.svc.cluster.local:3000) } }"},"target":"linkerd_app_outbound::endpoint","spans":[{"name":"outbound"},{"client.addr":"10.40.2.232:57436","name":"accept"},{"orig_dst":"10.40.30.51:3000","name":"ingress"},{"v":"1.x","name":"http"},{"dst":"grafana.kube-system.svc.cluster.local:3000","name":"override"},{"dst":"grafana.kube-system.svc.cluster.local:3000","name":"logical"},{"addr":"grafana.kube-system.svc.cluster.local:3000","name":"concrete"}],"threadId":"ThreadId(2)"}
{"timestamp":"[ 98786.232276s]","level":"DEBUG","fields":{"message":"resolve_srv","name":"linkerd-dst-headless.linkerd.svc.cluster.local."},"target":"linkerd_dns","spans":[{"orig_dst":"10.40.30.51:3000","name":"ingress"},{"dst":"grafana.kube-system.svc.cluster.local:3000","name":"override"}],"threadId":"ThreadId(3)"}
{"timestamp":"[ 98786.234414s]","level":"DEBUG","fields":{"addrs":"[10.40.12.80:8086, 10.40.16.95:8086, 10.40.32.167:8086]"},"target":"linkerd_dns","spans":[{"orig_dst":"10.40.30.51:3000","name":"ingress"},{"dst":"grafana.kube-system.svc.cluster.local:3000","name":"override"}],"threadId":"ThreadId(2)"}
{"timestamp":"[ 98786.234437s]","level":"DEBUG","fields":{"addrs":"[10.40.12.80:8086, 10.40.16.95:8086, 10.40.32.167:8086]"},"target":"linkerd_proxy_dns_resolve","spans":[{"orig_dst":"10.40.30.51:3000","name":"ingress"},{"dst":"grafana.kube-system.svc.cluster.local:3000","name":"override"}],"threadId":"ThreadId(2)"}I scanned another hour of logs for that Pod without finding any log message for |
|
Interesting! I think this at least gives us some pointers about what to look into. In the meantime, you may want to run with a more targeted logging configuration so we get some better signal if it recurs after restart: config.linkerd.io/proxy-log-level: warn,linkerd=info,linkerd_dns=debug,linkerd_proxy_dns_resolve=debug,linkerd_proxy_resolve=trace,linkerd_reconnect=debug |
|
@olix0r I applied the log configuration that you recommended to our ingress gateways. Now, the problem appears again on one of our ingress gateway Pods, but the log of that Pod still does not contain any recent log messages matching Note, the logs of the others ingress gateway Pods, which show no symptoms contain plenty of log messages that match The log of the affected |
|
Actually, doesn't this look rather similar to what we had in #6037 (comment), a retry (reconnect) loop that never ends? Some first ad-hoc |
|
@alex-berger Thanks! I think we have a pretty good understanding of why this is happening. I think it's similar to the other issue in that this probably can't cause any runtime problems -- as soon as the identity client is actually used, it should trigger a re-resolution and get a fresh set of endpoints to use. However, this is definitely undesirable behavior as-is, and we'll make changes to the proxy to avoid this state. We need to do a little more thinking on exactly what these changes should be, though ;) |
We currently build the identity client at startup and hold it to be used fairly infrequently: the client is used once per day by default, and even in extremely aggressive scenarios is unlikely to be used more frequently than once every few minutes. As such, there's very little benefit to holding the client (and buffers, DNS resolutions, etc) open continually. Instead, it seems preferable to instantiate the identity client only as it's needed. Practically, we see issues like linkerd/linkerd2#6184 where the identity client may try to reconnect to stale endpoints when the identity deployment is rescheduled (because there aren't a steady stream of requests on this client). This change makes the controller stack a `NewService<()>` so that clients can be instantiated lazily. The identity module now creates a new connection for each identity request. Other controller clients are unaffacted, continuing to use long-live clients.
We currently build the identity client at startup and hold it to be used fairly infrequently: the client is used once per day by default, and even in extremely aggressive scenarios is unlikely to be used more frequently than once every few minutes. As such, there's very little benefit to holding the client (and buffers, DNS resolutions, etc) open continually. Instead, it seems preferable to instantiate the identity client only as it's needed. Practically, we see issues like linkerd/linkerd2#6184 where the identity client may try to reconnect to stale endpoints when the identity deployment is rescheduled (because there aren't a steady stream of requests on this client). This change makes the controller stack a `NewService<()>` so that clients can be instantiated lazily. The identity module now creates a new connection for each identity request. Other controller clients are unaffacted, continuing to use long-live clients.
|
I've published an image with the fix proposed in linkerd/linkerd2-proxy#1021 to |
|
@olix0r the stale address FYI, I guess that in case of |
|
The original issue was definitely the identity client, so i think that change is still worth merging.
In the logs you shared, the scope |
We currently build the identity client at startup and hold it to be used fairly infrequently: the client is used once per day by default, and even in extremely aggressive scenarios is unlikely to be used more frequently than once every few minutes. As such, there's very little benefit to holding the client (and buffers, DNS resolutions, etc) open continually. Instead, it seems preferable to instantiate the identity client only as it's needed. Practically, we see issues like linkerd/linkerd2#6184 where the identity client may try to reconnect to stale endpoints when the identity deployment is rescheduled (because there aren't a steady stream of requests on this client). This change makes the controller stack a `NewService<()>` so that clients can be instantiated lazily. The identity module now creates a new connection for each identity request. Other controller clients are unaffacted, continuing to use long-live clients.
|
I installed I also have the suspicion that the following statement is not true, as some
I also have the suspicion that this happens only if the meshed HTTP client is reusing the same TCP connection for multiple requests (e.g. HTTP 1.1 without Note, this is a serious problem! Whenever an IP address is reassigned to a new Pod which is listening on the same port as the one of the stale resolve, traffic is successfully routed to the wrong Pod by the outbound
To recap, this is not just about stale targets it is also about routing traffic to the wrong target as IP addresses are reassigned to (reused by) new Pods. And this happens all the time on our clusters, so it is not a weird edge case it's the default. Maybe this is a classical over-optimization trap, where we are victims of caching (reusing old information) instead of resolving destinations with each request (or at least once per N seconds). Whatever is the cause of this, IMHO linkerd should prioritize correctness over performance. |
|
I think I managed to identify one specific use-case where this happens. Having long-lived gRPC connections the outbound
I would expect that the |
|
OK, I think this sounds like a plausible thesis about the behavior. Looking at our error-handling, I see that we may not properly teardown connections when HTTP/2 is being used: Here, we only return a stream-level reset when the error includes a h2 stream reset information. I'd be curious if we see the "Propagating HTTP2 reset" message. If we see that message logged, then we need to do more inspecting of the h2 reset to determine whether the connection can be torn down. But that may not even be enough to totally eliminate this... I could imagine a scenario where, if the IP is recycled quickly enough, it would be indistinguishable from a temporary network interruption. We can probably reproduce parts of this issue given the information we have, but I'm not sure how we can make a kubernetes cluster reuse IPs reliably in tests to cover the whole scenario you're seeing... Anyway, I think we have enough information to dig into a fix; but it's going to be tricky to get full integration tests to cover this. |
olix0r
added
priority/P0
|
OK, I'm able to reproduce this with emojivoto. It seems specific to ingress-mode, which is a little surprising to me, but at least it's a solid lead: In a k3s cluster with the latest edge release installed. I've configured the voting and emoji services with In both cases, I watched the web logs While restarting the voting service: With That is, the failfast error causes an error that triggers the application's client connection to be torn down so it re-resolves the target. With Full manifests and log files here. |
The ingress-mode proxy's forwarding stack--used when a request does not set the `l5d-dst-override` header--has no failfast implemetation. This means that when a connection can't be obtained for the endpoint, requests are buffered indefinitely. This change adds a failfast layer so that these requests are failed eagerly after 3s of unavailability, causing the serverside connection to be dropped (so that the application client may re-resolve the endpoint). This is really a temporary solution. We should probably avoid implementing reconnection at all in this case so that connection errors can be used in place of failfast errors. Related to linkerd/linkerd2#6184
|
@olix0r I wanted to test your changes, but was not able to pull the image |
|
@alex-berger 🤦 helps if i actually push the image, sorry. |
|
@olix0r First tests look promising, the temporary solution introduced by c49488c makes the system resilient again. As you mentioned it is not a perfect/permanent solution but at least the system is now self-healing and will recover fast (within ~10 seconds) when the gloo xDS control plane is restarted. |
|
@alex-berger yeah, I think we can introduce the temporary fix until we've modified the reconnect logic (some changes to set this up are already in-flight). |
The ingress-mode proxy's forwarding stack--used when a request does not set the `l5d-dst-override` header--has no failfast implemetation. This means that when a connection can't be obtained for the endpoint, requests are buffered indefinitely. This change adds a failfast layer so that these requests are failed eagerly after 3s of unavailability, causing the serverside connection to be dropped (so that the application client may re-resolve the endpoint). This is really a temporary solution. We should probably avoid implementing reconnection at all in this case so that connection errors can be used in place of failfast errors. Related to linkerd/linkerd2#6184
olix0r
added
priority/P1
|
@olix0r We're suffering from the same bug I guess, but our Linkerd-proxy is operating on default mode and not ingress we do use l5d-dst-override headers. Does the temp fix affect it also? |
|
@AlonGluz Can you please open a new issue with as many relevant details as possible? Thanks. |
|
This issue has been automatically marked as stale because it has not had recent activity. It will be closed in 14 days if no further activity occurs. Thank you for your contributions. |
Bug Report
While testing #6157 and #6146 I observed another occurrence of the
linkerd-proxytrying to connect to stale (no longer existing) endpoints.What is the issue?
One of our meshed ingress gateways (running in ingress mode) tries to connect to a stale linkerd-identity address
10.40.25.18:8080. That IP address is currently not in use by any Pod, but the affectedlinkerd-proxyinstance keeps on trying to connect to it, which is visible from the log as well as fromstracetrace below.Note, this only affects one single
linkerd-proxysidecar instance in our cluster, which is suspicious and looks like some bad state (race condition) thingy.How can it be reproduced?
Logs, error output, etc
Linkerd-proxy log message:
The full log is available from this gist.
Linkerd-proxy strace excerpt:
linkerd checkoutputEnvironment
ghcr.io/olix0r/l2-proxy:a07b33d7LINKERD2_PROXY_CORES=2Possible solution
Additional context
The text was updated successfully, but these errors were encountered: