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]}
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 ?
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.
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 ?
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.
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
}
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.
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
As you can see in the log, we start with Jwt authentication, then get an OK status.
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?
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.
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.
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 ?
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.