[lldb-dap] Ensure logging statements are written as a single chunk. (#131916)

I noticed this while debugging some unit tests that the logs
occasionally would intersperse two log statements.

Previously, it was possible for a log statement to have two messages
interspersed since the timestamp and log statement were two different
writes to the log stream.

I created a Log helper to ensure we have a lock while attempting to write
to the logs.

Author: ashgti

lldb/tools/lldb-dap/CMakeLists.txt

@@ -23,6 +23,7 @@ add_lldb_tool(lldb-dap
   Breakpoint.cpp
   BreakpointBase.cpp
   DAP.cpp
+  DAPLog.cpp
   EventHelper.cpp
   ExceptionBreakpoint.cpp
   FifoFiles.cpp

lldb/tools/lldb-dap/DAP.cpp

@@ -68,8 +68,7 @@ const char DEV_NULL[] = "/dev/null";
 
 namespace lldb_dap {
 
-DAP::DAP(llvm::StringRef path, std::ofstream *log,
-         const ReplMode default_repl_mode,
+DAP::DAP(llvm::StringRef path, Log *log, const ReplMode default_repl_mode,
          std::vector<std::string> pre_init_commands, Transport &transport)
     : debug_adapter_path(path), log(log), transport(transport),
       broadcaster("lldb-dap"), exception_breakpoints(),

lldb/tools/lldb-dap/DAP.h

@@ -144,7 +144,7 @@ struct SendEventRequestHandler : public lldb::SBCommandPluginInterface {
 
 struct DAP {
   llvm::StringRef debug_adapter_path;
-  std::ofstream *log;
+  Log *log;
   Transport &transport;
   lldb::SBFile in;
   OutputRedirector out;
@@ -211,15 +211,14 @@ struct DAP {
   /// \param[in] path
   ///     Path to the lldb-dap binary.
   /// \param[in] log
-  ///     Log file stream, if configured.
+  ///     Log stream, if configured.
   /// \param[in] default_repl_mode
   ///     Default repl mode behavior, as configured by the binary.
   /// \param[in] pre_init_commands
   ///     LLDB commands to execute as soon as the debugger instance is allocaed.
   /// \param[in] transport
   ///     Transport for this debug session.
-  DAP(llvm::StringRef path, std::ofstream *log,
-      const ReplMode default_repl_mode,
+  DAP(llvm::StringRef path, Log *log, const ReplMode default_repl_mode,
       std::vector<std::string> pre_init_commands, Transport &transport);
 
   ~DAP();

lldb/tools/lldb-dap/DAPForward.h

@@ -19,6 +19,7 @@ struct SourceBreakpoint;
 struct Watchpoint;
 struct InstructionBreakpoint;
 struct DAP;
+class Log;
 class BaseRequestHandler;
 class ResponseHandler;
 } // namespace lldb_dap

lldb/tools/lldb-dap/DAPLog.cpp

@@ -0,0 +1,30 @@
+//===-- DAPLog.cpp --------------------------------------------------------===//
+//
+// Part of the LLVM Project, under the Apache License v2.0 with LLVM Exceptions.
+// See https://llvm.org/LICENSE.txt for license information.
+// SPDX-License-Identifier: Apache-2.0 WITH LLVM-exception
+//
+//===----------------------------------------------------------------------===//
+
+#include "DAPLog.h"
+#include "llvm/ADT/StringRef.h"
+#include "llvm/Support/raw_ostream.h"
+#include <chrono>
+#include <mutex>
+#include <system_error>
+
+using namespace llvm;
+
+namespace lldb_dap {
+
+Log::Log(StringRef filename, std::error_code &EC) : m_stream(filename, EC) {}
+
+void Log::WriteMessage(StringRef message) {
+  std::lock_guard<std::mutex> lock(m_mutex);
+  std::chrono::duration<double> now{
+      std::chrono::system_clock::now().time_since_epoch()};
+  m_stream << formatv("{0:f9} ", now.count()).str() << message << "\n";
+  m_stream.flush();
+}
+
+} // namespace lldb_dap

lldb/tools/lldb-dap/DAPLog.h

@@ -9,44 +9,53 @@
 #ifndef LLDB_TOOLS_LLDB_DAP_DAPLOG_H
 #define LLDB_TOOLS_LLDB_DAP_DAPLOG_H
 
+#include "llvm/ADT/StringRef.h"
 #include "llvm/Support/Error.h"
 #include "llvm/Support/FormatAdapters.h"
 #include "llvm/Support/FormatVariadic.h"
-#include <chrono>
-#include <fstream>
+#include "llvm/Support/raw_ostream.h"
+#include <mutex>
 #include <string>
+#include <system_error>
 
 // Write a message to log, if logging is enabled.
 #define DAP_LOG(log, ...)                                                      \
   do {                                                                         \
-    ::std::ofstream *log_private = (log);                                      \
+    ::lldb_dap::Log *log_private = (log);                                      \
     if (log_private) {                                                         \
-      ::std::chrono::duration<double> now{                                     \
-          ::std::chrono::system_clock::now().time_since_epoch()};              \
-      *log_private << ::llvm::formatv("{0:f9} ", now.count()).str()            \
-                   << ::llvm::formatv(__VA_ARGS__).str() << std::endl;         \
+      log_private->WriteMessage(::llvm::formatv(__VA_ARGS__).str());           \
     }                                                                          \
   } while (0)
 
 // Write message to log, if error is set. In the log message refer to the error
 // with {0}. Error is cleared regardless of whether logging is enabled.
 #define DAP_LOG_ERROR(log, error, ...)                                         \
   do {                                                                         \
-    ::std::ofstream *log_private = (log);                                      \
+    ::lldb_dap::Log *log_private = (log);                                      \
     ::llvm::Error error_private = (error);                                     \
     if (log_private && error_private) {                                        \
-      ::std::chrono::duration<double> now{                                     \
-          std::chrono::system_clock::now().time_since_epoch()};                \
-      *log_private << ::llvm::formatv("{0:f9} ", now.count()).str()            \
-                   << ::lldb_dap::FormatError(::std::move(error_private),      \
-                                              __VA_ARGS__)                     \
-                   << std::endl;                                               \
+      log_private->WriteMessage(                                               \
+          ::lldb_dap::FormatError(::std::move(error_private), __VA_ARGS__));   \
     } else                                                                     \
       ::llvm::consumeError(::std::move(error_private));                        \
   } while (0)
 
 namespace lldb_dap {
 
+/// Log manages the lldb-dap log file, used with the corresponding `DAP_LOG` and
+/// `DAP_LOG_ERROR` helpers.
+class Log final {
+public:
+  /// Creates a log file with the given filename.
+  Log(llvm::StringRef filename, std::error_code &EC);
+
+  void WriteMessage(llvm::StringRef message);
+
+private:
+  std::mutex m_mutex;
+  llvm::raw_fd_ostream m_stream;
+};
+
 template <typename... Args>
 inline auto FormatError(llvm::Error error, const char *format, Args &&...args) {
   return llvm::formatv(format, llvm::toString(std::move(error)),

lldb/tools/lldb-dap/EventHelper.cpp

@@ -8,6 +8,7 @@
 
 #include "EventHelper.h"
 #include "DAP.h"
+#include "DAPLog.h"
 #include "JSONUtils.h"
 #include "LLDBUtils.h"
 #include "lldb/API/SBFileSpec.h"
@@ -178,15 +179,13 @@ void SendThreadStoppedEvent(DAP &dap) {
           SendThreadExitedEvent(dap, tid);
       }
     } else {
-      if (dap.log)
-        *dap.log << "error: SendThreadStoppedEvent() when process"
-                    " isn't stopped ("
-                 << lldb::SBDebugger::StateAsCString(state) << ')' << std::endl;
+      DAP_LOG(
+          dap.log,
+          "error: SendThreadStoppedEvent() when process isn't stopped ({0})",
+          lldb::SBDebugger::StateAsCString(state));
     }
   } else {
-    if (dap.log)
-      *dap.log << "error: SendThreadStoppedEvent() invalid process"
-               << std::endl;
+    DAP_LOG(dap.log, "error: SendThreadStoppedEvent() invalid process");
   }
   dap.RunStopCommands();
 }

lldb/tools/lldb-dap/Transport.cpp

@@ -63,8 +63,8 @@ static constexpr StringLiteral kHeaderSeparator = "\r\n\r\n";
 
 namespace lldb_dap {
 
-Transport::Transport(StringRef client_name, std::ofstream *log,
-                     IOObjectSP input, IOObjectSP output)
+Transport::Transport(StringRef client_name, Log *log, IOObjectSP input,
+                     IOObjectSP output)
     : m_client_name(client_name), m_log(log), m_input(std::move(input)),
       m_output(std::move(output)) {}
 

lldb/tools/lldb-dap/Transport.h

@@ -14,11 +14,11 @@
 #ifndef LLDB_TOOLS_LLDB_DAP_TRANSPORT_H
 #define LLDB_TOOLS_LLDB_DAP_TRANSPORT_H
 
+#include "DAPForward.h"
 #include "Protocol/ProtocolBase.h"
 #include "lldb/lldb-forward.h"
 #include "llvm/ADT/StringRef.h"
 #include "llvm/Support/Error.h"
-#include <fstream>
 #include <optional>
 
 namespace lldb_dap {
@@ -27,8 +27,8 @@ namespace lldb_dap {
 /// with the client.
 class Transport {
 public:
-  Transport(llvm::StringRef client_name, std::ofstream *log,
-            lldb::IOObjectSP input, lldb::IOObjectSP output);
+  Transport(llvm::StringRef client_name, Log *log, lldb::IOObjectSP input,
+            lldb::IOObjectSP output);
   ~Transport() = default;
 
   /// Transport is not copyable.
@@ -51,7 +51,7 @@ class Transport {
 
 private:
   llvm::StringRef m_client_name;
-  std::ofstream *m_log;
+  Log *m_log;
   lldb::IOObjectSP m_input;
   lldb::IOObjectSP m_output;
 };

lldb/tools/lldb-dap/lldb-dap.cpp

@@ -48,6 +48,7 @@
 #include <memory>
 #include <mutex>
 #include <string>
+#include <system_error>
 #include <thread>
 #include <utility>
 #include <vector>
@@ -281,7 +282,7 @@ validateConnection(llvm::StringRef conn) {
 
 static llvm::Error
 serveConnection(const Socket::SocketProtocol &protocol, const std::string &name,
-                std::ofstream *log, llvm::StringRef program_path,
+                Log *log, llvm::StringRef program_path,
                 const ReplMode default_repl_mode,
                 const std::vector<std::string> &pre_init_commands) {
   Status status;
@@ -484,10 +485,17 @@ int main(int argc, char *argv[]) {
   }
 #endif
 
-  std::unique_ptr<std::ofstream> log = nullptr;
+  std::unique_ptr<Log> log = nullptr;
   const char *log_file_path = getenv("LLDBDAP_LOG");
-  if (log_file_path)
-    log = std::make_unique<std::ofstream>(log_file_path);
+  if (log_file_path) {
+    std::error_code EC;
+    log = std::make_unique<Log>(log_file_path, EC);
+    if (EC) {
+      llvm::logAllUnhandledErrors(llvm::errorCodeToError(EC), llvm::errs(),
+                                  "Failed to create log file: ");
+      return EXIT_FAILURE;
+    }
+  }
 
   // Initialize LLDB first before we do anything.
   lldb::SBError error = lldb::SBDebugger::InitializeWithErrorHandling();