[lldb-dap] Improving logging support and formatting. (#170731)

Adjusting logs in a few ways:

* The `DAP_LOG` and `DAP_LOG_ERROR` macros now include the file/line of
the log statement.
* Added support for creating a log with a prefix. This simplifies how we
create logs for the `lldb_dap::DAP` instance and `lldb_dap::Transport`
instance, allowing us to not have to pass the client name around as
much.
* Updated logging usage to take the `lldb_dap::Log` as a reference but
it now defaults to `llvm::raw_null_stream` if not configured. This
ensures more uniform access to the logger, even if its not written
anywhere.

The logs now look like:

```
1764896564.038788080 (stdio) --> {"command":"initialize","arguments":{...},"type":"request","seq":1}
1764896564.039064884 DAP.cpp:1007 (stdio) queued (command=initialize seq=1)
1764896564.039768934 (stdio) <-- {"body":{...},"command":"initialize","request_seq":1,"seq":1,"success":true,"type":"response"}
```

Author: ashgti

lldb/tools/lldb-dap/DAP.cpp

@@ -122,7 +122,7 @@ static std::string capitalize(llvm::StringRef str) {
 
 llvm::StringRef DAP::debug_adapter_path = "";
 
-DAP::DAP(Log *log, const ReplMode default_repl_mode,
+DAP::DAP(Log &log, const ReplMode default_repl_mode,
          std::vector<std::string> pre_init_commands, bool no_lldbinit,
          llvm::StringRef client_name, DAPTransport &transport, MainLoop &loop)
     : log(log), transport(transport), broadcaster("lldb-dap"),
@@ -134,8 +134,6 @@ DAP::DAP(Log *log, const ReplMode default_repl_mode,
   RegisterRequests();
 }
 
-DAP::~DAP() = default;
-
 void DAP::PopulateExceptionBreakpoints() {
   if (lldb::SBDebugger::SupportsLanguage(lldb::eLanguageTypeC_plus_plus)) {
     exception_breakpoints.emplace_back(*this, "cpp_catch", "C++ Catch",
@@ -263,8 +261,7 @@ void DAP::SendJSON(const llvm::json::Value &json) {
   Message message;
   llvm::json::Path::Root root;
   if (!fromJSON(json, message, root)) {
-    DAP_LOG_ERROR(log, root.getError(), "({1}) encoding failed: {0}",
-                  m_client_name);
+    DAP_LOG_ERROR(log, root.getError(), "encoding failed: {0}");
     return;
   }
   Send(message);
@@ -285,15 +282,13 @@ Id DAP::Send(const Message &message) {
 
   if (const protocol::Event *event = std::get_if<protocol::Event>(&msg)) {
     if (llvm::Error err = transport.Send(*event))
-      DAP_LOG_ERROR(log, std::move(err), "({0}) sending event failed",
-                    m_client_name);
+      DAP_LOG_ERROR(log, std::move(err), "sending event failed: {0}");
     return event->seq;
   }
 
   if (const Request *req = std::get_if<Request>(&msg)) {
     if (llvm::Error err = transport.Send(*req))
-      DAP_LOG_ERROR(log, std::move(err), "({0}) sending request failed",
-                    m_client_name);
+      DAP_LOG_ERROR(log, std::move(err), "sending request failed: {0}");
     return req->seq;
   }
 
@@ -313,8 +308,7 @@ Id DAP::Send(const Message &message) {
                             })
                           : transport.Send(*resp);
     if (err)
-      DAP_LOG_ERROR(log, std::move(err), "({0}) sending response failed",
-                    m_client_name);
+      DAP_LOG_ERROR(log, std::move(err), "sending response failed: {0}");
     return resp->seq;
   }
 
@@ -857,8 +851,7 @@ bool DAP::HandleObject(const Message &M) {
 
     dispatcher.Set("error",
                    llvm::Twine("unhandled-command:" + req->command).str());
-    DAP_LOG(log, "({0}) error: unhandled command '{1}'", m_client_name,
-            req->command);
+    DAP_LOG(log, "error: unhandled command '{0}'", req->command);
     return false; // Fail
   }
 
@@ -1004,35 +997,33 @@ void DAP::Received(const protocol::Request &request) {
     // effort attempt to interrupt.
     std::lock_guard<std::mutex> guard(m_active_request_mutex);
     if (m_active_request && cancel_args->requestId == m_active_request->seq) {
-      DAP_LOG(log, "({0}) interrupting inflight request (command={1} seq={2})",
-              m_client_name, m_active_request->command, m_active_request->seq);
+      DAP_LOG(log, "interrupting inflight request (command={0} seq={1})",
+              m_active_request->command, m_active_request->seq);
       debugger.RequestInterrupt();
     }
   }
 
   std::lock_guard<std::mutex> guard(m_queue_mutex);
-  DAP_LOG(log, "({0}) queued (command={1} seq={2})", m_client_name,
-          request.command, request.seq);
+  DAP_LOG(log, "queued (command={0} seq={1})", request.command, request.seq);
   m_queue.push_back(request);
   m_queue_cv.notify_one();
 }
 
 void DAP::Received(const protocol::Response &response) {
   std::lock_guard<std::mutex> guard(m_queue_mutex);
-  DAP_LOG(log, "({0}) queued (command={1} seq={2})", m_client_name,
-          response.command, response.request_seq);
+  DAP_LOG(log, "queued (command={0} seq={1})", response.command,
+          response.request_seq);
   m_queue.push_back(response);
   m_queue_cv.notify_one();
 }
 
 void DAP::OnError(llvm::Error error) {
-  DAP_LOG_ERROR(log, std::move(error), "({1}) received error: {0}",
-                m_client_name);
+  DAP_LOG_ERROR(log, std::move(error), "transport error: {0}");
   TerminateLoop(/*failed=*/true);
 }
 
 void DAP::OnClosed() {
-  DAP_LOG(log, "({0}) received EOF", m_client_name);
+  DAP_LOG(log, "transport closed");
   TerminateLoop();
 }
 
@@ -1058,16 +1049,14 @@ void DAP::TransportHandler() {
   auto handle = transport.RegisterMessageHandler(m_loop, *this);
   if (!handle) {
     DAP_LOG_ERROR(log, handle.takeError(),
-                  "({1}) registering message handler failed: {0}",
-                  m_client_name);
+                  "registering message handler failed: {0}");
     std::lock_guard<std::mutex> guard(m_queue_mutex);
     m_error_occurred = true;
     return;
   }
 
   if (Status status = m_loop.Run(); status.Fail()) {
-    DAP_LOG_ERROR(log, status.takeError(), "({1}) MainLoop run failed: {0}",
-                  m_client_name);
+    DAP_LOG_ERROR(log, status.takeError(), "MainLoop run failed: {0}");
     std::lock_guard<std::mutex> guard(m_queue_mutex);
     m_error_occurred = true;
     return;

lldb/tools/lldb-dap/DAP.h

@@ -33,11 +33,9 @@
 #include "lldb/API/SBTarget.h"
 #include "lldb/API/SBThread.h"
 #include "lldb/Host/MainLoop.h"
-#include "lldb/Utility/Status.h"
 #include "lldb/lldb-types.h"
 #include "llvm/ADT/DenseMap.h"
 #include "llvm/ADT/DenseSet.h"
-#include "llvm/ADT/FunctionExtras.h"
 #include "llvm/ADT/SmallSet.h"
 #include "llvm/ADT/StringMap.h"
 #include "llvm/ADT/StringRef.h"
@@ -88,7 +86,7 @@ struct DAP final : public DAPTransport::MessageHandler {
   /// Path to the lldb-dap binary itself.
   static llvm::StringRef debug_adapter_path;
 
-  Log *log;
+  Log &log;
   DAPTransport &transport;
   lldb::SBFile in;
   OutputRedirector out;
@@ -194,12 +192,12 @@ struct DAP final : public DAPTransport::MessageHandler {
   ///     Transport for this debug session.
   /// \param[in] loop
   ///     Main loop associated with this instance.
-  DAP(Log *log, const ReplMode default_repl_mode,
+  DAP(Log &log, const ReplMode default_repl_mode,
       std::vector<std::string> pre_init_commands, bool no_lldbinit,
       llvm::StringRef client_name, DAPTransport &transport,
       lldb_private::MainLoop &loop);
 
-  ~DAP();
+  ~DAP() override = default;
 
   /// DAP is not copyable.
   /// @{

lldb/tools/lldb-dap/DAPLog.cpp

@@ -9,21 +9,26 @@
 #include "DAPLog.h"
 #include "llvm/ADT/StringRef.h"
 #include "llvm/Support/Chrono.h"
+#include "llvm/Support/Path.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::Emit(StringRef message) { Emit(message, "", 0); }
 
-void Log::WriteMessage(StringRef message) {
-  std::lock_guard<std::mutex> lock(m_mutex);
+void Log::Emit(StringRef message, StringRef file, size_t line) {
+  std::lock_guard<Log::Mutex> lock(m_mutex);
   const llvm::sys::TimePoint<> time = std::chrono::system_clock::now();
-  m_stream << formatv("[{0:%H:%M:%S.%L}] ", time) << message << '\n';
+  m_stream << formatv("[{0:%H:%M:%S.%L}]", time) << " ";
+  if (!file.empty())
+    m_stream << sys::path::filename(file) << ":" << line << " ";
+  if (!m_prefix.empty())
+    m_stream << m_prefix;
+  m_stream << message << "\n";
   m_stream.flush();
 }
 

lldb/tools/lldb-dap/DAPLog.h

@@ -11,33 +11,28 @@
 
 #include "llvm/ADT/StringRef.h"
 #include "llvm/Support/Error.h"
-#include "llvm/Support/FormatAdapters.h"
 #include "llvm/Support/FormatVariadic.h"
 #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 {                                                                         \
-    ::lldb_dap::Log *log_private = (log);                                      \
-    if (log_private) {                                                         \
-      log_private->WriteMessage(::llvm::formatv(__VA_ARGS__).str());           \
-    }                                                                          \
+    ::lldb_dap::Log &log_private = (log);                                      \
+    log_private.Emit(::llvm::formatv(__VA_ARGS__).str(), __FILE__, __LINE__);  \
   } 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 {                                                                         \
-    ::lldb_dap::Log *log_private = (log);                                      \
+    ::lldb_dap::Log &log_private = (log);                                      \
     ::llvm::Error error_private = (error);                                     \
-    if (log_private && error_private) {                                        \
-      log_private->WriteMessage(                                               \
-          ::lldb_dap::FormatError(::std::move(error_private), __VA_ARGS__));   \
-    } else                                                                     \
-      ::llvm::consumeError(::std::move(error_private));                        \
+    if (error_private)                                                         \
+      log_private.Emit(                                                        \
+          ::lldb_dap::FormatError(::std::move(error_private), __VA_ARGS__),    \
+          __FILE__, __LINE__);                                                 \
   } while (0)
 
 namespace lldb_dap {
@@ -46,14 +41,32 @@ namespace lldb_dap {
 /// `DAP_LOG_ERROR` helpers.
 class Log final {
 public:
-  /// Creates a log file with the given filename.
-  Log(llvm::StringRef filename, std::error_code &EC);
+  using Mutex = std::mutex;
 
-  void WriteMessage(llvm::StringRef message);
+  Log(llvm::raw_ostream &stream, Mutex &mutex)
+      : m_stream(stream), m_mutex(mutex) {}
+  Log(llvm::StringRef prefix, const Log &log)
+      : m_prefix(prefix), m_stream(log.m_stream), m_mutex(log.m_mutex) {}
+
+  /// Retuns a new Log instance with the associated prefix for all messages.
+  inline Log WithPrefix(llvm::StringRef prefix) const {
+    std::string full_prefix =
+        m_prefix.empty() ? prefix.str() : m_prefix + prefix.str();
+    full_prefix += " ";
+    return Log(full_prefix, *this);
+  }
+
+  /// Emit writes a message to the underlying stream.
+  void Emit(llvm::StringRef message);
+
+  /// Emit writes a message to the underlying stream, including the file and
+  /// line the message originated from.
+  void Emit(llvm::StringRef message, llvm::StringRef file, size_t line);
 
 private:
-  std::mutex m_mutex;
-  llvm::raw_fd_ostream m_stream;
+  std::string m_prefix;
+  llvm::raw_ostream &m_stream;
+  Mutex &m_mutex;
 };
 
 template <typename... Args>

lldb/tools/lldb-dap/DAPSessionManager.cpp

@@ -110,7 +110,8 @@ DAPSessionManager::GetEventThreadForDebugger(lldb::SBDebugger debugger,
   auto new_thread_sp = std::make_shared<ManagedEventThread>(
       requesting_dap->broadcaster,
       std::thread(EventThread, debugger, requesting_dap->broadcaster,
-                  requesting_dap->m_client_name, requesting_dap->log));
+                  requesting_dap->m_client_name,
+                  std::ref(requesting_dap->log)));
   m_debugger_event_threads[debugger_id] = new_thread_sp;
   return new_thread_sp;
 }

lldb/tools/lldb-dap/EventHelper.cpp

@@ -324,8 +324,8 @@ void SendMemoryEvent(DAP &dap, lldb::SBValue variable) {
 // the original DAP::Handle*Event pattern while supporting multi-session
 // debugging.
 
-void HandleProcessEvent(const lldb::SBEvent &event, bool &process_exited,
-                        Log *log) {
+static void HandleProcessEvent(const lldb::SBEvent &event, bool &process_exited,
+                               Log &log) {
   lldb::SBProcess process = lldb::SBProcess::GetProcessFromEvent(event);
 
   // Find the DAP instance that owns this process's target.
@@ -393,7 +393,7 @@ void HandleProcessEvent(const lldb::SBEvent &event, bool &process_exited,
   }
 }
 
-void HandleTargetEvent(const lldb::SBEvent &event, Log *log) {
+static void HandleTargetEvent(const lldb::SBEvent &event, Log &log) {
   lldb::SBTarget target = lldb::SBTarget::GetTargetFromEvent(event);
 
   // Find the DAP instance that owns this target.
@@ -480,7 +480,7 @@ void HandleTargetEvent(const lldb::SBEvent &event, Log *log) {
   }
 }
 
-void HandleBreakpointEvent(const lldb::SBEvent &event, Log *log) {
+static void HandleBreakpointEvent(const lldb::SBEvent &event, Log &log) {
   const uint32_t event_mask = event.GetType();
   if (!(event_mask & lldb::SBTarget::eBroadcastBitBreakpointChanged))
     return;
@@ -529,7 +529,7 @@ void HandleBreakpointEvent(const lldb::SBEvent &event, Log *log) {
   }
 }
 
-void HandleThreadEvent(const lldb::SBEvent &event, Log *log) {
+static void HandleThreadEvent(const lldb::SBEvent &event, Log &log) {
   uint32_t event_type = event.GetType();
 
   if (!(event_type & lldb::SBThread::eBroadcastBitStackChanged))
@@ -550,7 +550,7 @@ void HandleThreadEvent(const lldb::SBEvent &event, Log *log) {
                        thread.GetThreadID());
 }
 
-void HandleDiagnosticEvent(const lldb::SBEvent &event, Log *log) {
+static void HandleDiagnosticEvent(const lldb::SBEvent &event, Log &log) {
   // Global debugger events - send to all DAP instances.
   std::vector<DAP *> active_instances =
       DAPSessionManager::GetInstance().GetActiveSessions();
@@ -588,7 +588,7 @@ void HandleDiagnosticEvent(const lldb::SBEvent &event, Log *log) {
 // them prevent multiple threads from writing simultaneously so no locking
 // is required.
 void EventThread(lldb::SBDebugger debugger, lldb::SBBroadcaster broadcaster,
-                 llvm::StringRef client_name, Log *log) {
+                 llvm::StringRef client_name, Log &log) {
   llvm::set_thread_name("lldb.DAP.client." + client_name + ".event_handler");
   lldb::SBListener listener = debugger.GetListener();
   broadcaster.AddListener(listener, eBroadcastBitStopEventThread);

lldb/tools/lldb-dap/EventHelper.h

@@ -51,16 +51,7 @@ void SendMemoryEvent(DAP &dap, lldb::SBValue variable);
 /// \param client_name The client name for thread naming/logging purposes.
 /// \param log The log instance for logging.
 void EventThread(lldb::SBDebugger debugger, lldb::SBBroadcaster broadcaster,
-                 llvm::StringRef client_name, Log *log);
-
-/// Event handler functions called by EventThread.
-/// These handlers extract the necessary objects from events and find the
-/// appropriate DAP instance to handle them.
-void HandleProcessEvent(const lldb::SBEvent &event, bool &done, Log *log);
-void HandleTargetEvent(const lldb::SBEvent &event, Log *log);
-void HandleBreakpointEvent(const lldb::SBEvent &event, Log *log);
-void HandleThreadEvent(const lldb::SBEvent &event, Log *log);
-void HandleDiagnosticEvent(const lldb::SBEvent &event, Log *log);
+                 llvm::StringRef client_name, Log &log);
 
 } // namespace lldb_dap
 

lldb/tools/lldb-dap/Transport.cpp

@@ -17,13 +17,13 @@ using namespace lldb_private;
 
 namespace lldb_dap {
 
-Transport::Transport(llvm::StringRef client_name, lldb_dap::Log *log,
-                     lldb::IOObjectSP input, lldb::IOObjectSP output)
-    : HTTPDelimitedJSONTransport(input, output), m_client_name(client_name),
-      m_log(log) {}
+Transport::Transport(lldb_dap::Log &log, lldb::IOObjectSP input,
+                     lldb::IOObjectSP output)
+    : HTTPDelimitedJSONTransport(input, output), m_log(log) {}
 
 void Transport::Log(llvm::StringRef message) {
-  DAP_LOG(m_log, "({0}) {1}", m_client_name, message);
+  // Emit the message directly, since this log was forwarded.
+  m_log.Emit(message);
 }
 
 } // namespace lldb_dap

lldb/tools/lldb-dap/Transport.h

@@ -35,15 +35,14 @@ class Transport final
     : public lldb_private::transport::HTTPDelimitedJSONTransport<
           ProtocolDescriptor> {
 public:
-  Transport(llvm::StringRef client_name, lldb_dap::Log *log,
-            lldb::IOObjectSP input, lldb::IOObjectSP output);
+  Transport(lldb_dap::Log &log, lldb::IOObjectSP input,
+            lldb::IOObjectSP output);
   virtual ~Transport() = default;
 
   void Log(llvm::StringRef message) override;
 
 private:
-  llvm::StringRef m_client_name;
-  lldb_dap::Log *m_log;
+  lldb_dap::Log &m_log;
 };
 
 } // namespace lldb_dap