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

[Meghana]

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'

[Sabyasachi2k]

It’s almost always because of the certs being used on the gateway. use the complete chain. I gave a similar soltution here

ISTIO_MUTUAL for gateway

The problem we faced is you have to give the complete chain in while creating the secret. We use SIMPLE for the TLS settings but hopefully this would work for ISTIO_MUTUAL as well. assuming your cert name is mycert.pfx here is the commands to get the complete chain openssl pkcs12 -in mycert.pfx -nokeys -chain | sed -ne '/-BEGIN CERTIFICATE-/,/-END CERTIFICATE-/p' > mycert.certs.pem here is the key command. open the pem and remove the BAG attributes. openssl pkcs12 -in mycert.pfx -nocerts -n…

hope that helps.

[Meghana]

Thanks for the suggestion. But we are not using openssl for the certificates. We have installed cert-manager along with Istio SDS for cert management. So this would not have caused the issue.

[prune]

Can you please send access logs from both the ingress GW and the upstream server ?
How large is your cluster ? (nodes, services, pods)
How many of them have Istio sidecars ?

Thanks

[Meghana]

@prune , I don’t have the logs which you have requested as this issue was resolved after pod restart. But I do get this error frequently, and will try to share the logs next time when this occurs. And the cluster currently has 3 nodes, each node with 4 core CPU and autoscaling is enabled on the nodes. We have almost 15 services running in the cluster and all of them have the sidecars injected.