Add a more succinct logging syntax

This adds the LLDB_LOG macro, which enables one to write more succinct log
statements.
if (log)
  log->Printf("log something: %d", var);
becomes
LLDB_LOG(log, "log something: {0}, var);

The macro still internally does the "if(log)" dance, so the arguments are only
evaluated if logging is enabled, meaning it has the same overhead as the
previous syntax.

Additionally, the log statements will be automatically prefixed with the file
and function generating the log (if the corresponding new argument to the "log
enable" command is enabled), so one does not need to manually specify this in
the log statement.

It also uses the new llvm formatv syntax, which means we don't have to worry
about PRIx64 macros and similar, and we can log complex object (llvm::StringRef,
lldb_private::Error, ...) more easily.

Differential Revision: https://reviews.llvm.org/D27459

llvm-svn: 292360

7 files changed, 165 insertions, 65 deletions

diff --git a/lldb/include/lldb/Core/Log.h b/lldb/include/lldb/Core/Log.h
index d87c263a427..97fc5eb1a6d 100644
--- a/lldb/include/lldb/Core/Log.h
+++ b/lldb/include/lldb/Core/Log.h
@@ -10,14 +10,6 @@
 #ifndef liblldb_Log_h_
 #define liblldb_Log_h_
 
-// C Includes
-#include <signal.h>
-#include <stdarg.h>
-#include <stdint.h>
-#include <stdio.h>
-
-// C++ Includes
-// Other libraries and framework includes
 // Project includes
 #include "lldb/Core/ConstString.h"
 #include "lldb/Core/Flags.h"
@@ -25,7 +17,12 @@
 #include "lldb/Core/PluginInterface.h"
 #include "lldb/lldb-private.h"
 
+// Other libraries and framework includes
 #include "llvm/Support/FormatVariadic.h"
+// C++ Includes
+#include <cstdarg>
+#include <cstdint>
+// C Includes
 
 //----------------------------------------------------------------------
 // Logging Options
@@ -39,6 +36,7 @@
 #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)
 
 //----------------------------------------------------------------------
 // Logging Functions
@@ -109,8 +107,10 @@ public:
   void PutCString(const char *cstr);
   void PutString(llvm::StringRef str);
 
-  template <typename... Args> void Format(const char *fmt, Args &&... args) {
-    PutString(llvm::formatv(fmt, std::forward<Args>(args)...).str());
+  template <typename... Args>
+  void Format(llvm::StringRef file, llvm::StringRef function,
+              const char *format, Args &&... args) {
+    Format(file, function, llvm::formatv(format, std::forward<Args>(args)...));
   }
 
   // CLEANUP: Add llvm::raw_ostream &Stream() function.
@@ -155,6 +155,13 @@ protected:
 
 private:
   DISALLOW_COPY_AND_ASSIGN(Log);
+
+  void WriteHeader(llvm::raw_ostream &OS, llvm::StringRef file,
+                   llvm::StringRef function);
+  void WriteMessage(const std::string &message);
+
+  void Format(llvm::StringRef file, llvm::StringRef function,
+              const llvm::formatv_object_base &payload);
 };
 
 class LogChannel : public PluginInterface {
@@ -186,4 +193,11 @@ private:
 
 } // namespace lldb_private
 
+#define LLDB_LOG(log, ...)                                                     \
+  do {                                                                         \
+    ::lldb_private::Log *log_private = (log);                                  \
+    if (log_private)                                                           \
+      log_private->Format(__FILE__, __FUNCTION__, __VA_ARGS__);                \
+  } while (0)
+
 #endif // liblldb_Log_h_
diff --git a/lldb/source/Commands/CommandObjectLog.cpp b/lldb/source/Commands/CommandObjectLog.cpp
index 3fdd888d2ed..6b219e0a752 100644
--- a/lldb/source/Commands/CommandObjectLog.cpp
+++ b/lldb/source/Commands/CommandObjectLog.cpp
@@ -48,6 +48,7 @@ static OptionDefinition g_log_options[] = {
   { LLDB_OPT_SET_1, false, "thread-name",'n', OptionParser::eNoArgument,       nullptr, nullptr, 0, eArgTypeNone,     "Prepend all log lines with the thread name for the thread that generates the log line." },
   { LLDB_OPT_SET_1, false, "stack",      'S', OptionParser::eNoArgument,       nullptr, nullptr, 0, eArgTypeNone,     "Append a stack backtrace to each log line." },
   { LLDB_OPT_SET_1, false, "append",     'a', OptionParser::eNoArgument,       nullptr, nullptr, 0, eArgTypeNone,     "Append to the log file instead of overwriting." },
+  { LLDB_OPT_SET_1, false, "file-function",'F',OptionParser::eNoArgument,      nullptr, nullptr, 0, eArgTypeNone,     "Prepend the names of files and function that generate the logs." },
     // clang-format on
 };
 
@@ -130,6 +131,8 @@ public:
       case 'a':
         log_options |= LLDB_LOG_OPTION_APPEND;
         break;
+      case 'F':
+        log_options |= LLDB_LOG_OPTION_PREPEND_FILE_FUNCTION;
       default:
         error.SetErrorStringWithFormat("unrecognized option '%c'",
                                        short_option);
diff --git a/lldb/source/Core/Log.cpp b/lldb/source/Core/Log.cpp
index 28fb711b0ae..1329ea05917 100644
--- a/lldb/source/Core/Log.cpp
+++ b/lldb/source/Core/Log.cpp
@@ -20,6 +20,7 @@
 // Other libraries and framework includes
 #include "llvm/ADT/SmallString.h"
 #include "llvm/Support/Chrono.h"
+#include "llvm/Support/Path.h"
 #include "llvm/Support/Signals.h"
 #include "llvm/Support/raw_ostream.h"
 
@@ -69,58 +70,18 @@ void Log::Printf(const char *format, ...) {
 // a valid file handle, we also log to the file.
 //----------------------------------------------------------------------
 void Log::VAPrintf(const char *format, va_list args) {
-  // Make a copy of our stream shared pointer in case someone disables our
-  // log while we are logging and releases the stream
-  StreamSP stream_sp(m_stream_sp);
-  if (stream_sp) {
-    static uint32_t g_sequence_id = 0;
-    StreamString header;
-
-    // Add a sequence ID if requested
-    if (m_options.Test(LLDB_LOG_OPTION_PREPEND_SEQUENCE))
-      header.Printf("%u ", ++g_sequence_id);
-
-    // Timestamp if requested
-    if (m_options.Test(LLDB_LOG_OPTION_PREPEND_TIMESTAMP)) {
-      auto now = std::chrono::duration<double>(
-          std::chrono::system_clock::now().time_since_epoch());
-      header.Printf("%.9f ", now.count());
-    }
+  std::string message_string;
+  llvm::raw_string_ostream message(message_string);
+  WriteHeader(message, "", "");
 
-    // Add the process and thread if requested
-    if (m_options.Test(LLDB_LOG_OPTION_PREPEND_PROC_AND_THREAD))
-      header.Printf("[%4.4x/%4.4" PRIx64 "]: ", getpid(),
-                    Host::GetCurrentThreadID());
-
-    // Add the thread name if requested
-    if (m_options.Test(LLDB_LOG_OPTION_PREPEND_THREAD_NAME)) {
-      llvm::SmallString<32> thread_name;
-      ThisThread::GetName(thread_name);
-      if (!thread_name.empty())
-        header.Printf("%s ", thread_name.c_str());
-    }
-
-    header.PrintfVarArg(format, args);
-    header.PutCString("\n");
+  char *text;
+  vasprintf(&text, format, args);
+  message << text;
+  free(text);
 
-    if (m_options.Test(LLDB_LOG_OPTION_BACKTRACE)) {
-      std::string back_trace;
-      llvm::raw_string_ostream stream(back_trace);
-      llvm::sys::PrintStackTrace(stream);
-      stream.flush();
-      header.PutCString(back_trace);
-    }
+  message << "\n";
 
-    if (m_options.Test(LLDB_LOG_OPTION_THREADSAFE)) {
-      static std::recursive_mutex g_LogThreadedMutex;
-      std::lock_guard<std::recursive_mutex> guard(g_LogThreadedMutex);
-      stream_sp->PutCString(header.GetString());
-      stream_sp->Flush();
-    } else {
-      stream_sp->PutCString(header.GetString());
-      stream_sp->Flush();
-    }
-  }
+  WriteMessage(message.str());
 }
 
 //----------------------------------------------------------------------
@@ -353,6 +314,71 @@ bool Log::GetDebug() const {
   return false;
 }
 
+void Log::WriteHeader(llvm::raw_ostream &OS, llvm::StringRef file,
+                      llvm::StringRef function) {
+  static uint32_t g_sequence_id = 0;
+  // Add a sequence ID if requested
+  if (m_options.Test(LLDB_LOG_OPTION_PREPEND_SEQUENCE))
+    OS << ++g_sequence_id << " ";
+
+  // Timestamp if requested
+  if (m_options.Test(LLDB_LOG_OPTION_PREPEND_TIMESTAMP)) {
+    auto now = std::chrono::duration<double>(
+        std::chrono::system_clock::now().time_since_epoch());
+    OS << llvm::formatv("{0:f9} ", now.count());
+  }
+
+  // Add the process and thread if requested
+  if (m_options.Test(LLDB_LOG_OPTION_PREPEND_PROC_AND_THREAD))
+    OS << llvm::formatv("[{0,0+4}/{1,0+4}] ", getpid(),
+                        Host::GetCurrentThreadID());
+
+  // Add the thread name if requested
+  if (m_options.Test(LLDB_LOG_OPTION_PREPEND_THREAD_NAME)) {
+    llvm::SmallString<32> thread_name;
+    ThisThread::GetName(thread_name);
+    if (!thread_name.empty())
+      OS << thread_name;
+  }
+
+  if (m_options.Test(LLDB_LOG_OPTION_BACKTRACE))
+    llvm::sys::PrintStackTrace(OS);
+
+  if (m_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());
+  }
+}
+
+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
+  StreamSP stream_sp(m_stream_sp);
+  if (!stream_sp)
+    return;
+
+  if (m_options.Test(LLDB_LOG_OPTION_THREADSAFE)) {
+    static std::recursive_mutex g_LogThreadedMutex;
+    std::lock_guard<std::recursive_mutex> guard(g_LogThreadedMutex);
+    stream_sp->PutCString(message.c_str());
+    stream_sp->Flush();
+  } else {
+    stream_sp->PutCString(message.c_str());
+    stream_sp->Flush();
+  }
+}
+
+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";
+  WriteMessage(message.str());
+}
+
 LogChannelSP LogChannel::FindPlugin(const char *plugin_name) {
   LogChannelSP log_channel_sp;
   LogChannelMap &channel_map = GetChannelMap();
diff --git a/lldb/source/Plugins/ExpressionParser/Clang/IRForTarget.cpp b/lldb/source/Plugins/ExpressionParser/Clang/IRForTarget.cpp
index 356e2e7eba2..6545b9d99bc 100644
--- a/lldb/source/Plugins/ExpressionParser/Clang/IRForTarget.cpp
+++ b/lldb/source/Plugins/ExpressionParser/Clang/IRForTarget.cpp
@@ -512,11 +512,9 @@ bool IRForTarget::RewriteObjCConstString(llvm::GlobalVariable *ns_str,
    break;
  default:
    encoding_flags = 0x0600; /* fall back to 0x0600, kCFStringEncodingASCII */
-   if (log) {
-     log->Format("Encountered an Objective-C constant string with unusual "
+   LLDB_LOG(log, "Encountered an Objective-C constant string with unusual "
                  "element size {0}",
-                 string_array->getElementByteSize());
-   }
+            string_array->getElementByteSize());
  }
  Constant *encoding_arg = ConstantInt::get(i32_ty, encoding_flags, false);
  Constant *isExternal_arg =
diff --git a/lldb/tools/lldb-server/lldb-gdbserver.cpp b/lldb/tools/lldb-server/lldb-gdbserver.cpp
index 5a388722b3c..85c68f0fe6e 100644
--- a/lldb/tools/lldb-server/lldb-gdbserver.cpp
+++ b/lldb/tools/lldb-server/lldb-gdbserver.cpp
@@ -424,8 +424,10 @@ int main_gdbserver(int argc, char *argv[]) {
     exit(option_error);
   }
 
-  if (!LLDBServerUtilities::SetupLogging(log_file, log_channels,
-                                         LLDB_LOG_OPTION_PREPEND_TIMESTAMP))
+  if (!LLDBServerUtilities::SetupLogging(
+          log_file, log_channels,
+          LLDB_LOG_OPTION_PREPEND_TIMESTAMP |
+              LLDB_LOG_OPTION_PREPEND_FILE_FUNCTION))
     return -1;
 
   Log *log(lldb_private::GetLogIfAnyCategoriesSet(GDBR_LOG_VERBOSE));
diff --git a/lldb/unittests/Core/CMakeLists.txt b/lldb/unittests/Core/CMakeLists.txt
index 980bc5b9f9a..d5a7d533637 100644
--- a/lldb/unittests/Core/CMakeLists.txt
+++ b/lldb/unittests/Core/CMakeLists.txt
@@ -4,6 +4,7 @@ add_lldb_unittest(LLDBCoreTests
   DataExtractorTest.cpp
   ErrorTest.cpp
   ListenerTest.cpp
+  LogTest.cpp
   ScalarTest.cpp
   StructuredDataTest.cpp
   TimerTest.cpp
diff --git a/lldb/unittests/Core/LogTest.cpp b/lldb/unittests/Core/LogTest.cpp
new file mode 100644
index 00000000000..46640edfb15
--- /dev/null
+++ b/lldb/unittests/Core/LogTest.cpp
@@ -0,0 +1,56 @@
+//===-- LogTest.cpp ---------------------------------------------*- C++ -*-===//
+//
+//                     The LLVM Compiler Infrastructure
+//
+// This file is distributed under the University of Illinois Open Source
+// License. See LICENSE.TXT for details.
+//
+//===----------------------------------------------------------------------===//
+
+#include "lldb/Core/Log.h"
+#include "lldb/Core/StreamString.h"
+#include "lldb/Host/Host.h"
+#include "gtest/gtest.h"
+
+using namespace lldb;
+using namespace lldb_private;
+
+static std::string GetLogString(uint32_t log_options, const char *format,
+                                int arg) {
+  std::shared_ptr<StreamString> stream_sp(new StreamString());
+  Log log_(stream_sp);
+  log_.GetOptions().Reset(log_options);
+  Log *log = &log_;
+  LLDB_LOG(log, format, arg);
+  return stream_sp->GetString();
+}
+
+TEST(LogTest, LLDB_LOG_nullptr) {
+  Log *log = nullptr;
+  LLDB_LOG(log, "{0}", 0); // Shouldn't crash
+}
+
+TEST(LogTest, log_options) {
+  EXPECT_EQ("Hello World 47\n", GetLogString(0, "Hello World {0}", 47));
+  EXPECT_EQ("Hello World 47\n",
+            GetLogString(LLDB_LOG_OPTION_THREADSAFE, "Hello World {0}", 47));
+
+  {
+    std::string msg =
+        GetLogString(LLDB_LOG_OPTION_PREPEND_SEQUENCE, "Hello World {0}", 47);
+    int seq_no;
+    EXPECT_EQ(1, sscanf(msg.c_str(), "%d Hello World 47", &seq_no));
+  }
+
+  EXPECT_EQ(
+      "LogTest.cpp:GetLogString                                     Hello "
+      "World 47\n",
+      GetLogString(LLDB_LOG_OPTION_PREPEND_FILE_FUNCTION, "Hello World {0}", 47));
+
+  EXPECT_EQ(llvm::formatv("[{0}/{1}] Hello World 47\n",
+                          Host::GetCurrentProcessID(),
+                          Host::GetCurrentThreadID())
+                .str(),
+            GetLogString(LLDB_LOG_OPTION_PREPEND_PROC_AND_THREAD,
+                         "Hello World {0}", 47));
+}