istio: Some HTTP/2 requests fail with duplicate value in envoy authority request header

Is this the right place to submit this?

This is not a security vulnerability or a crashing bug
This is not a question about how to use Istio

Bug Description

Hi all,

I am using SAP BTP Kyma and hitting a truly strange situation. I’m at a bit of a loss as to why this issue is occurring, but it seems it might be occurring between Kyma and Istio, and since there are differing areas of expertise in those repos, I am cross-posting this issue in both repositories and linking them together (not something I’d typically do.)

Background

We use SAP BTP Kyma, which uses Istio:

Kubernetes v1.26.9
Istio v1.19.3

Within Kyma, we are using an API Rule to allow traffic. It is a very broad rule currently, allowing put/get/post/delete requests across .*

Kyma, as I understand, uses Istio VirtualServices to work with a single kyma-gateway.

I am newer to troubleshooting both Istio and Kyma, so I don’t want anyone to assume that I know something I don’t; let me know if I’m missing something conceptually.

The Problem

All HTTP/1.x requests to our app succeed. However, some HTTP/2 requests succeed, and some do not.

I can make HTTP/2 requests via Insomnia (on Windows) or curl (via WSL) and receive a successful response.
In some cases, with some clients – Apidog on Windows, or an SAP environment that’s making an HTTP/1.1 request and wrapping it in HTTP/2 – those same calls result in a 404 error (I can flip a switch for HTTP/2 support on/off on the client and it will work when not an HTTP/2 request). Same body, same URL, same content-type, etc. etc.

After a bunch of troubleshooting and getting deeper into the Istio logs, I noticed a pattern.

In the requests that fail, the authority header within istio seems to be duplicated. E.g. if the correct authority is xyz, the value being shown in the logs is xyz,xyz. Requests that fail seem to consistently have this occur, and I have never seen it occur in a successful request.

I am having difficulty understanding whether:

The calling clients are somehow doing something they shouldn’t that’s not in the spirit of HTTP/2
The Kyma/istio integration is causing this to be duplicated
Something within Istio is causing it to be duplicated.

Logs

Istio logs for a failed request

2023-11-29T19:16:18.155693Z	debug	envoy filter external/envoy/source/extensions/filters/listener/tls_inspector/tls_inspector.cc:137	tls:onServerName(), requestedServerName: cip.REDACTED.kyma.ondemand.com	thread=24
2023-11-29T19:16:18.203382Z	debug	envoy http2 external/envoy/source/common/http/http2/codec_impl.cc:1605	[Tags: "ConnectionId":"1735723"] updating connection-level initial window size to 268435456	thread=24
2023-11-29T19:16:18.204324Z	debug	envoy http external/envoy/source/common/http/conn_manager_impl.cc:378	[Tags: "ConnectionId":"1735723"] new stream	thread=24
2023-11-29T19:16:18.204510Z	debug	envoy http external/envoy/source/common/http/conn_manager_impl.cc:1165	[Tags: "ConnectionId":"1735723","StreamId":"511241007191140157"] request headers complete (end_stream=false):
':method', 'POST'
':scheme', 'https'
':path', '/api/SvcRequest/ProcessServiceRequest'
':authority', 'cip.REDACTED.kyma.ondemand.com,cip.REDACTED.kyma.ondemand.com'
'content-type', 'application/xml; charset=utf-8'
'content-length', '1816'
'accept', 'application/xml'
'authorization', 'Bearer REDACTED'
'user-agent', 'SAP NetWeaver Application Server (1.0;757)'
'accept-encoding', 'gzip, br'
	thread=24
2023-11-29T19:16:18.204576Z	debug	envoy connection external/envoy/source/common/network/connection_impl.h:98	[C1735723] current connecting state: false	thread=24
2023-11-29T19:16:18.204632Z	debug	envoy filter source/extensions/filters/http/alpn/alpn_filter.cc:61	cannot find route entry	thread=24
2023-11-29T19:16:18.204655Z	debug	envoy router external/envoy/source/common/router/router.cc:408	[Tags: "ConnectionId":"1735723","StreamId":"511241007191140157"] no route match for URL '/api/SvcRequest/ProcessServiceRequest'	thread=24
2023-11-29T19:16:18.204669Z	debug	envoy http external/envoy/source/common/http/filter_manager.cc:946	[Tags: "ConnectionId":"1735723","StreamId":"511241007191140157"] Preparing local reply with details route_not_found	thread=24
2023-11-29T19:16:18.204711Z	debug	envoy http external/envoy/source/common/http/filter_manager.cc:988	[Tags: "ConnectionId":"1735723","StreamId":"511241007191140157"] Executing sending local reply.	thread=24
2023-11-29T19:16:18.204760Z	debug	envoy http external/envoy/source/common/http/conn_manager_impl.cc:1819	[Tags: "ConnectionId":"1735723","StreamId":"511241007191140157"] encoding headers via codec (end_stream=true):
':status', '404'
'date', 'Wed, 29 Nov 2023 19:16:17 GMT'
'server', 'istio-envoy'
	thread=24
2023-11-29T19:16:18.204775Z	debug	envoy http external/envoy/source/common/http/conn_manager_impl.cc:237	[Tags: "ConnectionId":"1735723","StreamId":"511241007191140157"] doEndStream() resetting stream	thread=24
2023-11-29T19:16:18.204783Z	debug	envoy http external/envoy/source/common/http/conn_manager_impl.cc:1888	[Tags: "ConnectionId":"1735723","StreamId":"511241007191140157"] stream reset: reset reason: local reset, response details: -	thread=24
2023-11-29T19:16:18.204851Z	debug	envoy http2 external/envoy/source/common/http/http2/codec_impl.cc:1225	[Tags: "ConnectionId":"1735723"] sent reset code=0	thread=24
2023-11-29T19:16:18.204881Z	debug	envoy http2 external/envoy/source/common/http/http2/codec_impl.cc:1350	[Tags: "ConnectionId":"1735723"] stream 1 closed: 0	thread=24

Istio logs for a successful request

2023-11-29T18:01:12.409335Z	debug	envoy filter external/envoy/source/extensions/filters/listener/tls_inspector/tls_inspector.cc:137	tls:onServerName(), requestedServerName: cip.REDACTED.kyma.ondemand.com	thread=23
2023-11-29T18:01:12.446095Z	debug	envoy http2 external/envoy/source/common/http/http2/codec_impl.cc:1605	[Tags: "ConnectionId":"1733026"] updating connection-level initial window size to 268435456	thread=23
2023-11-29T18:01:12.446162Z	debug	envoy http external/envoy/source/common/http/conn_manager_impl.cc:378	[Tags: "ConnectionId":"1733026"] new stream	thread=23
2023-11-29T18:01:12.446285Z	debug	envoy http external/envoy/source/common/http/conn_manager_impl.cc:1165	[Tags: "ConnectionId":"1733026","StreamId":"16013734393669961989"] request headers complete (end_stream=false):
':method', 'POST'
':path', '/api/SvcRequest/ProcessServiceRequest'
':scheme', 'https'
':authority', 'cip.REDACTED.kyma.ondemand.com'
'content-type', 'application/xml'
'user-agent', 'SeanInsomnia/8.3.0'
'authorization', 'Bearer REDACTED'
'accept', '*/*'
'content-length', '1816'
	thread=23
2023-11-29T18:01:12.446330Z	debug	envoy connection external/envoy/source/common/network/connection_impl.h:98	[C1733026] current connecting state: false	thread=23
2023-11-29T18:01:12.446407Z	debug	envoy filter source/extensions/filters/http/alpn/alpn_filter.cc:92	override with 3 ALPNs	thread=23
2023-11-29T18:01:12.446467Z	debug	envoy router external/envoy/source/common/router/router.cc:478	[Tags: "ConnectionId":"1733026","StreamId":"16013734393669961989"] cluster 'outbound|80||cip.sct-products.svc.cluster.local' match for URL '/api/SvcRequest/ProcessServiceRequest'	thread=23
2023-11-29T18:01:12.446569Z	debug	envoy router external/envoy/source/common/router/router.cc:690	[Tags: "ConnectionId":"1733026","StreamId":"16013734393669961989"] router decoding headers:
':method', 'POST'
':path', '/api/SvcRequest/ProcessServiceRequest'
':scheme', 'https'
':authority', 'cip.REDACTED.kyma.ondemand.com'
'content-type', 'application/xml'
'user-agent', 'SeanInsomnia/8.3.0'
'authorization', 'Bearer REDACTED'
'accept', '*/*'
'content-length', '1816'
'x-forwarded-for', '10.250.0.4'
'x-forwarded-proto', 'https'
'x-envoy-internal', 'true'
'x-request-id', '144dda5d-3b6e-4d6c-8950-fd617f61f188'
'x-envoy-peer-metadata-id', 'router~100.64.0.49~istio-ingressgateway-5b96c5b95f-5vxdj.istio-system~istio-system.svc.cluster.local'
'x-envoy-peer-metadata', 'ChoKCkNMVVNURVJfSUQSDBoKS3ViZXJuZXRlcwodCgxJTlNUQU5DRV9JUFMSDRoLMTAwLjY0LjAuNDkKGQoNSVNUSU9fVkVSU0lPThIIGgYxLjE5LjMKzwMKBkxBQkVMUxLEAyrBAwodCgNhcHASFhoUaXN0aW8taW5ncmVzc2dhdGV3YXkKEwoFY2hhcnQSChoIZ2F0ZXdheXMKFAoIaGVyaXRhZ2USCBoGVGlsbGVyCjYKKWluc3RhbGwub3BlcmF0b3IuaXN0aW8uaW8vb3duaW5nLXJlc291cmNlEgkaB3Vua25vd24KGQoFaXN0aW8SEBoOaW5ncmVzc2dhdGV3YXkKGQoMaXN0aW8uaW8vcmV2EgkaB2RlZmF1bHQKMAobb3BlcmF0b3IuaXN0aW8uaW8vY29tcG9uZW50EhEaD0luZ3Jlc3NHYXRld2F5cwoxCiRwb2RzLndhcmRlbi5reW1hLXByb2plY3QuaW8vdmFsaWRhdGUSCRoHc3VjY2VzcwoSCgdyZWxlYXNlEgcaBWlzdGlvCjkKH3NlcnZpY2UuaXN0aW8uaW8vY2Fub25pY2FsLW5hbWUSFhoUaXN0aW8taW5ncmVzc2dhdGV3YXkKLwojc2VydmljZS5pc3Rpby5pby9jYW5vbmljYWwtcmV2aXNpb24SCBoGbGF0ZXN0CiIKF3NpZGVjYXIuaXN0aW8uaW8vaW5qZWN0EgcaBWZhbHNlChoKB01FU0hfSUQSDxoNY2x1c3Rlci5sb2NhbAovCgROQU1FEicaJWlzdGlvLWluZ3Jlc3NnYXRld2F5LTViOTZjNWI5NWYtNXZ4ZGoKGwoJTkFNRVNQQUNFEg4aDGlzdGlvLXN5c3RlbQpdCgVPV05FUhJUGlJrdWJlcm5ldGVzOi8vYXBpcy9hcHBzL3YxL25hbWVzcGFjZXMvaXN0aW8tc3lzdGVtL2RlcGxveW1lbnRzL2lzdGlvLWluZ3Jlc3NnYXRld2F5CqQFChFQTEFURk9STV9NRVRBREFUQRKOBSqLBQomCgphenVyZV9OYW1lEhgaFnNob290LS1reW1hLS1jLTM1OTY0YzMKOQoyYXp1cmVfa3ViZXJuZXRlcy5pby1jbHVzdGVyLXNob290LS1reW1hLS1jLTM1OTY0YzMSAxoBMQokCh1henVyZV9rdWJlcm5ldGVzLmlvLXJvbGUtbm9kZRIDGgExCiMKGGF6dXJlX2t1YmVybmV0ZXMuaW9fYXJjaBIHGgVhbWQ2NAoaCg5henVyZV9sb2NhdGlvbhIIGgZlYXN0dXMKQgoKYXp1cmVfbmFtZRI0GjJzaG9vdC0ta3ltYS0tYy0zNTk2NGMzLWNwdS13b3JrZXItMC16My01YzRkZC1nZzc0cwpACjZhenVyZV9uZXR3b3JraW5nLmdhcmRlbmVyLmNsb3VkX25vZGUtbG9jYWwtZG5zLWVuYWJsZWQSBhoEdHJ1ZQonCh1henVyZV9ub2RlLmt1YmVybmV0ZXMuaW9fcm9sZRIGGgRub2RlCjQKCmF6dXJlX3ZtSWQSJhokZWZkZWVhN2UtODhhOC00OTA5LTlkYjItYjM5MzE5OWI1OWZmCjcKJWF6dXJlX3dvcmtlci5nYXJkZW4uc2FwY2xvdWQuaW9fZ3JvdXASDhoMY3B1LXdvcmtlci0wCjQKJGF6dXJlX3dvcmtlci5nYXJkZW5lci5jbG91ZF9jcmktbmFtZRIMGgpjb250YWluZXJkCjIKIGF6dXJlX3dvcmtlci5nYXJkZW5lci5jbG91ZF9wb29sEg4aDGNwdS13b3JrZXItMAo3Ci1henVyZV93b3JrZXIuZ2FyZGVuZXIuY2xvdWRfc3lzdGVtLWNvbXBvbmVudHMSBhoEdHJ1ZQonCg1XT1JLTE9BRF9OQU1FEhYaFGlzdGlvLWluZ3Jlc3NnYXRld2F5'
'x-envoy-expected-rq-timeout-ms', '180000'
'x-envoy-attempt-count', '1'
'x-forwarded-host', 'cip.REDACTED.kyma.ondemand.com'
	thread=23
2023-11-29T18:01:12.447195Z	debug	envoy http external/envoy/source/common/http/conn_manager_impl.cc:1148	[Tags: "ConnectionId":"1733026","StreamId":"16013734393669961989"] request end stream	thread=23
2023-11-29T18:01:12.451942Z	debug	envoy router external/envoy/source/common/router/upstream_request.cc:562	[Tags: "ConnectionId":"1733026","StreamId":"16013734393669961989"] pool ready	thread=23
2023-11-29T18:01:19.821992Z	debug	envoy router external/envoy/source/common/router/router.cc:1437	[Tags: "ConnectionId":"1733026","StreamId":"16013734393669961989"] upstream headers complete: end_stream=false	thread=23
2023-11-29T18:01:19.822329Z	debug	envoy http external/envoy/source/common/http/conn_manager_impl.cc:1819	[Tags: "ConnectionId":"1733026","StreamId":"16013734393669961989"] encoding headers via codec (end_stream=false):
':status', '200'
'content-type', 'application/xml'
'date', 'Wed, 29 Nov 2023 18:01:18 GMT'
'server', 'istio-envoy'
'x-envoy-upstream-service-time', '7375'
	thread=23
2023-11-29T18:01:19.823102Z	debug	envoy http external/envoy/source/common/http/conn_manager_impl.cc:1924	[Tags: "ConnectionId":"1733026","StreamId":"16013734393669961989"] Codec completed encoding stream.	thread=23
2023-11-29T18:01:19.823154Z	debug	envoy http2 external/envoy/source/common/http/http2/codec_impl.cc:1350	[Tags: "ConnectionId":"1733026"] stream 1 closed: 0	thread=23
2023-11-29T18:01:19.823191Z	debug	envoy http2 external/envoy/source/common/http/http2/codec_impl.cc:1414	[Tags: "ConnectionId":"1733026"] Recouping 0 bytes of flow control window for stream 1.	thread=23

As far as I can tell, the difference seems to be that when these failing requests are made, and the authority header is formatted in that way, the alpn_filter in istio can’t find the routes, and therefore there’s a 404. I’m not sure if that’s because

The header itself is badly formed and shouldn’t be in that format
The header is fine but there is some kind of matching on host that is too strict and needs to be relaxed
Something else is going on that I’m missing.

Troubleshooting So far

Many many successful and failed requests to try to reproduce the pattern
I’ve enabled more verbose logs (let me know if others would be helpful!) --level "http:debug,http2:debug,admin:debug,client:debug,connection:debug,envoy_bug:debug,filter:debug,main:debug,multi_connection:debug,quic_stream:debug,router:debug,upstream:debug"
Installed Kiali to check things out visually, look at some config validation, etc. – no issues found.

Version

istioctl: 

client version: 1.20.0
control plane version: 1.19.3
data plane version: 1.19.3 (20 proxies)

kubectl:

Client Version: v1.28.2
Server Version: v1.26.9