[lldb-dap] Adding logging helpers. (#130653)

Improving logging by defining new helpers for more uniform log handling.
This should help us clearly identify log messages and helps abstract the
underlying log type within the macro in case we want to update the log
handler in the future.

Author: ashgti

lldb/tools/lldb-dap/DAP.cpp

@@ -7,6 +7,7 @@
 //===----------------------------------------------------------------------===//
 
 #include "DAP.h"
+#include "DAPLog.h"
 #include "Handler/ResponseHandler.h"
 #include "JSONUtils.h"
 #include "LLDBUtils.h"
@@ -25,6 +26,7 @@
 #include "llvm/ADT/ArrayRef.h"
 #include "llvm/ADT/ScopeExit.h"
 #include "llvm/ADT/StringExtras.h"
+#include "llvm/ADT/StringRef.h"
 #include "llvm/ADT/Twine.h"
 #include "llvm/Support/Error.h"
 #include "llvm/Support/ErrorHandling.h"
@@ -61,10 +63,10 @@ const char DEV_NULL[] = "/dev/null";
 
 namespace lldb_dap {
 
-DAP::DAP(std::string name, llvm::StringRef path, std::ofstream *log,
+DAP::DAP(llvm::StringRef client_name, llvm::StringRef path, std::ofstream *log,
          lldb::IOObjectSP input, lldb::IOObjectSP output, ReplMode repl_mode,
          std::vector<std::string> pre_init_commands)
-    : name(std::move(name)), debug_adapter_path(path), log(log),
+    : client_name(client_name), debug_adapter_path(path), log(log),
       input(std::move(input)), output(std::move(output)),
       broadcaster("lldb-dap"), exception_breakpoints(),
       pre_init_commands(std::move(pre_init_commands)),
@@ -239,14 +241,7 @@ void DAP::SendJSON(const llvm::json::Value &json) {
   std::lock_guard<std::mutex> locker(mutex);
   SendJSON(json_str);
 
-  if (log) {
-    auto now = std::chrono::duration<double>(
-        std::chrono::system_clock::now().time_since_epoch());
-    *log << llvm::formatv("{0:f9} {1} <-- ", now.count(), name).str()
-         << std::endl
-         << "Content-Length: " << json_str.size() << "\r\n\r\n"
-         << llvm::formatv("{0:2}", json).str() << std::endl;
-  }
+  DAP_LOG(log, "({0}) <-- {1}", client_name, json_str);
 }
 
 // Read a JSON packet from the "in" stream.
@@ -270,13 +265,7 @@ std::string DAP::ReadJSON() {
   if (!input.read_full(log, length, json_str))
     return json_str;
 
-  if (log) {
-    auto now = std::chrono::duration<double>(
-        std::chrono::system_clock::now().time_since_epoch());
-    *log << llvm::formatv("{0:f9} {1} --> ", now.count(), name).str()
-         << std::endl
-         << "Content-Length: " << length << "\r\n\r\n";
-  }
+  DAP_LOG(log, "({0}) --> {1}", client_name, json_str);
   return json_str;
 }
 
@@ -711,22 +700,15 @@ PacketStatus DAP::GetNextObject(llvm::json::Object &object) {
 
   llvm::StringRef json_sref(json);
   llvm::Expected<llvm::json::Value> json_value = llvm::json::parse(json_sref);
-  if (auto error = json_value.takeError()) {
-    std::string error_str = llvm::toString(std::move(error));
-    if (log)
-      *log << "error: failed to parse JSON: " << error_str << std::endl
-           << json << std::endl;
+  if (!json_value) {
+    DAP_LOG_ERROR(log, json_value.takeError(),
+                  "({1}) failed to parse JSON: {0}", client_name);
     return PacketStatus::JSONMalformed;
   }
 
-  if (log) {
-    *log << llvm::formatv("{0:2}", *json_value).str() << std::endl;
-  }
-
   llvm::json::Object *object_ptr = json_value->getAsObject();
   if (!object_ptr) {
-    if (log)
-      *log << "error: json packet isn't a object" << std::endl;
+    DAP_LOG(log, "({0}) error: json packet isn't a object", client_name);
     return PacketStatus::JSONNotObject;
   }
   object = *object_ptr;
@@ -744,9 +726,7 @@ bool DAP::HandleObject(const llvm::json::Object &object) {
       return true; // Success
     }
 
-    if (log)
-      *log << "error: unhandled command \"" << command.data() << "\""
-           << std::endl;
+    DAP_LOG(log, "({0}) error: unhandled command '{1}'", client_name, command);
     return false; // Fail
   }
 

lldb/tools/lldb-dap/DAP.h

@@ -145,7 +145,7 @@ struct SendEventRequestHandler : public lldb::SBCommandPluginInterface {
 };
 
 struct DAP {
-  std::string name;
+  llvm::StringRef client_name;
   llvm::StringRef debug_adapter_path;
   std::ofstream *log;
   InputStream input;
@@ -210,7 +210,7 @@ struct DAP {
   // will contain that expression.
   std::string last_nonempty_var_expression;
 
-  DAP(std::string name, llvm::StringRef path, std::ofstream *log,
+  DAP(llvm::StringRef client_name, llvm::StringRef path, std::ofstream *log,
       lldb::IOObjectSP input, lldb::IOObjectSP output, ReplMode repl_mode,
       std::vector<std::string> pre_init_commands);
   ~DAP();

lldb/tools/lldb-dap/DAPLog.h

@@ -0,0 +1,58 @@
+//===-- DAPLog.h ----------------------------------------------------------===//
+//
+// 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
+//
+//===----------------------------------------------------------------------===//
+
+#ifndef LLDB_TOOLS_LLDB_DAP_DAPLOG_H
+#define LLDB_TOOLS_LLDB_DAP_DAPLOG_H
+
+#include "llvm/Support/Error.h"
+#include "llvm/Support/FormatAdapters.h"
+#include "llvm/Support/FormatVariadic.h"
+#include <chrono>
+#include <fstream>
+#include <string>
+
+// Write a message to log, if logging is enabled.
+#define DAP_LOG(log, ...)                                                      \
+  do {                                                                         \
+    ::std::ofstream *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;         \
+    }                                                                          \
+  } 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);                                      \
+    ::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;                                               \
+    } else                                                                     \
+      ::llvm::consumeError(::std::move(error_private));                        \
+  } while (0)
+
+namespace lldb_dap {
+
+template <typename... Args>
+inline auto FormatError(llvm::Error error, const char *format, Args &&...args) {
+  return llvm::formatv(format, llvm::toString(std::move(error)),
+                       std::forward<Args>(args)...)
+      .str();
+}
+} // namespace lldb_dap
+
+#endif

lldb/tools/lldb-dap/Handler/InitializeRequestHandler.cpp

@@ -111,7 +111,7 @@ void ProgressEventThreadFunction(DAP &dap) {
 // them prevent multiple threads from writing simultaneously so no locking
 // is required.
 static void EventThreadFunction(DAP &dap) {
-  llvm::set_thread_name(dap.name + ".event_handler");
+  llvm::set_thread_name(dap.client_name + ".event_handler");
   lldb::SBEvent event;
   lldb::SBListener listener = dap.debugger.GetListener();
   dap.broadcaster.AddListener(listener, eBroadcastBitStopEventThread);

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

@@ -7,6 +7,7 @@
 //===----------------------------------------------------------------------===//
 
 #include "DAP.h"
+#include "DAPLog.h"
 #include "EventHelper.h"
 #include "Handler/RequestHandler.h"
 #include "RunInTerminal.h"
@@ -294,8 +295,7 @@ serveConnection(const Socket::SocketProtocol &protocol, const std::string &name,
   }
 
   std::string address = llvm::join(listener->GetListeningConnectionURI(), ", ");
-  if (log)
-    *log << "started with connection listeners " << address << "\n";
+  DAP_LOG(log, "started with connection listeners {0}", address);
 
   llvm::outs() << "Listening for: " << address << "\n";
   // Ensure listening address are flushed for calles to retrieve the resolve
@@ -315,22 +315,17 @@ serveConnection(const Socket::SocketProtocol &protocol, const std::string &name,
                                           &dap_sessions_mutex, &dap_sessions,
                                           &clientCount](
                                              std::unique_ptr<Socket> sock) {
-    std::string name = llvm::formatv("client_{0}", clientCount++).str();
-    if (log) {
-      auto now = std::chrono::duration<double>(
-          std::chrono::system_clock::now().time_since_epoch());
-      *log << llvm::formatv("{0:f9}", now.count()).str()
-           << " client connected: " << name << "\n";
-    }
+    std::string client_name = llvm::formatv("client_{0}", clientCount++).str();
+    DAP_LOG(log, "({0}) client connected", client_name);
 
     lldb::IOObjectSP io(std::move(sock));
 
     // Move the client into a background thread to unblock accepting the next
     // client.
     std::thread client([=, &dap_sessions_condition, &dap_sessions_mutex,
                         &dap_sessions]() {
-      llvm::set_thread_name(name + ".runloop");
-      DAP dap = DAP(name, program_path, log, io, io, default_repl_mode,
+      llvm::set_thread_name(client_name + ".runloop");
+      DAP dap = DAP(client_name, program_path, log, io, io, default_repl_mode,
                     pre_init_commands);
 
       if (auto Err = dap.ConfigureIO()) {
@@ -351,13 +346,7 @@ serveConnection(const Socket::SocketProtocol &protocol, const std::string &name,
                                     "DAP session error: ");
       }
 
-      if (log) {
-        auto now = std::chrono::duration<double>(
-            std::chrono::system_clock::now().time_since_epoch());
-        *log << llvm::formatv("{0:f9}", now.count()).str()
-             << " client closed: " << name << "\n";
-      }
-
+      DAP_LOG(log, "({0}) client disconnected", client_name);
       std::unique_lock<std::mutex> lock(dap_sessions_mutex);
       dap_sessions.erase(io.get());
       std::notify_all_at_thread_exit(dap_sessions_condition, std::move(lock));
@@ -374,9 +363,9 @@ serveConnection(const Socket::SocketProtocol &protocol, const std::string &name,
     return status.takeError();
   }
 
-  if (log)
-    *log << "lldb-dap server shutdown requested, disconnecting remaining "
-            "clients...\n";
+  DAP_LOG(
+      log,
+      "lldb-dap server shutdown requested, disconnecting remaining clients...");
 
   bool client_failed = false;
   {
@@ -385,7 +374,7 @@ serveConnection(const Socket::SocketProtocol &protocol, const std::string &name,
       auto error = dap->Disconnect();
       if (error.Fail()) {
         client_failed = true;
-        llvm::errs() << "DAP client " << dap->name
+        llvm::errs() << "DAP client " << dap->client_name
                      << " disconnected failed: " << error.GetCString() << "\n";
       }
       // Close the socket to ensure the DAP::Loop read finishes.