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 m_options{0}; std::atomic 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); 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/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( 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(getpid())); + message.attribute("tid", static_cast(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 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/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/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/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 @@ -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 parsed = llvm::json::parse(Out); + EXPECT_TRUE(static_cast(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 function = parsed_obj.getString("function"); + llvm::Optional 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 pid = parsed_obj.getInteger("pid"); + llvm::Optional tid = parsed_obj.getInteger("tid"); + EXPECT_TRUE(pid.hasValue()); + EXPECT_TRUE(tid.hasValue()); + + EXPECT_EQ(*pid, static_cast(::getpid())); + EXPECT_EQ(*tid, static_cast(llvm::get_threadid())); + } } TEST_F(LogChannelEnabledTest, LLDB_LOG_ERROR) { @@ -252,7 +275,7 @@ llvm::make_error( "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) {