[lldb] Inject commands into log output when directed to file

[hawkinsw]

Summary

When logging for the lldb channel is enabled for any category and the
channel output is being directed to a file, inject a copy of every
command entered. This change will make it easier to contextualize the
debugging output with any commands that the user entered.

[hawkinsw]

As always, thank you for the work that you all do on lldb! An amazing tool! It is so much fun to be able to help and I hope that this is a helpful addition. Please let me know whether this is something that you find useful and whether or not there are changes that I can make to get this patch acceptable!

[labath]

Just my opinion, but I wouldn't like to complicate the logging architecture with file-only log statements and cross-channel dependencies. If you want to cross-reference some other logging channel with the executed commands then I'd say you should enable both channels. We can definitely talk about making the command feature more prominently in the log stream.

[hawkinsw]

In D124922#3491190, @labath wrote:

Just my opinion, but I wouldn't like to complicate the logging architecture with file-only log statements and cross-channel dependencies. If you want to cross-reference some other logging channel with the executed commands then I'd say you should enable both channels. We can definitely talk about making the command feature more prominently in the log stream.

Thanks! I am just trying to be helpful!

You are suggesting that the user would always add commands to what you enable in order to have this feature? Ie,

log enable -f lldb.out lldb break commands

The only reason that would be less than ideal for me (personally) is that there is lots of other output that comes along with commands that I might not necessarily want.

Again, just trying to be helpful! Again, I am happy to do whatever the group consensus is!!

Just happy to participate!
Will

[labath]

Yeah, I guess that what I am saying.

For me the commands channel gives 6 lines of output for a command. Compared to what some of our other logging channels do, that's nothing.

[hawkinsw]

In D124922#3491214, @labath wrote:

Yeah, I guess that what I am saying.

For me the commands channel gives 6 lines of output for a command. Compared to what some of our other logging channels do, that's nothing.

Totally understand.

Whatever the consensus is, I am happy to oblige. I just have been having so much fun working with LLDB. While I have your ear, are there any other pain points where I could contribute?

[labath]

Heh, well.. there definitely are, though a lot of things that come to mind right now are not really suitable for a first-time contributor. Is there any specific are that you would like to know (or that you know already)?

One of the things that I ran into recently, but hadn't had time to fix is the relocation processing code in ObjectFileELF::ApplyRelocations. It's currently fairly messy, and mixes relocations of different architectures (which generally doesn't work as different constants mean different things depending on the architecture. If you could refactor the function such that it has a clear split between architectures, and still allows for code sharing for relocations that mean the same thing on each architecture, then that would be greatly appreciated.

You can try that out by compiling a .o file for some non-x86 architecture and checking whether lldb can read the debug info without asserting.

[hawkinsw]

In D124922#3491267, @labath wrote:

Heh, well.. there definitely are, though a lot of things that come to mind right now are not really suitable for a first-time contributor. Is there any specific are that you would like to know (or that you know already)?

One of the things that I ran into recently, but hadn't had time to fix is the relocation processing code in ObjectFileELF::ApplyRelocations. It's currently fairly messy, and mixes relocations of different architectures (which generally doesn't work as different constants mean different things depending on the architecture. If you could refactor the function such that it has a clear split between architectures, and still allows for code sharing for relocations that mean the same thing on each architecture, then that would be greatly appreciated.

You can try that out by compiling a .o file for some non-x86 architecture and checking whether lldb can read the debug info without asserting.

Thanks!!

If there is interest in pursuing this patch, I will keep it open!

I have committed several typo changes in the past and I am a fairly seasoned developer. In fact, I have another outstanding patch waiting for review.

I will definitely look in to what you suggest. I hope that you will see some submissions forthcoming. Thanks again!

lldb/include/lldb/Utility/Log.h

 #include "llvm/Support/Error.h"
 #include "llvm/Support/FormatVariadic.h"
 #include "llvm/Support/ManagedStatic.h"
 #include "llvm/Support/RWMutex.h"
 
 #include <atomic>
 #include <cstdarg>
 #include <cstdint>
+#include <limits>
 #include <memory>
 #include <string>
 #include <type_traits>
 
 namespace llvm {
 class raw_ostream;
 }
 // Logging Options
 #define LLDB_LOG_OPTION_THREADSAFE (1u << 0)
 #define LLDB_LOG_OPTION_VERBOSE (1u << 1)
 #define LLDB_LOG_OPTION_PREPEND_SEQUENCE (1u << 3)
 #define LLDB_LOG_OPTION_PREPEND_TIMESTAMP (1u << 4)
 #define LLDB_LOG_OPTION_PREPEND_PROC_AND_THREAD (1u << 5)
 #define LLDB_LOG_OPTION_PREPEND_THREAD_NAME (1U << 6)
 #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_LOG_TO_FILE (1U << 10)
 
 // Logging Functions
 namespace lldb_private {
 
 class Log final {
 public:
   /// The underlying type of all log channel enums. Declare them as:
   /// enum class MyLog : MaskType {

 /// Returns a valid Log object if any of the provided categories are enabled.
 /// Otherwise, returns nullptr.
 template <typename Cat> Log *GetLog(Cat mask) {
   static_assert(std::is_same<Log::MaskType, std::underlying_type_t<Cat>>::value,
                 "");
   return LogChannelFor<Cat>().GetLog(Log::MaskType(mask));
 }
 
+/// Retrieve the Log object for a channel when any of its categories are
+/// enabled.
+///
+/// Returns a valid Log object if any of the categories for a channel are
+/// enabled. Otherwise, returns nullptr.
+template <typename Channel> Log *GetChannelLogWhenAnyCategoryEnabled() {
+  static_assert(
+      std::is_same<Log::MaskType, std::underlying_type_t<Channel>>::value, "");
+  Log::MaskType any_category_flag = std::numeric_limits<Log::MaskType>::max();
+  return LogChannelFor<Channel>().GetLog(any_category_flag);
+}
+
 } // namespace lldb_private
 
 /// The LLDB_LOG* macros defined below are the way to emit log messages.
 ///
 /// Note that the macros surround the arguments in a check for the log
 /// being on, so you can freely call methods in arguments without affecting
 /// the non-log execution flow.
 ///

 
 #define LLDB_LOGF(log, ...)                                                    \
   do {                                                                         \
     ::lldb_private::Log *log_private = (log);                                  \
     if (log_private)                                                           \
       log_private->Printf(__VA_ARGS__);                                        \
   } while (0)
 
+// Write a message to the log only if that log is sending its output to a file.
+#define LLDB_LOGF_FILE_ONLY(log, ...)                                          \
+  do {                                                                         \
+    ::lldb_private::Log *log_private = (log);                                  \
+    if (log_private &&                                                         \
+        log_private->GetOptions().Test(LLDB_LOG_OPTION_LOG_TO_FILE))           \
+      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/Commands/CommandObjectLog.cpp

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);
+        log_options |= LLDB_LOG_OPTION_LOG_TO_FILE;
         break;
       case 't':
         log_options |= LLDB_LOG_OPTION_THREADSAFE;
         break;
       case 'v':
         log_options |= LLDB_LOG_OPTION_VERBOSE;
         break;
       case 's':

lldb/source/Interpreter/CommandInterpreter.cpp

 bool CommandInterpreter::HandleCommand(const char *command_line,
                                        LazyBool lazy_add_to_history,
                                        CommandReturnObject &result) {
 
   std::string command_string(command_line);
   std::string original_command_string(command_line);
 
   Log *log = GetLog(LLDBLog::Commands);
+  Log *lldb_log = GetChannelLogWhenAnyCategoryEnabled<LLDBLog>();
   llvm::PrettyStackTraceFormat stack_trace("HandleCommand(command = \"%s\")",
                                    command_line);
 
   LLDB_LOGF(log, "Processing command: %s", command_line);
   LLDB_SCOPED_TIMERF("Processing command: %s.", command_line);
+  // If there is logging enabled for any category in the lldb channel that
+  // is being directed to a file, log every command. This functionality will
+  // make it easier for the user reading a log file after the fact to correlate
+  // the debugging output with the commands that may have caused it.
+  LLDB_LOGF_FILE_ONLY(lldb_log, "(lldb) %s\n", command_line);
 
   if (WasInterrupted()) {
     result.AppendError("interrupted");
     return false;
   }
 
   bool add_to_history;
   if (lazy_add_to_history == eLazyBoolCalculate)