Add unconditional logging to debugserver for launch/attach processes

Debugging app launch/attach failures can be difficult because of
all of the messages logged to the console on a darwin system;
emitting specific messages around critical API calls can make it
easier to narrow the search for the console messages related to
the failure.

<rdar://problem/67220442>

Differential revision: https://reviews.llvm.org/D94357

Author: jasonmolenda

lldb/tools/debugserver/source/MacOSX/MachProcess.mm

@@ -140,8 +140,10 @@ static bool CallBoardSystemServiceOpenApplication(NSString *bundleIDNSStr,
     cstr = "<Unknown Bundle ID>";
 
   NSString *description = [options description];
-  DNBLog("About to launch process for bundle ID: %s - options:\n%s", cstr,
-    [description UTF8String]);
+  DNBLog("[LaunchAttach] START (%d) templated *Board launcher: app lunch "
+         "request for "
+         "'%s' - options:\n%s",
+         getpid(), cstr, [description UTF8String]);
   [system_service
       openApplication:bundleIDNSStr
               options:options
@@ -156,33 +158,36 @@ static bool CallBoardSystemServiceOpenApplication(NSString *bundleIDNSStr,
                if (wants_pid) {
                  pid_in_block =
                      [system_service pidForApplication:bundleIDNSStr];
-                 DNBLog(
-                     "In completion handler, got pid for bundle id, pid: %d.",
-                     pid_in_block);
-                 DNBLogThreadedIf(
-                     LOG_PROCESS,
-                     "In completion handler, got pid for bundle id, pid: %d.",
-                     pid_in_block);
-               } else
-                 DNBLogThreadedIf(LOG_PROCESS,
-                                  "In completion handler: success.");
+                 DNBLog("[LaunchAttach] In completion handler, got pid for "
+                        "bundle id "
+                        "'%s', pid: %d.",
+                        cstr, pid_in_block);
+               } else {
+                 DNBLog("[LaunchAttach] In completion handler, launch was "
+                        "successful, "
+                        "debugserver did not ask for the pid");
+               }
              } else {
                const char *error_str =
                    [(NSString *)[bks_error localizedDescription] UTF8String];
                if (error_str) {
                  open_app_error_string = error_str;
-                 DNBLogError("In app launch attempt, got error "
-                             "localizedDescription '%s'.", error_str);
+                 DNBLogError(
+                     "[LaunchAttach] END (%d) In app launch attempt, got error "
+                     "localizedDescription '%s'.",
+                     getpid(), error_str);
                  const char *obj_desc = 
                       [NSString stringWithFormat:@"%@", bks_error].UTF8String;
-                 DNBLogError("In app launch attempt, got error "
-                             "NSError object description: '%s'.",
-                             obj_desc);
+                 DNBLogError(
+                     "[LaunchAttach] END (%d) In app launch attempt, got error "
+                     "NSError object description: '%s'.",
+                     getpid(), obj_desc);
                }
-               DNBLogThreadedIf(LOG_PROCESS, "In completion handler for send "
-                                             "event, got error \"%s\"(%ld).",
+               DNBLogThreadedIf(LOG_PROCESS,
+                                "In completion handler for send "
+                                "event, got error \"%s\"(%ld).",
                                 error_str ? error_str : "<unknown error>",
-                                open_app_error);
+                                (long)open_app_error);
              }
 
              [system_service release];
@@ -200,15 +205,23 @@ static bool CallBoardSystemServiceOpenApplication(NSString *bundleIDNSStr,
 
   dispatch_release(semaphore);
 
+  DNBLog("[LaunchAttach] END (%d) templated *Board launcher finished app lunch "
+         "request for "
+         "'%s'",
+         getpid(), cstr);
+
   if (!success) {
-    DNBLogError("timed out trying to send openApplication to %s.", cstr);
+    DNBLogError("[LaunchAttach] END (%d) timed out trying to send "
+                "openApplication to %s.",
+                getpid(), cstr);
     error.SetError(OPEN_APPLICATION_TIMEOUT_ERROR, DNBError::Generic);
     error.SetErrorString("timed out trying to launch app");
   } else if (open_app_error != no_error_enum_value) {
     error_function(open_app_error, open_app_error_string, error);
-    DNBLogError("unable to launch the application with CFBundleIdentifier '%s' "
-                "bks_error = %u",
-                cstr, open_app_error);
+    DNBLogError("[LaunchAttach] END (%d) unable to launch the application with "
+                "CFBundleIdentifier '%s' "
+                "bks_error = %ld",
+                getpid(), cstr, (long)open_app_error);
     success = false;
   } else if (wants_pid) {
     *return_pid = pid_in_block;
@@ -1428,7 +1441,7 @@ static bool FBSAddEventDataToOptions(NSMutableDictionary *options,
   DNBLogThreadedIf(LOG_PROCESS, "MachProcess::Kill() DoSIGSTOP() state = %s",
                    DNBStateAsString(state));
   errno = 0;
-  DNBLog("Sending ptrace PT_KILL to terminate inferior process.");
+  DNBLog("Sending ptrace PT_KILL to terminate inferior process pid %d.", m_pid);
   ::ptrace(PT_KILL, m_pid, 0, 0);
   DNBError err;
   err.SetErrorToErrno();
@@ -2623,15 +2636,26 @@ static bool FBSAddEventDataToOptions(NSMutableDictionary *options,
       ::snprintf(err_str, err_len, "%s",
                  err_cstr ? err_cstr : "unable to start the exception thread");
       DNBLogThreadedIf(LOG_PROCESS, "error: failed to attach to pid %d", pid);
-      DNBLogError ("MachProcess::AttachForDebug failed to start exception thread: %s", err_str);
+      DNBLogError(
+          "[LaunchAttach] END (%d) MachProcess::AttachForDebug failed to start "
+          "exception thread attaching to pid %i: %s",
+          getpid(), pid, err_str);
       m_pid = INVALID_NUB_PROCESS;
       return INVALID_NUB_PROCESS;
     }
 
+    DNBLog("[LaunchAttach] (%d) About to ptrace(PT_ATTACHEXC, %d)...", getpid(),
+           pid);
     errno = 0;
-    if (::ptrace(PT_ATTACHEXC, pid, 0, 0)) {
-      err.SetError(errno);
-      DNBLogError ("MachProcess::AttachForDebug failed to ptrace(PT_ATTACHEXC): %s", err.AsString());
+    int ptrace_result = ::ptrace(PT_ATTACHEXC, pid, 0, 0);
+    int ptrace_errno = errno;
+    DNBLog("[LaunchAttach] (%d) Completed ptrace(PT_ATTACHEXC, %d) == %d",
+           getpid(), pid, ptrace_result);
+    if (ptrace_result != 0) {
+      err.SetError(ptrace_errno);
+      DNBLogError("MachProcess::AttachForDebug failed to ptrace(PT_ATTACHEXC) "
+                  "pid %i: %s",
+                  pid, err.AsString());
     } else {
       err.Clear();
     }
@@ -2642,19 +2666,27 @@ static bool FBSAddEventDataToOptions(NSMutableDictionary *options,
       // status
       // to stopped.
       ::usleep(250000);
+      DNBLog("[LaunchAttach] (%d) Done napping after ptrace(PT_ATTACHEXC)'ing",
+             getpid());
       DNBLogThreadedIf(LOG_PROCESS, "successfully attached to pid %d", pid);
       return m_pid;
     } else {
       ::snprintf(err_str, err_len, "%s", err.AsString());
-      DNBLogError ("MachProcess::AttachForDebug error: failed to attach to pid %d", pid);
+      DNBLogError(
+          "[LaunchAttach] (%d) MachProcess::AttachForDebug error: failed to "
+          "attach to pid %d",
+          getpid(), pid);
 
       struct kinfo_proc kinfo;
       int mib[] = {CTL_KERN, KERN_PROC, KERN_PROC_PID, pid};
       size_t len = sizeof(struct kinfo_proc);
       if (sysctl(mib, sizeof(mib) / sizeof(mib[0]), &kinfo, &len, NULL, 0) == 0 && len > 0) {
         if (kinfo.kp_proc.p_flag & P_TRACED) {
           ::snprintf(err_str, err_len, "%s - process %d is already being debugged", err.AsString(), pid);
-          DNBLogError ("MachProcess::AttachForDebug pid %d is already being debugged", pid);
+          DNBLogError(
+              "[LaunchAttach] (%d) MachProcess::AttachForDebug pid %d is "
+              "already being debugged",
+              getpid(), pid);
         }
       }
     }
@@ -2815,6 +2847,9 @@ static bool FBSAddEventDataToOptions(NSMutableDictionary *options,
 
     NSString *bundleIDNSStr = (NSString *)bundleIDCFStr;
 
+    DNBLog("[LaunchAttach] START (%d) requesting FBS launch of app with bundle "
+           "ID '%s'",
+           getpid(), bundleIDStr.c_str());
     [system_service openApplication:bundleIDNSStr
                             options:options
                          clientPort:client_port
@@ -2893,6 +2928,9 @@ static bool FBSAddEventDataToOptions(NSMutableDictionary *options,
 
     NSString *bundleIDNSStr = (NSString *)bundleIDCFStr;
 
+    DNBLog("[LaunchAttach] START (%d) requesting BKS launch of app with bundle "
+           "ID '%s'",
+           getpid(), bundleIDStr.c_str());
     [system_service openApplication:bundleIDNSStr
                             options:options
                          clientPort:client_port
@@ -2923,7 +2961,7 @@ static bool FBSAddEventDataToOptions(NSMutableDictionary *options,
       std::string empty_str;
       SetBKSError(attach_error_code, empty_str, attach_err);
       DNBLogError("unable to launch the application with CFBundleIdentifier "
-                  "'%s' bks_error = %ld",
+                  "'%s' bks_error = %d",
                   bundleIDStr.c_str(), attach_error_code);
     }
     dispatch_release(semaphore);
@@ -2945,6 +2983,10 @@ static bool FBSAddEventDataToOptions(NSMutableDictionary *options,
                                   "SBSApplicationLaunchWaitForDebugger )",
                      bundleIDStr.c_str(), stdout_err, stdout_err);
 
+    DNBLog("[LaunchAttach] START (%d) requesting SpringBoard launch of app "
+           "with bundle "
+           "ID '%s'",
+           getpid(), bundleIDStr.c_str());
     sbs_error = SBSLaunchApplicationForDebugging(
         bundleIDCFStr,
         (CFURLRef)NULL, // openURL
@@ -3105,7 +3147,7 @@ static bool FBSAddEventDataToOptions(NSMutableDictionary *options,
       m_flags |= (eMachProcessFlagsUsingFBS | eMachProcessFlagsBoardCalculated);
       if (BoardServiceLaunchForDebug(app_bundle_path.c_str(), argv, envp,
                                      no_stdio, disable_aslr, event_data,
-                                     launch_err) != 0)
+                                     unmask_signals, launch_err) != 0)
         return m_pid; // A successful SBLaunchForDebug() returns and assigns a
                       // non-zero m_pid.
       else
@@ -3121,7 +3163,7 @@ static bool FBSAddEventDataToOptions(NSMutableDictionary *options,
       m_flags |= (eMachProcessFlagsUsingBKS | eMachProcessFlagsBoardCalculated);
       if (BoardServiceLaunchForDebug(app_bundle_path.c_str(), argv, envp,
                                      no_stdio, disable_aslr, event_data,
-                                     launch_err) != 0)
+                                     unmask_signals, launch_err) != 0)
         return m_pid; // A successful SBLaunchForDebug() returns and assigns a
                       // non-zero m_pid.
       else
@@ -3148,7 +3190,7 @@ static bool FBSAddEventDataToOptions(NSMutableDictionary *options,
     if (app_ext) {
       std::string app_bundle_path(path, app_ext + strlen(".app"));
       if (SBLaunchForDebug(app_bundle_path.c_str(), argv, envp, no_stdio,
-                           disable_aslr, launch_err) != 0)
+                           disable_aslr, unmask_signals, launch_err) != 0)
         return m_pid; // A successful SBLaunchForDebug() returns and assigns a
                       // non-zero m_pid.
       else
@@ -3200,14 +3242,19 @@ static bool FBSAddEventDataToOptions(NSMutableDictionary *options,
 
       SetState(eStateAttaching);
       errno = 0;
+      DNBLog("[LaunchAttach] (%d) About to ptrace(PT_ATTACHEXC, %d)...",
+             getpid(), m_pid);
       int err = ::ptrace(PT_ATTACHEXC, m_pid, 0, 0);
+      int ptrace_errno = errno;
+      DNBLog("[LaunchAttach] (%d) Completed ptrace(PT_ATTACHEXC, %d) == %d",
+             getpid(), m_pid, err);
       if (err == 0) {
         m_flags |= eMachProcessFlagsAttached;
         DNBLogThreadedIf(LOG_PROCESS, "successfully spawned pid %d", m_pid);
         launch_err.Clear();
       } else {
         SetState(eStateExited);
-        DNBError ptrace_err(errno, DNBError::POSIX);
+        DNBError ptrace_err(ptrace_errno, DNBError::POSIX);
         DNBLogThreadedIf(LOG_PROCESS, "error: failed to attach to spawned pid "
                                       "%d (err = %i, errno = %i (%s))",
                          m_pid, err, ptrace_err.Status(),
@@ -3577,7 +3624,11 @@ static CFStringRef CopyBundleIDForPath(const char *app_bundle_path,
 
     StartSTDIOThread();
     SetState(eStateAttaching);
+    DNBLog("[LaunchAttach] (%d) About to ptrace(PT_ATTACHEXC, %d)...", getpid(),
+           m_pid);
     int err = ::ptrace(PT_ATTACHEXC, m_pid, 0, 0);
+    DNBLog("[LaunchAttach] (%d) Completed ptrace(PT_ATTACHEXC, %d) == %d",
+           getpid(), m_pid, err);
     if (err == 0) {
       m_flags |= eMachProcessFlagsAttached;
       DNBLogThreadedIf(LOG_PROCESS, "successfully attached to pid %d", m_pid);
@@ -3779,22 +3830,30 @@ static CFStringRef CopyBundleIDForPath(const char *app_bundle_path,
     if (launch_err.Fail()) {
       if (launch_err.AsString() == NULL)
         launch_err.SetErrorString("unable to start the exception thread");
-      DNBLog("Could not get inferior's Mach exception port, sending ptrace "
-             "PT_KILL and exiting.");
+      DNBLog("[LaunchAttach] END (%d) Could not get inferior's Mach exception "
+             "port, "
+             "sending ptrace "
+             "PT_KILL to pid %i and exiting.",
+             getpid(), m_pid);
       ::ptrace(PT_KILL, m_pid, 0, 0);
       m_pid = INVALID_NUB_PROCESS;
       return INVALID_NUB_PROCESS;
     }
 
     StartSTDIOThread();
     SetState(eStateAttaching);
+    DNBLog("[LaunchAttach] (%d) About to ptrace(PT_ATTACHEXC, %d)...", getpid(),
+           m_pid);
     int err = ::ptrace(PT_ATTACHEXC, m_pid, 0, 0);
+    DNBLog("[LaunchAttach] (%d) Completed ptrace(PT_ATTACHEXC, %d) == %d",
+           getpid(), m_pid, err);
     if (err == 0) {
       m_flags |= eMachProcessFlagsAttached;
-      DNBLogThreadedIf(LOG_PROCESS, "successfully attached to pid %d", m_pid);
+      DNBLog("[LaunchAttach] successfully attached to pid %d", m_pid);
     } else {
       SetState(eStateExited);
-      DNBLogThreadedIf(LOG_PROCESS, "error: failed to attach to pid %d", m_pid);
+      DNBLog("[LaunchAttach] END (%d) error: failed to attach to pid %d",
+             getpid(), m_pid);
     }
   }
   return m_pid;

lldb/tools/debugserver/source/MacOSX/MachTask.mm

@@ -512,6 +512,7 @@ static void get_threads_profile_data(DNBProfileDataScanType scanType,
     mach_port_t task_self = mach_task_self();
     task_t task = TASK_NULL;
     for (uint32_t i = 0; i < num_retries; i++) {
+      DNBLog("[LaunchAttach] (%d) about to task_for_pid(%d)", getpid(), pid);
       err = ::task_for_pid(task_self, pid, &task);
 
       if (DNBLogCheckLogBit(LOG_TASK) || err.Fail()) {
@@ -522,13 +523,19 @@ static void get_threads_profile_data(DNBProfileDataScanType scanType,
                    err.AsString() ? err.AsString() : "success");
         if (err.Fail()) {
           err.SetErrorString(str);
-          DNBLogError ("MachTask::TaskPortForProcessID task_for_pid failed: %s", str);
+          DNBLogError(
+              "[LaunchAttach] MachTask::TaskPortForProcessID task_for_pid(%d) "
+              "failed: %s",
+              pid, str);
         }
         err.LogThreaded(str);
       }
 
-      if (err.Success())
+      if (err.Success()) {
+        DNBLog("[LaunchAttach] (%d) successfully task_for_pid(%d)'ed", getpid(),
+               pid);
         return task;
+      }
 
       // Sleep a bit and try again
       ::usleep(usec_interval);