From 1993922765cf754ddeb8cf64b9efc18c31ed0c24 Mon Sep 17 00:00:00 2001 From: Gregory Brail Date: Tue, 3 Aug 2021 00:42:31 +0000 Subject: [PATCH 1/4] ext_proc: Ensure that timer is always cancelled Ensure that the timer is cancelled when an "ImmediateResponse" message is received. Signed-off-by: Gregory Brail --- .../filters/http/ext_proc/ext_proc.cc | 2 ++ .../filters/http/ext_proc/filter_test.cc | 26 ++++++++++++++++++- .../filters/http/ext_proc/ordering_test.cc | 14 ++++++++++ 3 files changed, 41 insertions(+), 1 deletion(-) diff --git a/source/extensions/filters/http/ext_proc/ext_proc.cc b/source/extensions/filters/http/ext_proc/ext_proc.cc index 711e377161cc8..414ea56b5fca8 100644 --- a/source/extensions/filters/http/ext_proc/ext_proc.cc +++ b/source/extensions/filters/http/ext_proc/ext_proc.cc @@ -50,6 +50,7 @@ Filter::StreamOpenState Filter::openStream() { } void Filter::onDestroy() { + ENVOY_LOG(trace, "onDestroy"); // Make doubly-sure we no longer use the stream, as // per the filter contract. processing_complete_ = true; @@ -414,6 +415,7 @@ void Filter::onReceiveMessage(std::unique_ptr&& r) { // We won't be sending anything more to the stream after we // receive this message. processing_complete_ = true; + cleanUpTimers(); sendImmediateResponse(response->immediate_response()); message_handled = true; break; diff --git a/test/extensions/filters/http/ext_proc/filter_test.cc b/test/extensions/filters/http/ext_proc/filter_test.cc index 54a3c1820288c..d84901bc46202 100644 --- a/test/extensions/filters/http/ext_proc/filter_test.cc +++ b/test/extensions/filters/http/ext_proc/filter_test.cc @@ -38,6 +38,7 @@ using Http::FilterHeadersStatus; using Http::FilterTrailersStatus; using Http::LowerCaseString; +using testing::AnyNumber; using testing::Eq; using testing::Invoke; using testing::ReturnRef; @@ -57,6 +58,19 @@ class HttpFilterTest : public testing::Test { EXPECT_CALL(*client_, start(_)).WillOnce(Invoke(this, &HttpFilterTest::doStart)); EXPECT_CALL(encoder_callbacks_, dispatcher()).WillRepeatedly(ReturnRef(dispatcher_)); EXPECT_CALL(decoder_callbacks_, dispatcher()).WillRepeatedly(ReturnRef(dispatcher_)); + EXPECT_CALL(dispatcher_, createTimer_(_)) + .Times(AnyNumber()) + .WillRepeatedly(Invoke([this](Unused) { + // Create a mock timer that we can check at destruction time to see if + // all timers were disabled no matter what. MockTimer has default + // actions that we just have to enable properly here. + auto* timer = new Event::MockTimer(); + EXPECT_CALL(*timer, enableTimer(_, _)).Times(AnyNumber()); + EXPECT_CALL(*timer, disableTimer()).Times(AnyNumber()); + EXPECT_CALL(*timer, enabled()).Times(AnyNumber()); + timers_.push_back(timer); + return timer; + })); envoy::extensions::filters::http::ext_proc::v3alpha::ExternalProcessor proto_config{}; if (!yaml.empty()) { @@ -72,6 +86,15 @@ class HttpFilterTest : public testing::Test { request_headers_.setMethod("POST"); } + void TearDown() override { + for (auto* t : timers_) { + // This will fail if any timer is un-disabled at the end of the test run. + // (This particular test suite does not actually let timers expire, + // although other test suites do.) + EXPECT_FALSE(t->enabled_); + } + } + ExternalProcessorStreamPtr doStart(ExternalProcessorCallbacks& callbacks) { stream_callbacks_ = &callbacks; @@ -214,13 +237,14 @@ class HttpFilterTest : public testing::Test { NiceMock stats_store_; FilterConfigSharedPtr config_; std::unique_ptr filter_; - NiceMock dispatcher_; + testing::NiceMock dispatcher_; Http::MockStreamDecoderFilterCallbacks decoder_callbacks_; Http::MockStreamEncoderFilterCallbacks encoder_callbacks_; Http::TestRequestHeaderMapImpl request_headers_; Http::TestResponseHeaderMapImpl response_headers_; Http::TestRequestTrailerMapImpl request_trailers_; Http::TestResponseTrailerMapImpl response_trailers_; + std::vector timers_; }; // Using the default configuration, test the filter with a processor that diff --git a/test/extensions/filters/http/ext_proc/ordering_test.cc b/test/extensions/filters/http/ext_proc/ordering_test.cc index d76da3dd8eec1..df7cf2ac284f1 100644 --- a/test/extensions/filters/http/ext_proc/ordering_test.cc +++ b/test/extensions/filters/http/ext_proc/ordering_test.cc @@ -32,6 +32,7 @@ using Http::FilterHeadersStatus; using Http::FilterTrailersStatus; using Http::LowerCaseString; +using testing::AnyNumber; using testing::Invoke; using testing::Return; using testing::ReturnRef; @@ -532,9 +533,14 @@ TEST_F(OrderingTest, AddRequestTrailers) { TEST_F(OrderingTest, ImmediateResponseOnRequest) { initialize(absl::nullopt); + // MockTimer constructor sets up expectations in the Dispatcher class to wire it up + MockTimer* request_timer = new MockTimer(&dispatcher_); + EXPECT_CALL(*request_timer, enableTimer(kMessageTimeout, nullptr)); + EXPECT_CALL(*request_timer, enabled()).Times(AnyNumber()); EXPECT_CALL(stream_delegate_, send(_, false)); sendRequestHeadersGet(true); EXPECT_CALL(encoder_callbacks_, sendLocalReply(Http::Code::InternalServerError, _, _, _, _)); + EXPECT_CALL(*request_timer, disableTimer()); sendImmediateResponse500(); // The rest of the filter isn't necessarily called after this. } @@ -543,14 +549,22 @@ TEST_F(OrderingTest, ImmediateResponseOnRequest) { TEST_F(OrderingTest, ImmediateResponseOnResponse) { initialize(absl::nullopt); + MockTimer* request_timer = new MockTimer(&dispatcher_); + EXPECT_CALL(*request_timer, enabled()).Times(AnyNumber()); + EXPECT_CALL(*request_timer, enableTimer(kMessageTimeout, nullptr)); EXPECT_CALL(stream_delegate_, send(_, false)); sendRequestHeadersGet(true); EXPECT_CALL(decoder_callbacks_, continueDecoding()); + EXPECT_CALL(*request_timer, disableTimer()); sendRequestHeadersReply(); + MockTimer* response_timer = new MockTimer(&dispatcher_); + EXPECT_CALL(*response_timer, enableTimer(kMessageTimeout, nullptr)); + EXPECT_CALL(*response_timer, enabled()).Times(AnyNumber()); EXPECT_CALL(stream_delegate_, send(_, false)); sendResponseHeaders(true); EXPECT_CALL(encoder_callbacks_, sendLocalReply(Http::Code::InternalServerError, _, _, _, _)); + EXPECT_CALL(*response_timer, disableTimer()); sendImmediateResponse500(); Buffer::OwnedImpl resp_body("Hello!"); EXPECT_EQ(FilterDataStatus::Continue, filter_->encodeData(resp_body, true)); From dfd901d7c669cd83afd41c995d1f79ef322800ee Mon Sep 17 00:00:00 2001 From: Gregory Brail Date: Tue, 3 Aug 2021 06:59:40 +0000 Subject: [PATCH 2/4] ext_proc: Add one more extra check Signed-off-by: Gregory Brail --- source/extensions/filters/http/ext_proc/ext_proc.cc | 3 +++ 1 file changed, 3 insertions(+) diff --git a/source/extensions/filters/http/ext_proc/ext_proc.cc b/source/extensions/filters/http/ext_proc/ext_proc.cc index 414ea56b5fca8..bc13d616676e4 100644 --- a/source/extensions/filters/http/ext_proc/ext_proc.cc +++ b/source/extensions/filters/http/ext_proc/ext_proc.cc @@ -467,6 +467,9 @@ void Filter::onGrpcError(Grpc::Status::GrpcStatus status) { void Filter::onGrpcClose() { ENVOY_LOG(debug, "Received gRPC stream close"); + if (processing_complete_) { + return; + } processing_complete_ = true; stats_.streams_closed_.inc(); // Successful close. We can ignore the stream for the rest of our request From 74e5f79a10e30560f74d89f895cb99794b59db38 Mon Sep 17 00:00:00 2001 From: Gregory Brail Date: Wed, 4 Aug 2021 18:00:14 +0000 Subject: [PATCH 3/4] ext_proc: Address code review comments Signed-off-by: Gregory Brail --- source/extensions/filters/http/ext_proc/ext_proc.cc | 3 --- test/extensions/filters/http/ext_proc/BUILD | 2 +- test/extensions/filters/http/ext_proc/filter_test.cc | 2 +- 3 files changed, 2 insertions(+), 5 deletions(-) diff --git a/source/extensions/filters/http/ext_proc/ext_proc.cc b/source/extensions/filters/http/ext_proc/ext_proc.cc index e1d5b3052647f..bb2673f664e39 100644 --- a/source/extensions/filters/http/ext_proc/ext_proc.cc +++ b/source/extensions/filters/http/ext_proc/ext_proc.cc @@ -514,9 +514,6 @@ void Filter::onGrpcError(Grpc::Status::GrpcStatus status) { void Filter::onGrpcClose() { ENVOY_LOG(debug, "Received gRPC stream close"); - if (processing_complete_) { - return; - } processing_complete_ = true; stats_.streams_closed_.inc(); // Successful close. We can ignore the stream for the rest of our request diff --git a/test/extensions/filters/http/ext_proc/BUILD b/test/extensions/filters/http/ext_proc/BUILD index 827731d8066f5..0ecdb6aff3787 100644 --- a/test/extensions/filters/http/ext_proc/BUILD +++ b/test/extensions/filters/http/ext_proc/BUILD @@ -111,7 +111,7 @@ envoy_extension_cc_test( envoy_extension_cc_test( name = "streaming_integration_test", - size = "medium", + size = "small", srcs = ["streaming_integration_test.cc"], extension_names = ["envoy.filters.http.ext_proc"], deps = [ diff --git a/test/extensions/filters/http/ext_proc/filter_test.cc b/test/extensions/filters/http/ext_proc/filter_test.cc index 9fbd443de2f76..df872b98a3580 100644 --- a/test/extensions/filters/http/ext_proc/filter_test.cc +++ b/test/extensions/filters/http/ext_proc/filter_test.cc @@ -88,7 +88,7 @@ class HttpFilterTest : public testing::Test { void TearDown() override { for (auto* t : timers_) { - // This will fail if any timer is un-disabled at the end of the test run. + // This will fail if, at the end of the test, we left any timers enabled. // (This particular test suite does not actually let timers expire, // although other test suites do.) EXPECT_FALSE(t->enabled_); From a7dab572f1532ea3e9a9ca46a16126504d633f79 Mon Sep 17 00:00:00 2001 From: Gregory Brail Date: Thu, 5 Aug 2021 16:01:07 +0000 Subject: [PATCH 4/4] ext_proc: streaming_integration_test is medium with tsan Signed-off-by: Gregory Brail --- test/extensions/filters/http/ext_proc/BUILD | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/test/extensions/filters/http/ext_proc/BUILD b/test/extensions/filters/http/ext_proc/BUILD index 0ecdb6aff3787..827731d8066f5 100644 --- a/test/extensions/filters/http/ext_proc/BUILD +++ b/test/extensions/filters/http/ext_proc/BUILD @@ -111,7 +111,7 @@ envoy_extension_cc_test( envoy_extension_cc_test( name = "streaming_integration_test", - size = "small", + size = "medium", srcs = ["streaming_integration_test.cc"], extension_names = ["envoy.filters.http.ext_proc"], deps = [