Skip to content

[lldb-dap] Updating the logging of lldb-dap to use existing LLDBLog. #129294

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Closed
wants to merge 5 commits into from
Closed

[lldb-dap] Updating the logging of lldb-dap to use existing LLDBLog. #129294

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
5 commits
Select commit Hold shift + click to select a range
8d466e5
[lldb-dap] Updating the logging of lldb-dap to use existing LLDBLog.h…
ashgti Feb 27, 2025
2ddb7a5
Applying formatting.
ashgti Feb 28, 2025
133ca86
Fixing the comment and include guard
ashgti Feb 28, 2025
1b896fb
Adjusting the transport logs to be 'verbose' to make it less likely f…
ashgti Mar 3, 2025
aca9129
Adjusting logging statements.
ashgti Mar 3, 2025
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
1 change: 1 addition & 0 deletions lldb/tools/lldb-dap/CMakeLists.txt
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -23,6 +23,7 @@ add_lldb_tool(lldb-dap
Breakpoint.cpp
BreakpointBase.cpp
DAP.cpp
DAPLog.cpp
EventHelper.cpp
ExceptionBreakpoint.cpp
FifoFiles.cpp
Expand Down
62 changes: 20 additions & 42 deletions lldb/tools/lldb-dap/DAP.cpp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -7,6 +7,7 @@
//===----------------------------------------------------------------------===//

#include "DAP.h"
#include "DAPLog.h"
#include "Handler/ResponseHandler.h"
#include "JSONUtils.h"
#include "LLDBUtils.h"
Expand All @@ -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"
Expand Down Expand Up @@ -50,6 +52,7 @@
#endif

using namespace lldb_dap;
using namespace lldb_private;

namespace {
#ifdef _WIN32
Expand All @@ -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),
Expand Down Expand Up @@ -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_LOGV(GetLog(DAPLog::Transport), "{0} <-- {1}", name, json_str);
Copy link
Member

@vogelsgesang vogelsgesang Mar 4, 2025

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

Copy link
Member

@walter-erquinigo walter-erquinigo Mar 4, 2025

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

Copy link
Member

@walter-erquinigo walter-erquinigo Mar 4, 2025

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

}

// Serialize the JSON value into a string and send the JSON packet to
Expand All @@ -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.
Expand All @@ -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_LOGV(GetLog(DAPLog::Transport), "{0} --> {1}", name, json_str);
return json_str;
}

Expand Down Expand Up @@ -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;
Expand All @@ -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
}

Expand Down
5 changes: 2 additions & 3 deletions lldb/tools/lldb-dap/DAP.h
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down Expand Up @@ -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;
Expand Down
30 changes: 30 additions & 0 deletions lldb/tools/lldb-dap/DAPLog.cpp
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -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"

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);
Copy link
Member

@vogelsgesang vogelsgesang Mar 1, 2025 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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:

  1. lldb-dap receives a stackTrace command
  2. as part of receiving this stackTrace command, we will be writing to the Protocol log (see DAP::ReadJSON())
  3. because logging for this channel is enabled, we try to send the log message to the debug client via an output event
  4. but this attempt to send the log-information goes through DAP::sendJSON which will also writing to the Protocol log
  5. which in turn will trigger another output event
  6. which will again go through DAP::sendJSON
  7. which in turn will trigger another output event
  8. which will again go through DAP::sendJSON
  9. and so on...

Is this something we can / should guard against?

Copy link
Contributor Author

@ashgti ashgti Mar 3, 2025

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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).

Copy link
Member

@vogelsgesang vogelsgesang Mar 3, 2025

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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?

Copy link
Contributor Author

@ashgti ashgti Mar 4, 2025

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Maybe given the limitations of the lldb/Utility/Log.h I should make a different abstraction that improves logging instead, what do you think?

Copy link
Member

@vogelsgesang vogelsgesang Mar 4, 2025 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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:

  1. export the log helper from liblldb.(so,dylib,dll), such that log enable lldb-dap ... works
  2. 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

Copy link
Member

@vogelsgesang vogelsgesang Mar 4, 2025 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

Copy link
Member

@walter-erquinigo walter-erquinigo Mar 4, 2025

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

(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.

Copy link
Contributor Author

@ashgti ashgti Mar 5, 2025

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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)

}
34 changes: 34 additions & 0 deletions lldb/tools/lldb-dap/DAPLog.h
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -0,0 +1,34 @@
//===-- 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 "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
136 changes: 70 additions & 66 deletions lldb/tools/lldb-dap/EventHelper.cpp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -8,6 +8,7 @@

#include "EventHelper.h"
#include "DAP.h"
#include "DAPLog.h"
#include "JSONUtils.h"
#include "LLDBUtils.h"
#include "lldb/API/SBFileSpec.h"
Expand All @@ -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) {
Expand Down Expand Up @@ -117,76 +121,76 @@ void SendProcessEvent(DAP &dap, LaunchMethod launch_method) {
// is stopped.
void SendThreadStoppedEvent(DAP &dap) {
lldb::SBProcess process = dap.target.GetProcess();
if (process.IsValid()) {
auto state = process.GetState();
if (state == lldb::eStateStopped) {
llvm::DenseSet<lldb::tid_t> old_thread_ids;
old_thread_ids.swap(dap.thread_ids);
uint32_t stop_id = process.GetStopID();
const uint32_t num_threads = process.GetNumThreads();

// First make a pass through the threads to see if the focused thread
// has a stop reason. In case the focus thread doesn't have a stop
// reason, remember the first thread that has a stop reason so we can
// set it as the focus thread if below if needed.
lldb::tid_t first_tid_with_reason = LLDB_INVALID_THREAD_ID;
uint32_t num_threads_with_reason = 0;
bool focus_thread_exists = false;
for (uint32_t thread_idx = 0; thread_idx < num_threads; ++thread_idx) {
lldb::SBThread thread = process.GetThreadAtIndex(thread_idx);
const lldb::tid_t tid = thread.GetThreadID();
const bool has_reason = ThreadHasStopReason(thread);
// If the focus thread doesn't have a stop reason, clear the thread ID
if (tid == dap.focus_tid) {
focus_thread_exists = true;
if (!has_reason)
dap.focus_tid = LLDB_INVALID_THREAD_ID;
}
if (has_reason) {
++num_threads_with_reason;
if (first_tid_with_reason == LLDB_INVALID_THREAD_ID)
first_tid_with_reason = tid;
}
}
if (!process.IsValid()) {
LLDB_LOG(GetLog(DAPLog::Protocol),
"error: SendThreadStoppedEvent() invalid process");
return;
}

// We will have cleared dap.focus_tid if the focus thread doesn't have
// a stop reason, so if it was cleared, or wasn't set, or doesn't exist,
// then set the focus thread to the first thread with a stop reason.
if (!focus_thread_exists || dap.focus_tid == LLDB_INVALID_THREAD_ID)
dap.focus_tid = first_tid_with_reason;

// If no threads stopped with a reason, then report the first one so
// we at least let the UI know we stopped.
if (num_threads_with_reason == 0) {
lldb::SBThread thread = process.GetThreadAtIndex(0);
dap.focus_tid = thread.GetThreadID();
dap.SendJSON(CreateThreadStopped(dap, thread, stop_id));
} else {
for (uint32_t thread_idx = 0; thread_idx < num_threads; ++thread_idx) {
lldb::SBThread thread = process.GetThreadAtIndex(thread_idx);
dap.thread_ids.insert(thread.GetThreadID());
if (ThreadHasStopReason(thread)) {
dap.SendJSON(CreateThreadStopped(dap, thread, stop_id));
}
}
}
auto state = process.GetState();
if (state != lldb::eStateStopped) {
LLDB_LOG(GetLog(DAPLog::Protocol),
"error: SendThreadStoppedEvent() when process isn't stopped ({0})",
lldb::SBDebugger::StateAsCString(state));
return;
}

for (auto tid : old_thread_ids) {
auto end = dap.thread_ids.end();
auto pos = dap.thread_ids.find(tid);
if (pos == end)
SendThreadExitedEvent(dap, tid);
}
} else {
if (dap.log)
*dap.log << "error: SendThreadStoppedEvent() when process"
" isn't stopped ("
<< lldb::SBDebugger::StateAsCString(state) << ')' << std::endl;
llvm::DenseSet<lldb::tid_t> old_thread_ids;
old_thread_ids.swap(dap.thread_ids);
uint32_t stop_id = process.GetStopID();
const uint32_t num_threads = process.GetNumThreads();

// First make a pass through the threads to see if the focused thread
// has a stop reason. In case the focus thread doesn't have a stop
// reason, remember the first thread that has a stop reason so we can
// set it as the focus thread if below if needed.
lldb::tid_t first_tid_with_reason = LLDB_INVALID_THREAD_ID;
uint32_t num_threads_with_reason = 0;
bool focus_thread_exists = false;
for (uint32_t thread_idx = 0; thread_idx < num_threads; ++thread_idx) {
lldb::SBThread thread = process.GetThreadAtIndex(thread_idx);
const lldb::tid_t tid = thread.GetThreadID();
const bool has_reason = ThreadHasStopReason(thread);
// If the focus thread doesn't have a stop reason, clear the thread ID
if (tid == dap.focus_tid) {
focus_thread_exists = true;
if (!has_reason)
dap.focus_tid = LLDB_INVALID_THREAD_ID;
}
if (has_reason) {
++num_threads_with_reason;
if (first_tid_with_reason == LLDB_INVALID_THREAD_ID)
first_tid_with_reason = tid;
}
}

// We will have cleared dap.focus_tid if the focus thread doesn't have
// a stop reason, so if it was cleared, or wasn't set, or doesn't exist,
// then set the focus thread to the first thread with a stop reason.
if (!focus_thread_exists || dap.focus_tid == LLDB_INVALID_THREAD_ID)
dap.focus_tid = first_tid_with_reason;

// If no threads stopped with a reason, then report the first one so
// we at least let the UI know we stopped.
if (num_threads_with_reason == 0) {
lldb::SBThread thread = process.GetThreadAtIndex(0);
dap.focus_tid = thread.GetThreadID();
dap.SendJSON(CreateThreadStopped(dap, thread, stop_id));
} else {
if (dap.log)
*dap.log << "error: SendThreadStoppedEvent() invalid process"
<< std::endl;
for (uint32_t thread_idx = 0; thread_idx < num_threads; ++thread_idx) {
lldb::SBThread thread = process.GetThreadAtIndex(thread_idx);
dap.thread_ids.insert(thread.GetThreadID());
if (ThreadHasStopReason(thread)) {
dap.SendJSON(CreateThreadStopped(dap, thread, stop_id));
}
}
}

for (auto tid : old_thread_ids) {
auto end = dap.thread_ids.end();
auto pos = dap.thread_ids.find(tid);
if (pos == end)
SendThreadExitedEvent(dap, tid);
}
dap.RunStopCommands();
}
Expand Down
Loading