diff --git a/lldb/include/lldb/Utility/Log.h b/lldb/include/lldb/Utility/Log.h index 9da33f5f39562..73b9764508cbf 100644 --- a/lldb/include/lldb/Utility/Log.h +++ b/lldb/include/lldb/Utility/Log.h @@ -31,6 +31,9 @@ namespace llvm { class raw_ostream; +namespace json { +class Object; +} } // Logging Options #define LLDB_LOG_OPTION_VERBOSE (1u << 1) @@ -41,6 +44,7 @@ class raw_ostream; #define LLDB_LOG_OPTION_BACKTRACE (1U << 7) #define LLDB_LOG_OPTION_APPEND (1U << 8) #define LLDB_LOG_OPTION_PREPEND_FILE_FUNCTION (1U << 9) +#define LLDB_LOG_OPTION_JSON (1U << 10) // Logging Functions namespace lldb_private { @@ -288,7 +292,11 @@ class Log final { void WriteHeader(llvm::raw_ostream &OS, llvm::StringRef file, llvm::StringRef function); + void WriteJSONHeader(llvm::json::Object &obj, llvm::StringRef file, + llvm::StringRef function); void WriteMessage(llvm::StringRef message); + void EmitJSONMessage(llvm::StringRef file, llvm::StringRef function, + llvm::StringRef message); void Format(llvm::StringRef file, llvm::StringRef function, const llvm::formatv_object_base &payload); diff --git a/lldb/source/Commands/CommandObjectLog.cpp b/lldb/source/Commands/CommandObjectLog.cpp index e51a85e9f0308..945dc6210bfea 100644 --- a/lldb/source/Commands/CommandObjectLog.cpp +++ b/lldb/source/Commands/CommandObjectLog.cpp @@ -129,6 +129,9 @@ class CommandObjectLogEnable : public CommandObjectParsed { case 'F': log_options |= LLDB_LOG_OPTION_PREPEND_FILE_FUNCTION; break; + case 'j': + log_options |= LLDB_LOG_OPTION_JSON; + break; default: llvm_unreachable("Unimplemented option"); } diff --git a/lldb/source/Commands/Options.td b/lldb/source/Commands/Options.td index 1f525c07f852a..f118f219f5ec1 100644 --- a/lldb/source/Commands/Options.td +++ b/lldb/source/Commands/Options.td @@ -915,6 +915,9 @@ let Command = "log enable" in { : Option<"file-function", "F">, Group<1>, Desc<"Prepend the names of files and function that generate the logs.">; + def log_json : Option<"json", "j">, + Group<1>, + Desc<"Emit each log message as its own JSON object.">; } let Command = "log dump" in { diff --git a/lldb/source/Utility/Log.cpp b/lldb/source/Utility/Log.cpp index 6b077a3766e9f..09b4eb05f2edd 100644 --- a/lldb/source/Utility/Log.cpp +++ b/lldb/source/Utility/Log.cpp @@ -15,6 +15,7 @@ #include "llvm/Support/Casting.h" #include "llvm/Support/Chrono.h" +#include "llvm/Support/JSON.h" #include "llvm/Support/ManagedStatic.h" #include "llvm/Support/Path.h" #include "llvm/Support/Signals.h" @@ -47,6 +48,10 @@ llvm::ManagedStatic Log::g_channel_map; // LLDB_LOG_ERROR is not enabled, error messages are logged to the error log. static std::atomic g_error_log = nullptr; +// Shared sequence counter used by both the text and JSON header writers so +// sequence numbers stay consistent regardless of output format. +static uint32_t g_sequence_id = 0; + void Log::ForEachCategory( const Log::ChannelMap::value_type &entry, llvm::function_ref lambda) { @@ -145,6 +150,10 @@ Log::MaskType Log::GetMask() const { void Log::PutCString(const char *cstr) { PutString(cstr); } void Log::PutString(llvm::StringRef str) { + if (GetOptions().Test(LLDB_LOG_OPTION_JSON)) { + EmitJSONMessage("", "", str); + return; + } std::string FinalMessage; llvm::raw_string_ostream Stream(FinalMessage); WriteHeader(Stream, "", ""); @@ -304,7 +313,6 @@ bool Log::GetVerbose() const { void Log::WriteHeader(llvm::raw_ostream &OS, 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 << " "; @@ -343,6 +351,45 @@ void Log::WriteHeader(llvm::raw_ostream &OS, llvm::StringRef file, } } +void Log::WriteJSONHeader(llvm::json::Object &obj, llvm::StringRef file, + llvm::StringRef function) { + Flags options = GetOptions(); + if (options.Test(LLDB_LOG_OPTION_PREPEND_SEQUENCE)) + obj["sequence"] = ++g_sequence_id; + + if (options.Test(LLDB_LOG_OPTION_PREPEND_TIMESTAMP)) { + auto now = std::chrono::duration( + std::chrono::system_clock::now().time_since_epoch()); + obj["timestamp"] = now.count(); + } + + if (options.Test(LLDB_LOG_OPTION_PREPEND_PROC_AND_THREAD)) { + obj["pid"] = static_cast(getpid()); + obj["tid"] = static_cast(llvm::get_threadid()); + } + + if (options.Test(LLDB_LOG_OPTION_PREPEND_THREAD_NAME)) { + llvm::SmallString<32> thread_name; + llvm::get_thread_name(thread_name); + // Value(StringRef) stores by reference; copy into a std::string so the + // Value owns the data and we don't dangle once `thread_name` goes away. + obj["thread_name"] = std::string(thread_name); + } + + if (options.Test(LLDB_LOG_OPTION_BACKTRACE)) { + std::string backtrace; + llvm::raw_string_ostream backtrace_os(backtrace); + llvm::sys::PrintStackTrace(backtrace_os); + obj["backtrace"] = std::move(backtrace); + } + + if (options.Test(LLDB_LOG_OPTION_PREPEND_FILE_FUNCTION) && + (!file.empty() || !function.empty())) { + obj["file"] = llvm::sys::path::filename(file); + obj["function"] = function; + } +} + // If we have a callback registered, then we call the logging callback. If we // have a valid file handle, we also log to the file. void Log::WriteMessage(llvm::StringRef message) { @@ -356,6 +403,10 @@ void Log::WriteMessage(llvm::StringRef message) { void Log::Format(llvm::StringRef file, llvm::StringRef function, const llvm::formatv_object_base &payload) { + if (GetOptions().Test(LLDB_LOG_OPTION_JSON)) { + EmitJSONMessage(file, function, payload.str()); + return; + } std::string message_string; llvm::raw_string_ostream message(message_string); WriteHeader(message, file, function); @@ -363,6 +414,17 @@ void Log::Format(llvm::StringRef file, llvm::StringRef function, WriteMessage(message_string); } +void Log::EmitJSONMessage(llvm::StringRef file, llvm::StringRef function, + llvm::StringRef message) { + llvm::json::Object obj; + WriteJSONHeader(obj, file, function); + obj["message"] = message; + std::string out; + llvm::raw_string_ostream os(out); + os << llvm::json::Value(std::move(obj)) << "\n"; + WriteMessage(out); +} + StreamLogHandler::StreamLogHandler(int fd, bool should_close, size_t buffer_size) : m_stream(fd, should_close, buffer_size == 0) { diff --git a/lldb/test/API/commands/log/basic/TestLogging.py b/lldb/test/API/commands/log/basic/TestLogging.py index daa32dc85753d..eacf8d83390f7 100644 --- a/lldb/test/API/commands/log/basic/TestLogging.py +++ b/lldb/test/API/commands/log/basic/TestLogging.py @@ -4,6 +4,7 @@ import os +import json import lldb from lldbsuite.test.decorators import * from lldbsuite.test.lldbtest import * @@ -94,3 +95,32 @@ def test_all_log_options(self): self.runCmd("log disable lldb") self.assertTrue(os.path.isfile(self.log_file)) + + # Check that -j produces a valid JSONL log file where every line is a JSON + # object and the requested metadata flags surface as JSON fields rather + # than line prefixes. + def test_json_output(self): + if os.path.exists(self.log_file): + os.remove(self.log_file) + + self.runCmd("log enable -j -s -T -p -F -f '%s' lldb commands" % self.log_file) + self.runCmd("help log") + self.runCmd("log disable lldb") + + self.assertTrue(os.path.isfile(self.log_file)) + with open(self.log_file, "r") as f: + lines = f.readlines() + + self.assertGreater(len(lines), 0, "log file should not be empty") + for line in lines: + # Every line must parse as JSON on its own. + obj = json.loads(line) + self.assertIsInstance(obj, dict) + self.assertIn("message", obj) + # The flags we passed must turn into JSON fields. + self.assertIn("sequence", obj) + self.assertIn("timestamp", obj) + self.assertIn("pid", obj) + self.assertIn("tid", obj) + self.assertIn("file", obj) + self.assertIn("function", obj) diff --git a/lldb/unittests/Utility/LogTest.cpp b/lldb/unittests/Utility/LogTest.cpp index 602d019adac54..fed0a5274b948 100644 --- a/lldb/unittests/Utility/LogTest.cpp +++ b/lldb/unittests/Utility/LogTest.cpp @@ -12,6 +12,7 @@ #include "lldb/Utility/Log.h" #include "lldb/Utility/StreamString.h" #include "llvm/ADT/BitmaskEnum.h" +#include "llvm/Support/JSON.h" #include "llvm/Support/ManagedStatic.h" #include "llvm/Support/Threading.h" #include @@ -335,6 +336,51 @@ TEST_F(LogChannelEnabledTest, log_options) { logAndTakeOutput("Hello World")); } +TEST_F(LogChannelEnabledTest, JSONLOutput) { + std::string Err; + + // With JSON, every line must parse as JSON and contain exactly the message we + // logged. + EXPECT_TRUE(EnableChannel( + getLogHandler(), /*log_options=*/LLDB_LOG_OPTION_JSON, "chan", {}, Err)); + llvm::StringRef Msg = logAndTakeOutput("Hello \"World\"\nsecond line"); + ASSERT_TRUE(Msg.ends_with("\n")); + ASSERT_EQ(Msg.count('\n'), 1u) << "expected one JSON object per line"; + llvm::Expected Parsed = llvm::json::parse(Msg); + ASSERT_TRUE(static_cast(Parsed)) << llvm::toString(Parsed.takeError()); + llvm::json::Object *Obj = Parsed->getAsObject(); + ASSERT_NE(Obj, nullptr); + EXPECT_EQ(Obj->getString("message").value_or(""), + "Hello \"World\"\nsecond line"); + EXPECT_EQ(Obj->size(), 1u); + + // Combining JSON with metadata flags: each metadata flag becomes a JSON + // field instead of a prefix on the line. + uint32_t Opts = LLDB_LOG_OPTION_JSON | LLDB_LOG_OPTION_PREPEND_SEQUENCE | + LLDB_LOG_OPTION_PREPEND_TIMESTAMP | + LLDB_LOG_OPTION_PREPEND_PROC_AND_THREAD | + LLDB_LOG_OPTION_PREPEND_THREAD_NAME | + LLDB_LOG_OPTION_BACKTRACE | + LLDB_LOG_OPTION_PREPEND_FILE_FUNCTION; + EXPECT_TRUE(EnableChannel(getLogHandler(), Opts, "chan", {}, Err)); + Msg = logAndTakeOutput("payload"); + Parsed = llvm::json::parse(Msg); + ASSERT_TRUE(static_cast(Parsed)) << llvm::toString(Parsed.takeError()); + Obj = Parsed->getAsObject(); + ASSERT_NE(Obj, nullptr); + EXPECT_EQ(Obj->getString("message").value_or(""), "payload"); + EXPECT_TRUE(Obj->getInteger("sequence").has_value()); + EXPECT_TRUE(Obj->getNumber("timestamp").has_value()); + EXPECT_EQ(Obj->getInteger("pid").value_or(-1), + static_cast(::getpid())); + EXPECT_EQ(Obj->getInteger("tid").value_or(-1), + static_cast(llvm::get_threadid())); + EXPECT_TRUE(Obj->getString("thread_name").has_value()); + EXPECT_TRUE(Obj->getString("backtrace").has_value()); + EXPECT_EQ(Obj->getString("file").value_or(""), "LogTest.cpp"); + EXPECT_EQ(Obj->getString("function").value_or(""), "logAndTakeOutput"); +} + TEST_F(LogChannelEnabledTest, LLDB_LOG_ERROR) { LLDB_LOG_ERROR(getLog(), llvm::Error::success(), "Foo failed: {0}"); ASSERT_EQ("", takeOutput());