[lldb-dap] Updating the logging of lldb-dap to use existing LLDBLog. #129294
Conversation
… helpers. This only creates the basic types need to start using the LLDBLog.h helpers. Today, logging is handling by a simple `std::ofstream *` for handling logging. LLDBLog.h can help improve logging by adding new categories of logs and give us additional formatting support for log messages.
ashgti
force-pushed
the
lldb-dap-logging
branch
from
71f82c8 to
8d466e5
Compare
|
@llvm/pr-subscribers-lldb Author: John Harrison (ashgti) ChangesToday, logging is handling by a simple LLDBLog.h can help improve logging by adding new categories of logs and give us additional formatting support for log messages. We link against the libHost, which includes lldbUtility. This also simplifies logging by not requiring the Full diff: https://github.com/llvm/llvm-project/pull/129294.diff 9 Files Affected:
diff --git a/lldb/tools/lldb-dap/CMakeLists.txt b/lldb/tools/lldb-dap/CMakeLists.txt
index 8b3c520ec4360..d9f09f6d022ed 100644
--- a/lldb/tools/lldb-dap/CMakeLists.txt
+++ b/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
diff --git a/lldb/tools/lldb-dap/DAP.cpp b/lldb/tools/lldb-dap/DAP.cpp
index 53c514b790f38..81f5205d4f6bd 100644
--- a/lldb/tools/lldb-dap/DAP.cpp
+++ b/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"
@@ -19,6 +20,7 @@
#include "lldb/API/SBProcess.h"
#include "lldb/API/SBStream.h"
#include "lldb/Utility/IOObject.h"
+#include "lldb/Utility/Log.h"
#include "lldb/Utility/Status.h"
#include "lldb/lldb-defines.h"
#include "lldb/lldb-enumerations.h"
@@ -50,6 +52,7 @@
#endif
using namespace lldb_dap;
+using namespace lldb_private;
namespace {
#ifdef _WIN32
@@ -61,13 +64,12 @@ const char DEV_NULL[] = "/dev/null";
namespace lldb_dap {
-DAP::DAP(std::string name, llvm::StringRef path, std::ofstream *log,
- lldb::IOObjectSP input, lldb::IOObjectSP output, ReplMode repl_mode,
+DAP::DAP(std::string name, llvm::StringRef path, 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),
- input(std::move(input)), output(std::move(output)),
- broadcaster("lldb-dap"), exception_breakpoints(),
- pre_init_commands(std::move(pre_init_commands)),
+ : name(std::move(name)), debug_adapter_path(path), input(std::move(input)),
+ output(std::move(output)), broadcaster("lldb-dap"),
+ exception_breakpoints(), pre_init_commands(std::move(pre_init_commands)),
focus_tid(LLDB_INVALID_THREAD_ID), stop_at_entry(false), is_attach(false),
enable_auto_variable_summaries(false),
enable_synthetic_child_debugging(false),
@@ -245,6 +247,8 @@ void DAP::SendJSON(const std::string &json_str) {
output.write_full(llvm::utostr(json_str.size()));
output.write_full("\r\n\r\n");
output.write_full(json_str);
+
+ LLDB_LOG(GetLog(DAPLog::Transport), "{0} <-- {1}", name, json_str);
}
// Serialize the JSON value into a string and send the JSON packet to
@@ -256,15 +260,6 @@ void DAP::SendJSON(const llvm::json::Value &json) {
static std::mutex mutex;
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;
- }
}
// Read a JSON packet from the "in" stream.
@@ -273,28 +268,22 @@ std::string DAP::ReadJSON() {
std::string json_str;
int length;
- if (!input.read_expected(log, "Content-Length: "))
+ if (!input.read_expected("Content-Length: "))
return json_str;
- if (!input.read_line(log, length_str))
+ if (!input.read_line(length_str))
return json_str;
if (!llvm::to_integer(length_str, length))
return json_str;
- if (!input.read_expected(log, "\r\n"))
+ if (!input.read_expected("\r\n"))
return json_str;
- if (!input.read_full(log, length, json_str))
+ if (!input.read_full(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";
- }
+ LLDB_LOG(GetLog(DAPLog::Transport), "{0} --> {1}", name, json_str);
return json_str;
}
@@ -729,24 +718,14 @@ PacketStatus DAP::GetNextObject(llvm::json::Object &object) {
llvm::Expected<llvm::json::Value> json_value = llvm::json::parse(json_sref);
if (!json_value) {
auto error = json_value.takeError();
- if (log) {
- std::string error_str;
- llvm::raw_string_ostream strm(error_str);
- strm << error;
- *log << "error: failed to parse JSON: " << error_str << std::endl
- << json << std::endl;
- }
+ LLDB_LOG_ERROR(GetLog(DAPLog::Protocol), std::move(error),
+ "failed to parse JSON: {0}");
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;
+ LLDB_LOG(GetLog(DAPLog::Protocol), "error: json packet isn't a object");
return PacketStatus::JSONNotObject;
}
object = *object_ptr;
@@ -764,9 +743,8 @@ bool DAP::HandleObject(const llvm::json::Object &object) {
return true; // Success
}
- if (log)
- *log << "error: unhandled command \"" << command.data() << "\""
- << std::endl;
+ LLDB_LOG(GetLog(DAPLog::Protocol), "error: unhandled command '{0}'",
+ command);
return false; // Fail
}
diff --git a/lldb/tools/lldb-dap/DAP.h b/lldb/tools/lldb-dap/DAP.h
index 8b2e498a28c95..ea5e17eb5d95f 100644
--- a/lldb/tools/lldb-dap/DAP.h
+++ b/lldb/tools/lldb-dap/DAP.h
@@ -125,21 +125,21 @@ struct Variables {
struct StartDebuggingRequestHandler : public lldb::SBCommandPluginInterface {
DAP &dap;
- explicit StartDebuggingRequestHandler(DAP &d) : dap(d) {};
+ explicit StartDebuggingRequestHandler(DAP &d) : dap(d){};
bool DoExecute(lldb::SBDebugger debugger, char **command,
lldb::SBCommandReturnObject &result) override;
};
struct ReplModeRequestHandler : public lldb::SBCommandPluginInterface {
DAP &dap;
- explicit ReplModeRequestHandler(DAP &d) : dap(d) {};
+ explicit ReplModeRequestHandler(DAP &d) : dap(d){};
bool DoExecute(lldb::SBDebugger debugger, char **command,
lldb::SBCommandReturnObject &result) override;
};
struct SendEventRequestHandler : public lldb::SBCommandPluginInterface {
DAP &dap;
- explicit SendEventRequestHandler(DAP &d) : dap(d) {};
+ explicit SendEventRequestHandler(DAP &d) : dap(d){};
bool DoExecute(lldb::SBDebugger debugger, char **command,
lldb::SBCommandReturnObject &result) override;
};
@@ -147,7 +147,6 @@ struct SendEventRequestHandler : public lldb::SBCommandPluginInterface {
struct DAP {
std::string name;
llvm::StringRef debug_adapter_path;
- std::ofstream *log;
InputStream input;
OutputStream output;
lldb::SBFile in;
@@ -210,8 +209,8 @@ struct DAP {
// will contain that expression.
std::string last_nonempty_var_expression;
- DAP(std::string name, llvm::StringRef path, std::ofstream *log,
- lldb::IOObjectSP input, lldb::IOObjectSP output, ReplMode repl_mode,
+ DAP(std::string name, llvm::StringRef path, lldb::IOObjectSP input,
+ lldb::IOObjectSP output, ReplMode repl_mode,
std::vector<std::string> pre_init_commands);
~DAP();
DAP(const DAP &rhs) = delete;
diff --git a/lldb/tools/lldb-dap/DAPLog.cpp b/lldb/tools/lldb-dap/DAPLog.cpp
new file mode 100644
index 0000000000000..840e995b14af8
--- /dev/null
+++ b/lldb/tools/lldb-dap/DAPLog.cpp
@@ -0,0 +1,22 @@
+#include "DAPLog.h"
+
+using namespace lldb_private;
+using namespace lldb_dap;
+
+static constexpr Log::Category g_categories[] = {
+ {{"transport"}, {"log DAP transport"}, DAPLog::Transport},
+ {{"protocol"}, {"log protocol handling"}, DAPLog::Protocol},
+ {{"connection"}, {"log connection handling"}, DAPLog::Connection},
+};
+
+static Log::Channel g_log_channel(g_categories, DAPLog::Transport |
+ DAPLog::Protocol |
+ DAPLog::Connection);
+
+template <> Log::Channel &lldb_private::LogChannelFor<DAPLog>() {
+ return g_log_channel;
+}
+
+void lldb_dap::InitializeDAPChannel() {
+ Log::Register("lldb-dap", g_log_channel);
+}
diff --git a/lldb/tools/lldb-dap/DAPLog.h b/lldb/tools/lldb-dap/DAPLog.h
new file mode 100644
index 0000000000000..49be7602b2c88
--- /dev/null
+++ b/lldb/tools/lldb-dap/DAPLog.h
@@ -0,0 +1,34 @@
+//===-- DAPLog.h ------------------------------------------------*- C++ -*-===//
+//
+// 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_UTILITY_LLDBLOG_H
+#define LLDB_UTILITY_LLDBLOG_H
+
+#include "lldb/Utility/Log.h"
+#include "llvm/ADT/BitmaskEnum.h"
+
+namespace lldb_dap {
+
+enum class DAPLog : lldb_private::Log::MaskType {
+ Transport = lldb_private::Log::ChannelFlag<0>,
+ Protocol = lldb_private::Log::ChannelFlag<1>,
+ Connection = lldb_private::Log::ChannelFlag<2>,
+ LLVM_MARK_AS_BITMASK_ENUM(Connection),
+};
+
+LLVM_ENABLE_BITMASK_ENUMS_IN_NAMESPACE();
+
+void InitializeDAPChannel();
+
+} // end namespace lldb_dap
+
+namespace lldb_private {
+template <> lldb_private::Log::Channel &LogChannelFor<lldb_dap::DAPLog>();
+} // namespace lldb_private
+
+#endif
diff --git a/lldb/tools/lldb-dap/EventHelper.cpp b/lldb/tools/lldb-dap/EventHelper.cpp
index 705eb0a457d9c..299d8f8a482ac 100644
--- a/lldb/tools/lldb-dap/EventHelper.cpp
+++ b/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"
@@ -21,6 +22,9 @@
#endif
#endif
+using namespace lldb_dap;
+using namespace lldb_private;
+
namespace lldb_dap {
static void SendThreadExitedEvent(DAP &dap, lldb::tid_t tid) {
@@ -178,15 +182,14 @@ 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;
+ LLDB_LOG(GetLog(DAPLog::Protocol),
+ "error: SendThreadStoppedEvent() when process"
+ " isn't stopped ({0})",
+ lldb::SBDebugger::StateAsCString(state));
}
} else {
- if (dap.log)
- *dap.log << "error: SendThreadStoppedEvent() invalid process"
- << std::endl;
+ LLDB_LOG(GetLog(DAPLog::Protocol),
+ "error: SendThreadStoppedEvent() invalid process");
}
dap.RunStopCommands();
}
diff --git a/lldb/tools/lldb-dap/IOStream.cpp b/lldb/tools/lldb-dap/IOStream.cpp
index c6f1bfaf3b799..0e93ce8111891 100644
--- a/lldb/tools/lldb-dap/IOStream.cpp
+++ b/lldb/tools/lldb-dap/IOStream.cpp
@@ -7,12 +7,13 @@
//===----------------------------------------------------------------------===//
#include "IOStream.h"
+#include "DAPLog.h"
#include "lldb/Utility/IOObject.h"
#include "lldb/Utility/Status.h"
-#include <fstream>
#include <string>
using namespace lldb_dap;
+using namespace lldb_private;
bool OutputStream::write_full(llvm::StringRef str) {
if (!descriptor)
@@ -23,8 +24,7 @@ bool OutputStream::write_full(llvm::StringRef str) {
return status.Success();
}
-bool InputStream::read_full(std::ofstream *log, size_t length,
- std::string &text) {
+bool InputStream::read_full(size_t length, std::string &text) {
if (!descriptor)
return false;
@@ -39,10 +39,10 @@ bool InputStream::read_full(std::ofstream *log, size_t length,
return true;
}
-bool InputStream::read_line(std::ofstream *log, std::string &line) {
+bool InputStream::read_line(std::string &line) {
line.clear();
while (true) {
- if (!read_full(log, 1, line))
+ if (!read_full(1, line))
return false;
if (llvm::StringRef(line).ends_with("\r\n"))
@@ -52,14 +52,13 @@ bool InputStream::read_line(std::ofstream *log, std::string &line) {
return true;
}
-bool InputStream::read_expected(std::ofstream *log, llvm::StringRef expected) {
+bool InputStream::read_expected(llvm::StringRef expected) {
std::string result;
- if (!read_full(log, expected.size(), result))
+ if (!read_full(expected.size(), result))
return false;
if (expected != result) {
- if (log)
- *log << "Warning: Expected '" << expected.str() << "', got '" << result
- << "\n";
+ LLDB_LOG(GetLog(DAPLog::Transport), "Warning: Expected '{0}', got '{1}'",
+ expected, result);
}
return true;
}
diff --git a/lldb/tools/lldb-dap/IOStream.h b/lldb/tools/lldb-dap/IOStream.h
index e9fb8e11c92da..c90fee57d0479 100644
--- a/lldb/tools/lldb-dap/IOStream.h
+++ b/lldb/tools/lldb-dap/IOStream.h
@@ -11,7 +11,6 @@
#include "lldb/lldb-forward.h"
#include "llvm/ADT/StringRef.h"
-#include <fstream>
#include <string>
namespace lldb_dap {
@@ -22,11 +21,11 @@ struct InputStream {
explicit InputStream(lldb::IOObjectSP descriptor)
: descriptor(std::move(descriptor)) {}
- bool read_full(std::ofstream *log, size_t length, std::string &text);
+ bool read_full(size_t length, std::string &text);
- bool read_line(std::ofstream *log, std::string &line);
+ bool read_line(std::string &line);
- bool read_expected(std::ofstream *log, llvm::StringRef expected);
+ bool read_expected(llvm::StringRef expected);
};
struct OutputStream {
diff --git a/lldb/tools/lldb-dap/lldb-dap.cpp b/lldb/tools/lldb-dap/lldb-dap.cpp
index d005eccfae903..2c337edc86b89 100644
--- a/lldb/tools/lldb-dap/lldb-dap.cpp
+++ b/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"
@@ -71,13 +72,7 @@ typedef int socklen_t;
#endif
using namespace lldb_dap;
-using lldb_private::File;
-using lldb_private::IOObject;
-using lldb_private::MainLoop;
-using lldb_private::MainLoopBase;
-using lldb_private::NativeFile;
-using lldb_private::Socket;
-using lldb_private::Status;
+using namespace lldb_private;
namespace {
using namespace llvm::opt;
@@ -277,8 +272,7 @@ validateConnection(llvm::StringRef conn) {
static llvm::Error
serveConnection(const Socket::SocketProtocol &protocol, const std::string &name,
- std::ofstream *log, llvm::StringRef program_path,
- const ReplMode default_repl_mode,
+ llvm::StringRef program_path, const ReplMode default_repl_mode,
const std::vector<std::string> &pre_init_commands) {
Status status;
static std::unique_ptr<Socket> listener = Socket::Create(protocol, status);
@@ -292,8 +286,8 @@ 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";
+ LLDB_LOG(GetLog(DAPLog::Connection), "started with connection listeners {0}",
+ address);
llvm::outs() << "Listening for: " << address << "\n";
// Ensure listening address are flushed for calles to retrieve the resolve
@@ -314,12 +308,7 @@ serveConnection(const Socket::SocketProtocol &protocol, const std::string &name,
&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";
- }
+ LLDB_LOG(GetLog(DAPLog::Connection), "client ({0}) connected", name);
lldb::IOObjectSP io(std::move(sock));
@@ -328,8 +317,8 @@ serveConnection(const Socket::SocketProtocol &protocol, const std::string &name,
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,
- pre_init_commands);
+ DAP dap =
+ DAP(name, program_path, io, io, default_repl_mode, pre_init_commands);
if (auto Err = dap.ConfigureIO()) {
llvm::logAllUnhandledErrors(std::move(Err), llvm::errs(),
@@ -349,12 +338,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";
- }
+ LLDB_LOG(GetLog(DAPLog::Connection), "client ({0}) closed", name);
std::unique_lock<std::mutex> lock(dap_sessions_mutex);
dap_sessions.erase(io.get());
@@ -372,9 +356,8 @@ serveConnection(const Socket::SocketProtocol &protocol, const std::string &name,
return status.takeError();
}
- if (log)
- *log << "lldb-dap server shutdown requested, disconnecting remaining "
- "clients...\n";
+ LLDB_LOG(GetLog(DAPLog::Connection),
+ "shutdown requested, disconnecting remaining clients");
bool client_failed = false;
{
@@ -402,6 +385,22 @@ serveConnection(const Socket::SocketProtocol &protocol, const std::string &name,
return llvm::Error::success();
}
+class DAPLogHandler : public lldb_private::LogHandler {
+public:
+ DAPLogHandler(std::unique_ptr<std::ofstream> stream)
+ : m_stream(std::move(stream)) {}
+
+ void Emit(llvm::StringRef message) override {
+ std::lock_guard<std::mutex> guard(m_mutex);
+ (*m_stream) << message.str();
+ m_stream->flush();
+ }
+
+private:
+ std::mutex m_mutex;
+ std::unique_ptr<std::ofstream> m_stream;
+};
+
int main(int argc, char *argv[]) {
llvm::InitLLVM IL(argc, argv, /*InstallPipeSignalExitHandler=*/false);
#if !defined(__APPLE__)
@@ -490,10 +489,20 @@ int main(int argc, char *argv[]) {
}
#endif
- std::unique_ptr<std::ofstream> log = nullptr;
+ InitializeDAPChannel();
+
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::unique_ptr<std::ofstream> log =
+ std::make_unique<std::ofstream>(log_file_path);
+
+ if (!lldb_private::Log::EnableLogChannel(
+ std::make_shared<DAPLogHandler>(std::move(log)),
+ LLDB_LOG_OPTION_PREPEND_TIMESTAMP, "lldb-dap", {"all"},
+ llvm::errs())) {
+ return EXIT_FAILURE;
+ }
+ }
// Initialize LLDB first before we do anything.
lldb::SBError error = lldb::SBDebugger::InitializeWithErrorHandling();
@@ -525,7 +534,7 @@ int main(int argc, char *argv[]) {
Socket::SocketProtocol protocol;
std::string name;
std::tie(protocol, name) = *maybeProtoclAndName;
- if (auto Err = serveConnection(protocol, name, log.get(), program_path,
+ if (auto Err = serveConnection(protocol, name, program_path,
default_repl_mode, pre_init_commands)) {
llvm::logAllUnhandledErrors(std::move(Err), llvm::errs(),
"Connection failed: ");
@@ -559,7 +568,7 @@ int main(int argc, char *argv[]) {
lldb::IOObjectSP output = std::make_shared<NativeFile>(
stdout_fd, File::eOpenOptionWriteOnly, false);
- DAP dap = DAP("stdin/stdout", program_path, log.get(), std::move(input),
+ DAP dap = DAP("stdin/stdout", program_path, std::move(input),
std::move(output), default_repl_mode, pre_init_commands);
// stdout/stderr redirection to the IDE's console
|
|
✅ With the latest revision this PR passed the C/C++ code formatter. |
ashgti
force-pushed
the
lldb-dap-logging
branch
from
240d523 to
133ca86
Compare
|
Also, for reference, this does change the output format. Is an example of what things look like with this change. Before this was formatted like: So its more compact now since we don't include the full protocol encoding header ("Content-Length: {size}\r\n\r\n"). |
lldb/tools/lldb-dap/EventHelper.cpp
Outdated
| LLDB_LOG(GetLog(DAPLog::Protocol), | ||
| "error: SendThreadStoppedEvent() when process" | ||
| " isn't stopped ({0})", | ||
| lldb::SBDebugger::StateAsCString(state)); | ||
| } | ||
| } else { | ||
| if (dap.log) | ||
| *dap.log << "error: SendThreadStoppedEvent() invalid process" | ||
| << std::endl; | ||
| LLDB_LOG(GetLog(DAPLog::Protocol), | ||
| "error: SendThreadStoppedEvent() invalid process"); |
There was a problem hiding this comment.
Do those two messages really fit into the "protocol" log category? I thought they would rather be "internal assertion failures" / "programming bugs inside lldb-dap"?
There was a problem hiding this comment.
I wasn't sure of a better name, but they do represent a kind of internal error where we're not in the expected state. This helper is meant to send the 'stopped' event and if the process isn't stopped, then there is something wrong with how we're implementing the protocol. But I'm open to suggestions on a better name.
There was a problem hiding this comment.
I guess having this under protocol is fine after all 🤷
Maybe we should add something like "This should never happen. Please file a bug report." to the message, though to make it clear that this should actually be unreachable?
| } | ||
|
|
||
| void lldb_dap::InitializeDAPChannel() { | ||
| Log::Register("lldb-dap", g_log_channel); |
There was a problem hiding this comment.
does this mean, I could now run log enable lldb-dap connection from the lldb-dap console, and get the log messages directly printed to my VS-Code debug console? That would be pretty neat 🎉
But... What would happen if I run log enable lldb-dap protocol? Afaict, this would lead to an endless cycle of:
- lldb-dap receives a
stackTracecommand - as part of receiving this
stackTracecommand, we will be writing to theProtocollog (seeDAP::ReadJSON()) - because logging for this channel is enabled, we try to send the log message to the debug client via an
outputevent - but this attempt to send the log-information goes through
DAP::sendJSONwhich will also writing to theProtocollog - which in turn will trigger another
outputevent - which will again go through
DAP::sendJSON - which in turn will trigger another
outputevent - which will again go through
DAP::sendJSON - and so on...
Is this something we can / should guard against?
There was a problem hiding this comment.
I tried to see if I could guard against this and heres some things I noticed. With the default (~ish) build flags, lldb-dap actually doesn't show up with the log list command. This is due to the log helper having static linking and the liblldb.(so,dylib,dll) not exporting that symbol. If you build with -DLLDB_EXPORT_ALL_SYMBOLS=ON then it will show up. If you do enable this in that configuration it does very quickly cause problems for the process and it will recursively trigger logging statements.
I made this a verbose log to help make this less likely to happen, although that doesn't truly prevent it from happening. But also, I think this is not as likely to come up with release builds because they tend to use the exported symbol list to only export some symbols from liblldb.(so,dylib,dll).
There was a problem hiding this comment.
the log helper having static linking and the liblldb.(so,dylib,dll) not exporting that symbol.
I wonder whether that is a feature or a bug. Should the log helper be exported by liblldb.{so,dylib,dll}, to allow extensions / host-binaries to add their own log channels?
There was a problem hiding this comment.
Maybe given the limitations of the lldb/Utility/Log.h I should make a different abstraction that improves logging instead, what do you think?
There was a problem hiding this comment.
except for this particular issue here, I think the lldb logging framework is exactly what we want.
We get a lot of functionality (filtering, writing to files, ...) for free, and will be able to benefit from future enhancements.
My preferred solution would be:
- export the log helper from
liblldb.(so,dylib,dll), such thatlog enable lldb-dap ...works - break the logging cycle: All events sent as part of outputting a log event, should suppress creating additional log events
(1) would be straightforward to implement. If we agree that this is the right direction, I would like to address this right away.
For (2), we could easily add a suppressLog to void SendOutput(OutputType o, const llvm::StringRef output, bool suppressLog = false) and to SendJSON. But, afaik, log messages are simply written to stdout and we currently can't distinguish log messages from stdout outputs. What would it take to extend LLDB's logging framework with a capability to write log messages via a customizable output function instead of to stdout? If it turns out to be too hard, I would also be fine with the current solution, i.e. having the potential cyclical log messages marked as verbose, and postpone a more principled fix until later.
All in all, I am out of my depth here, though. I would like to hear what others think about it. CC @labath @JDevlieghere @walter-erquinigo
There was a problem hiding this comment.
But, afaik, log messages are simply written to stdout and we currently can't distinguish log messages from stdout outputs. What would it take to extend LLDB's logging framework with a capability to write log messages via a customizable output function instead of to stdout?
Actually... it seems that such a mechanism already exists. We could probably use SBDebugger::SetLoggingCallback to write all log output using SendOutput(..., /*supressLog*/ true), thereby breaking the logging cycle.
One downside is that after calling SBDebugger::SetLoggingCallback some options like log enable ... --file mylog.txt no longer work. See Debugger::EnableLog: if (m_callback_handler_sp) { takes precedence over all other options and ignores, e.g., the file name. I think this might be a bug in Debugger::EnableLog. I think Debugger::EnableLog should only use m_callback_handler_sp, if neither --file nor --log-handler was specified.
Then we could also go back to marking the SendJSON log messages as non-verbose
There was a problem hiding this comment.
(1) seems really like a beautiful idea. Currently we have to set some environment variables to have lldb-dap output its logs to a file, which is not great. It would be great if we can simply plug into the regular logger framework, just like the gdb-remote logs do.
(2) Another alternative for this is to enable this only when writing logs to a text file. This would require some encapsulation for logging within lldb-dap, but it wouldn't be a bad idea. A default text file could also be used, as LLDB has a default logging folder set somewhere in the code. I thnk it writes to ~/.lldb.
Something similar, but not exactly the same, happens when you do lldb log enable all in the terminal, which causes that upon every keystroke you see lots of logs and then you lose track of what you were writing. In this case sending the logs to a text file is pretty much the only effectively way to use this logging configuration.
I can't find a good solution for the case in which we write the logs to the IDE, because blocking logging at some depth in the logging stack seems potentially error-prone or confusing? I'd rather keep this simple and not allow it in the IDE case.
There was a problem hiding this comment.
I think given this issue and some other issues related to using the LLDBLog API I think I may not go forward with this patch and revisit at a later date. I think lldb-dap could use some improvements to logging, instead of just passing a std::ofstream * around, but I am not sure this is the best approach, also see #129294 (comment)
| output.write_full("\r\n\r\n"); | ||
| output.write_full(json_str); | ||
|
|
||
| LLDB_LOGV(GetLog(DAPLog::Transport), "{0} <-- {1}", name, json_str); |
There was a problem hiding this comment.
should the Transport messages also include the client name? Otherwise, we will have a hard time understanding the logs if we have multiple clients connected
There was a problem hiding this comment.
that could be said for pretty much every log coming from lldb-dap.
It wouldn'be a bad idea to have some new macros like DAP_LOGV that also receive a DAP instance and append the client name in the message
There was a problem hiding this comment.
Another thought that I have is that in an ideal world it would be nice to a logging category per client, so that you could do something like lldb log enable lldb-dap transport my-client-1, which would only enable logging for this specific client. You could potentially write to a different log file per client.
Anyway, maybe this is not needed by anyone yet, but just leaving this idea here for posterity.
|
The more I think about it, the less I like the idea of using I think if we want to do this right, we have two options, and they're both pretty drastic:
There is of course the third option which is designing a dedicated logging framework for |
I think I also ran into this issue when using some of the Host types in lldb-dap where we had two different 'global' instances of a value due to the static linking. Specifically this was the in the
At Google, we do actually do this to support building lldb-dap at head with the LLDB.framework linked from Xcode. This is a pretty specific use case because we are doing that so we can support mobile devices. And every once in a while when lldb-dap uses a new SB API that isn't in the internally supported Xcode release I end up writing either a back port or a fallback implementation.
I think there are some improvements we could make to the logging incrementally, instead of just passing a Thinking about these issues, I agree that we may not want to use the LLDBLog api and instead maybe we can make some incremental improvements to the existing system instead. I may revisit this after I get my other patch in to refactor the IOStream into a Transport abstraction and then I had two other follow ups for better type handling and cancel request support. For now I think I'll just close this PR. |
Today, logging is handling by a simple
std::ofstream *for handling logging.LLDBLog.h can help improve logging by adding new categories of logs and give us additional formatting support for log messages. We link against the libHost, which includes lldbUtility. This also simplifies logging by not requiring the
std::ofstream *pointer being passed to every function that includes logging.