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 ↗

(On Diff #87036)

This is also unnecessary.

lldb/include/lldb/Utility/Error.h

14 ↗

(On Diff #87036)

All these includes are now unnecessary :)

lldb/source/Host/common/Host.cpp

911 ↗

(On Diff #87036)

lol :)

952 ↗

(On Diff #87036)

looks like you forgot this one.

[clayborg]

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

lldb/trunk/include/lldb/Utility/Error.h

 //===-- Error.h -------------------------------------------------*- C++ -*-===//
 //
 //                     The LLVM Compiler Infrastructure
 //
 // This file is distributed under the University of Illinois Open Source
 // License. See LICENSE.TXT for details.
 //
 //===----------------------------------------------------------------------===//
 
 #ifndef __DCError_h__
 #define __DCError_h__
 #if defined(__cplusplus)
 
 #include "llvm/Support/DataTypes.h"
+#include "llvm/Support/FormatAdapters.h"
 #include "llvm/Support/FormatVariadic.h"
 
 #include <cstdarg>
 #include <cstdio>
 #include <string>
 
 #include "lldb/lldb-private.h"
 
 #include "llvm/Support/FormatVariadic.h"
 
 namespace lldb_private {
 
-class Log;
-
 //----------------------------------------------------------------------
 /// @class Error Error.h "lldb/Utility/Error.h"
 /// @brief An error handling class.
 ///
 /// This class is designed to be able to hold any error code that can be
 /// encountered on a given platform. The errors are stored as a value
 /// of type Error::ValueType. This value should be large enough to hold
 /// any and all errors that the class supports. Each error has an
public:
   /// Access the error type.
   ///
   /// @return
   ///     The error type enumeration value.
   //------------------------------------------------------------------
   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
   /// to \c MachKernel.
   ///
   /// @param[in] err
   ///     A mach error code.
   //------------------------------------------------------------------
protected:
   mutable std::string m_string; ///< A string representation of the error code.
 };
 
 } // namespace lldb_private
 
 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);
 };
 }
 
 #endif // #if defined(__cplusplus)
 #endif // #ifndef __DCError_h__

lldb/trunk/source/Core/Communication.cpp

case eConnectionStatusEndOfFile:
       done = true;
       break;
     case eConnectionStatusError: // Check GetError() for details
       if (error.GetType() == eErrorTypePOSIX && error.GetError() == EIO) {
         // EIO on a pipe is usually caused by remote shutdown
         comm->Disconnect();
         done = true;
       }
-      if (log)
-        error.LogIfError(
-            log, "%p Communication::ReadFromConnection () => status = %s", p,
+      if (error.Fail())
+        LLDB_LOG(log, "error: {0}, status = {1}", error,
                  Communication::ConnectionStatusAsCString(status));
       break;
     case eConnectionStatusInterrupted: // Synchronization signal from
                                        // SynchronizeWithReadThread()
       // The connection returns eConnectionStatusInterrupted only when there is
       // no
       // input pending to be read, so we can signal that.
       comm->BroadcastEvent(eBroadcastBitNoMorePendingInput);
       break;
     case eConnectionStatusNoConnection:   // No connection
     case eConnectionStatusLostConnection: // Lost connection while connected to
                                           // a valid connection
       done = true;
       LLVM_FALLTHROUGH;
     case eConnectionStatusTimedOut: // Request timed out
-      if (log)
-        error.LogIfError(
-            log, "%p Communication::ReadFromConnection () => status = %s", p,
+      if (error.Fail())
+        LLDB_LOG(log, "error: {0}, status = {1}", error,
                  Communication::ConnectionStatusAsCString(status));
       break;
     }
   }
   log = lldb_private::GetLogIfAllCategoriesSet(LIBLLDB_LOG_COMMUNICATION);
   if (log)
     log->Printf("%p Communication::ReadThread () thread exiting...", p);
 
   comm->m_read_thread_did_exit = true;

lldb/trunk/source/Host/common/Host.cpp

Error Host::LaunchProcessPosixSpawn(const char *exe_path,
                                     lldb::pid_t &pid) {
   Error error;
   Log *log(lldb_private::GetLogIfAllCategoriesSet(LIBLLDB_LOG_HOST |
                                                   LIBLLDB_LOG_PROCESS));
 
   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(log, "error: {0}, ::posix_spawnattr_init ( &attr )", error);
     return error;
+  }
 
   // Make a quick class that will cleanup the posix spawn attributes in case
   // we return in the middle of this function.
   lldb_utility::CleanUp<posix_spawnattr_t *, int> posix_spawnattr_cleanup(
       &attr, posix_spawnattr_destroy);
 
   sigset_t no_signals;
   sigset_t all_signals;
   sigemptyset(&no_signals);
   sigfillset(&all_signals);
   ::posix_spawnattr_setsigmask(&attr, &no_signals);
 #if defined(__linux__) || defined(__FreeBSD__)
   ::posix_spawnattr_setsigdefault(&attr, &no_signals);
 #else
   ::posix_spawnattr_setsigdefault(&attr, &all_signals);
 #endif
 
   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(log,
+             "error: {0}, ::posix_spawnattr_setflags ( &attr, flags={1:x} )",
+             error, 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/
 #if defined(__APPLE__) && !defined(__arm__)
 
   // Don't set the binpref if a shell was provided.  After all, that's only
   // going to affect what version of the shell
   // is launched, not what fork of the binary is launched.  We insert "arch
if (launch_info.GetShell() == nullptr) {
     if (cpu != 0 && cpu != static_cast<cpu_type_t>(UINT32_MAX) &&
         cpu != static_cast<cpu_type_t>(LLDB_INVALID_CPUTYPE) &&
         !(cpu == 0x01000007 && sub == 8)) // If haswell is specified, don't try
                                           // to set the CPU type or we will fail
     {
       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(log, "error: {0}, ::posix_spawnattr_setbinpref_np ( &attr, 1, "
+                      "cpu_type = {1:x}, count => {2} )",
+                 error, cpu, ocount);
 
       if (error.Fail() || ocount != 1)
         return error;
     }
   }
 
 #endif
 
#endif
   }
 
   ::pid_t result_pid = LLDB_INVALID_PROCESS_ID;
   const size_t num_file_actions = launch_info.GetNumFileActions();
   if (num_file_actions > 0) {
     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(log,
+               "error: {0}, ::posix_spawn_file_actions_init ( &file_actions )",
+               error);
       return error;
+    }
 
     // Make a quick class that will cleanup the posix spawn attributes in case
     // we return in the middle of this function.
     lldb_utility::CleanUp<posix_spawn_file_actions_t *, int>
         posix_spawn_file_actions_cleanup(&file_actions,
                                          posix_spawn_file_actions_destroy);
 
     for (size_t i = 0; i < num_file_actions; ++i) {
       const FileAction *launch_file_action =
           launch_info.GetFileActionAtIndex(i);
       if (launch_file_action) {
         if (!AddPosixSpawnFileAction(&file_actions, launch_file_action, log,
                                      error))
           return error;
       }
     }
 
     error.SetError(
         ::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(log, "error: {0}, ::posix_spawnp(pid => {1}, path = '{2}', "
+                    "file_actions = {3}, "
+                    "attr = {4}, argv = {5}, envp = {6} )",
+               error, 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]);
       }
     }
 
   } else {
     error.SetError(
         ::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(log, "error: {0}, ::posix_spawnp ( pid => {1}, path = '{2}', "
+                    "file_actions = NULL, attr = {3}, argv = {4}, envp = {5} )",
+               error, 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]);
       }
     }
   }
   pid = result_pid;
 
   if (working_dir) {
 #if defined(__APPLE__)
     // No more thread specific current working directory
bool Host::AddPosixSpawnFileAction(void *_file_actions, const FileAction *info,
   case FileAction::eFileActionClose:
     if (info->GetFD() == -1)
       error.SetErrorString(
           "invalid fd for posix_spawn_file_actions_addclose(...)");
     else {
       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(log, "error: {0}, posix_spawn_file_actions_addclose "
+                      "(action={1}, fd={2})",
+                 error, file_actions, info->GetFD());
     }
     break;
 
   case FileAction::eFileActionDuplicate:
     if (info->GetFD() == -1)
       error.SetErrorString(
           "invalid fd for posix_spawn_file_actions_adddup2(...)");
     else if (info->GetActionArgument() == -1)
       error.SetErrorString(
           "invalid duplicate fd for posix_spawn_file_actions_adddup2(...)");
     else {
       error.SetError(
           ::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(log, "error: {0}, posix_spawn_file_actions_adddup2 "
+                      "(action={1}, fd={2}, dup_fd={3})",
+                 error, file_actions, info->GetFD(), info->GetActionArgument());
     }
     break;
 
   case FileAction::eFileActionOpen:
     if (info->GetFD() == -1)
       error.SetErrorString(
           "invalid fd in posix_spawn_file_actions_addopen(...)");
     else {
       int oflag = info->GetActionArgument();
 
       mode_t mode = 0;
 
       if (oflag & O_CREAT)
         mode = 0640;
 
       error.SetError(::posix_spawn_file_actions_addopen(
                          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(
+            log, "error: {0}, posix_spawn_file_actions_addopen (action={1}, "
+                 "fd={2}, path='{3}', oflag={4}, mode={5})",
+            error, file_actions, info->GetFD(), info->GetPath(), oflag, mode);
     }
     break;
   }
   return error.Success();
 }
 #endif // !defined(__ANDROID__)
 #endif // defined (__APPLE__) || defined (__linux__) || defined (__FreeBSD__) ||
        // defined (__GLIBC__) || defined(__NetBSD__)

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

bool OperatingSystemGo::UpdateThreadList(ThreadList &old_thread_list,
   // The threads that are in "new_thread_list" upon entry are the threads from
   // the
   // lldb_private::Process subclass, no memory threads will be in this list.
 
   Error err;
   for (uint64_t i = 0; i < allglen; ++i) {
     goroutines.push_back(CreateGoroutineAtIndex(i, err));
     if (err.Fail()) {
-      err.PutToLog(log, "OperatingSystemGo::UpdateThreadList");
+      LLDB_LOG(log, "error: {0}", err);
       return new_thread_list.GetSize(false) > 0;
     }
   }
   // Make a map so we can match goroutines with backing threads.
   std::map<uint64_t, ThreadSP> stack_map;
   for (uint32_t i = 0; i < real_thread_list.GetSize(false); ++i) {
     ThreadSP thread = real_thread_list.GetThreadAtIndex(i, false);
     stack_map[thread->GetRegisterContext()->GetSP()] = thread;

lldb/trunk/source/Utility/Error.cpp

 
 //----------------------------------------------------------------------
 // Returns true if this object contains a value that describes an
 // error or otherwise non-success result.
 //----------------------------------------------------------------------
 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"
 //----------------------------------------------------------------------
 void Error::SetMachError(uint32_t err) {
   m_code = err;
   m_type = eErrorTypeMachKernel;
   m_string.clear();
 }

 // Returns true if the error code in this object is considered a
 // successful return value.
 //----------------------------------------------------------------------
 bool Error::Success() const { return m_code == 0; }
 
 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);
+}