Logging: provide a way to safely disable logging in a forked process

[labath]

Summary

We had a bug where if we had forked (in the ProcessLauncherPosixFork)
while another thread was writing a log message, we would deadlock. This
happened because the fork child inherited the locked log rwmutex, which
would never get unlocked. This meant the child got stuck trying to
disable all log channels.

The bug existed for a while but only started being apparent after
D37930, which started using ThreadLauncher (which uses logging) instead
of std::thread (which does not) for launching TaskPool threads.

The fix is to provide a lock free way to disable logging, which should
be used in this case, and this case only.

[clayborg]

Who is holding the lock and then fork'ing? Seems like we should fix that? I thought all log calls should be "lock, log, unlock". Why is this causing problems?

[clayborg]

Never mind, re-reading your original comment made it clear.

[eugene]

DisableUnlocked methods makes me uneasy.
Maybe we can take a log lock before forking and then properly release it in both parent and child processes?

[labath]

Solve the problem using pthread_atfork().

This way the locks are properly taken before forking and released in both child
and parent processes. This behavior is encapsulated within the Log class and is
completely transparent to all fork users (but it requires a tiny bit of
system-specific code).

[clayborg]

Much better.

[labath]

The previous fix had a problem where a more paraniod libc (e.g., android, but I
suspect freebds would do that as well) would detect that the
thread unlocking the mutex is not the same one as the one that locked, and
refused to comply.

The new fix is a combination of the first two solutions: we disable the logging
via custom code after forking, but we still do it via pthread_atfork to avoid
this detail leaking outside the Log implementation. The added benefit is that
forking code does not need to worry about logging at all, as it will be
automatically disabled.

[eugene]

source/Utility/Log.cpp

333 ↗

(On Diff #119710)

A little comment here describing nature of a deadlock if we don't disable logging would be nice.

lldb/trunk/include/lldb/Utility/Log.h

public:
     Log *GetLogIfAny(uint32_t mask) {
       Log *log = log_ptr.load(std::memory_order_relaxed);
       if (log && log->GetMask().AnySet(mask))
         return log;
       return nullptr;
     }
   };
 
+
+  static void Initialize();
+
   //------------------------------------------------------------------
   // Static accessors for logging channels
   //------------------------------------------------------------------
   static void Register(llvm::StringRef name, Channel &channel);
   static void Unregister(llvm::StringRef name);
 
   static bool
   EnableLogChannel(const std::shared_ptr<llvm::raw_ostream> &log_stream_sp,
private:
   typedef llvm::StringMap<Log> ChannelMap;
   static llvm::ManagedStatic<ChannelMap> g_channel_map;
 
   static void ListCategories(llvm::raw_ostream &stream,
                              const ChannelMap::value_type &entry);
   static uint32_t GetFlags(llvm::raw_ostream &stream, const ChannelMap::value_type &entry,
                            llvm::ArrayRef<const char *> categories);
 
+  static void DisableLoggingChild();
+
   Log(const Log &) = delete;
   void operator=(const Log &) = delete;
 };
 
 } // namespace lldb_private
 
 #define LLDB_LOG(log, ...)                                                     \
   do {                                                                         \

lldb/trunk/include/lldb/Utility/Logging.h

 class Log;
 
 void LogIfAnyCategoriesSet(uint32_t mask, const char *format, ...);
 
 Log *GetLogIfAllCategoriesSet(uint32_t mask);
 
 Log *GetLogIfAnyCategoriesSet(uint32_t mask);
 
-void InitializeLog();
+void InitializeLldbChannel();
 
 } // namespace lldb_private
 
 #endif // LLDB_UTILITY_LOGGING_H

lldb/trunk/source/Host/posix/ProcessLauncherPosixFork.cpp

if (::dup2(target_fd, fd) == -1)
     ExitWithError(error_fd, "DupDescriptor-dup2");
 
   ::close(target_fd);
   return;
 }
 
 static void LLVM_ATTRIBUTE_NORETURN ChildFunc(int error_fd,
                                               const ProcessLaunchInfo &info) {
-  // First, make sure we disable all logging. If we are logging to stdout, our
-  // logs can be mistaken for inferior output.
-  Log::DisableAllLogChannels();
-
   // Do not inherit setgid powers.
   if (setgid(getgid()) != 0)
     ExitWithError(error_fd, "setgid");
 
   if (info.GetFlags().Test(eLaunchFlagLaunchInSeparateProcessGroup)) {
     if (setpgid(0, 0) != 0)
       ExitWithError(error_fd, "setpgid");
   }

lldb/trunk/source/Initialization/SystemInitializerCommon.cpp

if (disable_crash_dialog_var &&
     _CrtSetReportMode(_CRT_ERROR, _CRTDBG_MODE_FILE | _CRTDBG_MODE_DEBUG);
     _CrtSetReportFile(_CRT_ASSERT, _CRTDBG_FILE_STDERR);
     _CrtSetReportFile(_CRT_WARN, _CRTDBG_FILE_STDERR);
     _CrtSetReportFile(_CRT_ERROR, _CRTDBG_FILE_STDERR);
   }
 #endif
 
   llvm::EnablePrettyStackTrace();
-  InitializeLog();
+  Log::Initialize();
   HostInfo::Initialize();
   static Timer::Category func_cat(LLVM_PRETTY_FUNCTION);
   Timer scoped_timer(func_cat, LLVM_PRETTY_FUNCTION);
 
   process_gdb_remote::ProcessGDBRemoteLog::Initialize();
 
   // Initialize plug-ins
   ObjectContainerBSDArchive::Initialize();

lldb/trunk/source/Utility/Log.cpp

 #include <mutex>
 #include <utility> // for pair
 
 #include <assert.h>  // for assert
 #if defined(LLVM_ON_WIN32)
 #include <process.h> // for getpid
 #else
 #include <unistd.h>
+#include <pthread.h>
 #endif
 
 using namespace lldb_private;
 
 llvm::ManagedStatic<Log::ChannelMap> Log::g_channel_map;
 
 void Log::ListCategories(llvm::raw_ostream &stream, const ChannelMap::value_type &entry) {
   stream << llvm::formatv("Logging categories for '{0}':\n", entry.first());
void Log::Warning(const char *format, ...) {
   va_list args;
   va_start(args, format);
   VASprintf(Content, format, args);
   va_end(args);
 
   Printf("warning: %s", Content.c_str());
 }
 
+void Log::Initialize() {
+#ifdef LLVM_ON_UNIX
+  pthread_atfork(nullptr, nullptr, &Log::DisableLoggingChild);
+#endif
+  InitializeLldbChannel();
+}
+
 void Log::Register(llvm::StringRef name, Channel &channel) {
   auto iter = g_channel_map->try_emplace(name, channel);
   assert(iter.second == true);
   (void)iter;
 }
 
 void Log::Unregister(llvm::StringRef name) {
   auto iter = g_channel_map->find(name);

 void Log::Format(llvm::StringRef file, llvm::StringRef function,
                  const llvm::formatv_object_base &payload) {
   std::string message_string;
   llvm::raw_string_ostream message(message_string);
   WriteHeader(message, file, function);
   message << payload << "\n";
   WriteMessage(message.str());
 }
+
+void Log::DisableLoggingChild() {
+  // Disable logging by clearing out the atomic variable after forking -- if we
+  // forked while another thread held the channel mutex, we would deadlock when
+  // trying to write to the log.
+  for (auto &c: *g_channel_map)
+    c.second.m_channel.log_ptr.store(nullptr, std::memory_order_relaxed);
+}

lldb/trunk/source/Utility/Logging.cpp

static constexpr Log::Category g_categories[] = {
   {{"thread"}, {"log thread events and activities"}, LIBLLDB_LOG_THREAD},
   {{"types"}, {"log type system related activities"}, LIBLLDB_LOG_TYPES},
   {{"unwind"}, {"log stack unwind activities"}, LIBLLDB_LOG_UNWIND},
   {{"watch"}, {"log watchpoint related activities"}, LIBLLDB_LOG_WATCHPOINTS},
 };
 
 static Log::Channel g_log_channel(g_categories, LIBLLDB_LOG_DEFAULT);
 
-void lldb_private::InitializeLog() {
+void lldb_private::InitializeLldbChannel() {
   Log::Register("lldb", g_log_channel);
 }
 
 Log *lldb_private::GetLogIfAllCategoriesSet(uint32_t mask) {
   return g_log_channel.GetLogIfAll(mask);
 }
 
 Log *lldb_private::GetLogIfAnyCategoriesSet(uint32_t mask) {