[lldb] Improve logging for process state change (NFC)

[mib]

Summary

This patch improves process state change logging messages to include to
process plugin name.

It also replaces the LLDB_LOGF macro by LLDB_LOG macro that adds the
class and method name in the log message using the compiler instead of
having to change the string litteral for every method.

This is very useful when investigating interactions between different
types of process plugins. That comes very handy when investigating bugs
related to interactive scripted process debugging.

Signed-off-by: Med Ismail Bennani <[e-mail]>

[JDevlieghere]

I think a lot of this can be simplified by using LLDB_LOG instead of LLDB_LOGF.

[bulbazord]

+1 to what Jonas said. LLDB_LOG would greatly simplify this since it puts __FILE__ and __func__ in each message, which is what these are doing manually.

[mib]

In D148399#4274470, @JDevlieghere wrote:

I think a lot of this can be simplified by using LLDB_LOG instead of LLDB_LOGF.

In D148399#4275219, @bulbazord wrote:

+1 to what Jonas said. LLDB_LOG would greatly simplify this since it puts __FILE__ and __func__ in each message, which is what these are doing manually.

@bulbazord @JDevlieghere I don't think using using LLDB_LOG instead of LLDB_LOGF would be of any use here, because we're interested because that will just say we're in Process::__func__. What we care about here is to know which process plugin calling that function, so I still have to pass GetPluginName as an argument.

[bulbazord]

We'd go from:

LLDB_LOGF(log,
          "Process::SetPrivateState (plugin = %s, state = %s) state didn't "
          "change. Ignoring...",
          GetPluginName().data(), StateAsCString(new_state));

to

LLDB_LOG(log, "(plugin = %s, state = %s) state didn't "
          "change. Ignoring...",
          GetPluginName().data(), StateAsCString(new_state));

LLDB_LOG automatically inserts the file and func into the log. There are plenty of places where we copy/paste logs like these into other files without remembering to update this piece of information, so removing it from the log line entirely helps prevent those kinds of issues in the future. It's a minor thing, but if the point of this patch is to improve the logging mechanism entirely, then I think we should also think about these kinds of things. See 0a74fbb7b1d3e04ac03389f1fc455ac593c2e5ee for an example of what I mean.

[mib]

In D148399#4284809, @bulbazord wrote:

We'd go from:

LLDB_LOGF(log,
          "Process::SetPrivateState (plugin = %s, state = %s) state didn't "
          "change. Ignoring...",
          GetPluginName().data(), StateAsCString(new_state));

to

LLDB_LOG(log, "(plugin = %s, state = %s) state didn't "
          "change. Ignoring...",
          GetPluginName().data(), StateAsCString(new_state));

LLDB_LOG automatically inserts the file and func into the log. There are plenty of places where we copy/paste logs like these into other files without remembering to update this piece of information, so removing it from the log line entirely helps prevent those kinds of issues in the future. It's a minor thing, but if the point of this patch is to improve the logging mechanism entirely, then I think we should also think about these kinds of things. See 0a74fbb7b1d3e04ac03389f1fc455ac593c2e5ee for an example of what I mean.

I didn't understand that originally (since what you guys are suggesting doesn't have anything to do with my change), but I'll update it in this patch.

[mib]

Address @JDevlieghere @bulbazord comments

[bulbazord]

LGTM

lldb/source/Target/Process.cpp

const char *Process::GetExitDescription() {
   return nullptr;
 }
 
 bool Process::SetExitStatus(int status, const char *cstr) {
   // Use a mutex to protect setting the exit status.
   std::lock_guard<std::mutex> guard(m_exit_status_mutex);
 
   Log *log(GetLog(LLDBLog::State | LLDBLog::Process));
-  LLDB_LOGF(
-      log, "Process::SetExitStatus (status=%i (0x%8.8x), description=%s%s%s)",
-      status, status, cstr ? "\"" : "", cstr ? cstr : "NULL", cstr ? "\"" : "");
+  LLDB_LOG(log, "(plugin = %s status=%i (0x%8.8x), description=%s%s%s)",
+           GetPluginName().data(), status, status, cstr ? "\"" : "",
+           cstr ? cstr : "NULL", cstr ? "\"" : "");
 
   // We were already in the exited state
   if (m_private_state.GetValue() == eStateExited) {
-    LLDB_LOGF(log, "Process::SetExitStatus () ignoring exit status because "
-                   "state was already set to eStateExited");
+    LLDB_LOG(log,
+             "(plugin = %s) ignoring exit status because state was already set "
+             "to eStateExited",
+             GetPluginName().data());
     return false;
   }
 
   m_exit_status = status;
   if (cstr)
     m_exit_string = cstr;
   else
     m_exit_string.clear();
if (new_state_is_stopped) {
     // at the stop ID because many private stops might have happened, so we
     // can't check for a stop ID of zero. This allows the "statistics" command
     // to dump the time it takes to reach somewhere in your code, like a
     // breakpoint you set.
     GetTarget().GetStatistics().SetFirstPublicStopTime();
   }
 
   Log *log(GetLog(LLDBLog::State | LLDBLog::Process));
-  LLDB_LOGF(log, "Process::SetPublicState (state = %s, restarted = %i)",
-            StateAsCString(new_state), restarted);
+  LLDB_LOG(log, "(plugin = %s, state = %s, restarted = %i)",
+           GetPluginName().data(), StateAsCString(new_state), restarted);
   const StateType old_state = m_public_state.GetValue();
   m_public_state.SetValue(new_state);
 
   // On the transition from Run to Stopped, we unlock the writer end of the run
   // lock.  The lock gets locked in Resume, which is the public API to tell the
   // program to run.
   if (!StateChangedIsExternallyHijacked()) {
     if (new_state == eStateDetached) {
-      LLDB_LOGF(log,
-                "Process::SetPublicState (%s) -- unlocking run lock for detach",
-                StateAsCString(new_state));
+      LLDB_LOG(log,
+               "(plugin = %s, state = %s) -- unlocking run lock for detach",
+               GetPluginName().data(), StateAsCString(new_state));
       m_public_run_lock.SetStopped();
     } else {
       const bool old_state_is_stopped = StateIsStoppedState(old_state, false);
       if ((old_state_is_stopped != new_state_is_stopped)) {
         if (new_state_is_stopped && !restarted) {
-          LLDB_LOGF(log, "Process::SetPublicState (%s) -- unlocking run lock",
-                    StateAsCString(new_state));
+          LLDB_LOG(log, "(plugin = %s, state = %s) -- unlocking run lock",
+                   GetPluginName().data(), StateAsCString(new_state));
           m_public_run_lock.SetStopped();
         }
       }
     }
   }
 }
 
 Status Process::Resume() {
   Log *log(GetLog(LLDBLog::State | LLDBLog::Process));
-  LLDB_LOGF(log, "Process::Resume -- locking run lock");
+  LLDB_LOG(log, "(plugin = %s) -- locking run lock", GetPluginName().data());
   if (!m_public_run_lock.TrySetRunning()) {
     Status error("Resume request failed - process still running.");
-    LLDB_LOGF(log, "Process::Resume: -- TrySetRunning failed, not resuming.");
+    LLDB_LOG(log, "(plugin = %s) -- TrySetRunning failed, not resuming.",
+             GetPluginName().data());
     return error;
   }
   Status error = PrivateResume();
   if (!error.Success()) {
     // Undo running state change
     m_public_run_lock.SetStopped();
   }
   return error;

 
 void Process::SetPrivateState(StateType new_state) {
   if (m_finalizing)
     return;
 
   Log *log(GetLog(LLDBLog::State | LLDBLog::Process | LLDBLog::Unwind));
   bool state_changed = false;
 
-  LLDB_LOGF(log, "Process::SetPrivateState (%s)", StateAsCString(new_state));
+  LLDB_LOG(log, "(plugin = %s, state = %s)", GetPluginName().data(),
+           StateAsCString(new_state));
 
   std::lock_guard<std::recursive_mutex> thread_guard(m_thread_list.GetMutex());
   std::lock_guard<std::recursive_mutex> guard(m_private_state.GetMutex());
 
   const StateType old_state = m_private_state.GetValueNoLock();
   state_changed = old_state != new_state;
 
   const bool old_state_is_stopped = StateIsStoppedState(old_state, false);
if (StateIsStoppedState(new_state, false)) {
       m_thread_list.DidStop();
 
       if (m_mod_id.BumpStopID() == 0)
         GetTarget().GetStatistics().SetFirstPrivateStopTime();
 
       if (!m_mod_id.IsLastResumeForUserExpression())
         m_mod_id.SetStopEventForLastNaturalStopID(event_sp);
       m_memory_cache.Clear();
-      LLDB_LOGF(log, "Process::SetPrivateState (%s) stop_id = %u",
-                StateAsCString(new_state), m_mod_id.GetStopID());
+      LLDB_LOG(log, "(plugin = %s, state = %s, stop_id = %u",
+               GetPluginName().data(), StateAsCString(new_state),
+               m_mod_id.GetStopID());
     }
 
     m_private_state_broadcaster.BroadcastEvent(event_sp);
   } else {
-    LLDB_LOGF(log,
-              "Process::SetPrivateState (%s) state didn't change. Ignoring...",
-              StateAsCString(new_state));
+    LLDB_LOG(log, "(plugin = %s, state = %s) state didn't change. Ignoring...",
+             GetPluginName().data(), StateAsCString(new_state));
   }
 }
 
 void Process::SetRunningUserExpression(bool on) {
   m_mod_id.SetRunningUserExpression(on);
 }
 
 void Process::SetRunningUtilityFunction(bool on) {