Log: Fix race in accessing the stream variable

[labath]

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.

lldb/trunk/include/lldb/Core/Log.h

 // Project includes
 #include "lldb/Core/Logging.h"
 #include "lldb/Utility/ConstString.h"
 #include "lldb/Utility/Flags.h"
 #include "lldb/lldb-private.h"
 
 // Other libraries and framework includes
 #include "llvm/Support/FormatVariadic.h"
+#include "llvm/Support/RWMutex.h"
 // C++ Includes
 #include <atomic>
 #include <cstdarg>
 #include <cstdint>
 // C Includes
 
 //----------------------------------------------------------------------
 // Logging Options
public:
 
   Flags &GetMask();
 
   const Flags &GetMask() const;
 
   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;
 
 private:
   DISALLOW_COPY_AND_ASSIGN(Log);
 
   void WriteHeader(llvm::raw_ostream &OS, llvm::StringRef file,
                    llvm::StringRef function);

lldb/trunk/source/Core/Log.cpp

if (m_options.Test(LLDB_LOG_OPTION_PREPEND_FILE_FUNCTION) &&
     function = function.take_front(40);
     OS << llvm::formatv("{0,-60:60} ", (file + ":" + function).str());
   }
 }
 
 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;
 
   if (m_options.Test(LLDB_LOG_OPTION_THREADSAFE)) {
     static std::recursive_mutex g_LogThreadedMutex;
     std::lock_guard<std::recursive_mutex> guard(g_LogThreadedMutex);
     *stream_sp << message;
     stream_sp->flush();

lldb/trunk/unittests/Core/LogTest.cpp

 //===-- LogTest.cpp ---------------------------------------------*- C++ -*-===//
 //
 //                     The LLVM Compiler Infrastructure
 //
 // This file is distributed under the University of Illinois Open Source
 // License. See LICENSE.TXT for details.
 //
 //===----------------------------------------------------------------------===//
 
 #include "gtest/gtest.h"
 
 #include "lldb/Core/Log.h"
 #include "lldb/Host/Host.h"
 #include "lldb/Utility/StreamString.h"
 #include "llvm/Support/ManagedStatic.h"
+#include <thread>
 
 using namespace lldb;
 using namespace lldb_private;
 
 enum { FOO = 1, BAR = 2 };
 static constexpr Log::Category test_categories[] = {
     {"foo", "log foo", FOO}, {"bar", "log bar", BAR},
 };
 static constexpr uint32_t default_flags = FOO;
 
 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);
   }
 
   static void TearDownTestCase() {
     Log::Unregister("chan");
     llvm::llvm_shutdown();
   }
TEST_F(LogChannelTest, List) {
   bar - log bar
 )";
   EXPECT_EQ(expected, str.GetString().str());
   str.Clear();
 
   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();
+}