[lldb] Add a log dump command to dump the circular log buffer

[JDevlieghere]

Summary

Add a log dump command to dump the circular log buffer. This also adds a test for the circular log handler.

[mib]

LGTM!

[clayborg]

So we either need to track categories for each buffered log message in the circular buffer so that if the user specifies a category within a channel to dump with "log dump lldb <category>" we can filter out the messages we dump if they are not in the one or more categories that were supplied, or remove categories from the "log dump" command and only specify the channel. Easy to fix the code to work either way.

The idea is if the user does:

(lldb) log enable -b 5 -h circular lldb command state process
(lldb) ...
(lldb log dump lldb process

I would expect only "process" category messages to be shown. The current code allows the user to specify categories, but they don't do anything. So we should either obey the categories correctly by changing "LogHandler::Emit(StringRef message)" to take an extra category mask like "LogHandler::Emit(StringRef message, uint64_t category)" so that we can cache a vector of "std::pair<std::string, uint64_t>" so we can emit only the requested categories when using "log dump", or just remove the categories from the "log dump" command.

lldb/source/Commands/CommandObjectLog.cpp

359

If we aren't going to correctly track what category that each log channel comes from, then specifying the categories doesn't do anything and the categories shouldn't be part of this command unless you want to fix that. We could easily do this if we modify LogHandler::Emit(...) to take a category integer and then our buffer would need to store category + message in an array.

lldb/source/Utility/Log.cpp

242

We don't need categories here. We have no way to separate each log message since we don't store this, and the user shouldn't be required to know the categories right?

lldb/test/API/commands/log/basic/TestLogHandlers.py

21

Do we want to test that non circular buffers can't be dumped too to make sure nothing goes wrong or that we get a good error message stating that this log channel isn't circular?

23

It seems wrong to specify the categories in the "log dump" command since we won't do the right thing. If you can specified categories I would expect this to work:

(lldb) log enable -b 5 -h circular lldb command state process
(lldb) ...
(lldb) log dump lldb process

And that only process log lines would come out. Since we don't store this information, we shouldn't have to specify the categories at all, so the "log dump" command should just take the channel:

(lldb) log dump lldb

[JDevlieghere]

Thanks for pointing that out. I blindly copied the categories logic from Log::Disable which uses it when computing the flags. I've omitted it for now because I think it would be weird to set the circular buffer size to 5 and then have 0 messages printed for the process category because 5 log messages from the commands category pushed them out. One solution would be to keep a circular buffer per category. I'll think about it and if I come up with a good solution I'll put up another patch.

[labath]

In D128557#3609545, @JDevlieghere wrote:

One solution would be to keep a circular buffer per category. I'll think about it and if I come up with a good solution I'll put up another patch.

This isn't completely trivial, because there it's not possible to associate each log message with a specific log category -- GetLog(FOO | BAR) will return a log object if either of the two categories are set. So we'd either need to attach a set of categories to each log message, give up the multi-category messages, or do something more complicated...

lldb/test/API/commands/log/basic/TestLogHandlers.py

21

Is that done? I would expect to see a test which runs something like "log enable -h XXX" and then checks that "log dump" errors out with something like "log handler XXX does not support dumping"...

[JDevlieghere]

Print error message when dumping is not supported.

[clayborg]

In D128557#3609545, @JDevlieghere wrote:

Thanks for pointing that out. I blindly copied the categories logic from Log::Disable which uses it when computing the flags. I've omitted it for now because I think it would be weird to set the circular buffer size to 5 and then have 0 messages printed for the process category because 5 log messages from the commands category pushed them out. One solution would be to keep a circular buffer per category. I'll think about it and if I come up with a good solution I'll put up another patch.

Sounds good. We would still want to keep a circular buffer and keep all messages in order in case they want to dump just a few of the total categories as those log messages still need to come out in order.

This isn't completely trivial, because there it's not possible to associate each log message with a specific log category -- GetLog(FOO | BAR) will return a log object if either of the two categories are set. So we'd either need to attach a set of categories to each log message, give up the multi-category messages, or do something more complicated...

If we keep a list of messages and the log mask as the other part of the pair, it is very easy to keep as bot the "FOO" and "BAR" bits will be set in the 64 bit log mask.

lldb/include/lldb/Host/Host.h

static uint32_t FindProcessesImpl(const ProcessInstanceInfoMatch &match_info,
                                     ProcessInstanceInfoList &proc_infos);
 };
 
 /// Log handler that emits log messages to the operating system log.
 class SystemLogHandler : public LogHandler {
 public:
   SystemLogHandler();
   void Emit(llvm::StringRef message) override;
+
+  bool isA(const void *ClassID) const override { return ClassID == &ID; }
+  static bool classof(const LogHandler *obj) { return obj->isA(&ID); }
+
+private:
+  static char ID;
 };
 
 } // namespace lldb_private
 
 namespace llvm {
 template <> struct format_provider<lldb_private::WaitStatus> {
   /// Options = "" gives a human readable description of the status Options =
   /// "g" gives a gdb-remote protocol status (e.g., X09)
   static void format(const lldb_private::WaitStatus &WS, raw_ostream &OS,
                      llvm::StringRef Options);
 };
 } // namespace llvm
 
 #endif // LLDB_HOST_HOST_H

lldb/include/lldb/Utility/Log.h

 
 // Logging Functions
 namespace lldb_private {
 
 class LogHandler {
 public:
   virtual ~LogHandler() = default;
   virtual void Emit(llvm::StringRef message) = 0;
+
+  virtual bool isA(const void *ClassID) const { return ClassID == &ID; }
+  static bool classof(const LogHandler *obj) { return obj->isA(&ID); }
+
+private:
+  static char ID;
 };
 
 class StreamLogHandler : public LogHandler {
 public:
   StreamLogHandler(int fd, bool should_close, size_t buffer_size = 0);
   ~StreamLogHandler() override;
 
   void Emit(llvm::StringRef message) override;
   void Flush();
 
+  bool isA(const void *ClassID) const override { return ClassID == &ID; }
+  static bool classof(const LogHandler *obj) { return obj->isA(&ID); }
+
 private:
   std::mutex m_mutex;
   llvm::raw_fd_ostream m_stream;
+  static char ID;
 };
 
 class CallbackLogHandler : public LogHandler {
 public:
   CallbackLogHandler(lldb::LogOutputCallback callback, void *baton);
 
   void Emit(llvm::StringRef message) override;
 
+  bool isA(const void *ClassID) const override { return ClassID == &ID; }
+  static bool classof(const LogHandler *obj) { return obj->isA(&ID); }
+
 private:
   lldb::LogOutputCallback m_callback;
   void *m_baton;
+  static char ID;
 };
 
 class RotatingLogHandler : public LogHandler {
 public:
   RotatingLogHandler(size_t size);
 
   void Emit(llvm::StringRef message) override;
   void Dump(llvm::raw_ostream &stream) const;
 
+  bool isA(const void *ClassID) const override { return ClassID == &ID; }
+  static bool classof(const LogHandler *obj) { return obj->isA(&ID); }
+
 private:
   size_t NormalizeIndex(size_t i) const;
   size_t GetNumMessages() const;
   size_t GetFirstMessageIndex() const;
 
   mutable std::mutex m_mutex;
   std::unique_ptr<std::string[]> m_messages;
   const size_t m_size = 0;
   size_t m_next_index = 0;
   size_t m_total_count = 0;
+  static char ID;
 };
 
 class Log final {
 public:
   /// The underlying type of all log channel enums. Declare them as:
   /// enum class MyLog : MaskType {
   ///   Channel0 = Log::ChannelFlag<0>,
   ///   Channel1 = Log::ChannelFlag<1>,
EnableLogChannel(const std::shared_ptr<LogHandler> &log_handler_sp,
                    uint32_t log_options, llvm::StringRef channel,
                    llvm::ArrayRef<const char *> categories,
                    llvm::raw_ostream &error_stream);
 
   static bool DisableLogChannel(llvm::StringRef channel,
                                 llvm::ArrayRef<const char *> categories,
                                 llvm::raw_ostream &error_stream);
 
+  static bool DumpLogChannel(llvm::StringRef channel,
+                             llvm::raw_ostream &output_stream,
+                             llvm::raw_ostream &error_stream);
+
   static bool ListChannelCategories(llvm::StringRef channel,
                                     llvm::raw_ostream &stream);
 
   /// Returns the list of log channels.
   static std::vector<llvm::StringRef> ListChannels();
   /// Calls the given lambda for every category in the given channel.
   /// If no channel with the given name exists, lambda is never called.
   static void ForEachChannelCategory(
std::shared_ptr<LogHandler> GetHandler() {
     return m_handler;
   }
 
   void Enable(const std::shared_ptr<LogHandler> &handler_sp, uint32_t options,
               uint32_t flags);
 
   void Disable(uint32_t flags);
 
+  bool Dump(llvm::raw_ostream &stream);
+
   typedef llvm::StringMap<Log> ChannelMap;
   static llvm::ManagedStatic<ChannelMap> g_channel_map;
 
   static void ForEachCategory(
       const Log::ChannelMap::value_type &entry,
       llvm::function_ref<void(llvm::StringRef, llvm::StringRef)> lambda);
 
   static void ListCategories(llvm::raw_ostream &stream,

lldb/source/Commands/CommandObjectLog.cpp

 
 static constexpr OptionEnumValues LogHandlerType() {
   return OptionEnumValues(g_log_handler_type);
 }
 
 #define LLDB_OPTIONS_log_enable
 #include "CommandOptions.inc"
 
+#define LLDB_OPTIONS_log_dump
+#include "CommandOptions.inc"
+
 /// Common completion logic for log enable/disable.
 static void CompleteEnableDisable(CompletionRequest &request) {
   size_t arg_index = request.GetCursorIndex();
   if (arg_index == 0) { // We got: log enable/disable x[tab]
     for (llvm::StringRef channel : Log::ListChannels())
       request.TryCompleteCurrentArg(channel);
   } else if (arg_index >= 1) { // We got: log enable/disable channel x[tab]
     llvm::StringRef channel = request.GetParsedLine().GetArgumentAtIndex(0);
if (args.empty()) {
             success && Log::ListChannelCategories(entry.ref(), output_stream);
       if (success)
         result.SetStatus(eReturnStatusSuccessFinishResult);
     }
     result.GetOutputStream() << output_stream.str();
     return result.Succeeded();
   }
 };
+class CommandObjectLogDump : public CommandObjectParsed {
+public:
+  CommandObjectLogDump(CommandInterpreter &interpreter)
+      : CommandObjectParsed(interpreter, "log dump",
+                            "dump circular buffer logs", nullptr) {
+    CommandArgumentEntry arg1;
+    CommandArgumentData channel_arg;
+
+    // Define the first (and only) variant of this arg.
+    channel_arg.arg_type = eArgTypeLogChannel;
+    channel_arg.arg_repetition = eArgRepeatPlain;
+
+    // There is only one variant this argument could be; put it into the
+    // argument entry.
+    arg1.push_back(channel_arg);
+
+    // Push the data for the first argument into the m_arguments vector.
+    m_arguments.push_back(arg1);
+  }
+
+  ~CommandObjectLogDump() override = default;
+
+  Options *GetOptions() override { return &m_options; }
+
+  class CommandOptions : public Options {
+  public:
+    CommandOptions() = default;
+
+    ~CommandOptions() override = default;
+
+    Status SetOptionValue(uint32_t option_idx, llvm::StringRef option_arg,
+                          ExecutionContext *execution_context) override {
+      Status error;
+      const int short_option = m_getopt_table[option_idx].val;
+
+      switch (short_option) {
+      case 'f':
+        log_file.SetFile(option_arg, FileSpec::Style::native);
+        FileSystem::Instance().Resolve(log_file);
+        break;
+      default:
+        llvm_unreachable("Unimplemented option");
+      }
+
+      return error;
+    }
+
+    void OptionParsingStarting(ExecutionContext *execution_context) override {
+      log_file.Clear();
+    }
+
+    llvm::ArrayRef<OptionDefinition> GetDefinitions() override {
+      return llvm::makeArrayRef(g_log_dump_options);
+    }
+
+    FileSpec log_file;
+  };
+
+  void
+  HandleArgumentCompletion(CompletionRequest &request,
+                           OptionElementVector &opt_element_vector) override {
+    CompleteEnableDisable(request);
+  }
+
+protected:
+  bool DoExecute(Args &args, CommandReturnObject &result) override {
+    if (args.empty()) {
+      result.AppendErrorWithFormat(
+          "%s takes a log channel and one or more log types.\n",
+          m_cmd_name.c_str());
+      return false;
+    }
+
+    std::unique_ptr<llvm::raw_ostream> stream_up;
+    if (m_options.log_file) {
+      const File::OpenOptions flags = File::eOpenOptionWriteOnly |
+                                      File::eOpenOptionCanCreate |
+                                      File::eOpenOptionTruncate;
+      llvm::Expected<FileUP> file = FileSystem::Instance().Open(
+          m_options.log_file, flags, lldb::eFilePermissionsFileDefault, false);
+      if (!file) {
+        result.AppendErrorWithFormat("Unable to open log file '%s': %s",
+                                     m_options.log_file.GetCString(),
+                                     llvm::toString(file.takeError()).c_str());
+        return false;
+      }
+      stream_up = std::make_unique<llvm::raw_fd_ostream>(
+          (*file)->GetDescriptor(), /*shouldClose=*/true);
+    } else {
+      stream_up = std::make_unique<llvm::raw_fd_ostream>(
+          GetDebugger().GetOutputFile().GetDescriptor(), /*shouldClose=*/false);
+    }
+
+    const std::string channel = std::string(args[0].ref());
+    std::string error;
+    llvm::raw_string_ostream error_stream(error);
+    if (Log::DumpLogChannel(channel, *stream_up, error_stream)) {
+      result.SetStatus(eReturnStatusSuccessFinishNoResult);
+    } else {
+      result.SetStatus(eReturnStatusFailed);
+      result.GetErrorStream() << error_stream.str();
+    }
+
+    return result.Succeeded();
+  }
+
+  CommandOptions m_options;
+};
 
 class CommandObjectLogTimerEnable : public CommandObjectParsed {
 public:
   // Constructors and Destructors
   CommandObjectLogTimerEnable(CommandInterpreter &interpreter)
       : CommandObjectParsed(interpreter, "log timers enable",
                             "enable LLDB internal performance timers",
                             "log timers enable <depth>") {
: CommandObjectMultiword(interpreter, "log",
                              "Commands controlling LLDB internal logging.",
                              "log <subcommand> [<command-options>]") {
   LoadSubCommand("enable",
                  CommandObjectSP(new CommandObjectLogEnable(interpreter)));
   LoadSubCommand("disable",
                  CommandObjectSP(new CommandObjectLogDisable(interpreter)));
   LoadSubCommand("list",
                  CommandObjectSP(new CommandObjectLogList(interpreter)));
+  LoadSubCommand("dump",
+                 CommandObjectSP(new CommandObjectLogDump(interpreter)));
   LoadSubCommand("timers",
                  CommandObjectSP(new CommandObjectLogTimer(interpreter)));
 }
 
 CommandObjectLog::~CommandObjectLog() = default;

lldb/source/Commands/Options.td

let Command = "log enable" in {
   def log_stack : Option<"stack", "S">, Group<1>,
     Desc<"Append a stack backtrace to each log line.">;
   def log_append : Option<"append", "a">, Group<1>,
     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.">;
 }
 
+let Command = "log dump" in {
+  def log_dump_file : Option<"file", "f">, Group<1>, Arg<"Filename">,
+    Desc<"Set the destination file to dump to.">;
+}
+
 let Command = "reproducer dump" in {
   def reproducer_provider : Option<"provider", "p">, Group<1>,
     EnumArg<"None", "ReproducerProviderType()">,
     Required, Desc<"The reproducer provider to dump.">;
   def reproducer_file : Option<"file", "f">, Group<1>, Arg<"Filename">,
     Desc<"The reproducer path. If a reproducer is replayed and no path is "
     "provided, that reproducer is dumped.">;
 }

lldb/source/Host/common/Host.cpp

if (repro::Generator *g = repro::Reproducer::Instance().GetGenerator()) {
     g->GetOrCreate<repro::ProcessInfoProvider>()
         .GetNewProcessInfoRecorder()
         ->Record(process_infos);
   }
 
   return result;
 }
 
+char SystemLogHandler::ID;
+
 SystemLogHandler::SystemLogHandler() {}
 
 void SystemLogHandler::Emit(llvm::StringRef message) {
   Host::SystemLog(message);
 }

lldb/source/Utility/Log.cpp

 //===-- Log.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 "lldb/Utility/Log.h"
 #include "lldb/Utility/VASPrintf.h"
 
 #include "llvm/ADT/SmallString.h"
 #include "llvm/ADT/Twine.h"
 #include "llvm/ADT/iterator.h"
 
+#include "llvm/Support/Casting.h"
 #include "llvm/Support/Chrono.h"
 #include "llvm/Support/ManagedStatic.h"
 #include "llvm/Support/Path.h"
 #include "llvm/Support/Signals.h"
 #include "llvm/Support/Threading.h"
 #include "llvm/Support/raw_ostream.h"
 
 #include <chrono>
 #include <cstdarg>
 #include <mutex>
 #include <utility>
 
 #include <cassert>
 #if defined(_WIN32)
 #include <process.h>
 #else
 #include <unistd.h>
 #endif
 
 using namespace lldb_private;
 
+char LogHandler::ID;
+char StreamLogHandler::ID;
+char CallbackLogHandler::ID;
+char RotatingLogHandler::ID;
+
 llvm::ManagedStatic<Log::ChannelMap> Log::g_channel_map;
 
 void Log::ForEachCategory(
     const Log::ChannelMap::value_type &entry,
     llvm::function_ref<void(llvm::StringRef, llvm::StringRef)> lambda) {
   lambda("all", "all available logging categories");
   lambda("default", "default set of logging categories");
   for (const auto &category : entry.second.m_channel.categories)
void Log::Disable(uint32_t flags) {
 
   MaskType mask = m_mask.fetch_and(~flags, std::memory_order_relaxed);
   if (!(mask & ~flags)) {
     m_handler.reset();
     m_channel.log_ptr.store(nullptr, std::memory_order_relaxed);
   }
 }
 
+bool Log::Dump(llvm::raw_ostream &output_stream) {
+  llvm::sys::ScopedReader lock(m_mutex);
+  if (RotatingLogHandler *handler =
+          llvm::dyn_cast_or_null<RotatingLogHandler>(m_handler.get())) {
+    handler->Dump(output_stream);
+    return true;
+  }
+  return false;
+}
+
 const Flags Log::GetOptions() const {
   return m_options.load(std::memory_order_relaxed);
 }
 
 const Flags Log::GetMask() const {
   return m_mask.load(std::memory_order_relaxed);
 }
 
bool Log::DisableLogChannel(llvm::StringRef channel,
   }
   uint32_t flags = categories.empty()
                        ? UINT32_MAX
                        : GetFlags(error_stream, *iter, categories);
   iter->second.Disable(flags);
   return true;
 }
 
+bool Log::DumpLogChannel(llvm::StringRef channel,
+                         llvm::raw_ostream &output_stream,
+                         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;
+  }
+  if (!iter->second.Dump(output_stream)) {
+    error_stream << llvm::formatv(
+        "log channel '{0}' does not support dumping.\n", channel);
+    return false;
+  }
+  return true;
+}
+
 bool Log::ListChannelCategories(llvm::StringRef channel,
                                 llvm::raw_ostream &stream) {
   auto ch = g_channel_map->find(channel);
   if (ch == g_channel_map->end()) {
     stream << llvm::formatv("Invalid log channel '{0}'.\n", channel);
     return false;
   }
   ListCategories(stream, *ch);

lldb/test/API/commands/log/basic/TestLogHandlers.py

+"""
+Test lldb log handlers.
+"""
+
+import os
+import lldb
+from lldbsuite.test.decorators import *
+from lldbsuite.test.lldbtest import *
+from lldbsuite.test import lldbutil
+
+
+class LogHandlerTestCase(TestBase):
+    NO_DEBUG_INFO_TESTCASE = True
+
+    def setUp(self):
+        TestBase.setUp(self)
+        self.log_file = self.getBuildArtifact("log-file.txt")
+        if (os.path.exists(self.log_file)):
+            os.remove(self.log_file)
+
+    def test_circular(self):
+        self.runCmd("log enable -b 5 -h circular lldb commands")
+        self.runCmd("bogus", check=False)
+        self.runCmd("log dump lldb -f {}".format(self.log_file))
+
+        with open(self.log_file, 'r') as f:
+            log_lines = f.readlines()
+
+        self.assertEqual(len(log_lines), 5)
+
+        found_command_log_dump = False
+        found_command_bogus = False
+
+        for line in log_lines:
+            if 'Processing command: log dump' in line:
+                found_command_log_dump = True
+            if 'Processing command: bogus' in line:
+                found_command_bogus = True
+
+        self.assertTrue(found_command_log_dump)
+        self.assertFalse(found_command_bogus)
+
+    def test_circular_no_buffer_size(self):
+        self.expect(
+            "log enable -h circular lldb commands",
+            error=True,
+            substrs=[
+                'the circular buffer handler requires a non-zero buffer size'
+            ])
+
+    def test_dump_unsupported(self):
+        self.runCmd("log enable lldb commands -f {}".format(self.log_file))
+        self.expect("log dump lldb",
+                    error=True,
+                    substrs=["log channel 'lldb' does not support dumping"])