istio-proxy 403 error:'upstream connect error or disconnect/reset before headers. reset reason: connection failure'

Question

We have deployed an application behind the istio ingress gateway and is accessible at test.domain.com/jenkinscore.We have used istio 1.4.5. The domain name is created for the istio ingress gateway service IP. As per the below logs, when we hit this URL, istio-proxy is throwing a 403 error: upstream connect error or disconnect/reset before headers. reset reason: connection failure . Below are the logs. This happens only intermittently. On re-starting the ingress gateway pod, issue gets resolved. Can anyone let us know what could be the reason for this error?

:42:20.798][46][debug][http] [external/envoy/source/common/http/conn_manager_impl.cc:259] [C2469] new stream
[Envoy (Epoch 1)] [2020-06-09 11:42:20.798][46][trace][http2] [external/envoy/source/common/http/http2/codec_impl.cc:483] [C2469] recv frame type=1
[Envoy (Epoch 1)] [2020-06-09 11:42:20.798][46][debug][http] [external/envoy/source/common/http/conn_manager_impl.cc:708] [C2469][S10386582713969444678] request headers complete (end_stream=true):
':method', 'GET'
':authority', 'test.domain.com'
':scheme', 'https'
':path', '/jenkinscore'
'cache-control', 'max-age=0'
'upgrade-insecure-requests', '1'
'user-agent', 'Mozilla/5.0 (Windows NT 10.0; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/81.0.4044.138 Safari/537.36'
'accept', 'text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.9'
'sec-fetch-site', 'cross-site'
'sec-fetch-mode', 'navigate'
'sec-fetch-user', '?1'
'sec-fetch-dest', 'document'
'accept-encoding', 'gzip, deflate, br'
'accept-language', 'en-US,en;q=0.9'

[Envoy (Epoch 1)] [2020-06-09 11:42:20.798][46][debug][http] [external/envoy/source/common/http/conn_manager_impl.cc:1257] [C2469][S10386582713969444678] request end stream
[Envoy (Epoch 1)] [2020-06-09 11:42:20.798][46][debug][jwt] [external/envoy/source/extensions/filters/http/jwt_authn/filter.cc:101] Called Filter : setDecoderFilterCallbacks
[Envoy (Epoch 1)] [2020-06-09 11:42:20.798][46][debug][filter] [src/envoy/http/mixer/filter.cc:47] Called Mixer::Filter : Filter
[Envoy (Epoch 1)] [2020-06-09 11:42:20.798][46][debug][filter] [src/envoy/http/mixer/filter.cc:148] Called Mixer::Filter : setDecoderFilterCallbacks
[Envoy (Epoch 1)] [2020-06-09 11:42:20.799][46][trace][filter] [external/envoy/source/extensions/filters/http/ext_authz/ext_authz.cc:80] [C2469][S10386582713969444678] ext_authz filter calling authorization server
[Envoy (Epoch 1)] [2020-06-09 11:42:20.799][46][debug][router] [external/envoy/source/common/router/router.cc:434] [C0][S9059969016458298666] cluster 'ext_authz' match for URL '/envoy.service.auth.v2.Authorization/Check'
[Envoy (Epoch 1)] [2020-06-09 11:42:20.799][46][debug][router] [external/envoy/source/common/router/router.cc:549] [C0][S9059969016458298666] router decoding headers:
':method', 'POST'
':path', '/envoy.service.auth.v2.Authorization/Check'
':authority', 'ext_authz'
':scheme', 'http'
'te', 'trailers'
'grpc-timeout', '10000m'
'content-type', 'application/grpc'
'x-b3-traceid', 'a4xxxx3471f0f7496063d056b2d9'
'x-b3-spanid', '7a236se1c6c190'
'x-b3-parentspanid', 'f7496063d056b2d9'
'x-b3-sampled', '0'
'x-envoy-internal', 'true'
'x-forwarded-for', '10.48.3.5'
'x-envoy-expected-rq-timeout-ms', '10000'

[Envoy (Epoch 1)] [2020-06-09 11:42:20.799][46][debug][client] [external/envoy/source/common/http/codec_client.cc:31] [C2470] connecting
[Envoy (Epoch 1)] [2020-06-09 11:42:20.799][46][debug][connection] [external/envoy/source/common/network/connection_impl.cc:711] [C2470] connecting to 127.0.0.1:10003
[Envoy (Epoch 1)] [2020-06-09 11:42:20.799][46][debug][connection] [external/envoy/source/common/network/connection_impl.cc:720] [C2470] connection in progress
[Envoy (Epoch 1)] [2020-06-09 11:42:20.799][46][debug][http2] [external/envoy/source/common/http/http2/codec_impl.cc:912] [C2470] setting stream-level initial window size to 268435456
[Envoy (Epoch 1)] [2020-06-09 11:42:20.799][46][debug][http2] [external/envoy/source/common/http/http2/codec_impl.cc:934] [C2470] updating connection-level initial window size to 268435456
[Envoy (Epoch 1)] [2020-06-09 11:42:20.799][46][debug][pool] [external/envoy/source/common/http/conn_pool_base.cc:20] queueing request due to no available connections
[Envoy (Epoch 1)] [2020-06-09 11:42:20.799][46][trace][router] [external/envoy/source/common/router/router.cc:1475] [C0][S9059969016458298666] buffering 1023 bytes
[Envoy (Epoch 1)] [2020-06-09 11:42:20.799][46][trace][http] [external/envoy/source/common/http/conn_manager_impl.cc:966] [C2469][S10386582713969444678] decode headers called: filter=0x559dc3768780 status=4
[Envoy (Epoch 1)] [2020-06-09 11:42:20.799][46][trace][http2] [external/envoy/source/common/http/http2/codec_impl.cc:424] [C2469] dispatched 441 bytes
[Envoy (Epoch 1)] [2020-06-09 11:42:20.799][46][trace][http2] [external/envoy/source/common/http/http2/codec_impl.cc:666] [C2469] about to send frame type=4, flags=0
[Envoy (Epoch 1)] [2020-06-09 11:42:20.799][46][trace][http2] [external/envoy/source/common/http/http2/codec_impl.cc:720] [C2469] send data: bytes=15
[Envoy (Epoch 1)] [2020-06-09 11:42:20.799][46][trace][connection] [external/envoy/source/common/network/connection_impl.cc:398] [C2469] writing 15 bytes, end_stream false
[Envoy (Epoch 1)] [2020-06-09 11:42:20.799][46][trace][http2] [external/envoy/source/common/http/http2/codec_impl.cc:608] [C2469] sent frame type=4
[Envoy (Epoch 1)] [2020-06-09 11:42:20.799][46][trace][http2] [external/envoy/source/common/http/http2/codec_impl.cc:666] [C2469] about to send frame type=4, flags=1
[Envoy (Epoch 1)] [2020-06-09 11:42:20.799][46][trace][http2] [external/envoy/source/common/http/http2/codec_impl.cc:720] [C2469] send data: bytes=9
[Envoy (Epoch 1)] [2020-06-09 11:42:20.799][46][trace][connection] [external/envoy/source/common/network/connection_impl.cc:398] [C2469] writing 9 bytes, end_stream false
[Envoy (Epoch 1)] [2020-06-09 11:42:20.799][46][trace][http2] [external/envoy/source/common/http/http2/codec_impl.cc:608] [C2469] sent frame type=4
[Envoy (Epoch 1)] [2020-06-09 11:42:20.799][46][trace][http2] [external/envoy/source/common/http/http2/codec_impl.cc:666] [C2469] about to send frame type=8, flags=0
[Envoy (Epoch 1)] [2020-06-09 11:42:20.799][46][trace][http2] [external/envoy/source/common/http/http2/codec_impl.cc:720] [C2469] send data: bytes=13
[Envoy (Epoch 1)] [2020-06-09 11:42:20.799][46][trace][connection] [external/envoy/source/common/network/connection_impl.cc:398] [C2469] writing 13 bytes, end_stream false
[Envoy (Epoch 1)] [2020-06-09 11:42:20.799][46][trace][http2] [external/envoy/source/common/http/http2/codec_impl.cc:608] [C2469] sent frame type=8
[Envoy (Epoch 1)] [2020-06-09 11:42:20.799][46][trace][connection] [external/envoy/source/common/network/connection_impl.cc:462] [C2469] socket event: 2
[Envoy (Epoch 1)] [2020-06-09 11:42:20.799][46][trace][connection] [external/envoy/source/common/network/connection_impl.cc:550] [C2469] write ready
[Envoy (Epoch 1)] [2020-06-09 11:42:20.799][46][trace][connection] [external/envoy/source/extensions/transport_sockets/tls/ssl_socket.cc:259] [C2469] ssl write returns: 37
[Envoy (Epoch 1)] [2020-06-09 11:42:20.799][46][trace][connection] [external/envoy/source/common/network/connection_impl.cc:462] [C2470] socket event: 3
[Envoy (Epoch 1)] [2020-06-09 11:42:20.799][46][trace][connection] [external/envoy/source/common/network/connection_impl.cc:550] [C2470] write ready
[Envoy (Epoch 1)] [2020-06-09 11:42:20.799][46][debug][connection] [external/envoy/source/common/network/connection_impl.cc:568] [C2470] delayed connection error: 111
[Envoy (Epoch 1)] [2020-06-09 11:42:20.799][46][debug][connection] [external/envoy/source/common/network/connection_impl.cc:193] [C2470] closing socket: 0
[Envoy (Epoch 1)] [2020-06-09 11:42:20.799][46][debug][client] [external/envoy/source/common/http/codec_client.cc:88] [C2470] disconnect. resetting 0 pending requests
[Envoy (Epoch 1)] [2020-06-09 11:42:20.799][46][debug][pool] [external/envoy/source/common/http/http2/conn_pool.cc:152] [C2470] client disconnected
[Envoy (Epoch 1)] [2020-06-09 11:42:20.799][46][debug][router] [external/envoy/source/common/router/router.cc:911] [C0][S9059969016458298666] upstream reset: reset reason connection failure
[Envoy (Epoch 1)] [2020-06-09 11:42:20.799][46][debug][http] [external/envoy/source/common/http/async_client_impl.cc:93] async http request response headers (end_stream=true):
':status', '200'
'content-type', 'application/grpc'
'grpc-status', '14'
'grpc-message', 'upstream connect error or disconnect/reset before headers. reset reason: connection failure'

[Envoy (Epoch 1)] [2020-06-09 11:42:20.799][46][trace][filter] [external/envoy/source/extensions/filters/http/ext_authz/ext_authz.cc:244] [C2469][S10386582713969444678] ext_authz filter rejected the request with an error. Response status code: 403
[Envoy (Epoch 1)] [2020-06-09 11:42:20.799][46][debug][http] [external/envoy/source/common/http/conn_manager_impl.cc:1354] [C2469][S10386582713969444678] Sending local reply with details ext_authz_error
[Envoy (Epoch 1)] [2020-06-09 11:42:20.799][46][trace][http] [external/envoy/source/common/http/conn_manager_impl.cc:1441] [C2469][S10386582713969444678] encode headers called: filter=0x559dc3646d20 status=0
[Envoy (Epoch 1)] [2020-06-09 11:42:20.799][46][trace][http] [external/envoy/source/common/http/conn_manager_impl.cc:1441] [C2469][S10386582713969444678] encode headers called: filter=0x559dc3554730 status=0
[Envoy (Epoch 1)] [2020-06-09 11:42:20.799][46][debug][filter] [src/envoy/http/mixer/filter.cc:135] Called Mixer::Filter : encodeHeaders 0
[Envoy (Epoch 1)] [2020-06-09 11:42:20.799][46][trace][http] [external/envoy/source/common/http/conn_manager_impl.cc:1441] [C2469][S10386582713969444678] encode headers called: filter=0x559dc35ce1e0 status=0
[Envoy (Epoch 1)] [2020-06-09 11:42:20.799][46][debug][http] [external/envoy/source/common/http/conn_manager_impl.cc:1552] [C2469][S10386582713969444678] encoding headers via codec (end_stream=true):
':status', '403'
'date', 'Tue, 09 Jun 2020 11:42:20 GMT'
'server', 'istio-envoy'

Answer 1

As I mentioned in comments

Envoy documentation says that

status_on_error Sets the HTTP status that is returned to the client when there is a network error between the filter and the authorization server. The default status is HTTP 403 Forbidden.

As mentioned here

The External authorization filter calls an authorization service to check if the incoming request is authorized or not. The filter can be either configured as a network filter, or as a HTTP filter or both. If the request is deemed unauthorized by the network filter then the connection will be closed. If the request is deemed unauthorized at the HTTP filter the request will be denied with 403 (Forbidden) response.

---

Recently I found that tutorial which might be helpful, as they setup an external authorization server for istio.

In this setup, the ingresss-gateway will first send the inbound request headers to another istio service which check the header values submitted by the remote user/client. If the header values passes some criteria, the external authorization server will instruct the authorization server to proceed with the request upstream.

I would suggest to take a look at this tutorial and check if everything in istio and external authorization is configured correct.

Tip -> It is recommended that these filters are configured as the first filter in the filter chain so that requests are authorized prior to rest of the filters processing the request.

The external authorization service cluster may be either statically configured or configured via the Cluster Discovery Service. If the external service is not available when a request comes in then whether the request is authorized or not is defined by the configuration setting of failure_mode_allow configuration in the applicable network filter or HTTP filter. If it is set to true then the request will be permitted (fail open) otherwise it will be denied. The default setting is false.

---

One more thing which came to my mind might be failure mode, if grpc service get upstream connect error or disconnect/reset before headers. reset reason: connection failure, in istio it´s 503 error. So if you take a look at below point 2, ext-authz will reject client requests and return a Forbidden response if the communication the authorization service has returned a HTTP 5xx error. So maybe worth to try to change it to true? It should be possible to do with envoy filter.

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.

---

Hope this helps.