Linkerd Multicluster Authentication and HTTP Balancer failures

[mstefa27-ford]

Good morning -- my team is having an issue with linkerd multicluster and aren't sure how to fix or even diagnose the issue. The linkerd gateway pod for multicluster (namespace: linkerd-multicluster) keeps throwing these errors repeatedly (using linkerd 2.10):

[ 276.621867s] WARN ThreadId(01) inbound:accept{client.addr=:42340 target.addr=:4143}: linkerd_app_core::errors: Failed to proxy request: HTTP Balancer service in fail-fast
[ 276.634868s] INFO ThreadId(01) inbound:accept{client.addr=:30257 target.addr=:4143}: linkerd_app_core::serve: Connection closed error=Direct connections must be mutually authenticated
[ 276.656885s] INFO ThreadId(01) inbound:accept{client.addr=:19330 target.addr=:4181}: linkerd_app_core::serve: Connection closed error=identity required

We re-created the trust anchor and issuing certificates for the cluster and applied them to both clusters. Although we relinked them, and linkerd check shows multicluster everything as OK (indeed, the whole cluster shows as "OK"), we continue to see these errors and can observe connectivity issues where services on one cluster cannot query services on the other.

To us, this smells like an SSL mTLS issue since it says Direct connections must be mutually authenticated, but with completely re-generated certs, this shouldn't be an issue I think. What would we need to do / what should we check for new information?

Some discussion from Slack below (Thanks William!):

william: I’m not a multicluster expert by any means, but as a first guess, is the service itself alive and responding to requests?
william: And… did anything change recently? Was this working in the past?
Johnathan Bell: The services are alive and spitting out logs. Not sure how to tell if it's responding to requests, however.
Johnathan Bell: As far as any changes, the cert expired over the weekend, and the team did not have access to the original key, so we had to re-roll a whole new trust anchor and issuer cert.
Johnathan Bell: That's really the only thing that's changed, but since trying to re-roll the certificates, we have not yet been able to get the clusters to behave as linked
william: Ah, ok
william: So… if you regenerated the trust anchor, you will need to re-roll every meshed pod (sorry!) so that the proxy picks up the new trust anchor
william: (The trust anchor / root is provided to the proxy at startup time, and is fixed for the life of the proxy)
william: Do you think that could be the issue?
Johnathan Bell: We re-rolled all of the pods already
Johnathan Bell: Twice 😂

We've been working at this for days and at the moment, we're looking at a full reinstall of linkerd. Any advice on how we can begin to diagnose these very general errors we're getting despite linkerd check giving OK on everything?

[olix0r]

If this was a trust root issue, I'd expect the error to be different. We'd probably expect TLS validation errors. In this case, it sounds like the client isn't trying to establish TLS to the gateway.

You could try increasing the log level with an annotation like config.linkerd.io/proxy-log-level: linkerd=debug,info -- this should at least give us some more information about what's going on. I'd also be curious to see similar logs from the client. It could be the case that the destination service isn't providing the proper identity hints.

What versions of Linkerd are you running? Do linkerd check --proxy -n linkerd-multicluster and linkerd multicluster check pass in both clusters?

[mstefa27-ford]

Using linkerd 2.10 (as 2.11 had issues with getting past init which I believe are being worked on). All linkerd checks pass, including the --proxy and multicluster. We do get a warning about the version, as expected.

We did eventually find out about the proxy-log-level, but we didn't include info, so thanks! Here's the info above a HTTP Balancer error:

[   205.443289s] DEBUG ThreadId(01) inbound:accept{client.addr=10.240.0.46:64162 target.addr=255.0.57.7:4143}:direct:gateway:http{v=h2}: linkerd_app_core::errors: Closing server-side connection
[   205.443297s] DEBUG ThreadId(01) inbound:accept{client.addr=10.240.0.46:64162 target.addr=255.0.57.7:4143}:direct:gateway:http{v=h2}: linkerd_app_core::errors: Handling error with HTTP response status=503 Service Unavailable version=HTTP/2.0
[   205.443345s] DEBUG ThreadId(01) inbound:accept{client.addr=10.240.0.46:64162 target.addr=255.0.57.7:4143}:direct:gateway: linkerd_proxy_http::server: The stack is tearing down the connection
[   205.443369s] DEBUG ThreadId(01) inbound:accept{client.addr=10.240.0.46:64162 target.addr=255.0.57.7:4143}:direct:gateway:Connection{peer=Server}: h2::codec::framed_write: send frame=GoAway { error_code: NO_ERROR, last_stream_id: StreamId(2147483647) }
[   205.443381s] DEBUG ThreadId(01) inbound:accept{client.addr=10.240.0.46:64162 target.addr=255.0.57.7:4143}:direct:gateway:Connection{peer=Server}: h2::codec::framed_write: send frame=Ping { ack: false, payload: [11, 123, 162, 240, 139, 155, 254, 84] }
[   205.443400s] DEBUG ThreadId(01) inbound:accept{client.addr=10.240.0.46:64162 target.addr=255.0.57.7:4143}:direct:gateway:Connection{peer=Server}: h2::codec::framed_write: send frame=Headers { stream_id: StreamId(1), flags: (0x5: END_HEADERS | END_STREAM) }
[   205.443429s] DEBUG ThreadId(01) inbound:accept{client.addr=10.240.0.46:64162 target.addr=255.0.57.7:4143}:direct:gateway:Connection{peer=Server}: h2::codec::framed_write: send frame=Reset { stream_id: StreamId(1), error_code: CANCEL }
[   205.449163s] DEBUG ThreadId(01) inbound:accept{client.addr=10.240.0.47:57628 target.addr=255.0.57.7:4181}: linkerd_tls::server: Peeked bytes from TCP stream sz=0
[   205.449202s] DEBUG ThreadId(01) inbound:accept{client.addr=10.240.0.47:57628 target.addr=255.0.57.7:4181}: linkerd_app_inbound::require_identity: port=4181 tls=None(NoClientHello) id_required=true
[   205.449289s]  INFO ThreadId(01) inbound:accept{client.addr=10.240.0.47:57628 target.addr=255.0.57.7:4181}: linkerd_app_core::serve: Connection closed error=identity required
[   205.451197s] DEBUG ThreadId(01) inbound: linkerd_app_inbound::prevent_loop: addr=255.0.57.7:4181 self.port=4143
[   205.504303s] DEBUG ThreadId(01) inbound:accept{client.addr=10.240.0.46:63479 target.addr=255.0.57.7:4181}: linkerd_tls::server: Peeked bytes from TCP stream sz=0
[   205.504353s] DEBUG ThreadId(01) inbound:accept{client.addr=10.240.0.46:63479 target.addr=255.0.57.7:4181}: linkerd_app_inbound::require_identity: port=4181 tls=None(NoClientHello) id_required=true
[   205.504436s]  INFO ThreadId(01) inbound:accept{client.addr=10.240.0.46:63479 target.addr=255.0.57.7:4181}: linkerd_app_core::serve: Connection closed error=identity required
[   205.509231s] DEBUG ThreadId(01) inbound:accept{client.addr=10.240.0.46:64162 target.addr=255.0.57.7:4143}:direct:gateway:Connection{peer=Server}: h2::codec::framed_read: received frame=Data { stream_id: StreamId(1) }
[   205.509277s] DEBUG ThreadId(01) inbound:accept{client.addr=10.240.0.46:64162 target.addr=255.0.57.7:4143}:direct:gateway:Connection{peer=Server}: h2::codec::framed_read: received frame=Data { stream_id: StreamId(1) }
[   205.509304s] DEBUG ThreadId(01) inbound:accept{client.addr=10.240.0.46:64162 target.addr=255.0.57.7:4143}:direct:gateway:Connection{peer=Server}: h2::codec::framed_read: received frame=Headers { stream_id: StreamId(3), flags: (0x4: END_HEADERS) }
[   205.509364s] DEBUG ThreadId(01) inbound:accept{client.addr=10.240.0.46:64162 target.addr=255.0.57.7:4143}:direct:gateway:http{v=h2}: linkerd_proxy_http::orig_proto: translating HTTP2 to orig-proto: "HTTP/1.1"
[   205.509464s] DEBUG ThreadId(01) inbound:accept{client.addr=10.240.0.46:64162 target.addr=255.0.57.7:4143}:direct:gateway:http{v=h2}: tower::buffer::worker: service.ready=true processing request
[   205.509489s] DEBUG ThreadId(01) inbound:accept{client.addr=10.240.0.46:64162 target.addr=255.0.57.7:4143}:direct:gateway:http{v=h2}:gateway{target=metric-proxy.prometheus.svc.cluster.local:80 v=1.x}: linkerd_app_gateway::gateway: Passing request to outbound
[   205.509542s] DEBUG ThreadId(01) inbound:accept{client.addr=10.240.0.46:64162 target.addr=255.0.57.7:4143}:direct:gateway:http{v=h2}:gateway{target=metric-proxy.prometheus.svc.cluster.local:80 v=1.x}:logical{dst=metric-proxy.prometheus.svc.cluster.local:80}:concrete{addr=metric-proxy.prometheus.svc.cluster.local:80}: linkerd_timeout::failfast: HTTP Balancer in failfast
[   205.509571s] DEBUG ThreadId(01) inbound:accept{client.addr=10.240.0.46:64162 target.addr=255.0.57.7:4143}:direct:gateway:http{v=h2}:gateway{target=metric-proxy.prometheus.svc.cluster.local:80 v=1.x}:logical{dst=metric-proxy.prometheus.svc.cluster.local:80}: tower::buffer::worker: service.ready=true processing request
[   205.509625s]  WARN ThreadId(01) inbound:accept{client.addr=10.240.0.46:64162 target.addr=255.0.57.7:4143}:direct:gateway:http{v=h2}: linkerd_app_core::errors: Failed to proxy request: HTTP Balancer service in fail-fast

Here's some output from out mutual authentication required and identity required issues:

0.58.73:10901}: linkerd_proxy_http::client: Building HTTP client settings=H2
[   204.734792s] DEBUG ThreadId(01) inbound:accept{client.addr=10.240.0.32:5611 target.addr=255.0.57.7:4143}:direct:gateway:http{v=h2}:gateway{target=prometheus-cross.prometheus.svc.cluster.local:10910 v=h2}:logical{dst=prometheus-cross.prometheus.svc.cluster.local:10910}:concrete{addr=prometheus-cross.prometheus.svc.cluster.local:10910}:endpoint{peer.addr=255.0.58.73:10901}: linkerd_tls::client: Initiating TLS connection server.id=prometheus.prometheus.serviceaccount.identity.linkerd.cluster.local
[   204.734806s] DEBUG ThreadId(01) inbound:accept{client.addr=10.240.0.32:5611 target.addr=255.0.57.7:4143}:direct:gateway:http{v=h2}:gateway{target=prometheus-cross.prometheus.svc.cluster.local:10910 v=h2}:logical{dst=prometheus-cross.prometheus.svc.cluster.local:10910}:concrete{addr=prometheus-cross.prometheus.svc.cluster.local:10910}:endpoint{peer.addr=255.0.58.73:10901}: linkerd_proxy_transport::connect: Connecting server.addr=255.0.58.73:10901
[   204.736059s] DEBUG ThreadId(01) inbound:accept{client.addr=10.240.0.21:53664 target.addr=255.0.57.7:4143}:direct:gateway:http{v=h2}:gateway{target=metric-proxy.prometheus.svc.cluster.local:80 v=1.x}:logical{dst=metric-proxy.prometheus.svc.cluster.local:80}:concrete{addr=metric-proxy.prometheus.svc.cluster.local:80}:endpoint{peer.addr=255.0.53.17:8000}: linkerd_reconnect::service: Failed to connect error=request timed out
[   204.736089s] DEBUG ThreadId(01) inbound:accept{client.addr=10.240.0.21:53664 target.addr=255.0.57.7:4143}:direct:gateway:http{v=h2}:gateway{target=metric-proxy.prometheus.svc.cluster.local:80 v=1.x}:logical{dst=metric-proxy.prometheus.svc.cluster.local:80}:concrete{addr=metric-proxy.prometheus.svc.cluster.local:80}:endpoint{peer.addr=255.0.53.17:8000}: linkerd_reconnect::service: Recovering
[   204.737217s] DEBUG ThreadId(01) inbound:accept{client.addr=10.240.0.21:53664 target.addr=255.0.57.7:4143}:direct:gateway:http{v=h2}:gateway{target=metric-proxy.prometheus.svc.cluster.local:80 v=1.x}:logical{dst=metric-proxy.prometheus.svc.cluster.local:80}:concrete{addr=metric-proxy.prometheus.svc.cluster.local:80}:endpoint{peer.addr=255.0.29.53:8000}: linkerd_reconnect::service: Failed to connect error=request timed out
[   204.737243s] DEBUG ThreadId(01) inbound:accept{client.addr=10.240.0.21:53664 target.addr=255.0.57.7:4143}:direct:gateway:http{v=h2}:gateway{target=metric-proxy.prometheus.svc.cluster.local:80 v=1.x}:logical{dst=metric-proxy.prometheus.svc.cluster.local:80}:concrete{addr=metric-proxy.prometheus.svc.cluster.local:80}:endpoint{peer.addr=255.0.29.53:8000}: linkerd_reconnect::service: Recovering
[   204.737275s] DEBUG ThreadId(01) inbound:accept{client.addr=10.240.0.21:53664 target.addr=255.0.57.7:4143}:direct:gateway:http{v=h2}:gateway{target=metric-proxy.prometheus.svc.cluster.local:80 v=1.x}:logical{dst=metric-proxy.prometheus.svc.cluster.local:80}:concrete{addr=metric-proxy.prometheus.svc.cluster.local:80}:endpoint{peer.addr=255.0.10.36:8000}: linkerd_reconnect::service: Failed to connect error=request timed out
[   204.737285s] DEBUG ThreadId(01) inbound:accept{client.addr=10.240.0.21:53664 target.addr=255.0.57.7:4143}:direct:gateway:http{v=h2}:gateway{target=metric-proxy.prometheus.svc.cluster.local:80 v=1.x}:logical{dst=metric-proxy.prometheus.svc.cluster.local:80}:concrete{addr=metric-proxy.prometheus.svc.cluster.local:80}:endpoint{peer.addr=255.0.10.36:8000}: linkerd_reconnect::service: Recovering
[   204.737318s] DEBUG ThreadId(01) inbound:accept{client.addr=10.240.0.21:53664 target.addr=255.0.57.7:4143}:direct:gateway:http{v=h2}:gateway{target=metric-proxy.prometheus.svc.cluster.local:80 v=1.x}:logical{dst=metric-proxy.prometheus.svc.cluster.local:80}:concrete{addr=metric-proxy.prometheus.svc.cluster.local:80}:endpoint{peer.addr=255.0.15.28:8000}: linkerd_reconnect::service: Failed to connect error=request timed out
[   204.737336s] DEBUG ThreadId(01) inbound:accept{client.addr=10.240.0.21:53664 target.addr=255.0.57.7:4143}:direct:gateway:http{v=h2}:gateway{target=metric-proxy.prometheus.svc.cluster.local:80 v=1.x}:logical{dst=metric-proxy.prometheus.svc.cluster.local:80}:concrete{addr=metric-proxy.prometheus.svc.cluster.local:80}:endpoint{peer.addr=255.0.15.28:8000}: linkerd_reconnect::service: Recovering
[   204.737368s] DEBUG ThreadId(01) inbound:accept{client.addr=10.240.0.21:53664 target.addr=255.0.57.7:4143}:direct:gateway:http{v=h2}:gateway{target=metric-proxy.prometheus.svc.cluster.local:80 v=1.x}:logical{dst=metric-proxy.prometheus.svc.cluster.local:80}:concrete{addr=metric-proxy.prometheus.svc.cluster.local:80}:endpoint{peer.addr=255.0.15.29:8000}: linkerd_reconnect::service: Failed to connect error=request timed out
[   204.737380s] DEBUG ThreadId(01) inbound:accept{client.addr=10.240.0.21:53664 target.addr=255.0.57.7:4143}:direct:gateway:http{v=h2}:gateway{target=metric-proxy.prometheus.svc.cluster.local:80 v=1.x}:logical{dst=metric-proxy.prometheus.svc.cluster.local:80}:concrete{addr=metric-proxy.prometheus.svc.cluster.local:80}:endpoint{peer.addr=255.0.15.29:8000}: linkerd_reconnect::service: Recovering
[   204.738273s] DEBUG ThreadId(01) inbound:accept{client.addr=10.240.0.18:9188 target.addr=255.0.57.7:4143}: linkerd_tls::server: Peeked bytes from TCP stream sz=0
[   204.738358s]  INFO ThreadId(01) inbound:accept{client.addr=10.240.0.18:9188 target.addr=255.0.57.7:4143}: linkerd_app_core::serve: Connection closed error=Direct connections must be mutually authenticated
[   204.740155s] DEBUG ThreadId(01) inbound: linkerd_app_inbound::prevent_loop: addr=255.0.57.7:4143 self.port=4143
[   204.751002s] DEBUG ThreadId(01) inbound:accept{client.addr=10.240.0.8:14993 target.addr=255.0.57.7:4181}: linkerd_tls::server: Peeked bytes from TCP stream sz=0
[   204.751040s] DEBUG ThreadId(01) inbound:accept{client.addr=10.240.0.8:14993 target.addr=255.0.57.7:4181}: linkerd_app_inbound::require_identity: port=4181 tls=None(NoClientHello) id_required=true
[   204.751120s]  INFO ThreadId(01) inbound:accept{client.addr=10.240.0.8:14993 target.addr=255.0.57.7:4181}: linkerd_app_core::serve: Connection closed error=identity required

[olix0r]

Let's start with the easy one:

[   204.751002s] DEBUG ThreadId(01) inbound:accept{client.addr=10.240.0.8:14993 target.addr=255.0.57.7:4181}: linkerd_tls::server: Peeked bytes from TCP stream sz=0
[   204.751040s] DEBUG ThreadId(01) inbound:accept{client.addr=10.240.0.8:14993 target.addr=255.0.57.7:4181}: linkerd_app_inbound::require_identity: port=4181 tls=None(NoClientHello) id_required=true
[   204.751120s]  INFO ThreadId(01) inbound:accept{client.addr=10.240.0.8:14993 target.addr=255.0.57.7:4181}: linkerd_app_core::serve: Connection closed error=identity required

This indicates that the client is closing its write stream before any data is written on the connection (see this code). I assume these connections are coming from a gateway probe in a source cluster? It might be helpful to view logs from the service mirror and its proxy in the source cluster.

As for the 503 issue:

[   205.509542s] DEBUG ThreadId(01) inbound:accept{client.addr=10.240.0.46:64162 target.addr=255.0.57.7:4143}:direct:gateway:http{v=h2}:gateway{target=metric-proxy.prometheus.svc.cluster.local:80 v=1.x}:logical{dst=metric-proxy.prometheus.svc.cluster.local:80}:concrete{addr=metric-proxy.prometheus.svc.cluster.local:80}: linkerd_timeout::failfast: HTTP Balancer in failfast

This tells us that the balancer has no available endpoints and is eagerly failing requests without waiting for a timeout. Are there endpoints in metric-proxy.prometheus.svc.cluster.local? You can check agains the control plane in the target cluster with:

:; linkerd diagnostics endpoints metric-proxy.prometheus.svc.cluster.local:80

Does the gateway log connection errors previously? There may be something helpful in:

:; linkerd diagnostics proxy-metrics -n linkerd-multicluster deploy/linkerd-gateway | grep metric-proxy.prometheus.svc.cluster.local

[mstefa27-ford]

Thanks olix0r for taking a look at this - apparently all of these issues are indicative of our network policy not being applied to our linkerd-multicluster namespace...

After 5 days of debugging, we noticed that our network policy was looking for a label that was not included on our namespace. It looks like this label was manually applied when the cluster was created ages ago. When we reinstalled linkerd-multicluster, the namespace was deleted, hence the label was deleted too. Thus, none of the pods in linkerd-multicluster were able to talk to the rest of our cluster and vice-versa. This also means that all the linkerd checks passed (as the linkerd-multicluster could reach the other cluster), but none of the other pods could get there because they couldn't communicate with anything in the linkerd-multicluster namespace.

Perhaps we want to add a check to linkerd multicluster check to make sure linkerd proxy containers can reach linkerd-gateway?