Envoy proxy returns 502 reset reason: protocol error for upstream error 502 Bad Gateway

[shonecyx]

Bug Description

This issue is similar with #24753. Our case is using Istio as Ingress gateway and there is sidecar injection in the backend app. The problem here is that for some requests application will return 502 Bad Gateway but the client will get 502 with error msg upstream connect error or disconnect/reset before headers. reset reason: protocol error. Overall flow is as below:

Expected behavior
The client should get whatever application returned. Here the response code is not changed but the response message is confusing, it should be just 502 Bad Gateway.

Sidecar trace Log

2022-01-05T08:32:51.285810Z trace envoy http  [C397140][S5773887665609108525] decode headers called: filter=0x555b6110cee0 status=0
2022-01-05T08:32:51.285814Z trace envoy http  [C397140][S5773887665609108525] decode headers called: filter=0x555b61dd02a0 status=0
2022-01-05T08:32:51.285825Z trace envoy http  [C397140][S5773887665609108525] decode headers called: filter=0x555b611f8930 status=0
2022-01-05T08:32:51.285831Z debug envoy router  [C397140][S5773887665609108525] cluster 'inbound|10082||' match for URL '/somepath'
2022-01-05T08:32:51.285864Z debug envoy router  [C397140][S5773887665609108525] router decoding headers:
':path', '/somepath'
':method', 'GET'
':scheme', 'https'
'user-agent', 'curl/7.58.0'
'accept', '*/*'
'x-forwarded-for', '10.0.0.1'
'x-forwarded-proto', 'https'
'x-request-id', '59d0180e-ba38-4647-b849-1eacc822c0e5'
'x-envoy-attempt-count', '1'
'x-envoy-original-path', '/somepath'
'x-envoy-internal', 'true'
'x-datadog-trace-id', '6430674086367752771'
'x-datadog-parent-id', '8078618686577601494'
'x-datadog-sampling-priority', '-1'

2022-01-05T08:32:51.285872Z debug envoy pool  queueing stream due to no available connections
2022-01-05T08:32:51.285875Z debug envoy pool  trying to create new connection
2022-01-05T08:32:51.285895Z trace envoy pool  ConnPoolImplBase 0x555b60e6b380, ready_clients_.size(): 0, busy_clients_.size(): 0, connecting_clients_.size(): 0, connecting_stream_capacity_: 0, num_active_streams_: 0, pending_streams_.size(): 1 per upstream preconnect ratio: 1
2022-01-05T08:32:51.285899Z debug envoy pool  creating a new connection
2022-01-05T08:32:51.285925Z debug envoy client  [C397141] connecting
2022-01-05T08:32:51.285928Z debug envoy connection  [C397141] connecting to 127.0.0.1:10082
2022-01-05T08:32:51.285981Z debug envoy connection  [C397141] connection in progress
2022-01-05T08:32:51.285989Z trace envoy pool  not creating a new connection, shouldCreateNewConnection returned false.
2022-01-05T08:32:51.285993Z trace envoy http  [C397140][S5773887665609108525] decode headers called: filter=0x555b61d7f570 status=1
2022-01-05T08:32:51.285997Z trace envoy http  [C397140] parsed 1911 bytes
2022-01-05T08:32:51.286005Z trace envoy connection  [C397140] socket event: 2
2022-01-05T08:32:51.286006Z trace envoy connection  [C397140] write ready
2022-01-05T08:32:51.286008Z trace envoy connection  [C397141] socket event: 2
2022-01-05T08:32:51.286009Z trace envoy connection  [C397141] write ready
2022-01-05T08:32:51.286012Z debug envoy connection  [C397141] connected
2022-01-05T08:32:51.286013Z trace envoy connection  [C397141] raising connection event 2
2022-01-05T08:32:51.286015Z debug envoy client  [C397141] connected
2022-01-05T08:32:51.286021Z debug envoy pool  [C397141] attaching to next stream
2022-01-05T08:32:51.286023Z debug envoy pool  [C397141] creating stream
2022-01-05T08:32:51.286028Z debug envoy router  [C397140][S5773887665609108525] pool ready
2022-01-05T08:32:51.286042Z trace envoy connection  [C397141] writing 916 bytes, end_stream false
2022-01-05T08:32:51.286048Z trace envoy connection  [C397141] write ready
2022-01-05T08:32:51.286059Z trace envoy connection  [C397141] write returns: 916
2022-01-05T08:32:51.286063Z trace envoy connection  [C397141] socket event: 2
2022-01-05T08:32:51.286064Z trace envoy connection  [C397141] write ready
2022-01-05T08:32:51.328611Z debug envoy filter  original_dst: New connection accepted
2022-01-05T08:32:51.328671Z debug envoy filter  [C397142] new tcp proxy session
2022-01-05T08:32:51.328675Z trace envoy connection  [C397142] readDisable: disable=true disable_count=0 state=0 buffer_length=0
2022-01-05T08:32:51.328694Z debug envoy filter  [C397142] Creating connection to cluster PassthroughCluster
2022-01-05T08:32:51.328722Z debug envoy upstream  transport socket match, socket default selected for host with address 10.0.0.2:443
2022-01-05T08:32:51.328726Z debug envoy upstream  Created host 10.0.0.2:443.
2022-01-05T08:32:51.328744Z debug envoy pool  creating a new connection
2022-01-05T08:32:51.328769Z debug envoy pool  [C397143] connecting
2022-01-05T08:32:51.328773Z debug envoy connection  [C397143] connecting to 10.0.0.2:443
2022-01-05T08:32:51.328795Z debug envoy connection  [C397143] connection in progress
2022-01-05T08:32:51.328801Z debug envoy pool  queueing request due to no available connections
2022-01-05T08:32:51.328805Z debug envoy conn_handler  [C397142] new connection
2022-01-05T08:32:51.328818Z trace envoy connection  [C397142] socket event: 2
2022-01-05T08:32:51.328820Z trace envoy connection  [C397142] write ready
2022-01-05T08:32:51.328831Z debug envoy upstream  addHost() adding 10.0.0.2:443
2022-01-05T08:32:51.328908Z debug envoy upstream  membership update for TLS cluster PassthroughCluster added 1 removed 0
2022-01-05T08:32:51.328917Z debug envoy upstream  membership update for TLS cluster PassthroughCluster added 1 removed 0
2022-01-05T08:32:51.328921Z debug envoy upstream  membership update for TLS cluster PassthroughCluster added 1 removed 0
2022-01-05T08:32:51.328913Z debug envoy upstream  membership update for TLS cluster PassthroughCluster added 1 removed 0
2022-01-05T08:32:51.328934Z debug envoy upstream  membership update for TLS cluster PassthroughCluster added 1 removed 0
2022-01-05T08:32:51.328941Z debug envoy upstream  membership update for TLS cluster PassthroughCluster added 1 removed 0
2022-01-05T08:32:51.328947Z debug envoy upstream  re-creating local LB for TLS cluster PassthroughCluster
2022-01-05T08:32:51.328947Z debug envoy upstream  membership update for TLS cluster PassthroughCluster added 1 removed 0
2022-01-05T08:32:51.328953Z debug envoy upstream  membership update for TLS cluster PassthroughCluster added 1 removed 0
2022-01-05T08:32:51.328959Z debug envoy upstream  membership update for TLS cluster PassthroughCluster added 1 removed 0
2022-01-05T08:32:51.328960Z debug envoy upstream  membership update for TLS cluster PassthroughCluster added 1 removed 0
2022-01-05T08:32:51.328932Z debug envoy upstream  re-creating local LB for TLS cluster PassthroughCluster
2022-01-05T08:32:51.328968Z debug envoy upstream  membership update for TLS cluster PassthroughCluster added 1 removed 0
2022-01-05T08:32:51.328969Z debug envoy upstream  membership update for TLS cluster PassthroughCluster added 1 removed 0
2022-01-05T08:32:51.329070Z debug envoy upstream  re-creating local LB for TLS cluster PassthroughCluster
2022-01-05T08:32:51.328945Z debug envoy upstream  re-creating local LB for TLS cluster PassthroughCluster
2022-01-05T08:32:51.328945Z debug envoy upstream  membership update for TLS cluster PassthroughCluster added 1 removed 0
2022-01-05T08:32:51.329135Z debug envoy upstream  re-creating local LB for TLS cluster PassthroughCluster
2022-01-05T08:32:51.328955Z debug envoy upstream  re-creating local LB for TLS cluster PassthroughCluster
2022-01-05T08:32:51.328930Z debug envoy upstream  membership update for TLS cluster PassthroughCluster added 1 removed 0
2022-01-05T08:32:51.328963Z debug envoy upstream  re-creating local LB for TLS cluster PassthroughCluster
2022-01-05T08:32:51.328965Z debug envoy upstream  re-creating local LB for TLS cluster PassthroughCluster
2022-01-05T08:32:51.328972Z debug envoy upstream  re-creating local LB for TLS cluster PassthroughCluster
2022-01-05T08:32:51.328934Z debug envoy upstream  re-creating local LB for TLS cluster PassthroughCluster
2022-01-05T08:32:51.328976Z debug envoy upstream  membership update for TLS cluster PassthroughCluster added 1 removed 0
2022-01-05T08:32:51.328981Z debug envoy upstream  re-creating local LB for TLS cluster PassthroughCluster
2022-01-05T08:32:51.328969Z debug envoy upstream  re-creating local LB for TLS cluster PassthroughCluster
2022-01-05T08:32:51.328985Z debug envoy upstream  membership update for TLS cluster PassthroughCluster added 1 removed 0
2022-01-05T08:32:51.329245Z debug envoy upstream  re-creating local LB for TLS cluster PassthroughCluster
2022-01-05T08:32:51.328987Z debug envoy upstream  membership update for TLS cluster PassthroughCluster added 1 removed 0
2022-01-05T08:32:51.328996Z debug envoy upstream  membership update for TLS cluster PassthroughCluster added 1 removed 0
2022-01-05T08:32:51.329281Z debug envoy upstream  re-creating local LB for TLS cluster PassthroughCluster
2022-01-05T08:32:51.328989Z debug envoy upstream  membership update for TLS cluster PassthroughCluster added 1 removed 0
2022-01-05T08:32:51.328990Z debug envoy upstream  membership update for TLS cluster PassthroughCluster added 1 removed 0
2022-01-05T08:32:51.328925Z debug envoy upstream  re-creating local LB for TLS cluster PassthroughCluster
2022-01-05T08:32:51.329167Z debug envoy upstream  re-creating local LB for TLS cluster PassthroughCluster
2022-01-05T08:32:51.329220Z debug envoy upstream  re-creating local LB for TLS cluster PassthroughCluster
2022-01-05T08:32:51.329266Z debug envoy upstream  re-creating local LB for TLS cluster PassthroughCluster
2022-01-05T08:32:51.328924Z debug envoy upstream  membership update for TLS cluster PassthroughCluster added 1 removed 0
2022-01-05T08:32:51.329314Z debug envoy upstream  re-creating local LB for TLS cluster PassthroughCluster
2022-01-05T08:32:51.329391Z debug envoy upstream  re-creating local LB for TLS cluster PassthroughCluster
2022-01-05T08:32:51.329328Z debug envoy upstream  re-creating local LB for TLS cluster PassthroughCluster
2022-01-05T08:32:51.329769Z trace envoy connection  [C397143] socket event: 2
2022-01-05T08:32:51.329772Z trace envoy connection  [C397143] write ready
2022-01-05T08:32:51.329775Z debug envoy connection  [C397143] connected
2022-01-05T08:32:51.329777Z trace envoy connection  [C397143] raising connection event 2
2022-01-05T08:32:51.329784Z debug envoy pool  [C397143] assigning connection
2022-01-05T08:32:51.329789Z trace envoy connection  [C397142] readDisable: disable=false disable_count=1 state=0 buffer_length=0
2022-01-05T08:32:51.329796Z debug envoy filter  [C397142] TCP:onUpstreamEvent(), requestedServerName:
2022-01-05T08:32:51.329805Z trace envoy connection  [C397142] socket event: 3
2022-01-05T08:32:51.329807Z trace envoy connection  [C397142] write ready
2022-01-05T08:32:51.329809Z trace envoy connection  [C397142] read ready. dispatch_buffered_data=false
2022-01-05T08:32:51.329819Z trace envoy connection  [C397142] read returns: 252
2022-01-05T08:32:51.329829Z trace envoy connection  [C397142] read error: Resource temporarily unavailable
2022-01-05T08:32:51.329834Z trace envoy filter  [C397142] downstream connection received 252 bytes, end_stream=false
2022-01-05T08:32:51.329837Z trace envoy filter  Alpn Protocol Not Found. Expected istio-peer-exchange, Got
2022-01-05T08:32:51.329841Z trace envoy connection  [C397143] writing 252 bytes, end_stream false
2022-01-05T08:32:51.329845Z trace envoy connection  [C397143] socket event: 2
2022-01-05T08:32:51.329848Z trace envoy connection  [C397143] write ready
2022-01-05T08:32:51.329866Z trace envoy connection  [C397143] write returns: 252
2022-01-05T08:32:51.330288Z trace envoy connection  [C397143] socket event: 3
2022-01-05T08:32:51.330292Z trace envoy connection  [C397143] write ready
2022-01-05T08:32:51.330293Z trace envoy connection  [C397143] read ready. dispatch_buffered_data=false
2022-01-05T08:32:51.330307Z trace envoy connection  [C397143] read returns: 1460
2022-01-05T08:32:51.330350Z trace envoy connection  [C397143] read returns: 3661
2022-01-05T08:32:51.330368Z trace envoy connection  [C397143] read error: Resource temporarily unavailable
2022-01-05T08:32:51.330378Z trace envoy filter  [C397142] upstream connection received 5121 bytes, end_stream=false
2022-01-05T08:32:51.330385Z trace envoy connection  [C397142] writing 5121 bytes, end_stream false
2022-01-05T08:32:51.330399Z trace envoy connection  [C397143] socket event: 2
2022-01-05T08:32:51.330402Z trace envoy connection  [C397143] write ready
2022-01-05T08:32:51.330405Z trace envoy connection  [C397142] socket event: 2
2022-01-05T08:32:51.330407Z trace envoy connection  [C397142] write ready
2022-01-05T08:32:51.330459Z trace envoy connection  [C397142] write returns: 5121
2022-01-05T08:32:51.332131Z trace envoy connection  [C397142] socket event: 3
2022-01-05T08:32:51.332152Z trace envoy connection  [C397142] write ready
2022-01-05T08:32:51.332155Z trace envoy connection  [C397142] read ready. dispatch_buffered_data=false
2022-01-05T08:32:51.332163Z trace envoy connection  [C397142] read returns: 267
2022-01-05T08:32:51.332168Z trace envoy connection  [C397142] read error: Resource temporarily unavailable
2022-01-05T08:32:51.332174Z trace envoy filter  [C397142] downstream connection received 267 bytes, end_stream=false
2022-01-05T08:32:51.332179Z trace envoy connection  [C397143] writing 267 bytes, end_stream false
2022-01-05T08:32:51.332185Z trace envoy connection  [C397143] socket event: 2
2022-01-05T08:32:51.332187Z trace envoy connection  [C397143] write ready
2022-01-05T08:32:51.332200Z trace envoy connection  [C397143] write returns: 267
2022-01-05T08:32:51.332262Z trace envoy connection  [C397142] socket event: 3
2022-01-05T08:32:51.332264Z trace envoy connection  [C397142] write ready
2022-01-05T08:32:51.332265Z trace envoy connection  [C397142] read ready. dispatch_buffered_data=false
2022-01-05T08:32:51.332270Z trace envoy connection  [C397142] read returns: 6
2022-01-05T08:32:51.332273Z trace envoy connection  [C397142] read error: Resource temporarily unavailable
2022-01-05T08:32:51.332275Z trace envoy filter  [C397142] downstream connection received 6 bytes, end_stream=false
2022-01-05T08:32:51.332277Z trace envoy connection  [C397143] writing 6 bytes, end_stream false
2022-01-05T08:32:51.332280Z trace envoy connection  [C397143] socket event: 2
2022-01-05T08:32:51.332282Z trace envoy connection  [C397143] write ready
2022-01-05T08:32:51.332288Z trace envoy connection  [C397143] write returns: 6
2022-01-05T08:32:51.332401Z trace envoy connection  [C397142] socket event: 3
2022-01-05T08:32:51.332403Z trace envoy connection  [C397142] write ready
2022-01-05T08:32:51.332404Z trace envoy connection  [C397142] read ready. dispatch_buffered_data=false
2022-01-05T08:32:51.332407Z trace envoy connection  [C397142] read returns: 45
2022-01-05T08:32:51.332410Z trace envoy connection  [C397142] read error: Resource temporarily unavailable
2022-01-05T08:32:51.332412Z trace envoy filter  [C397142] downstream connection received 45 bytes, end_stream=false
2022-01-05T08:32:51.332413Z trace envoy connection  [C397143] writing 45 bytes, end_stream false
2022-01-05T08:32:51.332416Z trace envoy connection  [C397143] socket event: 2
2022-01-05T08:32:51.332417Z trace envoy connection  [C397143] write ready
2022-01-05T08:32:51.332423Z trace envoy connection  [C397143] write returns: 45
2022-01-05T08:32:51.335863Z trace envoy connection  [C397143] socket event: 3
2022-01-05T08:32:51.335887Z trace envoy connection  [C397143] write ready
2022-01-05T08:32:51.335890Z trace envoy connection  [C397143] read ready. dispatch_buffered_data=false
2022-01-05T08:32:51.335897Z trace envoy connection  [C397143] read returns: 51
2022-01-05T08:32:51.335903Z trace envoy connection  [C397143] read error: Resource temporarily unavailable
2022-01-05T08:32:51.335907Z trace envoy filter  [C397142] upstream connection received 51 bytes, end_stream=false
2022-01-05T08:32:51.335911Z trace envoy connection  [C397142] writing 51 bytes, end_stream false
2022-01-05T08:32:51.335917Z trace envoy connection  [C397142] socket event: 2
2022-01-05T08:32:51.335919Z trace envoy connection  [C397142] write ready
2022-01-05T08:32:51.335942Z trace envoy connection  [C397142] write returns: 51
2022-01-05T08:32:51.336772Z trace envoy connection  [C397142] socket event: 3
2022-01-05T08:32:51.336775Z trace envoy connection  [C397142] write ready
2022-01-05T08:32:51.336776Z trace envoy connection  [C397142] read ready. dispatch_buffered_data=false
2022-01-05T08:32:51.336783Z trace envoy connection  [C397142] read returns: 2876
2022-01-05T08:32:51.336788Z trace envoy connection  [C397142] read error: Resource temporarily unavailable
2022-01-05T08:32:51.336790Z trace envoy filter  [C397142] downstream connection received 2876 bytes, end_stream=false
2022-01-05T08:32:51.336792Z trace envoy connection  [C397143] writing 2876 bytes, end_stream false
2022-01-05T08:32:51.336795Z trace envoy connection  [C397143] socket event: 2
2022-01-05T08:32:51.336797Z trace envoy connection  [C397143] write ready
2022-01-05T08:32:51.336805Z trace envoy connection  [C397143] write returns: 2876
2022-01-05T08:32:51.391598Z trace envoy connection  [C397143] socket event: 3
2022-01-05T08:32:51.391620Z trace envoy connection  [C397143] write ready
2022-01-05T08:32:51.391629Z trace envoy connection  [C397143] read ready. dispatch_buffered_data=false
2022-01-05T08:32:51.391668Z trace envoy connection  [C397143] read returns: 8221
2022-01-05T08:32:51.391673Z trace envoy connection  [C397143] read error: Resource temporarily unavailable
2022-01-05T08:32:51.391677Z trace envoy filter  [C397142] upstream connection received 8221 bytes, end_stream=false
2022-01-05T08:32:51.391680Z trace envoy connection  [C397142] writing 8221 bytes, end_stream false
2022-01-05T08:32:51.391685Z trace envoy connection  [C397142] socket event: 2
2022-01-05T08:32:51.391688Z trace envoy connection  [C397142] write ready
2022-01-05T08:32:51.391738Z trace envoy connection  [C397142] write returns: 8221
2022-01-05T08:32:51.391743Z trace envoy connection  [C397143] socket event: 3
2022-01-05T08:32:51.391745Z trace envoy connection  [C397143] write ready
2022-01-05T08:32:51.391746Z trace envoy connection  [C397143] read ready. dispatch_buffered_data=false
2022-01-05T08:32:51.391760Z trace envoy connection  [C397143] read returns: 7300
2022-01-05T08:32:51.391764Z trace envoy connection  [C397143] read returns: 921
2022-01-05T08:32:51.391767Z trace envoy connection  [C397143] read error: Resource temporarily unavailable
2022-01-05T08:32:51.391769Z trace envoy filter  [C397142] upstream connection received 8221 bytes, end_stream=false
2022-01-05T08:32:51.391771Z trace envoy connection  [C397142] writing 8221 bytes, end_stream false
2022-01-05T08:32:51.391774Z trace envoy connection  [C397143] socket event: 2
2022-01-05T08:32:51.391776Z trace envoy connection  [C397143] write ready
2022-01-05T08:32:51.391777Z trace envoy connection  [C397142] socket event: 2
2022-01-05T08:32:51.391779Z trace envoy connection  [C397142] write ready
2022-01-05T08:32:51.391797Z trace envoy connection  [C397142] write returns: 8221
2022-01-05T08:32:51.392212Z trace envoy connection  [C397143] socket event: 3
2022-01-05T08:32:51.392223Z trace envoy connection  [C397143] write ready
2022-01-05T08:32:51.392243Z trace envoy connection  [C397143] read ready. dispatch_buffered_data=false
2022-01-05T08:32:51.392257Z trace envoy connection  [C397143] read returns: 8221
2022-01-05T08:32:51.392263Z trace envoy connection  [C397143] read error: Resource temporarily unavailable
2022-01-05T08:32:51.392267Z trace envoy filter  [C397142] upstream connection received 8221 bytes, end_stream=false
2022-01-05T08:32:51.392271Z trace envoy connection  [C397142] writing 8221 bytes, end_stream false
2022-01-05T08:32:51.392277Z trace envoy connection  [C397142] socket event: 2
2022-01-05T08:32:51.392279Z trace envoy connection  [C397142] write ready
2022-01-05T08:32:51.392301Z trace envoy connection  [C397142] write returns: 8221
2022-01-05T08:32:51.392323Z trace envoy connection  [C397143] socket event: 3
2022-01-05T08:32:51.392325Z trace envoy connection  [C397143] write ready
2022-01-05T08:32:51.392326Z trace envoy connection  [C397143] read ready. dispatch_buffered_data=false
2022-01-05T08:32:51.392331Z trace envoy connection  [C397143] read returns: 1460
2022-01-05T08:32:51.392334Z trace envoy connection  [C397143] read error: Resource temporarily unavailable
2022-01-05T08:32:51.392337Z trace envoy filter  [C397142] upstream connection received 1460 bytes, end_stream=false
2022-01-05T08:32:51.392339Z trace envoy connection  [C397142] writing 1460 bytes, end_stream false
2022-01-05T08:32:51.392343Z trace envoy connection  [C397142] socket event: 2
2022-01-05T08:32:51.392344Z trace envoy connection  [C397142] write ready
2022-01-05T08:32:51.392354Z trace envoy connection  [C397142] write returns: 1460
2022-01-05T08:32:51.392358Z trace envoy connection  [C397143] socket event: 3
2022-01-05T08:32:51.392360Z trace envoy connection  [C397143] write ready
2022-01-05T08:32:51.392361Z trace envoy connection  [C397143] read ready. dispatch_buffered_data=false
2022-01-05T08:32:51.392369Z trace envoy connection  [C397143] read returns: 6761
2022-01-05T08:32:51.392372Z trace envoy connection  [C397143] read error: Resource temporarily unavailable
2022-01-05T08:32:51.392374Z trace envoy filter  [C397142] upstream connection received 6761 bytes, end_stream=false
2022-01-05T08:32:51.392375Z trace envoy connection  [C397142] writing 6761 bytes, end_stream false
2022-01-05T08:32:51.392377Z trace envoy connection  [C397142] socket event: 2
2022-01-05T08:32:51.392378Z trace envoy connection  [C397142] write ready
2022-01-05T08:32:51.392395Z trace envoy connection  [C397142] write returns: 6761
2022-01-05T08:32:51.392650Z trace envoy connection  [C397143] socket event: 3
2022-01-05T08:32:51.392652Z trace envoy connection  [C397143] write ready
2022-01-05T08:32:51.392653Z trace envoy connection  [C397143] read ready. dispatch_buffered_data=false
2022-01-05T08:32:51.392657Z trace envoy connection  [C397143] read returns: 1460
2022-01-05T08:32:51.392659Z trace envoy connection  [C397143] read error: Resource temporarily unavailable
2022-01-05T08:32:51.392661Z trace envoy filter  [C397142] upstream connection received 1460 bytes, end_stream=false
2022-01-05T08:32:51.392663Z trace envoy connection  [C397142] writing 1460 bytes, end_stream false
2022-01-05T08:32:51.392665Z trace envoy connection  [C397142] socket event: 2
2022-01-05T08:32:51.392668Z trace envoy connection  [C397142] write ready
2022-01-05T08:32:51.392676Z trace envoy connection  [C397142] write returns: 1460
2022-01-05T08:32:51.392679Z trace envoy connection  [C397143] socket event: 3
2022-01-05T08:32:51.392681Z trace envoy connection  [C397143] write ready
2022-01-05T08:32:51.392682Z trace envoy connection  [C397143] read ready. dispatch_buffered_data=false
2022-01-05T08:32:51.392689Z trace envoy connection  [C397143] read returns: 6761
2022-01-05T08:32:51.392692Z trace envoy connection  [C397143] read error: Resource temporarily unavailable
2022-01-05T08:32:51.392694Z trace envoy filter  [C397142] upstream connection received 6761 bytes, end_stream=false
2022-01-05T08:32:51.392695Z trace envoy connection  [C397142] writing 6761 bytes, end_stream false
2022-01-05T08:32:51.392698Z trace envoy connection  [C397142] socket event: 2
2022-01-05T08:32:51.392700Z trace envoy connection  [C397142] write ready
2022-01-05T08:32:51.392707Z trace envoy connection  [C397142] write returns: 6761
2022-01-05T08:32:51.392908Z trace envoy connection  [C397143] socket event: 3
2022-01-05T08:32:51.392910Z trace envoy connection  [C397143] write ready
2022-01-05T08:32:51.392911Z trace envoy connection  [C397143] read ready. dispatch_buffered_data=false
2022-01-05T08:32:51.392914Z trace envoy connection  [C397143] read returns: 1460
2022-01-05T08:32:51.392917Z trace envoy connection  [C397143] read error: Resource temporarily unavailable
2022-01-05T08:32:51.392919Z trace envoy filter  [C397142] upstream connection received 1460 bytes, end_stream=false
2022-01-05T08:32:51.392920Z trace envoy connection  [C397142] writing 1460 bytes, end_stream false
2022-01-05T08:32:51.392923Z trace envoy connection  [C397142] socket event: 2
2022-01-05T08:32:51.392924Z trace envoy connection  [C397142] write ready
2022-01-05T08:32:51.392933Z trace envoy connection  [C397142] write returns: 1460
2022-01-05T08:32:51.392941Z trace envoy connection  [C397143] socket event: 3
2022-01-05T08:32:51.392943Z trace envoy connection  [C397143] write ready
2022-01-05T08:32:51.392944Z trace envoy connection  [C397143] read ready. dispatch_buffered_data=false
2022-01-05T08:32:51.392950Z trace envoy connection  [C397143] read returns: 6761
2022-01-05T08:32:51.392953Z trace envoy connection  [C397143] read error: Resource temporarily unavailable
2022-01-05T08:32:51.392955Z trace envoy filter  [C397142] upstream connection received 6761 bytes, end_stream=false
2022-01-05T08:32:51.392957Z trace envoy connection  [C397142] writing 6761 bytes, end_stream false
2022-01-05T08:32:51.392959Z trace envoy connection  [C397142] socket event: 2
2022-01-05T08:32:51.392961Z trace envoy connection  [C397142] write ready
2022-01-05T08:32:51.392967Z trace envoy connection  [C397142] write returns: 6761
2022-01-05T08:32:51.393214Z trace envoy connection  [C397141] socket event: 3
2022-01-05T08:32:51.393223Z trace envoy connection  [C397141] write ready
2022-01-05T08:32:51.393226Z trace envoy connection  [C397141] read ready. dispatch_buffered_data=false
2022-01-05T08:32:51.393237Z trace envoy connection  [C397141] read returns: 8192
2022-01-05T08:32:51.393251Z trace envoy connection  [C397141] read returns: 8192
2022-01-05T08:32:51.393257Z trace envoy connection  [C397141] read error: Resource temporarily unavailable
2022-01-05T08:32:51.393279Z trace envoy http  [C397141] parsing 16384 bytes
2022-01-05T08:32:51.393284Z trace envoy http  [C397141] message begin
2022-01-05T08:32:51.393295Z trace envoy http  [C397141] completed header: key=RlogId value=uuid
2022-01-05T08:32:51.393300Z trace envoy http  [C397141] completed header: key=X-Frame-Options value=DENY
2022-01-05T08:32:51.393303Z trace envoy http  [C397141] completed header: key=Transfer-Encoding value=chunked
2022-01-05T08:32:51.393309Z trace envoy http  [C397141] completed header: key=Keep-Alive value=timeout=20
2022-01-05T08:32:51.393313Z trace envoy http  [C397141] completed header: key=Cache-Control value=no-cache, no-store, max-age=0, must-revalidate
2022-01-05T08:32:51.393318Z trace envoy http  [C397141] completed header: key=X-Content-Type-Options value=nosniff
2022-01-05T08:32:51.393320Z trace envoy http  [C397141] completed header: key=Connection value=keep-alive
2022-01-05T08:32:51.393323Z trace envoy http  [C397141] completed header: key=Expires value=0
2022-01-05T08:32:51.393328Z trace envoy http  [C397141] completed header: key=Pragma value=no-cache
2022-01-05T08:32:51.393331Z trace envoy http  [C397141] completed header: key=X-XSS-Protection value=1; mode=block
2022-01-05T08:32:51.393333Z trace envoy http  [C397141] completed header: key=Date value=Wed, 05 Jan 2022 08:32:50 GMT
2022-01-05T08:32:51.393338Z trace envoy http  [C397141] completed header: key=Content-Type value=application/json
2022-01-05T08:32:51.393343Z trace envoy http  [C397141] onHeadersCompleteBase
2022-01-05T08:32:51.393345Z trace envoy http  [C397141] completed header: key=Transfer-Encoding value=chunked
2022-01-05T08:32:51.393352Z debug envoy client  [C397141] Error dispatching received data: http/1.1 protocol error: unsupported transfer encoding
2022-01-05T08:32:51.393357Z debug envoy connection  [C397141] closing data_to_write=0 type=1
2022-01-05T08:32:51.393358Z debug envoy connection  [C397141] closing socket: 1
2022-01-05T08:32:51.393387Z trace envoy connection  [C397141] raising connection event 1
2022-01-05T08:32:51.393390Z debug envoy client  [C397141] disconnect. resetting 1 pending requests
2022-01-05T08:32:51.393393Z debug envoy client  [C397141] request reset
2022-01-05T08:32:51.393396Z trace envoy main  item added to deferred deletion list (size=1)
2022-01-05T08:32:51.393404Z debug envoy router  [C397140][S5773887665609108525] upstream reset: reset reason: protocol error, transport failure reason:
2022-01-05T08:32:51.393550Z debug envoy http  [C397140][S5773887665609108525] Sending local reply with details upstream_reset_before_response_started{protocol error}
2022-01-05T08:32:51.393565Z trace envoy http  [C397140][S5773887665609108525] encode headers called: filter=0x555b6110d420 status=0
2022-01-05T08:32:51.393568Z trace envoy http  [C397140][S5773887665609108525] encode headers called: filter=0x555b61d7e8c0 status=0
2022-01-05T08:32:51.393571Z trace envoy http  [C397140][S5773887665609108525] encode headers called: filter=0x555b61709880 status=0
2022-01-05T08:32:51.393580Z trace envoy http  [C397140][S5773887665609108525] encode headers called: filter=0x555b61d7e5b0 status=0
2022-01-05T08:32:51.393585Z trace envoy connection  [C397142] socket event: 3
2022-01-05T08:32:51.393588Z trace envoy connection  [C397142] write ready
2022-01-05T08:32:51.393590Z trace envoy connection  [C397142] read ready. dispatch_buffered_data=false
2022-01-05T08:32:51.393598Z debug envoy http  [C397140][S5773887665609108525] encoding headers via codec (end_stream=false):
':status', '502'
'content-length', '87'
'content-type', 'text/plain'
'x-envoy-peer-metadata', 'Ch8KDkFQUF9DT05UQUlORVJTEg0aC2FwcCxzaWRlY2FyChoKCkNMVVNURVJfSUQSDBoKS3ViZXJuZXRlcwobCg1JU1RJT19WRVJTSU9OEgoaCDEuMTAtZGV2CqEFCgZMQUJFTFMSlgUqkwUKLAoYYXBwbGljYXRpb24udGVzcy5pby9uYW1lEhAaDmZhc3J0c3ZjcG9ydGFsCjkKIGFwcGxpY2F0aW9uaW5zdGFuY2UudGVzcy5pby9uYW1lEhUaE2Zhc3J0c3ZjcG9ydGFsMmNvbnQKLgokYXBwbGljYXRpb25pbnN0YW5jZS50ZXNzLmlvL3NlbGVjdG9yEgYaBHRydWUKQAohYXBwbGljYXRpb25pbnN0YW5jZS50ZXNzLmlvL3N0YWNrEhsaGXJhcHRvcnNlcnZpY2UubWFya2V0cGxhY2UKKQodYXBwcy50ZXNzLmlvL3BvZC1hZG1pbi1zdGF0dXMSCBoGTk9STUFMCicKHWFwcHMudGVzcy5pby9wb2QtYXNzZXQtc3RhdHVzEgYaBGxpdmUKIwoYZW52aXJvbm1lbnQudGVzcy5pby9uYW1lEgcaBXJucGNpChkKDGlzdGlvLmlvL3JldhIJGgdkZWZhdWx0CiwKHGxpZmVjeWNsZS1zdGF0ZS50ZXNzLmlvL25hbWUSDBoKcHJvZHVjdGlvbgohChFwb2QtdGVtcGxhdGUtaGFzaBIMGgo1OGZmNjQ4OTg2Ch8KBHBvb2wSFxoVcjFmYXNydHN2Y3BvcnRhbDJjb250CiQKGXNlY3VyaXR5LmlzdGlvLmlvL3Rsc01vZGUSBxoFaXN0aW8KOAofc2VydmljZS5pc3Rpby5pby9jYW5vbmljYWwtbmFtZRIVGhNmYXNydHN2Y3BvcnRhbDJjb250Ci8KI3NlcnZpY2UuaXN0aW8uaW8vY2Fub25pY2FsLXJldmlzaW9uEggaBmxhdGVzdAofChR6b25lLm5ldHdvcmsudGVzcy5pbxIHGgVybnBjaQoaCgdNRVNIX0lEEg8aDXJucGNpLnRlc3MuaW8KLgoETkFNRRImGiRmYXNydHN2Y3BvcnRhbDJjb250LTU4ZmY2NDg5ODYtaGt3NmgKJQoJTkFNRVNQQUNFEhgaFmZhc3J0c3ZjcG9ydGFsLXJucGNpLTIKZgoFT1dORVISXRpba3ViZXJuZXRlczovL2FwaXMvYXBwcy92MS9uYW1lc3BhY2VzL2Zhc3J0c3ZjcG9ydGFsLXJucGNpLTIvZGVwbG95bWVudHMvZmFzcnRzdmNwb3J0YWwyY29udAoXChFQTEFURk9STV9NRVRBREFUQRICKgAKJgoNV09SS0xPQURfTkFNRRIVGhNmYXNydHN2Y3BvcnRhbDJjb250'
'date', 'Wed, 05 Jan 2022 08:32:51 GMT'
'server', 'envoy'

2022-01-05T08:32:51.393607Z trace envoy connection  [C397142] read returns: 31
2022-01-05T08:32:51.393609Z trace envoy connection  [C397140] writing 1705 bytes, end_stream false
2022-01-05T08:32:51.393611Z trace envoy connection  [C397142] read error: Connection reset by peer
2022-01-05T08:32:51.393615Z debug envoy misc  Unknown error code 104 details Connection reset by peer
2022-01-05T08:32:51.393616Z trace envoy http  [C397140][S5773887665609108525] encode data called: filter=0x555b6110d420 status=0
2022-01-05T08:32:51.393618Z trace envoy filter  [C397142] downstream connection received 31 bytes, end_stream=false
2022-01-05T08:32:51.393618Z trace envoy http  [C397140][S5773887665609108525] encode data called: filter=0x555b61d7e8c0 status=0

Sidecar access log

{"upstream_local_address":"10.0.0.1:59804","downstream_remote_address":"10.0.0.1:59802","response_code":0,"connection_termination_details":null,"x_forwarded_for":null,"upstream_host":"10.0.0.2:443","method":null,"downstream_local_address":"10.0.0.2:443","user_agent":null,"authority":null,"response_flags":"-","upstream_transport_failure_reason":null,"request_id":null,"bytes_sent":53734,"path":null,"duration":78,"bytes_received":3210,"protocol":null,"requested_server_name":null,"upstream_cluster":"PassthroughCluster","upstream_service_time":null,"start_time":"2022-01-05T08:06:37.204Z","route_name":null,"response_code_details":null}
{"requested_server_name":"outbound_.8082_._.somecluster","response_flags":"UPE","start_time":"2022-01-05T08:06:37.722Z","route_name":"default","user_agent":"curl/7.58.0","path":"/somepath","downstream_local_address":"10.0.0.1:10082","authority":"example.com:8443","bytes_sent":87,"upstream_transport_failure_reason":null,"upstream_host":"127.0.0.1:10082","response_code_details":"upstream_reset_before_response_started{protocol_error}","upstream_service_time":null,"downstream_remote_address":"10.0.0.3:0","upstream_cluster":"inbound|10082||","protocol":"HTTP/1.1","upstream_local_address":"127.0.0.1:60534","bytes_received":0,"duration":103,"request_id":"eaf0c5d8-7e16-4eca-aa60-87e783eb1502","method":"GET","connection_termination_details":null,"response_code":502,"x_forwarded_for":"10.0.0.3"}

Version

istioctl version -i istio-staging
client version: 1.9.0
control plane version: 1.10-dev-3e1cdc98208a4824619469fc09d984315f9aece8
data plane version: 1.10-dev
kubectl version: 1.18.8

Additional Information

No response

[ramaraochavali]

This needs to be fixed in Envoy I think. @lizan @lambdai any thoughts?

[l8huang]

In envoy's log, it shows response has two Transfer-Encoding headers:

2022-01-05T08:32:51.393303Z trace envoy http  [C397141] completed header: key=Transfer-Encoding value=chunked
...
2022-01-05T08:32:51.393343Z trace envoy http  [C397141] onHeadersCompleteBase
2022-01-05T08:32:51.393345Z trace envoy http  [C397141] completed header: key=Transfer-Encoding value=chunked

Looks like this issue is same as #24753, see this issue comment.

A PR was raised by @lambdai for fixing this issue was closed: envoyproxy/envoy#11916, please check the comment for the reason. This issue should be resolved on application-side by removing duplicated Transfer-Encoding header. @lambdai could you please help to confirm?

[shonecyx]

Thanks @l8huang, I think we already have the fix envoyproxy/envoy#15033 that's why it returns 502 protocol error but this error msg is more confusing than the 502 bad gateway. @lambdai what's your thought?

[l8huang]

The client should get whatever application returned. Here the response code is not changed but the response message is confusing, it should be just 502 Bad Gateway.

Because application's 502 response had two Transfer-Encoding headers, sidecar failed to parse the response even. The 502 response received by client is generated by sidecar, not the one from application. This is coincidence that application returned a 502 response which had encoding issue and caused sidecar return a 502 UPE response.

[shonecyx]

@l8huang I see, thanks. Upstream app returns two header Transfer-Encoding value=chunked

2022-01-05T08:32:51.393303Z trace envoy http  [C397141] completed header: key=Transfer-Encoding value=chunked
2022-01-05T08:32:51.393309Z trace envoy http  [C397141] completed header: key=Keep-Alive value=timeout=20
2022-01-05T08:32:51.393333Z trace envoy http  [C397141] completed header: key=Date value=Wed, 05 Jan 2022 08:32:50 GMT
2022-01-05T08:32:51.393338Z trace envoy http  [C397141] completed header: key=Content-Type value=application/json
2022-01-05T08:32:51.393343Z trace envoy http  [C397141] onHeadersCompleteBase
2022-01-05T08:32:51.393345Z trace envoy http  [C397141] completed header: key=Transfer-Encoding value=chunked

This is Transfer-Encoding: chunked twice in same http response, same issue as here #24753 (comment),

According to the RFC this line appeared twice has the exact same semantic of "Transfer-Encoding: chunked, chunked`.

To avoid future confusing let's refer it as multiple-chunked regardless it's literal "chunked, chunked" or duplicated "Transfer-Encoding: chunked" :)

So it's a upstream app issue, need to fix in the app side to remove the duplicated header Transfer-Encoding: chunked