Test flake in OauthIntegrationTest.UnauthenticatedFlow

[oschaaf]

In a CI coverage run for another PR, a flake was caught in OauthIntegrationTest.UnauthenticatedFlow
which I haven't been able to reproduce locally using O(10k) repetitions. Possibly something
that coverage does, like adding pressure on certain system resources, is needed to tease the issue
out.

Relevant CI log: https://dev.azure.com/cncf/4684fb3d-0389-4e0b-8251-221942316e06/_apis/build/builds/50172/logs/98

[snowp]

I've been able to reproduce this only when running bazel test -c dbg //test/extensions/filters/http/oauth2:oauth_integration_test --runs_per_test=1000, it does not seem to reproduce under gdb or with ASAN for me, which makes it pretty hard to debug.

[antoniovicente]

cc @lizan

Saw this flake on a recent coverage run. I think the main difference between coverage and regular runs is related to log levels. It being reproducible in dbg mode seems interesting.

[antoniovicente]

I seem to have repo'ed under ASAN in the 1.16 release branch.

[ RUN ] OauthIntegrationTest.UnauthenticatedFlow

==12==ERROR: AddressSanitizer: heap-use-after-free on address 0x6190000cc528 at pc 0x000017db0c94 bp 0x7ffc46b3b3b0 sp 0x7ffc46b3b3a8
READ of size 8 at 0x6190000cc528 thread T0
#0 0x17db0c93 in Envoy::Extensions::HttpFilters::Oauth::(anonymous namespace)::OauthIntegrationTest_UnauthenticatedFlow_Test::TestBody() oauth_integration_test.cc:?
#1 0x26f56bdb in void testing::internal::HandleSehExceptionsInMethodIfSupported<testing::Test, void>(testing::Test*, void (testing::Test::)(), char const) ??:?
#2 0x26f005c0 in void testing::internal::HandleExceptionsInMethodIfSupported<testing::Test, void>(testing::Test*, void (testing::Test::)(), char const) ??:?
#3 0x26eb49bf in testing::Test::Run() ??:?
#4 0x26eb6d7f in testing::TestInfo::Run() ??:?
#5 0x26eb8f7e in testing::TestSuite::Run() ??:?
#6 0x26ee350a in testing::internal::UnitTestImpl::RunAllTests() ??:?
#7 0x26f6c1db in bool testing::internal::HandleSehExceptionsInMethodIfSupported<testing::internal::UnitTestImpl, bool>(testing::internal::UnitTestImpl*, bool (testing::internal::UnitTestImpl::)(), char const) ??:?
#8 0x26f093e5 in bool testing::internal::HandleExceptionsInMethodIfSupported<testing::internal::UnitTestImpl, bool>(testing::internal::UnitTestImpl*, bool (testing::internal::UnitTestImpl::)(), char const) ??:?
#9 0x26ee20a2 in testing::UnitTest::Run() ??:?
#10 0x204c1741 in RUN_ALL_TESTS() ??:?
#11 0x204bf5ab in Envoy::TestRunner::RunTests(int, char**) ??:?
#12 0x204b8076 in main ??:?
#13 0x7fca80ac7cc9 in __libc_start_main csu/../csu/libc-start.c:308
#14 0x17d071e9 in _start ??:?

0x6190000cc528 is located 936 bytes inside of 992-byte region [0x6190000cc180,0x6190000cc560)
freed by thread T0 here:
#0 0x17d7f6ad in __interceptor_free ??:?
#1 0x1f507f20 in Envoy::Http::Http2::ConnectionImpl::ClientStreamImpl::~ClientStreamImpl() ??:?
#2 0x191faa6a in std::__1::default_deleteEnvoy::Event::DeferredDeletable::operator()(Envoy::Event::DeferredDeletable*) const connection_handler_impl.cc:?
#3 0x191fa79c in std::__1::unique_ptr<Envoy::Event::DeferredDeletable, std::__1::default_deleteEnvoy::Event::DeferredDeletable >::reset(Envoy::Event::DeferredDeletable*) connection_handler_impl.cc:?
#4 0x20720b22 in Envoy::Event::DispatcherImpl::clearDeferredDeleteList() ??:?
#5 0x2073334c in Envoy::Event::DispatcherImpl::DispatcherImpl(std::__1::basic_string<char, std::__1::char_traits, std::__1::allocator > const&, std::__1::unique_ptr<Envoy::Buffer::WatermarkFactory, std::__1::default_deleteEnvoy::Buffer::WatermarkFactory >&&, Envoy::Api::Api&, Envoy::Event::TimeSystem&)::$_0::operator()() const dispatcher_impl.cc:?
#6 0x20733229 in _ZNSt3__18__invokeIRZN5Envoy5Event14DispatcherImplC1ERKNS_12basic_stringIcNS_11char_traitsIcEENS_9allocatorIcEEEEONS_10unique_ptrINS1_6Buffer16WatermarkFactoryENS_14default_deleteISE_EEEERNS1_3Api3ApiERNS2_10TimeSystemEE3$0JEEEDTclclsr3std3__1E7forwardIT_Efp_Espclsr3std3__1E7forwardIT0_Efp0_EEEOSQ_DpOSR dispatcher_impl.cc:?
#7 0x20733079 in void std::__1::__invoke_void_return_wrapper::__call<Envoy::Event::DispatcherImpl::DispatcherImpl(std::__1::basic_string<char, std::__1::char_traits, std::__1::allocator > const&, std::__1::unique_ptr<Envoy::Buffer::WatermarkFactory, std::__1::default_deleteEnvoy::Buffer::WatermarkFactory >&&, Envoy::Api::Api&, Envoy::Event::TimeSystem&)::$_0&>(Envoy::Event::DispatcherImpl::DispatcherImpl(std::__1::basic_string<char, std::__1::char_traits, std::__1::allocator > const&, std::__1::unique_ptr<Envoy::Buffer::WatermarkFactory, std::__1::default_deleteEnvoy::Buffer::WatermarkFactory >&&, Envoy::Api::Api&, Envoy::Event::TimeSystem&)::$_0&) dispatcher_impl.cc:?
#8 0x20732fcf in std::__1::__function::__alloc_func<Envoy::Event::DispatcherImpl::DispatcherImpl(std::__1::basic_string<char, std::__1::char_traits, std::__1::allocator > const&, std::__1::unique_ptr<Envoy::Buffer::WatermarkFactory, std::__1::default_deleteEnvoy::Buffer::WatermarkFactory >&&, Envoy::Api::Api&, Envoy::Event::TimeSystem&)::$_0, std::__1::allocator<Envoy::Event::DispatcherImpl::DispatcherImpl(std::__1::basic_string<char, std::__1::char_traits, std::__1::allocator > const&, std::__1::unique_ptr<Envoy::Buffer::WatermarkFactory, std::__1::default_deleteEnvoy::Buffer::WatermarkFactory >&&, Envoy::Api::Api&, Envoy::Event::TimeSystem&)::$_0>, void ()>::operator()() dispatcher_impl.cc:?
#9 0x2072dbda in std::__1::__function::__func<Envoy::Event::DispatcherImpl::DispatcherImpl(std::__1::basic_string<char, std::__1::char_traits, std::__1::allocator > const&, std::__1::unique_ptr<Envoy::Buffer::WatermarkFactory, std::__1::default_deleteEnvoy::Buffer::WatermarkFactory >&&, Envoy::Api::Api&, Envoy::Event::TimeSystem&)::$_0, std::__1::allocator<Envoy::Event::DispatcherImpl::DispatcherImpl(std::__1::basic_string<char, std::__1::char_traits, std::__1::allocator > const&, std::__1::unique_ptr<Envoy::Buffer::WatermarkFactory, std::__1::default_deleteEnvoy::Buffer::WatermarkFactory >&&, Envoy::Api::Api&, Envoy::Event::TimeSystem&)::$_0>, void ()>::operator()() dispatcher_impl.cc:?
#10 0x18735ad3 in std::__1::__function::__value_func<void ()>::operator()() const autonomous_upstream.cc:?
#11 0x187351da in std::__1::function<void ()>::operator()() const ??:?
#12 0x21eade1f in Envoy::Event::SchedulableCallbackImpl::SchedulableCallbackImpl(Envoy::CSmartPtr<event_base, &event_base_free>&, std::__1::function<void ()>)::$_0::operator()(int, short, void*) const schedulable_cb_impl.cc:?
#13 0x21eadd65 in Envoy::Event::SchedulableCallbackImpl::SchedulableCallbackImpl(Envoy::CSmartPtr<event_base, &event_base_free>&, std::__1::function<void ()>)::$_0::__invoke(int, short, void*) schedulable_cb_impl.cc:?
#14 0x223e48ad in event_process_active_single_queue event.c:?
#15 0x223bc080 in event_process_active event.c:?
#16 0x223b3959 in event_base_loop ??:?
#17 0x21ea3a57 in Envoy::Event::LibeventScheduler::run(Envoy::Event::Dispatcher::RunType) ??:?
#18 0x2072b7a9 in Envoy::Event::DispatcherImpl::run(Envoy::Event::Dispatcher::RunType) ??:?
#19 0x1824c039 in Envoy::IntegrationCodecClient::flushWrite() ??:?
#20 0x1824f31d in Envoy::IntegrationCodecClient::startRequest(Envoy::Http::RequestHeaderMap const&) ??:?
#21 0x17db0bd0 in Envoy::Extensions::HttpFilters::Oauth::(anonymous namespace)::OauthIntegrationTest_UnauthenticatedFlow_Test::TestBody() oauth_integration_test.cc:?
#22 0x26f56bdb in void testing::internal::HandleSehExceptionsInMethodIfSupported<testing::Test, void>(testing::Test*, void (testing::Test::)(), char const) ??:?
#23 0x26f005c0 in void testing::internal::HandleExceptionsInMethodIfSupported<testing::Test, void>(testing::Test*, void (testing::Test::)(), char const) ??:?
#24 0x26eb49bf in testing::Test::Run() ??:?
#25 0x26eb6d7f in testing::TestInfo::Run() ??:?
#26 0x26eb8f7e in testing::TestSuite::Run() ??:?
#27 0x26ee350a in testing::internal::UnitTestImpl::RunAllTests() ??:?
#28 0x26f6c1db in bool testing::internal::HandleSehExceptionsInMethodIfSupported<testing::internal::UnitTestImpl, bool>(testing::internal::UnitTestImpl*, bool (testing::internal::UnitTestImpl::)(), char const) ??:?
#29 0x26f093e5 in bool testing::internal::HandleExceptionsInMethodIfSupported<testing::internal::UnitTestImpl, bool>(testing::internal::UnitTestImpl*, bool (testing::internal::UnitTestImpl::)(), char const) ??:?

previously allocated by thread T0 here:
#0 0x17d7f92d in __interceptor_malloc ??:?
#1 0x7fca80d62a37 in operator new(unsigned long) ??:?
#2 0x1f1828cf in Envoy::Http::CodecClient::newStream(Envoy::Http::ResponseDecoder&) ??:?
#3 0x1824ef52 in Envoy::IntegrationCodecClient::startRequest(Envoy::Http::RequestHeaderMap const&) ??:?
#4 0x17db0bd0 in Envoy::Extensions::HttpFilters::Oauth::(anonymous namespace)::OauthIntegrationTest_UnauthenticatedFlow_Test::TestBody() oauth_integration_test.cc:?
#5 0x26f56bdb in void testing::internal::HandleSehExceptionsInMethodIfSupported<testing::Test, void>(testing::Test*, void (testing::Test::)(), char const) ??:?
#6 0x26f005c0 in void testing::internal::HandleExceptionsInMethodIfSupported<testing::Test, void>(testing::Test*, void (testing::Test::)(), char const) ??:?
#7 0x26eb49bf in testing::Test::Run() ??:?
#8 0x26eb6d7f in testing::TestInfo::Run() ??:?
#9 0x26eb8f7e in testing::TestSuite::Run() ??:?
#10 0x26ee350a in testing::internal::UnitTestImpl::RunAllTests() ??:?
#11 0x26f6c1db in bool testing::internal::HandleSehExceptionsInMethodIfSupported<testing::internal::UnitTestImpl, bool>(testing::internal::UnitTestImpl*, bool (testing::internal::UnitTestImpl::)(), char const) ??:?
#12 0x26f093e5 in bool testing::internal::HandleExceptionsInMethodIfSupported<testing::internal::UnitTestImpl, bool>(testing::internal::UnitTestImpl*, bool (testing::internal::UnitTestImpl::)(), char const) ??:?
#13 0x26ee20a2 in testing::UnitTest::Run() ??:?
#14 0x204c1741 in RUN_ALL_TESTS() ??:?
#15 0x204bf5ab in Envoy::TestRunner::RunTests(int, char**) ??:?
#16 0x204b8076 in main ??:?
#17 0x7fca80ac7cc9 in __libc_start_main csu/../csu/libc-start.c:308

SUMMARY: AddressSanitizer: heap-use-after-free oauth_integration_test.cc:? in Envoy::Extensions::HttpFilters::Oauth::(anonymous namespace)::OauthIntegrationTest_UnauthenticatedFlow_Test::TestBody()

[lizan]

Yeah I can see that this is highest flaky test in master branch (crash):
https://dev.azure.com/cncf/envoy/_test/analytics?definitionId=11&contextType=build

[antoniovicente]

I think I understand the bug. Attempt to send end stream in the test boddy after the client got a fully reply for that stream and deleted it.