Race condition between Envoy's deferred deletion and cancelled gRPC response
- Dominant language
- C++
- Stars
- 28.9k
- Forks
- 5.6k
- Avg merge
- 1d 20h
- Merged PRs (30d)
- 437
Description
This is a follow up of https://github.com/envoyproxy/envoy/issues/27999, which was closed due to inactivity. I am unable to reopen that issue, so raising a new issue.
We are hitting the crash mentioned in https://github.com/envoyproxy/envoy/issues/27999 more frequent with the upgrade of envoy from v1.20.7 to v1.29.0. To add a bit more context and details on the issue. The sequence of events are as follows:
1. We are issuing a gRPC request using an `Envoy::Grpc::AsyncRequestImpl` object and `Envoy::Grpc::AsyncRequestCallbacks` for handling the callbacks
2. Based on certain criteria, we decide to destroy the gRPC request for which we are still waiting on a response by calling `cancel()` on the `Envoy::Grpc::AsyncRequestImpl` in the destructor of the `Envoy::Grpc::AsyncRequestCallbacks` object. The `cancel()` call chain is as follows where the request is appended to the deferred deletion list. Everything on our side including callbacks are deleted after this point as we don’t expect Envoy to invoke the callback on the gRPC request whose response is still pending.
```
void AsyncRequestImpl::cancel() {
current_span_->setTag(Tracing::Tags::get().Status, Tracing::Tags::get().Canceled);
current_span_->finishSpan();
this->resetStream();
}
void AsyncStreamImpl::resetStream() { cleanup(); }
void AsyncStreamImpl::cleanup() {
if (!http_reset_) {
http_reset_ = true;
stream_->reset();
}
// This will destroy us, but only do so if we are actually in a list. This does not happen in
// the immediate failure case.
if (LinkedObject::inserted()) {
ASSERT(dispatcher_->isThreadSafe());
dispatcher_->deferredDelete(
LinkedObject::removeFromList(parent_.active_streams_));
}
}
```
3. We receive the gRPC response that was sent in Step 1 but Envoy has not got to deleting the `AsyncRequestImpl` that was on the deferred deletion list yet, so the callback is called by Envoy and we hit a crash with the following call stack since everything is freed on our side.
```
"message": "#27: Envoy::Thread::ThreadImplPosix::ThreadImplPosix()::{lambda()#1}::__invoke()",
"message": "#26: Envoy::Server::WorkerImpl::threadRoutine()",
"message": "#25: event_base_loop"
"message": "#24: event_process_active_single_queue"
"message": "#23: Envoy::Event::FileEventImpl::assignEvents()::$_1::__invoke()",
"message": "#22: std::_Function_handler<>::_M_invoke()"
"message": "#21: Envoy::Network::ConnectionImpl::onFileEvent()",
"message": "#20: Envoy::Network::ConnectionImpl::onReadReady()",
"message": "#19: Envoy::Network::FilterManagerImpl::onContinueReading()",
"message": "#18: Envoy::Http::CodecClient::CodecReadFilter::onData()",
"message": "#17: Envoy::Http::CodecClient::onData()"
"message": "#16: Envoy::Http::Http2::ConnectionImpl::dispatch()",
"message": "#15: Envoy::Http::Http2::ConnectionImpl::dispatch()",
"message": "#14: http2::adapter::NgHttp2Adapter::ProcessBytes()"
"message": "#13: nghttp2_session_mem_recv",
"message": "#12: http2::adapter::callbacks::OnFrameReceived()",
"message": "#11: http2::adapter::CallbackVisitor::OnEndHeadersForStream()",
"message": "#10: Envoy::Http::Http2::ConnectionImpl::Http2Callbacks::Http2Callbacks()::$_29::__invoke()"
"message": "#9: Envoy::Http::Http2::ConnectionImpl::onFrameReceived()",
"message": "#8: Envoy::Http::ResponseDecoderWrapper::decodeTrailers()",
"message": "#7: Envoy::Router::UpstreamRequest::decodeTrailers()"
"message": "#6: Envoy::Http::AsyncStreamImpl::encodeTrailers()",
"message": "#5: Envoy::Grpc::AsyncStreamImpl::onTrailers()",
"message": "#4: Envoy::Grpc::AsyncRequestImpl::onRemoteClose()"
"message": "#3: Envoy::Grpc::AsyncRequestCallbacks<>::onSuccessRaw()"
```
Essentially, there is a race between Envoy deleting the deferred `AsyncRequestImpl` object and the gRPC response for the cancelled `AsyncRequestImpl` request. In the core, we are able to see that the `AsyncRequestImpl` is still in the deferred deletion list and treated as an active stream.
From frame `"message": "#9: Envoy::Http::Http2::ConnectionImpl::onFrameReceived()"`,
```
(gdb) p *frame
$96 = {
hd = {
length = 1,
stream_id = 31928399,
type = 1 '\001', <——— NGHTTP2_HEADERS
flags = 5 '\005', <——— NGHTTP2_FLAG_END_STREAM, NGHTTP2_FLAG_END_HEADERS
reserved = 0 '\000'
},
data = {
hd = {
length = 1,
stream_id = 31928399,
type = 1 '\001',
flags = 5 '\005',
reserved = 0 '\000'
},
padlen = 0
},
headers = {
hd = {
length = 1,
stream_id = 31928399,
type = 1 '\001',
flags = 5 '\005',
reserved = 0 '\000'
},
padlen = 0,
pri_spec = {
stream_id = 0,
weight = 0,
exclusive = 0 '\000'
},
nva = 0x0,
nvlen = 0,
cat = NGHTTP2_HCAT_HEADERS
},
priority = {
hd = {
length = 1,
stream_id = 31928399,
type = 1 '\001',
flags = 5 '\005',
reserved = 0 '\000'
},
pri_spec = {
stream_id = 0,
weight = 0,
exclusive = 0 '\000'
}
},
rst_stream = {
hd = {
length = 1,
stream_id = 31928399,
type = 1 '\001',
flags = 5 '\005',
reserved = 0 '\000'
},
error_code = 0
},
settings = {
hd = {
length = 1,
stream_id = 31928399,
type = 1 '\001',
flags = 5 '\005',
reserved = 0 '\000'
},
niv = 0,
iv = 0x0
},
push_promise = {
hd = {
length = 1,
stream_id = 31928399,
type = 1 '\001',
flags = 5 '\005',
reserved = 0 '\000'
},
padlen = 0,
nva = 0x0,
nvlen = 0,
promised_stream_id = 0,
reserved = 0 '\000'
},
ping = {
hd = {
length = 1,
stream_id = 31928399,
type = 1 '\001',
flags = 5 '\005',
reserved = 0 '\000'
},
opaque_data = "\000\000\000\000\000\000\000"
},
goaway = {
hd = {
length = 1,
stream_id = 31928399,
type = 1 '\001',
flags = 5 '\005',
reserved = 0 '\000'
},
last_stream_id = 0,
error_code = 0,
opaque_data = 0x0,
opaque_data_len = 0,
reserved = 0 '\000'
},
window_update = {
hd = {
length = 1,
stream_id = 31928399,
type = 1 '\001',
flags = 5 '\005',
reserved = 0 '\000'
},
window_size_increment = 0,
reserved = 0 '\000'
},
ext = {
hd = {
length = 1,
stream_id = 31928399,
type = 1 '\001',
flags = 5 '\005',
reserved = 0 '\000'
},
payload = 0x0
}
}
(gdb) p active_streams_
$97 = {
>, std::allocator > > >> = {
_M_impl = {
> > >> = {
<__gnu_cxx::new_allocator > > >> = {}, },
members of std::__cxx11::_List_base >, std::allocator > > >::_List_impl:
_M_node = {
= {
_M_next = 0x55ddcb3d4f40,
_M_prev = 0x55dda734eb60
},
members of std::__detail::_List_node_header:
_M_size = 32
}
}
}, }
(gdb) set $n = active_streams_._M_impl._M_node._M_next
(gdb) set $i = 0
(gdb) while $i < 32
>set $p = ((Envoy::Http::Http2::ConnectionImpl::StreamImpl*)((void**)$n)[2])
>p $p->stream_id_
>set $n = $n->_M_next
>set $i = $i + 1
>end
$98 = 31928467
$99 = 31928465
$100 = 31928463
$101 = 31928461
$102 = 31928459
$103 = 31928457
$104 = 31928455
$105 = 31928453
$106 = 31928451
$107 = 31928449
$108 = 31928447
$109 = 31928445
$110 = 31928443
$111 = 31928441
$112 = 31928439
$113 = 31928437
$114 = 31928435
$115 = 31928433
$116 = 31928431
$117 = 31928429
$118 = 31928427
$119 = 31928425
$120 = 31928423
$121 = 31928421
$122 = 31928419
$123 = 31928417
$124 = 31928415
$125 = 31928413
$126 = 31928411
$127 = 31928409
$128 = 31928399 <—————— stream that we got the trailer on
$129 = 31928395
```
Contributor guide
Assessment
This issue has not been assessed yet.