MongoDB | 2607914

Info

The CaptureLogs facility is just implemented in a racy way. It has a data member capturedLogMessages that is a vector. It creates a LogCatpureBackend, which saves a reference to that data member. Everytime the backend's consume function is called by the logging infrastructure, it pushes a new string into that vector. And everytime a test calls getCapturedTextFormatLogMessages (i.e. via countTextFormatLogMessagesContaining), it reads from that same vector. These writes via the log system and reads via unittests are unsynchronized, and TSAN has observed such an unsynchronized read/write interleaving onto one of the string log messages. The LogCaptureBackend we provide to boost as a log sink is a synchronized sink (i.e. it has frontend requirement boost::log::sinks::synchronized_feeding), which implies that it expects the frontend to handle synchronization for it; the expectation is that the frontend guarantees there are no concurrent calls to consume. And indeed the _captureSink we use for unittests uses boost::log::sinks::synchronous_sink as the frontend, which uses a mutex to serialize threads passing things to the backend by calling consume(). This prevents multiple logging threads from calling consume concurrently, but it doesn't prevent a single logging-thread in consume from writing to LogCaptureBackend::_logLines, which is a reference to CaptureLogs::_capturedLogMessages, while the unittest-main thread tries to read _capturedLogMessages. To fix this we should either take the same lock the frontend is using to synchronize calls to consume(), or a new mutex, and make a copy of the capturedLogMessages for use by the unittests under the lock

Top User Comments

Steps to Reproduce