Ext Authz (gRPC): Plugin denies when failure_mode_allow set to true and Auth Server responses 5xx

[kikogolk]

Title: Ext Authz (gRPC): Plugin denies when failure_mode_allow set to true and Auth Server responses 5xx

Description:
Hi!

Envoy version: v1.13.0

Not sure if this is an issue or just I misunderstood the meaning of the "failure_mode_allow" parameter in the HTTP External Authorization plugin (using grpc_service).

From following link:
https://www.envoyproxy.io/docs/envoy/v1.13.0/api-v2/config/filter/http/ext_authz/v2/ext_authz.proto#envoy-api-msg-config-filter-http-ext-authz-v2-extauthz

failure_mode_allow

(bool) Changes filter’s behaviour on errors:

    1. When set to true, the filter will accept client request even if the communication with the authorization service has failed, or if the authorization service has returned a HTTP 5xx error.

    2. When set to false, ext-authz will reject client requests and return a Forbidden response if the communication with the authorization service has failed, or if the authorization service has returned a HTTP 5xx error.

When failure_mode_allow is set to true, I am afraid the request is denied even when the External Authz server returns HTTP 5xx error. However it is working as stated in the description when the connection fails or timeout (i.e request is accepted and passed to router plugin). Checking the code, it seems the "http_service" is routing the request (as described in the documentation) but not happening the same in "grpc_service".

This is the Envoy's filter configuration I am using:

      - filters:
        - name: envoy.http_connection_manager
          config:
            codec_type: auto
            stat_prefix: ingress_http
            access_log:
              - name: envoy.file_access_log
                config:
                  path: /dev/null
            rds:
               route_config_name: local_route
               config_source:
                  path: /etc/envoy/rds.yaml
            http_filters:
              - name: envoy.ext_authz
                config:
                  grpc_service:
                    envoy_grpc:
                      cluster_name: ext-authz
                    timeout: 3s
                  clear_route_cache: true
                  status_on_error:
                    code: InternalServerError
                  with_request_body:
                    max_request_bytes: 2048
                    allow_partial_message: true
                  failure_mode_allow: true
              - name: envoy.router

When sending a request that Auth Server denies:

$ curl -v localhost:8000/service/1
*   Trying 127.0.0.1...
* TCP_NODELAY set
* Connected to localhost (127.0.0.1) port 8000 (#0)
> GET /service/1 HTTP/1.1
> Host: localhost:8000
> User-Agent: curl/7.58.0
> Accept: */*
> 
< HTTP/1.1 503 Service Unavailable
< date: Fri, 14 Feb 2020 15:46:55 GMT
< server: envoy
< content-length: 0
< 
* Connection #0 to host localhost left intact

When Auth Server query fails due to timeout (upstream answers correctly):

$ curl -v localhost:8000/service/1
*   Trying 127.0.0.1...
* TCP_NODELAY set
* Connected to localhost (127.0.0.1) port 8000 (#0)
> GET /service/1 HTTP/1.1
> Host: localhost:8000
> User-Agent: curl/7.58.0
> Accept: */*
> 
< HTTP/1.1 200 OK
< content-type: text/html; charset=utf-8
< content-length: 93
< server: envoy
< date: Fri, 14 Feb 2020 15:51:17 GMT
< x-envoy-upstream-service-time: 1
< 
Hello from behind Envoy GET (service 1)! hostname: d3ac953e9781 resolvedhostname: 172.23.0.5
* Connection #0 to host localhost left intact

I was checking this already closed issue: #4124 . Not sure then if it is an documentation issue or I am misunderstanding the proper behavior.

Thanks a lot!

[mattklein123]

@gkleiman is going to fix this.

[gkleiman]

@kikogolk are you sure that your ext authz service is responding with a 503?

I tried this using a very simple HTTP/2 server that always responds with a 503 and an empty response body and I couldn't reproduce the behavior you describe.

In my tests Envoy will allow the request and increase both the http.ingress_http.ext_authz.error and the http.ingress_http.ext_authz.failure_mode_allowed stats.

[dio]

@kikogolk could you try to run envoy with --component-log-level router:debug,http:debug turned on?

e.g.

$ envoy-c /path/to/configs/envoy/ext_authz.yaml --component-log-level router:debug,http:debug

Try to find log lines similar to:

[2020-03-10 01:45:42.165][21748][debug][http] [source/common/http/conn_manager_impl.cc:1316] [C0][S14673170453406023249] request end stream
[2020-03-10 01:45:42.166][21748][debug][router] [source/common/router/router.cc:477] [C0][S7122998583319880937] cluster 'service_ext_authz' match for URL '/envoy.service.auth.v2.Authorization/Check'
[2020-03-10 01:45:42.166][21748][debug][router] [source/common/router/router.cc:617] [C0][S7122998583319880937] router decoding headers:
':method', 'POST'
':path', '/envoy.service.auth.v2.Authorization/Check'
':authority', 'service_ext_authz'
':scheme', 'http'
'te', 'trailers'
'grpc-timeout', '3000m'
'content-type', 'application/grpc'
'x-envoy-internal', 'true'
'x-forwarded-for', '10.148.0.3'
'x-envoy-expected-rq-timeout-ms', '3000'

[2020-03-10 01:45:42.167][21748][debug][router] [source/common/router/upstream_request.cc:322] [C0][S7122998583319880937] pool ready
[2020-03-10 01:45:42.172][21748][debug][router] [source/common/router/router.cc:1118] [C0][S7122998583319880937] upstream headers complete: end_stream=false
[2020-03-10 01:45:42.173][21748][debug][http] [source/common/http/async_client_impl.cc:96] async http request response headers (end_stream=false):
':status', '500'
'content-type', 'text/plain; charset=utf-8'
'x-content-type-options', 'nosniff'
'content-length', '1'
'date', 'Tue, 10 Mar 2020 01:45:42 GMT'
'x-envoy-upstream-service-time', '5'

These lines:

[2020-03-10 01:45:42.173][21748][debug][http] [source/common/http/async_client_impl.cc:96] async http request response headers (end_stream=false):
':status', '500'

denote we received 500 HTTP status code from the "authorization" server.

Thanks!

[kikogolk]

Hi all!

Sorry for the misunderstanding, but maybe my description was not good enough. My issue is related to the gRPC Auth Server plugin, not the HTTP one.

When I said the Authz Server responses 5xx, it was the error enclosed inside the CheckResponse gRPC message. I mean, the gRPC Authz Server is responding with a Denied Check Response, setting the Http Status code to 5xx.

Here you have some logs I captured from my silly gRPC Auth Server.

The CheckRequest received from Envoy:

CHECK REQUEST: attributes {
  source {
    address {
      socket_address {
        address: "172.20.0.1"
        port_value: 51286
      }
    }
  }
  destination {
    address {
      socket_address {
        address: "172.20.0.3"
        port_value: 8888
      }
    }
  }
  request {
    time {
      seconds: 1583837115
      nanos: 587179000
    }
    http {
      id: "5561742167649911107"
      method: "POST"
      headers {
        key: ":path"
        value: "/service/2"
      }
      headers {
        key: "x-forwarded-proto"
        value: "http"
      }
      headers {
        key: "accept"
        value: "*/*"
      }
      headers {
        key: "user-agent"
        value: "curl/7.58.0"
      }
      headers {
        key: ":authority"
        value: "localhost:8000"
      }
      headers {
        key: ":method"
        value: "POST"
      }
      headers {
        key: "x-request-id"
        value: "97808ceb-f3c4-4d82-a79b-cf33e0effbb6"
      }
      path: "/service/2"
      host: "localhost:8000"
      protocol: "HTTP/1.1"
    }
  }
  context_extensions {
    key: "virtual_host"
    value: "backend"
  }
  11: {
  }
}

And the CheckResponse returned to Envoy (note the HttpStatus code was set to "ServiceUnavailable"):

CHECK RESPONSE: status {
  code: 7
}
denied_response {
  status {
    code: ServiceUnavailable
  }
}

And the logs from Envoy:

[2020-03-10 10:45:15.587][13][debug][http] [source/common/http/conn_manager_impl.cc:263] [C3] new stream
[2020-03-10 10:45:15.587][13][debug][http] [source/common/http/conn_manager_impl.cc:731] [C3][S5561742167649911107] request headers complete (end_stream=true):
':authority', 'localhost:8000'
':path', '/service/2'
':method', 'POST'
'user-agent', 'curl/7.58.0'
'accept', '*/*'

[2020-03-10 10:45:15.587][13][debug][http] [source/common/http/conn_manager_impl.cc:1276] [C3][S5561742167649911107] request end stream
[2020-03-10 10:45:15.587][13][debug][router] [source/common/router/router.cc:474] [C0][S5679559686827133584] cluster 'authz-server' match for URL '/envoy.service.auth.v2.Authorization/Check'
[2020-03-10 10:45:15.587][13][debug][router] [source/common/router/router.cc:614] [C0][S5679559686827133584] router decoding headers:
':method', 'POST'
':path', '/envoy.service.auth.v2.Authorization/Check'
':authority', 'authz-server'
':scheme', 'http'
'te', 'trailers'
'grpc-timeout', '3000m'
'content-type', 'application/grpc'
'x-envoy-internal', 'true'
'x-forwarded-for', '172.20.0.3'
'x-envoy-expected-rq-timeout-ms', '3000'

[2020-03-10 10:45:15.587][13][debug][http2] [source/common/http/http2/codec_impl.cc:900] [C4] setting stream-level initial window size to 268435456
[2020-03-10 10:45:15.587][13][debug][http2] [source/common/http/http2/codec_impl.cc:922] [C4] updating connection-level initial window size to 268435456
[2020-03-10 10:45:15.587][13][debug][router] [source/common/router/router.cc:1711] [C0][S5679559686827133584] pool ready
[2020-03-10 10:45:15.609][13][debug][router] [source/common/router/router.cc:1115] [C0][S5679559686827133584] upstream headers complete: end_stream=false
[2020-03-10 10:45:15.609][13][debug][http] [source/common/http/async_client_impl.cc:95] async http request response headers (end_stream=false):
':status', '200'
'content-type', 'application/grpc'
'grpc-encoding', 'identity'
'grpc-accept-encoding', 'gzip'
'x-envoy-upstream-service-time', '21'

[2020-03-10 10:45:15.616][13][debug][http] [source/common/http/async_client_impl.cc:121] async http request response trailers:
'grpc-status', '0'

[2020-03-10 10:45:15.617][13][debug][http] [source/common/http/conn_manager_impl.cc:1417] [C3][S5561742167649911107] Sending local reply with details ext_authz_denied
[2020-03-10 10:45:15.617][13][debug][http] [source/common/http/conn_manager_impl.cc:1615] [C3][S5561742167649911107] encoding headers via codec (end_stream=true):
':status', '503'
'x-envoy-upstream-healthchecked-cluster', 'test'
'date', 'Tue, 10 Mar 2020 10:45:15 GMT'
'server', 'envoy'

[2020-03-10 10:45:15.617][13][debug][http2] [source/common/http/http2/codec_impl.cc:732] [C4] stream closed: 0

That is why I started the post saying maybe I was not understanding properly the behavior of the "failure_mode_allow" parameter. My gRPC Auth server is responding Denied with enclosed Http Status 5xx but, as I understand how failure_mode_allow works, the request should be routed, but it is rejected by Envoy instead.

Sorry for the misunderstanding and wasting your time.

Thanks a lot.

[dio]

Yes. I think when your auth-server is able to send back a "successful response", it will fall into one of two possible states: "OK" or "Denied".

The failure itself: if the HTTP status code of the auth-server's response is not 200 (that's why @gkleiman tried to simulate the failure by sending the HTTP status code to 503), while in your case, envoy received 200 from the auth-server:

[2020-03-10 10:45:15.609][13][debug][http] [source/common/http/async_client_impl.cc:95] async http request response headers (end_stream=false):
':status', '200'

[gkleiman]

According to the CheckResponse message definition what you observe is the expect behavior:

  // Status `OK` allows the request. Any other status indicates the request should be denied.
  google.rpc.Status status = 1;

CheckResponse.denied_response.status can be used to override the status that Envoy will return, but is not used to determine whether a request should be allowed or denied.

@dio I think we can probably close this issue unless we want to improve some documentation.

[dio]

@kikogolk I'm closing this. But I encourage you to help with PR/issue to improve the docs. Thanks!