Change Error::PutToLog to LLDB_LOG_ERROR

[zturner]

Summary

Instead of having the Error class (which is in Utility) know about logging (which is in Core), it seems more appropriate to put all logging code together, and teach Log about errors rather than teaching Error about logs. This patch does so.

[labath]

I'm not opposed to this patch, if people really want it, but I don't really see the value of this macro.
Why couldn't I write
LLDB_LOG(log, "foo: {0}", error);
instead of
LLDB_LOG_ERROR(log, error, "foo");
Am I missing something?

[labath]

As for the modules part, I assumed the Log class will end up in the lowest layer also. I intended to move it there after I am done with it, but we can do it sooner if that is stopping you from doing anything. ( I do agree that it makes sense to reverse the dependency though).

[clayborg]

I realize the functionality would add a "error: " prefix if it wasn't there, but it seems like we could add this as a formatting option of the lldb_private::Error class? Then we can just switch the logging code to put the error in as a log item and add the extra flag to ensure we print "error:" it is isn't already prefixed with that?

[clayborg]

So I agree with Pavel. Let us know what you think

[zturner]

In D29514#666285, @labath wrote:

I'm not opposed to this patch, if people really want it, but I don't really see the value of this macro.
Why couldn't I write
LLDB_LOG(log, "foo: {0}", error);
instead of
LLDB_LOG_ERROR(log, error, "foo");
Am I missing something?

I'm all for making it simpler. The reason I did it this way is that I wanted to keep the exact same syntax as before to minimize the impact of the change. It's rather confusing, but suppose you have these two errors:

1. E1 = Success, message = "The operation completed successfully", code = 0
2. E2 = Error, message = "The operation failed", code = 0x12345

When you call PutToLog(E1, "While reading the %d'th item", 7) it will log the string While reading the 7'th item err = 0x0
When you call PutToLog(E2, "While reading the %d'th item", 7) it will log the string error: While reading the 7'th item err = The operation failed (0x12345)

If we do what you suggest, then we are relying on the lldb::Error format provider, which does not have the ability to accept this kind of "contextual reason" string (i.e. the string "While reading the %d'th item" in the above example). So if we did this:

LLDB_LOG(log, error, "While reading the {0}'th item", 7)

Then the entire error must be formatted independently of the entire context string. So we could produce the output error: The operation failed (0x12345), context: While reading the 7'th item but this is slightly different from what was being printed before.

I didn't actually try this approach and see if anything broke, because Windows runs much fewer tests than the rest of LLDB, so even if my test suite passed, it wouldn't guarantee that another test somewhere else wasn't relying on the message being exactly as it currently prints.

[labath]

In D29514#666341, @zturner wrote:

If we do what you suggest, then we are relying on the lldb::Error format provider, which does not have the ability to accept this kind of "contextual reason" string (i.e. the string "While reading the %d'th item" in the above example). So if we did this:

LLDB_LOG(log, error, "While reading the {0}'th item", 7)

Then the entire error must be formatted independently of the entire context string. So we could produce the output error: The operation failed (0x12345), context: While reading the 7'th item but this is slightly different from what was being printed before.

I didn't actually try this approach and see if anything broke, because Windows runs much fewer tests than the rest of LLDB, so even if my test suite passed, it wouldn't guarantee that another test somewhere else wasn't relying on the message being exactly as it currently prints.

I doubt anything is depending on the exact string printed to the log. We should just make the new output makes sense.
I'd format this message like this:
LLDB_LOG(log, "Reading the {0}'th item: {1}", 7, error)
which should give you something like:
Reading 7th item: Too many open files.
if you want, we can add the "error:" prefix, numeric error code, or something to the format provider,, but this would be enough for me.

[zturner]

Fair enough, I can do that.

[labath]

looks good, just make sure it compiles.

lldb/include/lldb/Core/Log.h

18

This is also unnecessary.

lldb/include/lldb/Utility/Error.h

14

All these includes are now unnecessary :)

lldb/source/Host/common/Host.cpp

911

lol :)

952

looks like you forgot this one.

[clayborg]

Much better, just clean up the unnecessary includes and we are good to go.

lldb/include/lldb/Core/Log.h

 #include "lldb/Core/Logging.h"
 #include "lldb/Core/PluginInterface.h"
 #include "lldb/Utility/ConstString.h"
+#include "lldb/Utility/Error.h"
 #include "lldb/lldb-private.h"
 
 // Other libraries and framework includes

       log_private->Format(__FILE__, __FUNCTION__, __VA_ARGS__);                \
   } while (0)
 
+#define LLDB_LOG_ERROR(log, error, ...)                                        \
+  do {                                                                         \
+    ::lldb_private::Log *log_private = (log);                                  \
+    if (log_private) {                                                         \
+      log_private->Format(                                                     \
+          __FILE__, __FUNCTION__, "{0}",                                       \
+          fmt_error_context(std::forward<lldb_private::Error>(error),          \
+                            __VA_ARGS__));                                     \
+    }                                                                          \
+  } while (0)
+
 #endif // liblldb_Log_h_

lldb/include/lldb/Utility/Error.h

 #define __DCError_h__
 #if defined(__cplusplus)
 
+#include "llvm/ADT/StringRef.h"
+#include "llvm/ADT/Twine.h"
 #include "llvm/Support/DataTypes.h"
+#include "llvm/Support/FormatAdapters.h"
 #include "llvm/Support/FormatVariadic.h"
 
 #include <cstdarg>

 
 namespace lldb_private {
 
-class Log;
-
 //----------------------------------------------------------------------
 /// @class Error Error.h "lldb/Utility/Error.h"
 /// @brief An error handling class.

   lldb::ErrorType GetType() const;
 
   //------------------------------------------------------------------
-  /// Log an error to Log().
-  ///
-  /// Log the error given a formatted string \a format. If the this
-  /// object contains an error code, update the error string to
-  /// contain the prefix "error: ", followed by the formatted string,
-  /// followed by the error value and any string that describes the
-  /// error value. This allows more context to be given to an error
-  /// string that remains cached in this object. Logging always occurs
-  /// even when the error code contains a non-error value.
-  ///
-  /// @param[in] format
-  ///     A printf style format string.
-  ///
-  /// @param[in] ...
-  ///     Variable arguments that are needed for the printf style
-  ///     format string \a format.
-  //------------------------------------------------------------------
-  void PutToLog(Log *log, const char *format, ...)
-      __attribute__((format(printf, 3, 4)));
-
-  //------------------------------------------------------------------
-  /// Log an error to Log() if the error value is an error.
-  ///
-  /// Log the error given a formatted string \a format only if the
-  /// error value in this object describes an error condition. If the
-  /// this object contains an error, update the error string to
-  /// contain the prefix "error: " followed by the formatted string,
-  /// followed by the error value and any string that describes the
-  /// error value. This allows more context to be given to an error
-  /// string that remains cached in this object.
-  ///
-  /// @param[in] format
-  ///     A printf style format string.
-  ///
-  /// @param[in] ...
-  ///     Variable arguments that are needed for the printf style
-  ///     format string \a format.
-  //------------------------------------------------------------------
-  void LogIfError(Log *log, const char *format, ...)
-      __attribute__((format(printf, 3, 4)));
-
-  //------------------------------------------------------------------
   /// Set accessor from a kern_return_t.
   ///
   /// Set accesssor for the error value to \a err and the error type

 namespace llvm {
 template <> struct format_provider<lldb_private::Error> {
   static void format(const lldb_private::Error &error, llvm::raw_ostream &OS,
-                     llvm::StringRef Options) {
-    llvm::format_provider<llvm::StringRef>::format(error.AsCString(), OS,
-                                                   Options);
+                     llvm::StringRef Options);
+};
+}
+
+namespace lldb_private {
+namespace detail {
+class ErrorWithContextAdapter final : public llvm::FormatAdapter<Error> {
+  std::string Context;
+
+public:
+  template <typename... Ts>
+  ErrorWithContextAdapter(Error &&Err, const char *Context, Ts &&... Args)
+      : FormatAdapter<Error>(std::forward<Error>(Err)) {
+    this->Context = llvm::formatv(Context, std::forward<Ts>(Args)...).str();
+  }
+
+  void format(llvm::raw_ostream &Stream, llvm::StringRef Style) {
+    if (Item.Fail()) {
+      const char *err_str = Item.AsCString();
+      if (err_str == nullptr)
+        err_str = "???";
+
+      Stream << llvm::formatv("error: {0} err = {1} ({2:x})", Context, err_str,
+                              Item.GetError());
+    } else {
+      Stream << llvm::formatv("{0} err = {1:x}", Context, Item.GetError());
+    }
   }
 };
 }
 
+template <typename... Ts>
+inline detail::ErrorWithContextAdapter
+fmt_error_context(Error &&Err, const char *Context, Ts &&... Args) {
+  return detail::ErrorWithContextAdapter(std::forward<Error>(Err), Context,
+                                         std::forward<Ts>(Args)...);
+}
+}
+
 #endif // #if defined(__cplusplus)
 #endif // #ifndef __DCError_h__

lldb/source/Core/Communication.cpp

         comm->Disconnect();
         done = true;
       }
-      if (log)
-        error.LogIfError(
-            log, "%p Communication::ReadFromConnection () => status = %s", p,
-            Communication::ConnectionStatusAsCString(status));
+      if (error.Fail())
+        LLDB_LOG_ERROR(log, error, "status = {0}",
+                       Communication::ConnectionStatusAsCString(status));
       break;
     case eConnectionStatusInterrupted: // Synchronization signal from
                                        // SynchronizeWithReadThread()

       done = true;
       LLVM_FALLTHROUGH;
     case eConnectionStatusTimedOut: // Request timed out
-      if (log)
-        error.LogIfError(
-            log, "%p Communication::ReadFromConnection () => status = %s", p,
-            Communication::ConnectionStatusAsCString(status));
+      if (error.Fail())
+        LLDB_LOG_ERROR(log, error, "status = {0}",
+                       Communication::ConnectionStatusAsCString(status));
       break;
     }
   }

lldb/source/Host/common/Host.cpp

   posix_spawnattr_t attr;
   error.SetError(::posix_spawnattr_init(&attr), eErrorTypePOSIX);
 
-  if (error.Fail() || log)
-    error.PutToLog(log, "::posix_spawnattr_init ( &attr )");
-  if (error.Fail())
+  if (error.Fail()) {
+    LLDB_LOG_ERROR(log, error, "::posix_spawnattr_init ( &attr )");
     return error;
+  }
 
   // Make a quick class that will cleanup the posix spawn attributes in case
   // we return in the middle of this function.

   short flags = GetPosixspawnFlags(launch_info);
 
   error.SetError(::posix_spawnattr_setflags(&attr, flags), eErrorTypePOSIX);
-  if (error.Fail() || log)
-    error.PutToLog(log, "::posix_spawnattr_setflags ( &attr, flags=0x%8.8x )",
-                   flags);
-  if (error.Fail())
+  if (error.Fail()) {
+    LLDB_LOG_ERROR(log, error, "::posix_spawnattr_setflags ( &attr, flags={0:x} )", flags);
     return error;
+  }
 
 // posix_spawnattr_setbinpref_np appears to be an Apple extension per:
 // http://www.unix.com/man-page/OSX/3/posix_spawnattr_setbinpref_np/

       size_t ocount = 0;
       error.SetError(::posix_spawnattr_setbinpref_np(&attr, 1, &cpu, &ocount),
                      eErrorTypePOSIX);
-      if (error.Fail() || log)
-        error.PutToLog(log, "::posix_spawnattr_setbinpref_np ( &attr, 1, "
-                            "cpu_type = 0x%8.8x, count => %llu )",
-                       cpu, (uint64_t)ocount);
+      if (error.Fail())
+        LLDB_LOG_ERROR(log, error, "::posix_spawnattr_setbinpref_np ( &attr, 1, "
+                            "cpu_type = {0:x}, count => {1} )", cpu, ocount);
 
       if (error.Fail() || ocount != 1)
         return error;

     posix_spawn_file_actions_t file_actions;
     error.SetError(::posix_spawn_file_actions_init(&file_actions),
                    eErrorTypePOSIX);
-    if (error.Fail() || log)
-      error.PutToLog(log, "::posix_spawn_file_actions_init ( &file_actions )");
-    if (error.Fail())
+    if (error.Fail()) {
+      LLDB_LOG_ERROR(log, error, "::posix_spawn_file_actions_init ( &file_actions )");
       return error;
+    }
 
     // Make a quick class that will cleanup the posix spawn attributes in case
     // we return in the middle of this function.

         ::posix_spawnp(&result_pid, exe_path, &file_actions, &attr, argv, envp),
         eErrorTypePOSIX);
 
-    if (error.Fail() || log) {
-      error.PutToLog(
-          log, "::posix_spawnp ( pid => %i, path = '%s', file_actions = %p, "
-               "attr = %p, argv = %p, envp = %p )",
-          result_pid, exe_path, static_cast<void *>(&file_actions),
-          static_cast<void *>(&attr), reinterpret_cast<const void *>(argv),
-          reinterpret_cast<const void *>(envp));
+    if (error.Fail()) {
+      LLDB_LOG_ERROR(log, error, "::posix_spawnp(pid => {0}, path = '{1}', file_actions = {2}, "
+               "attr = {3}, argv = {4}, envp = {5} )",
+          result_pid, exe_path, &file_actions, &attr, argv, envp);
       if (log) {
         for (int ii = 0; argv[ii]; ++ii)
-          log->Printf("argv[%i] = '%s'", ii, argv[ii]);
+          LLDB_LOG(log, "argv[{0}] = '{1}'", ii, argv[ii]);
       }
     }
 

         ::posix_spawnp(&result_pid, exe_path, NULL, &attr, argv, envp),
         eErrorTypePOSIX);
 
-    if (error.Fail() || log) {
-      error.PutToLog(log, "::posix_spawnp ( pid => %i, path = '%s', "
-                          "file_actions = NULL, attr = %p, argv = %p, envp = "
-                          "%p )",
-                     result_pid, exe_path, static_cast<void *>(&attr),
-                     reinterpret_cast<const void *>(argv),
-                     reinterpret_cast<const void *>(envp));
+    if (error.Fail()) {
+      LLDB_LOG_ERROR(log, error, "::posix_spawnp ( pid => {0}, path = '{1}', "
+        "file_actions = NULL, attr = {2}, argv = {3}, envp = {4} )",
+                     result_pid, exe_path, &attr, argv, envp);
       if (log) {
         for (int ii = 0; argv[ii]; ++ii)
-          log->Printf("argv[%i] = '%s'", ii, argv[ii]);
+          LLDB_LOG("argv[{0}] = '{1}'", ii, argv[ii]);
       }
     }
   }

       error.SetError(
           ::posix_spawn_file_actions_addclose(file_actions, info->GetFD()),
           eErrorTypePOSIX);
-      if (log && (error.Fail() || log))
-        error.PutToLog(log,
-                       "posix_spawn_file_actions_addclose (action=%p, fd=%i)",
-                       static_cast<void *>(file_actions), info->GetFD());
+      if (error.Fail())
+        LLDB_LOG_ERROR(log, error, "posix_spawn_file_actions_addclose (action={0}, fd={1})",
+                       file_actions, info->GetFD());
     }
     break;
 

           ::posix_spawn_file_actions_adddup2(file_actions, info->GetFD(),
                                              info->GetActionArgument()),
           eErrorTypePOSIX);
-      if (log && (error.Fail() || log))
-        error.PutToLog(
-            log,
-            "posix_spawn_file_actions_adddup2 (action=%p, fd=%i, dup_fd=%i)",
-            static_cast<void *>(file_actions), info->GetFD(),
-            info->GetActionArgument());
+      if (error.Fail())
+        LLDB_LOG_ERROR(log, error, 
+            "posix_spawn_file_actions_adddup2 (action={0}, fd={1}, dup_fd={2})",
+            file_actions, info->GetFD(), info->GetActionArgument());
     }
     break;
 

                          file_actions, info->GetFD(),
                          info->GetPath().str().c_str(), oflag, mode),
                      eErrorTypePOSIX);
-      if (error.Fail() || log)
-        error.PutToLog(log, "posix_spawn_file_actions_addopen (action=%p, "
-                            "fd=%i, path='%s', oflag=%i, mode=%i)",
-                       static_cast<void *>(file_actions), info->GetFD(),
-                       info->GetPath().str().c_str(), oflag, mode);
+      if (error.Fail())
+        LLDB_LOG_ERROR(log, error, "posix_spawn_file_actions_addopen (action={0}, "
+                            "fd={1}, path='{2}', oflag={3}, mode={4})",
+                       file_actions, info->GetFD(), info->GetPath(), oflag, mode);
     }
     break;
   }

lldb/source/Plugins/OperatingSystem/Go/OperatingSystemGo.cpp

   for (uint64_t i = 0; i < allglen; ++i) {
     goroutines.push_back(CreateGoroutineAtIndex(i, err));
     if (err.Fail()) {
-      err.PutToLog(log, "OperatingSystemGo::UpdateThreadList");
+      LLDB_LOG_ERROR(log, err, "OperatingSystemGo::UpdateThreadList");
       return new_thread_list.GetSize(false) > 0;
     }
   }

lldb/source/Utility/Error.cpp

 bool Error::Fail() const { return m_code != 0; }
 
 //----------------------------------------------------------------------
-// Log the error given a string with format. If the this object
-// contains an error code, update the error string to contain the
-// "error: " followed by the formatted string, followed by the error
-// value and any string that describes the current error. This
-// allows more context to be given to an error string that remains
-// cached in this object. Logging always occurs even when the error
-// code contains a non-error value.
-//----------------------------------------------------------------------
-void Error::PutToLog(Log *log, const char *format, ...) {
-  char *arg_msg = nullptr;
-  va_list args;
-  va_start(args, format);
-  ::vasprintf(&arg_msg, format, args);
-  va_end(args);
-
-  if (arg_msg != nullptr) {
-    if (Fail()) {
-      const char *err_str = AsCString();
-      if (err_str == nullptr)
-        err_str = "???";
-
-      SetErrorStringWithFormat("error: %s err = %s (0x%8.8x)", arg_msg, err_str,
-                               m_code);
-      if (log != nullptr)
-        log->Error("%s", m_string.c_str());
-    } else {
-      if (log != nullptr)
-        log->Printf("%s err = 0x%8.8x", arg_msg, m_code);
-    }
-    ::free(arg_msg);
-  }
-}
-
-//----------------------------------------------------------------------
-// Log the error given a string with format. If the this object
-// contains an error code, update the error string to contain the
-// "error: " followed by the formatted string, followed by the error
-// value and any string that describes the current error. This
-// allows more context to be given to an error string that remains
-// cached in this object. Logging only occurs even when the error
-// code contains a error value.
-//----------------------------------------------------------------------
-void Error::LogIfError(Log *log, const char *format, ...) {
-  if (Fail()) {
-    char *arg_msg = nullptr;
-    va_list args;
-    va_start(args, format);
-    ::vasprintf(&arg_msg, format, args);
-    va_end(args);
-
-    if (arg_msg != nullptr) {
-      const char *err_str = AsCString();
-      if (err_str == nullptr)
-        err_str = "???";
-
-      SetErrorStringWithFormat("%s err = %s (0x%8.8x)", arg_msg, err_str,
-                               m_code);
-      if (log != nullptr)
-        log->Error("%s", m_string.c_str());
-
-      ::free(arg_msg);
-    }
-  }
-}
-
-//----------------------------------------------------------------------
 // Set accesssor for the error value to "err" and the type to
 // "eErrorTypeMachKernel"
 //----------------------------------------------------------------------

 bool Error::WasInterrupted() const {
   return (m_type == eErrorTypePOSIX && m_code == EINTR);
 }
+
+void llvm::format_provider<lldb_private::Error>::format(
+    const lldb_private::Error &error, llvm::raw_ostream &OS,
+    llvm::StringRef Options) {
+  llvm::format_provider<llvm::StringRef>::format(error.AsCString(), OS,
+                                                 Options);
+}

llvm/include/llvm/Support/FormatProviders.h

 #include "llvm/ADT/Optional.h"
 #include "llvm/ADT/STLExtras.h"
 #include "llvm/ADT/StringSwitch.h"
+#include "llvm/ADT/Twine.h"
 #include "llvm/Support/FormatVariadicDetails.h"
 #include "llvm/Support/NativeFormatting.h"
 

   }
 };
 
+template <> struct format_provider<Twine> {
+  static void format(const Twine &T, raw_ostream &Stream, StringRef Style) {
+    Stream << T;
+  }
+};
+
 /// Implementation of format_provider<T> for floating point types.
 ///
 /// The options string of a floating point type has the format: