simtime alarm race condition #12585
Description
This got exposed and/or became easier to repro via #12527. Basically the alarm is getting deleted in parallel to it being scheduled. We need to rethink the locking here to make sure the time system mutex is held across all operations and objects are kept alive if already scheduled and the callback should just not be called, etc.
WARNING: ThreadSanitizer: data race (pid=12)
Write of size 8 at 0x7b0c000ce858 by thread T18:
#0 std::__1::unique_ptr<Envoy::Event::SchedulableCallback, std::__1::default_delete<Envoy::Event::SchedulableCallback> >::reset(Envoy::Event::SchedulableCallback*) /opt/llvm/bin/../include/c++/v1/memory:2616:20 (proxy_filter_integration_test+0x3745045)
#1 std::__1::unique_ptr<Envoy::Event::SchedulableCallback, std::__1::default_delete<Envoy::Event::SchedulableCallback> >::~unique_ptr() /opt/llvm/bin/../include/c++/v1/memory:2572:19 (proxy_filter_integration_test+0x3744fbc)
#2 Envoy::Event::SimulatedTimeSystemHelper::Alarm::~Alarm() /proc/self/cwd/test/test_common/simulated_time_system.cc:146:1 (proxy_filter_integration_test+0x4ee05f2)
#3 Envoy::Event::SimulatedTimeSystemHelper::Alarm::~Alarm() /proc/self/cwd/test/test_common/simulated_time_system.cc:142:51 (proxy_filter_integration_test+0x4ee064f)
#4 std::__1::default_delete<Envoy::Event::Timer>::operator()(Envoy::Event::Timer*) const /opt/llvm/bin/../include/c++/v1/memory:2363:5 (proxy_filter_integration_test+0x2dfc5c6)
#5 std::__1::unique_ptr<Envoy::Event::Timer, std::__1::default_delete<Envoy::Event::Timer> >::reset(Envoy::Event::Timer*) /opt/llvm/bin/../include/c++/v1/memory:2618:7 (proxy_filter_integration_test+0x2dfc4e0)
#6 Envoy::ConnectionPool::ConnPoolImplBase::onConnectionEvent(Envoy::ConnectionPool::ActiveClient&, std::__1::basic_string_view<char, std::__1::char_traits<char> >, Envoy::Network::ConnectionEvent) /proc/self/cwd/source/common/conn_pool/conn_pool_base.cc:356:27 (proxy_filter_integration_test+0x3c73235)
#7 Envoy::Http::ActiveClient::onEvent(Envoy::Network::ConnectionEvent) /proc/self/cwd/bazel-out/k8-dbg/bin/source/common/http/_virtual_includes/conn_pool_base_lib/common/http/conn_pool_base.h:93:13 (proxy_filter_integration_test+0x3c441c2)
#8 Envoy::Network::ConnectionImplBase::raiseConnectionEvent(Envoy::Network::ConnectionEvent) /proc/self/cwd/source/common/network/connection_impl_base.cc:38:15 (proxy_filter_integration_test+0x596c485)
#9 Envoy::Network::ConnectionImpl::raiseEvent(Envoy::Network::ConnectionEvent) /proc/self/cwd/source/common/network/connection_impl.cc:369:23 (proxy_filter_integration_test+0x5947a4b)
#10 non-virtual thunk to Envoy::Network::ConnectionImpl::raiseEvent(Envoy::Network::ConnectionEvent) /proc/self/cwd/source/common/network/connection_impl.cc (proxy_filter_integration_test+0x594946b)
#11 Envoy::Extensions::TransportSockets::Tls::SslSocket::doHandshake() /proc/self/cwd/source/extensions/transport_sockets/tls/ssl_socket.cc:178:17 (proxy_filter_integration_test+0x31f8453)
#12 Envoy::Extensions::TransportSockets::Tls::SslSocket::doWrite(Envoy::Buffer::Instance&, bool) /proc/self/cwd/source/extensions/transport_sockets/tls/ssl_socket.cc:234:27 (proxy_filter_integration_test+0x31f995b)
#13 Envoy::Network::ConnectionImpl::onWriteReady() /proc/self/cwd/source/common/network/connection_impl.cc:631:40 (proxy_filter_integration_test+0x594c4c2)
#14 Envoy::Network::ConnectionImpl::onFileEvent(unsigned int) /proc/self/cwd/source/common/network/connection_impl.cc:533:5 (proxy_filter_integration_test+0x594bb4a)
#15 Envoy::Network::ConnectionImpl::ConnectionImpl(Envoy::Event::Dispatcher&, std::__1::unique_ptr<Envoy::Network::ConnectionSocket, std::__1::default_delete<Envoy::Network::ConnectionSocket> >&&, std::__1::unique_ptr<Envoy::Network::TransportSocket, std::__1::default_delete<Envoy::Network::TransportSocket> >&&, Envoy::StreamInfo::StreamInfo&, bool)::$_6::operator()(unsigned int) const /proc/self/cwd/source/common/network/connection_impl.cc:77:74 (proxy_filter_integration_test+0x5961c97)
#16 decltype(std::__1::forward<Envoy::Network::ConnectionImpl::ConnectionImpl(Envoy::Event::Dispatcher&, std::__1::unique_ptr<Envoy::Network::ConnectionSocket, std::__1::default_delete<Envoy::Network::ConnectionSocket> >&&, std::__1::unique_ptr<Envoy::Network::TransportSocket, std::__1::default_delete<Envoy::Network::TransportSocket> >&&, Envoy::StreamInfo::StreamInfo&, bool)::$_6&>(fp)(std::__1::forward<unsigned int>(fp0))) std::__1::__invoke<Envoy::Network::ConnectionImpl::ConnectionImpl(Envoy::Event::Dispatcher&, std::__1::unique_ptr<Envoy::Network::ConnectionSocket, std::__1::default_delete<Envoy::Network::ConnectionSocket> >&&, std::__1::unique_ptr<Envoy::Network::TransportSocket, std::__1::default_delete<Envoy::Network::TransportSocket> >&&, Envoy::StreamInfo::StreamInfo&, bool)::$_6&, unsigned int>(Envoy::Network::ConnectionImpl::ConnectionImpl(Envoy::Event::Dispatcher&, std::__1::unique_ptr<Envoy::Network::ConnectionSocket, std::__1::default_delete<Envoy::Network::ConnectionSocket> >&&, std::__1::unique_ptr<Envoy::Network::TransportSocket, std::__1::default_delete<Envoy::Network::TransportSocket> >&&, Envoy::StreamInfo::StreamInfo&, bool)::$_6&, unsigned int&&) /opt/llvm/bin/../include/c++/v1/type_traits:3539:1 (proxy_filter_integration_test+0x5961bdc)
#17 void std::__1::__invoke_void_return_wrapper<void>::__call<Envoy::Network::ConnectionImpl::ConnectionImpl(Envoy::Event::Dispatcher&, std::__1::unique_ptr<Envoy::Network::ConnectionSocket, std::__1::default_delete<Envoy::Network::ConnectionSocket> >&&, std::__1::unique_ptr<Envoy::Network::TransportSocket, std::__1::default_delete<Envoy::Network::TransportSocket> >&&, Envoy::StreamInfo::StreamInfo&, bool)::$_6&, unsigned int>(Envoy::Network::ConnectionImpl::ConnectionImpl(Envoy::Event::Dispatcher&, std::__1::unique_ptr<Envoy::Network::ConnectionSocket, std::__1::default_delete<Envoy::Network::ConnectionSocket> >&&, std::__1::unique_ptr<Envoy::Network::TransportSocket, std::__1::default_delete<Envoy::Network::TransportSocket> >&&, Envoy::StreamInfo::StreamInfo&, bool)::$_6&, unsigned int&&) /opt/llvm/bin/../include/c++/v1/__functional_base:348:9 (proxy_filter_integration_test+0x5961b0d)
#18 std::__1::__function::__alloc_func<Envoy::Network::ConnectionImpl::ConnectionImpl(Envoy::Event::Dispatcher&, std::__1::unique_ptr<Envoy::Network::ConnectionSocket, std::__1::default_delete<Envoy::Network::ConnectionSocket> >&&, std::__1::unique_ptr<Envoy::Network::TransportSocket, std::__1::default_delete<Envoy::Network::TransportSocket> >&&, Envoy::StreamInfo::StreamInfo&, bool)::$_6, std::__1::allocator<Envoy::Network::ConnectionImpl::ConnectionImpl(Envoy::Event::Dispatcher&, std::__1::unique_ptr<Envoy::Network::ConnectionSocket, std::__1::default_delete<Envoy::Network::ConnectionSocket> >&&, std::__1::unique_ptr<Envoy::Network::TransportSocket, std::__1::default_delete<Envoy::Network::TransportSocket> >&&, Envoy::StreamInfo::StreamInfo&, bool)::$_6>, void (unsigned int)>::operator()(unsigned int&&) /opt/llvm/bin/../include/c++/v1/functional:1540:16 (proxy_filter_integration_test+0x5961a8d)
#19 std::__1::__function::__func<Envoy::Network::ConnectionImpl::ConnectionImpl(Envoy::Event::Dispatcher&, std::__1::unique_ptr<Envoy::Network::ConnectionSocket, std::__1::default_delete<Envoy::Network::ConnectionSocket> >&&, std::__1::unique_ptr<Envoy::Network::TransportSocket, std::__1::default_delete<Envoy::Network::TransportSocket> >&&, Envoy::StreamInfo::StreamInfo&, bool)::$_6, std::__1::allocator<Envoy::Network::ConnectionImpl::ConnectionImpl(Envoy::Event::Dispatcher&, std::__1::unique_ptr<Envoy::Network::ConnectionSocket, std::__1::default_delete<Envoy::Network::ConnectionSocket> >&&, std::__1::unique_ptr<Envoy::Network::TransportSocket, std::__1::default_delete<Envoy::Network::TransportSocket> >&&, Envoy::StreamInfo::StreamInfo&, bool)::$_6>, void (unsigned int)>::operator()(unsigned int&&) /opt/llvm/bin/../include/c++/v1/functional:1714:12 (proxy_filter_integration_test+0x595fd3c)
#20 std::__1::__function::__value_func<void (unsigned int)>::operator()(unsigned int&&) const /opt/llvm/bin/../include/c++/v1/functional:1867:16 (proxy_filter_integration_test+0x444e5a4)
#21 std::__1::function<void (unsigned int)>::operator()(unsigned int) const /opt/llvm/bin/../include/c++/v1/functional:2473:12 (proxy_filter_integration_test+0x444e498)
#22 Envoy::Event::FileEventImpl::mergeInjectedEventsAndRunCb(unsigned int) /proc/self/cwd/source/common/event/file_event_impl.cc:130:3 (proxy_filter_integration_test+0x5932339)
#23 Envoy::Event::FileEventImpl::assignEvents(unsigned int, event_base*)::$_1::operator()(int, short, void*) const /proc/self/cwd/source/common/event/file_event_impl.cc:103:16 (proxy_filter_integration_test+0x593262d)
#24 Envoy::Event::FileEventImpl::assignEvents(unsigned int, event_base*)::$_1::__invoke(int, short, void*) /proc/self/cwd/source/common/event/file_event_impl.cc:87:7 (proxy_filter_integration_test+0x59323b6)
#25 event_persist_closure /home/ubuntu/ephemeral/build_root/sandbox/linux-sandbox/483/execroot/envoy/external/com_github_libevent_libevent/event.c:1645:9 (proxy_filter_integration_test+0x7e495bf)
#26 event_process_active_single_queue /home/ubuntu/ephemeral/build_root/sandbox/linux-sandbox/483/execroot/envoy/external/com_github_libevent_libevent/event.c:1704:4 (proxy_filter_integration_test+0x7e47f0c)
#27 event_process_active /home/ubuntu/ephemeral/build_root/sandbox/linux-sandbox/483/execroot/envoy/external/com_github_libevent_libevent/event.c:1805:9 (proxy_filter_integration_test+0x7e3c9b7)
#28 event_base_loop /home/ubuntu/ephemeral/build_root/sandbox/linux-sandbox/483/execroot/envoy/external/com_github_libevent_libevent/event.c:2047:12 (proxy_filter_integration_test+0x7e3a36f)
#29 Envoy::Event::LibeventScheduler::run(Envoy::Event::Dispatcher::RunType) /proc/self/cwd/source/common/event/libevent_scheduler.cc:68:3 (proxy_filter_integration_test+0x5c311ff)
#30 Envoy::Event::DispatcherImpl::run(Envoy::Event::Dispatcher::RunType) /proc/self/cwd/source/common/event/dispatcher_impl.cc:203:19 (proxy_filter_integration_test+0x591ce61)
#31 Envoy::Server::WorkerImpl::threadRoutine(Envoy::Server::GuardDog&) /proc/self/cwd/source/server/worker_impl.cc:133:16 (proxy_filter_integration_test+0x355d4c3)
#32 Envoy::Server::WorkerImpl::start(Envoy::Server::GuardDog&)::$_4::operator()() const /proc/self/cwd/source/server/worker_impl.cc:99:38 (proxy_filter_integration_test+0x356b847)
#33 decltype(std::__1::forward<Envoy::Server::WorkerImpl::start(Envoy::Server::GuardDog&)::$_4&>(fp)()) std::__1::__invoke<Envoy::Server::WorkerImpl::start(Envoy::Server::GuardDog&)::$_4&>(Envoy::Server::WorkerImpl::start(Envoy::Server::GuardDog&)::$_4&) /opt/llvm/bin/../include/c++/v1/type_traits:3539:1 (proxy_filter_integration_test+0x356b780)
#34 void std::__1::__invoke_void_return_wrapper<void>::__call<Envoy::Server::WorkerImpl::start(Envoy::Server::GuardDog&)::$_4&>(Envoy::Server::WorkerImpl::start(Envoy::Server::GuardDog&)::$_4&) /opt/llvm/bin/../include/c++/v1/__functional_base:348:9 (proxy_filter_integration_test+0x356b6e0)
#35 std::__1::__function::__alloc_func<Envoy::Server::WorkerImpl::start(Envoy::Server::GuardDog&)::$_4, std::__1::allocator<Envoy::Server::WorkerImpl::start(Envoy::Server::GuardDog&)::$_4>, void ()>::operator()() /opt/llvm/bin/../include/c++/v1/functional:1540:16 (proxy_filter_integration_test+0x356b680)
#36 std::__1::__function::__func<Envoy::Server::WorkerImpl::start(Envoy::Server::GuardDog&)::$_4, std::__1::allocator<Envoy::Server::WorkerImpl::start(Envoy::Server::GuardDog&)::$_4>, void ()>::operator()() /opt/llvm/bin/../include/c++/v1/functional:1714:12 (proxy_filter_integration_test+0x356994f)
#37 std::__1::__function::__value_func<void ()>::operator()() const /opt/llvm/bin/../include/c++/v1/functional:1867:16 (proxy_filter_integration_test+0x2f1af96)
#38 std::__1::function<void ()>::operator()() const /opt/llvm/bin/../include/c++/v1/functional:2473:12 (proxy_filter_integration_test+0x2f1ac28)
#39 Envoy::Thread::ThreadImplPosix::ThreadImplPosix(std::__1::function<void ()>, std::__1::optional<Envoy::Thread::Options> const&)::'lambda'(void*)::operator()(void*) const /proc/self/cwd/source/common/common/posix/thread_impl.cc:49:11 (proxy_filter_integration_test+0x7e1ba6b)
#40 Envoy::Thread::ThreadImplPosix::ThreadImplPosix(std::__1::function<void ()>, std::__1::optional<Envoy::Thread::Options> const&)::'lambda'(void*)::__invoke(void*) /proc/self/cwd/source/common/common/posix/thread_impl.cc:48:9 (proxy_filter_integration_test+0x7e1b9f8)
Previous read of size 8 at 0x7b0c000ce858 by main thread:
#0 std::__1::unique_ptr<Envoy::Event::SchedulableCallback, std::__1::default_delete<Envoy::Event::SchedulableCallback> >::operator->() const /opt/llvm/bin/../include/c++/v1/memory:2587:19 (proxy_filter_integration_test+0x374a957)
#1 Envoy::Event::SimulatedTimeSystemHelper::Alarm::activateLockHeld() /proc/self/cwd/test/test_common/simulated_time_system.cc:96:5 (proxy_filter_integration_test+0x4ee3aab)
#2 Envoy::Event::SimulatedTimeSystemHelper::alarmActivateLockHeld(Envoy::Event::SimulatedTimeSystemHelper::Alarm&) /proc/self/cwd/test/test_common/simulated_time_system.cc:300:9 (proxy_filter_integration_test+0x4ee2fcd)
#3 Envoy::Event::SimulatedTimeSystemHelper::scheduleReadyAlarmsLockHeld() /proc/self/cwd/test/test_common/simulated_time_system.cc:383:5 (proxy_filter_integration_test+0x4ee32d8)
#4 Envoy::Event::SimulatedTimeSystemHelper::setMonotonicTimeLockHeld(std::__1::chrono::time_point<std::__1::chrono::steady_clock, std::__1::chrono::duration<long long, std::__1::ratio<1l, 1000000000l> > > const&) /proc/self/cwd/test/test_common/simulated_time_system.cc:360:5 (proxy_filter_integration_test+0x4ee2854)
#5 Envoy::Event::SimulatedTimeSystemHelper::waitForImpl(absl::Mutex&, absl::Condition const&, std::__1::chrono::duration<long long, std::__1::ratio<1l, 1000000000l> > const&, bool) /proc/self/cwd/test/test_common/simulated_time_system.cc:279:9 (proxy_filter_integration_test+0x4ee2d61)
#6 Envoy::Event::DelegatingTestTimeSystemBase<Envoy::Event::TestTimeSystem>::waitForImpl(absl::Mutex&, absl::Condition const&, std::__1::chrono::duration<long long, std::__1::ratio<1l, 1000000000l> > const&, bool) /proc/self/cwd/./test/test_common/test_time_system.h:116:25 (proxy_filter_integration_test+0x2feee9a)
#7 bool Envoy::Event::TestTimeSystem::waitFor<std::__1::chrono::duration<long long, std::__1::ratio<1l, 1000l> > >(absl::Mutex&, absl::Condition const&, std::__1::chrono::duration<long long, std::__1::ratio<1l, 1000l> > const&, bool) /proc/self/cwd/./test/test_common/test_time_system.h:69:12 (proxy_filter_integration_test+0x2f6fb65)
#8 Envoy::(anonymous namespace)::waitForWithDispatcherRun(Envoy::Event::TestTimeSystem&, absl::Mutex&, std::__1::function<bool ()> const&, Envoy::Event::Dispatcher&, std::__1::chrono::duration<long long, std::__1::ratio<1l, 1000l> >) /proc/self/cwd/test/integration/fake_upstream.cc:168:21 (proxy_filter_integration_test+0x2f2f7e3)
#9 Envoy::FakeHttpConnection::waitForNewStream(Envoy::Event::Dispatcher&, std::__1::unique_ptr<Envoy::FakeStream, std::__1::default_delete<Envoy::FakeStream> >&, std::__1::chrono::duration<long long, std::__1::ratio<1l, 1000l> >) /proc/self/cwd/test/integration/fake_upstream.cc:384:8 (proxy_filter_integration_test+0x2f32682)
#10 Envoy::HttpIntegrationTest::waitForNextUpstreamRequest(std::__1::vector<unsigned long, std::__1::allocator<unsigned long> > const&, std::__1::chrono::duration<long long, std::__1::ratio<1l, 1000l> >) /proc/self/cwd/test/integration/http_integration.cc:388:34 (proxy_filter_integration_test+0x2e3f123)
#11 Envoy::HttpIntegrationTest::waitForNextUpstreamRequest(unsigned long, std::__1::chrono::duration<long long, std::__1::ratio<1l, 1000l> >) /proc/self/cwd/test/integration/http_integration.cc:399:3 (proxy_filter_integration_test+0x2e3db29)
#12 Envoy::(anonymous namespace)::ProxyFilterIntegrationTest_UpstreamTls_Test::TestBody() /proc/self/cwd/test/extensions/filters/http/dynamic_forward_proxy/proxy_filter_integration_test.cc:271:3 (proxy_filter_integration_test+0x2c1d7d4)
#13 void testing::internal::HandleSehExceptionsInMethodIfSupported<testing::Test, void>(testing::Test*, void (testing::Test::*)(), char const*) /proc/self/cwd/external/com_google_googletest/googletest/src/gtest.cc:2433:10 (proxy_filter_integration_test+0x7fe21ac)
#14 void testing::internal::HandleExceptionsInMethodIfSupported<testing::Test, void>(testing::Test*, void (testing::Test::*)(), char const*) /proc/self/cwd/external/com_google_googletest/googletest/src/gtest.cc:2469:14 (proxy_filter_integration_test+0x7fc685e)
#15 testing::Test::Run() /proc/self/cwd/external/com_google_googletest/googletest/src/gtest.cc:2508:5 (proxy_filter_integration_test+0x7fabc01)
#16 testing::TestInfo::Run() /proc/self/cwd/external/com_google_googletest/googletest/src/gtest.cc:2684:11 (proxy_filter_integration_test+0x7facaa3)
#17 testing::TestSuite::Run() /proc/self/cwd/external/com_google_googletest/googletest/src/gtest.cc:2816:28 (proxy_filter_integration_test+0x7fad4da)
#18 testing::internal::UnitTestImpl::RunAllTests() /proc/self/cwd/external/com_google_googletest/googletest/src/gtest.cc:5338:44 (proxy_filter_integration_test+0x7fbcc7d)
#19 bool testing::internal::HandleSehExceptionsInMethodIfSupported<testing::internal::UnitTestImpl, bool>(testing::internal::UnitTestImpl*, bool (testing::internal::UnitTestImpl::*)(), char const*) /proc/self/cwd/external/com_google_googletest/googletest/src/gtest.cc:2433:10 (proxy_filter_integration_test+0x7fe972c)
#20 bool testing::internal::HandleExceptionsInMethodIfSupported<testing::internal::UnitTestImpl, bool>(testing::internal::UnitTestImpl*, bool (testing::internal::UnitTestImpl::*)(), char const*) /proc/self/cwd/external/com_google_googletest/googletest/src/gtest.cc:2469:14 (proxy_filter_integration_test+0x7fca56e)
#21 testing::UnitTest::Run() /proc/self/cwd/external/com_google_googletest/googletest/src/gtest.cc:4925:10 (proxy_filter_integration_test+0x7fbc53b)
#22 RUN_ALL_TESTS() /proc/self/cwd/external/com_google_googletest/googletest/include/gtest/gtest.h:2473:46 (proxy_filter_integration_test+0x583e787)
#23 Envoy::TestRunner::RunTests(int, char**) /proc/self/cwd/test/test_runner.cc:154:10 (proxy_filter_integration_test+0x583da3f)
#24 main /proc/self/cwd/test/main.cc:34:10 (proxy_filter_integration_test+0x583bd34)