I am using the ext-authz filter using a cluster setting like below:
static_resources:
clusters:
- name: ext-authz
type: static
http2_protocol_options: {}
hosts:
# Host docker0 IP address.
- socket_address: { address: 172.17.0.1, port_value: 10003 }
# THIS SETTING does not seem to be honored
connect_timeout: 5s
However, Envoy still seems to use the default timeout of 200ms, by looking at the timestamps (Envoy started with loglevel=debug in my docker-compose.yml file):
[2018-10-22 12:11:36.517][39][debug][router] source/common/router/router.cc:252] [C0][S17403403242644461340] cluster 'ext-authz' match for URL '/envoy.service.auth.v2alpha.Authorization/Check'
[2018-10-22 12:11:36.517][39][debug][router] source/common/router/router.cc:303] [C0][S17403403242644461340] router decoding headers:
':method', 'POST'
':path', '/envoy.service.auth.v2alpha.Authorization/Check'
':authority', 'ext-authz'
':scheme', 'http'
'te', 'trailers'
'grpc-timeout', '200m'
'content-type', 'application/grpc'
'x-envoy-internal', 'true'
'x-forwarded-for', '172.21.0.2'
'x-envoy-expected-rq-timeout-ms', '200'
[2018-10-22 12:11:36.517][39][debug][client] source/common/http/codec_client.cc:25] [C5] connecting
[2018-10-22 12:11:36.517][39][debug][connection] source/common/network/connection_impl.cc:632] [C5] connecting to 172.17.0.1:10003
[2018-10-22 12:11:36.517][39][debug][connection] source/common/network/connection_impl.cc:641] [C5] connection in progress
[2018-10-22 12:11:36.517][39][debug][http2] source/common/http/http2/codec_impl.cc:632] [C5] setting stream-level initial window size to 268435456
[2018-10-22 12:11:36.517][39][debug][http2] source/common/http/http2/codec_impl.cc:654] [C5] updating connection-level initial window size to 268435456
[2018-10-22 12:11:36.517][39][debug][pool] source/common/http/http2/conn_pool.cc:97] [C5] creating stream
[2018-10-22 12:11:36.517][39][debug][router] source/common/router/router.cc:981] [C0][S17403403242644461340] pool ready
[2018-10-22 12:11:36.517][39][debug][connection] source/common/network/connection_impl.cc:514] [C5] connected
[2018-10-22 12:11:36.517][39][debug][client] source/common/http/codec_client.cc:63] [C5] connected
[2018-10-22 12:11:36.716][39][debug][router] source/common/router/router.cc:438] [C0][S17403403242644461340] upstream timeout
[2018-10-22 12:11:36.716][39][debug][router] source/common/router/router.cc:926] [C0][S17403403242644461340] resetting pool request
[2018-10-22 12:11:36.716][39][debug][client] source/common/http/codec_client.cc:104] [C5] request reset
[2018-10-22 12:11:36.716][39][debug][pool] source/common/http/http2/conn_pool.cc:189] [C5] destroying stream: 0 remaining
[2018-10-22 12:11:36.716][39][debug][http2] source/common/http/http2/codec_impl.cc:467] [C5] sent reset code=0
[2018-10-22 12:11:36.716][39][debug][http2] source/common/http/http2/codec_impl.cc:512] [C5] stream closed: 0
[2018-10-22 12:11:36.716][39][debug][http] source/common/http/async_client_impl.cc:94] async http request response headers (end_stream=true):
':status', '200'
'content-type', 'application/grpc'
'grpc-status', '14'
'grpc-message', 'upstream request timeout'
[2018-10-22 12:11:36.716][39][debug][filter] source/extensions/filters/http/ext_authz/ext_authz.cc:104] [C4][S8759593104547971249] ext_authz rejected the request
Am I missing something obvious here or is this a bug in Envoy?
This causes the first request to fail for me, since establishing the connection takes such a long time. Subsequent requests succeed, since they utilize a HTTP/2 persistent connection so the handshake doesn't take any time. (or at least, much less time)
The friendly people in the Envoy community helped me find the problem: https://github.com/envoyproxy/envoy/issues/4829
The problem was that connect_timeout isn't really the request timeout but specifically, the connect timeout. The documentation has now been updated to list the proper way to set the request timeout:
http_filters:
- name: envoy.ext_authz
config:
grpc_service:
envoy_grpc:
cluster_name: ext-authz
# Default is 200ms; override if your server needs e.g. warmup time.
timeout: 0.5s
With this setting in place, things work just like a charm and my initial requests are no longer failing.