Summary
After upgrade envoy-1.29 to envoy-1.31.* started observing increased number of failures on downstream services, failing with parsing errors etc.
Details
setup where issue is reproduceable, however could not find a minimal working environment ALB->HTTP/1.1->EnvoyA->HTTP2->EnvoyB->HTTP/1.1->Custom HTTP/1.1 SRV
EnvoyB performs queueing with disabled outlier detection through upstream cluster config:
outlier_detection:
consecutive_5xx: 0
enforcing_consecutive_5xx: 0
consecutive_gateway_failure: 0
enforcing_consecutive_gateway_failure: 0
split_external_local_origin_errors: true
consecutive_local_origin_failure: 0
enforcing_consecutive_local_origin_failure: 0
enforcing_local_origin_success_rate: 0
circuit_breakers:
thresholds:
- priority: DEFAULT
max_connections: 1536
max_requests: 2048
max_pending_requests: 2048
max_retries: 512
- priority: HIGH
max_connections: 1536
max_requests: 2048
max_pending_requests: 2048
max_retries: 512
per_host_thresholds:
- priority: DEFAULT
max_connections: 3
- priority: HIGH
max_connections: 3
typed_extension_protocol_options:
envoy.extensions.upstreams.http.v3.HttpProtocolOptions:
"@type": type.googleapis.com/envoy.extensions.upstreams.http.v3.HttpProtocolOptions
common_http_protocol_options:
idle_timeout: 90s
max_requests_per_connection: 64
explicit_http_config:
http_protocol_options:
allow_chunked_length: false
override_stream_error_on_invalid_http_message: false
Original hypothesis was that some of requests got entangled, which was confirmed during research. Investigation leads to envoy.reloadable_features.http1_balsa_delay_reset flag which is set to true by default, together with another leading observation that HEAD request could not flow though envoyB always failing through UT/DR (depends on client timeout settings) and parser failure when SRV response is coupled with 102 Processing
here is the log of simple curl request:
lifecycle of a head request with 102 :
```
{"line":"[2024-10-22 16:12:28.264][60][debug][pool] [external/envoy/source/common/conn_pool/conn_pool_base.cc:495] [Tags: \"ConnectionId\":\"87\"] client disconnected, failure reason: "}}
{"line":"[2024-10-22 16:12:28.264][60][debug][client] [external/envoy/source/common/http/codec_client.cc:107] [Tags: \"ConnectionId\":\"87\"] disconnect. resetting 0 pending requests"}}
{"line":"[2024-10-22 16:12:28.264][60][trace][connection] [external/envoy/source/common/network/connection_impl.cc:469] [Tags: \"ConnectionId\":\"87\"] raising connection event 1"}}
{"line":"[2024-10-22 16:12:28.264][60][debug][connection] [external/envoy/source/common/tls/ssl_socket.cc:334] [Tags: \"ConnectionId\":\"87\"] SSL shutdown: rc=0"}}
{"line":"[2024-10-22 16:12:28.264][60][debug][connection] [external/envoy/source/common/network/connection_impl.cc:276] [Tags: \"ConnectionId\":\"87\"] closing socket: 1"}}
{"line":"[2024-10-22 16:12:28.264][60][debug][connection] [external/envoy/source/common/network/connection_impl.cc:150] [Tags: \"ConnectionId\":\"87\"] closing data_to_write=0 type=1"}}
{"line":"[2024-10-22 16:12:28.264][60][debug][client] [external/envoy/source/common/http/codec_client.cc:171] [Tags: \"ConnectionId\":\"87\"] Error dispatching received data: "}}
{"line":"[2024-10-22 16:12:28.264][60][trace][http] [external/envoy/source/common/http/http1/codec_impl.cc:1486] [Tags: \"ConnectionId\":\"87\"] status_code 200"}}
{"line":"[2024-10-22 16:12:28.264][60][trace][http] [external/envoy/source/common/http/http1/codec_impl.cc:544] [Tags: \"ConnectionId\":\"87\"] completed header: key=Content-Length value=0"}}
{"line":"[2024-10-22 16:12:28.264][60][trace][http] [external/envoy/source/common/http/http1/codec_impl.cc:838] [Tags: \"ConnectionId\":\"87\"] onHeadersCompleteImpl"}}
{"line":"[2024-10-22 16:12:28.264][60][trace][http] [external/envoy/source/common/http/http1/codec_impl.cc:544] [Tags: \"ConnectionId\":\"87\"] completed header: key=... value=..."}}
{"line":"[2024-10-22 16:12:28.264][60][trace][http] [external/envoy/source/common/http/http1/codec_impl.cc:544] [Tags: \"ConnectionId\":\"87\"] completed header: key=... value=...."}}
{"line":"[2024-10-22 16:12:28.264][60][trace][http] [external/envoy/source/common/http/http1/codec_impl.cc:544] [Tags: \"ConnectionId\":\"87\"] completed header: key=Content-Type value=application/xml"}}
{"line":"[2024-10-22 16:12:28.264][60][trace][http] [external/envoy/source/common/http/http1/codec_impl.cc:544] [Tags: \"ConnectionId\":\"87\"] completed header: key=... value=..."}}
{"line":"[2024-10-22 16:12:28.264][60][trace][http] [external/envoy/source/common/http/http1/codec_impl.cc:544] [Tags: \"ConnectionId\":\"87\"] completed header: key=... value=..."}}
{"line":"[2024-10-22 16:12:28.264][60][trace][http] [external/envoy/source/common/http/http1/codec_impl.cc:544] [Tags: \"ConnectionId\":\"87\"] completed header: key=Set-Cookie ..."}}
{"line":"[2024-10-22 16:12:28.264][60][trace][http] [external/envoy/source/common/http/http1/codec_impl.cc:544] [Tags: \"ConnectionId\":\"87\"] completed header: key=Set-Cookie ..."}}
{"line":"[2024-10-22 16:12:28.264][60][trace][http] [external/envoy/source/common/http/http1/codec_impl.cc:544] [Tags: \"ConnectionId\":\"87\"] completed header: key=Set-Cookie ..."}}
{"line":"[2024-10-22 16:12:28.264][60][trace][http] [external/envoy/source/common/http/http1/codec_impl.cc:544] [Tags: \"ConnectionId\":\"87\"] completed header: key=Set-Cookie ..."}}
{"line":"[2024-10-22 16:12:28.264][60][trace][http] [external/envoy/source/common/http/http1/codec_impl.cc:587] [Tags: \"ConnectionId\":\"87\"] message begin"}}
{"line":"[2024-10-22 16:12:28.264][60][trace][http] [external/envoy/source/common/http/http1/codec_impl.cc:645] [Tags: \"ConnectionId\":\"87\"] parsing 593 bytes"}}
{"line":"[2024-10-22 16:12:28.264][60][trace][connection] [external/envoy/source/common/tls/ssl_socket.cc:168] [Tags: \"ConnectionId\":\"87\"] ssl read 593 bytes"}}
{"line":"[2024-10-22 16:12:28.264][60][trace][connection] [external/envoy/source/common/tls/ssl_socket.cc:132] [Tags: \"ConnectionId\":\"87\"] ssl error occurred while read: WANT_READ"}}
{"line":"[2024-10-22 16:12:28.264][60][trace][connection] [external/envoy/source/common/tls/ssl_socket.cc:92] [Tags: \"ConnectionId\":\"87\"] ssl read returns: -1"}}
{"line":"[2024-10-22 16:12:28.264][60][trace][connection] [external/envoy/source/common/tls/ssl_socket.cc:92] [Tags: \"ConnectionId\":\"87\"] ssl read returns: 593"}}
{"line":"[2024-10-22 16:12:28.264][60][trace][connection] [external/envoy/source/common/network/connection_impl.cc:654] [Tags: \"ConnectionId\":\"87\"] read ready. dispatch_buffered_data=0"}}
{"line":"[2024-10-22 16:12:28.264][60][trace][connection] [external/envoy/source/common/network/connection_impl.cc:737] [Tags: \"ConnectionId\":\"87\"] write ready"}}
{"line":"[2024-10-22 16:12:28.264][60][trace][connection] [external/envoy/source/common/network/connection_impl.cc:614] [Tags: \"ConnectionId\":\"87\"] socket event: 3"}}
{"line":"[2024-10-22 16:12:28.259][60][trace][http] [external/envoy/source/common/http/http1/codec_impl.cc:695] [Tags: \"ConnectionId\":\"87\"] parsed 27 bytes"}}
{"line":"[2024-10-22 16:12:28.259][60][debug][pool] [external/envoy/source/common/conn_pool/conn_pool_base.cc:215] [Tags: \"ConnectionId\":\"87\"] destroying stream: 0 remaining"}}
{"line":"[2024-10-22 16:12:28.259][60][debug][pool] [external/envoy/source/common/http/http1/conn_pool.cc:53] [Tags: \"ConnectionId\":\"87\"] response complete"}}
{"line":"[2024-10-22 16:12:28.259][60][debug][client] [external/envoy/source/common/http/codec_client.cc:129] [Tags: \"ConnectionId\":\"87\"] response complete"}}
{"line":"[2024-10-22 16:12:28.259][60][trace][http] [external/envoy/source/common/http/http1/codec_impl.cc:1568] [Tags: \"ConnectionId\":\"87\"] message complete"}}
{"line":"[2024-10-22 16:12:28.259][60][trace][http] [external/envoy/source/common/http/http1/codec_impl.cc:942] [Tags: \"ConnectionId\":\"87\"] message complete"}}
{"line":"[2024-10-22 16:12:28.259][60][trace][http] [external/envoy/source/common/http/http1/codec_impl.cc:1568] [Tags: \"ConnectionId\":\"87\"] message complete"}}
{"line":"[2024-10-22 16:12:28.259][60][trace][http] [external/envoy/source/common/http/http1/codec_impl.cc:942] [Tags: \"ConnectionId\":\"87\"] message complete"}}
{"line":"[2024-10-22 16:12:28.259][60][trace][http] [external/envoy/source/common/http/http1/codec_impl.cc:1496] [Tags: \"ConnectionId\":\"87\"] Client: onHeadersComplete size=0"}}
{"line":"[2024-10-22 16:12:28.259][60][trace][http] [external/envoy/source/common/http/http1/codec_impl.cc:1486] [Tags: \"ConnectionId\":\"87\"] status_code 102"}}
{"line":"[2024-10-22 16:12:28.259][60][trace][http] [external/envoy/source/common/http/http1/codec_impl.cc:544] [Tags: \"ConnectionId\":\"87\"] completed header: key= value="}}
{"line":"[2024-10-22 16:12:28.259][60][trace][http] [external/envoy/source/common/http/http1/codec_impl.cc:838] [Tags: \"ConnectionId\":\"87\"] onHeadersCompleteImpl"}}
{"line":"[2024-10-22 16:12:28.259][60][trace][http] [external/envoy/source/common/http/http1/codec_impl.cc:587] [Tags: \"ConnectionId\":\"87\"] message begin"}}
{"line":"[2024-10-22 16:12:28.259][60][trace][http] [external/envoy/source/common/http/http1/codec_impl.cc:645] [Tags: \"ConnectionId\":\"87\"] parsing 27 bytes"}}
{"line":"[2024-10-22 16:12:28.259][60][trace][connection] [external/envoy/source/common/tls/ssl_socket.cc:168] [Tags: \"ConnectionId\":\"87\"] ssl read 27 bytes"}}
{"line":"[2024-10-22 16:12:28.259][60][trace][connection] [external/envoy/source/common/tls/ssl_socket.cc:132] [Tags: \"ConnectionId\":\"87\"] ssl error occurred while read: WANT_READ"}}
{"line":"[2024-10-22 16:12:28.259][60][trace][connection] [external/envoy/source/common/tls/ssl_socket.cc:92] [Tags: \"ConnectionId\":\"87\"] ssl read returns: -1"}}
{"line":"[2024-10-22 16:12:28.258][60][trace][connection] [external/envoy/source/common/tls/ssl_socket.cc:92] [Tags: \"ConnectionId\":\"87\"] ssl read returns: 27"}}
{"line":"[2024-10-22 16:12:28.258][60][trace][connection] [external/envoy/source/common/network/connection_impl.cc:654] [Tags: \"ConnectionId\":\"87\"] read ready. dispatch_buffered_data=0"}}
{"line":"[2024-10-22 16:12:28.258][60][trace][connection] [external/envoy/source/common/network/connection_impl.cc:737] [Tags: \"ConnectionId\":\"87\"] write ready"}}
{"line":"[2024-10-22 16:12:28.258][60][trace][connection] [external/envoy/source/common/network/connection_impl.cc:614] [Tags: \"ConnectionId\":\"87\"] socket event: 3"}}
{"line":"[2024-10-22 16:12:28.258][60][trace][connection] [external/envoy/source/common/tls/ssl_socket.cc:168] [Tags: \"ConnectionId\":\"87\"] ssl read 0 bytes"}}
{"line":"[2024-10-22 16:12:28.258][60][trace][connection] [external/envoy/source/common/tls/ssl_socket.cc:132] [Tags: \"ConnectionId\":\"87\"] ssl error occurred while read: WANT_READ"}}
{"line":"[2024-10-22 16:12:28.258][60][trace][connection] [external/envoy/source/common/tls/ssl_socket.cc:92] [Tags: \"ConnectionId\":\"87\"] ssl read returns: -1"}}
{"line":"[2024-10-22 16:12:28.258][60][trace][connection] [external/envoy/source/common/network/connection_impl.cc:654] [Tags: \"ConnectionId\":\"87\"] read ready. dispatch_buffered_data=0"}}
{"line":"[2024-10-22 16:12:28.258][60][trace][connection] [external/envoy/source/common/network/connection_impl.cc:737] [Tags: \"ConnectionId\":\"87\"] write ready"}}
{"line":"[2024-10-22 16:12:28.258][60][trace][connection] [external/envoy/source/common/network/connection_impl.cc:614] [Tags: \"ConnectionId\":\"87\"] socket event: 3"}}
{"line":"[2024-10-22 16:12:28.258][60][trace][connection] [external/envoy/source/common/network/connection_impl.cc:737] [Tags: \"ConnectionId\":\"87\"] write ready"}}
{"line":"[2024-10-22 16:12:28.258][60][trace][connection] [external/envoy/source/common/network/connection_impl.cc:614] [Tags: \"ConnectionId\":\"87\"] socket event: 2"}}
{"line":"[2024-10-22 16:12:28.258][60][trace][connection] [external/envoy/source/common/tls/ssl_socket.cc:168] [Tags: \"ConnectionId\":\"87\"] ssl read 0 bytes"}}
{"line":"[2024-10-22 16:12:28.258][60][trace][connection] [external/envoy/source/common/tls/ssl_socket.cc:132] [Tags: \"ConnectionId\":\"87\"] ssl error occurred while read: WANT_READ"}}
{"line":"[2024-10-22 16:12:28.258][60][trace][connection] [external/envoy/source/common/tls/ssl_socket.cc:92] [Tags: \"ConnectionId\":\"87\"] ssl read returns: -1"}}
{"line":"[2024-10-22 16:12:28.257][60][trace][connection] [external/envoy/source/common/network/connection_impl.cc:654] [Tags: \"ConnectionId\":\"87\"] read ready. dispatch_buffered_data=0"}}
{"line":"[2024-10-22 16:12:28.257][60][trace][connection] [external/envoy/source/common/tls/ssl_socket.cc:282] [Tags: \"ConnectionId\":\"87\"] ssl write returns: 626"}}
{"line":"[2024-10-22 16:12:28.257][60][trace][connection] [external/envoy/source/common/network/connection_impl.cc:737] [Tags: \"ConnectionId\":\"87\"] write ready"}}
{"line":"[2024-10-22 16:12:28.257][60][debug][client] [external/envoy/source/common/http/codec_client.cc:142] [Tags: \"ConnectionId\":\"87\"] encode complete"}}
{"line":"[2024-10-22 16:12:28.257][60][trace][connection] [external/envoy/source/common/network/connection_impl.cc:529] [Tags: \"ConnectionId\":\"87\"] writing 626 bytes, end_stream false"}}
{"line":"[2024-10-22 16:12:28.257][60][debug][pool] [external/envoy/source/common/conn_pool/conn_pool_base.cc:182] [Tags: \"ConnectionId\":\"87\"] creating stream"}}
{"line":"[2024-10-22 16:12:28.257][60][debug][pool] [external/envoy/source/common/conn_pool/conn_pool_base.cc:328] [Tags: \"ConnectionId\":\"87\"] attaching to next stream"}}
{"line":"[2024-10-22 16:12:28.257][60][debug][client] [external/envoy/source/common/http/codec_client.cc:88] [Tags: \"ConnectionId\":\"87\"] connected"}}
{"line":"[2024-10-22 16:12:28.257][60][trace][connection] [external/envoy/source/common/network/connection_impl.cc:469] [Tags: \"ConnectionId\":\"87\"] raising connection event 2"}}
{"line":"[2024-10-22 16:12:28.257][60][trace][connection] [external/envoy/source/common/network/connection_impl.cc:737] [Tags: \"ConnectionId\":\"87\"] write ready"}}
{"line":"[2024-10-22 16:12:28.257][60][trace][connection] [external/envoy/source/common/network/connection_impl.cc:614] [Tags: \"ConnectionId\":\"87\"] socket event: 3"}}
{"line":"[2024-10-22 16:12:28.254][60][trace][connection] [external/envoy/source/common/tls/ssl_handshaker.cc:149] [Tags: \"ConnectionId\":\"87\"] ssl error occurred while read: WANT_READ"}}
{"line":"[2024-10-22 16:12:28.254][60][debug][connection] [external/envoy/source/common/network/connection_impl.cc:746] [Tags: \"ConnectionId\":\"87\"] connected"}}
{"line":"[2024-10-22 16:12:28.254][60][trace][connection] [external/envoy/source/common/network/connection_impl.cc:737] [Tags: \"ConnectionId\":\"87\"] write ready"}}
{"line":"[2024-10-22 16:12:28.254][60][trace][connection] [external/envoy/source/common/network/connection_impl.cc:614] [Tags: \"ConnectionId\":\"87\"] socket event: 2"}}
{"line":"[2024-10-22 16:12:28.253][60][debug][connection] [external/envoy/source/common/network/connection_impl.cc:1036] [Tags: \"ConnectionId\":\"87\"] connection in progress"}}
{"line":"[2024-10-22 16:12:28.253][60][debug][connection] [external/envoy/source/common/network/connection_impl.cc:1017] [Tags: \"ConnectionId\":\"87\"] connecting to 10.104.108.183:50089"}}
{"line":"[2024-10-22 16:12:28.253][60][debug][client] [external/envoy/source/common/http/codec_client.cc:57] [Tags: \"ConnectionId\":\"87\"] connecting"}}
{"line":"[2024-10-22 16:12:28.253][60][debug][connection] [external/envoy/source/common/network/connection_impl.h:98] [Tags: \"ConnectionId\":\"87\"] current connecting state: true"}}
```
the theory is that configuration somehow triggers the problem in the parser and make it even worse if response from the server is not
well formatted single response, as a result other components become unreliable, while we would UPE or something similar.
PoC
in test environment were able to easily reproduce by submitting HEAD
requests, and server response as sequence of:
HTTP/1.1 102 Processing\r\n
\r\n
HTTP/1.1 200 Ok \r\n
......
25 clients. one instance of envoyB, all requests hitting same SRV instance(process is sequential), Client timeout ~ 150ms, Request Duration ~30ms, Avg Response on client ~ 440ms,, 65% of request failing with DC on envoyA, %50 of requests got to envoyB failing with DR, rest of requests has 200 ok
was not able to reproduce the request entanglement without keep-alive max_requests_per_connection: 1
or with disabled delayed reset: envoy.reloadable_features.http1_balsa_delay_reset=false
Impact
High, users who are using keep-alive http/1.1 upstream and/or vulnerable upstream server which not strictly posing single well formatted responses
Mitigation
- Disable envoy.reloadable_features.http1_balsa_delay_reset
Summary
After upgrade envoy-1.29 to envoy-1.31.* started observing increased number of failures on downstream services, failing with parsing errors etc.
Details
setup where issue is reproduceable, however could not find a minimal working environment ALB->HTTP/1.1->EnvoyA->HTTP2->EnvoyB->HTTP/1.1->Custom HTTP/1.1 SRV
EnvoyB performs queueing with disabled outlier detection through upstream cluster config:
Original hypothesis was that some of requests got entangled, which was confirmed during research. Investigation leads to envoy.reloadable_features.http1_balsa_delay_reset flag which is set to true by default, together with another leading observation that HEAD request could not flow though envoyB always failing through UT/DR (depends on client timeout settings) and parser failure when SRV response is coupled with
102 Processing
here is the log of simple curl request:lifecycle of a head request with 102 :
``` {"line":"[2024-10-22 16:12:28.264][60][debug][pool] [external/envoy/source/common/conn_pool/conn_pool_base.cc:495] [Tags: \"ConnectionId\":\"87\"] client disconnected, failure reason: "}} {"line":"[2024-10-22 16:12:28.264][60][debug][client] [external/envoy/source/common/http/codec_client.cc:107] [Tags: \"ConnectionId\":\"87\"] disconnect. resetting 0 pending requests"}} {"line":"[2024-10-22 16:12:28.264][60][trace][connection] [external/envoy/source/common/network/connection_impl.cc:469] [Tags: \"ConnectionId\":\"87\"] raising connection event 1"}} {"line":"[2024-10-22 16:12:28.264][60][debug][connection] [external/envoy/source/common/tls/ssl_socket.cc:334] [Tags: \"ConnectionId\":\"87\"] SSL shutdown: rc=0"}} {"line":"[2024-10-22 16:12:28.264][60][debug][connection] [external/envoy/source/common/network/connection_impl.cc:276] [Tags: \"ConnectionId\":\"87\"] closing socket: 1"}} {"line":"[2024-10-22 16:12:28.264][60][debug][connection] [external/envoy/source/common/network/connection_impl.cc:150] [Tags: \"ConnectionId\":\"87\"] closing data_to_write=0 type=1"}} {"line":"[2024-10-22 16:12:28.264][60][debug][client] [external/envoy/source/common/http/codec_client.cc:171] [Tags: \"ConnectionId\":\"87\"] Error dispatching received data: "}} {"line":"[2024-10-22 16:12:28.264][60][trace][http] [external/envoy/source/common/http/http1/codec_impl.cc:1486] [Tags: \"ConnectionId\":\"87\"] status_code 200"}} {"line":"[2024-10-22 16:12:28.264][60][trace][http] [external/envoy/source/common/http/http1/codec_impl.cc:544] [Tags: \"ConnectionId\":\"87\"] completed header: key=Content-Length value=0"}} {"line":"[2024-10-22 16:12:28.264][60][trace][http] [external/envoy/source/common/http/http1/codec_impl.cc:838] [Tags: \"ConnectionId\":\"87\"] onHeadersCompleteImpl"}} {"line":"[2024-10-22 16:12:28.264][60][trace][http] [external/envoy/source/common/http/http1/codec_impl.cc:544] [Tags: \"ConnectionId\":\"87\"] completed header: key=... value=..."}} {"line":"[2024-10-22 16:12:28.264][60][trace][http] [external/envoy/source/common/http/http1/codec_impl.cc:544] [Tags: \"ConnectionId\":\"87\"] completed header: key=... value=...."}} {"line":"[2024-10-22 16:12:28.264][60][trace][http] [external/envoy/source/common/http/http1/codec_impl.cc:544] [Tags: \"ConnectionId\":\"87\"] completed header: key=Content-Type value=application/xml"}} {"line":"[2024-10-22 16:12:28.264][60][trace][http] [external/envoy/source/common/http/http1/codec_impl.cc:544] [Tags: \"ConnectionId\":\"87\"] completed header: key=... value=..."}} {"line":"[2024-10-22 16:12:28.264][60][trace][http] [external/envoy/source/common/http/http1/codec_impl.cc:544] [Tags: \"ConnectionId\":\"87\"] completed header: key=... value=..."}} {"line":"[2024-10-22 16:12:28.264][60][trace][http] [external/envoy/source/common/http/http1/codec_impl.cc:544] [Tags: \"ConnectionId\":\"87\"] completed header: key=Set-Cookie ..."}} {"line":"[2024-10-22 16:12:28.264][60][trace][http] [external/envoy/source/common/http/http1/codec_impl.cc:544] [Tags: \"ConnectionId\":\"87\"] completed header: key=Set-Cookie ..."}} {"line":"[2024-10-22 16:12:28.264][60][trace][http] [external/envoy/source/common/http/http1/codec_impl.cc:544] [Tags: \"ConnectionId\":\"87\"] completed header: key=Set-Cookie ..."}} {"line":"[2024-10-22 16:12:28.264][60][trace][http] [external/envoy/source/common/http/http1/codec_impl.cc:544] [Tags: \"ConnectionId\":\"87\"] completed header: key=Set-Cookie ..."}} {"line":"[2024-10-22 16:12:28.264][60][trace][http] [external/envoy/source/common/http/http1/codec_impl.cc:587] [Tags: \"ConnectionId\":\"87\"] message begin"}} {"line":"[2024-10-22 16:12:28.264][60][trace][http] [external/envoy/source/common/http/http1/codec_impl.cc:645] [Tags: \"ConnectionId\":\"87\"] parsing 593 bytes"}} {"line":"[2024-10-22 16:12:28.264][60][trace][connection] [external/envoy/source/common/tls/ssl_socket.cc:168] [Tags: \"ConnectionId\":\"87\"] ssl read 593 bytes"}} {"line":"[2024-10-22 16:12:28.264][60][trace][connection] [external/envoy/source/common/tls/ssl_socket.cc:132] [Tags: \"ConnectionId\":\"87\"] ssl error occurred while read: WANT_READ"}} {"line":"[2024-10-22 16:12:28.264][60][trace][connection] [external/envoy/source/common/tls/ssl_socket.cc:92] [Tags: \"ConnectionId\":\"87\"] ssl read returns: -1"}} {"line":"[2024-10-22 16:12:28.264][60][trace][connection] [external/envoy/source/common/tls/ssl_socket.cc:92] [Tags: \"ConnectionId\":\"87\"] ssl read returns: 593"}} {"line":"[2024-10-22 16:12:28.264][60][trace][connection] [external/envoy/source/common/network/connection_impl.cc:654] [Tags: \"ConnectionId\":\"87\"] read ready. dispatch_buffered_data=0"}} {"line":"[2024-10-22 16:12:28.264][60][trace][connection] [external/envoy/source/common/network/connection_impl.cc:737] [Tags: \"ConnectionId\":\"87\"] write ready"}} {"line":"[2024-10-22 16:12:28.264][60][trace][connection] [external/envoy/source/common/network/connection_impl.cc:614] [Tags: \"ConnectionId\":\"87\"] socket event: 3"}} {"line":"[2024-10-22 16:12:28.259][60][trace][http] [external/envoy/source/common/http/http1/codec_impl.cc:695] [Tags: \"ConnectionId\":\"87\"] parsed 27 bytes"}} {"line":"[2024-10-22 16:12:28.259][60][debug][pool] [external/envoy/source/common/conn_pool/conn_pool_base.cc:215] [Tags: \"ConnectionId\":\"87\"] destroying stream: 0 remaining"}} {"line":"[2024-10-22 16:12:28.259][60][debug][pool] [external/envoy/source/common/http/http1/conn_pool.cc:53] [Tags: \"ConnectionId\":\"87\"] response complete"}} {"line":"[2024-10-22 16:12:28.259][60][debug][client] [external/envoy/source/common/http/codec_client.cc:129] [Tags: \"ConnectionId\":\"87\"] response complete"}} {"line":"[2024-10-22 16:12:28.259][60][trace][http] [external/envoy/source/common/http/http1/codec_impl.cc:1568] [Tags: \"ConnectionId\":\"87\"] message complete"}} {"line":"[2024-10-22 16:12:28.259][60][trace][http] [external/envoy/source/common/http/http1/codec_impl.cc:942] [Tags: \"ConnectionId\":\"87\"] message complete"}} {"line":"[2024-10-22 16:12:28.259][60][trace][http] [external/envoy/source/common/http/http1/codec_impl.cc:1568] [Tags: \"ConnectionId\":\"87\"] message complete"}} {"line":"[2024-10-22 16:12:28.259][60][trace][http] [external/envoy/source/common/http/http1/codec_impl.cc:942] [Tags: \"ConnectionId\":\"87\"] message complete"}} {"line":"[2024-10-22 16:12:28.259][60][trace][http] [external/envoy/source/common/http/http1/codec_impl.cc:1496] [Tags: \"ConnectionId\":\"87\"] Client: onHeadersComplete size=0"}} {"line":"[2024-10-22 16:12:28.259][60][trace][http] [external/envoy/source/common/http/http1/codec_impl.cc:1486] [Tags: \"ConnectionId\":\"87\"] status_code 102"}} {"line":"[2024-10-22 16:12:28.259][60][trace][http] [external/envoy/source/common/http/http1/codec_impl.cc:544] [Tags: \"ConnectionId\":\"87\"] completed header: key= value="}} {"line":"[2024-10-22 16:12:28.259][60][trace][http] [external/envoy/source/common/http/http1/codec_impl.cc:838] [Tags: \"ConnectionId\":\"87\"] onHeadersCompleteImpl"}} {"line":"[2024-10-22 16:12:28.259][60][trace][http] [external/envoy/source/common/http/http1/codec_impl.cc:587] [Tags: \"ConnectionId\":\"87\"] message begin"}} {"line":"[2024-10-22 16:12:28.259][60][trace][http] [external/envoy/source/common/http/http1/codec_impl.cc:645] [Tags: \"ConnectionId\":\"87\"] parsing 27 bytes"}} {"line":"[2024-10-22 16:12:28.259][60][trace][connection] [external/envoy/source/common/tls/ssl_socket.cc:168] [Tags: \"ConnectionId\":\"87\"] ssl read 27 bytes"}} {"line":"[2024-10-22 16:12:28.259][60][trace][connection] [external/envoy/source/common/tls/ssl_socket.cc:132] [Tags: \"ConnectionId\":\"87\"] ssl error occurred while read: WANT_READ"}} {"line":"[2024-10-22 16:12:28.259][60][trace][connection] [external/envoy/source/common/tls/ssl_socket.cc:92] [Tags: \"ConnectionId\":\"87\"] ssl read returns: -1"}} {"line":"[2024-10-22 16:12:28.258][60][trace][connection] [external/envoy/source/common/tls/ssl_socket.cc:92] [Tags: \"ConnectionId\":\"87\"] ssl read returns: 27"}} {"line":"[2024-10-22 16:12:28.258][60][trace][connection] [external/envoy/source/common/network/connection_impl.cc:654] [Tags: \"ConnectionId\":\"87\"] read ready. dispatch_buffered_data=0"}} {"line":"[2024-10-22 16:12:28.258][60][trace][connection] [external/envoy/source/common/network/connection_impl.cc:737] [Tags: \"ConnectionId\":\"87\"] write ready"}} {"line":"[2024-10-22 16:12:28.258][60][trace][connection] [external/envoy/source/common/network/connection_impl.cc:614] [Tags: \"ConnectionId\":\"87\"] socket event: 3"}} {"line":"[2024-10-22 16:12:28.258][60][trace][connection] [external/envoy/source/common/tls/ssl_socket.cc:168] [Tags: \"ConnectionId\":\"87\"] ssl read 0 bytes"}} {"line":"[2024-10-22 16:12:28.258][60][trace][connection] [external/envoy/source/common/tls/ssl_socket.cc:132] [Tags: \"ConnectionId\":\"87\"] ssl error occurred while read: WANT_READ"}} {"line":"[2024-10-22 16:12:28.258][60][trace][connection] [external/envoy/source/common/tls/ssl_socket.cc:92] [Tags: \"ConnectionId\":\"87\"] ssl read returns: -1"}} {"line":"[2024-10-22 16:12:28.258][60][trace][connection] [external/envoy/source/common/network/connection_impl.cc:654] [Tags: \"ConnectionId\":\"87\"] read ready. dispatch_buffered_data=0"}} {"line":"[2024-10-22 16:12:28.258][60][trace][connection] [external/envoy/source/common/network/connection_impl.cc:737] [Tags: \"ConnectionId\":\"87\"] write ready"}} {"line":"[2024-10-22 16:12:28.258][60][trace][connection] [external/envoy/source/common/network/connection_impl.cc:614] [Tags: \"ConnectionId\":\"87\"] socket event: 3"}} {"line":"[2024-10-22 16:12:28.258][60][trace][connection] [external/envoy/source/common/network/connection_impl.cc:737] [Tags: \"ConnectionId\":\"87\"] write ready"}} {"line":"[2024-10-22 16:12:28.258][60][trace][connection] [external/envoy/source/common/network/connection_impl.cc:614] [Tags: \"ConnectionId\":\"87\"] socket event: 2"}} {"line":"[2024-10-22 16:12:28.258][60][trace][connection] [external/envoy/source/common/tls/ssl_socket.cc:168] [Tags: \"ConnectionId\":\"87\"] ssl read 0 bytes"}} {"line":"[2024-10-22 16:12:28.258][60][trace][connection] [external/envoy/source/common/tls/ssl_socket.cc:132] [Tags: \"ConnectionId\":\"87\"] ssl error occurred while read: WANT_READ"}} {"line":"[2024-10-22 16:12:28.258][60][trace][connection] [external/envoy/source/common/tls/ssl_socket.cc:92] [Tags: \"ConnectionId\":\"87\"] ssl read returns: -1"}} {"line":"[2024-10-22 16:12:28.257][60][trace][connection] [external/envoy/source/common/network/connection_impl.cc:654] [Tags: \"ConnectionId\":\"87\"] read ready. dispatch_buffered_data=0"}} {"line":"[2024-10-22 16:12:28.257][60][trace][connection] [external/envoy/source/common/tls/ssl_socket.cc:282] [Tags: \"ConnectionId\":\"87\"] ssl write returns: 626"}} {"line":"[2024-10-22 16:12:28.257][60][trace][connection] [external/envoy/source/common/network/connection_impl.cc:737] [Tags: \"ConnectionId\":\"87\"] write ready"}} {"line":"[2024-10-22 16:12:28.257][60][debug][client] [external/envoy/source/common/http/codec_client.cc:142] [Tags: \"ConnectionId\":\"87\"] encode complete"}} {"line":"[2024-10-22 16:12:28.257][60][trace][connection] [external/envoy/source/common/network/connection_impl.cc:529] [Tags: \"ConnectionId\":\"87\"] writing 626 bytes, end_stream false"}} {"line":"[2024-10-22 16:12:28.257][60][debug][pool] [external/envoy/source/common/conn_pool/conn_pool_base.cc:182] [Tags: \"ConnectionId\":\"87\"] creating stream"}} {"line":"[2024-10-22 16:12:28.257][60][debug][pool] [external/envoy/source/common/conn_pool/conn_pool_base.cc:328] [Tags: \"ConnectionId\":\"87\"] attaching to next stream"}} {"line":"[2024-10-22 16:12:28.257][60][debug][client] [external/envoy/source/common/http/codec_client.cc:88] [Tags: \"ConnectionId\":\"87\"] connected"}} {"line":"[2024-10-22 16:12:28.257][60][trace][connection] [external/envoy/source/common/network/connection_impl.cc:469] [Tags: \"ConnectionId\":\"87\"] raising connection event 2"}} {"line":"[2024-10-22 16:12:28.257][60][trace][connection] [external/envoy/source/common/network/connection_impl.cc:737] [Tags: \"ConnectionId\":\"87\"] write ready"}} {"line":"[2024-10-22 16:12:28.257][60][trace][connection] [external/envoy/source/common/network/connection_impl.cc:614] [Tags: \"ConnectionId\":\"87\"] socket event: 3"}} {"line":"[2024-10-22 16:12:28.254][60][trace][connection] [external/envoy/source/common/tls/ssl_handshaker.cc:149] [Tags: \"ConnectionId\":\"87\"] ssl error occurred while read: WANT_READ"}} {"line":"[2024-10-22 16:12:28.254][60][debug][connection] [external/envoy/source/common/network/connection_impl.cc:746] [Tags: \"ConnectionId\":\"87\"] connected"}} {"line":"[2024-10-22 16:12:28.254][60][trace][connection] [external/envoy/source/common/network/connection_impl.cc:737] [Tags: \"ConnectionId\":\"87\"] write ready"}} {"line":"[2024-10-22 16:12:28.254][60][trace][connection] [external/envoy/source/common/network/connection_impl.cc:614] [Tags: \"ConnectionId\":\"87\"] socket event: 2"}} {"line":"[2024-10-22 16:12:28.253][60][debug][connection] [external/envoy/source/common/network/connection_impl.cc:1036] [Tags: \"ConnectionId\":\"87\"] connection in progress"}} {"line":"[2024-10-22 16:12:28.253][60][debug][connection] [external/envoy/source/common/network/connection_impl.cc:1017] [Tags: \"ConnectionId\":\"87\"] connecting to 10.104.108.183:50089"}} {"line":"[2024-10-22 16:12:28.253][60][debug][client] [external/envoy/source/common/http/codec_client.cc:57] [Tags: \"ConnectionId\":\"87\"] connecting"}} {"line":"[2024-10-22 16:12:28.253][60][debug][connection] [external/envoy/source/common/network/connection_impl.h:98] [Tags: \"ConnectionId\":\"87\"] current connecting state: true"}} ```the theory is that configuration somehow triggers the problem in the parser and make it even worse if response from the server is not
well formatted single response, as a result other components become unreliable, while we would UPE or something similar.
PoC
in test environment were able to easily reproduce by submitting
HEAD
requests, and server response as sequence of:25 clients. one instance of envoyB, all requests hitting same SRV instance(process is sequential), Client timeout ~ 150ms, Request Duration ~30ms, Avg Response on client ~ 440ms,, 65% of request failing with DC on envoyA, %50 of requests got to envoyB failing with DR, rest of requests has
200 ok
was not able to reproduce the request entanglement without keep-alive
max_requests_per_connection: 1
or with disabled delayed reset:envoy.reloadable_features.http1_balsa_delay_reset=false
Impact
High, users who are using keep-alive http/1.1 upstream and/or vulnerable upstream server which not strictly posing single well formatted responses
Mitigation