asynPortDriver: data race on mutex in destructor

[mark0n]

Every once in a while thread sanitizer reports a data race when running the unit tests for one of our drivers:

WARNING: ThreadSanitizer: data race (pid=7727)
  Write of size 1 at 0x7b0c0018f060 by main thread (mutexes: write M14):
    #0 pthread_mutex_destroy <null> (libtsan.so.0+0x2cd89)
    #1 epicsMutexOsdDestroy <null> (libCom.so.3.15.5+0x43108)
    #2 drvFGPDB::~drvFGPDB() /home/marko/work/RF/LLRF/support/drvfgpdb/drvFGPDBApp/src/drvFGPDB.cpp:147 (libdrvfgpdb.so.1.3+0x28715)
    #3 std::default_delete<drvFGPDB>::operator()(drvFGPDB*) const /usr/include/c++/8/bits/unique_ptr.h:81 (drvFGPDBTests+0x6c878)
    #4 std::unique_ptr<drvFGPDB, std::default_delete<drvFGPDB> >::~unique_ptr() /usr/include/c++/8/bits/unique_ptr.h:274 (drvFGPDBTests+0x6c878)
    #5 AnFGPDBDriver::~AnFGPDBDriver() /home/marko/work/RF/LLRF/support/drvfgpdb/drvFGPDBApp/test/drvFGPDBTestCommon.h:75 (drvFGPDBTests+0x6c878)
    #6 AnFGPDBDriverUsingIOSyncMock::~AnFGPDBDriverUsingIOSyncMock() /home/marko/work/RF/LLRF/support/drvfgpdb/drvFGPDBApp/test/drvFGPDBTests.cpp:69 (drvFGPDBTests+0x6d54e)
    #7 AnFGPDBDriverUsingIOSyncMock_newDriverInstanceContainsDriverParams_Test::~AnFGPDBDriverUsingIOSyncMock_newDriverInstanceContainsDriverParams_Test() /home/marko/work/RF/LLRF/support/drvfgpdb/drvFGPDBApp/test/drvFGPDBTests.cpp:108 (drvFGPDBTests+0x6d54e)
    #8 AnFGPDBDriverUsingIOSyncMock_newDriverInstanceContainsDriverParams_Test::~AnFGPDBDriverUsingIOSyncMock_newDriverInstanceContainsDriverParams_Test() /home/marko/work/RF/LLRF/support/drvfgpdb/drvFGPDBApp/test/drvFGPDBTests.cpp:108 (drvFGPDBTests+0x6d54e)
    #9 testing::Test::DeleteSelf_() /usr/lib/epics/include/gtest/gtest.h:453 (drvFGPDBTests+0xcfaec)
    #10 void testing::internal::HandleSehExceptionsInMethodIfSupported<testing::Test, void>(testing::Test*, void (testing::Test::*)(), char const*) /usr/src/googletest/googletest/src/gtest.cc:2402 (drvFGPDBTests+0xda048)
    #11 void testing::internal::HandleExceptionsInMethodIfSupported<testing::Test, void>(testing::Test*, void (testing::Test::*)(), char const*) /usr/src/googletest/googletest/src/gtest.cc:2438 (drvFGPDBTests+0xda048)
    #12 testing::TestInfo::Run() /usr/src/googletest/googletest/src/gtest.cc:2662 (drvFGPDBTests+0xcb9fb)
    #13 testing::TestCase::Run() /usr/src/googletest/googletest/src/gtest.cc:2776 (drvFGPDBTests+0xcbf47)
    #14 testing::internal::UnitTestImpl::RunAllTests() /usr/src/googletest/googletest/src/gtest.cc:4651 (drvFGPDBTests+0xcc875)
    #15 bool testing::internal::HandleSehExceptionsInMethodIfSupported<testing::internal::UnitTestImpl, bool>(testing::internal::UnitTestImpl*, bool (testing::internal::UnitTestImpl::*)(), char const*) /usr/src/googletest/googletest/src/gtest.cc:2402 (drvFGPDBTests+0xccfd9)
    #16 bool testing::internal::HandleExceptionsInMethodIfSupported<testing::internal::UnitTestImpl, bool>(testing::internal::UnitTestImpl*, bool (testing::internal::UnitTestImpl::*)(), char const*) /usr/src/googletest/googletest/src/gtest.cc:2438 (drvFGPDBTests+0xccfd9)
    #17 testing::UnitTest::Run() /usr/src/googletest/googletest/src/gtest.cc:4259 (drvFGPDBTests+0xccfd9)
    #18 RUN_ALL_TESTS() /usr/lib/epics/include/gtest/gtest.h:2233 (drvFGPDBTests+0x5a812)
    #19 main /usr/src/googletest/googlemock/src/gmock_main.cc:53 (drvFGPDBTests+0x5a812)

  Previous atomic read of size 1 at 0x7b0c0018f060 by thread T589 (mutexes: write M41512113047926320, write M40949163094503520):
    #0 pthread_mutex_unlock <null> (libtsan.so.0+0x402d9)
    #1 epicsMutexOsdUnlock <null> (libCom.so.3.15.5+0x43188)

  Location is heap block of size 48 at 0x7b0c0018f060 allocated by main thread:
    #0 calloc <null> (libtsan.so.0+0x2b653)
    #1 epicsMutexOsdCreate <null> (libCom.so.3.15.5+0x43074)
    #2 std::_MakeUniq<drvFGPDB>::__single_object std::make_unique<drvFGPDB, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >&, std::shared_ptr<asynOctetSyncIOInterface>&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, unsigned int const&, ResendMode, std::shared_ptr<logger>&>(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >&, std::shared_ptr<asynOctetSyncIOInterface>&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, unsigned int const&, ResendMode&&, std::shared_ptr<logger>&) /usr/include/c++/8/bits/unique_ptr.h:831 (drvFGPDBTests+0x82833)
    #3 AnFGPDBDriverUsingIOSyncMock::AnFGPDBDriverUsingIOSyncMock() /home/marko/work/RF/LLRF/support/drvfgpdb/drvFGPDBApp/test/drvFGPDBTests.cpp:79 (drvFGPDBTests+0x82833)
    #4 AnFGPDBDriverUsingIOSyncMock_newDriverInstanceContainsDriverParams_Test::AnFGPDBDriverUsingIOSyncMock_newDriverInstanceContainsDriverParams_Test() /home/marko/work/RF/LLRF/support/drvfgpdb/drvFGPDBApp/test/drvFGPDBTests.cpp:108 (drvFGPDBTests+0x83744)
    #5 testing::internal::TestFactoryImpl<AnFGPDBDriverUsingIOSyncMock_newDriverInstanceContainsDriverParams_Test>::CreateTest() /usr/lib/epics/include/gtest/internal/gtest-internal.h:484 (drvFGPDBTests+0x83744)
    #6 testing::Test* testing::internal::HandleSehExceptionsInMethodIfSupported<testing::internal::TestFactoryBase, testing::Test*>(testing::internal::TestFactoryBase*, testing::Test* (testing::internal::TestFactoryBase::*)(), char const*) /usr/src/googletest/googletest/src/gtest.cc:2402 (drvFGPDBTests+0xda288)
    #7 testing::Test* testing::internal::HandleExceptionsInMethodIfSupported<testing::internal::TestFactoryBase, testing::Test*>(testing::internal::TestFactoryBase*, testing::Test* (testing::internal::TestFactoryBase::*)(), char const*) /usr/src/googletest/googletest/src/gtest.cc:2438 (drvFGPDBTests+0xda288)
    #8 testing::TestInfo::Run() /usr/src/googletest/googletest/src/gtest.cc:2647 (drvFGPDBTests+0xcb8f9)
    #9 testing::TestCase::Run() /usr/src/googletest/googletest/src/gtest.cc:2776 (drvFGPDBTests+0xcbf47)
    #10 testing::internal::UnitTestImpl::RunAllTests() /usr/src/googletest/googletest/src/gtest.cc:4651 (drvFGPDBTests+0xcc875)
    #11 bool testing::internal::HandleSehExceptionsInMethodIfSupported<testing::internal::UnitTestImpl, bool>(testing::internal::UnitTestImpl*, bool (testing::internal::UnitTestImpl::*)(), char const*) /usr/src/googletest/googletest/src/gtest.cc:2402 (drvFGPDBTests+0xccfd9)
    #12 bool testing::internal::HandleExceptionsInMethodIfSupported<testing::internal::UnitTestImpl, bool>(testing::internal::UnitTestImpl*, bool (testing::internal::UnitTestImpl::*)(), char const*) /usr/src/googletest/googletest/src/gtest.cc:2438 (drvFGPDBTests+0xccfd9)
    #13 testing::UnitTest::Run() /usr/src/googletest/googletest/src/gtest.cc:4259 (drvFGPDBTests+0xccfd9)
    #14 RUN_ALL_TESTS() /usr/lib/epics/include/gtest/gtest.h:2233 (drvFGPDBTests+0x5a812)
    #15 main /usr/src/googletest/googlemock/src/gmock_main.cc:53 (drvFGPDBTests+0x5a812)

  Mutex M14 (0x7b0c00000000) created at:
    #0 pthread_mutex_init <null> (libtsan.so.0+0x2cc3d)
    #1 epicsMutexOsdCreate <null> (libCom.so.3.15.5+0x430a8)

  Mutex M41512113047926320 is already destroyed.

  Mutex M40949163094503520 is already destroyed.

  Thread T589 'testDriver301' (tid=9790, running) created by main thread at:
    #0 pthread_create <null> (libtsan.so.0+0x2c37e)
    #1 epicsThreadCreate <null> (libCom.so.3.15.5+0x415c0)
    #2 std::_MakeUniq<drvFGPDB>::__single_object std::make_unique<drvFGPDB, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >&, std::shared_ptr<asynOctetSyncIOInterface>&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, unsigned int const&, ResendMode, std::shared_ptr<logger>&>(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >&, std::shared_ptr<asynOctetSyncIOInterface>&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, unsigned int const&, ResendMode&&, std::shared_ptr<logger>&) /usr/include/c++/8/bits/unique_ptr.h:831 (drvFGPDBTests+0x82833)
    #3 AnFGPDBDriverUsingIOSyncMock::AnFGPDBDriverUsingIOSyncMock() /home/marko/work/RF/LLRF/support/drvfgpdb/drvFGPDBApp/test/drvFGPDBTests.cpp:79 (drvFGPDBTests+0x82833)
    #4 AnFGPDBDriverUsingIOSyncMock_newDriverInstanceContainsDriverParams_Test::AnFGPDBDriverUsingIOSyncMock_newDriverInstanceContainsDriverParams_Test() /home/marko/work/RF/LLRF/support/drvfgpdb/drvFGPDBApp/test/drvFGPDBTests.cpp:108 (drvFGPDBTests+0x83744)
    #5 testing::internal::TestFactoryImpl<AnFGPDBDriverUsingIOSyncMock_newDriverInstanceContainsDriverParams_Test>::CreateTest() /usr/lib/epics/include/gtest/internal/gtest-internal.h:484 (drvFGPDBTests+0x83744)
    #6 testing::Test* testing::internal::HandleSehExceptionsInMethodIfSupported<testing::internal::TestFactoryBase, testing::Test*>(testing::internal::TestFactoryBase*, testing::Test* (testing::internal::TestFactoryBase::*)(), char const*) /usr/src/googletest/googletest/src/gtest.cc:2402 (drvFGPDBTests+0xda288)
    #7 testing::Test* testing::internal::HandleExceptionsInMethodIfSupported<testing::internal::TestFactoryBase, testing::Test*>(testing::internal::TestFactoryBase*, testing::Test* (testing::internal::TestFactoryBase::*)(), char const*) /usr/src/googletest/googletest/src/gtest.cc:2438 (drvFGPDBTests+0xda288)
    #8 testing::TestInfo::Run() /usr/src/googletest/googletest/src/gtest.cc:2647 (drvFGPDBTests+0xcb8f9)
    #9 testing::TestCase::Run() /usr/src/googletest/googletest/src/gtest.cc:2776 (drvFGPDBTests+0xcbf47)
    #10 testing::internal::UnitTestImpl::RunAllTests() /usr/src/googletest/googletest/src/gtest.cc:4651 (drvFGPDBTests+0xcc875)
    #11 bool testing::internal::HandleSehExceptionsInMethodIfSupported<testing::internal::UnitTestImpl, bool>(testing::internal::UnitTestImpl*, bool (testing::internal::UnitTestImpl::*)(), char const*) /usr/src/googletest/googletest/src/gtest.cc:2402 (drvFGPDBTests+0xccfd9)
    #12 bool testing::internal::HandleExceptionsInMethodIfSupported<testing::internal::UnitTestImpl, bool>(testing::internal::UnitTestImpl*, bool (testing::internal::UnitTestImpl::*)(), char const*) /usr/src/googletest/googletest/src/gtest.cc:2438 (drvFGPDBTests+0xccfd9)
    #13 testing::UnitTest::Run() /usr/src/googletest/googletest/src/gtest.cc:4259 (drvFGPDBTests+0xccfd9)
    #14 RUN_ALL_TESTS() /usr/lib/epics/include/gtest/gtest.h:2233 (drvFGPDBTests+0x5a812)
    #15 main /usr/src/googletest/googlemock/src/gmock_main.cc:53 (drvFGPDBTests+0x5a812)

SUMMARY: ThreadSanitizer: data race (/usr/lib/x86_64-linux-gnu/libtsan.so.0+0x2cd89) in pthread_mutex_destroy
==================

~asynPortDriver() destroys the mutex but I don't see how we can be sure that the mutex is unlocked at this time. I'm wondering if the "asynPortDriverCallback" thread could still be holding the lock.

[MarkRivers]

Would it work to take the lock in the destructor, wait to get it, release it, and then exit?

[mark0n]

Nope, that wouldn't work - for two reasons:

1. Another thread might take the lock right after the destructor released it. This might make the data race less likely but it would still be there (I would even say it would hide the problem).
2. Something is apparently still calling member functions of the asynPortDriver object we are destroying. This most likely could also result in use after-free problems.

I noticed that asynPortDriver() is spawning the "asynPortDriverCallback" thread that (at least in case of our unit tests) might not have enough time to complete until the destructor is being called. I'm working on a fix.

[MarkRivers]

Fixed via #84