Istio "Error dispatching received data: http/1.1 protocol error: unsupported transfer encoding&-CodePudding

Our microservice(in Kotlin, ktor) is served by Apache Tomcat, all works fine until it was deployed to a Kubernetes cluster with Istio and we came across the below scenario:

The below request fails only when the request contains the HTTP header Accept-Encoding = gzip, deflate, and then the server (Tomcat) cannot determine the Content-Length and sends back the HTTP header Transfer-Encoding = chunked.

The above is a very specific scenario that fails, everything else is fine.

Request:

curl -X GET "https://our-service-endpoint-in-k8s.xxxx.xx/swagger-ui/index.html?url=/v1/static/openapi.yaml" -v -H 'Accept-Encoding: gzip' --verbose

Response: 502 Bad Gateway

Envoy-sidecar trace log

{"level":"debug","time":"2022-06-28T17:36:21.396891Z","scope":"envoy http","msg":"[C10646] new stream"}
{"level":"debug","time":"2022-06-28T17:36:21.396994Z","scope":"envoy http","msg":"[C10646][S4095485723991115281] request headers complete (end_stream=true):\n':authority', 'our-service-endpoint-in-k8s.xxxx.xx'\n':path', '/swagger-ui/index.html?url=/v1/static/openapi.yaml'\n':method', 'GET'\n'user-agent', 'curl/7.78.0'\n'accept', '*/*'\n'accept-encoding', 'gzip'\n'x-forwarded-for', '10.4.33.163'\n'x-forwarded-proto', 'https'\n'x-envoy-internal', 'true'\n'x-request-id', '6744594b-bf13-4332-afa2-ef6d11c477ac'\n'x-envoy-decorator-operation', 'xxxx-data-service-xxxx-platform-data-service.xxxx-platform.svc.cluster.local:80/*'\n'x-envoy-peer-metadata', 'ChQKDkFQUF9DT05UQUlORVJTEgIaAAoaCgpDTFVTVEVSX0lEEgwaCkt1YmVybmV0ZXMKGQoNSVNUSU9fVkVSU0lPThIIGgYxLjEwLjQKvwMKBkxBQkVMUxK0AyqxAwodCgNhcHASFhoUaXN0aW8taW5ncmVzc2dhdGV3YXkKEwoFY2hhcnQSChoIZ2F0ZXdheXMKFAoIaGVyaXRhZ2USCBoGVGlsbGVyCjYKKWluc3RhbGwub3BlcmF0b3IuaXN0aW8uaW8vb3duaW5nLXJlc291cmNlEgkaB3Vua25vd24KGQoFaXN0aW8SEBoOaW5ncmVzc2dhdGV3YXkKGQoMaXN0aW8uaW8vcmV2EgkaB2RlZmF1bHQKMAobb3BlcmF0b3IuaXN0aW8uaW8vY29tcG9uZW50EhEaD0luZ3Jlc3NHYXRld2F5cwohChFwb2QtdGVtcGxhdGUtaGFzaBIMGgo3Yzg5ZDg0NzQ2ChIKB3JlbGVhc2USBxoFaXN0aW8KOQofc2VydmljZS5pc3Rpby5pby9jYW5vbmljYWwtbmFtZRIWGhRpc3Rpby1pbmdyZXNzZ2F0ZXdheQovCiNzZXJ2aWNlLmlzdGlvLmlvL2Nhbm9uaWNhbC1yZXZpc2lvbhIIGgZsYXRlc3QKIgoXc2lkZWNhci5pc3Rpby5pby9pbmplY3QSBxoFZmFsc2UKGgoHTUVTSF9JRBIPGg1jbHVzdGVyLmxvY2FsCi8KBE5BTUUSJxolaXN0aW8taW5ncmVzc2dhdGV3YXktN2M4OWQ4NDc0Ni05am50cwobCglOQU1FU1BBQ0USDhoMaXN0aW8tc3lzdGVtCl0KBU9XTkVSElQaUmt1YmVybmV0ZXM6Ly9hcGlzL2FwcHMvdjEvbmFtZXNwYWNlcy9pc3Rpby1zeXN0ZW0vZGVwbG95bWVudHMvaXN0aW8taW5ncmVzc2dhdGV3YXkKFwoRUExBVEZPUk1fTUVUQURBVEESAioACicKDVdPUktMT0FEX05BTUUSFhoUaXN0aW8taW5ncmVzc2dhdGV3YXk='\n'x-envoy-peer-metadata-id', 'router~10.4.15.143~istio-ingressgateway-7c89d84746-9jnts.istio-system~istio-'system.svc.cluster.local'\n'x-envoy-attempt-count', '1'\n'x-b3-traceid', '201f8bd16bfaf07a386c94b62c9170bc'\n'x-b3-spanid', '386c94b62c9170bc'\n'x-b3-sampled', '0'\n"}

{"level":"debug","time":"2022-06-28T17:36:21.397016Z","scope":"envoy http","msg":"[C10646][S4095485723991115281] request end stream"}

{"level":"debug","time":"2022-06-28T17:36:21.397206Z","scope":"envoy router","msg":"[C10646][S4095485723991115281] cluster 'inbound|3000||' match for URL '/swagger-ui/index.html?url=/v1/static/openapi.yaml'"}

{"level":"debug","time":"2022-06-28T19:42:42.592226Z","scope":"envoy upstream","msg":"Using existing host 10.4.41.207:3000."}
{"level":"debug","time":"2022-06-28T19:42:42.594839Z","scope":"envoy client","msg":"[C15006] Error dispatching received data: http/1.1 protocol error: unsupported transfer encoding"}

{"level":"debug","time":"2022-06-28T17:36:21.397267Z","scope":"envoy router","msg":"[C10646][S4095485723991115281] router decoding headers:\n':authority', 'our-service-endpoint-in-k8s.xxxx.xx'\n':path', '/swagger-ui/index.html?url=/v1/static/openapi.yaml'\n':method', 'GET'\n':scheme', 'https'\n'user-agent', 'curl/7.78.0'\n'accept', '*/*'\n'accept-encoding', 'gzip'\n'x-forwarded-for', '10.4.33.163'\n'x-forwarded-proto', 'https'\n'x-request-id', '6744594b-bf13-4332-afa2-ef6d11c477ac'\n'x-envoy-attempt-count', '1'\n'x-envoy-internal', 'true'\n'x-forwarded-client-cert', 'By=spiffe://cluster.local/ns/xxxx-'platform/sa/default;Hash=cd36c5c8ec401845e1c34085fd7d5eff830d6c380d86d7ada1ec97e752afb9ee;Subject=\"\";URI=spiffe://cluster.local/ns/istio-system/sa/istio-ingressgateway-service-account'\n'x-b3-traceid', '201f8bd16bfaf07a386c94b62c9170bc'\n'x-b3-spanid', 'f45094fb567b9c3e'\n'x-b3-parentspanid', '386c94b62c9170bc'\n'x-b3-sampled', '0'\n"}

{"level":"debug","time":"2022-06-28T19:42:42.592269Z","scope":"envoy pool","msg":"queueing stream due to no available connections"}
{"level":"debug","time":"2022-06-28T19:42:42.592281Z","scope":"envoy pool","msg":"trying to create new connection"}
{"level":"debug","time":"2022-06-28T19:42:42.592285Z","scope":"envoy pool","msg":"creating a new connection"}
{"level":"debug","time":"2022-06-28T19:42:42.592333Z","scope":"envoy client","msg":"[C15006] connecting"}
{"level":"debug","time":"2022-06-28T19:42:42.592341Z","scope":"envoy connection","msg":"[C15006] connecting to 10.4.41.207:3000"}
{"level":"debug","time":"2022-06-28T19:42:42.592599Z","scope":"envoy connection","msg":"[C15006] connection in progress"}
{"level":"debug","time":"2022-06-28T19:42:42.592654Z","scope":"envoy connection","msg":"[C15006] connected"}
{"level":"debug","time":"2022-06-28T19:42:42.592659Z","scope":"envoy client","msg":"[C15006] connected"}
{"level":"debug","time":"2022-06-28T19:42:42.592665Z","scope":"envoy pool","msg":"[C15006] attaching to next stream"}
{"level":"debug","time":"2022-06-28T19:42:42.592670Z","scope":"envoy pool","msg":"[C15006] creating stream"}

{"level":"debug","time":"2022-06-28T17:36:21.397450Z","scope":"envoy router","msg":"[C10646][S4095485723991115281] pool ready"}

{"level":"debug","time":"2022-06-28T19:42:42.594839Z","scope":"envoy client","msg":"[C15006] Error dispatching received data: http/1.1 protocol error: unsupported transfer encoding"}
{"level":"debug","time":"2022-06-28T19:42:42.594858Z","scope":"envoy connection","msg":"[C15006] closing data_to_write=0 type=1"}
{"level":"debug","time":"2022-06-28T19:42:42.594862Z","scope":"envoy connection","msg":"[C15006] closing socket: 1"}
{"level":"debug","time":"2022-06-28T19:42:42.594888Z","scope":"envoy client","msg":"[C15006] disconnect. resetting 1 pending requests"}
{"level":"debug","time":"2022-06-28T19:42:42.594901Z","scope":"envoy client","msg":"[C15006] request reset"}


{"level":"debug","time":"2022-06-28T17:36:21.400730Z","scope":"envoy router","msg":"[C10646][S4095485723991115281] upstream reset: reset reason: protocol error, transport failure reason: "}

{"level":"debug","time":"2022-06-28T17:36:21.400780Z","scope":"envoy http","msg":"[C10646][S4095485723991115281] Sending local reply with details upstream_reset_before_response_started{protocol error}"}

{"level":"debug","time":"2022-06-28T17:36:21.400833Z","scope":"envoy http","msg":"[C10646][S4095485723991115281] encoding headers via codec (end_stream=false):\n':status', '502'\n'content-length', '87'\n'content-type', 'text/plain'\n'x-envoy-peer-metadata', 'CjQKDkFQUF9DT05UQUlORVJTEiIaIGNvbXBseWRhdGEtcGxhdGZvcm0tZGF0YS1zZXJ2aWNlChoKCkNMVVNURVJfSUQSDBoKS3ViZXJuZXRlcwoZCg1JU1RJT19WRVJTSU9OEggaBjEuMTAuNArhAgoGTEFCRUxTEtYCKtMCCjcKGmFwcC5rdWJlcm5ldGVzLmlvL2luc3RhbmNlEhkaF2NvbXBseWRhdGEtZGF0YS1zZXJ2aWNlCjwKFmFwcC5rdWJlcm5ldGVzLmlvL25hbWUSIhogY29tcGx5ZGF0YS1wbGF0Zm9ybS1kYXRhLXNlcnZpY2UKGQoMaXN0aW8uaW8vcmV2EgkaB2RlZmF1bHQKIQoRcG9kLXRlbXBsYXRlLWhhc2gSDBoKNzk5ZDk4NDlkZgokChlzZWN1cml0eS5pc3Rpby5pby90bHNNb2RlEgcaBWlzdGlvCkUKH3NlcnZpY2UuaXN0aW8uaW8vY2Fub25pY2FsLW5hbWUSIhogY29tcGx5ZGF0YS1wbGF0Zm9ybS1kYXRhLXNlcnZpY2UKLwojc2VydmljZS5pc3Rpby5pby9jYW5vbmljYWwtcmV2aXNpb24SCBoGbGF0ZXN0ChoKB01FU0hfSUQSDxoNY2x1c3Rlci5sb2NhbApJCgROQU1FEkEaP2NvbXBseWRhdGEtZGF0YS1zZXJ2aWNlLWNvbXBseWRhdGEtcGxhdGZvcm0tZGF0YS1zZXJ2aWNlLTdyNHdsNAoiCglOQU1FU1BBQ0USFRoTY29tcGx5ZGF0YS1wbGF0Zm9ybQqIAQoFT1dORVISfxp9a3ViZXJuZXRlczovL2FwaXMvYXBwcy92MS9uYW1lc3BhY2VzL2NvbXBseWRhdGEtcGxhdGZvcm0vZGVwbG95bWVudHMvY29tcGx5ZGF0YS1kYXRhLXNlcnZpY2UtY29tcGx5ZGF0YS1wbGF0Zm9ybS1kYXRhLXNlcnZpY2UKFwoRUExBVEZPUk1fTUVUQURBVEESAioACksKDVdPUktMT0FEX05BTUUSOho4Y29tcGx5ZGF0YS1kYXRhLXNlcnZpY2UtY29tcGx5ZGF0YS1wbGF0Zm9ybS1kYXRhLXNlcnZpY2U='\n'x-envoy-peer-metadata-id', 'sidecar~10.4.41.207~xxxx-data-service-xxxx-platform-data-service-7r4wl4.xxxx-platform~xxxx-platform.svc.cluster.local'\n'date', 'Tue, 28 Jun 2022 17:36:20 GMT'\n'server', 'istio-envoy'\n"}

Envoy-sidecar access log

{
"bytes_received":0,
"requested_server_name":"outbound_.80_._.xxxx-data-service-xxxx-platform-data-service.xxxx-platform.svc.cluster.local",
"upstream_transport_failure_reason":null,
"connection_termination_details":null,
"downstream_local_address":"10.4.41.207:3000",
"protocol":"HTTP/1.1",
"upstream_service_time":null,
"route_name":"default",
"request_id":"73ffc016-9941-450f-9524-c8b45e89b38f",
"start_time":"2022-06-28T17:55:22.314Z",
"response_flags":"UPE",
"bytes_sent":87,
"upstream_cluster":"inbound|3000||",
"method":"GET",
"upstream_local_address":"127.0.0.6:51439",
"downstream_remote_address":"10.4.15.142:0",
"path":"/swagger-ui/index.html?url=/v1/static/openapi.yaml",
"user_agent":"curl/7.78.0",
"x_forwarded_for":"10.4.15.142",
"response_code_details":"upstream_reset_before_response_started{protocol_error}",
"authority":"our-service-endpoint-in-k8s.xxxx.xx",
"duration":2,
"upstream_host":"10.4.41.207:3000",
"response_code":502
}

CodePudding user response：

Unfortunately, Envoy did not log the headers that it's processing, so we're not sure where exactly it's breaking.

Definitely, it's somewhere between the communication between Apache Tomcat(webserver) and Envoy proxy.

However, we changed the webserver from Apache Tomcat to Netty(in our Ktor/Kotlin) and it started working without any other changes.

For more details, refer: https://github.com/istio/istio/issues/39706