Thrift connection manager crash on remote close during active request #9037
Description
Description:
With a non-Envoy downstream service sending Thrift requests to Envoy using the THeader transport/TBinary protocol. If the downstream service closes the connection (e.g. close on timeout) while the request is pending, Envoy can crash.
Repro steps:
Send THeader/TBinary Thrift request with Xms timeout and it times out. Can provide a full repro if required as used proprietary code to produce the below output.
Config:
[
{
"@type": "type.googleapis.com/envoy.api.v2.Listener",
"address": {
"socket_address": {
"address": "0.0.0.0",
"port_value": 9000
}
},
"filter_chains": [
{
"filters": [
{
"name": "envoy.filters.network.thrift_proxy",
"typed_config": {
"@type": "type.googleapis.com/envoy.config.filter.network.thrift_proxy.v2alpha1.ThriftProxy",
"route_config": {
"name": "routes",
"routes": [
{
"match": {
"method_name": ""
},
"route": {
"cluster": "local_cluster"
}
}
]
},
"stat_prefix": "ingress",
"thrift_filters": [
{
"name": "envoy.filters.thrift.router",
"typed_config": {
"@type": "type.googleapis.com/envoy.config.filter.thrift.router.v2alpha1.Router"
}
}
]
}
}
],
"tls_context": {
"common_tls_context": {
...
},
"require_client_certificate": true
}
}
],
"name": "ingress"
},
{
"@type": "type.googleapis.com/envoy.api.v2.Cluster",
"circuit_breakers": {
"thresholds": [
{
"max_connections": 16384,
"max_pending_requests": 16384,
"max_requests": 16384,
"priority": "DEFAULT"
}
]
},
"connect_timeout": "0.25s",
"lb_policy": "LEAST_REQUEST",
"load_assignment": {
"cluster_name": "local_cluster",
"endpoints": [
{
"lb_endpoints": [
{
"endpoint": {
"address": {
"socket_address": {
"address": "127.0.0.1",
"port_value": 9200
}
}
}
},
...
{
"endpoint": {
"address": {
"socket_address": {
"address": "127.0.0.1",
"port_value": 9239
}
}
}
}
]
}
]
},
"name": "local_cluster",
"type": "STATIC"
}
]
Logs:
[2019-11-15 01:16:20.152][91][debug][conn_handler] [external/envoy/source/server/connection_handler_impl.cc:335] [C8] new connection
[2019-11-15 01:16:20.152][91][debug][connection] [external/envoy/source/extensions/transport_sockets/tls/ssl_socket.cc:191] [C8] handshake expecting read
[2019-11-15 01:16:20.152][91][debug][connection] [external/envoy/source/extensions/transport_sockets/tls/ssl_socket.cc:191] [C8] handshake expecting read
[2019-11-15 01:16:20.153][91][debug][connection] [external/envoy/source/extensions/transport_sockets/tls/ssl_socket.cc:176] [C8] handshake complete
[2019-11-15 01:16:20.154][91][debug][thrift] [external/envoy/source/extensions/filters/network/thrift_proxy/decoder.cc:367] thrift: 254 bytes available
[2019-11-15 01:16:20.154][91][debug][thrift] [external/envoy/source/extensions/filters/network/thrift_proxy/decoder.cc:388] thrift: header(auto) transport started
[2019-11-15 01:16:20.154][91][debug][thrift] [external/envoy/source/extensions/filters/network/thrift_proxy/decoder.cc:394] thrift: header(auto) transport forced binary(auto) protocol
[2019-11-15 01:16:20.154][91][debug][thrift] [external/envoy/source/extensions/filters/network/thrift_proxy/decoder.cc:422] thrift: protocol binary(auto), state MessageBegin, 120 bytes available
[2019-11-15 01:16:20.154][91][debug][thrift] [external/envoy/source/extensions/filters/network/thrift_proxy/router/router_impl.cc:226] [C8][S4833533741472223023] cluster 'local_cluster' match for method 'thrift_method'
[2019-11-15 01:16:20.154][91][debug][thrift] [external/envoy/source/extensions/filters/network/thrift_proxy/router/router_impl.cc:259] [C8][S4833533741472223023] router decoding request
[2019-11-15 01:16:20.154][91][debug][pool] [external/envoy/source/common/tcp/conn_pool.cc:83] creating a new connection
[2019-11-15 01:16:20.154][91][debug][pool] [external/envoy/source/common/tcp/conn_pool.cc:364] [C9] connecting
[2019-11-15 01:16:20.154][91][debug][connection] [external/envoy/source/common/network/connection_impl.cc:707] [C9] connecting to 127.0.0.1:9210
[2019-11-15 01:16:20.154][91][debug][connection] [external/envoy/source/common/network/connection_impl.cc:716] [C9] connection in progress
[2019-11-15 01:16:20.154][91][debug][pool] [external/envoy/source/common/tcp/conn_pool.cc:109] queueing request due to no available connections
[2019-11-15 01:16:20.154][91][debug][thrift] [external/envoy/source/extensions/filters/network/thrift_proxy/decoder.cc:430] thrift: wait for continuation
[2019-11-15 01:16:20.154][91][debug][connection] [external/envoy/source/common/network/connection_impl.cc:555] [C9] connected
[2019-11-15 01:16:20.154][91][debug][pool] [external/envoy/source/common/tcp/conn_pool.cc:285] [C9] assigning connection
[2019-11-15 01:16:20.154][91][debug][thrift] [external/envoy/source/extensions/filters/network/thrift_proxy/conn_manager.cc:128] [C8] thrift filter continued
[2019-11-15 01:16:20.154][91][debug][thrift] [external/envoy/source/extensions/filters/network/thrift_proxy/decoder.cc:367] thrift: 82 bytes available
[2019-11-15 01:16:20.154][91][debug][thrift] [external/envoy/source/extensions/filters/network/thrift_proxy/decoder.cc:422] thrift: protocol binary(auto), state StructBegin, 82 bytes available
[2019-11-15 01:16:20.154][91][debug][thrift] [external/envoy/source/extensions/filters/network/thrift_proxy/decoder.cc:446] thrift: header(auto) transport ended
[2019-11-15 01:16:20.169][91][debug][connection] [external/envoy/source/common/network/connection_impl.cc:523] [C9] remote close
[2019-11-15 01:16:20.169][91][debug][connection] [external/envoy/source/common/network/connection_impl.cc:189] [C9] closing socket: 0
[2019-11-15 01:16:20.169][91][debug][pool] [external/envoy/source/common/tcp/conn_pool.cc:124] [C9] client disconnected
[2019-11-15 01:16:20.169][91][debug][connection] [external/envoy/source/common/network/connection_impl.cc:100] [C8] closing data_to_write=226 type=0
[2019-11-15 01:16:20.170][91][debug][pool] [external/envoy/source/common/tcp/conn_pool.cc:238] [C9] connection destroyed
[2019-11-15 01:16:20.170][91][debug][connection] [external/envoy/source/extensions/transport_sockets/tls/ssl_socket.cc:298] [C8] SSL shutdown: rc=0
[2019-11-15 01:16:20.170][91][debug][connection] [external/envoy/source/extensions/transport_sockets/tls/ssl_socket.cc:226] [C8]
[2019-11-15 01:16:20.170][91][debug][connection] [external/envoy/source/common/network/connection_impl.cc:585] [C8] write flush complete
[2019-11-15 01:16:20.170][91][debug][connection] [external/envoy/source/common/network/connection_impl.cc:189] [C8] closing socket: 1
[2019-11-15 01:16:20.170][91][debug][thrift] [external/envoy/source/extensions/filters/network/thrift_proxy/conn_manager.cc:147] [C8] local close with active request
[2019-11-15 01:16:20.170][91][debug][conn_handler] [external/envoy/source/server/connection_handler_impl.cc:88] [C8] adding to cleanup list
Call Stack:
[2019-11-15 01:16:20.170][91][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:83] Caught Segmentation fault, suspect faulting address 0x0
[2019-11-15 01:16:20.170][91][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:70] Backtrace (use tools/stack_decode.py to get line numbers):
[2019-11-15 01:16:20.170][91][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:71] Envoy version: 0/1.13.0-dev//RELEASE/BoringSSL
[2019-11-15 01:16:20.170][91][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:75] #0: __restore_rt [0x7f15eb357890] ??:0
[2019-11-15 01:16:20.172][91][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:75] #1: Envoy::Extensions::NetworkFilters::ThriftProxy::ConnectionManager::ActiveRpc::~ActiveRpc() [0x556162c51d89] ??:0
[2019-11-15 01:16:20.174][91][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:75] #2: Envoy::Extensions::NetworkFilters::ThriftProxy::ConnectionManager::ActiveRpc::~ActiveRpc() [0x556162c5209e] ??:0
[2019-11-15 01:16:20.177][91][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:75] #3: Envoy::Event::DispatcherImpl::clearDeferredDeleteList() [0x556162d1a8f7] ??:0
[2019-11-15 01:16:20.179][91][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:75] #4: event_process_active_single_queue [0x55616303be06] ??:0
[2019-11-15 01:16:20.181][91][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:75] #5: event_base_loop [0x55616303a9be] ??:0
[2019-11-15 01:16:20.183][91][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:75] #6: Envoy::Server::WorkerImpl::threadRoutine() [0x556162d139b6] ??:0
[2019-11-15 01:16:20.185][91][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:75] #7: Envoy::Thread::ThreadImplPosix::ThreadImplPosix()::$_0::__invoke() [0x5561631c44b5] ??:0
[2019-11-15 01:16:20.185][91][critical][backtrace] [bazel-out/k8-opt/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:75] #8: start_thread [0x7f15eb34c6db] ??:0
cc @rgs1