JWT Filter randomly fails with error 500

[jaynis]

Describe the bug I use a the JWT Filter with a jwksUri pointing to a JWKS statically served from a nginx hosted the same cluster. This works 95% of the time, however, some requests randomly fail with an internal server error stating that the JWKS could not be reached due to a context deadline exceeded error.

This is the stacktrace:

HTTP 500 Get \"http://jwks.ambassador.svc.cluster.local/jwks.json\": context deadline exceeded
GET http://jwks.ambassador.svc.cluster.local/jwks.json
github.com/datawire/apro/lib/jwks.FetchJWKS
\tgithub.com/datawire/apro/lib/jwks/jwks.go:43
github.com/datawire/apro/cmd/amb-sidecar/filters/handler/jwthandler.validateToken
\tgithub.com/datawire/apro/cmd/amb-sidecar/filters/handler/jwthandler/jwthandler.go:150
github.com/datawire/apro/cmd/amb-sidecar/filters/handler/jwthandler.(*JWTFilter).Filter.func2
\tgithub.com/datawire/apro/cmd/amb-sidecar/filters/handler/jwthandler/jwthandler.go:62
github.com/datawire/apro/lib/oauth2/resourceserver/rfc6750.(*AuthorizationValidator).ValidateAuthorization
\tgithub.com/datawire/apro/lib/oauth2/resourceserver/rfc6750/rfc6750.go:228
github.com/datawire/apro/cmd/amb-sidecar/filters/handler/jwthandler.(*JWTFilter).Filter
\tgithub.com/datawire/apro/cmd/amb-sidecar/filters/handler/jwthandler/jwthandler.go:74
github.com/datawire/apro/cmd/amb-sidecar/filters/handler.(*FilterMux).runFilterRef
\tgithub.com/datawire/apro/cmd/amb-sidecar/filters/handler/handler.go:340
github.com/datawire/apro/cmd/amb-sidecar/filters/handler.(*FilterMux).runFilterRefs
\tgithub.com/datawire/apro/cmd/amb-sidecar/filters/handler/handler.go:281
github.com/datawire/apro/cmd/amb-sidecar/filters/handler.(*FilterMux).Filter
\tgithub.com/datawire/apro/cmd/amb-sidecar/filters/handler/handler.go:154
github.com/datawire/apro/lib/filterapi.authorizationService.Check
\tgithub.com/datawire/apro/lib/filterapi/filterapi.go:34
github.com/datawire/ambassador/pkg/api/envoy/service/auth/v2._Authorization_Check_Handler
\tgithub.com/datawire/[email protected]/pkg/api/envoy/service/auth/v2/external_auth.pb.go:555
google.golang.org/grpc.(*Server).processUnaryRPC
\tgoogle.golang.org/[email protected]/server.go:1210
google.golang.org/grpc.(*Server).handleStream
\tgoogle.golang.org/[email protected]/server.go:1533
google.golang.org/grpc.(*Server).serveStreams.func1.2
\tgoogle.golang.org/[email protected]/server.go:871
runtime.goexit
\truntime/asm_amd64.s:1374" func=github.com/datawire/apro/cmd/amb-sidecar/filters/handler/middleware.errorResponse file="github.com/datawire/apro/cmd/amb-sidecar/filters/handler/middleware/errors.go:82" CMD=amb-sidecar FILTER=jwt-filter.default PID=16 REQUEST_ID=9132431083104095873 THREAD="/http/127.0.0.1:8500"

In the logs I can also see that the HTTP client apparently fails after just a few µs. Not quite sure if this is related to the actual request or just a cache lookup.

time="2022-06-21 12:28:19.1521" level=info msg="HTTP CLIENT: NET: \"GET\" \"http://jwks.ambassador.svc.cluster.local/jwks.json\" => ERR context deadline exceeded (request duration: 2.5µs)" func="github.com/datawire/apro/cmd/amb-sidecar/filters/handler/httpclient.(*cachingRoundTripper).RoundTrip.func1" file="github.com/datawire/apro/cmd/amb-sidecar/filters/handler/httpclient/httpcache.go:103" CMD=amb-sidecar FILTER=jwt-filter.default PID=14 REQUEST_ID=7889700326996321378 THREAD="/http/127.0.0.1:8500"

Versions:

• Ambassador: 1.14.4
• Kubernetes: 1.21.7