[lldb] Add an always-on log channel

[JDevlieghere]

Summary

Add an "always on" log channel. The channel is meant to be used sparsely and deliberately for logging high-value information. Unlike other log channels, it's not exposed to the user. Log messages are logged to a ring buffer with a fixed number of entries. The ring buffer is dumped to disk as part of the diagnostics, i.e. when the debugger crashes or when the user explicitly requests a dump.

[labath]

I'm not sure if this will do what you wanted it to do. Despite the title, this patch is not adding a new log *channel* -- it is adding a new log *category* to the "lldb" channel. Our logging infra, perhaps somewhat misleadingly, manages all of the log state on a per-channel basis. This means that it is not e.g. possible to redirect one log category to a different sink than a different category in the same channel. I haven't checked this, but I suspect that for this reason, any explicit "log enable" commands by the user will redirect this special channel into the new (user-provided) destination. If this is not what you intended to do then, you probably ought to add a new log channel, for real.

That said, without knowing what kind of information do you want to log here, I am wondering if the same kind of information could be gathered by reusing some existing data collection mechanism, like session transcripts, or the yet-to-be-implemented telemetry data.

[JDevlieghere]

In D135621#3849043, @labath wrote:

I'm not sure if this will do what you wanted it to do. Despite the title, this patch is not adding a new log *channel* -- it is adding a new log *category* to the "lldb" channel. Our logging infra, perhaps somewhat misleadingly, manages all of the log state on a per-channel basis. This means that it is not e.g. possible to redirect one log category to a different sink than a different category in the same channel. I haven't checked this, but I suspect that for this reason, any explicit "log enable" commands by the user will redirect this special channel into the new (user-provided) destination. If this is not what you intended to do then, you probably ought to add a new log channel, for real.

You're absolutely right. I actually came to that same conclusion myself when I implemented an earlier iteration of this patch a long while ago but evidently didn't think of it before recreating the patch from memory.

That said, without knowing what kind of information do you want to log here, I am wondering if the same kind of information could be gathered by reusing some existing data collection mechanism, like session transcripts, or the yet-to-be-implemented telemetry data.

I see those two things as orthogonal. Always-on logging is something that has comes up quite frequently. @kastiglione can talk about our downstream log channel for Swift and @Michael137 was also interested in this to triage common issues with the expression evaluator.

[clayborg]

Maybe use LLDBLog::Diagnostics instead of LLDBLog::AlwaysOn? and maybe "diagnostics" instead of "always-on"?

I am also questioning if the these even belong in the LLDB logging stuff? Seems like it would be just as easy to create a diagnostic message by calling Diagnostics::Report(...). Do we really want to modify the log channels here? Seems like always on diagnostics should just a dedicated API.

It might be nice to also have a "diagnostics" log channel that _can_ be enabled, and any diagnostic messages would then also be included in the log output but only if enabled by the user?

lldb/include/lldb/Utility/Diagnostics.h

65

Move out of header file as a file static only? Better name might be a good idea. "g_log_messages" sounds like a boolean setting. Maybe "g_max_log_messages" or "g_num_log_messages"?

[clayborg]

It might be nice to also have a "diagnostics" log channel that _can_ be enabled, and any diagnostic messages would then also be included in the log output but only if enabled by the user?

And if the logging gets enabled, we can write out all of the diagnostics and are in the circular buffer if the "log enable lldb diagnostics" is enabled, then as each diagnostic is reported, the Diagnostics::Report(...) call could emit the log messages real time.

[JDevlieghere]

• Address code review feedback

[JDevlieghere]

In D135621#3850248, @clayborg wrote:

I am also questioning if the these even belong in the LLDB logging stuff? Seems like it would be just as easy to create a diagnostic message by calling Diagnostics::Report(...). Do we really want to modify the log channels here? Seems like always on diagnostics should just a dedicated API.

I expect the majority of places where we want to log to the diagnostic log channel to be places where we already log today. It being a its own log channel complicates that somewhat, because unlike categories you can't do GetLog(LLDB::Expression | Diagnostics::Expression). That's still pretty important to us, so I've added two more macros that allow you to specify multiple log channels to achieve a somewhat similar result:

LOG_MULTI_PRINTF(GetLog(LLDBLog::Expression), GetLog(Diagnostics::Foo), "%s", foo)

Similarly, I also plan to change LLDB_LOG_ERROR to always log to the diagnostic channel. I didn't include it in this patch as it requires moving the macro in the diagnostics header and generates a lot of churn.

[kastiglione]

I expect the majority of places where we want to log to the diagnostic log channel to be places where we already log today.

This is my expectation too. Some logs are helpful for diagnosing problems, and having them already saved makes it easier for users to include info in their reports.

lldb/source/Utility/Diagnostics.cpp

23

To me, it's not ideal that there's an "lldb" channel, and this channel has an "lldb" category.

Do you have other categories in mind for later updates, that should be moved into this patch? For example, will there eventually be "warning" and "error" categories? If so, maybe start with those instead of "lldb".

[JDevlieghere]

lldb/source/Utility/Diagnostics.cpp

23

Yes, for the errors I was going to add an error category. Maybe we can call this one general or something?

[labath]

In D135621#3875218, @JDevlieghere wrote:

In D135621#3850248, @clayborg wrote:

I am also questioning if the these even belong in the LLDB logging stuff? Seems like it would be just as easy to create a diagnostic message by calling Diagnostics::Report(...). Do we really want to modify the log channels here? Seems like always on diagnostics should just a dedicated API.

I expect the majority of places where we want to log to the diagnostic log channel to be places where we already log today.

Yeah, but that could be achieved by having the "dedicated diagnostic API" forward the message to a regular log when it deems it necessary (or always).

Speaking of dedicated APIs, we already have the Debugger::ReportWarning/Error functions. I would expect we want those to show up in the diagnostic log, as these are things that we've already deemed important enough to print to the user. Wouldn't it be better to use that as a starting point? Possibly extend it by adding some sort of an "info" priority, which does not get printed to the user (but makes its way to the log)?

Similarly, I also plan to change LLDB_LOG_ERROR to always log to the diagnostic channel. I didn't include it in this patch as it requires moving the macro in the diagnostics header and generates a lot of churn.

I'm not sure that's a good default. Some of those messages could be fairly innocuous, and the ratio of the innocuous ones will probably increase as we use llvm::Error more.

lldb/source/Utility/Diagnostics.cpp

23

I'm not entirely sure of what's the purpose of having multiple categories, if they're all supposed to be on all the time (the category name is not recorded anywhere, so the only thing they do is enable one to selectively enable/disable some log messages).

lldb/test/Shell/Diagnostics/TestLogChannel.test

2

Judging by the patch, I think the user will still be able to disable diagnostics if he is able to "guess" that there is a log channel called that way (log disable diagnostics). Is that intentional?

[JDevlieghere]

Seems like the consensus is that we prefer a dedicated API rather than using the existing logging infrastructure.

lldb/include/lldb/Utility/Diagnostics.h

 //===-- Diagnostics.h -------------------------------------------*- C++ -*-===//
 //
 // 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
 //
 //===----------------------------------------------------------------------===//
 
 #ifndef LLDB_UTILITY_DIAGNOSTICS_H
 #define LLDB_UTILITY_DIAGNOSTICS_H
 
 #include "lldb/Utility/FileSpec.h"
 #include "lldb/Utility/Log.h"
+#include "llvm/ADT/BitmaskEnum.h"
 #include "llvm/ADT/Optional.h"
 #include "llvm/ADT/SmallVector.h"
 #include "llvm/ADT/StringSet.h"
 #include "llvm/Support/Error.h"
 
 #include <functional>
 #include <mutex>
 #include <vector>
 
 namespace lldb_private {
 
+enum class DiagnosticsLog : Log::MaskType {
+  LLDB = Log::ChannelFlag<0>,
+  LLVM_MARK_AS_BITMASK_ENUM(LLDB)
+};
+
+LLVM_ENABLE_BITMASK_ENUMS_IN_NAMESPACE();
+
+class LogChannelDiagnostics {
+public:
+  static void Initialize();
+  static void Terminate();
+};
+
+template <> Log::Channel &LogChannelFor<DiagnosticsLog>();
+
 /// Diagnostics are a collection of files to help investigate bugs and
 /// troubleshoot issues. Any part of the debugger can register itself with the
 /// help of a callback to emit one or more files into the diagnostic directory.
 class Diagnostics {
 public:
   Diagnostics();
   ~Diagnostics();
 
   /// Gather diagnostics in the given directory.
   llvm::Error Create(const FileSpec &dir);
 
   /// Gather diagnostics and print a message to the given output stream.
   bool Dump(llvm::raw_ostream &stream);
 
   using Callback = std::function<llvm::Error(const FileSpec &)>;
 
   void AddCallback(Callback callback);
 
   static Diagnostics &Instance();
   static void Initialize();
   static void Terminate();
 
 private:
   static llvm::Optional<Diagnostics> &InstanceImpl();
 
+  llvm::Error DumpAlwaysOnLog(const FileSpec &dir) const;
+
+  std::shared_ptr<RotatingLogHandler> m_always_on_log_handler;
+
   llvm::SmallVector<Callback, 4> m_callbacks;
   std::mutex m_callbacks_mutex;
 };
 
 } // namespace lldb_private
 
 #endif

lldb/include/lldb/Utility/Log.h

public:
   // necessary to enable a log channel in an atomic manner.
   class Channel {
     std::atomic<Log *> log_ptr;
     friend class Log;
 
   public:
     const llvm::ArrayRef<Category> categories;
     const MaskType default_flags;
+    const bool internal = false;
 
     template <typename Cat>
     constexpr Channel(llvm::ArrayRef<Log::Category> categories,
-                      Cat default_flags)
+                      Cat default_flags, bool internal = false)
         : log_ptr(nullptr), categories(categories),
-          default_flags(MaskType(default_flags)) {
+          default_flags(MaskType(default_flags)), internal(internal) {
       static_assert(
           std::is_same<Log::MaskType, std::underlying_type_t<Cat>>::value);
     }
 
     // This function is safe to call at any time. If the channel is disabled
     // after (or concurrently with) this function returning a non-null Log
     // pointer, it is still safe to attempt to write to the Log object -- the
     // output will be discarded.

 
 #define LLDB_LOG(log, ...)                                                     \
   do {                                                                         \
     ::lldb_private::Log *log_private = (log);                                  \
     if (log_private)                                                           \
       log_private->Format(__FILE__, __func__, __VA_ARGS__);                    \
   } while (0)
 
+#define LLDB_MULTI_LOG(log1, log2, ...)                                        \
+  do {                                                                         \
+    if (::lldb_private::Log *log_private = (log1))                             \
+      log_private->Format(__FILE__, __func__, __VA_ARGS__);                    \
+    if (::lldb_private::Log *log_private = (log2))                             \
+      log_private->Format(__FILE__, __func__, __VA_ARGS__);                    \
+  } while (0)
+
 #define LLDB_LOGF(log, ...)                                                    \
   do {                                                                         \
     ::lldb_private::Log *log_private = (log);                                  \
     if (log_private)                                                           \
       log_private->Printf(__VA_ARGS__);                                        \
   } while (0)
 
+#define LLDB_MULTI_LOGF(log1, log2, ...)                                       \
+  do {                                                                         \
+    if (::lldb_private::Log *log_private = (log1))                             \
+      log_private->Printf(__VA_ARGS__);                                        \
+    if (::lldb_private::Log *log_private = (log2))                             \
+      log_private->Printf(__VA_ARGS__);                                        \
+  } while (0)
+
 #define LLDB_LOGV(log, ...)                                                    \
   do {                                                                         \
     ::lldb_private::Log *log_private = (log);                                  \
     if (log_private && log_private->GetVerbose())                              \
       log_private->Format(__FILE__, __func__, __VA_ARGS__);                    \
   } while (0)
 
 // Write message to log, if error is set. In the log message refer to the error

lldb/source/Utility/Diagnostics.cpp

 #include "llvm/Support/Error.h"
 #include "llvm/Support/FileSystem.h"
 #include "llvm/Support/raw_ostream.h"
 
 using namespace lldb_private;
 using namespace lldb;
 using namespace llvm;
 
+static constexpr size_t g_num_log_messages = 100;
+
+static constexpr Log::Category g_categories[] = {
+    {{"lldb"}, {"diagnostics log for lldb"}, DiagnosticsLog::LLDB},
+};
+
+static Log::Channel g_channel(g_categories, DiagnosticsLog::LLDB,
+                              /*internal=*/true);
+
+template <> Log::Channel &lldb_private::LogChannelFor<DiagnosticsLog>() {
+  return g_channel;
+}
+
+void LogChannelDiagnostics::Initialize() {
+  Log::Register("diagnostics", g_channel);
+}
+
+void LogChannelDiagnostics::Terminate() { Log::Unregister("diagnostics"); }
+
 void Diagnostics::Initialize() {
+  LogChannelDiagnostics::Initialize();
   lldbassert(!InstanceImpl() && "Already initialized.");
   InstanceImpl().emplace();
 }
 
 void Diagnostics::Terminate() {
   lldbassert(InstanceImpl() && "Already terminated.");
   InstanceImpl().reset();
+  LogChannelDiagnostics::Terminate();
 }
 
 Optional<Diagnostics> &Diagnostics::InstanceImpl() {
   static Optional<Diagnostics> g_diagnostics;
   return g_diagnostics;
 }
 
 Diagnostics &Diagnostics::Instance() { return *InstanceImpl(); }
 
-Diagnostics::Diagnostics() {}
+Diagnostics::Diagnostics()
+    : m_always_on_log_handler(
+          std::make_shared<RotatingLogHandler>(g_num_log_messages)) {
+  const uint32_t log_options = LLDB_LOG_OPTION_PREPEND_THREAD_NAME;
+  Log::EnableLogChannel(m_always_on_log_handler, log_options, "diagnostics",
+                        {"all"}, llvm::nulls());
+  AddCallback([&](const FileSpec &dir) { return DumpAlwaysOnLog(dir); });
+}
 
-Diagnostics::~Diagnostics() {}
+Diagnostics::~Diagnostics() {
+  Log::DisableLogChannel("diagnostics", {"all"}, llvm::nulls());
+}
 
 void Diagnostics::AddCallback(Callback callback) {
   std::lock_guard<std::mutex> guard(m_callbacks_mutex);
   m_callbacks.push_back(callback);
 }
 
 bool Diagnostics::Dump(raw_ostream &stream) {
   SmallString<128> diagnostics_dir;
if (error) {
     stream << toString(std::move(error)) << '\n';
     return false;
   }
 
   return true;
 }
 
 Error Diagnostics::Create(const FileSpec &dir) {
+  LLDB_LOG(GetLog(DiagnosticsLog::LLDB), "Dumping {0} diagnostics to '{1}'",
+           m_callbacks.size(), dir.GetPath());
+
   for (Callback c : m_callbacks) {
     if (Error err = c(dir))
       return err;
   }
   return Error::success();
 }
+
+llvm::Error Diagnostics::DumpAlwaysOnLog(const FileSpec &dir) const {
+  FileSpec log_file = dir.CopyByAppendingPathComponent("always-on.log");
+  std::error_code ec;
+  llvm::raw_fd_ostream stream(log_file.GetPath(), ec, llvm::sys::fs::OF_None);
+  if (ec)
+    return errorCodeToError(ec);
+  m_always_on_log_handler->Dump(stream);
+  return Error::success();
+}

lldb/source/Utility/Log.cpp

void Log::ForEachChannelCategory(
   if (ch == g_channel_map->end())
     return;
 
   ForEachCategory(*ch, lambda);
 }
 
 std::vector<llvm::StringRef> Log::ListChannels() {
   std::vector<llvm::StringRef> result;
-  for (const auto &channel : *g_channel_map)
-    result.push_back(channel.first());
+  for (const auto &entry : *g_channel_map) {
+    if (!entry.second.m_channel.internal)
+      result.push_back(entry.first());
+  }
   return result;
 }
 
 void Log::ListAllLogChannels(llvm::raw_ostream &stream) {
   if (g_channel_map->empty()) {
     stream << "No logging channels are currently registered.\n";
     return;
   }
 
-  for (const auto &channel : *g_channel_map)
-    ListCategories(stream, channel);
+  for (const auto &entry : *g_channel_map) {
+    if (!entry.second.m_channel.internal)
+      ListCategories(stream, entry);
+  }
 }
 
 bool Log::GetVerbose() const {
   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) {

lldb/test/Shell/Diagnostics/TestLogChannel.test

+# RUN: %lldb -o 'log list' 2>&1 | FileCheck %s
+# CHECK-NOT: Logging categories for 'diagnostics'