Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

TSAN: data race related to hasLoggedCurrentTestStart #217

Closed
jktjkt opened this issue Mar 28, 2019 · 6 comments
Closed

TSAN: data race related to hasLoggedCurrentTestStart #217

jktjkt opened this issue Mar 28, 2019 · 6 comments

Comments

@jktjkt
Copy link
Contributor

jktjkt commented Mar 28, 2019

I'm on Fedora 29, clang 7.0.1, latest dev of doctest as of yesterday. It seems that there's a race when two threads access hasLoggedCurrentTestStart, for example:

  • via doctest::(anonymous namespace)::ConsoleReporter::logTestStart() in thread A,
  • via doctest::(anonymous namespace)::ConsoleReporter::subcase_end() in thread B.

In the report below, thread T1 is a background worker thread which calls to methods mocked via Trompeloeil. Everything is driven by a single TEST_CASE macro, so I believe, based on the thread safety promise listed in the FAQ, that this is a bug.

I don't have an easy reproducer, unfortunately. I found this when looking for another problem, and it required running our internal test suite in a loop, sometimes only failing after 25+ iterations...

WARNING: ThreadSanitizer: data race (pid=7776)
  Read of size 1 at 0x7b1c00000010 by thread T1 (mutexes: write M47, write M98, write M41, write M164):
    #0 doctest::(anonymous namespace)::ConsoleReporter::logTestStart() /home/ci/target/include/doctest/doctest.h:5016 (test_XXX+0x5822c6)
    #1 doctest::(anonymous namespace)::ConsoleReporter::log_message(doctest::MessageData const&) /home/ci/target/include/doctest/doctest.h:5381 (test_XXX+0x581ce8)
    #2 doctest::detail::MessageBuilder::log() /home/ci/target/include/doctest/doctest.h:4299 (test_XXX+0x5718fe)
    #3 trompeloeil::reporter<trompeloeil::specialized>::send(trompeloeil::severity, char const*, unsigned long, char const*) tests/doctest_integration.cpp:17 (test_XXX+0x576f98)
    #4 void trompeloeil::send_report<trompeloeil::specialized>(trompeloeil::severity, trompeloeil::location, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&) /home/ci/target/include/trompeloeil.hpp:848 (test_XXX+0x54383b)
    #5 void trompeloeil::report_mismatch<void (std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&)>(trompeloeil::call_matcher_list<void (std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&)>&, trompeloeil::call_matcher_list<void (std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&)>&, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, trompeloeil::call_params_type<void (std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&)>::type const&) /home/ci/target/include/trompeloeil.hpp:3005 (test_XXX+0x54548d)
    #6 trompeloeil::return_of<void (std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&)>::type trompeloeil::mock_func<false, void (std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&), std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&>(std::__1::integral_constant<bool, true>, trompeloeil::expectations<false, void (std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&)>&, char const*, char const*, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&) /home/ci/target/include/trompeloeil.hpp:3931 (test_XXX+0x5450f6)
    #7 FakeSerial::write(std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&) tests/mock/io/Serial.h:17 (test_XXX+0x541aec)
    #8 cla::driver::textlines::Generic::writeProperty(std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, std::__1::variant<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, bool, double, long, unsigned long, int, unsigned int, short, unsigned short, signed char, unsigned char, cla::DeletedProperty> const&) src/drivers/textlines/Generic.cpp:123 (test_XXX+0x58dd9e)
    #9 cla::driver::textlines::Generic::writeProperty(std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, std::__1::variant<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, bool, double, long, unsigned long, int, unsigned int, short, unsigned short, signed char, unsigned char, cla::DeletedProperty> const&) src/drivers/textlines/Generic.cpp:257 (test_XXX+0x58dd9e)
    #10 cla::driver::textlines::EdfaManlight::writeProperty(std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, std::__1::variant<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, bool, double, long, unsigned long, int, unsigned int, short, unsigned short, signed char, unsigned char, cla::DeletedProperty> const&) src/drivers/textlines/EdfaManlight.cpp:82 (test_XXX+0x58a717)
    #11 auto cla::driver::Driver::writeMultiProperties(std::__1::map<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, std::__1::variant<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, bool, double, long, unsigned long, int, unsigned int, short, unsigned short, signed char, unsigned char, cla::DeletedProperty>, std::__1::less<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > >, std::__1::allocator<std::__1::pair<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const, std::__1::variant<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, bool, double, long, unsigned long, int, unsigned int, short, unsigned short, signed char, unsigned char, cla::DeletedProperty> > > > const&)::$_0::operator()<std::__1::pair<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const, std::__1::variant<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, bool, double, long, unsigned long, int, unsigned int, short, unsigned short, signed char, unsigned char, cla::DeletedProperty> > >(std::__1::pair<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const, std::__1::variant<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, bool, double, long, unsigned long, int, unsigned int, short, unsigned short, signed char, unsigned char, cla::DeletedProperty> > const&) const /home/ci/src/cesnet-gerrit-czechlight/CzechLight/cla-sysrepo/src/drivers/Driver.cpp:59 (test_XXX+0x5b2fee)
    #12 cla::driver::Driver::writeMultiProperties(std::__1::map<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, std::__1::variant<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, bool, double, long, unsigned long, int, unsigned int, short, unsigned short, signed char, unsigned char, cla::DeletedProperty>, std::__1::less<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > >, std::__1::allocator<std::__1::pair<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const, std::__1::variant<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, bool, double, long, unsigned long, int, unsigned int, short, unsigned short, signed char, unsigned char, cla::DeletedProperty> > > > const&)::$_0 std::__1::for_each<std::__1::__map_const_iterator<std::__1::__tree_const_iterator<std::__1::__value_type<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, std::__1::variant<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, bool, double, long, unsigned long, int, unsigned int, short, unsigned short, signed char, unsigned char, cla::DeletedProperty> >, std::__1::__tree_node<std::__1::__value_type<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, std::__1::variant<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, bool, double, long, unsigned long, int, unsigned int, short, unsigned short, signed char, unsigned char, cla::DeletedProperty> >, void*>*, long> >, cla::driver::Driver::writeMultiProperties(std::__1::map<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, std::__1::variant<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, bool, double, long, unsigned long, int, unsigned int, short, unsigned short, signed char, unsigned char, cla::DeletedProperty>, std::__1::less<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > >, std::__1::allocator<std::__1::pair<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const, std::__1::variant<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, bool, double, long, unsigned long, int, unsigned int, short, unsigned short, signed char, unsigned char, cla::DeletedProperty> > > > const&)::$_0>(std::__1::__map_const_iterator<std::__1::__tree_const_iterator<std::__1::__value_type<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, std::__1::variant<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, bool, double, long, unsigned long, int, unsigned int, short, unsigned short, signed char, unsigned char, cla::DeletedProperty> >, std::__1::__tree_node<std::__1::__value_type<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, std::__1::variant<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, bool, double, long, unsigned long, int, unsigned int, short, unsigned short, signed char, unsigned char, cla::DeletedProperty> >, void*>*, long> >, std::__1::__map_const_iterator<std::__1::__tree_const_iterator<std::__1::__value_type<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, std::__1::variant<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, bool, double, long, unsigned long, int, unsigned int, short, unsigned short, signed char, unsigned char, cla::DeletedProperty> >, std::__1::__tree_node<std::__1::__value_type<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, std::__1::variant<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, bool, double, long, unsigned long, int, unsigned int, short, unsigned short, signed char, unsigned char, cla::DeletedProperty> >, void*>*, long> >, cla::driver::Driver::writeMultiProperties(std::__1::map<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, std::__1::variant<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, bool, double, long, unsigned long, int, unsigned int, short, unsigned short, signed char, unsigned char, cla::DeletedProperty>, std::__1::less<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > >, std::__1::allocator<std::__1::pair<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const, std::__1::variant<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, bool, double, long, unsigned long, int, unsigned int, short, unsigned short, signed char, unsigned char, cla::DeletedProperty> > > > const&)::$_0) /usr/bin/../include/c++/v1/algorithm:967 (test_XXX+0x5b2fee)
    #13 cla::driver::Driver::writeMultiProperties(std::__1::map<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, std::__1::variant<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, bool, double, long, unsigned long, int, unsigned int, short, unsigned short, signed char, unsigned char, cla::DeletedProperty>, std::__1::less<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > >, std::__1::allocator<std::__1::pair<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const, std::__1::variant<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, bool, double, long, unsigned long, int, unsigned int, short, unsigned short, signed char, unsigned char, cla::DeletedProperty> > > > const&) src/drivers/Driver.cpp:58 (test_XXX+0x5b2fee)
    #14 cla::sysrepo::DeviceChanges::processChanges(std::__1::shared_ptr<sysrepo::Session>, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, sr_notif_event_e) src/sysrepo/Daemon.cpp:235 (test_XXX+0x5a7728)
    #15 cla::sysrepo::DeviceChanges::subtree_change(std::__1::shared_ptr<sysrepo::Session>, char const*, sr_notif_event_e, void*) src/sysrepo/Daemon.cpp:136 (test_XXX+0x5a6a1d)
    #16 sysrepo::subtree_change_cb(sr_session_ctx_s*, char const*, sr_notif_event_e, void*) dependencies/sysrepo/swig/cpp/src/Session.cpp:468 (libSysrepo-cpp.so.0.7+0x2050e)
    #17 cl_sm_notif_process dependencies/sysrepo/src/clientlib/cl_subscription_manager.c:718 (libsysrepo.so.0.7+0x281693)
    #18 cl_sm_conn_msg_process dependencies/sysrepo/src/clientlib/cl_subscription_manager.c:1085 (libsysrepo.so.0.7+0x27f52b)
    #19 cl_sm_conn_in_buff_process dependencies/sysrepo/src/clientlib/cl_subscription_manager.c:1137 (libsysrepo.so.0.7+0x27e73a)
    #20 cl_sm_fd_read_data dependencies/sysrepo/src/clientlib/cl_subscription_manager.c:1222 (libsysrepo.so.0.7+0x27a7b5)
    #21 cl_sm_fd_event_process dependencies/sysrepo/src/clientlib/cl_subscription_manager.c:1942 (libsysrepo.so.0.7+0x278245)
    #22 sr_fd_event_process dependencies/sysrepo/src/clientlib/client_library.c:3826 (libsysrepo.so.0.7+0x27166f)
    #23 cla::sysrepo::EventLoop::ioHandler(ev::io&, int) cla-sysrepo/src/sysrepo/EventLoop.cpp:305 (test_XXX+0x5b63b7)
    #24 void ev::base<ev_io, ev::io>::method_thunk<cla::sysrepo::EventLoop, &cla::sysrepo::EventLoop::ioHandler>(ev_loop*, ev_io*, int) /usr/include/ev++.h:479 (test_XXX+0x5b7688)
    #25 ev_invoke_pending ??:? (libev.so.4+0x4f72)

  Previous write of size 1 at 0x7b1c00000010 by main thread:
    #0 doctest::(anonymous namespace)::ConsoleReporter::subcase_end() /home/ci/target/include/doctest/doctest.h:5327 (test_XXX+0x580f9a)
    #1 ~Subcase /home/ci/target/include/doctest/doctest.h:3612 (test_XXX+0x56e7fb)
    #2 _DOCTEST_ANON_FUNC_2() /usr/bin/../include/c++/v1/memory:? (test_XXX+0x4ff80f)
    #3 doctest::Context::run() /home/ci/target/include/doctest/doctest.h:5919 (test_XXX+0x5759e7)
    #4 main /home/ci/target/include/doctest/doctest.h:5997 (test_XXX+0x576e26)

  Location is heap block of size 104 at 0x7b1c00000000 allocated by main thread:
    #0 operator new(unsigned long) ??:? (test_XXX+0x4f6652)
    #1 doctest::IReporter* doctest::detail::reporterCreator<doctest::(anonymous namespace)::ConsoleReporter>(doctest::ContextOptions const&) /home/ci/target/include/doctest/doctest.h:1814 (test_XXX+0x57d19e)
    #2 doctest::Context::run() /home/ci/target/include/doctest/doctest.h:5781 (test_XXX+0x57481d)
    #3 main /home/ci/target/include/doctest/doctest.h:5997 (test_XXX+0x576e26)

  Mutex M47 (0x7fa4c0c429e0) created at:
    #0 pthread_mutex_lock ??:? (test_XXX+0x48bda6)
    #1 sr_fd_watcher_init dependencies/sysrepo/src/clientlib/client_library.c:3781 (libsysrepo.so.0.7+0x270ece)
    #2 EventLoop cla-sysrepo/src/sysrepo/EventLoop.cpp:165 (test_XXX+0x5b48bd)
    #3 cla::sysrepo::EventLoop::instance() cla-sysrepo/src/sysrepo/EventLoop.cpp:217 (test_XXX+0x5b5921)
    #4 _DOCTEST_ANON_FUNC_2()::$_11::operator()() const cla-sysrepo/tests/sysrepo-integration-XXX.cpp:41 (test_XXX+0x50178f)
    #5 _ZNSt3__18__invokeIRZL20_DOCTEST_ANON_FUNC_2vE4$_11JEEEDTclclsr3std3__1E7forwardIT_Efp_Espclsr3std3__1E7forwardIT0_Efp0_EEEOS3_DpOS4_ /usr/bin/../include/c++/v1/type_traits:4345 (test_XXX+0x50178f)
    #6 <null> /usr/bin/../include/c++/v1/__functional_base:349 (test_XXX+0x50178f)
    #7 std::__1::__function::__func<_DOCTEST_ANON_FUNC_2()::$_11, std::__1::allocator<_DOCTEST_ANON_FUNC_2()::$_11>, void ()>::operator()() /usr/bin/../include/c++/v1/functional:1562 (test_XXX+0x50178f)
    #8 cla::utils::UniqueResource::UniqueResource(std::__1::function<void ()>&&, std::__1::function<void ()>&&) /usr/bin/../include/c++/v1/functional:1913 (test_XXX+0x54b7ef)
    #9 UniqueResource cla-sysrepo/src/utils/UniqueResource.h:31 (test_XXX+0x54b7ef)
    #10 cla::utils::make_unique_resource(std::__1::function<void ()>&&, std::__1::function<void ()>&&) cla-sysrepo/src/utils/UniqueResource.h:38 (test_XXX+0x4fb20c)
    #11 _DOCTEST_ANON_FUNC_2() cla-sysrepo/tests/sysrepo-integration-XXX.cpp:41 (test_XXX+0x4fb20c)
    #12 doctest::Context::run() /home/ci/target/include/doctest/doctest.h:5919 (test_XXX+0x5759e7)
    #13 main /home/ci/target/include/doctest/doctest.h:5997 (test_XXX+0x576e26)

  Mutex M98 (0x7b4400002348) created at:
    #0 pthread_mutex_init ??:? (test_XXX+0x462fee)
    #1 cl_sm_init dependencies/sysrepo/src/clientlib/cl_subscription_manager.c:1726 (libsysrepo.so.0.7+0x2725bc)
    #2 cl_subscription_init dependencies/sysrepo/src/clientlib/client_library.c:285 (libsysrepo.so.0.7+0x259bda)
    #3 sr_subtree_change_subscribe dependencies/sysrepo/src/clientlib/client_library.c:2593 (libsysrepo.so.0.7+0x25e9c9)
    #4 sysrepo::Subscribe::subtree_change_subscribe(char const*, std::__1::shared_ptr<sysrepo::Callback>, void*, unsigned int, unsigned int) dependencies/sysrepo/swig/cpp/src/Session.cpp:529 (libSysrepo-cpp.so.0.7+0x2011d)
    #5 cla::sysrepo::Daemon::registerSubtreeModifications(std::__1::shared_ptr<cla::driver::Driver>, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&) cla-sysrepo/src/sysrepo/Daemon.cpp:83 (test_XXX+0x5a5ca7)
    #6 _DOCTEST_ANON_FUNC_2() cla-sysrepo/tests/sysrepo-integration-XXX.cpp:46 (test_XXX+0x4fb3c4)
    #7 doctest::Context::run() /home/ci/target/include/doctest/doctest.h:5919 (test_XXX+0x5759e7)
    #8 main /home/ci/target/include/doctest/doctest.h:5997 (test_XXX+0x576e26)

  Mutex M41 (0x0000010d1300) created at:
    #0 pthread_mutex_init ??:? (test_XXX+0x462fee)
    #1 std::__1::recursive_mutex::recursive_mutex() ??:? (libc++.so.1+0x86a33)
    #2 _DOCTEST_ANON_FUNC_2() /home/ci/target/include/trompeloeil.hpp:3817 (test_XXX+0x4f8b3a)
    #3 _DOCTEST_ANON_FUNC_2() cla-sysrepo/tests/sysrepo-integration-XXX.cpp:25 (test_XXX+0x4f8b3a)
    #4 doctest::Context::run() /home/ci/target/include/doctest/doctest.h:5919 (test_XXX+0x5759e7)
    #5 main /home/ci/target/include/doctest/doctest.h:5997 (test_XXX+0x576e26)

  Mutex M164 (0x7b1c00000030) created at:
    #0 pthread_mutex_lock ??:? (test_XXX+0x48bda6)
    #1 std::__1::mutex::lock() ??:? (libc++.so.1+0x869b5)
    #2 doctest::detail::ResultBuilder::log() /home/ci/target/include/doctest/doctest.h:4251 (test_XXX+0x570f9e)
    #3 doctest::detail::decomp_assert(doctest::assertType::Enum, char const*, int, char const*, doctest::detail::Result) /home/ci/target/include/doctest/doctest.h:4284 (test_XXX+0x5714c1)
    #4 waitForCompletionAndBitMore(trompeloeil::sequence const&) cla-sysrepo/tests/wait-a-bit-longer.cpp:35 (test_XXX+0x5897a2)
    #5 _DOCTEST_ANON_FUNC_2() cla-sysrepo/tests/sysrepo-integration-XXX.cpp:69 (test_XXX+0x4fd03e)
    #6 doctest::Context::run() /home/ci/target/include/doctest/doctest.h:5919 (test_XXX+0x5759e7)
    #7 main /home/ci/target/include/doctest/doctest.h:5997 (test_XXX+0x576e26)

  Thread T1 (tid=7780, running) created by main thread at:
    #0 pthread_create ??:? (test_XXX+0x462dea)
    #1 std::__1::__libcpp_thread_create(unsigned long*, void* (*)(void*), void*) /usr/bin/../include/c++/v1/__threading_support:328 (test_XXX+0x5b5a28)
    #2 std::__1::thread::thread<cla::sysrepo::EventLoop::run()::$_0, , void>(cla::sysrepo::EventLoop::run()::$_0&&) /usr/bin/../include/c++/v1/thread:368 (test_XXX+0x5b5a28)
    #3 cla::sysrepo::EventLoop::run() cla-sysrepo/src/sysrepo/EventLoop.cpp:229 (test_XXX+0x5b5a28)
    #4 _DOCTEST_ANON_FUNC_2()::$_11::operator()() const cla-sysrepo/tests/sysrepo-integration-XXX.cpp:41 (test_XXX+0x501797)
    #5 _ZNSt3__18__invokeIRZL20_DOCTEST_ANON_FUNC_2vE4$_11JEEEDTclclsr3std3__1E7forwardIT_Efp_Espclsr3std3__1E7forwardIT0_Efp0_EEEOS3_DpOS4_ /usr/bin/../include/c++/v1/type_traits:4345 (test_XXX+0x501797)
    #6 <null> /usr/bin/../include/c++/v1/__functional_base:349 (test_XXX+0x501797)
    #7 std::__1::__function::__func<_DOCTEST_ANON_FUNC_2()::$_11, std::__1::allocator<_DOCTEST_ANON_FUNC_2()::$_11>, void ()>::operator()() /usr/bin/../include/c++/v1/functional:1562 (test_XXX+0x501797)
    #8 cla::utils::UniqueResource::UniqueResource(std::__1::function<void ()>&&, std::__1::function<void ()>&&) /usr/bin/../include/c++/v1/functional:1913 (test_XXX+0x54b7ef)
    #9 UniqueResource cla-sysrepo/src/utils/UniqueResource.h:31 (test_XXX+0x54b7ef)
    #10 cla::utils::make_unique_resource(std::__1::function<void ()>&&, std::__1::function<void ()>&&) cla-sysrepo/src/utils/UniqueResource.h:38 (test_XXX+0x4fb20c)
    #11 _DOCTEST_ANON_FUNC_2() cla-sysrepo/tests/sysrepo-integration-XXX.cpp:41 (test_XXX+0x4fb20c)
    #12 doctest::Context::run() /home/ci/target/include/doctest/doctest.h:5919 (test_XXX+0x5759e7)
    #13 main /home/ci/target/include/doctest/doctest.h:5997 (test_XXX+0x576e26)

SUMMARY: ThreadSanitizer: data race /home/ci/target/include/doctest/doctest.h:5016 in doctest::(anonymous namespace)::ConsoleReporter::logTestStart()
==================
@onqtam
Copy link
Member

onqtam commented Mar 28, 2019

hopefully the subcases in the test case are all traversed from a single thread...? So if you spawn multiple threads - they all have to join before another subcase is entered or the current one is exited. This sounds serious and I'll look into it when I have the chance.

@jktjkt
Copy link
Contributor Author

jktjkt commented Mar 28, 2019

hopefully the subcases in the test case are all traversed from a single thread...?

Yes, that's the main thread. The other thread(s) end up eventually calling mocks from Trompeloeil, and the glue code (which integrates trompeloeil with doctest) calls "stuff in doctest", in this case, doctest::detail::MessageBuilder::log().

So if you spawn multiple threads - they all have to join before another subcase is entered or the current one is exited. This sounds serious and I'll look into it when I have the chance.

I do not fully understand this. I hope you do not mean that I have to join all threads which might end up "calling into" doctest, such as shown here? I'm using quite some nesting of subsections...

@onqtam
Copy link
Member

onqtam commented Mar 28, 2019

Some examples: this is safe:

TEST_CASE("OK") {
    SUBCASE("") {
                CHECK(1 == 2);
    }

    std::thread t1([](){
        CHECK(1 == 2);
    });
    std::thread t2([](){
        CHECK(1 == 2);
    });
    
    CHECK(1 == 2);

    t1.join();
    t2.join();

    SUBCASE("") {
        CHECK(1 == 2);
    }
}

This is not:

TEST_CASE("bad 1") {
    std::thread t1([]() {
        SUBCASE("t_sub") {}
    });

    SUBCASE("sub") {}
    t1.join();
}

TEST_CASE("bad 2") {
    std::thread t1([]() {
        CHECK(1 == 2);
    });

    SUBCASE("sub") {}
    t1.join();
}

basically all threads that have been started within a subcase should end before it is exited, and no other subcases should be entered (this is more correct than my previous comment). I'm not even sure I'm explaining it properly - long day... I might look into relaxing these requirements.

Btw I've seen many times people using subcases not to share setup/teardown code but to structure tests hierarchically and nest them - with doctest that can be done with test suites + test cases.

@jktjkt
Copy link
Contributor Author

jktjkt commented Mar 29, 2019

We definitely use real-world code like this:

TEST_CASE("device operations") {
  // this creates the "io" variable which is a Trompeloeil mock
  // it also uses a trompeloeil::sequence which calls REQUIRE(...) from its destructor
  INIT_MOCKED_IO;

  // this starts a background thread which uses "io" and therefore calls
  // into Trompeloeil mock which in turn calls REQUIRE(a == b) from that background thread
  ServiceWorker w(io);

  DeviceUnderTest thing;

  SUBCASE("device reset") {
    REQUIRE_CALL(io, write("reset"));
    thing.reset();
  }

  SUBCASE("poweroff") {
    REQUIRE_CALL(io, write("poweroff"));
    thing.poweroff();
  }

  REQUIRE(io.ok());

  // ~ServiceWorker() gets called, which eventually joins its background thread

  // And here, behind the scenes, trompeloeil::sequence::~sequence()
  // performs additional checks and calls REQUIRE(...)
}

To me, this looks like your "bad 2" test case even though I would classify it as "just sharing common startup and teardown". Do you think that this is not a reasonable setup?

@onqtam
Copy link
Member

onqtam commented Mar 30, 2019

You are indeed correct that this is a bug according to what I've written in the FAQ about thread-safety - thanks for reporting this. I really could just put a lock around hasLoggedCurrentTestStart or do some atomic compare exchange and that will fix the problem. I think I'll have to handle subcasesStack as well though since it is pushed/popped from when entering/leaving subcases and is used when asserts fail.

I have only 1 concern and it can be illustrated with bad 2: suppose that while the thread is running we enter the subcase and only then does the assert fail - it then proceeds to report the current subcase stack (the stack of currently entered subcases) - that context will be a bit misleading at that point since the thread with the assert was started at a point when no subcases were entered at all but now reports a different subcase stack. This however seems like not important at all - a corner case of no significance. What do you think?

EDIT: anyway I just pushed a fix so let me know if the issue persists. I guess that concern I have is ... dumb. There are already no guarantees about the order of assert execution in a multi-threaded context anyway...

@jktjkt
Copy link
Contributor Author

jktjkt commented Apr 1, 2019

that context will be a bit misleading at that point since the thread with the assert was started at a point when no subcases were entered at all but now reports a different subcase stack. This however seems like not important at all - a corner case of no significance. What do you think?

That's not a bug. For me, that's actually the expected behavior. The background thread is typically "somehow related" to the main thread which descends into subcases. In my case, it is a background worker which handles requests submitted by the subcases. If the error report only included info about when the background thread was started, that would actually mask valuable information.

Thanks for fixing this. I'll give this a bunch of serial runs and report back if I see any more failures. I'll close this one as it indeed appears to be fixed.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants