teemperor created this revision.
teemperor added a reviewer: LLDB.
teemperor added a project: LLDB.
Herald added a subscriber: JDevlieghere.
teemperor requested review of this revision.
LLDB has a quite extensive logging framework that is mostly used to help with
bug reporting where users
are usually requested to attach the generated logs after reproducing a bug
locally.
Right now all logging is done in plain text where usually one line in the text
file equals one log message (but
that is more of a guidelines, there are multiline log messages too).
While the plain text logs are easy to read without any tools, they are often
also really limiting the usefulness
of LLDB's logging framework:
- The plain text logs become hard to read when they are filled out with too
much information. Because of that
we often only request users to enable a small subset of the logging
functionality in LLDB. When later on the
bug is outside one of the initially activated logging channels, we have to go
back to the user and ask them to
recreate the logs with more channels. We also essentially never tell users to
enable other useful parts of the
logging system (such as the automatic stacktraces) for that reason.
- We can't easily write tools that make viewing logs easier. Writing a parser
that extracts the different parts of a
log message from the plain text format is rather difficult.
This patch changes the output format of the log files to JSON. Every log
message is now a serialized JSON object
(that is now also guaranteed to occupy exactly one line) that is just appended
to the log file. For convenience I
also added a trailing comma behind every JSON object so that a log file can
always be turned into a single JSON
object again that by just surrounding it with `[]` and removing the last comma
(for strict parsers).
https://reviews.llvm.org/D107079
Files:
lldb/include/lldb/Utility/Log.h
lldb/packages/Python/lldbsuite/test/lldbutil.py
lldb/source/Utility/Log.cpp
lldb/test/API/api/log/TestAPILog.py
lldb/test/API/lang/cpp/member-and-local-vars-with-same-name/TestMembersAndLocalsWithSameName.py
lldb/unittests/Utility/LogTest.cpp
Index: lldb/unittests/Utility/LogTest.cpp
===================================================================
--- lldb/unittests/Utility/LogTest.cpp
+++ lldb/unittests/Utility/LogTest.cpp
@@ -11,6 +11,7 @@
#include "lldb/Utility/Log.h"
#include "lldb/Utility/StreamString.h"
+#include "llvm/Support/JSON.h"
#include "llvm/Support/ManagedStatic.h"
#include "llvm/Support/Threading.h"
#include <thread>
@@ -82,6 +83,16 @@
llvm::StringRef takeOutput();
llvm::StringRef logAndTakeOutput(llvm::StringRef Message);
+ llvm::json::Object logAndTakeLogObject(llvm::StringRef Message) {
+ llvm::StringRef Out = logAndTakeOutput(Message).trim();
+ EXPECT_TRUE(Out.consume_back(","));
+ llvm::Expected<llvm::json::Value> parsed = llvm::json::parse(Out);
+ EXPECT_TRUE(static_cast<bool>(parsed));
+ llvm::json::Object *parsed_obj = parsed->getAsObject();
+ EXPECT_NE(parsed_obj, nullptr);
+ return *parsed_obj;
+ }
+
public:
void SetUp() override;
};
@@ -211,37 +222,49 @@
TEST_F(LogChannelEnabledTest, log_options) {
std::string Err;
- EXPECT_EQ("Hello World\n", logAndTakeOutput("Hello World"));
+ EXPECT_EQ("{\"message\":\"Hello World\"},\n",
+ logAndTakeOutput("Hello World"));
EXPECT_TRUE(EnableChannel(getStream(), LLDB_LOG_OPTION_THREADSAFE, "chan", {},
Err));
- EXPECT_EQ("Hello World\n", logAndTakeOutput("Hello World"));
+ EXPECT_EQ("{\"message\":\"Hello World\"},\n",
+ logAndTakeOutput("Hello World"));
{
EXPECT_TRUE(EnableChannel(getStream(), LLDB_LOG_OPTION_PREPEND_SEQUENCE,
"chan", {}, Err));
- llvm::StringRef Msg = logAndTakeOutput("Hello World");
- int seq_no;
- EXPECT_EQ(1, sscanf(Msg.str().c_str(), "%d Hello World", &seq_no));
+ llvm::json::Object parsed_obj = logAndTakeLogObject("Hello World");
+ // Check that any sequence-id was added.
+ EXPECT_TRUE(parsed_obj.getInteger("sequence-id"));
}
{
EXPECT_TRUE(EnableChannel(getStream(), LLDB_LOG_OPTION_PREPEND_FILE_FUNCTION,
"chan", {}, Err));
- llvm::StringRef Msg = logAndTakeOutput("Hello World");
- char File[12];
- char Function[17];
-
- sscanf(Msg.str().c_str(), "%[^:]:%s Hello World", File, Function);
- EXPECT_STRCASEEQ("LogTest.cpp", File);
- EXPECT_STREQ("logAndTakeOutput", Function);
+ llvm::json::Object parsed_obj = logAndTakeLogObject("Hello World");
+ // Check that function/file parameters were added.
+ llvm::Optional<llvm::StringRef> function = parsed_obj.getString("function");
+ llvm::Optional<llvm::StringRef> file = parsed_obj.getString("file");
+ EXPECT_TRUE(function.hasValue());
+ EXPECT_TRUE(file.hasValue());
+
+ EXPECT_EQ(*function, "logAndTakeOutput");
+ EXPECT_EQ(*file, "LogTest.cpp");
}
- EXPECT_TRUE(EnableChannel(
- getStream(), LLDB_LOG_OPTION_PREPEND_PROC_AND_THREAD, "chan", {}, Err));
- EXPECT_EQ(llvm::formatv("[{0,0+4}/{1,0+4}] Hello World\n", ::getpid(),
- llvm::get_threadid())
- .str(),
- logAndTakeOutput("Hello World"));
+ {
+ EXPECT_TRUE(EnableChannel(
+ getStream(), LLDB_LOG_OPTION_PREPEND_PROC_AND_THREAD, "chan", {}, Err));
+ llvm::json::Object parsed_obj = logAndTakeLogObject("Hello World");
+
+ // Check that function/file parameters were added.
+ llvm::Optional<int64_t> pid = parsed_obj.getInteger("pid");
+ llvm::Optional<int64_t> tid = parsed_obj.getInteger("tid");
+ EXPECT_TRUE(pid.hasValue());
+ EXPECT_TRUE(tid.hasValue());
+
+ EXPECT_EQ(*pid, static_cast<int64_t>(::getpid()));
+ EXPECT_EQ(*tid, static_cast<int64_t>(llvm::get_threadid()));
+ }
}
TEST_F(LogChannelEnabledTest, LLDB_LOG_ERROR) {
@@ -252,7 +275,7 @@
llvm::make_error<llvm::StringError>(
"My Error", llvm::inconvertibleErrorCode()),
"Foo failed: {0}");
- ASSERT_EQ("Foo failed: My Error\n", takeOutput());
+ ASSERT_EQ("{\"message\":\"Foo failed: My Error\"},\n", takeOutput());
// Doesn't log, but doesn't assert either
LLDB_LOG_ERROR(nullptr,
@@ -274,7 +297,8 @@
// The log thread either managed to write to the log in time, or it didn't. In
// either case, we should not trip any undefined behavior (run the test under
// TSAN to verify this).
- EXPECT_THAT(takeOutput(), testing::AnyOf("", "Hello World\n"));
+ EXPECT_THAT(takeOutput(),
+ testing::AnyOf("", "{\"message\":\"Hello World\"},\n"));
}
TEST_F(LogChannelEnabledTest, LogVerboseThread) {
@@ -292,7 +316,8 @@
// The log thread either managed to write to the log, or it didn't. In either
// case, we should not trip any undefined behavior (run the test under TSAN to
// verify this).
- EXPECT_THAT(takeOutput(), testing::AnyOf("", "Hello World\n"));
+ EXPECT_THAT(takeOutput(),
+ testing::AnyOf("", "{\"message\":\"Hello World\"},\n"));
}
TEST_F(LogChannelEnabledTest, LogGetLogThread) {
Index: lldb/test/API/lang/cpp/member-and-local-vars-with-same-name/TestMembersAndLocalsWithSameName.py
===================================================================
--- lldb/test/API/lang/cpp/member-and-local-vars-with-same-name/TestMembersAndLocalsWithSameName.py
+++ lldb/test/API/lang/cpp/member-and-local-vars-with-same-name/TestMembersAndLocalsWithSameName.py
@@ -275,12 +275,18 @@
if configuration.is_reproducer_replay():
log_file = self.getReproducerRemappedPath(log_file)
self.runCmd("log disable lldb expr")
- local_var_regex = re.compile(r".*__lldb_local_vars::(.*);")
+ local_var_regex = re.compile(r".*__lldb_local_vars::([a-zA-Z0-9_]*);")
matched = []
with open(log_file, 'r') as log:
+ expr_lines = None
for line in log:
- if line.find('LLDB_BODY_START') != -1:
+ print(line)
+ if line.find('$__lldb_expr') != -1:
+ parsed_msg = lldbutil.parse_lldb_log(line)
+ expr_lines = parsed_msg[0]["message"].splitlines()
break
+
+ for line in expr_lines:
m = re.match(local_var_regex, line)
if m:
self.assertIn(m.group(1), variables)
Index: lldb/test/API/api/log/TestAPILog.py
===================================================================
--- lldb/test/API/api/log/TestAPILog.py
+++ lldb/test/API/api/log/TestAPILog.py
@@ -41,9 +41,9 @@
self.assertTrue(debugger_addr, log)
# Make sure the GetScriptingLanguage matches.
- self.assertTrue(re.search(r'lldb::SBDebugger::GetScriptingLanguage\([^)]*\) \(0x{}, ""\)'.format(
+ self.assertTrue(re.search(r'lldb::SBDebugger::GetScriptingLanguage\([^)]*\) \(0x{}, \\"\\"\)'.format(
debugger_addr[0]), log), log)
# Make sure the address matches.
- self.assertTrue(re.search(r'lldb::SBDebugger::CreateTarget\([^)]*\) \(0x{}, ""\)'.format(
+ self.assertTrue(re.search(r'lldb::SBDebugger::CreateTarget\([^)]*\) \(0x{}, \\"\\"\)'.format(
debugger_addr[0]), log), log)
Index: lldb/source/Utility/Log.cpp
===================================================================
--- lldb/source/Utility/Log.cpp
+++ lldb/source/Utility/Log.cpp
@@ -132,14 +132,17 @@
void Log::VAPrintf(const char *format, va_list args) {
llvm::SmallString<64> FinalMessage;
llvm::raw_svector_ostream Stream(FinalMessage);
- WriteHeader(Stream, "", "");
+ llvm::json::OStream J(Stream);
llvm::SmallString<64> Content;
lldb_private::VASprintf(Content, format, args);
- Stream << Content << "\n";
+ J.object([this, &J, &Content] {
+ AddMessageMetaInformation(J, /*file=*/"", /*function=*/"");
+ J.attribute("message", Content);
+ });
- WriteMessage(std::string(FinalMessage.str()));
+ WriteMessage(FinalMessage.str());
}
// Printing of errors that are not fatal.
@@ -277,25 +280,27 @@
return m_options.load(std::memory_order_relaxed) & LLDB_LOG_OPTION_VERBOSE;
}
-void Log::WriteHeader(llvm::raw_ostream &OS, llvm::StringRef file,
- llvm::StringRef function) {
+void Log::AddMessageMetaInformation(llvm::json::OStream &message,
+ llvm::StringRef file,
+ llvm::StringRef function) {
Flags options = GetOptions();
static uint32_t g_sequence_id = 0;
// Add a sequence ID if requested
if (options.Test(LLDB_LOG_OPTION_PREPEND_SEQUENCE))
- OS << ++g_sequence_id << " ";
+ message.attribute("sequence-id", ++g_sequence_id);
// Timestamp if requested
if (options.Test(LLDB_LOG_OPTION_PREPEND_TIMESTAMP)) {
auto now = std::chrono::duration<double>(
std::chrono::system_clock::now().time_since_epoch());
- OS << llvm::formatv("{0:f9} ", now.count());
+ message.attribute("message", llvm::formatv("{0:f9} ", now.count()).str());
}
// Add the process and thread if requested
- if (options.Test(LLDB_LOG_OPTION_PREPEND_PROC_AND_THREAD))
- OS << llvm::formatv("[{0,0+4}/{1,0+4}] ", getpid(),
- llvm::get_threadid());
+ if (options.Test(LLDB_LOG_OPTION_PREPEND_PROC_AND_THREAD)) {
+ message.attribute("pid", static_cast<int64_t>(getpid()));
+ message.attribute("tid", static_cast<int64_t>(llvm::get_threadid()));
+ }
// Add the thread name if requested
if (options.Test(LLDB_LOG_OPTION_PREPEND_THREAD_NAME)) {
@@ -305,35 +310,46 @@
llvm::SmallString<12> format_str;
llvm::raw_svector_ostream format_os(format_str);
format_os << "{0,-" << llvm::alignTo<16>(thread_name.size()) << "} ";
- OS << llvm::formatv(format_str.c_str(), thread_name);
+ message.attribute("thread-name", thread_name);
}
- if (options.Test(LLDB_LOG_OPTION_BACKTRACE))
- llvm::sys::PrintStackTrace(OS);
+ if (options.Test(LLDB_LOG_OPTION_BACKTRACE)) {
+ std::string stacktrace;
+ llvm::raw_string_ostream stacktrace_stream(stacktrace);
+ llvm::sys::PrintStackTrace(stacktrace_stream);
+ stacktrace_stream.flush();
+ message.attribute("stacktrace", stacktrace);
+ }
if (options.Test(LLDB_LOG_OPTION_PREPEND_FILE_FUNCTION) &&
(!file.empty() || !function.empty())) {
- file = llvm::sys::path::filename(file).take_front(40);
- function = function.take_front(40);
- OS << llvm::formatv("{0,-60:60} ", (file + ":" + function).str());
+ message.attribute("file", llvm::sys::path::filename(file));
+ message.attribute("function", function);
}
}
-void Log::WriteMessage(const std::string &message) {
+void Log::WriteMessage(llvm::StringRef json) {
// Make a copy of our stream shared pointer in case someone disables our log
// while we are logging and releases the stream
auto stream_sp = GetStream();
if (!stream_sp)
return;
+ // This is logging a JSON object. Add a trailing comma so that the full log
+ // output can be wrapped inside a JSON array to be one single valid JSON
+ // string. The newline puts every message on its own line which is just to
+ // make the raw JSON easier to read. Also prevents that we run into strange
+ // line limits if the log output gets copy pasted into some UI framework
+ // that then tries to break the one gigantic line in wrapping mode.
+ const llvm::StringRef terminator = ",\n";
Flags options = GetOptions();
if (options.Test(LLDB_LOG_OPTION_THREADSAFE)) {
static std::recursive_mutex g_LogThreadedMutex;
std::lock_guard<std::recursive_mutex> guard(g_LogThreadedMutex);
- *stream_sp << message;
+ *stream_sp << json << terminator;
stream_sp->flush();
} else {
- *stream_sp << message;
+ *stream_sp << json << terminator;
stream_sp->flush();
}
}
@@ -342,8 +358,13 @@
const llvm::formatv_object_base &payload) {
std::string message_string;
llvm::raw_string_ostream message(message_string);
- WriteHeader(message, file, function);
- message << payload << "\n";
+
+ llvm::json::OStream J(message);
+ J.object([this, &J, file, function, &payload] {
+ AddMessageMetaInformation(J, file, function);
+ J.attribute("message", payload.str());
+ });
+
WriteMessage(message.str());
}
Index: lldb/packages/Python/lldbsuite/test/lldbutil.py
===================================================================
--- lldb/packages/Python/lldbsuite/test/lldbutil.py
+++ lldb/packages/Python/lldbsuite/test/lldbutil.py
@@ -9,6 +9,7 @@
# System modules
import errno
+import json
import os
import re
import sys
@@ -99,6 +100,21 @@
return subprocess.check_output(['xcrun', '-sdk', sdk, '-f', 'clang'
]).rstrip().decode("utf-8")
+def parse_lldb_log(log_contents):
+ """ Given a raw LLDB log, parses it as JSON and returns it."""
+ log_contents = log_contents.strip()
+
+ # Remove the trailing comma as that's not allowed in a JSON array.
+ if log_contents.endswith(","):
+ log_contents = log_contents[:-1]
+
+ # Wrap the contents into a top level JSON array.
+ if not log_contents.startswith("["):
+ log_contents = "[" + log_contents
+ if not log_contents.endswith("]"):
+ log_contents = log_contents + "]"
+
+ return json.loads(log_contents)
# ===================================================
# Disassembly for an SBFunction or an SBSymbol object
@@ -1551,13 +1567,19 @@
expect_dylib_info_response = False
for line in logfile:
if expect_dylib_info_response:
- while line[0] != '$':
- line = line[1:]
- line = line[1:]
+ # Extract the full reply from the log.
+ reply = parse_lldb_log(line)[0]["message"]
+ # Payload starts after the first $.
+ while reply[0] != '$':
+ reply = reply[1:]
+ reply = reply[1:]
# Unescape '}'.
- dylib_info = json.loads(line.replace('}]','}')[:-4])
+ reply = reply.replace('}]','}')
+ # Remove the suffix that isn't part of the JSON payload
+ reply = reply[:-3]
+ dylib_info = json.loads(reply)
expect_dylib_info_response = False
- if 'send packet: $jGetLoadedDynamicLibrariesInfos:{"fetch_all_solibs":true}' in line:
+ if 'send packet: $jGetLoadedDynamicLibrariesInfos:{\\"fetch_all_solibs\\":true}' in line:
expect_dylib_info_response = True
return dylib_info
Index: lldb/include/lldb/Utility/Log.h
===================================================================
--- lldb/include/lldb/Utility/Log.h
+++ lldb/include/lldb/Utility/Log.h
@@ -19,6 +19,7 @@
#include "llvm/ADT/StringRef.h"
#include "llvm/Support/Error.h"
#include "llvm/Support/FormatVariadic.h"
+#include "llvm/Support/JSON.h"
#include "llvm/Support/ManagedStatic.h"
#include "llvm/Support/RWMutex.h"
@@ -182,9 +183,18 @@
std::atomic<uint32_t> m_options{0};
std::atomic<uint32_t> m_mask{0};
- void WriteHeader(llvm::raw_ostream &OS, llvm::StringRef file,
- llvm::StringRef function);
- void WriteMessage(const std::string &message);
+ /// Fills out the meta-information of the passed message JSON object.
+ ///
+ /// Meta-information includes things such as the source file/function that
+ /// is trying to write to the log, the current pid/tid and the backtrace.
+ ///
+ /// \param message The message object to fill out.
+ /// \param file The path of the source file with the LLDB_LOG call.
+ /// \param function The name of the function with the LLDB_LOG call.
+ void AddMessageMetaInformation(llvm::json::OStream &message,
+ llvm::StringRef file,
+ llvm::StringRef function);
+ void WriteMessage(llvm::StringRef message);
void Format(llvm::StringRef file, llvm::StringRef function,
const llvm::formatv_object_base &payload);
_______________________________________________
lldb-commits mailing list
lldb-commits@lists.llvm.org
https://lists.llvm.org/cgi-bin/mailman/listinfo/lldb-commits
