Index: lldb/docs/design/logging.rst =================================================================== --- /dev/null +++ lldb/docs/design/logging.rst @@ -0,0 +1,99 @@ +Logging +======= + +LLDB can create logs that describe events occuring during a debug session. These +logs are intended to be used as an aid when trying to understand LLDB's +behaviour from a developer perspective. Users are usually not expected to +enable or read logs. + +LLDB's logging framework organizes logs into channels each identified by +a name (e.g., ``lldb``, ```dwarf```, etc.). Each channel is further divided +into several categories which are also identified by a name (e.g., the``api`` +category in the ``lldb`` channel is used to log information about SB API calls). + +Each log message is associated with a specific category in a specific channel. +A message is only emitted when their respective category is enabled. + +There are two ways to enable and disable logging in lldb. The ``log`` +command offers the ``enable`` and ``disable`` subcommands which take a channel +and a list of categories to enable/disable. From the SB API the +`SBDebugger.EnableLog` function can also be used to enable a log channel and +category. + +LLDB allows configuring format that log messages are emitted in and what +metainformation should be attached to each log message. These options can +be set for each logging channel (but not separately for each logging category). +The output of each channel can also be directed to write to a log file, +to the standard output of the LLDB process or a logging callback specified +by the user (when using `SBDebugger.EnableLog`). + +Supported log formats in LLDB are plain text and JSON. The metainformation +that can be added to log messages includes timestamps, LLDB's own pid, or the +backtraces of where the log message was generated. See the options of the +``log enable`` command for a full list of ways to configure a logging channel. + +JSON log format +--------------- + +While the plain text log format is intended to be human-readable, the JSON +log format is only intended to be read by other programs. These other programs +can post-process the log files to filter them or present them in a more +sophisticated way such as a table. + +The JSON log format used by LLDB to log messages is not expected to change, but +it is also not guaranteed to be stable across LLDB releases. Users should not +rely on the format to be stable. + +The current JSON log format puts each log message in its own JSON object. Each +object also contains a trailing comma character (``,``). The intended way of +parsing a JSON log file is strip the last trailing comma character and then +surround the whole contents with brackets (``[]``). This way the list of +JSON objects printed by LLDB will form one single top-level JSON array object +that a normal JSON parser can parse. The listing below contains an example log +file in the JSON format. + +:: + + {"timestamp":24028401.002, "message":"A log message"}, + {"timestamp":24028401.004, "message":"Another log message"}, + + +Each JSON message object can contain several fields. The only mandatory field +in a message object is the ``message`` field. All other fields are optional +and are only created when the respective option in their logging channel is +set. + +.. list-table:: JSON message fields + :header-rows: 1 + :widths: 1 1 10 + + * - Field name + - JavaScript Type + - Description + * - ``message`` + - String + - The log message itself. + * - ``sequence-id`` + - Number + - A number uniquely identifying a log message within one debugging session. + * - ``timestamp`` + - Number + - The number of seconds since the host systems epoch (usually UNIX time). + * - ``pid`` + - Number + - The process id of the LLDB process itself. + * - ``tid`` + - Number + - The thread id of the thread in the LLDB process that generated the log message. + * - ``thread-name`` + - String + - The host specific name of the thread that generated the log message. + * - ``stacktrace`` + - String + - A textual representation of the stacktrace to where the log message was generated from. + * - ``function`` + - String + - The name of the function within the log message is generated. + * - ``file`` + - String + - The path to the LLDB source file where the log message is generated. Index: lldb/docs/index.rst =================================================================== --- lldb/docs/index.rst +++ lldb/docs/index.rst @@ -160,6 +160,7 @@ design/overview design/reproducers design/sbapi + design/logging .. toctree:: :hidden: Index: lldb/include/lldb/Interpreter/CommandCompletions.h =================================================================== --- lldb/include/lldb/Interpreter/CommandCompletions.h +++ lldb/include/lldb/Interpreter/CommandCompletions.h @@ -50,6 +50,7 @@ eRemoteDiskFileCompletion = (1u << 22), eRemoteDiskDirectoryCompletion = (1u << 23), eTypeCategoryNameCompletion = (1u << 24), + eLogFormatCompletion = (1u << 25), // This item serves two purposes. It is the last element in the enum, so // you can add custom enums starting from here in your Option class. Also // if you & in this bit the base code will not process the option. @@ -151,6 +152,10 @@ static void TypeCategoryNames(CommandInterpreter &interpreter, CompletionRequest &request, SearchFilter *searcher); + + /// Completes LLDB log format names. + static void LogFormats(CommandInterpreter &interpreter, + CompletionRequest &request, SearchFilter *searcher); }; } // namespace lldb_private 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" @@ -55,6 +56,23 @@ uint32_t flag; }; + /// The format used when emitting log messages. + enum class OutputFormat { + /// Log messages are printed as plain text. + Plain, + /// Log messages are printed as JSON objects. + JSON, + }; + + typedef llvm::StringMap OutputFormatMapping; + /// Returns the mapping from format names to their \b OutputFormat value. + static OutputFormatMapping GetOutputFormatNameMapping() { + return { + {"plain", OutputFormat::Plain}, + {"json", OutputFormat::JSON}, + }; + } + // This class describes a log channel. It also encapsulates the behavior // necessary to enable a log channel in an atomic manner. class Channel { @@ -110,6 +128,16 @@ llvm::ArrayRef categories, llvm::raw_ostream &error_stream); + /// Sets the log format for the specified channel. + /// + /// \param channel A string identifying the channel name such as 'lldb'. + /// \param format The log format that the channel should have. + /// \param error_stream On error, contains an error that should be displayed + /// to the user. + /// \return True iff the channel format was set successfully. + static bool SetLogChannelFormat(llvm::StringRef channel, OutputFormat format, + llvm::raw_ostream &error_stream); + static bool ListChannelCategories(llvm::StringRef channel, llvm::raw_ostream &stream); @@ -179,12 +207,12 @@ llvm::sys::RWMutex m_mutex; std::shared_ptr m_stream_sp; + /// Log output format of the current channel. + std::atomic m_output_format = {OutputFormat::Plain}; 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); + void WriteMessage(llvm::StringRef message); void Format(llvm::StringRef file, llvm::StringRef function, const llvm::formatv_object_base &payload); Index: lldb/include/lldb/lldb-enumerations.h =================================================================== --- lldb/include/lldb/lldb-enumerations.h +++ lldb/include/lldb/lldb-enumerations.h @@ -547,6 +547,7 @@ eArgTypeLineNum, eArgTypeLogCategory, eArgTypeLogChannel, + eArgTypeLogFormat, eArgTypeMethod, eArgTypeName, eArgTypeNewPathPrefix, Index: lldb/source/Commands/CommandCompletions.cpp =================================================================== --- lldb/source/Commands/CommandCompletions.cpp +++ lldb/source/Commands/CommandCompletions.cpp @@ -78,6 +78,7 @@ {eRemoteDiskDirectoryCompletion, CommandCompletions::RemoteDiskDirectories}, {eTypeCategoryNameCompletion, CommandCompletions::TypeCategoryNames}, + {eLogFormatCompletion, CommandCompletions::LogFormats}, {eNoCompletion, nullptr} // This one has to be last in the list. }; @@ -792,3 +793,10 @@ return true; }); } + +void CommandCompletions::LogFormats(CommandInterpreter &, + CompletionRequest &request, + SearchFilter *) { + for (const auto &key_value : Log::GetOutputFormatNameMapping()) + request.TryCompleteCurrentArg(key_value.first()); +} Index: lldb/source/Commands/CommandObjectLog.cpp =================================================================== --- lldb/source/Commands/CommandObjectLog.cpp +++ lldb/source/Commands/CommandObjectLog.cpp @@ -117,6 +117,16 @@ case 'F': log_options |= LLDB_LOG_OPTION_PREPEND_FILE_FUNCTION; break; + case 'O': { + Log::OutputFormatMapping mapping = Log::GetOutputFormatNameMapping(); + auto found_format = mapping.find(option_arg); + if (found_format == mapping.end()) { + error.SetErrorString("Unknown log format: " + option_arg.str()); + break; + } + log_format = found_format->second; + break; + } default: llvm_unreachable("Unimplemented option"); } @@ -127,6 +137,7 @@ void OptionParsingStarting(ExecutionContext *execution_context) override { log_file.Clear(); log_options = 0; + log_format = Log::OutputFormat::Plain; } llvm::ArrayRef GetDefinitions() override { @@ -137,6 +148,7 @@ FileSpec log_file; uint32_t log_options = 0; + Log::OutputFormat log_format = Log::OutputFormat::Plain; }; void @@ -168,6 +180,10 @@ bool success = GetDebugger().EnableLog(channel, args.GetArgumentArrayRef(), log_file, m_options.log_options, error_stream); + if (success) + success |= + Log::SetLogChannelFormat(channel, m_options.log_format, error_stream); + result.GetErrorStream() << error_stream.str(); if (success) Index: lldb/source/Commands/Options.td =================================================================== --- lldb/source/Commands/Options.td +++ lldb/source/Commands/Options.td @@ -443,6 +443,8 @@ Desc<"Append to the log file instead of overwriting.">; def log_file_function : Option<"file-function", "F">, Group<1>, Desc<"Prepend the names of files and function that generate the logs.">; + def log_format : Option<"format", "O">, Group<1>, Arg<"LogFormat">, + Desc<"Specify the used log format for the enabled channels.">; } let Command = "reproducer dump" in { Index: lldb/source/Interpreter/CommandObject.cpp =================================================================== --- lldb/source/Interpreter/CommandObject.cpp +++ lldb/source/Interpreter/CommandObject.cpp @@ -1069,6 +1069,7 @@ { eArgTypeFileLineColumn, "linespec", CommandCompletions::eNoCompletion, { nullptr, false }, "A source specifier in the form file:line[:column]" }, { eArgTypeLogCategory, "log-category", CommandCompletions::eNoCompletion, { nullptr, false }, "The name of a category within a log channel, e.g. all (try \"log list\" to see a list of all channels and their categories." }, { eArgTypeLogChannel, "log-channel", CommandCompletions::eNoCompletion, { nullptr, false }, "The name of a log channel, e.g. process.gdb-remote (try \"log list\" to see a list of all channels and their categories)." }, + { eArgTypeLogFormat, "log-format", CommandCompletions::eLogFormatCompletion, { nullptr, false }, "One of LLDB's supported log file formats." }, { eArgTypeMethod, "method", CommandCompletions::eNoCompletion, { nullptr, false }, "A C++ method name." }, { eArgTypeName, "name", CommandCompletions::eTypeCategoryNameCompletion, { nullptr, false }, "Help text goes here." }, { eArgTypeNewPathPrefix, "new-path-prefix", CommandCompletions::eNoCompletion, { nullptr, false }, "Help text goes here." }, Index: lldb/source/Utility/Log.cpp =================================================================== --- lldb/source/Utility/Log.cpp +++ lldb/source/Utility/Log.cpp @@ -132,14 +132,11 @@ void Log::VAPrintf(const char *format, va_list args) { llvm::SmallString<64> FinalMessage; llvm::raw_svector_ostream Stream(FinalMessage); - WriteHeader(Stream, "", ""); llvm::SmallString<64> Content; lldb_private::VASprintf(Content, format, args); - Stream << Content << "\n"; - - WriteMessage(std::string(FinalMessage.str())); + Format(/*file=*/"", /*function=*/"", llvm::formatv("{0}", Content)); } // Printing of errors that are not fatal. @@ -230,6 +227,17 @@ return true; } +bool Log::SetLogChannelFormat(llvm::StringRef channel, Log::OutputFormat format, + llvm::raw_ostream &error_stream) { + auto iter = g_channel_map->find(channel); + if (iter == g_channel_map->end()) { + error_stream << llvm::formatv("Invalid log channel '{0}'.\n", channel); + return false; + } + iter->second.m_output_format = format; + return true; +} + bool Log::ListChannelCategories(llvm::StringRef channel, llvm::raw_ostream &stream) { auto ch = g_channel_map->find(channel); @@ -277,25 +285,90 @@ 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::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; + Flags options = GetOptions(); + if (options.Test(LLDB_LOG_OPTION_THREADSAFE)) { + static std::recursive_mutex g_LogThreadedMutex; + std::lock_guard guard(g_LogThreadedMutex); + *stream_sp << json; + stream_sp->flush(); + } else { + *stream_sp << json; + stream_sp->flush(); + } +} + +namespace { +struct PlainTextWriter { + llvm::raw_ostream &m_output; + /// True if any output has been written by this class to this point. + bool m_anything_written = false; + explicit PlainTextWriter(llvm::raw_ostream &output) : m_output(output) {} + ~PlainTextWriter() { m_output << "\n"; } + void PrintSeparatorIfNeeded() { + // The first output at the start of the line doesn't need a separating + // space. + if (!m_anything_written) + return; + m_output << " "; + } + template void Write(llvm::StringRef key, const T &value) { + PrintSeparatorIfNeeded(); + m_anything_written = true; + m_output << value; + } + template <> void Write(llvm::StringRef key, const double &value) { + PrintSeparatorIfNeeded(); + m_anything_written = true; + // Limit the precision of printed doubles. + m_output << llvm::formatv("{0:f9}", value); + } +}; +struct JSONWriter { + llvm::raw_ostream &m_output; + llvm::json::OStream m_json; + explicit JSONWriter(llvm::raw_ostream &output) + : m_output(output), m_json(output) { + m_json.objectBegin(); + } + ~JSONWriter() { + m_json.objectEnd(); + m_json.flush(); + m_output << ",\n"; + } + template void Write(llvm::StringRef key, const T &value) { + m_json.attribute(key, value); + } +}; +} // namespace + +template +static void BuildMessage(Writer &output, const Flags options, + llvm::StringRef file, llvm::StringRef function, + llvm::StringRef message) { 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 << " "; + output.Write("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()); + output.Write("timestamp", now.count()); } // 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)) { + output.Write("pid", static_cast(getpid())); + output.Write("tid", static_cast(llvm::get_threadid())); + } // Add the thread name if requested if (options.Test(LLDB_LOG_OPTION_PREPEND_THREAD_NAME)) { @@ -305,45 +378,44 @@ 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); + output.Write("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(); + output.Write("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()); + output.Write("file", llvm::sys::path::filename(file)); + output.Write("function", function); } -} - -void Log::WriteMessage(const std::string &message) { - // 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; - 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->flush(); - } else { - *stream_sp << message; - stream_sp->flush(); - } + output.Write("message", message); } void Log::Format(llvm::StringRef file, llvm::StringRef function, const llvm::formatv_object_base &payload) { std::string message_string; llvm::raw_string_ostream message(message_string); - WriteHeader(message, file, function); - message << payload << "\n"; + + switch (m_output_format.load(std::memory_order_relaxed)) { + case Log::OutputFormat::JSON: { + JSONWriter json_writer(message); + BuildMessage(json_writer, GetOptions(), file, function, payload.str()); + break; + } + case Log::OutputFormat::Plain: { + PlainTextWriter plain_writer(message); + BuildMessage(plain_writer, GetOptions(), file, function, payload.str()); + break; + } + } + WriteMessage(message.str()); } Index: lldb/test/API/commands/log/invalid-args/TestInvalidArgsLog.py =================================================================== --- lldb/test/API/commands/log/invalid-args/TestInvalidArgsLog.py +++ lldb/test/API/commands/log/invalid-args/TestInvalidArgsLog.py @@ -21,3 +21,8 @@ invalid_path = os.path.join("this", "is", "not", "a", "valid", "path") self.expect("log enable lldb all -f " + invalid_path, error=True, substrs=["Unable to open log file '" + invalid_path + "': ", "\n"]) + + @no_debug_info_test + def test_disable_empty(self): + self.expect("log enable -O invalid_format lldb all", error=True, + substrs=["error: Unknown log format: invalid_format"]) Index: lldb/test/API/functionalities/completion/TestCompletion.py =================================================================== --- lldb/test/API/functionalities/completion/TestCompletion.py +++ lldb/test/API/functionalities/completion/TestCompletion.py @@ -244,6 +244,14 @@ self.complete_from_to('log enable lldb expr -f ' + src_dir, [src_dir + os.sep], turn_off_re_match=True) + def test_log_enable_output_format(self): + self.complete_from_to('log enable -O js', ['json']) + self.complete_from_to('log enable -O pl', ['plain']) + self.complete_from_to('log enable -O ', ['json', 'plain']) + # No possible completion. + self.complete_from_to('log enable -O b', + 'log enable -O b') + # def test_infinite_loop_while_completing(self): """Test that 'process print hello\' completes to itself and does not infinite loop.""" Index: lldb/test/API/functionalities/logging/Makefile =================================================================== --- /dev/null +++ lldb/test/API/functionalities/logging/Makefile @@ -0,0 +1,3 @@ +CXX_SOURCES := main.cpp + +include Makefile.rules Index: lldb/test/API/functionalities/logging/TestLogging.py =================================================================== --- /dev/null +++ lldb/test/API/functionalities/logging/TestLogging.py @@ -0,0 +1,74 @@ +import lldb +from lldbsuite.test.decorators import * +from lldbsuite.test.lldbtest import * +from lldbsuite.test import lldbutil + +import json + +class TestCase(TestBase): + + mydir = TestBase.compute_mydir(__file__) + + @no_debug_info_test + def test_mixed_log_formats(self): + """ + Tests having two log channels that target the same output file but with + different output formats (JSON and plain text). + """ + self.build() + logfile = self.getBuildArtifact("mixed.log") + + # Enable two logging channels. One uses JSON, the other plain text + # but they log to the same file. Timestamps are enabled so that + # the start of the plain text messages are just numbers and not by + # accident something that looks like a JSON object ("{...}"). + self.expect("log enable -T -O json lldb target comm -f {}".format(logfile)) + self.expect("log enable -T -O plain gdb-remote all -f {}".format(logfile)) + + lldbutil.run_to_source_breakpoint(self, "// break here", lldb.SBFileSpec("main.cpp")) + + if configuration.is_reproducer_replay(): + logfile = self.getReproducerRemappedPath(logfile) + + self.assertTrue(os.path.isfile(logfile)) + with open(logfile, 'r') as f: + log_lines = f.readlines() + log_content = "\n".join(log_lines) + + # Go over the log and try to parse all the JSON messages. Even with + # the also enabled plain text logging every separate JSON message should + # be valid. + found_json = False + for line in log_lines: + line = line.strip() + if line.startswith("{"): + found_json = True + json_payload = line + # Strip the trailing comma that is behind every object in the + # big JSON array that the logger is printing. JSON can't have + # trailing commas behind the top-level object, so we have to + # to make the JSON parser happy by removing the comma. + self.assertTrue(json_payload.endswith(","), "payload: " + json_payload) + json_payload = json_payload[:-1] + parsed_payload = json.loads(json_payload) + # Check that message and timestamps were added to the log + # message. + self.assertIn("timestamp", parsed_payload) + self.assertIn("message", parsed_payload) + + # Sanity check that we got at least one JSON log message. + self.assertTrue(found_json, "log: " + log_content) + + # Go over the log and try to verify the plain text messages. + found_plain = False + for line in log_lines: + line = line.strip() + # The only thing that can be checked for plain text is that there + # is at least one line that starts with something that looks like + # a timestamp (i.e., a digit). + if not line.startswith("{") and len(line) != 0 and line[0].isdigit(): + found_plain = True + break + + # Sanity check that we got a tleast one plain text message. + self.assertTrue(found_plain, "log: " + log_content) Index: lldb/test/API/functionalities/logging/main.cpp =================================================================== --- /dev/null +++ lldb/test/API/functionalities/logging/main.cpp @@ -0,0 +1,3 @@ +int main() { + return 0; // break here +} 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; }; @@ -92,6 +103,11 @@ std::string error; ASSERT_TRUE(EnableChannel(m_stream_sp, 0, "chan", {}, error)); + llvm::raw_string_ostream error_stream(error); + // Use JSON logging by default so the log messages can be parsed. + ASSERT_TRUE( + Log::SetLogChannelFormat("chan", Log::OutputFormat::JSON, error_stream)); + EXPECT_EQ(error, ""); m_log = test_channel.GetLogIfAll(FOO); ASSERT_NE(nullptr, m_log); @@ -211,37 +227,71 @@ 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, PlainTextFormat) { + std::string error; + llvm::raw_string_ostream error_stream(error); + EXPECT_TRUE( + Log::SetLogChannelFormat("chan", Log::OutputFormat::Plain, error_stream)); + EXPECT_EQ(error, ""); + + std::string Err; + EXPECT_EQ("Hello World\n", logAndTakeOutput("Hello World")); + + // Test plain text formatting with pid/tid option set. + { + EXPECT_TRUE(EnableChannel( + getStream(), LLDB_LOG_OPTION_PREPEND_PROC_AND_THREAD, "chan", {}, Err)); + const std::string expected_msg = + llvm::formatv("{0,0+4} {1,0+4} Hello World\n", getpid(), + llvm::get_threadid()) + .str(); + EXPECT_EQ(expected_msg, logAndTakeOutput("Hello World")); + } } TEST_F(LogChannelEnabledTest, LLDB_LOG_ERROR) { @@ -252,7 +302,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 +324,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 +343,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) {