[Lldb-commits] [lldb] r295712 - Log: Fix race in accessing the stream variable

[Pavel Labath via lldb-commits]

Author: labath
Date: Tue Feb 21 03:58:23 2017
New Revision: 295712

URL: http://llvm.org/viewvc/llvm-project?rev=295712&view=rev
Log:
Log: Fix race in accessing the stream variable

Summary:
The code was attempting to copy the shared pointer member in order to
guarantee atomicity, but this is not enough. Instead, protect the
pointer with a proper read-write mutex.

This bug was present here for a long time, but my recent refactors must
have altered the timings slightly, such that now this fails fairly often
when running the tests: the test runner runs the "log disable" command
just as the thread monitoring the lldb-server child is about to report
that the server has exited.

I add a test case for this. It's not possible to reproduce the race
deterministically in normal circumstances, but I have verified that
before the fix, the test failed when run under tsan, and was running
fine afterwards.

Reviewers: clayborg, zturner

Subscribers: lldb-commits

Differential Revision: https://reviews.llvm.org/D30168

Modified:
    lldb/trunk/include/lldb/Core/Log.h
    lldb/trunk/source/Core/Log.cpp
    lldb/trunk/unittests/Core/LogTest.cpp

Modified: lldb/trunk/include/lldb/Core/Log.h
URL: http://llvm.org/viewvc/llvm-project/lldb/trunk/include/lldb/Core/Log.h?rev=295712&r1=295711&r2=295712&view=diff
==============================================================================
--- lldb/trunk/include/lldb/Core/Log.h (original)
+++ lldb/trunk/include/lldb/Core/Log.h Tue Feb 21 03:58:23 2017
@@ -18,6 +18,7 @@
 
 // Other libraries and framework includes
 #include "llvm/Support/FormatVariadic.h"
+#include "llvm/Support/RWMutex.h"
 // C++ Includes
 #include <atomic>
 #include <cstdarg>
@@ -184,14 +185,22 @@ public:
   bool GetVerbose() const;
 
   void SetStream(const std::shared_ptr<llvm::raw_ostream> &stream_sp) {
+    llvm::sys::ScopedWriter lock(m_stream_mutex);
     m_stream_sp = stream_sp;
   }
 
+  std::shared_ptr<llvm::raw_ostream> GetStream() {
+    llvm::sys::ScopedReader lock(m_stream_mutex);
+    return m_stream_sp;
+  }
+
 protected:
   //------------------------------------------------------------------
   // Member variables
   //------------------------------------------------------------------
+  llvm::sys::RWMutex m_stream_mutex; // Protects m_stream_sp
   std::shared_ptr<llvm::raw_ostream> m_stream_sp;
+
   Flags m_options;
   Flags m_mask_bits;
 

Modified: lldb/trunk/source/Core/Log.cpp
URL: http://llvm.org/viewvc/llvm-project/lldb/trunk/source/Core/Log.cpp?rev=295712&r1=295711&r2=295712&view=diff
==============================================================================
--- lldb/trunk/source/Core/Log.cpp (original)
+++ lldb/trunk/source/Core/Log.cpp Tue Feb 21 03:58:23 2017
@@ -400,7 +400,7 @@ void Log::WriteHeader(llvm::raw_ostream
 void Log::WriteMessage(const std::string &message) {
   // Make a copy of our stream shared pointer in case someone disables our
   // log while we are logging and releases the stream
-  auto stream_sp = m_stream_sp;
+  auto stream_sp = GetStream();
   if (!stream_sp)
     return;
 

Modified: lldb/trunk/unittests/Core/LogTest.cpp
URL: http://llvm.org/viewvc/llvm-project/lldb/trunk/unittests/Core/LogTest.cpp?rev=295712&r1=295711&r2=295712&view=diff
==============================================================================
--- lldb/trunk/unittests/Core/LogTest.cpp (original)
+++ lldb/trunk/unittests/Core/LogTest.cpp Tue Feb 21 03:58:23 2017
@@ -13,6 +13,7 @@
 #include "lldb/Host/Host.h"
 #include "lldb/Utility/StreamString.h"
 #include "llvm/Support/ManagedStatic.h"
+#include <thread>
 
 using namespace lldb;
 using namespace lldb_private;
@@ -26,6 +27,8 @@ static constexpr uint32_t default_flags
 static Log::Channel test_channel(test_categories, default_flags);
 
 struct LogChannelTest : public ::testing::Test {
+  void TearDown() override { Log::DisableAllLogChannels(nullptr); }
+
   static void SetUpTestCase() {
     Log::Register("chan", test_channel);
   }
@@ -170,3 +173,26 @@ TEST_F(LogChannelTest, List) {
   EXPECT_FALSE(Log::ListChannelCategories("chanchan", str));
   EXPECT_EQ("Invalid log channel 'chanchan'.\n", str.GetString().str());
 }
+
+TEST_F(LogChannelTest, LogThread) {
+  // Test that we are able to concurrently write to a log channel and disable
+  // it.
+  std::string message;
+  std::shared_ptr<llvm::raw_string_ostream> stream_sp(
+      new llvm::raw_string_ostream(message));
+  StreamString err;
+  EXPECT_TRUE(Log::EnableLogChannel(stream_sp, 0, "chan", nullptr, err));
+
+  Log *log = test_channel.GetLogIfAll(FOO);
+
+  // Start logging on one thread. Concurrently, try disabling the log channel.
+  std::thread log_thread([log] { LLDB_LOG(log, "Hello World"); });
+  EXPECT_TRUE(Log::DisableLogChannel("chan", nullptr, err));
+  log_thread.join();
+
+  // The log thread either managed to write to the log in time, or it didn't. In
+  // either case, we should not trip any undefined behavior (run the test under
+  // TSAN to verify this).
+  EXPECT_TRUE(stream_sp->str() == "" || stream_sp->str() == "Hello World\n")
+      << "str(): " << stream_sp->str();
+}