gRPC JWT Authentication silently failing in Istio [workaround]

KarlMutch · June 24, 2019, 6:45pm

When using JWT authentication to secure the istio-gateway I am getting the following failure.

ServerReflectionInfo rpc failed. Error code: 16, message: Origin authentication failed., debug info: {"created":"@1561400758.691920836","description":"Error received from peer ipv4:52.89.159.189:80","file":"src/core/lib/surface/call.cc","file_line":1046,"grpc_message":"Origin authentication failed.","grpc_status":16}

The Authorization I am supplying works when using my own test code.
When following the authorization debugging instructions on the website I can see that the rules are being built by the discovery container in pilot.

2019-06-24T18:18:48.690003Z     debug   rbac    building filter for HTTP listener protocol
2019-06-24T18:18:48.690027Z     debug   rbac    used RBAC v1 for HTTP filter
2019-06-24T18:18:48.690035Z     debug   rbac    checking role service-user
2019-06-24T18:18:48.690057Z     debug   rbac    generated policy for role: service-user
2019-06-24T18:18:48.690140Z     debug   rbac    generated http filter config: {policies:<key:"service-user" value:<permissions:<and_rules:<rules:<or_rules:<rules:<header:<name:":method" present_match:true > > > > rules:<or_rules:<rules:<header:<name:":path" present_match:true > > > > > > principals:<and_ids:<ids:<any:true > > > > >  <nil> {} [] 0}
2019-06-24T18:18:48.690864Z     info    rbac    built RBAC http filter for &{downstream.default.svc.cluster.local map[pod-template-hash:846654d78d version:v1 app:downstream] map[destination.name:downstream destination.namespace:default destination.user:default]}
2019-06-24T18:26:28.484541Z     debug   rbac    building filter for HTTP listener protocol
2019-06-24T18:26:28.484561Z     debug   rbac    used RBAC v1 for HTTP filter
2019-06-24T18:26:28.484569Z     debug   rbac    checking role service-user
2019-06-24T18:26:28.484587Z     debug   rbac    generated policy for role: service-user
2019-06-24T18:26:28.484655Z     debug   rbac    generated http filter config: {policies:<key:"service-user" value:<permissions:<and_rules:<rules:<or_rules:<rules:<header:<name:":method" present_match:true > > > > rules:<or_rules:<rules:<header:<name:":path" present_match:true > > > > > > principals:<and_ids:<ids:<any:true > > > > >  <nil> {} [] 0}
2019-06-24T18:26:28.485202Z     info    rbac    built RBAC http filter for &{experiment.default.svc.cluster.local map[pod-template-hash:59f8cc7b8 version:v1 app:experiment] map[destination.name:experiment destination.namespace:default destination.user:default]}

The policy appears as follows:

---
apiVersion: networking.istio.io/v1alpha3
kind: Gateway
metadata:
  name: ingress-gateway
spec:
  selector:
    istio: ingressgateway # use istio default controller
  servers:
  - port:
      number: 80
      name: http
      protocol: HTTP2
    hosts:
    - "*"
---
apiVersion: authentication.istio.io/v1alpha1
kind: Policy
metadata:
  name: experiment-auth-policy
  namespace: istio-system
spec:
  targets:
  - name: istio-ingressgateway
  peers:
  - mtls: {}
  origins:
  - jwt:
      issuer: "https://cognizant-ai.auth0.com/"
      jwksUri: "https://cognizant-ai.auth0.com/.well-known/jwks.json"
      audiences:
        - "http://api.cognizant-ai.dev/experimentsrv"
  principalBinding: USE_ORIGIN
---

I have also enabled the rbac tracing as the website advises.
However the Authorization header string which otherwise works using test code is rejected by Istio and nothing is appearing in the proxy logs for the service. I have searched for any other logs across the istio-system namespace for logs mentioning authorization and rbac but cannot see anything that might hint as to why the authorization might have failed.

Is there any other logging at the gateway that can be enabled to help diagnose the actual point at which authentication/validation failed ?

YangminZhu · June 24, 2019, 9:07pm

The error Origin authentication failed is returned by the authentication when it fails to verify the JWT token of the request and is not even handled by authorization yet, so I guess that’s why you didn’t see anything when you enabled the debug logging for rbac.

You may enable the debug logging on the ingress gateway, it should include some information about why the JWT token of the request didn’t pass the verification.

KarlMutch · June 24, 2019, 10:16pm

How do I enable debugging on the gateway ?

I have tried using the instructions found at https://istio.io/docs/ops/controlz/ to use kubectl port forward with the istio-gateway pod. For example

kubectl port-forward -n istio-system istio-ingressgateway-7467c65c6d-7l226 9876:9876

When using a browser to try and access the ControlZ page to see if I can enable debugging the server is responding with ERR_EMPTY_RESPONSE.
Are there specific instructions for enabling debugging on the gateway ?

YangminZhu · June 24, 2019, 11:18pm

The ingress gateway is just Envoy without any application, you can turn on the debug logging with:
kubectl exec $(kubectl get pods -l istio=ingressgateway -n istio-system -o jsonpath='{.items[0].metadata.name}') -c istio-proxy -n istio-system -- curl -X POST "localhost:15000/logging?filter=debug" -s

The above command enables for filter which should be enough for debugging the JWT issue here.

KarlMutch · June 25, 2019, 1:36am

Awesome getting more information …

I did a bit of code crawling but cannot find the files emitting the dynamic_metadata error in the repos I had checkout from the envoy/istio project. Can you shed any light ?

Thanks

[2019-06-25 01:18:17.843][66][info][filter] [src/istio/utils/logger.cc:82] Logger active
[2019-06-25 01:20:17.263][97][debug][filter] [src/envoy/http/mixer/filter.cc:47] Called Mixer::Filter : Filter
[2019-06-25 01:20:17.263][97][debug][filter] [src/envoy/http/mixer/filter.cc:154] Called Mixer::Filter : setDecoderFilterCallbacks
[2019-06-25 01:20:17.263][97][debug][filter] [src/envoy/http/jwt_auth/jwt_authenticator.cc:82] Jwt authentication starts
[2019-06-25 01:20:17.263][97][debug][filter] [src/envoy/http/jwt_auth/jwt_authenticator.cc:243] Jwt authentication completed with: OK
[2019-06-25 01:20:17.263][97][debug][filter] [src/envoy/http/jwt_auth/jwt_authenticator.cc:246] The value of allow_missing_or_failed in AuthFilterConfig is: true
[2019-06-25 01:20:17.263][97][debug][filter] [src/envoy/http/jwt_auth/http_filter.cc:61] JwtVerificationFilter::onDone with status OK
[2019-06-25 01:20:17.263][97][debug][filter] [src/envoy/http/authn/http_filter.cc:54] AuthenticationFilter::decodeHeaders with config
policy {
  origins {
    jwt {
      issuer: "https://cognizant-ai.auth0.com/"
      audiences: "http://api.cognizant-ai.dev/experimentsrv"
      jwks_uri: "https://cognizant-ai.auth0.com/.well-known/jwks.json"
    }
  }
  principal_binding: USE_ORIGIN
}
jwt_output_payload_locations {
  key: "https://cognizant-ai.auth0.com/"
  value: "istio-sec-9d5f190b268dc1b70527ed9a4f5167e1e41f5ed3"
}

[2019-06-25 01:20:17.263][97][debug][filter] [src/envoy/http/authn/peer_authenticator.cc:36] No method defined. Skip source authentication.
[2019-06-25 01:20:17.263][97][debug][filter] [src/envoy/http/authn/origin_authenticator.cc:52] Got request path /grpc.reflection.v1alpha.ServerReflection/ServerReflectionInfo
[2019-06-25 01:20:17.263][97][debug][filter] [src/envoy/http/authn/origin_authenticator.cc:66] Validating request path /grpc.reflection.v1alpha.ServerReflection/ServerReflectionInfo for
jwt issuer: "https://cognizant-ai.auth0.com/"
audiences: "http://api.cognizant-ai.dev/experimentsrv"
jwks_uri: "https://cognizant-ai.auth0.com/.well-known/jwks.json"

[2019-06-25 01:20:17.263][97][debug][filter] [src/envoy/http/authn/filter_context.cc:81] No dynamic_metadata found for filter jwt-auth
[2019-06-25 01:20:17.263][97][debug][filter] [src/envoy/http/authn/origin_authenticator.cc:85] Origin authenticator failed
[2019-06-25 01:20:17.263][97][debug][filter] [src/envoy/http/mixer/filter.cc:141] Called Mixer::Filter : encodeHeaders 0
[2019-06-25 01:20:17.263][97][debug][filter] [src/envoy/http/authn/http_filter.cc:48] Called AuthenticationFilter : onDestroy
[2019-06-25 01:20:17.263][97][debug][filter] [src/envoy/http/mixer/filter.cc:214] Called Mixer::Filter : onDestroy state: 0
[2019-06-25 01:20:17.263][97][debug][filter] [src/envoy/http/mixer/filter.cc:228] Called Mixer::Filter : log
[2019-06-25 01:20:17.263][97][debug][filter] [./src/envoy/http/mixer/report_data.h:144] No dynamic_metadata found for filter envoy.filters.http.rbac
[2019-06-25 01:20:17.264][97][debug][filter] [src/istio/control/client_context_base.cc:140] Report attributes: attributes {
  key: "connection.mtls"
  value {
    bool_value: false
  }

philliple · June 25, 2019, 5:43pm

This is where you see [src/envoy/http/authn/filter_context.cc:81] No dynamic_metadata found for filter jwt-auth
https://github.com/istio/proxy/blob/bfc559d649acc1e3db30364a086776c74d2f4002/src/envoy/http/authn/filter_context.cc#L120.

The problem is Istio jwt filter failed to validate the request, so it did not write the result to the metadata for Istio authn filter to check. Since Istio authn filter did not find metadata from Istio jwt filter, it would not write to its metadata for RBAC filter to read. I’m not sure what went wrong, but I agree we should add more logs. I hope this helps a little.

KarlMutch · June 25, 2019, 9:11pm

I went digging a little further and turned on and off log levels until I managed to get the following additional information which seems to indicate that the Jwt Authentication did actually succeed prior to getting the error.

[2019-06-25 21:04:59.629][97][debug][filter] [src/envoy/http/jwt_auth/jwt_authenticator.cc:243] Jwt authentication completed with: OK

Does this shed any additional light ?

[2019-06-25 21:04:59.629][97][debug][filter] [src/envoy/http/mixer/filter.cc:47] Called Mixer::Filter : Filter
[2019-06-25 21:04:59.629][97][debug][filter] [src/envoy/http/mixer/filter.cc:154] Called Mixer::Filter : setDecoderFilterCallbacks
[2019-06-25 21:04:59.629][97][debug][filter] [src/envoy/http/jwt_auth/jwt_authenticator.cc:82] Jwt authentication starts
[2019-06-25 21:04:59.629][97][debug][filter] [src/envoy/http/jwt_auth/jwt_authenticator.cc:243] Jwt authentication completed with: OK
[2019-06-25 21:04:59.629][97][debug][filter] [src/envoy/http/jwt_auth/jwt_authenticator.cc:246] The value of allow_missing_or_failed in AuthFilterConfig is: true
[2019-06-25 21:04:59.629][97][debug][filter] [src/envoy/http/jwt_auth/http_filter.cc:61] JwtVerificationFilter::onDone with status OK
[2019-06-25 21:04:59.629][97][debug][filter] [src/envoy/http/authn/http_filter.cc:54] AuthenticationFilter::decodeHeaders with config
policy {
  origins {
    jwt {
      issuer: "https://cognizant-ai.auth0.com/"
      audiences: "http://api.cognizant-ai.dev/experimentsrv"
      jwks_uri: "https://cognizant-ai.auth0.com/.well-known/jwks.json"
    }
  }
  principal_binding: USE_ORIGIN
}
jwt_output_payload_locations {
  key: "https://cognizant-ai.auth0.com/"
  value: "istio-sec-9d5f190b268dc1b70527ed9a4f5167e1e41f5ed3"
}

[2019-06-25 21:04:59.629][97][debug][filter] [src/envoy/http/authn/peer_authenticator.cc:36] No method defined. Skip source authentication.
[2019-06-25 21:04:59.629][97][debug][filter] [src/envoy/http/authn/origin_authenticator.cc:52] Got request path /grpc.reflection.v1alpha.ServerReflection/ServerReflectionInfo
[2019-06-25 21:04:59.629][97][debug][filter] [src/envoy/http/authn/origin_authenticator.cc:66] Validating request path /grpc.reflection.v1alpha.ServerReflection/ServerReflectionInfo for
jwt issuer: "https://cognizant-ai.auth0.com/"
audiences: "http://api.cognizant-ai.dev/experimentsrv"
jwks_uri: "https://cognizant-ai.auth0.com/.well-known/jwks.json"

[2019-06-25 21:04:59.629][97][debug][filter] [src/envoy/http/authn/filter_context.cc:81] No dynamic_metadata found for filter jwt-auth
[2019-06-25 21:04:59.629][97][debug][filter] [src/envoy/http/authn/origin_authenticator.cc:85] Origin authenticator failed
[2019-06-25 21:04:59.629][97][debug][http] [external/envoy/source/common/http/conn_manager_impl.cc:1137] [C454][S4130852991934636687] Sending local reply with details istio_authn_access_
denied

philliple · June 25, 2019, 11:58pm

As you can see in the log, we start with Jwt authentication, then get an OK status.

github.com

istio/proxy/blob/bfc559d649acc1e3db30364a086776c74d2f4002/src/envoy/http/jwt_auth/jwt_authenticator.cc#L82


    Http::Headers::get().MethodValues.Options ==
        headers.Method()->value().getStringView() &&
    headers.Origin() && !headers.Origin()->value().empty() &&
    headers.AccessControlRequestMethod() &&
    !headers.AccessControlRequestMethod()->value().empty()) {
  ENVOY_LOG(debug, "CORS preflight request is passed through.");
  DoneWithStatus(Status::OK);
  return;
}


ENVOY_LOG(debug, "Jwt authentication starts");
std::vector<std::unique_ptr<JwtTokenExtractor::Token>> tokens;
store_.token_extractor().Extract(headers, &tokens);
if (tokens.size() == 0) {
  if (OkToBypass()) {
    DoneWithStatus(Status::OK);
  } else {
    DoneWithStatus(Status::JWT_MISSED);
  }
  return;
}

One possible reason is when the jwt filter extracts the token from headers, it gets nothing. And since you set allow_missing_or_failed to true, it’s considered success (at this filter, other filters in the pipe will validate this instead). Maybe check your requests?

divya21raj · June 26, 2019, 4:54am

Upon following that guide and going to localhost:9876, I see the following ->

E0626 10:09:59.481308 13528 portforward.go:400] an error occurred forwarding 9876 -> 9876: error forwarding port 9876 to pod 9d70cc7f5d869da7bc15688c4af61aa7398ac3e8fc442bdf170067eb180f54ea, uid : exit status 1: 2019/06/26 04:39:59 socat[22681] E connect(5, AF=2 127.0.0.1:9876, 16): Connection refused

Any ideas?

philliple · June 26, 2019, 5:13pm

I replied to your GitHub issue post. I think you want to change Envoy logs (port 15000), not the control plane (port 9876).

YangminZhu · June 27, 2019, 3:17am

I deployed a sample grpc server and the same Istio gateway, virtual service and authentication policy as you used here. Everything is working as expected for me.

The gRPC call succeeded with a valid JWT token:

/usr/local/google/home/ymzhu/Dev/grpc/bins/opt/grpc_cli call 35.188.157.61:80 helloworld.Greeter.SayHello "name: 'world'" --protofiles=helloworld/helloworld.proto --metadata authorization:"Bearer $TOKEN"
D0626 20:10:22.477413380  199663 ev_posix.cc:142]            Using polling engine: epollex
D0626 20:10:22.477536268  199663 dns_resolver.cc:339]        Using native dns resolver
D0626 20:10:22.477712486  199663 dns_resolver.cc:280]        Start resolving.
I0626 20:10:22.517947379  199663 subchannel.cc:608]          New connected subchannel at 0x5577f44fb800 for subchannel 0x7fc33c001cc0
connecting to 35.188.157.61:80
Sending client initial metadata:
authorization : Bearer eyJhbGciOiJSUzI1NiIsImtpZCI6IkRIRmJwb0lVcXJZOHQyenBBMnFYZkNtcjVWTzVaRXI0UnpIVV8tZW52dlEiLCJ0eXAiOiJKV1QifQ.eyJleHAiOjQ2ODU5ODk3MDAsImZvbyI6ImJhciIsImlhdCI6MTUzMjM4OTcwMCwiaXNzIjoidGVzdGluZ0BzZWN1cmUuaXN0aW8uaW8iLCJzdWIiOiJ0ZXN0aW5nQHNlY3VyZS5pc3Rpby5pbyJ9.CfNnxWP2tcnR9q0vxyxweaF3ovQYHYZl82hAUsn21bwQd9zP7c-LS9qd_vpdLG4Tn1A15NxfCjp5f7QNBUo-KC9PJqYpgGbaXhaGx7bEdFWjcwv3nZzvc7M__ZpaCERdwU7igUmJqYGBYQ51vr2njU9ZimyKkfDe3axcyiBZde7G6dabliUosJvvKOPcKIWPccCgefSj_GNfwIip3-SsFdlR7BtbVUcqR-yv-XOxJ3Uc1MI0tz3uMiiZcyPV7sNCU4KRnemRIMHVOfuvHsU60_GhGbiSFzgPTAa9WTltbnarTbxudb_YEOx12JiwYToeX0DCPb43W1tzIBxgm8NxUg
Received initial metadata from server:
date : Thu, 27 Jun 2019 03:10:22 GMT
server : istio-envoy
x-envoy-upstream-service-time : 4
message: "Hello world"

Rpc succeeded with OK status
I0626 20:10:22.605281607  199663 proto_reflection_descriptor_database.cc:51] ServerReflectionInfo rpc failed. Error code: 16, details: Origin authentication failed.

The gRPC call failed without JWT token:

/usr/local/google/home/ymzhu/Dev/grpc/bins/opt/grpc_cli call 35.188.157.61:80 helloworld.Greeter.SayHello "name: 'world'" --protofiles=helloworld/helloworld.proto                                        
D0626 20:09:50.069473672  199289 ev_posix.cc:142]            Using polling engine: epollex
D0626 20:09:50.069662490  199289 dns_resolver.cc:339]        Using native dns resolver
D0626 20:09:50.069829685  199289 dns_resolver.cc:280]        Start resolving.
I0626 20:09:50.110369510  199289 subchannel.cc:608]          New connected subchannel at 0x55f9e749d3b0 for subchannel 0x7fe180001cc0
connecting to 35.188.157.61:80
Received trailing metadata from server:
date : Thu, 27 Jun 2019 03:09:50 GMT
server : istio-envoy
Rpc failed with status code 16, error message: Origin authentication failed.
I0626 20:09:50.189037445  199289 proto_reflection_descriptor_database.cc:51] ServerReflectionInfo rpc failed. Error code: 16, details: Origin authentication failed.

I’m testing this in 1.2 but this should just work for previous versions.

Could you also double check if the JWT token is attached to the gRPC call correctly? Like @philliple mentioned, it looks like the JWT token is somehow not found by istio JWT filter which later triggers the error No dynamic_metadata found for filter jwt-auth.

KarlMutch · June 27, 2019, 11:56pm

Looking closely at the first example which is your working case, you do have an error after the OK. Is this expected ?

KarlMutch · June 28, 2019, 12:23am

Also what are your GRPC_ environment variables set to ?

Thanks

YangminZhu · June 28, 2019, 1:07am

The grpc_cli command line will actually send 2 requests here. One is the real request for Hello world and the other one is an internal request to get the protobuf information from the reflection service on the sever side (The gRPC server doesn’t have to implement this reflection service though).

The error in my log is expected because it’s the request to the reflection service being rejected as it doesn’t include any authorization header. The real request succeeded.

Looking at your original log, I realized it’s actually the reflection request being rejected(
ServerReflectionInfo rpc failed ...). This seems explaining everything now because it doesn’t include the authorization header at all.

I used export GRPC_VERBOSITY=DEBUG to turn on the debug logging of gRPC, I suggest you to use the latest grpc_cli (v1.12.0) as it seems the older version is not handling this case correctly.

KarlMutch · June 28, 2019, 6:57am

adding the following to the origin: -> jwt: section of the yaml configuration does workaround the problem. However the question remains should the reflection APIs be protected, and does not protecting it lead potentially to DDoS issues ?

      triggerRules:
      - excluded_paths:
          - prefix: "/grpc.reflection.v1alpha.ServerReflection/"

YangminZhu · June 28, 2019, 6:38pm

Normally you don’t need the reflection API, a gRPC server could choose not to support it at all. It’s the grpc_cli making this request. If you write your own gRPC client, I think it won’t send the reflection request in the first place.

The “workaround” is actually for grpc_cli, as istio is doing exactly the job to reject requests without valid JWT token.

Topic		Replies	Views
Istio JWT Auth - Origin authentication failed	6	3437	July 9, 2020
gRPC JWT Authentication not enforced Security	8	2432	July 2, 2019
GRPC Auth problem with GCP IAP	0	1422	April 20, 2020
Impossible to debug JWT based auth, not printing logs (1.1.8)	1	1715	July 16, 2019
gRPC Examples using Gateway, and VirtualService	7	4366	July 14, 2019

gRPC JWT Authentication silently failing in Istio [workaround]

Related topics