Major Description
The Clang thread sanitizer shows a race condition in the LogDomain and LogEncoder classes – this happens pretty much every time running the "Logging rollover" unit test.
The problem is that the LogDomain code is using the same C++ ostream objects that the LogEncoders use, without going through the mutexes.
I'm seeing this on the current master branch, but the relevant code hasn't been changed in a while so I assume this goes back to 2.7 at least.
==================
|
WARNING: ThreadSanitizer: data race (pid=75452)
|
Write of size 8 at 0x7b54000007b8 by thread T1 (mutexes: write M630):
|
#0 std::__1::basic_streambuf<char, std::__1::char_traits<char> >::xsputn(char const*, long) streambuf:473 (LiteCoreCppTests:x86_64+0x100044024)
|
#1 std::__1::basic_streambuf<char, std::__1::char_traits<char> >::sputn(char const*, long) streambuf:229 (LiteCoreCppTests:x86_64+0x10089dbea)
|
#2 std::__1::basic_ostream<char, std::__1::char_traits<char> >::write(char const*, long) ostream:921 (LiteCoreCppTests:x86_64+0x10089c121)
|
#3 litecore::operator<<(std::__1::basic_ostream<char, std::__1::char_traits<char> >&, fleece::slice) StringUtil.hh:66 (LiteCoreCppTests:x86_64+0x1016a6841)
|
#4 litecore::LogEncoder::_flush() LogEncoder.cc:279 (LiteCoreCppTests:x86_64+0x1016a1009)
|
#5 litecore::LogEncoder::performScheduledFlush() LogEncoder.cc:300 (LiteCoreCppTests:x86_64+0x10169ffd0)
|
#6 decltype(*(std::__1::forward<litecore::LogEncoder*&>(fp0)).*fp()) std::__1::__invoke<void (litecore::LogEncoder::*&)(), litecore::LogEncoder*&, void>(void (litecore::LogEncoder::*&)(), litecore::LogEncoder*&) type_traits:4366 (LiteCoreCppTests:x86_64+0x1016b1ddd)
|
#7 std::__1::__bind_return<void (litecore::LogEncoder::*)(), std::__1::tuple<litecore::LogEncoder*>, std::__1::tuple<>, __is_valid_bind_return<void (litecore::LogEncoder::*)(), std::__1::tuple<litecore::LogEncoder*>, std::__1::tuple<> >::value>::type std::__1::__apply_functor<void (litecore::LogEncoder::*)(), std::__1::tuple<litecore::LogEncoder*>, 0ul, std::__1::tuple<> >(void (litecore::LogEncoder::*&)(), std::__1::tuple<litecore::LogEncoder*>&, std::__1::__tuple_indices<0ul>, std::__1::tuple<>&&) functional:2716 (LiteCoreCppTests:x86_64+0x1016b1c09)
|
#8 std::__1::__bind_return<void (litecore::LogEncoder::*)(), std::__1::tuple<litecore::LogEncoder*>, std::__1::tuple<>, __is_valid_bind_return<void (litecore::LogEncoder::*)(), std::__1::tuple<litecore::LogEncoder*>, std::__1::tuple<> >::value>::type std::__1::__bind<void (litecore::LogEncoder::*)(), litecore::LogEncoder*>::operator()<>() functional:2749 (LiteCoreCppTests:x86_64+0x1016b1a5c)
|
#9 decltype(std::__1::forward<std::__1::__bind<void (litecore::LogEncoder::*)(), litecore::LogEncoder*>&>(fp)()) std::__1::__invoke<std::__1::__bind<void (litecore::LogEncoder::*)(), litecore::LogEncoder*>&>(std::__1::__bind<void (litecore::LogEncoder::*)(), litecore::LogEncoder*>&) type_traits:4425 (LiteCoreCppTests:x86_64+0x1016b18cd)
|
#10 void std::__1::__invoke_void_return_wrapper<void>::__call<std::__1::__bind<void (litecore::LogEncoder::*)(), litecore::LogEncoder*>&>(std::__1::__bind<void (litecore::LogEncoder::*)(), litecore::LogEncoder*>&) __functional_base:348 (LiteCoreCppTests:x86_64+0x1016b16cd)
|
#11 std::__1::__function::__alloc_func<std::__1::__bind<void (litecore::LogEncoder::*)(), litecore::LogEncoder*>, std::__1::allocator<std::__1::__bind<void (litecore::LogEncoder::*)(), litecore::LogEncoder*> >, void ()>::operator()() functional:1533 (LiteCoreCppTests:x86_64+0x1016b15f3)
|
#12 std::__1::__function::__func<std::__1::__bind<void (litecore::LogEncoder::*)(), litecore::LogEncoder*>, std::__1::allocator<std::__1::__bind<void (litecore::LogEncoder::*)(), litecore::LogEncoder*> >, void ()>::operator()() functional:1707 (LiteCoreCppTests:x86_64+0x1016abd9e)
|
#13 std::__1::__function::__value_func<void ()>::operator()() const functional:1860 (LiteCoreCppTests:x86_64+0x1001d0d76)
|
#14 std::__1::function<void ()>::operator()() const functional:2419 (LiteCoreCppTests:x86_64+0x1001c3ace)
|
#15 litecore::actor::Timer::Manager::run() Timer.cc:58 (LiteCoreCppTests:x86_64+0x1013de41b)
|
#16 litecore::actor::Timer::Manager::Manager()::$_0::operator()() const Timer.cc:34 (LiteCoreCppTests:x86_64+0x1013e4fa9)
|
#17 decltype(std::__1::forward<litecore::actor::Timer::Manager::Manager()::$_0>(fp)()) std::__1::__invoke<litecore::actor::Timer::Manager::Manager()::$_0>(litecore::actor::Timer::Manager::Manager()::$_0&&) type_traits:4425 (LiteCoreCppTests:x86_64+0x1013e4dad)
|
#18 void std::__1::__thread_execute<std::__1::unique_ptr<std::__1::__thread_struct, std::__1::default_delete<std::__1::__thread_struct> >, litecore::actor::Timer::Manager::Manager()::$_0>(std::__1::tuple<std::__1::unique_ptr<std::__1::__thread_struct, std::__1::default_delete<std::__1::__thread_struct> >, litecore::actor::Timer::Manager::Manager()::$_0>&, std::__1::__tuple_indices<>) thread:341 (LiteCoreCppTests:x86_64+0x1013e46e2)
|
#19 void* std::__1::__thread_proxy<std::__1::tuple<std::__1::unique_ptr<std::__1::__thread_struct, std::__1::default_delete<std::__1::__thread_struct> >, litecore::actor::Timer::Manager::Manager()::$_0> >(void*) thread:351 (LiteCoreCppTests:x86_64+0x1013e2358)
|
|
|
Previous read of size 8 at 0x7b54000007b8 by main thread (mutexes: write M588):
|
#0 std::__1::basic_streambuf<char, std::__1::char_traits<char> >::pptr() const streambuf:254 (LiteCoreCppTests:x86_64+0x1000469f1)
|
#1 std::__1::basic_filebuf<char, std::__1::char_traits<char> >::sync() fstream:987 (LiteCoreCppTests:x86_64+0x1000a5673)
|
#2 std::__1::basic_filebuf<char, std::__1::char_traits<char> >::seekoff(long long, std::__1::ios_base::seekdir, unsigned int) fstream:928 (LiteCoreCppTests:x86_64+0x1000a4e1b)
|
#3 std::__1::basic_streambuf<char, std::__1::char_traits<char> >::pubseekoff(long long, std::__1::ios_base::seekdir, unsigned int) streambuf:159 (LiteCoreCppTests:x86_64+0x100e2d557)
|
#4 std::__1::basic_ostream<char, std::__1::char_traits<char> >::tellp() ostream:967 (LiteCoreCppTests:x86_64+0x100e1156f)
|
#5 litecore::LogDomain::dylog(litecore::LogLevel, char const*, unsigned int, char const*, __va_list_tag*) Logging.cc:466 (LiteCoreCppTests:x86_64+0x100e10c7e)
|
#6 litecore::LogDomain::vlog(litecore::LogLevel, unsigned int, bool, char const*, __va_list_tag*) Logging.cc:417 (LiteCoreCppTests:x86_64+0x100e0fb86)
|
#7 litecore::Logging::_logv(litecore::LogLevel, char const*, __va_list_tag*) const Logging.cc:604 (LiteCoreCppTests:x86_64+0x100e13e5b)
|
#8 LogObject::doLog(char const*, ...) const LogEncoderTest.cc:48 (LiteCoreCppTests:x86_64+0x1002cf3ec)
|
#9 ____C_A_T_C_H____T_E_S_T____200() LogEncoderTest.cc:220 (LiteCoreCppTests:x86_64+0x10023043e)
|
#10 Catch::FreeFunctionTestCase::invoke() const catch.hpp:6582 (LiteCoreCppTests:x86_64+0x100037e89)
|
#11 Catch::TestCase::invoke() const catch.hpp:7519 (LiteCoreCppTests:x86_64+0x1000177e3)
|
#12 Catch::RunContext::invokeActiveTestCase() catch.hpp:6158 (LiteCoreCppTests:x86_64+0x100083d3c)
|
#13 Catch::RunContext::runCurrentTest(std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >&, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >&) catch.hpp:6129 (LiteCoreCppTests:x86_64+0x100082e26)
|
#14 Catch::RunContext::runTest(Catch::TestCase const&) catch.hpp:5949 (LiteCoreCppTests:x86_64+0x100007f1a)
|
#15 Catch::runTests(Catch::Ptr<Catch::Config> const&) catch.hpp:6297 (LiteCoreCppTests:x86_64+0x10000606d)
|
#16 Catch::Session::run() catch.hpp:6405 (LiteCoreCppTests:x86_64+0x100100e89)
|
#17 Catch::Session::run(int, char const* const*) catch.hpp:6384 (LiteCoreCppTests:x86_64+0x100032dec)
|
#18 main catch.hpp:10333 (LiteCoreCppTests:x86_64+0x100032bf2)
|
|
|
Location is heap block of size 568 at 0x7b5400000780 allocated by main thread:
|
#0 operator new(unsigned long) <null>:1061712 (libclang_rt.tsan_osx_dynamic.dylib:x86_64h+0x7596b)
|
#1 litecore::setupFileOut() Logging.cc:88 (LiteCoreCppTests:x86_64+0x100e0dc76)
|
#2 litecore::LogDomain::writeEncodedLogsTo(litecore::LogFileOptions const&, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&) Logging.cc:226 (LiteCoreCppTests:x86_64+0x100e0ca0e)
|
#3 ____C_A_T_C_H____T_E_S_T____200() LogEncoderTest.cc:216 (LiteCoreCppTests:x86_64+0x1002303bc)
|
#4 Catch::FreeFunctionTestCase::invoke() const catch.hpp:6582 (LiteCoreCppTests:x86_64+0x100037e89)
|
#5 Catch::TestCase::invoke() const catch.hpp:7519 (LiteCoreCppTests:x86_64+0x1000177e3)
|
#6 Catch::RunContext::invokeActiveTestCase() catch.hpp:6158 (LiteCoreCppTests:x86_64+0x100083d3c)
|
#7 Catch::RunContext::runCurrentTest(std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >&, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >&) catch.hpp:6129 (LiteCoreCppTests:x86_64+0x100082e26)
|
#8 Catch::RunContext::runTest(Catch::TestCase const&) catch.hpp:5949 (LiteCoreCppTests:x86_64+0x100007f1a)
|
#9 Catch::runTests(Catch::Ptr<Catch::Config> const&) catch.hpp:6297 (LiteCoreCppTests:x86_64+0x10000606d)
|
#10 Catch::Session::run() catch.hpp:6405 (LiteCoreCppTests:x86_64+0x100100e89)
|
#11 Catch::Session::run(int, char const* const*) catch.hpp:6384 (LiteCoreCppTests:x86_64+0x100032dec)
|
#12 main catch.hpp:10333 (LiteCoreCppTests:x86_64+0x100032bf2)
|
|
|
Mutex M630 (0x7b5400001400) created at:
|
#0 pthread_mutex_lock <null>:1061568 (libclang_rt.tsan_osx_dynamic.dylib:x86_64h+0x3b09e)
|
#1 std::__1::mutex::lock() <null>:1061568 (libc++.1.dylib:x86_64+0x36538)
|
#2 std::__1::lock_guard<std::__1::mutex>::lock_guard(std::__1::mutex&) __mutex_base:103 (LiteCoreCppTests:x86_64+0x1016a0b1a)
|
#3 litecore::LogEncoder::vlog(char const*, std::__1::map<unsigned int, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, std::__1::less<unsigned int>, std::__1::allocator<std::__1::pair<unsigned int const, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > > > > const&, litecore::LogEncoder::ObjectRef, char const*, __va_list_tag*) LogEncoder.cc:87 (LiteCoreCppTests:x86_64+0x1016a1669)
|
#4 litecore::LogEncoder::log(char const*, std::__1::map<unsigned int, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, std::__1::less<unsigned int>, std::__1::allocator<std::__1::pair<unsigned int const, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > > > > const&, litecore::LogEncoder::ObjectRef, char const*, ...) LogEncoder.cc:76 (LiteCoreCppTests:x86_64+0x1016a14c6)
|
#5 litecore::LogDomain::writeEncodedLogsTo(litecore::LogFileOptions const&, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&) Logging.cc:234 (LiteCoreCppTests:x86_64+0x100e0cc5c)
|
#6 ____C_A_T_C_H____T_E_S_T____200() LogEncoderTest.cc:216 (LiteCoreCppTests:x86_64+0x1002303bc)
|
#7 Catch::FreeFunctionTestCase::invoke() const catch.hpp:6582 (LiteCoreCppTests:x86_64+0x100037e89)
|
#8 Catch::TestCase::invoke() const catch.hpp:7519 (LiteCoreCppTests:x86_64+0x1000177e3)
|
#9 Catch::RunContext::invokeActiveTestCase() catch.hpp:6158 (LiteCoreCppTests:x86_64+0x100083d3c)
|
#10 Catch::RunContext::runCurrentTest(std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >&, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >&) catch.hpp:6129 (LiteCoreCppTests:x86_64+0x100082e26)
|
#11 Catch::RunContext::runTest(Catch::TestCase const&) catch.hpp:5949 (LiteCoreCppTests:x86_64+0x100007f1a)
|
#12 Catch::runTests(Catch::Ptr<Catch::Config> const&) catch.hpp:6297 (LiteCoreCppTests:x86_64+0x10000606d)
|
#13 Catch::Session::run() catch.hpp:6405 (LiteCoreCppTests:x86_64+0x100100e89)
|
#14 Catch::Session::run(int, char const* const*) catch.hpp:6384 (LiteCoreCppTests:x86_64+0x100032dec)
|
#15 main catch.hpp:10333 (LiteCoreCppTests:x86_64+0x100032bf2)
|
|
|
Mutex M588 (0x00010342bd78) created at:
|
#0 pthread_mutex_lock <null>:1061568 (libclang_rt.tsan_osx_dynamic.dylib:x86_64h+0x3b09e)
|
#1 std::__1::mutex::lock() <null>:1061568 (libc++.1.dylib:x86_64+0x36538)
|
#2 std::__1::unique_lock<std::__1::mutex>::unique_lock(std::__1::mutex&) __mutex_base:130 (LiteCoreCppTests:x86_64+0x100e0c33a)
|
#3 litecore::LogDomain::setLevel(litecore::LogLevel) Logging.cc:350 (LiteCoreCppTests:x86_64+0x100e0ef75)
|
#4 litecore::LogDomain::computeLevel() Logging.cc:339 (LiteCoreCppTests:x86_64+0x100e0ee35)
|
#5 litecore::LogDomain::vlog(litecore::LogLevel, unsigned int, bool, char const*, __va_list_tag*) Logging.cc:382 (LiteCoreCppTests:x86_64+0x100e0f674)
|
#6 litecore::LogDomain::vlog(litecore::LogLevel, char const*, __va_list_tag*) Logging.cc:423 (LiteCoreCppTests:x86_64+0x100e10e21)
|
#7 c4vlog c4Base.cc:425 (LiteCoreCppTests:x86_64+0x10105fcfa)
|
#8 c4log c4Base.cc:418 (LiteCoreCppTests:x86_64+0x10105fc1b)
|
#9 (anonymous namespace)::____C_A_T_C_H____T_E_S_T____116() c4BaseTest.cc:120 (LiteCoreCppTests:x86_64+0x10021f51d)
|
#10 Catch::FreeFunctionTestCase::invoke() const catch.hpp:6582 (LiteCoreCppTests:x86_64+0x100037e89)
|
#11 Catch::TestCase::invoke() const catch.hpp:7519 (LiteCoreCppTests:x86_64+0x1000177e3)
|
#12 Catch::RunContext::invokeActiveTestCase() catch.hpp:6158 (LiteCoreCppTests:x86_64+0x100083d3c)
|
#13 Catch::RunContext::runCurrentTest(std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >&, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >&) catch.hpp:6129 (LiteCoreCppTests:x86_64+0x100082e26)
|
#14 Catch::RunContext::runTest(Catch::TestCase const&) catch.hpp:5949 (LiteCoreCppTests:x86_64+0x100007f1a)
|
#15 Catch::runTests(Catch::Ptr<Catch::Config> const&) catch.hpp:6297 (LiteCoreCppTests:x86_64+0x10000606d)
|
#16 Catch::Session::run() catch.hpp:6405 (LiteCoreCppTests:x86_64+0x100100e89)
|
#17 Catch::Session::run(int, char const* const*) catch.hpp:6384 (LiteCoreCppTests:x86_64+0x100032dec)
|
#18 main catch.hpp:10333 (LiteCoreCppTests:x86_64+0x100032bf2)
|
|
|
Thread T1 (tid=9732580, running) created by main thread at:
|
#0 pthread_create <null>:1061760 (libclang_rt.tsan_osx_dynamic.dylib:x86_64h+0x2aacd)
|
#1 std::__1::__libcpp_thread_create(_opaque_pthread_t**, void* (*)(void*), void*) __threading_support:327 (LiteCoreCppTests:x86_64+0x1013e21be)
|
#2 std::__1::thread::thread<litecore::actor::Timer::Manager::Manager()::$_0, void>(litecore::actor::Timer::Manager::Manager()::$_0&&) thread:367 (LiteCoreCppTests:x86_64+0x1013e1cc4)
|
#3 std::__1::thread::thread<litecore::actor::Timer::Manager::Manager()::$_0, void>(litecore::actor::Timer::Manager::Manager()::$_0&&) thread:359 (LiteCoreCppTests:x86_64+0x1013ddeca)
|
#4 litecore::actor::Timer::Manager::Manager() Timer.cc:34 (LiteCoreCppTests:x86_64+0x1013ddc76)
|
#5 litecore::actor::Timer::Manager::Manager() Timer.cc:35 (LiteCoreCppTests:x86_64+0x1013ddb88)
|
#6 litecore::actor::Timer::manager() Timer.cc:28 (LiteCoreCppTests:x86_64+0x1013dda50)
|
#7 litecore::actor::Timer::fireAfter(std::__1::chrono::duration<long long, std::__1::ratio<1l, 1000000000l> >) Timer.hh:67 (LiteCoreCppTests:x86_64+0x1016ce172)
|
#8 void litecore::actor::Timer::fireAfter<long long, std::__1::ratio<1l, 1000000l> >(std::__1::chrono::duration<long long, std::__1::ratio<1l, 1000000l> > const&) Timer.hh:76 (LiteCoreCppTests:x86_64+0x1016a6e34)
|
#9 litecore::LogEncoder::_scheduleFlush() LogEncoder.cc:288 (LiteCoreCppTests:x86_64+0x1016a5ba8)
|
#10 litecore::LogEncoder::vlog(char const*, std::__1::map<unsigned int, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, std::__1::less<unsigned int>, std::__1::allocator<std::__1::pair<unsigned int const, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > > > > const&, litecore::LogEncoder::ObjectRef, char const*, __va_list_tag*) LogEncoder.cc:244 (LiteCoreCppTests:x86_64+0x1016a45df)
|
#11 litecore::LogEncoder::log(char const*, std::__1::map<unsigned int, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, std::__1::less<unsigned int>, std::__1::allocator<std::__1::pair<unsigned int const, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > > > > const&, litecore::LogEncoder::ObjectRef, char const*, ...) LogEncoder.cc:76 (LiteCoreCppTests:x86_64+0x1016a14c6)
|
#12 ____C_A_T_C_H____T_E_S_T____75() LogEncoderTest.cc:81 (LiteCoreCppTests:x86_64+0x10022baf7)
|
#13 Catch::FreeFunctionTestCase::invoke() const catch.hpp:6582 (LiteCoreCppTests:x86_64+0x100037e89)
|
#14 Catch::TestCase::invoke() const catch.hpp:7519 (LiteCoreCppTests:x86_64+0x1000177e3)
|
#15 Catch::RunContext::invokeActiveTestCase() catch.hpp:6158 (LiteCoreCppTests:x86_64+0x100083d3c)
|
#16 Catch::RunContext::runCurrentTest(std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >&, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >&) catch.hpp:6129 (LiteCoreCppTests:x86_64+0x100082e26)
|
#17 Catch::RunContext::runTest(Catch::TestCase const&) catch.hpp:5949 (LiteCoreCppTests:x86_64+0x100007f1a)
|
#18 Catch::runTests(Catch::Ptr<Catch::Config> const&) catch.hpp:6297 (LiteCoreCppTests:x86_64+0x10000606d)
|
#19 Catch::Session::run() catch.hpp:6405 (LiteCoreCppTests:x86_64+0x100100e89)
|
#20 Catch::Session::run(int, char const* const*) catch.hpp:6384 (LiteCoreCppTests:x86_64+0x100032dec)
|
#21 main catch.hpp:10333 (LiteCoreCppTests:x86_64+0x100032bf2)
|
|
|
SUMMARY: ThreadSanitizer: data race streambuf:473 in std::__1::basic_streambuf<char, std::__1::char_traits<char> >::xsputn(char const*, long)
|
==================
|