[Lldb-commits] [PATCH] D30168: Log: Fix race in accessing the stream variable

[Pavel Labath via Phabricator via lldb-commits]

labath created this revision.

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.


https://reviews.llvm.org/D30168

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


Index: unittests/Core/LogTest.cpp
===================================================================
--- unittests/Core/LogTest.cpp
+++ unittests/Core/LogTest.cpp
@@ -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 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 @@
   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();
+}
Index: source/Core/Log.cpp
===================================================================
--- source/Core/Log.cpp
+++ source/Core/Log.cpp
@@ -400,7 +400,7 @@
 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;
 
Index: include/lldb/Core/Log.h
===================================================================
--- include/lldb/Core/Log.h
+++ include/lldb/Core/Log.h
@@ -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 @@
   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;
 


-------------- next part --------------
A non-text attachment was scrubbed...
Name: D30168.89120.patch
Type: text/x-patch
Size: 3247 bytes
Desc: not available
URL: <http://lists.llvm.org/pipermail/lldb-commits/attachments/20170220/fa0dd160/attachment-0001.bin>